Jetty

leaks socket descriptors

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Critical Critical
  • Resolution: Fixed
  • Affects Version/s: 6.0.0beta8, 6.0.0beta9, 6.0.0beta10, 6.0.0beta11, 6.0.0beta12, 6.0.0beta14, 6.0.0beta15, 6.0.0RC0
  • Fix Version/s: 6.0.0rc1
  • Component/s: HTTP, NIO
  • Labels:
    None
  • Environment:
    FreeBSD 5.4-RELEASE-p3
    Java HotSpot(TM) Server VM (build diablo-1.5.0_06-b00, mixed mode)
  • Number of attachments :
    4

Description

New Jetty, apparently, leaks socket descriptors. When running unattended, Jetty would take all available OS descriptors, leading to the "Too many open files in system" (ENFILE?) error affecting the whole system. (There were no such problem with Jetty5).

root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 11:21:29 CEST 2006
30
111
50
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 11:27:42 CEST 2006
90
221
180
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 11:34:42 CEST 2006
102
203
306
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 11:43:03 CEST 2006
109
326
446
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 11:50:05 CEST 2006
118
299
544
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 12:00:57 CEST 2006
103
187
677
root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
Thu May 25 12:19:59 CEST 2006
105
305
987

Here we see, that amount of open sockets (sockstat) remain roughly the same, amount of TCP/IP stack entries (netstat) - too, but the amount of socket descriptors used by the process (fstat | grep tcp) - increases.

The leak was present at the time of beta8 till today (last tested was the SVN version of Jetty from 2006-05-25).
I can give JVMDI (java debugger) access to the machine to a specific IP.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Greg Wilkins added a comment -

I can't reproduce this problem. using jdk1.5 on ubuntu linux and measuring the open files with lsof

running the test webapp, 111 FD's are used when idle. Under load (250 clients) this increases and
stabilizes around 250 to 310 and then falls back to 111 once the load is removed.

Can you tell me more about your webapp? or can you reproduce against the test webapp?

Show
Greg Wilkins added a comment - I can't reproduce this problem. using jdk1.5 on ubuntu linux and measuring the open files with lsof running the test webapp, 111 FD's are used when idle. Under load (250 clients) this increases and stabilizes around 250 to 310 and then falls back to 111 once the load is removed. Can you tell me more about your webapp? or can you reproduce against the test webapp?
Hide
Permalink
Artem Kozarezov added a comment -

I've run our program under HPROF (http://java.sun.com/developer/technicalArticles/Programming/HPROF.html)
Unfortunately, it does not provide information why the instance is held in memory,
but it shows what IS in memory, and, i think, it proves that something is wrong here.

Here is excerpt from the hprof file, of what i thought is related to that problem:
SITES BEGIN (ordered by live bytes) Fri May 26 13:30:09 2006
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
43 0.39% 71.66% 120120 1001 306360 2553 307394 java.net.SocksSocketImpl
45 0.37% 72.40% 112112 1001 285936 2553 307964 sun.nio.ch.SocketChannelImpl
56 0.26% 75.64% 79288 901 217096 2467 308007 org.mortbay.jetty.HttpConnection
61 0.24% 76.89% 72080 901 197360 2467 308238 org.mortbay.jetty.HttpGenerator
65 0.21% 77.78% 64872 901 177624 2467 308001 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint
76 0.17% 79.79% 52192 932 142912 2552 308002 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint$IdleTask
80 0.17% 80.46% 50456 901 138152 2467 308008 org.mortbay.jetty.HttpURI
81 0.17% 80.63% 50456 901 138152 2467 308226 org.mortbay.jetty.Response
83 0.16% 80.94% 48000 1000 122496 2552 307984 sun.nio.ch.SocketAdaptor
91 0.13% 82.06% 38472 687 108528 1938 312369 org.mortbay.io.ByteArrayBuffer
102 0.10% 83.28% 30816 428 80568 1119 312355 org.mortbay.jetty.HttpConnection$OutputWriter
108 0.09% 83.85% 28520 713 80680 2017 312147 org.mortbay.jetty.HttpConnection$Output
116 0.08% 84.52% 24024 1001 61272 2553 307959 java.net.Inet4Address
117 0.08% 84.60% 24024 1001 61272 2553 307960 java.net.InetSocketAddress
121 0.08% 84.91% 23184 966 59208 2467 307997 java.nio.channels.SelectionKey[]
128 0.07% 85.42% 22296 929 60816 2534 312358 java.net.InetSocketAddress
129 0.07% 85.50% 22176 396 57120 1020 305827 sun.nio.cs.StreamEncoder$CharsetSE
135 0.07% 85.91% 20360 509 77040 1926 310806 javax.servlet.http.Cookie
136 0.07% 85.98% 20272 362 183232 3272 300046 java.nio.DirectByteBuffer
138 0.06% 86.11% 19776 412 89760 1870 303161 sun.nio.cs.ISO_8859_1$Encoder
145 0.06% 86.52% 17120 428 44760 1119 312356 org.mortbay.jetty.HttpConnection$1
149 0.05% 86.74% 16632 297 33152 592 308244 org.mortbay.io.nio.NIOBuffer
156 0.05% 87.11% 16016 1001 40864 2554 307953 java.io.FileDescriptor
157 0.05% 87.17% 16000 1000 40832 2552 307994 sun.nio.ch.SocketChannelImpl$1
158 0.05% 87.22% 16000 1000 40832 2552 307992 sun.nio.ch.OptionAdaptor
159 0.05% 87.27% 16000 1000 40832 2552 308248 java.nio.channels.spi.AbstractInterruptibleChannel$1
160 0.05% 87.32% 16000 1000 40832 2552 307996 sun.nio.ch.SocketOptsImpl$IP$TCP
161 0.05% 87.38% 15960 665 23880 995 309114 java.util.concurrent.locks.ReentrantLock$NonfairSync
169 0.05% 87.78% 14912 932 40832 2552 308009 org.mortbay.jetty.HttpConnection$RequestHandler
175 0.05% 88.07% 14520 605 14520 605 301162 java.net.Inet4Address
176 0.05% 88.11% 14480 362 130880 3272 300050 sun.misc.Cleaner
177 0.05% 88.16% 14400 600 14400 600 301163 java.net.InetAddress$CacheEntry
184 0.04% 88.47% 13240 331 233800 5845 300021 sun.nio.cs.ISO_8859_1$Decoder
190 0.04% 88.73% 12792 123 15496 149 307858 org.mortbay.thread.BoundedThreadPool$PoolThread
217 0.03% 89.74% 9888 412 44880 1870 303165 sun.nio.cs.Surrogate$Parser
219 0.03% 89.80% 9616 599 9616 599 307982 java.net.InetAddress[]
223 0.03% 89.92% 9336 389 24144 1006 312368 java.io.OutputStreamWriter
266 0.02% 91.09% 7520 188 102120 2553 307851 sun.nio.ch.SelectionKeyImpl
268 0.02% 91.14% 7416 309 187560 7815 300020 java.lang.StringCoding$CharsetSD
269 0.02% 91.16% 7416 309 7536 314 303459 java.security.Provider$ServiceKey
275 0.02% 91.31% 7296 152 184848 3851 310761 ru.webcrm.base.cms.Visitor
300 0.02% 91.87% 6456 269 63384 2641 308251 java.nio.DirectByteBuffer$Deallocator
304 0.02% 91.95% 6200 155 159280 3982 300102 sun.nio.cs.UTF_8$Decoder
342 0.02% 92.64% 4960 31 13600 85 310532 org.mortbay.jetty.Request
350 0.02% 92.77% 4720 118 102120 2553 307978 java.net.SocketPermission
365 0.01% 92.99% 4416 184 4488 187 303470 java.security.Provider$ServiceKey

