hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Isaac Cruz Ballesteros (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (HTTPCORE-366) Infinite loop when using HTTPS server + NIO
Date Tue, 26 Nov 2013 17:50:37 GMT

    [ https://issues.apache.org/jira/browse/HTTPCORE-366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13832795#comment-13832795
] 

Isaac Cruz Ballesteros edited comment on HTTPCORE-366 at 11/26/13 5:50 PM:
---------------------------------------------------------------------------

Well let me test it tomorrow, I inserted a throw new IOException under some conditions (when
bytesRead == 0, status == NEED_UNWRAP and there are some bytes available in inEncrypted) because
otherwise due to the infinite loop the logs where completely filled up in seconds and I lost
the beginning, the trigger of this issue...

I think bytesRead returns -1 only once, when the socket is closed from the other side. What
I'm not sure is in that example, which side is actually closing the connection... because
the SSL engine set the status to CLOSED but it has not received anything from the client,
so I think it's the library which is closing the session (I'm setting CoreConnectionPNames.SO_TIMEOUT
to 30 seconds). Maybe this is not actually the cause of the infinite loop, I will change the
"exception condition" to make sure I detect correctly when there's an infinite loop.

By the way, this is the generated log when there was an infinite loop:

2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE nio.DefaultHttpServerIODispatch: inputReady
on 192.168.100.40:9443<->75.37.14.167:41739[ACTIVE][r:r]
2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE ssl.SSLIOSession: bytesRead from socket:
0, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665 cap=16665]
2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE ssl.SSLIOSession: handshake status: NEED_UNWRAP
(repeated infinite times with zero delay)

In this case the inEncrypted buffer was full, and from netstat command I saw there was some
more incoming data in the Recv-R column. If this happens, it will probably not receive -1
until all incoming data has been read.... but it cannot read incoming data because the inEncrypted
buffer is full. What I don't understand is why it cannot unwrap anything from inEncrypted,
it's sized from session.getPacketBufferSize() so it should be as large as the max size of
a SSL packet... right?


was (Author: icruz):
Well let me test it tomorrow, I inserted a throw new IOException under some conditions (when
bytesRead == 0, status == NEED_UNWRAP and there are some bytes available in inEncrypted) because
otherwise due to the infinite loop the logs where completely filled up in seconds and I lost
the beginning, the trigger of this issue...

I think bytesRead returns -1 only once, when the socket is closed from the other side. What
I'm not sure is in that example, which side is actually closing the connection... because
the SSL engine set the status to CLOSED but it has not received anything from the client,
so I think it's the library which is closing the session (I'm setting CoreConnectionPNames.SO_TIMEOUT
to 30 seconds). Maybe this is not actually the cause of the infinite loop, I will change the
"exception condition" to make sure I detect correctly when there's an infinite loop.

By the way, this is the generated log when there was an infinite loop:

2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE nio.DefaultHttpServerIODispatch: inputReady
on 192.168.100.40:9443<->75.37.14.167:41739[ACTIVE][r:r]
2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE ssl.SSLIOSession: bytesRead from socket:
0, inEncrypted: java.nio.HeapByteBuffer[pos=16665 lim=16665 cap=16665]
2013-11-25 03:28:40,785 [I/O dispatcher 1] TRACE ssl.SSLIOSession: handshake status: NEED_UNWRAP
(repeated infinite times with zero delay)

In this case the inEncrypted buffer was full, and from netstat command I saw there was some
more incoming data in the Send-R column. If this happens, it will probably not receive -1
until all incoming data has been read.... but it cannot read incoming data because the inEncrypted
buffer is full. What I don't understand is why it cannot unwrap anything from inEncrypted,
it's sized from session.getPacketBufferSize() so it should be as large as the max size of
a SSL packet... right?

> 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-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message