Change Async Servlet span end logic to fix race condition on Undertow #2992

agoallikmaa · 2021-05-14T06:09:16Z

After enabling concurrency test to RestEasy HTTP server tests, it turned out that test intermittently fails when it uses Undertow as the servlet engine. This was because of a race condition in Async Servlet instrumentations - the async listener events were fired before the method exit instrumentation added the listener, yet the isAsyncStarted method did not yet revert to returning false.

There does not seem to be a straightforward way to avoid races like this properly in the servlet service method exit instrumentation, therefore I moved adding the async listener to the instrumentation of the startAsync method itself, which should guarantee that that the listener is added to the AsyncContext before it is possible for them to be invoked.

The logic in service method exit itself was reduced to simply checking if an async listener has already been attached to this request - this information is saved in the request attributes at the time when the listener is added. In case the listener is not present, assume it is a synchronous request and end it immediately.

agoallikmaa · 2021-05-14T10:12:42Z

Added fix for Liberty - response object attached as an attribute to request because on Liberty, AsyncContext#addListener(AsyncListener, ServletRequest, ServletResponse) must be called instead of AsyncContext#addListener(AsyncListener)

trask

The logic in service method exit itself was reduced to simply checking if an async listener has already been attached to this request

👍 this looks like a solid approach

...t-common/library/src/main/java/io/opentelemetry/instrumentation/servlet/ServletAccessor.java

...telemetry/javaagent/instrumentation/servlet/common/service/ServletAndFilterAdviceHelper.java

...ain/java/io/opentelemetry/javaagent/instrumentation/servlet/v5_0/async/AsyncStartAdvice.java

...n/java/io/opentelemetry/javaagent/instrumentation/servlet/v3_0/Servlet3AsyncStartAdvice.java

trask · 2021-05-15T23:34:45Z

...src/main/java/io/opentelemetry/javaagent/instrumentation/liberty/LibertyStartSpanAdvice.java

+    // For startAsync instrumentation to work on Liberty, the listener needs to be added with a
+    // response object included, which is not available in that instrumentation.


it seems like we should always be passing request/response to AsyncContext.addListener(), since our listener calls AsyncEvent.getSuppliedRequest() and AsyncEvent.getSuppliedResponse().

-- or --

maybe our listener should call event.getAsyncContext().getRequest() and event.getAsyncContext().getResponse() instead, and then maybe we don't ever need to pass request/response?

event.getAsyncContext().getResponse() does not seem to solve the current issue with Liberty as it is not available there either (and the spec allows it to be missing). Passing the response would mean storing the response as a request attribute for all servlet engines - I am not sure if we want to do that preemptively for all of them.

If we don't pass request/response to AsyncContext.addListener(), won't AsyncEvent.getSuppliedResponse() (which we call in our listener) always return null?

If the AsyncListener was added via AsyncContext.addListener(AsyncListener), this method must return null.

https://docs.oracle.com/javaee/7/api/javax/servlet/AsyncEvent.html#getSuppliedResponse--

According to documentation, yes, but apparently that was not the case in practice...

I've attached the servlet response as an attribute on all servlet engines now (in generic servlet instrumentation, and Tomcat and Jetty specific instrumentations).

trask · 2021-05-15T23:39:06Z

...telemetry/javaagent/instrumentation/servlet/common/service/ServletAndFilterAdviceHelper.java

+    // 2) asynchronously handled request, but startAsync instrumentation is broken on this server
+    //    (should be caught by tests for the specific server).
+    // In case of broken startAsync instrumentation, no fallback handling for asynchronous requests
+    // should be provided as handling it in the handler/service method is  prone to race conditions
+    // (seen happening on Undertow) that may make some tests pass which should fail due to the
+    // possible race.


i'm hoping we can remove this part about broken startAsync instrumentation if the above comment turns out to be fruitful

I actually added this comment before I encountered the issue with Liberty - so its purpose is to be a hint for debugging and to make it clear to the reader why we even need a separate instrumentation in the first place.

since Liberty was following spec (and not broken), can we remove (or modify) this comment?

Rephrased the comment

.../library/src/main/java/io/opentelemetry/instrumentation/servlet/ServletHttpServerTracer.java

trask · 2021-05-21T18:52:52Z

...c/main/java/io/opentelemetry/javaagent/instrumentation/jetty/v11_0/Jetty11HandlerAdvice.java