When this dump was made, there were about 50 active sockets (sockstat) and 500 tcp/ip file descriptors used (fstat | grep tcp). In the heap dump we can see that there is only 31 org.mortbay.jetty.Request instance, and amount of other working objects, like "ru.webcrm.base.cms.Visitor", is around 150, while amount of a lot of Jetty resources, like "java.io.FileDescriptor" and "org.mortbay.jetty.HttpConnection", is much higher (and seems relative to the number of open file descriptors).

Some traces, to complete the picture above:

TRACE 307953:
java.io.FileDescriptor.<init>(FileDescriptor.java:34)
sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:136)
org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:403)
org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)

TRACE 308007:
org.mortbay.jetty.HttpConnection.<init>(HttpConnection.java:83)
org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint.<init>(SelectChannelConnector.java:540)
org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:314)
org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)

TRACE 308248:
java.nio.channels.spi.AbstractInterruptibleChannel$1.<init>(AbstractInterruptibleChannel.java:140)
java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:139)
sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:147)
org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:115)

TRACE 310761:
ru.webcrm.base.cms.Visitor.<init>(Visitor.java:50)
ru.webcrm.base.cms.Waitress.receiveGuests(Waitress.java:165)
ru.webcrm.base.cms.Servlet.service(Servlet.java:125)
javax.servlet.http.HttpServlet.service(HttpServlet.java:860)

Can you tell me more about your webapp?

We use a single custom Servlet (DefaultServlet from Jetty isn't used). Nothing special (Continuations aren't used). The load might involve a lot of requests from proxy servers (we happen to test proxy servers by using the http://glim.ru/env.cgi there). Currently Jetty (and everything else) runs under URLClassLoader with special Java security permissions, but that is optional and i've checked that the leak remains with this sandbox turned off.

Show
Artem Kozarezov added a comment - I've run our program under HPROF ( http://java.sun.com/developer/technicalArticles/Programming/HPROF.html ) Unfortunately, it does not provide information why the instance is held in memory, but it shows what IS in memory, and, i think, it proves that something is wrong here. Here is excerpt from the hprof file, of what i thought is related to that problem: SITES BEGIN (ordered by live bytes) Fri May 26 13:30:09 2006 percent live alloc'ed stack class rank self accum bytes objs bytes objs trace name 43 0.39% 71.66% 120120 1001 306360 2553 307394 java.net.SocksSocketImpl 45 0.37% 72.40% 112112 1001 285936 2553 307964 sun.nio.ch.SocketChannelImpl 56 0.26% 75.64% 79288 901 217096 2467 308007 org.mortbay.jetty.HttpConnection 61 0.24% 76.89% 72080 901 197360 2467 308238 org.mortbay.jetty.HttpGenerator 65 0.21% 77.78% 64872 901 177624 2467 308001 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint 76 0.17% 79.79% 52192 932 142912 2552 308002 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint$IdleTask 80 0.17% 80.46% 50456 901 138152 2467 308008 org.mortbay.jetty.HttpURI 81 0.17% 80.63% 50456 901 138152 2467 308226 org.mortbay.jetty.Response 83 0.16% 80.94% 48000 1000 122496 2552 307984 sun.nio.ch.SocketAdaptor 91 0.13% 82.06% 38472 687 108528 1938 312369 org.mortbay.io.ByteArrayBuffer 102 0.10% 83.28% 30816 428 80568 1119 312355 org.mortbay.jetty.HttpConnection$OutputWriter 108 0.09% 83.85% 28520 713 80680 2017 312147 org.mortbay.jetty.HttpConnection$Output 116 0.08% 84.52% 24024 1001 61272 2553 307959 java.net.Inet4Address 117 0.08% 84.60% 24024 1001 61272 2553 307960 java.net.InetSocketAddress 121 0.08% 84.91% 23184 966 59208 2467 307997 java.nio.channels.SelectionKey[] 128 0.07% 85.42% 22296 929 60816 2534 312358 java.net.InetSocketAddress 129 0.07% 85.50% 22176 396 57120 1020 305827 sun.nio.cs.StreamEncoder$CharsetSE 135 0.07% 85.91% 20360 509 77040 1926 310806 javax.servlet.http.Cookie 136 0.07% 85.98% 20272 362 183232 3272 300046 java.nio.DirectByteBuffer 138 0.06% 86.11% 19776 412 89760 1870 303161 sun.nio.cs.ISO_8859_1$Encoder 145 0.06% 86.52% 17120 428 44760 1119 312356 org.mortbay.jetty.HttpConnection$1 149 0.05% 86.74% 16632 297 33152 592 308244 org.mortbay.io.nio.NIOBuffer 156 0.05% 87.11% 16016 1001 40864 2554 307953 java.io.FileDescriptor 157 0.05% 87.17% 16000 1000 40832 2552 307994 sun.nio.ch.SocketChannelImpl$1 158 0.05% 87.22% 16000 1000 40832 2552 307992 sun.nio.ch.OptionAdaptor 159 0.05% 87.27% 16000 1000 40832 2552 308248 java.nio.channels.spi.AbstractInterruptibleChannel$1 160 0.05% 87.32% 16000 1000 40832 2552 307996 sun.nio.ch.SocketOptsImpl$IP$TCP 161 0.05% 87.38% 15960 665 23880 995 309114 java.util.concurrent.locks.ReentrantLock$NonfairSync 169 0.05% 87.78% 14912 932 40832 2552 308009 org.mortbay.jetty.HttpConnection$RequestHandler 175 0.05% 88.07% 14520 605 14520 605 301162 java.net.Inet4Address 176 0.05% 88.11% 14480 362 130880 3272 300050 sun.misc.Cleaner 177 0.05% 88.16% 14400 600 14400 600 301163 java.net.InetAddress$CacheEntry 184 0.04% 88.47% 13240 331 233800 5845 300021 sun.nio.cs.ISO_8859_1$Decoder 190 0.04% 88.73% 12792 123 15496 149 307858 org.mortbay.thread.BoundedThreadPool$PoolThread 217 0.03% 89.74% 9888 412 44880 1870 303165 sun.nio.cs.Surrogate$Parser 219 0.03% 89.80% 9616 599 9616 599 307982 java.net.InetAddress[] 223 0.03% 89.92% 9336 389 24144 1006 312368 java.io.OutputStreamWriter 266 0.02% 91.09% 7520 188 102120 2553 307851 sun.nio.ch.SelectionKeyImpl 268 0.02% 91.14% 7416 309 187560 7815 300020 java.lang.StringCoding$CharsetSD 269 0.02% 91.16% 7416 309 7536 314 303459 java.security.Provider$ServiceKey 275 0.02% 91.31% 7296 152 184848 3851 310761 ru.webcrm.base.cms.Visitor 300 0.02% 91.87% 6456 269 63384 2641 308251 java.nio.DirectByteBuffer$Deallocator 304 0.02% 91.95% 6200 155 159280 3982 300102 sun.nio.cs.UTF_8$Decoder 342 0.02% 92.64% 4960 31 13600 85 310532 org.mortbay.jetty.Request 350 0.02% 92.77% 4720 118 102120 2553 307978 java.net.SocketPermission 365 0.01% 92.99% 4416 184 4488 187 303470 java.security.Provider$ServiceKey When this dump was made, there were about 50 active sockets (sockstat) and 500 tcp/ip file descriptors used (fstat | grep tcp). In the heap dump we can see that there is only 31 org.mortbay.jetty.Request instance, and amount of other working objects, like "ru.webcrm.base.cms.Visitor", is around 150, while amount of a lot of Jetty resources, like "java.io.FileDescriptor" and "org.mortbay.jetty.HttpConnection", is much higher (and seems relative to the number of open file descriptors). Some traces, to complete the picture above: TRACE 307953: java.io.FileDescriptor.<init>(FileDescriptor.java:34) sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:136) org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:403) org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) TRACE 308007: org.mortbay.jetty.HttpConnection.<init>(HttpConnection.java:83) org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint.<init>(SelectChannelConnector.java:540) org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:314) org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) TRACE 308248: java.nio.channels.spi.AbstractInterruptibleChannel$1.<init>(AbstractInterruptibleChannel.java:140) java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:139) sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:147) org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:115) TRACE 310761: ru.webcrm.base.cms.Visitor.<init>(Visitor.java:50) ru.webcrm.base.cms.Waitress.receiveGuests(Waitress.java:165) ru.webcrm.base.cms.Servlet.service(Servlet.java:125) javax.servlet.http.HttpServlet.service(HttpServlet.java:860) Can you tell me more about your webapp? We use a single custom Servlet (DefaultServlet from Jetty isn't used). Nothing special (Continuations aren't used). The load might involve a lot of requests from proxy servers (we happen to test proxy servers by using the http://glim.ru/env.cgi there). Currently Jetty (and everything else) runs under URLClassLoader with special Java security permissions, but that is optional and i've checked that the leak remains with this sandbox turned off.
Hide
Permalink
Artem Kozarezov added a comment -

I'm installing everything required to run the JMP under a VNC session. If it works, expect some news from me on sunday.

Show
Artem Kozarezov added a comment - I'm installing everything required to run the JMP under a VNC session. If it works, expect some news from me on sunday.
Hide
Permalink
Artem Kozarezov added a comment -

From evaluating behaviour of Jetty with out application under JMP (http://www.khelekore.org/jmp/) i can draw the followin:
1)
HPROF was a bit misleading about amount of some object, in particular, org.mortbay.jetty.Request instance is allocated as much as everything else bundled with HttpConnection.
2)
java.io.FileDescriptor
is referenced from
sun.nio.ch.SocketChannelImpl
which is referenced from
org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint
which is practically always referenced from
org.mortbay.jetty.HttpConnection$OutputWriter
org.mortbay.jetty.HttpGenerator
org.mortbay.jetty.Request
org.mortbay.jetty.HttpParser
org.mortbay.jetty.HttpConnection
org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask
but only referenced from
sun.nio.ch.SelectionKeyImpl
when there is an actual socket connection.

It looks like there is a pool of all the resources (or a leak?) which includes, thru sun.nio.ch.SocketChannelImpl, even file descriptors... Perhaps it is possible to a) shrink that pool, b) set the reference, which points from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint to sun.nio.ch.SocketChannelImpl to null when the connection is no longer used (or otherwise close this channel).

Show
Artem Kozarezov added a comment - From evaluating behaviour of Jetty with out application under JMP ( http://www.khelekore.org/jmp/ ) i can draw the followin: 1) HPROF was a bit misleading about amount of some object, in particular, org.mortbay.jetty.Request instance is allocated as much as everything else bundled with HttpConnection. 2) java.io.FileDescriptor is referenced from sun.nio.ch.SocketChannelImpl which is referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint which is practically always referenced from org.mortbay.jetty.HttpConnection$OutputWriter org.mortbay.jetty.HttpGenerator org.mortbay.jetty.Request org.mortbay.jetty.HttpParser org.mortbay.jetty.HttpConnection org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask but only referenced from sun.nio.ch.SelectionKeyImpl when there is an actual socket connection. It looks like there is a pool of all the resources (or a leak?) which includes, thru sun.nio.ch.SocketChannelImpl , even file descriptors... Perhaps it is possible to a) shrink that pool, b) set the reference, which points from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint to sun.nio.ch.SocketChannelImpl to null when the connection is no longer used (or otherwise close this channel).
Hide
Permalink
Jan Bartel added a comment -

Artem,

If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?

Show
Jan Bartel added a comment - Artem, If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?
Hide
Permalink
Artem Kozarezov added a comment -

bt. If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?

First, our application performs System.gc every minute (a feature i'm planning to remove), and, secondly, JMP have a button to perform GC, and i've pressed it regularly (since it helps a bit with the speed of JMP doing and processing its memory dump), so my results were made after the full GC. So, the answer is no, full GC doesn't change anything.
If memory behaviour i'm experiencing is not as it should be, i can try to further investigate it by somehow examining the JMP heap dump itself (it's a 95 mb text file). But i've suspected, that these resources are held by org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask, which looks (by it's name) as it was intended to held them...

