Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
jasonjkeller opened this issue Nov 11, 2022 · 7 comments
Open

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

jasonjkeller opened this issue Nov 11, 2022 · 7 comments
Labels
GTSE There is an associated support escalation with this issue.

Comments

@jasonjkeller
Copy link
Contributor

jasonjkeller commented Nov 11, 2022 •
edited
Loading

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. #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
@workato-integration
Copy link

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

@kford-newrelic kford-newrelic mentioned this issue Nov 16, 2022
Closed
@kford-newrelic kford-newrelic added the GTSE There is an associated support escalation with this issue. label Nov 16, 2022
@kford-newrelic
Copy link
Contributor

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

@kford-newrelic
Copy link
Contributor

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

@jasonjkeller
Copy link
Contributor Author

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
Copy link
Contributor Author

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

@wyhasany
Copy link

Hello do you have any updates on this ticket?

@kdebski85
Copy link

I have similar issue without Sleuth.
I use:

  • Spring Boot 3.3.0
  • Java 21.0.3
  • New Relic agent 8.12.0
  • newrelic-api 8.12.0 (I add some custom parameters with addCustomParameter)
  • opentelemetry-sdk with opentelemetry-micrometer-1.5:1.33.2-alpha (I am not sure if it relevant)
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)

@jbedell-newrelic jbedell-newrelic mentioned this issue Aug 19, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
GTSE There is an associated support escalation with this issue.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@wyhasany @jasonjkeller @kdebski85 @kford-newrelic