[
https://issues.apache.org/jira/browse/HTTPCORE-366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13839967#comment-13839967
]
Oleg Kalnichevski commented on HTTPCORE-366:
--------------------------------------------
Infinite session loops are nasty. I'll sleep better with this check in place.
Oleg
> 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
> Fix For: 4.3.1
>
> Attachments: HTTPCORE-366.2.patch, HTTPCORE-366.patch
>
>
> 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