Show
Artem Kozarezov added a comment - bt. If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all? First, our application performs System.gc every minute (a feature i'm planning to remove), and, secondly, JMP have a button to perform GC, and i've pressed it regularly (since it helps a bit with the speed of JMP doing and processing its memory dump), so my results were made after the full GC. So, the answer is no, full GC doesn't change anything. If memory behaviour i'm experiencing is not as it should be, i can try to further investigate it by somehow examining the JMP heap dump itself (it's a 95 mb text file). But i've suspected, that these resources are held by org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask, which looks (by it's name) as it was intended to held them...
Hide
Permalink
Jan Bartel added a comment -

Artem,

What are the open files that are reported in fstat?

Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050

Does it sound something like you are describing? If so, it is fixed in the version of jdk1.5 that was released on the 25th May (jdk1.5_07) - you could try with that jdk.

Show
Jan Bartel added a comment - Artem, What are the open files that are reported in fstat? Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 Does it sound something like you are describing? If so, it is fixed in the version of jdk1.5 that was released on the 25th May (jdk1.5_07) - you could try with that jdk.
Hide
Permalink
Greg Wilkins added a comment -

Artem,

What is holding IdleTask in memory? It should only be there for the maxIdleTime of the connector as it is on a timer
list.

Does shortening MaxIdleTime reduce this leak? It may simply be that the idle timeout is not being cancelled and
you have a lot of new connections... so these connections are being held in memory for that period of time.

Note that lots of work has been done on the idle timeout recently - so If changing the idle timeout does
change the rate of HttpConnection retention, then I would suggest trying Jetty head/trunk from SVN.

I will double check now that the idle timeout is cancelled when a connection is closed.

Show
Greg Wilkins added a comment - Artem, What is holding IdleTask in memory? It should only be there for the maxIdleTime of the connector as it is on a timer list. Does shortening MaxIdleTime reduce this leak? It may simply be that the idle timeout is not being cancelled and you have a lot of new connections... so these connections are being held in memory for that period of time. Note that lots of work has been done on the idle timeout recently - so If changing the idle timeout does change the rate of HttpConnection retention, then I would suggest trying Jetty head/trunk from SVN. I will double check now that the idle timeout is cancelled when a connection is closed.
Hide
Permalink
Greg Wilkins added a comment -

ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to.

So if you have a high connection rate (and not many persistent connections), this would cause the symptoms you are seeing.

Fix was simple and is in SVN head now.

Please can you test so I can close this issue.

Show
Greg Wilkins added a comment - ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to. So if you have a high connection rate (and not many persistent connections), this would cause the symptoms you are seeing. Fix was simple and is in SVN head now. Please can you test so I can close this issue.
Hide
Permalink
Artem Kozarezov added a comment -

Answering Jan Bartel questions:

What are the open files that are reported in fstat?

fstat.txt was attached to the bug report in the first place.

Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 - Does it sound something like you are describing?

No, as i've said, nor netstat neither sockstat report these leaked descriptors. A socket in the CLOSE_WAIT state will be reported by netstat.

Answering Greg Wilkins:

ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to.

This looks like it! I will test and report.
BTW, the maxIdleTime behaviour has changed in Jetty6. We had tasks which take a very long time to complete, and Jetty began to simply drop connections (this is becouse SO_TIMEOUT is set to 30 seconds, and connection is simply dropped by the OS after that perios), therefore we had to set maxIdleTime to 600 seconds! So, what you've described looks like the reason for this problem, indeed.

Show
Artem Kozarezov added a comment - Answering Jan Bartel questions : What are the open files that are reported in fstat? fstat.txt was attached to the bug report in the first place. Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 - Does it sound something like you are describing? No, as i've said, nor netstat neither sockstat report these leaked descriptors. A socket in the CLOSE_WAIT state will be reported by netstat. Answering Greg Wilkins : ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to. This looks like it! I will test and report. BTW, the maxIdleTime behaviour has changed in Jetty6. We had tasks which take a very long time to complete, and Jetty began to simply drop connections (this is becouse SO_TIMEOUT is set to 30 seconds, and connection is simply dropped by the OS after that perios), therefore we had to set maxIdleTime to 600 seconds! So, what you've described looks like the reason for this problem, indeed.
Hide
Permalink
Artem Kozarezov added a comment -

With Jetty SVN 550, and MaxIdleTime set to 60 seconds, amount of used file descriptors remains low.
With MaxIdleTime of 600 seconds it is still very high, though not indefinitely as before.

P.S.
I think using MaxIdleTime for active connections is a bug. When browser awaits result from a working server thread, connection is not exactly "idle". Under heavy load, it is practically always desirable to sat "idle" timeout (which, i suspect, is used for "keep-alive" connections, and have a separate timeout tweak in Apache) to be smaller than the general connection timeout.

Show
Artem Kozarezov added a comment - With Jetty SVN 550, and MaxIdleTime set to 60 seconds, amount of used file descriptors remains low. With MaxIdleTime of 600 seconds it is still very high, though not indefinitely as before. P.S. I think using MaxIdleTime for active connections is a bug. When browser awaits result from a working server thread, connection is not exactly "idle". Under heavy load, it is practically always desirable to sat "idle" timeout (which, i suspect, is used for "keep-alive" connections, and have a separate timeout tweak in Apache) to be smaller than the general connection timeout.
Hide
Permalink
Artem Kozarezov added a comment -

Correction to my previous coment. I think connection which have an allocated thread should be subject to a "working" connection timeout, and connection whose thread is released, that is, no longer in HttpServlet#service, should be subject to another connection timeout. If i understand it correctly, Jetty6 can benefit the application by buffering the response, so that HttpServlet#service may exit and thread be released while Jetty still is about to send what remains of response to the client. HttpServlet#service induced timeout should be separated somehow from pure TCP/IP timeout. Perhaps SO_TIMEOUT can simply be set to 0 until HttpServlet#service exit.

Show
Artem Kozarezov added a comment - Correction to my previous coment. I think connection which have an allocated thread should be subject to a "working" connection timeout, and connection whose thread is released, that is, no longer in HttpServlet#service, should be subject to another connection timeout. If i understand it correctly, Jetty6 can benefit the application by buffering the response, so that HttpServlet#service may exit and thread be released while Jetty still is about to send what remains of response to the client. HttpServlet#service induced timeout should be separated somehow from pure TCP/IP timeout. Perhaps SO_TIMEOUT can simply be set to 0 until HttpServlet#service exit.
Hide
Permalink
Artem Kozarezov added a comment -

Hmm, maybe i was too eager to say that it's working. After running for a hour with MaxIdleTime set to 60 seconds, amount of tcp file descriptors slowly increased from 70 to 230... While nestat (which includes TIME_WAIT sessions, whose timeout, if i'm remeber correctly, is two minutes!) shows only 90 connections.
But we might be on the right track, as the leak definitely scales with MaxIdleTime...

Show
Artem Kozarezov added a comment - Hmm, maybe i was too eager to say that it's working. After running for a hour with MaxIdleTime set to 60 seconds, amount of tcp file descriptors slowly increased from 70 to 230... While nestat (which includes TIME_WAIT sessions, whose timeout, if i'm remeber correctly, is two minutes!) shows only 90 connections. But we might be on the right track, as the leak definitely scales with MaxIdleTime...
Hide
Permalink
Artem Kozarezov added a comment -

Now it's 140 in netstat against 340 in fstat.
BTW, I have 121 IOException and 23 NullPointerException in the log.
A sample IOException:

java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcher.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:104)
at sun.nio.ch.IOUtil.write(IOUtil.java:75)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:302)
at org.mortbay.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:151)
at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.flush(SelectChannelConnector.java:
at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:758)
at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:721)
at org.mortbay.jetty.HttpConnection.completeResponse(HttpConnection.java:437)
at org.mortbay.jetty.Response.complete(Response.java:896)
at org.mortbay.jetty.HttpConnection.handlerRequest(HttpConnection.java:399)
at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:614)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:197)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:288)
at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.run(SelectChannelConnector.java:80
at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

and a sample NPE:

java.lang.NullPointerException
at org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:400)
at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)
at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:611)
at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

Could this be related to leaked IdleTask's?

Show
Artem Kozarezov added a comment - Now it's 140 in netstat against 340 in fstat. BTW, I have 121 IOException and 23 NullPointerException in the log. A sample IOException: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:104) at sun.nio.ch.IOUtil.write(IOUtil.java:75) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:302) at org.mortbay.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:151) at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.flush(SelectChannelConnector.java: at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:758) at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:721) at org.mortbay.jetty.HttpConnection.completeResponse(HttpConnection.java:437) at org.mortbay.jetty.Response.complete(Response.java:896) at org.mortbay.jetty.HttpConnection.handlerRequest(HttpConnection.java:399) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:614) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:197) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:288) at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.run(SelectChannelConnector.java:80 at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475) and a sample NPE: java.lang.NullPointerException at org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:400) at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:611) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475) Could this be related to leaked IdleTask's?
Hide
Permalink
Artem Kozarezov added a comment -

"lsof -i -n" output, with a lot of leaked descriptors
(meanwhile, "netstat -p tcp -a -n | wc -l" shows only 22 TCP/IP slots)

Show
Artem Kozarezov added a comment - "lsof -i -n" output, with a lot of leaked descriptors (meanwhile, "netstat -p tcp -a -n | wc -l" shows only 22 TCP/IP slots)
Hide
Permalink
Greg Wilkins added a comment -

