[
https://issues.apache.org/jira/browse/HTTPCORE-366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13836537#comment-13836537
]
Isaac Cruz Ballesteros commented on HTTPCORE-366:
-------------------------------------------------
Got it! So it's related to the timeout handling, but not exactly what I said
above. One important thing: this server is having some freezing issues (it's a
VM) which makes sometimes to hang during 1 minute, and then continues. I have
made a test which simulates this by waiting 40 secs between the first data
packet and the second (and setting SO_TIMEOUT to 30 secs).
This is roughly the test:
<HANDSHAKE>
outPlain.put(("PUT " + uploadUrl.getPath() + "
HTTP/1.1\r\n").getBytes());
outPlain.put("host: localhost\r\n".getBytes());
outPlain.put("Content-Length: 50000\r\n".getBytes());
outPlain.put("\r\n".getBytes());
byte[] data = new byte[50000];
Arrays.fill(data, (byte)'0');
outPlain.put(data);
outPlain.flip();
int i = 1;
while (outPlain.hasRemaining()) {
result = sslEngine.wrap(outPlain, outEncrypted);
System.out.println("Result from wrap: " + result);
outEncrypted.flip();
int bytesWritten = channel.write(outEncrypted);
System.out.println("Written " + bytesWritten + " bytes");
outEncrypted.compact();
if (i == 1) {
// Wait 40 secs between two packets
Thread.sleep(40000);
}
i++;
}
And this is the log:
First packet after handshake:
bytesConsumed = 16384 bytesProduced = 16405
Written 16405 bytes
2013-12-02 14:59:59,064 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 16405, inEncrypted: java.nio.HeapByteBuffer[pos=16405 lim=16665
cap=16665]
2013-12-02 14:59:59,064 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NOT_HANDSHAKING
2013-12-02 14:59:59,066 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 16405 bytesProduced = 16384
2013-12-02 14:59:59,079 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - Request handler for URI /upload/a3a9dfe1
2013-12-02 14:59:59,080 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - onRequestReceived()
2013-12-02 14:59:59,081 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - Writing to file: target\dest, offset=0
2013-12-02 14:59:59,082 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - onEntityEnclosed()
2013-12-02 14:59:59,082 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - Incoming entity content (bytes): 50000
2013-12-02 14:59:59,082 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - onContentReceived()
2013-12-02 14:59:59,082 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - Transferred 8119 bytes to file target\dest
2013-12-02 14:59:59,084 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - Transferred 8192 bytes to file target\dest
30 seconds later, the timeout:
2013-12-02 15:00:29,084 [I/O dispatcher 2] DEBUG
datatransfer.DataTransferModule - releaseResources()
2013-12-02 15:00:29,089 [I/O dispatcher 2] TRACE ssl.SSLIOSession -
closeOutbound SSL session
Upload Completed
2013-12-02 15:00:29,089 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from wrap: Status = CLOSED HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 23
2013-12-02 15:00:29,090 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_UNDERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
and 10 seconds later, it sends the rest of the data and enter into infinite
loop (I removed your check for this test):
Result from wrap: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 16384 bytesProduced = 16405
Written 16405 bytes
2013-12-02 15:00:39,069 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 16405, inEncrypted: java.nio.HeapByteBuffer[pos=16405 lim=16665
cap=16665]
Result from wrap: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 16384 bytesProduced = 16405
2013-12-02 15:00:39,074 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 16405 bytesProduced = 16384
Written 16405 bytes
2013-12-02 15:00:39,075 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_UNDERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,075 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
Result from wrap: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 921 bytesProduced = 942
Written 942 bytes
2013-12-02 15:00:39,075 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 16405, inEncrypted: java.nio.HeapByteBuffer[pos=16405 lim=16665
cap=16665]
2013-12-02 15:00:39,075 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,075 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
2013-12-02 15:00:39,076 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 260, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665
cap=16665]
2013-12-02 15:00:39,076 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,076 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
2013-12-02 15:00:39,076 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 0, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665
cap=16665]
2013-12-02 15:00:39,076 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 0, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665
cap=16665]
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - bytesRead
from socket: 0, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665
cap=16665]
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - result
from unwrap: Status = BUFFER_OVERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2013-12-02 15:00:39,077 [I/O dispatcher 2] TRACE ssl.SSLIOSession - handshake
status: NEED_UNWRAP
So the problem is not that it's uncapable of decrypting received data, the
problem is the inPlain buffer is full because it doesn't seem to consume it
once the timeout has triggered.
> 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.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
