ClientTLSChannel#read sometimes hangs

[JasonTheKitten]

Hello

For a project I'm working on, the read method was hanging (no exceptions thrown, just hanging forever). I don't know how to reproduce it, but it was happening consistently on my application when I requested a certain site. It seems to be a race condition, as the issue went away if I ran some println between reads /shrug,

This behavior only happens in 4.0.0, so I have downgraded to 3.2.0 for now.

[marianobarrios]

Hi Jason, Thanks for the report. I know it may be hard to extract, but is there a chance that you can send an example of the code that makes it hang?

Alternatively, does it happen when you enable logging at the trace level? If so, getting the logs when it hangs would be helpful.

[JasonTheKitten]

Hello,

The codebase is rather giant, so sending an example of the code may not be plausible. I can send you a link to the repo.

Here is the logger's output:

11:15:35.857 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Called engine.beginHandshake()
11:15:35.859 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=BUFFER_OVERFLOW,handshakeStatus=NEED_WRAP,bytesProduced=0,bytesConsumed=0]; engine status: NEED_WRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.860 [Thread-0] TRACE tlschannel.impl.BufferHolder - enlarging buffer outEncrypted, increasing from 4096 to 8192 (automatic enlarge)
11:15:35.861 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=BUFFER_OVERFLOW,handshakeStatus=NEED_WRAP,bytesProduced=0,bytesConsumed=0]; engine status: NEED_WRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.861 [Thread-0] TRACE tlschannel.impl.BufferHolder - enlarging buffer outEncrypted, increasing from 8192 to 16384 (automatic enlarge)
11:15:35.861 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=BUFFER_OVERFLOW,handshakeStatus=NEED_WRAP,bytesProduced=0,bytesConsumed=0]; engine status: NEED_WRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.861 [Thread-0] TRACE tlschannel.impl.BufferHolder - enlarging buffer outEncrypted, increasing from 16384 to 17408 (automatic enlarge)
11:15:35.862 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=OK,handshakeStatus=NEED_UNWRAP,bytesProduced=403,bytesConsumed=0]; engine status: NEED_UNWRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.863 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Writing to channel: java.nio.DirectByteBuffer[pos=0 lim=403 cap=17408]
11:15:35.863 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NEED_UNWRAP,bytesProduced=0,bytesConsumed=0]. Engine status: NEED_UNWRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.863 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:35.884 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 99, buffer: java.nio.DirectByteBuffer[pos=99 lim=4096 cap=4096]
11:15:35.885 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_TASK,bytesProduced=0,bytesConsumed=93]. Engine status: NEED_TASK; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.900 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=OK,handshakeStatus=NEED_UNWRAP,bytesProduced=436,bytesConsumed=0]; engine status: NEED_UNWRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.901 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Writing to channel: java.nio.DirectByteBuffer[pos=0 lim=436 cap=17408]
11:15:35.901 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_UNWRAP,bytesProduced=0,bytesConsumed=6]. Engine status: NEED_UNWRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.901 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NEED_UNWRAP,bytesProduced=0,bytesConsumed=0]. Engine status: NEED_UNWRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.901 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:35.921 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 2920, buffer: java.nio.DirectByteBuffer[pos=2920 lim=4096 cap=4096]
11:15:35.922 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_TASK,bytesProduced=0,bytesConsumed=160]. Engine status: NEED_TASK; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.935 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=OK,handshakeStatus=NEED_UNWRAP,bytesProduced=6,bytesConsumed=0]; engine status: NEED_UNWRAP; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:35.935 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Writing to channel: java.nio.DirectByteBuffer[pos=0 lim=6 cap=17408]
11:15:35.937 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_TASK,bytesProduced=0,bytesConsumed=28]. Engine status: NEED_TASK; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.937 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NEED_UNWRAP,bytesProduced=0,bytesConsumed=0]. Engine status: NEED_UNWRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:35.937 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:35.937 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 1364, buffer: java.nio.DirectByteBuffer[pos=4096 lim=4096 cap=4096]
11:15:35.941 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_TASK,bytesProduced=0,bytesConsumed=4007]. Engine status: NEED_TASK; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:36.003 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NEED_UNWRAP,bytesProduced=0,bytesConsumed=0]. Engine status: NEED_UNWRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:36.004 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:36.004 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 271, buffer: java.nio.DirectByteBuffer[pos=360 lim=4096 cap=4096]
11:15:36.004 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_TASK,bytesProduced=0,bytesConsumed=286]. Engine status: NEED_TASK; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:36.012 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NEED_WRAP,bytesProduced=0,bytesConsumed=74]. Engine status: NEED_WRAP; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]], offset=0, length=1]
11:15:36.013 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=OK,handshakeStatus=FINISHED,bytesProduced=90,bytesConsumed=0]; engine status: FINISHED; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:36.013 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Writing to channel: java.nio.DirectByteBuffer[pos=0 lim=90 cap=17408]
11:15:36.014 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.wrap() result: [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=371,bytesConsumed=333]; engine status: NOT_HANDSHAKING; srcBuffer: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=333 lim=333 cap=333]], offset=0, length=1], outEncrypted: tlschannel.impl.BufferHolder@380d3d31
11:15:36.015 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Writing to channel: java.nio.DirectByteBuffer[pos=0 lim=371 cap=17408]
11:15:36.016 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. Engine status: NOT_HANDSHAKING; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]], offset=0, length=1]
11:15:36.016 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:36.035 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 478, buffer: java.nio.DirectByteBuffer[pos=478 lim=4096 cap=4096]
11:15:36.036 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=FINISHED,bytesProduced=0,bytesConsumed=239]. Engine status: FINISHED; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]], offset=0, length=1]
11:15:36.036 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel
11:15:36.056 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Read from channel; response: 1635, buffer: java.nio.DirectByteBuffer[pos=1874 lim=4096 cap=4096]
11:15:36.057 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=FINISHED,bytesProduced=0,bytesConsumed=239]. Engine status: FINISHED; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]], offset=0, length=1]
11:15:36.057 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - Reading from channel

