search

fizzed / ninja-undertow

Undertow standalone container for NinjaFramework
2 stars 5 forks source link

Exceptions thrown when client closes the connection #3

Closed jfendler closed 8 years ago

jfendler commented 8 years ago

Hi @jjlauer,

with ninja-undertow (instead of using jetty), I get plenty of "Broken Pipe" exceptions, apparently whenever a server response is not fully consumed by the client. With jetty I had a similar effect, but only when serving large file entities (see Google groups). Since using undertow the same basic issue seems to occur rather frequently with a lot of requests.

I couldn't really find this issue described anywhere in the undertow forums, so I'm not sure if it's an undertow, or a ninja-undertow issue. I'll try and build a test case for this, since I do believe this is not how it should be. Even if the root cause (IOException while trying to write to the response stream) is thrown by undertow for a reason, I don't believe anybody would want these specific exceptions to show up in production logs (clients close connections all the time..).

Do you have any thoughts or ideas on how to approach this best (perhaps something more elegant than just catching and ignoring the exception)?

Here's the stack trace I get when this happens:

2016-06-02 09:12:53.748 ERROR : Emitting bad request 500. Something really wrong when calling route: / (class: class controllers.ApplicationController method: public ninja.Result controllers.ApplicationControl
ler.index(ninja.Context))
ninja.exceptions.RenderingException: Broken pipe
        at ninja.template.TemplateEngineFreemarker.throwRenderingException(TemplateEngineFreemarker.java:378) ~[competix-0.8.4.jar:na]
        at ninja.template.TemplateEngineFreemarker.invoke(TemplateEngineFreemarker.java:328) ~[competix-0.8.4.jar:na]
        at ninja.utils.ResultHandler.renderWithTemplateEngineOrRaw(ResultHandler.java:116) ~[competix-0.8.4.jar:na]
        at ninja.utils.ResultHandler.handleResult(ResultHandler.java:78) ~[competix-0.8.4.jar:na]
        at ninja.NinjaDefault.onRouteRequest(NinjaDefault.java:104) ~[competix-0.8.4.jar:na]
        at conf.Ninja.onRouteRequest(Ninja.java:677) [competix-0.8.4.jar:na]
        at ninja.undertow.NinjaUndertowHandler.handleRequest(NinjaUndertowHandler.java:56) [competix-0.8.4.jar:na]
        at ninja.undertow.util.EagerFormParsingHandlerWithCharset.handleRequest(EagerFormParsingHandlerWithCharset.java:60) [competix-0.8.4.jar:na]
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202) [competix-0.8.4.jar:na]
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:802) [competix-0.8.4.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
Caused by: java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
        at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[na:1.8.0_91]
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
        at org.xnio.nio.NioSocketConduit.write(NioSocketConduit.java:152) ~[competix-0.8.4.jar:na]
        at io.undertow.server.protocol.http.HttpResponseConduit.write(HttpResponseConduit.java:599) ~[competix-0.8.4.jar:na]
        at org.xnio.conduits.AbstractStreamSinkConduit.write(AbstractStreamSinkConduit.java:51) ~[competix-0.8.4.jar:na]
        at org.xnio.conduits.ConduitStreamSinkChannel.write(ConduitStreamSinkChannel.java:150) ~[competix-0.8.4.jar:na]
        at io.undertow.channels.DetachableStreamSinkChannel.write(DetachableStreamSinkChannel.java:240) ~[competix-0.8.4.jar:na]
        at io.undertow.server.HttpServerExchange$WriteDispatchChannel.write(HttpServerExchange.java:2017) ~[competix-0.8.4.jar:na]
        at io.undertow.io.UndertowOutputStream.writeBufferBlocking(UndertowOutputStream.java:293) ~[competix-0.8.4.jar:na]
        at io.undertow.io.UndertowOutputStream.write(UndertowOutputStream.java:203) ~[competix-0.8.4.jar:na]
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) ~[na:1.8.0_91]
        at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282) ~[na:1.8.0_91]
        at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125) ~[na:1.8.0_91]
        at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:135) ~[na:1.8.0_91]
        at java.io.OutputStreamWriter.write(OutputStreamWriter.java:220) ~[na:1.8.0_91]
        at java.io.Writer.write(Writer.java:157) ~[na:1.8.0_91]
        at ninja.template.TemplateEngineFreemarker.invoke(TemplateEngineFreemarker.java:323) ~[competix-0.8.4.jar:na]
        ... 11 common frames omitted
