Isaac Cruz Ballesteros created HTTPCORE-366:
-----------------------------------------------
Summary: Infinite loop when using HTTPS server + NIO
Key: HTTPCORE-366
URL: https://issues.apache.org/jira/browse/HTTPCORE-366
Project: HttpComponents HttpCore
Issue Type: Bug
Components: HttpCore NIO
Affects Versions: 4.2.5
Reporter: Isaac Cruz Ballesteros
This affects 4.2.5 but probably the newer versions as well.
So I'm setting a HTTPS server using NIO to receive uploads from clients.
Clients are using libcurl to upload.
I've detected that sometimes (one every 2-4 days) the java process takes 100%
cpu, and it's the "I/O dispatcher" thread which is in a infinite loop, with
stack traces such as:
"I/O dispatcher 1" prio=10 tid=0x00007f3e2400b000 nid=0x11c9 runnable
[0x00007f3e3995e000]
java.lang.Thread.State: RUNNABLE
at
org.apache.http.impl.nio.reactor.IOSessionImpl.getEventMask(IOSessionImpl.java:139)
- locked <0x00000000e09f5a70> (a
org.apache.http.impl.nio.reactor.IOSessionImpl)
at
org.apache.http.nio.reactor.ssl.SSLIOSession.updateEventMask(SSLIOSession.java:306)
at
org.apache.http.nio.reactor.ssl.SSLIOSession.inboundTransport(SSLIOSession.java:411)
- locked <0x00000000e09f6938> (a
org.apache.http.nio.reactor.ssl.SSLIOSession)
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:220)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:284)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:613)
at java.lang.Thread.run(Thread.java:662)
"I/O dispatcher 1" prio=10 tid=0x00007f01a000b000 nid=0x1f78 runnable
[0x00007f01d1cf6000]
java.lang.Thread.State: RUNNABLE
at
org.apache.http.nio.reactor.ssl.SSLIOSession.doHandshake(SSLIOSession.java:276)
at
org.apache.http.nio.reactor.ssl.SSLIOSession.isAppInputReady(SSLIOSession.java:381)
- locked <0x00000000e08b5178> (a
org.apache.http.nio.reactor.ssl.SSLIOSession)
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:118)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:160)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:342)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:320)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:613)
at java.lang.Thread.run(Thread.java:662)
The socket in the server side is in CLOSE_WAIT state, so the client closed the
connection but not the server.
I added some logs to the httpcore-nio library to try to know some details of
when this issue happens, specifically in AbstractIODispatch.inputReady() and in
several places in SSLIOSession, to print the SSLEngineResult after doWrap and
doUnwrap in doHandshake() and decryptData() method, and also in
isAppInputReady() to print bytesRead, inEncrypted buffer state, and
HandshakeStatus.
I'm going to explain what I found, if you want I can attach the complete
generated logs.
So after handshake and some data exchange, we start receiving data from client,
and we keep getting a BUFFER_UNDERFLOW until the inEncrypted buffer is complete:
2013-11-26 02:59:37,914 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 1346, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665
cap=16665]
2013-11-26 02:59:37,915 [I/O dispatcher 1] ssl.SSLIOSession: result from
unwrap: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 16421 bytesProduced = 16384
We produce 16384 bytes of user data, and from here we start receiving more data:
2013-11-26 02:59:37,915 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 34, inEncrypted: java.nio.HeapByteBuffer[pos=278 lim=16665 cap=16665]
2013-11-26 02:59:37,948 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 1380, inEncrypted: java.nio.HeapByteBuffer[pos=1658 lim=16665 cap=16665]
2013-11-26 02:59:37,982 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 1380, inEncrypted: java.nio.HeapByteBuffer[pos=3038 lim=16665 cap=16665]
2013-11-26 02:59:38,017 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 1380, inEncrypted: java.nio.HeapByteBuffer[pos=4418 lim=16665 cap=16665]
2013-11-26 02:59:38,051 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 1380, inEncrypted: java.nio.HeapByteBuffer[pos=5798 lim=16665 cap=16665]
2013-11-26 02:59:38,391 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 4140, inEncrypted: java.nio.HeapByteBuffer[pos=9938 lim=16665 cap=16665]
2013-11-26 02:59:38,440 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 5520, inEncrypted: java.nio.HeapByteBuffer[pos=15458 lim=16665
cap=16665]
Between all these recvs we always get a BUFFER_UNDERFLOW from unwrap()
>From that time (note that the inEncrypted buffer is still not full) we stop
>receiving any data. For some reason there's a call to isAppInputReady() every
>second, which always do the same: bytesRead = 0, buffer_underflow. I don't
>know why this is called even though this channel hasn't been "selected" by
>select(), I think it comes from the validate() call in AbstractIOReactor line
>284:
// Validate active channels
validate(this.selector.keys());
But anyway, this isn't very important.
The point is after 30 seconds from last packet sent, the client closes
connection. This is probably a timeout, not sure, and I also don't understand
why the server thinks it needs more data to decrypt, and why the client does
not send more data if that's true.... In any case, after 30 seconds this is
what happens:
2013-11-26 03:00:07,481 [I/O dispatcher 1] nio.DefaultHttpServerIODispatch:
inputReady on 192.168.100.40:9443<->75.37.10.219:40186[ACTIVE][r:r]
2013-11-26 03:00:07,481 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 0, inEncrypted: java.nio.HeapByteBuffer[pos=15458 lim=16665 cap=16665]
2013-11-26 03:00:07,481 [I/O dispatcher 1] ssl.SSLIOSession: handshake status:
NOT_HANDSHAKING
2013-11-26 03:00:07,481 [I/O dispatcher 1] ssl.SSLIOSession: result from
unwrap: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
2013-11-26 03:00:08,483 [I/O dispatcher 1] nio.DefaultHttpServerIODispatch:
inputReady on 192.168.100.40:9443<->75.37.10.219:40186[ACTIVE][rw:r]
2013-11-26 03:00:08,483 [I/O dispatcher 1] ssl.SSLIOSession: bytesRead from
socket: 0, inEncrypted: java.nio.HeapByteBuffer[pos=15458 lim=16665 cap=16665]
2013-11-26 03:00:08,483 [I/O dispatcher 1] ssl.SSLIOSession: result from wrap:
Status = CLOSED HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 37
2013-11-26 03:00:08,483 [I/O dispatcher 1] ssl.SSLIOSession: handshake status:
NEED_UNWRAP
>From here it starts an infinite loop: it's calling continuously the
>inputReady() method, but it never closes the socket, it keeps getting status =
>BUFFER_UNDERFLOW when calling unwrap() and handshake status = NEED_UNWRAP (as
>the client has closed SSL session)
--
This message was sent by Atlassian JIRA
(v6.1#6144)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@hc.apache.org
For additional commands, e-mail: dev-h...@hc.apache.org
