Handles `javax.servlet.AsyncListener.onComplete` if the processing thread already has a Trace

[koo-taejin]

description

When the onComplete() in javax.servlet.AsyncListener is called on a thread that Reactor or Pinpoint is already has Trace, it will throw exception when executing com.navercorp.pinpoint.bootstrap.plugin.request.AsyncListenerInterceptorHelper#complete().

com.navercorp.pinpoint.exception.PinpointException: not empty call stack
    at com.navercorp.pinpoint.profiler.context.AsyncChildTrace.stackDump(AsyncChildTrace.java:120) ~[pinpoint-profiler-2.4.0.jar:2.4.0]
    at com.navercorp.pinpoint.profiler.context.AsyncChildTrace.close0(AsyncChildTrace.java:194) ~[pinpoint-profiler-2.4.0.jar:2.4.0]
    at com.navercorp.pinpoint.profiler.context.AsyncChildTrace.close(AsyncChildTrace.java:180) ~[pinpoint-profiler-2.4.0.jar:2.4.0]
    at com.navercorp.pinpoint.bootstrap.plugin.request.AsyncListenerInterceptorHelper.close(AsyncListenerInterceptorHelper.java:133) ~[?:2.4.0]
    at com.navercorp.pinpoint.bootstrap.plugin.request.AsyncListenerInterceptorHelper.complete(AsyncListenerInterceptorHelper.java:78) ~[?:2.4.0]
    at com.navercorp.pinpoint.plugin.jetty.JettyAsyncListener.onComplete(JettyAsyncListener.java:62) ~[pinpoint-jetty-plugin-2.4.0.jar:2.4.0]
    at org.eclipse.jetty.server.HttpChannelState.lambda$completed$1(HttpChannelState.java:1009) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1502) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:1225) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannelState.completed(HttpChannelState.java:1003) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$4(HttpChannel.java:538) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:129) ~[jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpOutput.onWriteComplete(HttpOutput.java:334) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpOutput.access$200(HttpOutput.java:62) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpOutput$WriteCompleteCB.succeeded(HttpOutput.java:1924) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.Callback$Nested.succeeded(Callback.java:266) ~[jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel$SendCallback.succeeded(HttpChannel.java:1285) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpConnection$SendCallback.onCompleteSuccess(HttpConnection.java:895) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:326) ~[jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:223) ~[jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:915) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:987) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor.write(GzipHttpOutputInterceptor.java:113) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:285) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpOutput.complete(HttpOutput.java:515) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.Response.completeOutput(Response.java:926) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:538) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:340) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1520) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:1225) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:733) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:72) ~[jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.springframework.http.server.reactive.ServletHttpHandlerAdapter.runIfAsyncNotComplete(ServletHttpHandlerAdapter.java:232) [spring-web-5.2.15.RELEASE.jar:5.2.15.RELEASE]
    at org.springframework.http.server.reactive.ServletHttpHandlerAdapter.access$100(ServletHttpHandlerAdapter.java:58) [spring-web-5.2.15.RELEASE.jar:5.2.15.RELEASE]
    at org.springframework.http.server.reactive.ServletHttpHandlerAdapter$HandlerResultSubscriber.onComplete(ServletHttpHandlerAdapter.java:331) [spring-web-5.2.15.RELEASE.jar:5.2.15.RELEASE]
    at reactor.core.publisher.StrictSubscriber.onComplete(StrictSubscriber.java:123) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:207) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onComplete(ScopePassingSpanSubscriber.java:104) [spring-cloud-sleuth-core-2.2.6.RELEASE.jar:2.2.6.RELEASE]
    at reactor.core.publisher.Operators.complete(Operators.java:135) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]
    at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:234) [reactor-core-3.3.17.RELEASE.jar:3.3.17.RELEASE]

Find and use the appropriate Trace to solve the problem.

[jaehong-kim]

@koo-taejin Hi. It would be nice if it could be reproduced in pinpoint/agent-testweb/jetty-plugin-testweb project. Or please share reproducible sample code.

[koo-taejin]

I fixed the problem without trying to reproduce it because it happened continuously within on my env. If I check how to reproduce it, then I am going to make it.

Thanks :)