I still think this could be a JVM issue as I don't think anything in Jetty can put a socket
into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE

we always call close and never just shutdown.

Can you repreoduce this problem running against the jetty test webapp?
Alternately can you send me a webapp that does have this problem so that I can
confirm that I am testing against the same conditions that you are.

Show
Greg Wilkins added a comment - I still think this could be a JVM issue as I don't think anything in Jetty can put a socket into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE we always call close and never just shutdown. Can you repreoduce this problem running against the jetty test webapp? Alternately can you send me a webapp that does have this problem so that I can confirm that I am testing against the same conditions that you are.
Hide
Permalink
Artem Kozarezov added a comment -

> I still think this could be a JVM issue as I don't think anything in Jetty can put a socket
> into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE

But i've traced, with JMP, that there are opened java.io.FileDescriptor's, referenced from sun.nio.ch.SocketChannelImpl, referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint...

> Can you repreoduce this problem running against the jetty test webapp?
> Alternately can you send me a webapp that does have this problem so that I can
> confirm that I am testing against the same conditions that you are.

I understand that you need more info. Please, wait until i have time to further trace why there is a lot of used SelectChannelConnector$HttpEndPoint objects (way too much) and/or write a test app, in an attempt to prove the problem. I can provide you with my app, but i suspect that a simple brute-force test won't lead to the same results.

Show
Artem Kozarezov added a comment - > I still think this could be a JVM issue as I don't think anything in Jetty can put a socket > into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE But i've traced, with JMP, that there are opened java.io.FileDescriptor's, referenced from sun.nio.ch.SocketChannelImpl, referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint... > Can you repreoduce this problem running against the jetty test webapp? > Alternately can you send me a webapp that does have this problem so that I can > confirm that I am testing against the same conditions that you are. I understand that you need more info. Please, wait until i have time to further trace why there is a lot of used SelectChannelConnector$HttpEndPoint objects (way too much) and/or write a test app, in an attempt to prove the problem. I can provide you with my app, but i suspect that a simple brute-force test won't lead to the same results.
Hide
Permalink
Artem Kozarezov added a comment -

With Jetty 6 i have a problem, practically always on a Windows box, when using localhost, and very seldom on a unix box, when a User-Agent session with Jetty hangs for no apparent reason after two or three subsequent request (loading a framed page with iframes). There is no such behaviour with the same page in Jetty 5. I suspect this might be related to the "leaked file descriptors" problem.

Here is the trace of hanging thread (using jetty-6.0.0rc0):
Thread [btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80] (Suspended)
owns: WindowsSelectorImpl (id=29)
owns: Collections$UnmodifiableSet<E> (id=30)
owns: Util$1 (id=31)
WindowsSelectorImpl$SubSelector.poll0(long, int, int[], int[], int[], long) line: not available [native method]
WindowsSelectorImpl$SubSelector.poll() line: 275
WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl$SubSelector) line: 257
WindowsSelectorImpl.doSelect(long) line: 138
WindowsSelectorImpl(SelectorImpl).lockAndDoSelect(long) line: 69
WindowsSelectorImpl(SelectorImpl).select(long) line: 80
SelectChannelConnector$SelectSet.accept() line: 361
SelectChannelConnector.accept(int) line: 177
AbstractConnector$Acceptor.run() line: 630
BoundedThreadPool$PoolThread.run() line: 475

In the SelectChannelConnector$SelectSet.accept() the variables are:

this= SelectChannelConnector$SelectSet (id=55)
_change= 0
_changes= ArrayList<E>[2] (id=70)
_idleTimeout= Timeout (id=71)
_duration= 60000
_head= Timeout$Task (id=93)
_now= 1152535639178
_nextSet= 0
_retryTimeout= Timeout (id=73)
_duration= 0
_head= Timeout$Task (id=95)
_now= 1152535639178
_selector= WindowsSelectorImpl (id=29)
cancelledKeys= HashSet<E> (id=96)
channelArray= SelectionKeyImpl[8] (id=100)
fdMap= WindowsSelectorImpl$FdMap (id=101)
finishLock= WindowsSelectorImpl$FinishLock (id=106)
INIT_CAP= 8
interruptLock= Object (id=108)
interruptor= AbstractSelector$1 (id=109)
interruptTriggered= false
keys= HashSet<E> (id=112)
pollWrapper= PollArrayWrapper (id=113)
provider= WindowsSelectorProvider (id=115)
publicKeys= Collections$UnmodifiableSet<E> (id=30)
publicSelectedKeys= Util$1 (id=31)
selectedKeys= HashSet<E> (id=120)
selectorOpen= AtomicBoolean (id=121)
startLock= WindowsSelectorImpl$StartLock (id=123)
subSelector= WindowsSelectorImpl$SubSelector (id=54)
threads= ArrayList<E> (id=125)
threadsCount= 0
timeout= 58477
totalChannels= 4
updateCount= 29
wakeupPipe= PipeImpl (id=126)
wakeupSinkFd= 2212
wakeupSourceFd= 2224
_setID= 0
_shortIdleTimeout= Timeout (id=76)
_duration= 2500
_head= Timeout$Task (id=168)
_now= 1152535639178
this$0= SelectChannelConnector (id=56)
_acceptChannel= ServerSocketChannelImpl (id=131)
_acceptKey= SelectionKeyImpl (id=141)
_acceptors= 1
_acceptorThread= Thread[1] (id=144)
_acceptQueueSize= 0
_confidentialPort= 0
_confidentialScheme= "https"
_connections= 0
_connectionsDurationMax= 0
_connectionsDurationMin= 0
_connectionsDurationTotal= 0
_connectionsOpen= 0
_connectionsOpenMax= 0
_connectionsOpenMin= 0
_connectionsRequestsMax= 0
_connectionsRequestsMin= 0
_delaySelectKeyUpdate= false
_headerBuffers= ArrayList<E> (id=148)
_headerBufferSize= 4096
_host= "localhost"
_integralPort= 0
_integralScheme= "https"
_lowResourceMaxIdleTime= 2500
_maxIdleTime= 60000
_name= null
_port= 80
_requestBuffers= ArrayList<E> (id=150)
_requestBufferSize= 8192
_requests= 0
_responseBuffers= ArrayList<E> (id=151)
_responseBufferSize= 32768
_selectSets= SelectChannelConnector$SelectSet[1] (id=152)
_server= Server (id=153)
_soLingerTime= 1000
_state= 2
_statsLock= Object (id=161)
_statsStartedAt= -1
_threadPool= BoundedThreadPool (id=162)
_useDNS= false
FAILED= -1
STARTED= 2
STARTING= 1
STOPPED= 0
STOPPING= 3
short_next= -1
idle_next= 58477
retry_next= -1
changes= ArrayList<E> (id=59)
wait= 58477

