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

Jetty Connection Closed When Application Attempts to Write - intermittent issue under load #3684

Closed
abennet opened this issue May 21, 2019 · 12 comments
Labels
Stale For auto-closed stale issues and pull requests

Comments

@abennet
Copy link

abennet commented May 21, 2019

Since upgrading jetty (7.x to 9.14) our server has been experiencing intermittent jetty EofExceptions under load with https traffic.
The stack traces are only seen as part of GET operations, and our analysis shows that our server is attempting to write the response to the jetty response, and the exception is triggered at this point because the jetty ResponseWriter already has an exception when the application attempts the first write (see ResponseWriter:isOpen, _ioException is non-null).

We have two concerning stack traces we are trying to understand/analyze.

Here is the first stack trace we see from failing to write the response of get requests:

05/10 10:40:22.304 org.eclipse.jetty.io.RuntimeIOException
05/10 10:40:22.304 org.eclipse.jetty.io.RuntimeIOException
05/10 10:40:22.304 org.eclipse.jetty.io.EofException

05/10 10:40:22.304 at TRACE ID 000000000000004a org.eclipse.jetty.server.ResponseWriter.isOpen(ResponseWriter.java:133)
05/10 10:40:22.304 at org.eclipse.jetty.server.ResponseWriter.write(ResponseWriter.java:202)
05/10 10:40:22.304 at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:129)
05/10 10:40:22.304 at java.io.BufferedWriter.flush(BufferedWriter.java:253)
05/10 10:40:22.304 at com.sun.xml.bind.v2.runtime.MarshallerImpl.cleanUp(MarshallerImpl.java:344)
05/10 10:40:22.304 at com.sun.xml.bind.v2.runtime.MarshallerImpl.write(MarshallerImpl.java:337)
05/10 10:40:22.304 at com.sun.xml.bind.v2.runtime.MarshallerImpl.marshal(MarshallerImpl.java:254)
05/10 10:40:22.304 at javax.xml.bind.helpers.AbstractMarshallerImpl.marshal(AbstractMarshallerImpl.java:116)
05/10 10:40:22.304 at com.myserver.JAXBUtil.toXml(JAXBUtil.java:182)
...
05/10 10:40:22.304 at com.myserver.GetHandler.process(GetHandler.java:893)
05/10 10:40:22.304 at com.myserver.GetHandler.doGet(GetHandler.java:167)
05/10 10:40:22.304 at com.myserver.GetHandler.execute(GetHandler.java:109)
05/10 10:40:22.304 at com.myserver.GetHandler.execute(GetHandler.java:59)
05/10 10:40:22.304 at com.myserver.Interface.doGetHelper(Interface.java:97)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
java.io.IOException
Close org.eclipse.jetty.server.HttpConnection$SendCallback@2d938872[PROCESSING] [i=HTTP/1.1{s=200,h=13,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@22fc2a6e] in state PROCESSING

Additionally and possibly more concerning is that we were able to catch a stack trace that originates in the reserved thread management (see attached). It seems to be a known issue in jetty (#3652)

org.eclipse.jetty.io.EofException

at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:284)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:909)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:823)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:850)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:921)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:249)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:225)
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:307)
at org.eclipse.jetty.server.HttpWriter.close(HttpWriter.java:49)
at org.eclipse.jetty.server.ResponseWriter.close(ResponseWriter.java:163)
at org.eclipse.jetty.server.Dispatcher.commitResponse(Dispatcher.java:260)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:230)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:78)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1679)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:513)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.Server.handle(Server.java:505)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321)
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:387)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:724)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:830)
at java.lang.Thread.run(Thread.java:748)
Caused by:
java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
at sun.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:262)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:909)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:823)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:850)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:921)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:249)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:225)
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:307)
at org.eclipse.jetty.server.HttpWriter.close(HttpWriter.java:49)
at org.eclipse.jetty.server.ResponseWriter.close(ResponseWriter.java:163)
at org.eclipse.jetty.server.Dispatcher.commitResponse(Dispatcher.java:260)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:230)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:78)
......
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:513)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.Server.handle(Server.java:505)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321)
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:387)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:724)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:830)
at java.lang.Thread.run(Thread.java:748)
2019-05-20 13:01:32.610:DBUG:oeji.AbstractEndPoint:qtp1514035599-251: close(org.eclipse.jetty.io.EofException) DecryptedEndPoint@56d419dd{/172.18.10.89:60658<->/172.20.65.155:8483,OPEN,fill=-,flush=W,to=1770/600000}
2019-05-20 13:01:32.611:DBUG:oejis.SslConnection:qtp1514035599-251: shutdownOutput: SslConnection@409705ac::SocketChannelEndPoint@192eeeb3{/172.18.10.89:60658<->/172.20.65.155:8483,OPEN,fill=-,flush=-,to=7/600000}{io=0/0,kio=0,kro=1}->SslConnection@409705ac{NOT_HANDSHAKING,eio=-1/53,di=-1,fill=IDLE,flush=IDLE}>DecryptedEndPoint@56d419dd{/172.18.10.89:60658<->/172.20.65.155:8483,CLOSED,fill=-,flush=W,to=1771/600000}=>HttpConnection@67486c1b[p=HttpParser{s=END,0 of -1},g=HttpGenerator@36fbe692{s=COMPLETING}]=>HttpChannelOverHttp@13d685c3{r=9,c=true,c=false/false,a=DISPATCHED,uri=https://myserver.com/hs3/bucket1?delimiter=%2F&max-keys=1000&prefix=,age=169} oshut=false, ishut=false {}
2019-05-20 13:01:32.612:DBUG:oejis.SslConnection:qtp1514035599-251: >flush SslConnection@409705ac::SocketChannelEndPoint@192eeeb3{/172.18.10.89:60658<->/172.20.65.155:8483,OPEN,fill=-,flush=-,to=8/600000}{io=0/0,kio=0,kro=1}->SslConnection@409705ac{NEED_WRAP,eio=-1/53,di=-1,fill=IDLE,flush=IDLE}
>DecryptedEndPoint@56d419dd{/172.18.10.89:60658<->/172.20.65.155:8483,CLOSED,fill=-,flush=W,to=1772/600000}=>HttpConnection@67486c1b[p=HttpParser{s=END,0 of -1},g=HttpGenerator@36fbe692{s=COMPLETING}]=>HttpChannelOverHttp@13d685c3{r=9,c=true,c=false/false,a=DISPATCHED,uri=https://myserver.com/hs3/bucket1?delimiter=%2F&max-keys=1000&prefix=,age=170}
2019-05-20 13:01:32.612:DBUG:oejis.SslConnection:qtp1514035599-251: flush b[0]=HeapByteBuffer@1a05a781[p=0,l=0,c=0,r=0]={<<<>>>}
2019-05-20 13:01:32.613:DBUG:oejis.SslConnection:qtp1514035599-251: SslConnection@409705ac::SocketChannelEndPoint@192eeeb3{/172.18.10.89:60658<->/172.20.65.155:8483,OPEN,fill=-,flush=-,to=9/600000}{io=0/0,kio=0,kro=1}->SslConnection@409705ac{NEED_WRAP,eio=-1/53,di=-1,fill=IDLE,flush=IDLE}~>DecryptedEndPoint@56d419dd{/172.18.10.89:60658<->/172.20.65.155:8483,CLOSED,fill=-,flush=W,to=1773/600000}=>HttpConnection@67486c1b[p=HttpParser{s=END,0 of -1},g=HttpGenerator@36fbe692{s=COMPLETING}]=>HttpChannelOverHttp@13d685c3{r=9,c=true,c=false/false,a=DISPATCHED,uri=https://myserver.com/hs3/bucket1?delimiter=%2F&max-keys=1000&prefix=,age=171}
org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:284)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:839)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doShutdownOutput(SslConnection.java:1110)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doClose(SslConnection.java:1176)
at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:220)
at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:983)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:823)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:850)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:921)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:249)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:225)
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:307)
at org.eclipse.jetty.server.HttpWriter.close(HttpWriter.java:49)
at org.eclipse.jetty.server.ResponseWriter.close(ResponseWriter.java:163)
at org.eclipse.jetty.server.Dispatcher.commitResponse(Dispatcher.java:260)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:230)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:78)
at com.myserver.Filter.doFilter(Filter.java:111)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1679)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:513)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.Server.handle(Server.java:505)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321)
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:387)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:724)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:830)
at java.lang.Thread.run(Thread.java:748)
Caused by:
java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
at sun.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:262)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:839)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doShutdownOutput(SslConnection.java:1110)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doClose(SslConnection.java:1176)
at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:220)
at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:983)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:823)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:850)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:921)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:249)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:225)
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:307)
at org.eclipse.jetty.server.HttpWriter.close(HttpWriter.java:49)
at org.eclipse.jetty.server.ResponseWriter.close(ResponseWriter.java:163)
at org.eclipse.jetty.server.Dispatcher.commitResponse(Dispatcher.java:260)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:230)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:78)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1687)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1679)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:513)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.eclipse.jetty.server.Server.handle(Server.java:505)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321)
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:387)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:724)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:830)
at java.lang.Thread.run(Thread.java:748)
2019-05-20 13:01:32.618:DBUG:oeji.AbstractEndPoint:qtp1514035599-251: close(org.eclipse.jetty.io.EofException) DecryptedEndPoint@56d419dd{/172.18.10.89:60658<->/172.20.65.155:8483,CLOSED,fill=-,flush=W,to=1778/600000}
2019-05-20 13:01:32.618:DBUG:oeji.AbstractEndPoint:qtp1514035599-251:zpNNYmPy2nEga.txt @ o.e.j.w.WebAppContext@ccf774b{HCAP HTTP Gateway,/,file:///var/arc/tmp/jetty-0.0.0.0-8080-http_gateway.war--any-/webapp/,AVAILABLE}{/http_gateway.war}
2019-05-20 13:01:32.603:DBUG:oejsh.ContextHandler:qtp1514035599-258: context=||/hs3/bucket1/Ol8uGl4H1ef2zpNNYmPy2nEga.txt @ o.e.j.w.WebAppContext@ccf774b{HCAP HTTP Gateway,/,file:///var/arc/tmp/jetty-0.0.0.0-8080-http_gateway.war-
-any-/webapp/,AVAILABLE}{/http_gateway.war}
2019-05-20 13:01:32.603:DBUG:oejs.session:qtp1514035599-258: SessionHandler.doScope
(fully jetty debug context is available for this one if necessary)

Details about our jetty configuration:
The jetty configuration is setup with 10 minimum threads and 255 maximum threads, with idleTimeout of 30000. reservedThreadsLifeSpan is set to default. We have separate http and https connectors (with the same thread sizing).

Any direction is much appreciated.

@sbordet
Copy link
Contributor

sbordet commented May 21, 2019

I don't think there is nothing strange in these stack traces.

The server is trying to write to the client, but the network connection has been interrupted.

You have DEBUG enabled, so it's typical to see that much of stack traces - that does not mean there is something wrong.

@joakime
Copy link
Contributor

joakime commented May 21, 2019

EofException is very common in a production environment.

This part of the stacktrace tell us the most ...

java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
at sun.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:262)
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:909)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:823)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:850)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:921)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:249)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:225)
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:307)
at org.eclipse.jetty.server.HttpWriter.close(HttpWriter.java:49)
at org.eclipse.jetty.server.ResponseWriter.close(ResponseWriter.java:163)
at org.eclipse.jetty.server.Dispatcher.commitResponse(Dispatcher.java:260)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:230)
at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:78)