2016-06-02 09:12:53.750 ERROR : Unable to handle result. That's really really fishy.
ninja.exceptions.RenderingException: UT000002: The response has already been started
        at ninja.template.TemplateEngineFreemarker.throwRenderingException(TemplateEngineFreemarker.java:378) ~[competix-0.8.4.jar:na]
        at ninja.template.TemplateEngineFreemarker.invoke(TemplateEngineFreemarker.java:328) ~[competix-0.8.4.jar:na]
        at ninja.utils.ResultHandler.renderWithTemplateEngineOrRaw(ResultHandler.java:116) ~[competix-0.8.4.jar:na]
        at ninja.utils.ResultHandler.handleResult(ResultHandler.java:78) ~[competix-0.8.4.jar:na]
        at ninja.NinjaDefault.renderErrorResultAndCatchAndLogExceptions(NinjaDefault.java:136) [competix-0.8.4.jar:na]
        at ninja.NinjaDefault.onRouteRequest(NinjaDefault.java:110) [competix-0.8.4.jar:na]
        at conf.Ninja.onRouteRequest(Ninja.java:677) [competix-0.8.4.jar:na]
        at ninja.undertow.NinjaUndertowHandler.handleRequest(NinjaUndertowHandler.java:56) [competix-0.8.4.jar:na]
        at ninja.undertow.util.EagerFormParsingHandlerWithCharset.handleRequest(EagerFormParsingHandlerWithCharset.java:60) [competix-0.8.4.jar:na]
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202) [competix-0.8.4.jar:na]
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:802) [competix-0.8.4.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
Caused by: java.lang.IllegalStateException: UT000002: The response has already been started
        at io.undertow.server.HttpServerExchange.setStatusCode(HttpServerExchange.java:1365) ~[competix-0.8.4.jar:na]
        at ninja.undertow.NinjaUndertowContext.finalizeHeaders(NinjaUndertowContext.java:344) ~[competix-0.8.4.jar:na]
        at ninja.utils.AbstractContext.finalizeHeaders(AbstractContext.java:327) ~[competix-0.8.4.jar:na]
        at ninja.template.TemplateEngineFreemarker.invoke(TemplateEngineFreemarker.java:321) ~[competix-0.8.4.jar:na]
        ... 12 common frames omitted
jjlauer commented 8 years ago

Can you copy-n-paste the exceptions -- I'd like to see the stacktraces.

On Thu, Jun 2, 2016 at 5:04 AM, Jens Fendler notifications@github.com wrote:

Hi @jjlauer https://github.com/jjlauer,

with ninja-undertow (instead of using jetty), I get plenty of "Broken Pipe" exceptions, apparently whenever a server response is not fully consumed by the client. With jetty I had a similar effect, but only when serving large file entities (see Google groups https://groups.google.com/forum/#!topic/ninja-framework/z12l8Izh7EM). Since using undertow the same basic issue seems to occur rather frequently with a lot of requests.

I couldn't really find this issue described anywhere in the undertow forums, so I'm not sure if it's an undertow, or a ninja-undertow issue. I'll try and build a test case for this, since I do believe this is not how it should be. Even if the root cause (IOException while trying to write to the response stream) is thrown by undertow for a reason, I don't believe anybody would want these specific exceptions to show up in production logs (clients close connections all the time..).

Do you have any thoughts or ideas on how to approach this best (perhaps something more elegant than just catching and ignoring the exception)?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/fizzed/ninja-undertow/issues/3, or mute the thread https://github.com/notifications/unsubscribe/AAjwApDF-1lXleM6Ir14sZeN6ma3P_2Xks5qHpy3gaJpZM4IsWIa .

jfendler commented 8 years ago

I thought so.... and added them to the post right after I first saved it. Please have a look at the issue page. 

jjlauer commented 8 years ago

I occasionally see the broken pipe too -- I'm happy undertow doesn't swallow it, but I agree we can make those safer to handle. I generally run HTTPS w/ undertow and that causes a different set of exceptions to be thrown as well.

Seems like issues similar to this exist for WildFly (which is the main container that uses Undertow). https://issues.jboss.org/browse/WFLY-3722 -- So i don't think ninja-undertow is doing anything special to cause it. Sounds like undertow's main author, Stuart, is recommending those get swallowed and logged as debug in WildFly. So I suppose we could do something similar. Two ideas. 1) Implement a generalized approach in Ninja to help handle exceptions while writing output. That would benefit Jetty as well. Maybe make the handler bound via guice so users can customize. 2) Implement a wrapped OutputStream from ninja-undertow that helps swallow & log the specific exceptions. So rather than return the OutputStream directly from undertow's exchange, that gets a wrapped version that can handle the various IOExceptions we want to swallow up.

On Thu, Jun 2, 2016 at 7:36 AM, Jens Fendler notifications@github.com wrote:

I thought so.... and added them to the post right after I first saved it. Please have a look at the issue page.

Kind regards, Jens Fendler -------- Original message --------From: Joe Lauer < notifications@github.com> Date: 2016/06/02 12:22 (GMT+01:00) To: fizzed/ninja-undertow ninja-undertow@noreply.github.com Cc: Jens Fendler jf@jensfendler.com, Author author@noreply.github.com Subject: Re: [fizzed/ninja-undertow] Exceptions thrown when client closes the connection (#3) Can you copy-n-paste the exceptions -- I'd like to see the stacktraces.

On Thu, Jun 2, 2016 at 5:04 AM, Jens Fendler notifications@github.com

wrote:

Hi @jjlauer https://github.com/jjlauer,

with ninja-undertow (instead of using jetty), I get plenty of "Broken

Pipe" exceptions, apparently whenever a server response is not fully

consumed by the client.

With jetty I had a similar effect, but only when serving large file

entities (see Google groups

https://groups.google.com/forum/#!topic/ninja-framework/z12l8Izh7EM).

Since using undertow the same basic issue seems to occur rather frequently

with a lot of requests.

I couldn't really find this issue described anywhere in the undertow

forums, so I'm not sure if it's an undertow, or a ninja-undertow issue.

I'll try and build a test case for this, since I do believe this is not how

it should be. Even if the root cause (IOException while trying to write to

the response stream) is thrown by undertow for a reason, I don't believe

anybody would want these specific exceptions to show up in production logs

(clients close connections all the time..).

Do you have any thoughts or ideas on how to approach this best (perhaps

something more elegant than just catching and ignoring the exception)?

—

You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub

https://github.com/fizzed/ninja-undertow/issues/3, or mute the thread

< https://github.com/notifications/unsubscribe/AAjwApDF-1lXleM6Ir14sZeN6ma3P_2Xks5qHpy3gaJpZM4IsWIa

.

— You are receiving this because you authored the thread.

Reply to this email directly, view it on GitHub, or mute the thread.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/fizzed/ninja-undertow/issues/3#issuecomment-223266653, or mute the thread https://github.com/notifications/unsubscribe/AAjwAsNag6X62C-RzMh6KZ9CWwu7haxkks5qHsBAgaJpZM4IsWIa .

jfendler commented 8 years ago

I'm definitely in favour of handling it in ninja, rather than in a specific server module. I'd assume all HTTP servers will act similarly (i.e. simply throw such exceptions), so if Ninja is prepared to swallow and silently log to DEBUG only that'd be the cleanest approach IMHO. Unless you get to this first, I'll dig into the respective Ninja code and see what I can come up with.. Thanks for your input.