I will now attach the captured packets of that session.

Show
Artem Kozarezov added a comment - With Jetty 6 i have a problem, practically always on a Windows box, when using localhost, and very seldom on a unix box, when a User-Agent session with Jetty hangs for no apparent reason after two or three subsequent request (loading a framed page with iframes). There is no such behaviour with the same page in Jetty 5. I suspect this might be related to the "leaked file descriptors" problem. Here is the trace of hanging thread (using jetty-6.0.0rc0): Thread [btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80] (Suspended) owns: WindowsSelectorImpl (id=29) owns: Collections$UnmodifiableSet<E> (id=30) owns: Util$1 (id=31) WindowsSelectorImpl$SubSelector.poll0(long, int, int[], int[], int[], long) line: not available [native method] WindowsSelectorImpl$SubSelector.poll() line: 275 WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl$SubSelector) line: 257 WindowsSelectorImpl.doSelect(long) line: 138 WindowsSelectorImpl(SelectorImpl).lockAndDoSelect(long) line: 69 WindowsSelectorImpl(SelectorImpl).select(long) line: 80 SelectChannelConnector$SelectSet.accept() line: 361 SelectChannelConnector.accept(int) line: 177 AbstractConnector$Acceptor.run() line: 630 BoundedThreadPool$PoolThread.run() line: 475 In the SelectChannelConnector$SelectSet.accept() the variables are: this= SelectChannelConnector$SelectSet (id=55) _change= 0 _changes= ArrayList<E> [2] (id=70) _idleTimeout= Timeout (id=71) _duration= 60000 _head= Timeout$Task (id=93) _now= 1152535639178 _nextSet= 0 _retryTimeout= Timeout (id=73) _duration= 0 _head= Timeout$Task (id=95) _now= 1152535639178 _selector= WindowsSelectorImpl (id=29) cancelledKeys= HashSet<E> (id=96) channelArray= SelectionKeyImpl [8] (id=100) fdMap= WindowsSelectorImpl$FdMap (id=101) finishLock= WindowsSelectorImpl$FinishLock (id=106) INIT_CAP= 8 interruptLock= Object (id=108) interruptor= AbstractSelector$1 (id=109) interruptTriggered= false keys= HashSet<E> (id=112) pollWrapper= PollArrayWrapper (id=113) provider= WindowsSelectorProvider (id=115) publicKeys= Collections$UnmodifiableSet<E> (id=30) publicSelectedKeys= Util$1 (id=31) selectedKeys= HashSet<E> (id=120) selectorOpen= AtomicBoolean (id=121) startLock= WindowsSelectorImpl$StartLock (id=123) subSelector= WindowsSelectorImpl$SubSelector (id=54) threads= ArrayList<E> (id=125) threadsCount= 0 timeout= 58477 totalChannels= 4 updateCount= 29 wakeupPipe= PipeImpl (id=126) wakeupSinkFd= 2212 wakeupSourceFd= 2224 _setID= 0 _shortIdleTimeout= Timeout (id=76) _duration= 2500 _head= Timeout$Task (id=168) _now= 1152535639178 this$0= SelectChannelConnector (id=56) _acceptChannel= ServerSocketChannelImpl (id=131) _acceptKey= SelectionKeyImpl (id=141) _acceptors= 1 _acceptorThread= Thread [1] (id=144) _acceptQueueSize= 0 _confidentialPort= 0 _confidentialScheme= "https" _connections= 0 _connectionsDurationMax= 0 _connectionsDurationMin= 0 _connectionsDurationTotal= 0 _connectionsOpen= 0 _connectionsOpenMax= 0 _connectionsOpenMin= 0 _connectionsRequestsMax= 0 _connectionsRequestsMin= 0 _delaySelectKeyUpdate= false _headerBuffers= ArrayList<E> (id=148) _headerBufferSize= 4096 _host= "localhost" _integralPort= 0 _integralScheme= "https" _lowResourceMaxIdleTime= 2500 _maxIdleTime= 60000 _name= null _port= 80 _requestBuffers= ArrayList<E> (id=150) _requestBufferSize= 8192 _requests= 0 _responseBuffers= ArrayList<E> (id=151) _responseBufferSize= 32768 _selectSets= SelectChannelConnector$SelectSet [1] (id=152) _server= Server (id=153) _soLingerTime= 1000 _state= 2 _statsLock= Object (id=161) _statsStartedAt= -1 _threadPool= BoundedThreadPool (id=162) _useDNS= false FAILED= -1 STARTED= 2 STARTING= 1 STOPPED= 0 STOPPING= 3 short_next= -1 idle_next= 58477 retry_next= -1 changes= ArrayList<E> (id=59) wait= 58477 I will now attach the captured packets of that session.
Hide
Permalink
Artem Kozarezov added a comment -

On a second thought, perhaps it is a separate issue, i don't think the file descriptor is leaked here...

Show
Artem Kozarezov added a comment - On a second thought, perhaps it is a separate issue, i don't think the file descriptor is leaked here...
Hide
Permalink
Artem Kozarezov added a comment -

properly filtered

