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.

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

Improper life cycle management in async servlet API #584

Closed
felixbarny opened this issue Apr 15, 2019 · 1 comment · Fixed by #605
Closed

Improper life cycle management in async servlet API #584

felixbarny opened this issue Apr 15, 2019 · 1 comment · Fixed by #605
Assignees
Labels
bug Bugs

Comments

@felixbarny
Copy link
Member

The /async-start-servlet test case logs warnings. The transaction is activated 3 times but deactivated 4 times.

[2019-04-15T11:43:21.683Z] [jetty] [qtp1983025922-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 00
-00000000000000000000000000000000-9c3a3bf78adb2a20-00 on thread 26
[2019-04-15T11:43:21.683Z] [jetty] [qtp1983025922-26] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span ('' 00-00000000000000000000000000000000-9c3a3bf78adb2a20-00) which is not the currently active span (null). This can happen when not properly deactivating a previous span.
[2019-04-15T11:43:21.683Z] [jetty] [qtp1983025922-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 00-00000000000000000000000000000000-9c3a3bf78adb2a20-00 on thread 26
[2019-04-15T11:43:21.683Z] [jetty] [qtp1983025922-26] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span ('' 00-00000000000000000000000000000000-9c3a3bf78adb2a20-00) which is not the currently active span (null). This can happen when not properly deactivating a previous span.

We should enable assertions in the servlet containers so this fails integration tests

@eyalkoren
Copy link
Contributor

Actually the lifecycle is mostly managed properly - activated and deactivated properly on the initiating thread and ended exactly once in all scenarios.
On the worker thread, things are a bit more complicated- some servlet containers wrap the already-wrapped-Runnable (the one we wrap during AsyncContext#start) and submit to an ExecutorService. If we instrument this ExecutorService, then the servlet-container-Runnable-wrapper escapes our check and gets wrapped again. In such scenarios, the Transaction gets activated and deactivated twice properly. The problem is with

where the first activation clears the stack and the second gets it empty.

We should probably get rid of this stack clearance. Instead, we can force a certain order of deactivate/end only for Transactions, and make the stack check-and-clear on Transaction#end.

In any case, I am adding two checks for this kind of situations:

  1. Avoid activating already active spans in the Runnable/Callable wrappers
  2. Avoid wrapping a wrapped Runnable/Callable by maintaining a thread-local state in the entry and exit of instrumented methods where we do wrapping

In addition, Jetty and Payara exposed another problem- AsyncContext#complete is called on the same thread that runs the Runnable, so it deactivates the Transaction before Runnable#run is ended and on the same thread. The fix for this is not deactivating spans from the AsyncContexListener explicitly when invoking

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Bugs
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants