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

Fix jetty context leak #1966

Merged
merged 1 commit into from
Jan 5, 2021
Merged

Fix jetty context leak #1966

merged 1 commit into from
Jan 5, 2021

Conversation

laurit
Copy link
Contributor

@laurit laurit commented Dec 28, 2020

Fix flaky JettyServlet3TestDispatchAsync test success with #count requests. Occasionally creating server span fails with

java.lang.IllegalStateException: Context leak detected
	at io.opentelemetry.instrumentation.api.tracer.BaseTracer.debugContextLeak(BaseTracer.java:208)
	at io.opentelemetry.instrumentation.api.tracer.BaseTracer.extract(BaseTracer.java:171)
	at io.opentelemetry.instrumentation.api.tracer.HttpServerTracer.startSpan(HttpServerTracer.java:72)
	at io.opentelemetry.instrumentation.api.tracer.HttpServerTracer.startSpan(HttpServerTracer.java:56)
	at io.opentelemetry.instrumentation.servlet.ServletHttpServerTracer.startSpan(ServletHttpServerTracer.java:29)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:724)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:558)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:489)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:972)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:417)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:906)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
	at org.eclipse.jetty.server.Server.handle(Server.java:346)
	at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:442)
	at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:910)
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:565)
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:217)
	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:46)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:545)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:43)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
	at java.base/java.lang.Thread.run(Thread.java:834)

Unexpected non-root current context found when extracting remote context!
It contains this span: RecordEventsReadableSpan{traceId=704ef07f14b079fffc7e9353059b3213, spanId=312d204c09674822, parentSpanContext=ImmutableSpanContext{traceIdAsHexString=00000000000000000000000000000000, spanIdAsHexString=0000000000000000, traceFlags=0, traceState=ArrayBasedTraceState{entries=[]}, remote=false}, name=/jetty-context/dispatch/success, kind=SERVER, attributes=AttributesMap{data={net.peer.ip=127.0.0.1, net.peer.port=62888, http.method=GET, http.user_agent=test-user-agent, http.url=http://localhost:62887/jetty-context/dispatch/success, http.flavor=HTTP/1.1, http.client_ip=1.1.1.1, http.status_code=200}, capacity=1000, totalAddedValues=8}, status=ImmutableStatus{statusCode=UNSET, description=null}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1608767918165001531, endEpochNanos=1608767918213995466}
a context leak was detected. it was propagated from:
io.opentelemetry.javaagent.instrumentation.api.concurrent.ExecutorInstrumentationUtils.setupState(ExecutorInstrumentationUtils.java:70)
org.eclipse.jetty.util.thread.QueuedThreadPool.dispatch(QueuedThreadPool.java:350)
org.eclipse.jetty.server.AsyncContinuation.start(AsyncContinuation.java:834)
javax.servlet.AsyncContext$start$0.call(Unknown Source)
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:115)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:127)
TestServlet3$Async.service(TestServlet3.groovy:57)
javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:558)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:489)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:972)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:417)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:906)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
org.eclipse.jetty.server.Server.handleAsync(Server.java:391)
org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:447)
org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:43)
org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:545)
org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:43)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
java.base/java.lang.Thread.run(Thread.java:834)
which was propagated from:
io.opentelemetry.javaagent.instrumentation.api.concurrent.ExecutorInstrumentationUtils.setupState(ExecutorInstrumentationUtils.java:70)
org.eclipse.jetty.util.thread.QueuedThreadPool.dispatch(QueuedThreadPool.java:350)
org.eclipse.jetty.server.nio.SelectChannelConnector$ConnectorSelectorManager.dispatch(SelectChannelConnector.java:339)
org.eclipse.jetty.io.nio.SelectChannelEndPoint.dispatch(SelectChannelEndPoint.java:204)
org.eclipse.jetty.server.AsyncContinuation.scheduleDispatch(AsyncContinuation.java:662)
org.eclipse.jetty.server.AsyncContinuation.dispatch(AsyncContinuation.java:434)
org.eclipse.jetty.server.AsyncContinuation.dispatch(AsyncContinuation.java:803)
javax.servlet.AsyncContext$dispatch$1.call(Unknown Source)
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:115)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:127)
TestServlet3$DispatchAsync$_service_closure1.doCall(TestServlet3.groovy:149)
TestServlet3$DispatchAsync$_service_closure1.doCall(TestServlet3.groovy)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:101)
groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)
groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)
groovy.lang.Closure.call(Closure.java:405)
groovy.lang.Closure.call(Closure.java:399)
groovy.lang.Closure.run(Closure.java:486)
org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1026)
org.eclipse.jetty.server.AsyncContinuation$1.run(AsyncContinuation.java:838)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
java.base/java.lang.Thread.run(Thread.java:834)
which was propagated from:
io.opentelemetry.javaagent.instrumentation.api.concurrent.ExecutorInstrumentationUtils.setupState(ExecutorInstrumentationUtils.java:70)
org.eclipse.jetty.util.thread.QueuedThreadPool.dispatch(QueuedThreadPool.java:350)
org.eclipse.jetty.server.AsyncContinuation.start(AsyncContinuation.java:834)
javax.servlet.AsyncContext$start$0.call(Unknown Source)
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:115)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:127)
TestServlet3$DispatchAsync.service(TestServlet3.groovy:148)
javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:558)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:489)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:972)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:417)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:906)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
org.eclipse.jetty.server.Server.handle(Server.java:346)
org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:442)
org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:910)
org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:565)
org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:217)
org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:46)
org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:545)
org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:43)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
java.base/java.lang.Thread.run(Thread.java:834)

trask
trask approved these changes Jan 5, 2021
View reviewed changes
Copy link
Member

@trask trask left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🎉

@trask trask merged commit 1671951 into open-telemetry:master Jan 5, 2021
@laurit laurit deleted the jetty-context-leak branch August 24, 2021 07:47
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@trask trask trask approved these changes

@anuraaga anuraaga Awaiting requested review from anuraaga

@iNikem iNikem Awaiting requested review from iNikem

@jkwatson jkwatson Awaiting requested review from jkwatson

@mateuszrzeszutek mateuszrzeszutek Awaiting requested review from mateuszrzeszutek

@tylerbenson tylerbenson Awaiting requested review from tylerbenson

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@laurit @trask