Show
Artem Kozarezov added a comment - properly filtered
Hide
Permalink
Artem Kozarezov added a comment -

Perhaps the browser is hanging becouse the last "302 Found" response is empty.
Shouldn't there be two "0"'s instead of one?
(Reconstruction of last keepalive request follows)

GET /cmsIface/i568948258i/ HTTP/1.1
Host: localhost
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; ru; rv:1.8.0.4) Gecko/20060508 Firefox/1.5.0.4
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5
Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip,deflate
Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Referer: http://localhost/cmsIface/
Cookie: wcForumSession1=1691zp24s1ov3_j1zdtt

HTTP/1.1 302 Found
Server: WebCRM/1.2 (via Jetty6)
Content-Type: text/html; charset=UTF-8
WWW-Authenticate: Basic realm="quadro cmsIface"
Cache-Control: no-cache
Pragma: no-cache
Location: /cmsIface/error&gvgyr=Gur~20yvax~20unf~20rkcverq~20~28gung~27f~20BX~29.&glcr=wnin.ynat.Rkprcgvba&fgnpxUnfu=ZUB&qngr=rcti9lvy
Transfer-Encoding: chunked
Connection: keep-alive

0

Show
Artem Kozarezov added a comment - Perhaps the browser is hanging becouse the last "302 Found" response is empty. Shouldn't there be two "0"'s instead of one? (Reconstruction of last keepalive request follows) GET /cmsIface/i568948258i/ HTTP/1.1 Host: localhost User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; ru; rv:1.8.0.4) Gecko/20060508 Firefox/1.5.0.4 Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png, / ;q=0.5 Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3 Accept-Encoding: gzip,deflate Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Referer: http://localhost/cmsIface/ Cookie: wcForumSession1=1691zp24s1ov3_j1zdtt HTTP/1.1 302 Found Server: WebCRM/1.2 (via Jetty6) Content-Type: text/html; charset=UTF-8 WWW-Authenticate: Basic realm="quadro cmsIface" Cache-Control: no-cache Pragma: no-cache Location: /cmsIface/error&gvgyr=Gur~20yvax~20unf~20rkcverq~20~28gung~27f~20BX~29.&glcr=wnin.ynat.Rkprcgvba&fgnpxUnfu=ZUB&qngr=rcti9lvy Transfer-Encoding: chunked Connection: keep-alive 0
Hide
Permalink
Artem Kozarezov added a comment -

BTW, apparently, Jetty 6 waits for a next KeepAlive request with a blocking IO operation here, using the "btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80" thread. I thought that Jetty 6 will do this with a non-blocking IO. Shouldn't it?

Show
Artem Kozarezov added a comment - BTW, apparently, Jetty 6 waits for a next KeepAlive request with a blocking IO operation here, using the "btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80" thread. I thought that Jetty 6 will do this with a non-blocking IO. Shouldn't it?
Hide
Permalink
Greg Wilkins added a comment -

Artem,

The single 0 is OK - it is a zero chunk and indicates no content. Although generally speaking
I prefer if jetty was to send back a content-length: 0 instead of an empty chunk.

But the strange this is that there is a WWW-Authenticate challenge in a 302 response?
This should be a 401 response?

What is your security constraint configuration?
this really should be a new issue! Can you open a new issue and attach your web.xml

Show
Greg Wilkins added a comment - Artem, The single 0 is OK - it is a zero chunk and indicates no content. Although generally speaking I prefer if jetty was to send back a content-length: 0 instead of an empty chunk. But the strange this is that there is a WWW-Authenticate challenge in a 302 response? This should be a 401 response? What is your security constraint configuration? this really should be a new issue! Can you open a new issue and attach your web.xml
Hide
Permalink
Greg Wilkins added a comment -

YIPEEEEE!!!!!!!!!!!!!!!!!! fixed!

The issue was that ab (and I expect other clients) sends a strange ack for the last data packet... which causes
the server to reset the connection rather than close it gracefully. This caused socket.shutdownOutput()
to throw an alreadyShutdown exception, which caused the calls to socket.close() and channel.close() to be missed!

The reason the socket.shutdownOutput and socket.close are there is because a pure channel.close() does
not appear to allow the socket to close quickly and there is a big delay injected.

So the fix is to protect all of these with finally calls, so that all three methods will always be called.
Obvious with 20:20 hindsight!

Thanks all for your perseverence in helping me find this one and thanks Christian for giving me access to
his machine.

Show
Greg Wilkins added a comment - YIPEEEEE!!!!!!!!!!!!!!!!!! fixed! The issue was that ab (and I expect other clients) sends a strange ack for the last data packet... which causes the server to reset the connection rather than close it gracefully. This caused socket.shutdownOutput() to throw an alreadyShutdown exception, which caused the calls to socket.close() and channel.close() to be missed! The reason the socket.shutdownOutput and socket.close are there is because a pure channel.close() does not appear to allow the socket to close quickly and there is a big delay injected. So the fix is to protect all of these with finally calls, so that all three methods will always be called. Obvious with 20:20 hindsight! Thanks all for your perseverence in helping me find this one and thanks Christian for giving me access to his machine.
Hide
Permalink
Artem Kozarezov added a comment -

Cool.

Show
Artem Kozarezov added a comment - Cool.
Hide
Permalink
Kirill Lastovirya added a comment -

was the issue solved? I see very similar behavior on jetty versions starting from 6.1.16
can I create an issue, I can provide detailed description

Show
Kirill Lastovirya added a comment - was the issue solved? I see very similar behavior on jetty versions starting from 6.1.16 can I create an issue, I can provide detailed description
Hide
Permalink
Jesse McConnell added a comment -

yes this issue was resolved ages ago

if your having a similar problem then please do open a new issue and provide details

Show
Jesse McConnell added a comment - yes this issue was resolved ages ago if your having a similar problem then please do open a new issue and provide details

People

  • Assignee:
    Greg Wilkins
    Reporter:
    Artem Kozarezov
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: