Using @Trace on a method in a utility class in an instrumentation module does not work

[philsttr]

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:

1. Turn on logging at the FINEST level
2. Turn on token debugging
3. Run an application that exercises code that uses @Trace in a utility class of an instrumentation module. For example, here
4. 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

[workato-integration]

https://issues.newrelic.com/browse/NEWRELIC-5219

[kford-newrelic]

Targeted for the Jan-Mar quarter

[kford-newrelic]

Moving review of this to the Apr-Jun quarter - no capacity to take this up currently

[jenerallyErrorFree]

Hey @kford-newrelic - Customer Success Manager here. As we're in Q2, is there any update to this issue you can share? Customer is asking.

[kford-newrelic]

@jenerallyErrorFree apologies but we haven't had the capacity to take this up. Unfortunately, no ETA at the moment

[jasonjkeller]

We tested this and determined that @Trace annotation does work as expected on instrumentation utility classes.

The "non-working" example that was cited was the TokenLinkingSubscriber utility class in our own netty-reactor-0.9.0 instrumentation. If you debug the TransactionPropagationTest in that instrumentation package while adding breakpoints in the places that were called out you can see it working correctly.

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.

TraceDetails is not null when the TraceClassVisitor visits the withNRToken method annotated with @Trace in the utility class

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...

tracedWeaveInstrumentationTrackers is not null and tracedWeaveInstrumentationDetails is not empty

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.

The token.link() call in withNRToken (within the TokenLinkingSubscriber utility class) is successful

The only obvious reason why the token linking would fail in this scenario is if the link() method were to get a null Transaction reference, meaning that no Transaction was actually started or that the context was lost at the point where the link was attempted.

---

It's not clear if this ticket is specifically meaning to call out a perceived issued with the netty-reactor-0.9.0 instrumentation or if a similar issue was discovered when attempting to write a custom instrumentation module. If it's the former, then it appears to be working correctly, if it's the latter we would need to know more details about the specific scenario.

[philsttr]

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 TransactionPropagationTest as you have done (which does not demonstrate the problem).
Perhaps TransactionPropagationTest is 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

• showed how to setup the test case
• demonstrated the problem,
• stepped through a debugger showing where the problem occurs, and
• demonstrated calling AgentPostprocessors.setTracedWeaveInstrumentationDetails in 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 how TransactionPropagationTest is 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.

[jasonjkeller]

Hey @philsttr , thanks for the additional context, it does help to clarify a bit.

The project that you linked didn't have any controllers in it but I added the following based on what you were showing in the YT video. Let me know if this is not correct for the repro.

@RestController
public class ExampleController {

    @GetMapping(path = "/works")
    public Mono<String> works() {
        return Mono.fromCallable(() -> "Works");
    }

    @GetMapping(path = "/does-not-work")
    public Mono<String> doesNotWork() {
        return Mono.fromCallable(() -> "Does Not Work").subscribeOn(Schedulers.boundedElastic());
    }
}

I am able to see some of the things you pointed out in the debugger when running the repro app but I'm not entirely clear on what the impact is that is blocking your custom instrumentation.

Here's a trace I see when hitting the /does-not-work route. It is correctly named after the controller route and the utility class method com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber/withNRToken is getting traced. Can you elaborate on what you are expecting to see (or not see) when hitting the /does-not-work route and how it would differ from this?

Also, what version of the Java agent are you using when debugging? Do you have the same issues with the latest version of the agent? We've had quite a few fixes/improvements around Spring/Reactor/Netty/Token linking instrumentation over the past year or so, so if you haven't tested with a recent agent release it would be worth doing so to see if the issue has been resolved.

All of the screenshots in this response are captured while debugging with Java agent version 8.4.0.

Even though I can see the things you pointed out when hitting the /does-not-work route at times while debugging, I also see things that are to the contrary.

For instance, these screenshots show the token being linked when withNRToken is called and the /does-not-work route is hit. It also shows the TraceDetails being instantiated when hitting the same route.

Generally speaking, using @Trace in a utility class is not a problem as we know that it works but there might be a gap in instrumentation somewhere that is causing the transaction context to get lost with your custom instrumentation and thus preventing token linking.

In the past, we've seen cases where an unexpected thread hop due to the use of subscribeOn(Schedulers.boundedElastic()) caused token linking failures. That's a problem that we thought was addressed, and which appears to be looking at the trace I posted, but perhaps there's a gap still present in more complicated scenarios. In cases where the boundedElastic scheduler was causing issues it would manifest as the transaction being named something like NettyDispatcher instead of being correctly named after the Spring controller route.

[philsttr]

The project that you linked didn't have any controllers in it but I added the following based on what you were showing in the YT video. Let me know if this is not correct for the repro.

Oops, I attached the wrong zip. But the controller you mentioned is correct. It's a simple project.

Also, what version of the Java agent are you using when debugging? Do you have the same issues with the latest version of the agent?

When I recorded the video in November, I was using 7.11.0, which was the latest at the time.

I have retested today with 8.4.0.

I still see the problem with 8.4.0, but the behavior is slightly different, as I'll describe below...

Regarding the breakpoint in TraceClassVisitor.visitMethod, restricted to this condition: this.className.contains("com/nr/instrumentation/reactor/netty/TokenLinkingSubscriber") && name.equals("withNRToken")...

That breakpoint will be hit on application startup, where the TraceDetails will be null. This is the same behavior in 8.4.0 as seen in the video for 7.11.0. It shows that TokenLinkingSubscriber.withNRToken is not instrumented properly on application startup.

Resume from the breakpoint, allow the app to finish startup, and then call the does-not-work endpoint.
You will see the following logs repeated in the newrelic log, assuming you enabled the debuging/logging system properties I mentioned in the video. This is the exact same behavior as in the video, and demonstrates the link failures in 8.4.0.

2023-07-26T13:28:09,312+0200 [10743 63] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@9c94c1: ignoring link call because there is no started txa to link to: null.
2023-07-26T13:28:09,313+0200 [10743 63] com.newrelic WARN: Token: com.newrelic.agent.TokenImpl@772d239e 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)?

But, this is where things are slightly different for 8.4.0. Specifically, in 8.4.0 you'll also see this log message, due to this change...

2023-07-26T13:52:34,845+0200 [18461 63] com.newrelic.agent.instrumentation.ClassTransformerServiceImpl FINE: Retransforming com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken for instrumentation.

It appears the link failure now schedules a reinstrumentation of the TokenLinkingSubscriber class, which was not instrumented correctly on startup (when TraceDetails was null above).

A few seconds later, when the PeriodicRetransformer runs, the TraceClassVisitor.visitMethod breakpoint will be hit again. This time the TraceDetails will be non-null when instrumenting TokenLinkingSubscriber.withNRToken.

If you call the does-not-work endpoint again, you won't see the WARN in the logs anymore, which indicates that linking is now working.

Yay! However, all is not working quite yet. Even though token linking in TokenLinkingSubscriber.withNRToken works after it is re-instrumented (when TraceDetails was not null), transaction details are not available where I would expect them to be.

To demonstrate the problem, change the controller to this:

@RestController
public class ExampleController {

	@GetMapping(path = "/works")
	public Mono<String> works() {
		return Mono.fromCallable(() -> response("works"));
	}

	@GetMapping(path = "/does-not-work")
	public Mono<String> doesNotWork() {
		return Mono.fromCallable(() -> response("does-not-work"))
				.subscribeOn(Schedulers.boundedElastic());
	}

	private String response(String endpoint) {
		NewRelic.setTransactionName("custom", endpoint + "-custom-transaction-name");
		NewRelic.addCustomParameter("custom.param", endpoint);

		Transaction transaction = NewRelic.getAgent().getTransaction();
		TracedMethod tracedMethod = transaction.getTracedMethod();
		return endpoint
				+ "\nTransaction:  " + transaction
				+ "\nTracedMethod: " + tracedMethod;
	}
}

I expect the custom transaction name and parameter to be set in all cases.
However, the does-not-work endpoint will fail to set the custom transaction name and parameter after the TokenLinkingSubscriber class is reinstrumented after the first call.

1. Start the application
2. Call does-not-work. Observe that the transaction seen in the response is an instance of TransactionApiImpl
3. Wait for TokenLinkingSubscriber to be reinstrumented (as described above)
4. Call does-not-work again. Observe that the transaction seen in the response is an instance of NoOpTransaction, and the custom transaction and custom parameter are not properly set.

I'm not sure if this behavior is related to the original problem, or something else.

To summarize...

There is still a bug in 8.4.0 in the initial (lack of) instrumentation of TokenLinkingSubscriber.withNRToken during application startup, where TokenDetails is observed as null in TraceClassVisitor.visitMethod. The missing instrumentation on startup is obvious due to the WARN log message on the first call to does-not-work.

There also appears to be a different problem after the reinstrumentation of TokenLinkingSubscriber.

I'd like to resolve the first problem before focusing too much on the second problem.
Specifically, I'd like to get the initial instrumentation of TokenLinkingSubscriber.withNRToken during application startup working.

[philsttr]

Another observation I made... When testing our custom instrumentation that uses a @Trace annotation on a method in a utility class with newrelic-java-agent 8.4.0, I noticed that it does not trigger the reinstrumentation that I mentioned above (the "Retransforming" log line). Therefore, the failed instrumentation of the utility classes during application startup continues to affect the application for the lifetime of the application.

I believe there is sufficient evidence to prove that instrumentation of these utility classes is not working properly during application startup. I believe you have seen this evidence for yourself. Specifically:

• It can be seen in a debugger: when TraceDetails is null when visiting the method annotated with @Trace in a utility class, causing the instrumentation for that method to be skipped.
• It can also be seen in the logs: with the message Did you forget to add @Trace(async = true), when it is clear that @Trace(async = true) is not missing.

Additionally, the "fix" I mentioned in this issue description and in the video of calling ((AgentPostprocessors)weavePackage.getConfig().getPostprocessor()).setTracedWeaveInstrumentationDetails(((AgentPreprocessors)weavePackage.getConfig().getPreprocessor()).getTracedWeaveInstrumentationDetails()) in PackageValidationResult.computeUtilityClassBytes for the utility class in a debugger during application startup continues to solve the problem in 8.4.0. In other words, if I do this, then the initial instrumentation of the utility class during application startup works, and TokenLinkingSubscriber.withNRToken works the first time, and my custom instrumentation works as well.

Since...

1. it is clear that instrumentation of @Trace on a method on some (all?) utility classes is not working on startup, and
2. I can "fix" that instrumentation on startup by setting the tracedWeaveInstrumentationDetails in a debugger, and
3. the @Trace method works properly every time after that (without needing to be reinstrumented), and
4. reinstrumentation of utility classes is not guaranteed to happen after the first failed attempt during startup

... I believe it is critical to fix the problem identified while instrumenting utility classes on startup.

(Side note: I'll be unavailable from 31. July until 4. Aug, but I can respond after that.)

[jasonjkeller]

@philsttr

I opened PR #1443 to test a change that explicitly calls AgentPostprocessors.setTracedWeaveInstrumentationDetails.

As you observed, it has the effect of changing the behavior such that the following is no longer logged, and TokenLinkingSubscriber is no longer being retransformed after calling the /does-not-work endpoint:

WARN: Token: com.newrelic.agent.TokenImpl@772d239e was NOT linked because there was no Transaction in progress

There is a custom build of the agent that you can find here if you want to do any testing with it: https://github.com/newrelic/newrelic-java-agent/actions/runs/5827290767

That said, it does not seem to address the problem that you pointed out with the refactoring of the controller where you are setting the transaction name (i.e. NewRelic.setTransactionName("custom", endpoint + "-custom-transaction-name");). Specifically, the renaming still isn't working when calling the /does-not-work endpoint. I am not entirely sure what is going on other than that a valid transaction doesn't seem to be linked where the response method is being called. There's also a couple of tokens involved in the lifecycle of the transaction.

// TokenImpl@5d74ef44 created
2023-08-10T16:25:39,362-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 created for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: io.netty.bootstrap.NettyDispatcher.channelRead(NettyDispatcher.java:50)
2023-08-10T16:25:39,371-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java)
2023-08-10T16:25:39,377-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 link ignored for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java)

// TokenImpl@34923295 created
2023-08-10T16:25:39,378-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 created for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: org.springframework.web.server.adapter.HttpWebHandlerAdapter.createExchange(HttpWebHandlerAdapter.java)
2023-08-10T16:25:39,382-0700 [43821 70] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken(TokenLinkingSubscriber.java:68)
2023-08-10T16:25:39,382-0700 [43821 70] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken(TokenLinkingSubscriber.java:68)
2023-08-10T16:25:39,383-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java)
2023-08-10T16:25:39,383-0700 [43821 70] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken(TokenLinkingSubscriber.java:68)
2023-08-10T16:25:39,383-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 link ignored for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java)

// TokenImpl@5d74ef44 expired
2023-08-10T16:25:39,386-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@5d74ef44 expired for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.agent.instrumentation.netty40.NettyUtil.processResponse(NettyUtil.java:52)
2023-08-10T16:25:39,386-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 linked for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.instrumentation.reactor.netty.TokenLinkingSubscriber.withNRToken(TokenLinkingSubscriber.java:68)
2023-08-10T16:25:39,387-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 link ignored for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.agent.instrumentation.spring.reactive.Util$TokenLinkingSubscriber.withNRToken(Util.java:78)

// TokenImpl@34923295 expired
2023-08-10T16:25:39,387-0700 [43821 58] com.newrelic INFO: Token: com.newrelic.agent.TokenImpl@34923295 expired for Transaction: com.newrelic.agent.Transaction@5322c2e5, at: com.nr.agent.instrumentation.spring.reactive.Util$TokenLinkingSubscriber.withNRToken(Util.java:78)

Out of curiosity, with your custom instrumentation, is it specifically failing due to this issue with TokenLinkingSubscriber.withNRToken? Or have you introduced a new utility class in your instrumentation that is showing the same behavior?

[philsttr]

Thanks @jasonjkeller !

There is a custom build of the agent that you can find here

Great! I'll test it next week, and let you know how it goes.

That said, it does not seem to address the problem that you pointed out with the refactoring of the controller where you are setting the transaction name

Ok, that might not have been the best test. I'll test our custom instrumentation where I first noticed the problem to confirm the fix.

Out of curiosity, with your custom instrumentation, is it specifically failing due to this issue with TokenLinkingSubscriber.withNRToken? Or have you introduced a new utility class in your instrumentation that is showing the same behavior?

Our custom instrumentation has a new utility class, with some methods annotated with @Trace. This is where I first noticed the problem. Then I looked for other locations that might be affected by the same problem and found the TokenLinkingSubscriber had the same problem.

[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. :)

[jasonjkeller]

Awesome, that's great to hear!

I'll go ahead and submit the PR to the team for review so that we can look to get it into an upcoming agent release.

[jasonjkeller]

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. #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. #1450

Thanks again for all of your help on this issue @philsttr !