That stacktrace says the server was attempting to commit/close/write/flush a response, but the remote side disconnected before it could complete.
Pretty low level, not much that can be done with that.
DEBUG shows you all of this going on.
Back in Jetty 7/Jetty 8 days this was quietly ignored (probably logged at IGNORE level, not even at DEBUG), and it just moved on.

@abennet
Copy link
Author

abennet commented May 23, 2019

At first we were also suspecting client mis-behavior.
However, we ran the same load test and client with the same application server logic on jetty 7.x and jetty 9.x. The issues are only reproducible under 9.x. The application gets dozens of errors when writing out the response on the second half of the load test due to closed connections.
We have ruled out slow request processing on the application server. Furthermore, we have identified a few different exceptions that we can hit when server tries to write out the response (EatWhatYouKill/ jetty EofException and Broken Pipe)

We are continuing to investigate what causes the jetty connection to close. Any thoughts on how we can track jetty connection management (other than enabling jetty debug which we have tried).

Thanks.

@sbordet
Copy link
Contributor

sbordet commented May 23, 2019

I've seen in the past such major Jetty upgrades and the new Jetty version was so much faster that the client was overwhelmed trying to cope with the server replying faster than before.
This cause the client to timeout connections due to being incapable to handle the load.
This is very very common - it's very difficult to write a good scalable load client.

I've also seen old clients that fail to parse more up-to-date HTTP responses that newer versions of Jetty now produce.

If the broken pipes are generated by the client I would investigate the client first, no matter the server version.
Verify with Wireshark that is the client closing the connection unexpectedly.
If that's the case, turn DEBUG on in the client - not the server - and try to figure out why the client is choking.

@sbordet
Copy link
Contributor

sbordet commented Jul 21, 2019

@abennet news?

@devilethon
Copy link

Is there a way we can change these ERRORS into WARN?

@sbordet
Copy link
Contributor

sbordet commented Apr 20, 2020

@devilethon consider opening a new issue and describe exactly your problem. Jetty does not log at ERROR level, so you must detail what is your issue in much more details.

@rhamedy
Copy link

rhamedy commented Jun 26, 2020

Back in Jetty 7/Jetty 8 days this was quietly ignored (probably logged at IGNORE level, not even at DEBUG), and it just moved on.

@joakime how can I find this change? Any specific class?

@joakime
Copy link
Contributor

joakime commented Jun 26, 2020

@rhamedy the code between Jetty 8.0 and Jetty 9.4 (a difference of 4 major versions) with regards to IO has changed massively.

If you want to verify that theory, just enable ALL (if using Jetty Logging) or TRACE (if using logback, log4j, slf4j, etc) or FINEST (if using java.util.logging) logging for org.eclipse.jetty and check for the word "IGNORED" or "IGNORE" in the output.

@joakime
Copy link
Contributor

joakime commented Jun 26, 2020

Is there a way we can change these ERRORS into WARN?

Done. Jetty never logs at ERROR level anyway.

@stale
Copy link

stale bot commented Jul 21, 2021

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the Stale For auto-closed stale issues and pull requests label Jul 21, 2021
@github-actions
Copy link

github-actions bot commented Mar 8, 2022

This issue has been closed due to it having no activity.

@github-actions github-actions bot closed this as completed Mar 8, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Stale For auto-closed stale issues and pull requests
Projects
None yet
Development

No branches or pull requests

5 participants