search

newrelic / newrelic-java-agent

The New Relic Java agent
Apache License 2.0
202 stars 145 forks source link

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

Open jasonjkeller opened 2 years ago

jasonjkeller commented 2 years ago

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:

workato-integration[bot] commented 2 years ago

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

kford-newrelic commented 2 years ago

Will consider as a future agent roadmap item/for a future quarter

kford-newrelic commented 2 years ago

Note : This situation may still occur, even when Spring Cloud Sleuth is disabled, so consider alternate ways this same behavior could be triggered

jasonjkeller commented 2 years ago

It looks like it is still something Spring related. In the latest logs I see this tracer for org.springframework.hateoas.config.WebMvcHateoasConfiguration$DummyInvocationUtilsCacheClearer.afterCompletion as the problematic one that is pointing to a NoOpTracer as its parent tracer.

2022-11-15T15:57:35,398+0000 [1 546] com.newrelic FINER: Tracer (com.newrelic.agent.tracers.DefaultTracer@5c598ce9) Started: org.springframework.hateoas.config.WebMvcHateoasConfiguration$DummyInvocationUtilsCacheClearer.afterCompletion(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Ljava/lang/Object;Ljava/lang/Exception;)V
2022-11-15T15:57:35,398+0000 [1 546] com.newrelic INFO: Tracer Debug: lastTracer set to com.newrelic.agent.tracers.NoOpTracer@2a9baf2, tracer = com.newrelic.agent.tracers.DefaultTracer@5c598ce9
2022-11-15T15:57:35,398+0000 [1 546] com.newrelic ERROR: Inconsistent state!  tracer != last tracer for com.newrelic.agent.TransactionActivity@0 (com.newrelic.agent.tracers.DefaultTracer@60a202a9 != com.newrelic.agent.tracers.NoOpTracer@2a9baf2)
jasonjkeller commented 2 years ago

Likely related to either the com.newrelic.instrumentation.spring-4.3.0 or com.newrelic.agent.instrumentation.pointcuts.frameworks.spring.SpringPointCut instrumentation.

wyhasany commented 1 year ago

Hello do you have any updates on this ticket?

kdebski85 commented 5 months ago

I have similar issue without Sleuth. I use:

2024-06-24T09:26:12,302+0000 [1 87] com.newrelic ERROR: Tracer Debug: Inconsistent state! tracer (actual tracer popped off stack) != lastTracer (pointer to top of stack) for com.newrelic.agent.TransactionActivity@42 (com.newrelic.agent.tracers.DefaultTracer@7ce43a8a != com.newrelic.agent.tracers.DefaultTracer@66605e92)
2024-06-24T09:26:12,302+0000 [1 87] com.newrelic ERROR: Tracer Debug: Inconsistent state! tracer (actual tracer popped off stack) != lastTracer (pointer to top of stack) for com.newrelic.agent.TransactionActivity@42 (com.newrelic.agent.tracers.DefaultTracer@3e0ff83a != com.newrelic.agent.tracers.DefaultTracer@66605e92)
2024-06-24T09:26:12,302+0000 [1 87] com.newrelic ERROR: Tracer Debug: Inconsistent state! tracer (actual tracer popped off stack) != lastTracer (pointer to top of stack) for com.newrelic.agent.TransactionActivity@42 (com.newrelic.agent.tracers.OtherRootTracer@391a244d != com.newrelic.agent.tracers.DefaultTracer@66605e92)