@@ -31,6 +32,8 @@ public static void onEnter(

    context = tracer().startServerSpan(request);
    scope = context.makeCurrent();
+
+    tracer().setAsyncListenerResponse(request, response);


do we need to add calls to setAsyncListenerResponse in each app server instrumentation, or can we do it once in servlet instrumentation?

Yes, since it is possible for requests to be handled entirely within app server handlers without servlet advices ever triggering.

can those requests have servlet async listeners?

Jetty handlers and Tomcat valves both expose the ServletRequest and are allowed to generate the response without a servlet ever being invoked. I have not tested using startAsync in them, but the documentation does not say that either of them would only support synchronous responses.

can you add comments to the code explaining this? otherwise worried these lines could be removed thinking they aren't really needed, and I don't think we have any tests that it would break

Added those comments for all the appservers.

laurit · 2021-05-24T17:26:08Z

...ent/src/main/java/io/opentelemetry/javaagent/instrumentation/liberty/ThreadLocalContext.java

  private Context context;
  private Scope scope;
  private boolean started;

-  private ThreadLocalContext(HttpServletRequest req) {
+  private ThreadLocalContext(HttpServletRequest req, HttpServletResponse response) {


could you rename req -> request in this class to make it consistent with our style of using verbose names

…l ignores

laurit · 2021-05-25T10:22:28Z

...n/java/io/opentelemetry/javaagent/instrumentation/servlet/v3_0/Servlet3AsyncStartAdvice.java

+
+  @Advice.OnMethodExit(suppress = Throwable.class)
+  public static void startAsyncExit(
+      @Advice.This(typing = Assigner.Typing.DYNAMIC) HttpServletRequest request) {


I think that instead of dynamic typing to HttpServletRequest it would be better to use @Advice.This ServletRequest request and use instanceof+cast to get HttpServletRequest.

laurit · 2021-05-25T10:31:37Z

...n/java/io/opentelemetry/javaagent/instrumentation/servlet/v3_0/Servlet3AsyncStartAdvice.java

+      return;
+    }
+
+    if (request != null) {


can request really be null here?

Replaced with instanceof due to the typing change.

...telemetry/javaagent/instrumentation/servlet/common/service/ServletAndFilterAdviceHelper.java

laurit · 2021-05-25T10:41:53Z

...o/opentelemetry/javaagent/instrumentation/tomcat/common/TomcatServerHandlerAdviceHelper.java

-
-      // In case the request finished before adding the listener on older tomcats...
-      if (!servletRequest.isAsyncStarted() && responseHandled.compareAndSet(false, true)) {
+    if (servletRequest != null) {


could combine these if statements

trask

@agoallikmaa thanks for your patience, and great find btw 👍

…open-telemetry#2992) * Attach servlet async listener with asyncStart instrumentation * Exclude Spring packages containing servlet request classes from global ignores * Exclude Tapestry HSR proxy with global ignore * Improve comments. * Fix for Liberty - request response when adding async listener * Removed unused methods * Explicit response to async listeners on all servlet engines * Attach response to request on Jetty * Fix broken build due to rebase, improved a comment * Address PR comments * Added a comment. * Addressed PR comments

agoallikmaa requested review from anuraaga, iNikem, jkwatson, laurit, mateuszrzeszutek, pavolloffay, trask and tylerbenson as code owners May 14, 2021 06:09

mateuszrzeszutek approved these changes May 14, 2021

View reviewed changes

agoallikmaa force-pushed the servlet-startasync branch from 1a2572f to 93638d8 Compare May 14, 2021 10:09

mateuszrzeszutek approved these changes May 14, 2021

View reviewed changes

trask reviewed May 15, 2021

View reviewed changes

agoallikmaa force-pushed the servlet-startasync branch from 14c69c4 to 622f291 Compare May 20, 2021 15:26

trask reviewed May 21, 2021

View reviewed changes

laurit reviewed May 24, 2021

View reviewed changes

agoallikmaa added 11 commits May 25, 2021 00:16

Attach servlet async listener with asyncStart instrumentation

a2dc390

Exclude Spring packages containing servlet request classes from globa…

3f57b9a

…l ignores

Exclude Tapestry HSR proxy with global ignore

0af651b

Improve comments.

308ff19

Fix for Liberty - request response when adding async listener

26ce952

Removed unused methods

a0377ee

Explicit response to async listeners on all servlet engines

4fafd7f

Attach response to request on Jetty

b2552fa

Fix broken build due to rebase, improved a comment

287b0f2

Address PR comments

995eba1

Added a comment.

512dc97

agoallikmaa force-pushed the servlet-startasync branch from 3314dca to 512dc97 Compare May 24, 2021 21:16

laurit reviewed May 25, 2021

View reviewed changes

...telemetry/javaagent/instrumentation/servlet/common/service/ServletAndFilterAdviceHelper.java Show resolved Hide resolved

laurit reviewed May 25, 2021

View reviewed changes

laurit approved these changes May 25, 2021

View reviewed changes

Addressed PR comments

763aef7

trask approved these changes May 26, 2021

View reviewed changes

trask merged commit fd132d4 into open-telemetry:main May 26, 2021

ryandens mentioned this pull request Aug 4, 2021

Upgrade OTEL to 1.3.1 hypertrace/javaagent#341

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Change Async Servlet span end logic to fix race condition on Undertow #2992

Change Async Servlet span end logic to fix race condition on Undertow #2992

agoallikmaa commented May 14, 2021

agoallikmaa commented May 14, 2021

trask left a comment •

edited

Loading

trask May 15, 2021

agoallikmaa May 19, 2021

trask May 19, 2021

agoallikmaa May 20, 2021

trask May 15, 2021

agoallikmaa May 19, 2021

trask May 20, 2021

agoallikmaa May 20, 2021

trask May 21, 2021

agoallikmaa May 23, 2021 •

edited

Loading

trask May 23, 2021

agoallikmaa May 24, 2021

trask May 24, 2021

agoallikmaa May 24, 2021

laurit May 24, 2021

agoallikmaa May 24, 2021

laurit May 25, 2021

agoallikmaa May 25, 2021

laurit May 25, 2021

agoallikmaa May 25, 2021

laurit May 25, 2021

agoallikmaa May 25, 2021

trask left a comment

		// For startAsync instrumentation to work on Liberty, the listener needs to be added with a
		// response object included, which is not available in that instrumentation.

Change Async Servlet span end logic to fix race condition on Undertow #2992

Change Async Servlet span end logic to fix race condition on Undertow #2992

Conversation

agoallikmaa commented May 14, 2021

agoallikmaa commented May 14, 2021

trask left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

agoallikmaa May 23, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trask left a comment

Choose a reason for hiding this comment

trask left a comment •

edited

Loading

agoallikmaa May 23, 2021 •

edited

Loading