Jetty

"Connection reset by peer" Exceptions in Jetty when client is using IE8 and closes tab during loading

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 8.0.4
  • Fix Version/s: 7.6.0
  • Component/s: HTTP
  • Labels:
    None
  • Environment:
    Ubuntu Linux 10.4 and Windows XP SP3
  • Number of attachments :
    0

Description

I recently tried to upgrade from Jetty-6.1.26 to 8.0.4. I did lots of testing beforehand, like replaying 100k requests from our logs in multiple threads, and everything went fine.

But after deployment I got the following Exceptions 1-5 times per minute (we have about 5000 client requests per minute, not counting static content):

...
Caused by: java.io.IOException: Connection reset by peer
at sun.nio.ch.SocketDispatcher.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:37)
at sun.nio.ch.IOUtil.write(IOUtil.java:125)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:367)
at java.nio.channels.SocketChannel.write(SocketChannel.java:360)
at org.eclipse.jetty.io.nio.ChannelEndPoint.gatheringFlush(ChannelEndPoint.java:354)
at org.eclipse.jetty.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:292)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.flush(SelectChannelEndPoint.java:300)
at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:848)
... 107 more

Our live server setup uses Jetty behind an Apache mod_proxy_balancer. In the Apache access logs most of these requests had response code 200. But then I observed a GoogleBot request with such an Exception, and the access log recorded a response code 500. That was when I did a (tedious) rollback to Jetty-6.1.26.

After some googling I found this bug report: http://www-01.ibm.com/support/docview.wss?uid=swg21560045

They claim the error occurs, when a client uses IE8 and closes the tab. I just tried to reproduce this while running Jetty on my Windows XP workstation, and succeeded easily. In contrast to our live setup, there is no Apache or mod_proxy between the browser and the Jetty server in this case.

Unfortunately I have no idea how to reproduce the 500 error code the GoogleBot has seen.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Jan Bartel added a comment -

Di9Jeo,

The most recent jetty-8 release is 8.1.0.RC0. This includes significant rework to the handling of half closes, so it would be good if you could upgrade to that. I think the logging you are seeing is harmless, just recording that a client has closed the connection while you were writing to it, HOWEVER check that you don't see resources in jetty being consumed by these half-closed connections (file descriptors, sockets etc). Also, are you running with log IGNORE enabled or not? Looking at the code, I would have expected an IOException to be caught by HttpGenerator and Log.ignored ...

Jan

Show
Jan Bartel added a comment - Di9Jeo, The most recent jetty-8 release is 8.1.0.RC0. This includes significant rework to the handling of half closes, so it would be good if you could upgrade to that. I think the logging you are seeing is harmless, just recording that a client has closed the connection while you were writing to it, HOWEVER check that you don't see resources in jetty being consumed by these half-closed connections (file descriptors, sockets etc). Also, are you running with log IGNORE enabled or not? Looking at the code, I would have expected an IOException to be caught by HttpGenerator and Log.ignored ... Jan
Hide
Permalink
Di9Jeo added a comment -

Hi Jan,

thanks for your help. I retried with 8.1.0-RC0, but it's the same behaviour, unfortunately.

There are no sockets left opened, when that happens, as far as I can tell. (I checked with Process Explorer an my WinXP workstation)

I don't think, this is just a logging issue, though. An IOException occurs, when the JSP tries to write something to the buffer, and this exception is passed on to the servlet. To see, how it gets propagated, have a look at the stacktrace (with 8.1.0.RC0):

org.eclipse.jetty.io.RuntimeIOException: org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.UncheckedPrintWriter.setError(UncheckedPrintWriter.java:110)
at org.eclipse.jetty.io.UncheckedPrintWriter.write(UncheckedPrintWriter.java:237)
at org.apache.jasper.runtime.JspWriterImpl.flushBuffer(JspWriterImpl.java:181)
at org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:453)
at org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:466)
...
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.eclipse.jetty.io.EofException
at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:939)
at org.eclipse.jetty.http.AbstractGenerator.flush(AbstractGenerator.java:438)
at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:94)
at org.eclipse.jetty.server.AbstractHttpConnection$Output.flush(AbstractHttpConnection.java:986)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:177)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:101)
at java.io.ByteArrayOutputStream.writeTo(ByteArrayOutputStream.java:109)
at org.eclipse.jetty.server.HttpWriter.write(HttpWriter.java:283)
at org.eclipse.jetty.io.UncheckedPrintWriter.write(UncheckedPrintWriter.java:228)
... 99 more
Caused by: java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
at sun.nio.ch.SocketDispatcher.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:37)
at sun.nio.ch.IOUtil.write(IOUtil.java:125)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:367)
at java.nio.channels.SocketChannel.write(SocketChannel.java:360)
at org.eclipse.jetty.io.nio.ChannelEndPoint.gatheringFlush(ChannelEndPoint.java:386)
at org.eclipse.jetty.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:338)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.flush(SelectChannelEndPoint.java:310)
at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:863)
... 107 more

It appears, UncheckedPrintWriter has _throwUnchecked=true, which is the default, and thus re-throws the Exception. As far as I can see (AbstractHttpConnection instantiates UncheckedPrintWriter by itself), all this is the default behaviour of jetty 8. Or is this some configuration error on my side? I didn't set anything consciously to affect this.

I don't think I use log IGNORE, unless it is enabled by default - I don't have any system property set for jetty logging.

Bye,
Michael

