Incompatibility with Spring Cloud Sleuth can cause "Inconsistent state! tracer != last tracer errors"

The Java agent does not currently support Spring Cloud Sleuth and using it can cause a clash with Java agent instrumentation that leads to the following Inconsistent state! tracer != lastTracer errors.

2022-11-09T14:47:03,181+0000 [1 49] com.newrelic ERROR: Inconsistent state!  tracer != lastTracer for com.newrelic.agent.TransactionActivity@0 (com.newrelic.agent.tracers.DefaultTracer@67bb6aec != com.newrelic.agent.tracers.NoOpTracer@1d1a05c7)

For context, this issue occurs when the agent is handling some async activity and is adding tracers for each method call and popping tracers off the stack as each method call completes. The agent tracks what the first tracer (root tracer) is when the async activity started and by the end we would expect that that last tracer we pop off should be the root, but in this case it isn't, which means that the agent has lost track of the correct call stack into this async code. When the pointer to the tracer object at the top of the stack differs from the actual tracer object that gets popped off then the agent is in an inconsistent state. If this happens the agent discards the async information it was attempting to record and logs the inconsistent state error.

A separate PR adds extra debug logging to the agent to help troubleshoot such issues. https://github.com/newrelic/newrelic-java-agent/pull/1066

Here is some analysis of such debug logging (note that the logging will change slightly when PR #1066 is merged):

// We set the initial root tracer for the TransactionActivity and add it to the stack
2022-11-09T14:47:03,172+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer and rootTracer set to com.newrelic.agent.tracers.OtherRootTracer@42ec8c4a

// We continue to add more tracers to the stack in the order shown
2022-11-09T14:47:03,172+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@3648f43c
2022-11-09T14:47:03,172+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@10e0b063
2022-11-09T14:47:03,172+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@c6c1633
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@1a8301e2
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@6b9bff9a
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@7e6d2922
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@12dc7552
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@1052eafa
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@2401a045
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@3332b9de
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@42b52c0f
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@45370b99
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@6c1d88f2
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@4a4730e6
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@21f9a8f5
2022-11-09T14:47:03,173+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@5c6f1490
2022-11-09T14:47:03,174+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@5cb55df7
2022-11-09T14:47:03,174+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@2f868687
2022-11-09T14:47:03,174+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.OtherRootTracer@43543d82
2022-11-09T14:47:03,174+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@1197d909

// When the last tracer (i.e. DefaultTracer@1197d909) is finished we pop it off the top of the stack and set the lastTracer pointer to tracer that is now at the top of the stack (i.e. DefaultTracer@67bb6aec)
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.tracers.DefaultTracer@1197d909

// Here we can see that we interleave adding more tracers to the stack and popping others off as they finish, each time trying to keep the lastTracer pointer accurately pointing to the tracer that is at the top of the stack
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@a3ed702
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.tracers.DefaultTracer@a3ed702
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@686443ea
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.tracers.DefaultTracer@686443ea
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@5434b800
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.tracers.DefaultTracer@5434b800
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@7bc47c1e
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.tracers.DefaultTracer@7bc47c1e
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.instrumentation.pointcuts.frameworks.spring.SpringPointCut$1@7be22a3
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@4d0f4aad
2022-11-09T14:47:03,175+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@12ab3da0
2022-11-09T14:47:03,177+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@4d0f4aad, tracer = com.newrelic.agent.tracers.DefaultTracer@12ab3da0
2022-11-09T14:47:03,178+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.instrumentation.pointcuts.frameworks.spring.SpringPointCut$1@7be22a3, tracer = com.newrelic.agent.tracers.DefaultTracer@4d0f4aad

// At this point we pop off the SpringPointCut$1@7be22a3 tracer and correctly set the lastTracer (top of the stack) to DefaultTracer@67bb6aec
2022-11-09T14:47:03,180+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@67bb6aec, tracer = com.newrelic.agent.instrumentation.pointcuts.frameworks.spring.SpringPointCut$1@7be22a3

// The problem seems to occur here, we now add a new tracer (i.e. DefaultTracer@53f2914f) to the top of the stack and it should point to DefaultTracer@67bb6aec as being the tracer directly below it on the stack. On the next line when we pop DefaultTracer@53f2914f from the stack it incorrectly sets lastTracer to NoOpTracer@1d1a05c7 which is a tracer that was never added to the stack. In reality it should have set lastTracer to DefaultTracer@67bb6aec.
2022-11-09T14:47:03,181+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@53f2914f
2022-11-09T14:47:03,181+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.NoOpTracer@1d1a05c7, tracer = com.newrelic.agent.tracers.DefaultTracer@53f2914f

// At this point we've lost track of which tracer actually is on top of the stack. Clearly DefaultTracer@67bb6aec does not equal NoOpTracer@1d1a05c7.
2022-11-09T14:47:03,181+0000 [1 49] com.newrelic ERROR: Inconsistent state!  tracer != last tracer for com.newrelic.agent.TransactionActivity@0 (com.newrelic.agent.tracers.DefaultTracer@67bb6aec != com.newrelic.agent.tracers.NoOpTracer@1d1a05c7)

So what causes DefaultTracer@53f2914f to incorrectly point to NoOpTracer@1d1a05c7 ??? Somehow this is the result that is returned when calling tracer.getParentTracer on DefaultTracer@53f2914f.

Here's info about DefaultTracer@53f2914f:

2022-11-09T14:47:03,181+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.DefaultTracer@53f2914f
2022-11-09T14:47:03,181+0000 [1 49] com.newrelic FINER: Tracer (com.newrelic.agent.tracers.DefaultTracer@53f2914f) Started: org.springframework.cloud.sleuth.instrument.web.mvc.SpanCustomizingAsyncHandlerInterceptor.postHandle(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Ljava/lang/Object;Lorg/springframework/web/servlet/ModelAndView;)V
2022-11-09T14:47:03,181+0000 [1 49] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.NoOpTracer@1d1a05c7, tracer = com.newrelic.agent.tracers.DefaultTracer@53f2914f 

It appears to be an incompatibility with Spring Cloud Slueth? Likely the SpanCustomizingAsyncHandlerInterceptor is causing the agent to lose track of the active transaction, thus leading to the creation of a NoOpTracer.

Until Spring Cloud Sleuth is properly supported the options are:

• Disable Spring Cloud Sleuth to avoid the conflict
• Accept that some async spans will be dropped for traces that encounter the Inconsistent state error

Start with TransactionActivity.java at getParentTracer and trace how DefaultTracer is created and removed during async activity. Compare that flow with SpringPointCut and Spring Cloud Sleuth's SpanCustomizingAsyncHandlerInterceptor, using the reported debug sequence as the reproduction guide. Done means Sleuth no longer causes inconsistent tracer state or dropped async spans.