newrelic-java-agent: Using @Trace on a method in a utility class in an instrumentation module does not work
Description
According to the README.md for instrumentation modules, an instrumentation module consists of weave classes, utility classes, and SkipIfPresent classes.
The @Trace annotation is handled properly on methods in weave classes. Unfortunately, it is not handled properly on methods in utility classes.
For example, this usage of @Trace on a utility class is not handled. Specifically, the token will not be linked properly here, because the @Trace is not handled properly.
Expected Behavior
I expect @Trace to work correctly when placed on a method in a utility class in an instrumentation module.
Steps to Reproduce
The easiest way to see the non-working behavior is to:
- Turn on logging at the FINEST level
- Turn on token debugging
- Run an application that exercises code that uses
@Tracein a utility class of an instrumentation module. For example, here - Look in the logs for messages like the following…
2022-11-10T18:53:13,317+0100 [7219 78] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@11ee9b3: ignoring link call because there is no started txa to link to: null.
2022-11-10T18:53:13,317+0100 [7219 78] com.newrelic WARN: Token: com.newrelic.agent.TokenImpl@100c4133 was NOT linked because there was no Transaction in progress. Did you forget to add @Trace(async = true) to: com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken(TokenLinkingSubscriber.java:68)?
This message indicates that the @Trace(async = true) annotation is not on the method in the utility class. However it actually IS on the method. This is a symptom of the @Trace not being handled properly on the method in the utility class.
Troubleshooting
I have determined that the problem seems to be related to where AgentPostprocessors handles utility classes.
Specifically here, tracedWeaveInstrumentationTrackers is always null, because the post processor’s tracedWeaveInstrumentationDetails map is always empty. It appears that the post processor’s setTracedWeaveInstrumentationDetails method is never called, therefore the tracedWeaveInstrumentationDetails map is always empty.
Because tracedWeaveInstrumentationTrackers is always null… when the TraceClassVisitor visits the method annotated with @Trace in the utility class, the TraceDetails is always null. Therefore the tracer logic is never injected into the utility class bytecode.
To confirm this theory, in a debugger I have explicitly called AgentPostprocessors.setTracedWeaveInstrumentationDetails with the return value of AgentPreprocessor.getTracedWeaveInstrumentationDetails before the post processor is executed in PackageValidationResult.computeUtilityClassBytes. After doing so, the tracer logic is injected properly into the utility class bytecode, and the @Trace functionality works properly.
Your Environment
newrelic-java-agent 7.11.0
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Reactions: 1
- Comments: 15 (8 by maintainers)
Going to close out this issue as the PR with the fix has been merged and will be included in the next agent release unless any issues crop up between now and then. https://github.com/newrelic/newrelic-java-agent/pull/1443
I’ve also gone ahead and filed another ticket for the issue regarding transaction renaming when using
subscribeOn(Schedulers.boundedElastic()). Not sure when this one will make it on to our roadmap though. https://github.com/newrelic/newrelic-java-agent/issues/1450Thanks again for all of your help on this issue @philsttr !
I had some time to do a quick test on the custom build today. It does indeed solve the problem. The util classes in our custom instrumentation work properly now. 😃
Hi Jason. Thank you so much for your time and investigation! I really appreciate it since this problem is blocking some of the custom instrumentation we would like to write, and therefore preventing us from adopting newrelic in more of our services.
I originally found the problem when writing some custom instrumentation, and I spent a lot of time debugging it. Before filing the original support case for the problem, I wanted to find and provide a minimal reproducible scenario. That’s when I noticed that I could also reproduce the problem with the reactor-netty instrumentation and
TokenLinkingSubscriber. So I used that as an example, since I thought it would be easier for newrelic to reproduce.Something must be different when running the newrelic java agent in an application as I have done (which demonstrates the problem), versus running the
TransactionPropagationTestas you have done (which does not demonstrate the problem). PerhapsTransactionPropagationTestis setting up something that is not quite the same as when running in an application. I haven’t looked into that yet, but I can most definitely reproduce the problem in a running application, so something has to be different. I’d like to understand what.When I filed the original support case, I provided an example project and a short video and that
AgentPostprocessors.setTracedWeaveInstrumentationDetailsin the debugger to “fix” the problem.The support folks directed me to file an issue here. I should have included the video and project here when I filed this issue for you to review. I will link them below.
I would really appreciate it if you could review the full video, and use the project to reproduce the problem as I have done, rather than a separate testcase with different setup. I would love to hear your diagnosis on why the problem can be reproduced in a running application, but not in the
TransactionPropagationTest. In the meantime, I will also look into howTransactionPropagationTestis setup, to see if I can identify what is different about that working test case.Again, thank you for your time. I really hope we can identify what is causing the behavior I am seeing, so we can rollout newrelic to more of our services.