And it hangs there

While working on some of the debugging, I found that if I let it sit a really long time (3 minutes) it eventually finishes hanging
11:18:36.354 [Thread-0] TRACE tlschannel.impl.TlsChannelImpl - engine.unwrap() result [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=1256,bytesConsumed=1278]. Engine status: NOT_HANDSHAKING; inEncrypted tlschannel.impl.BufferHolder@636225b8; inPlain: ByteBufferSet[array=[java.nio.HeapByteBuffer[pos=1256 lim=8192 cap=8192]], offset=0, length=1]

The site I am requesting here is https://www.example.com/

At this point, my code is in blocking mode, as I just realized, but downgrading to 0.3.2 caused things to work, so I think the library is the one with the bug, not the speed at which data is received. (Also, as I mentioned, there seems to be a race condition)

EDIT:
Setting the stream as non-blocking fixes the bug, so this is only a bug in blocking mode. It's definitely not waiting for more data (the data is being sent to the client almost instantly), so I do not know why it is hanging in blocking mode.
For my purposes, this is good enough. But in general, you may still want to find the bug.

[marianobarrios]

Hi Jason,

Sorry for the delay in the response. I tried hard, but could not reproduce your hanging. However, the master branch evolved in the last weeks, including some logical cleanups that might have fixed the bug. Is testing again with master something you could do?

Thanks and regards.

[JasonTheKitten]

In the original issue I opened, I mistyped the version number (it's 0.4.0, not 4.0.0. Same for the version that had been working).

However, even on that version, and using the same test site, I cannot reproduce it anymore, which is why I closed this issue.
I also tried to reproduce it on my previous computer (because I'm not sure if the bug had occurred on this computer or my previous computer), but could not reproduce it there either.

So either the issue only occurs on certain networks, or it was a one-off error.

[JasonTheKitten]

So if (using version 0.4.2), you go to the other bug I opened (For a totally different issue)
#30
And take the reproduction code for that bug
And change line 122 from sockChannel.configureBlocking(false); to sockChannel.configureBlocking(true);
You are also able to reproduce this bug too

I cannot test with the master branch because jitpack.io (the tool I use for using snapshots) will not compile the library.

[marianobarrios]

Thanks. I could reproduce it, and confirm that I the problem was already gone in master. So I just releases 0.5.0.

[JasonTheKitten]

Thank you!