Show
Di9Jeo added a comment - Hi Jan, thanks for your help. I retried with 8.1.0-RC0, but it's the same behaviour, unfortunately. There are no sockets left opened, when that happens, as far as I can tell. (I checked with Process Explorer an my WinXP workstation) I don't think, this is just a logging issue, though. An IOException occurs, when the JSP tries to write something to the buffer, and this exception is passed on to the servlet. To see, how it gets propagated, have a look at the stacktrace (with 8.1.0.RC0): org.eclipse.jetty.io.RuntimeIOException: org.eclipse.jetty.io.EofException at org.eclipse.jetty.io.UncheckedPrintWriter.setError(UncheckedPrintWriter.java:110) at org.eclipse.jetty.io.UncheckedPrintWriter.write(UncheckedPrintWriter.java:237) at org.apache.jasper.runtime.JspWriterImpl.flushBuffer(JspWriterImpl.java:181) at org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:453) at org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:466) ... at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533) at java.lang.Thread.run(Thread.java:662) Caused by: org.eclipse.jetty.io.EofException at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:939) at org.eclipse.jetty.http.AbstractGenerator.flush(AbstractGenerator.java:438) at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:94) at org.eclipse.jetty.server.AbstractHttpConnection$Output.flush(AbstractHttpConnection.java:986) at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:177) at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:101) at java.io.ByteArrayOutputStream.writeTo(ByteArrayOutputStream.java:109) at org.eclipse.jetty.server.HttpWriter.write(HttpWriter.java:283) at org.eclipse.jetty.io.UncheckedPrintWriter.write(UncheckedPrintWriter.java:228) ... 99 more Caused by: java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen at sun.nio.ch.SocketDispatcher.writev0(Native Method) at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:37) at sun.nio.ch.IOUtil.write(IOUtil.java:125) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:367) at java.nio.channels.SocketChannel.write(SocketChannel.java:360) at org.eclipse.jetty.io.nio.ChannelEndPoint.gatheringFlush(ChannelEndPoint.java:386) at org.eclipse.jetty.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:338) at org.eclipse.jetty.io.nio.SelectChannelEndPoint.flush(SelectChannelEndPoint.java:310) at org.eclipse.jetty.http.HttpGenerator.flushBuffer(HttpGenerator.java:863) ... 107 more It appears, UncheckedPrintWriter has _throwUnchecked=true, which is the default, and thus re-throws the Exception. As far as I can see (AbstractHttpConnection instantiates UncheckedPrintWriter by itself), all this is the default behaviour of jetty 8. Or is this some configuration error on my side? I didn't set anything consciously to affect this. I don't think I use log IGNORE, unless it is enabled by default - I don't have any system property set for jetty logging. Bye, Michael
Hide
Permalink
Jan Bartel added a comment -

There is a difference between jetty-6 and jetty-7/8 with regards the UncheckedPrintWriter. In jetty-6, any exception caused by the IO was suppressed. In jetty-7, the UncheckedPrintWriter is used and defaults to throwing the exception as a runtime exception.

These are the relevant issues:
https://bugs.eclipse.org/bugs/show_bug.cgi?id=318551
http://jira.codehaus.org/browse/JETTY-1086

I still believe that this log message is caused by a client (or the network or the server's operating system) closing the connection to the client when output is still being written to it.

I will look at why we don't have the ability to turn off the throwing of these runtime IOExceptions (like we do if we are using the UncheckedPrintWriter for the IncludableGzipFilter).

In the meanwhile you may want to set up some custom error pages for the webapp.

Jan

Show
Jan Bartel added a comment - There is a difference between jetty-6 and jetty-7/8 with regards the UncheckedPrintWriter. In jetty-6, any exception caused by the IO was suppressed. In jetty-7, the UncheckedPrintWriter is used and defaults to throwing the exception as a runtime exception. These are the relevant issues: https://bugs.eclipse.org/bugs/show_bug.cgi?id=318551 http://jira.codehaus.org/browse/JETTY-1086 I still believe that this log message is caused by a client (or the network or the server's operating system) closing the connection to the client when output is still being written to it. I will look at why we don't have the ability to turn off the throwing of these runtime IOExceptions (like we do if we are using the UncheckedPrintWriter for the IncludableGzipFilter). In the meanwhile you may want to set up some custom error pages for the webapp. Jan
Hide
Permalink
Di9Jeo added a comment -

> There is a difference between jetty-6 and jetty-7/8 with regards the UncheckedPrintWriter.

Wow, and what a difference! While I see the need for the option of throwing such an exception, I find it rather weird to make that the default behaviour.

> I still believe that this log message is caused by a client (or the network or the server's operating system) closing the connection to the client when output is still being written to it.

That's definitely the case when I reproduce the issue with the IE8. I close the tab during loading.

> I will look at why we don't have the ability to turn off the throwing of these runtime IOExceptions

Excellent, that would help me.

Thanks,
Michael

Show
Di9Jeo added a comment - > There is a difference between jetty-6 and jetty-7/8 with regards the UncheckedPrintWriter. Wow, and what a difference! While I see the need for the option of throwing such an exception, I find it rather weird to make that the default behaviour. > I still believe that this log message is caused by a client (or the network or the server's operating system) closing the connection to the client when output is still being written to it. That's definitely the case when I reproduce the issue with the IE8. I close the tab during loading. > I will look at why we don't have the ability to turn off the throwing of these runtime IOExceptions Excellent, that would help me. Thanks, Michael
Hide
Permalink
Jan Bartel added a comment -

Fixed for 7.6.0, and will be ported to jetty-8.1.0 also.

Show
Jan Bartel added a comment - Fixed for 7.6.0, and will be ported to jetty-8.1.0 also.

People

  • Assignee:
    Jan Bartel
    Reporter:
    Di9Jeo
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: