Custom transaction names stopped working and warning message

Chris_Blackwell · November 27, 2018, 12:10pm

We had apm working in an app, which is built on Lucee CFML (https://lucee.org/) . Which is a scripting language on the JVM. The app runs in tomcat, but because the script engine only exposes a single servlet we need to set a custom transaction name in the app. This was working fine with earlier version of apm, but upgrading to 1.0.1 seems to have broken it and we now get an error in the logs. Heres some details

In our onRequestStart handler we do

ElasticApm.currentTransaction().setName(txName);

Where ElasticAPM is a singleton instance of the co.elastic.apm.api.ElasticApm . Previously that was all we needed, and we got our custom tx name in apm. Now however, we still get data in apm, but all transactions are named CFMLServlet#doGet or CFMLServlet#doPost etc

In the server logs/console we get the stack trace below. I've truncated the trace, but it starts from /Application.cfc:129, which is the location in our code where we call ElasticApm.currentTransaction().setName(txName);

If this is better posted on github, then happy to move it over there

[edit]
I forgot to add environment info

openjdk version "1.8.0_181"
Apache Tomcat/7.0.59

2018-11-27 10:40:14.471 [http-bio-8080-exec-9] WARN co.elastic.apm.bci.bytebuddy.ErrorLoggingListener - ERROR on transformation co.elastic.apm.api.TransactionImpl
java.lang.IllegalStateException: Cannot locate field named span for class co.elastic.apm.api.TransactionImpl
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$OffsetMapping$ForField$Unresolved.resolve(Advice.java:2177)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$OffsetMapping$ForField.resolve(Advice.java:2121)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$ForMethodEnter.doApply(Advice.java:7664)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$ForMethodEnter$WithDiscardedEnterType.doApply(Advice.java:7756)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$ForMethodEnter.apply(Advice.java:7625)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$AdviceMethodInliner.visitMethod(Advice.java:7334)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.readMethod(ClassReader.java:1113)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:679)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:391)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$AdviceMethodInliner.apply(Advice.java:7328)
	at co.elastic.apm.shaded.bytebuddy.asm.Advice$AdviceVisitor.onAfterExceptionTable(Advice.java:9376)
	at co.elastic.apm.shaded.bytebuddy.utility.visitor.ExceptionTableSensitiveMethodVisitor.considerEndOfExceptionTable(ExceptionTableSensitiveMethodVisitor.java:49)
	at co.elastic.apm.shaded.bytebuddy.utility.visitor.ExceptionTableSensitiveMethodVisitor.visitLabel(ExceptionTableSensitiveMethodVisitor.java:62)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.Label.accept(Label.java:357)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.readCode(ClassReader.java:1815)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.readMethod(ClassReader.java:1275)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:679)
	at co.elastic.apm.shaded.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:391)
	at co.elastic.apm.shaded.bytebuddy.dynamic.scaffold.TypeWriter$Default$ForInlining.create(TypeWriter.java:3393)
	at co.elastic.apm.shaded.bytebuddy.dynamic.scaffold.TypeWriter$Default.make(TypeWriter.java:1930)
	at co.elastic.apm.shaded.bytebuddy.dynamic.scaffold.inline.RedefinitionDynamicTypeBuilder.make(RedefinitionDynamicTypeBuilder.java:207)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$Transformation$Simple$Resolution.apply(AgentBuilder.java:10050)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doTransform(AgentBuilder.java:10469)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:10432)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.access$1500(AgentBuilder.java:10198)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$LegacyVmDispatcher.run(AgentBuilder.java:10807)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$LegacyVmDispatcher.run(AgentBuilder.java:10754)
	at java.security.AccessController.doPrivileged(Native Method)
	at co.elastic.apm.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:10355)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2957)
	at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:1210)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1690)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1571)
	at co.elastic.apm.api.ElasticApm.currentTransaction(ElasticApm.java:94)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at lucee.runtime.reflection.pairs.MethodInstance.invoke(MethodInstance.java:55)
	at lucee.runtime.java.JavaObject.call(JavaObject.java:246)
	at lucee.runtime.java.JavaObject.call(JavaObject.java:268)
	at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:756)
	at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1718)
	at application_cfc$cf.udfCall1(/Application.cfc:129)

felixbarny · November 27, 2018, 2:04pm

Could it be that you are using an older version of the apm-agent-api module? Updating that to the latest version should fix the problem.

Chris_Blackwell · November 29, 2018, 7:44pm

no, we're using elastic-agent-api 1.0.1 and the same version of the agent

felixbarny · November 29, 2018, 9:25pm

Hmm, that's somewhat strange

In version 1.0.1, there is actually a span property in TransactionImpl's superclass SpanImpl:

github.com

elastic/apm-agent-java/blob/v1.0.1/apm-agent-api/src/main/java/co/elastic/apm/api/SpanImpl.java#L36


      
          * co.elastic.apm.plugin.api.SpanInstrumentation
          * into this class.
          * <p>
          * Otherwise, this class is a noop.
          * </p>
          */
          class SpanImpl implements Span {
          
             @Nonnull
             // co.elastic.apm.impl.transaction.AbstractSpan
             protected final Object span;
          
             SpanImpl(@Nonnull Object span) {
                 this.span = span;
             }
          
             @Override
             public void setName(String name) {
                 // co.elastic.apm.plugin.api.SpanInstrumentation$SetNameInstrumentation.setName
             }

However in previous versions, there was no property called span, as it was called transaction.

github.com

elastic/apm-agent-java/blob/v0.7.1/apm-agent-api/src/main/java/co/elastic/apm/api/TransactionImpl.java#L36


      
          * co.elastic.apm.plugin.api.TransactionInstrumentation
          * into this class.
          * <p>
          * Otherwise, this class is a noop.
          * </p>
          */
          class TransactionImpl implements Transaction {
          
             @Nonnull
             @SuppressWarnings("unused")
             private final Object transaction;
          
             TransactionImpl(@Nonnull Object transaction) {
                 this.transaction = transaction;
             }
          
             @Override
             public void setName(String name) {
                 // co.elastic.apm.plugin.api.TransactionInstrumentation$SetNameInstrumentation.setName
             }

Could you double check that you are using the current version of this artifact: Maven Central Repository Search

Chris_Blackwell · November 29, 2018, 10:04pm

My bad. I did a find ./src | grep apm and it spat out an old jar in a lib directory where it had no right to be hiding. Now works as expected, thank you!

However,I do get the following warning on the first request

2018-11-29 21:55:17.668 [http-bio-8080-exec-1] WARN co.elastic.apm.bci.bytebuddy.ErrorLoggingListener - ERROR on transformation lucee.runtime.net.http.HTTPServletRequestWrap
java.lang.IllegalStateException: Cannot resolve type description for javax.servlet.http.HttpUpgradeHandler

The src for that class would be here - https://github.com/lucee/Lucee/blob/master/core/src/main/java/lucee/runtime/net/http/HTTPServletRequestWrap.java

felixbarny · November 30, 2018, 7:18am

Warnings with the message Cannot resolve type description for are not something to worry about. The reason in this case is that Tomcat 7 ships with the Servlet API 3.0, but HTTPServletRequestWrap.java referrrs to classes of the servlet api 3.1, which are not present in Tomcat.

felixbarny · November 30, 2018, 7:54am

This pull request should remove the warning for that as it does not try to resolve the missing class anymore: https://github.com/elastic/apm-agent-java/pull/363

To get notified of the next release, go to https://github.com/elastic/apm-agent-java, click on watch and select "Releases only".

Thanks for reporting!

Chris_Blackwell · November 30, 2018, 7:03pm

Thankyou @felixbarny

system · December 21, 2018, 3:03pm

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.