eclipse-ee4j / grizzly

Grizzly
https://eclipse-ee4j.github.io/grizzly
Other
147 stars 69 forks source link

Prevent infinite loop when using TLS 1.3 #2124

Closed Pandrex247 closed 3 years ago

Pandrex247 commented 3 years ago

Under certain conditions when using TLS 1.3 and JDK11, an infinite loop can occur during handshaking (until it times out anyway). This appears to be in some way related to the behaviour of TLS 1.3 not requiring a closeNotify to be sent (the issue disappears when the system property to bring back the old behaviour is active).

Following the logic of the unwrapAll method and the output of the log, it appears to occur when trying to gracefully terminate the SSL connection - I'm not really sure why it's trying to handshake to close a connection but that's a separate issue and likely just a gap in my knowledge.

The flow of things goes as follows:

Presumably the other side has closed the connection but hasn't sent a closeNotify, causing this side (Payara in this case) to continually attempt to handshake with it on a no longer active connection. Again, I'm not clear on how the current graceful SSL connection termination is meant to work and why handshaking is a part of this, but this added change appears to work (even if it is a bit brutal in essentially killing the connection dead) - more graceful solutions are likely available.

Example log for reference (line numbers may be slightly off in a couple of places due to Payara having a few unsynced changes):

[2021-01-13T14:38:00.945+0000] [] [INFO] [] [foo.bar.blip.blop.WebsocketClientSessionHandler] [tid: _ThreadID=146 _ThreadName=__ejb-thread-pool11] [timeMillis: 1610548680945] [levelValue: 800] Websocket connection to wss://example.net/ws/v1/subscriptions?subId=5f6c6575546668007f998efe established.

[2021-01-13T14:38:00.953+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: unwrap] unwrap engine: sun.security.ssl.SSLEngineImpl@71d2caa5 input: ByteBufferWrapper (1457684535) [visible=[java.nio.HeapByteBuffer[pos=0 lim=128 cap=33418]]] output: HeapBuffer (378573741) [pos=0 lim=25056 cap=25056]

[2021-01-13T14:38:00.953+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: unwrap] [[
  unwrap done engine: sun.security.ssl.SSLEngineImpl@71d2caa5 result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 104 bytesProduced = 82 input: ByteBufferWrapper (1457684535) [visible=[java.nio.HeapByteBuffer[pos=104 lim=128 cap=33418]]] output: HeapBuffer (378573741) [pos=82 lim=25056 cap=25056]]]

[2021-01-13T14:38:00.953+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: unwrap] unwrap engine: sun.security.ssl.SSLEngineImpl@71d2caa5 input: ByteBufferWrapper (1457684535) [visible=[java.nio.HeapByteBuffer[pos=104 lim=128 cap=33418]]] output: HeapBuffer (378573741) [pos=82 lim=25138 cap=25138]

[2021-01-13T14:38:00.953+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: unwrap] [[
  unwrap done engine: sun.security.ssl.SSLEngineImpl@71d2caa5 result: Status = CLOSED HandshakeStatus = NEED_WRAP
bytesConsumed = 24 bytesProduced = 0 input: ByteBufferWrapper (1457684535) [visible=[java.nio.HeapByteBuffer[pos=128 lim=128 cap=33418]]] output: HeapBuffer (378573741) [pos=82 lim=25138 cap=25138]]]

[2021-01-13T14:38:00.953+0000] [] [FINEST] [] [org.glassfish.grizzly.ssl.SSLBaseFilter] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 300] [CLASSNAME: org.glassfish.grizzly.ssl.SSLBaseFilter] [METHODNAME: doHandshakeStep] Loop Engine: sun.security.ssl.SSLEngineImpl@71d2caa5 handshakeStatus=NEED_WRAP

[2021-01-13T14:38:00.953+0000] [] [FINEST] [] [org.glassfish.grizzly.ssl.SSLBaseFilter] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 300] [CLASSNAME: org.glassfish.grizzly.ssl.SSLBaseFilter] [METHODNAME: doHandshakeStep] NEED_WRAP Engine: sun.security.ssl.SSLEngineImpl@71d2caa5

[2021-01-13T14:38:00.953+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680953] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: wrap] wrap engine: sun.security.ssl.SSLEngineImpl@71d2caa5 input: ByteBufferWrapper (546389043) [visible=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]]] output: ByteBufferWrapper (1412516464) [visible=[java.nio.HeapByteBuffer[pos=0 lim=33418 cap=33418]]]

[2021-01-13T14:38:00.954+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLConnectionContext] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680954] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLConnectionContext] [METHODNAME: wrap] [[
  wrap done engine: sun.security.ssl.SSLEngineImpl@71d2caa5 result: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0 input: ByteBufferWrapper (546389043) [visible=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]]] output: ByteBufferWrapper (1412516464) [visible=[java.nio.HeapByteBuffer[pos=0 lim=33418 cap=33418]]]]]

[2021-01-13T14:38:00.954+0000] [] [FINER] [] [org.glassfish.grizzly.ssl.SSLBaseFilter] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680954] [levelValue: 400] [CLASSNAME: org.glassfish.grizzly.ssl.SSLBaseFilter] [METHODNAME: doHandshakeStep] Inbound connection is closed, cancelling handshake to avoid infinite loop

[2021-01-13T14:38:00.955+0000] [] [INFO] [] [foo.bar.blip.blop.PubSubWebsocketClient] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680955] [levelValue: 800] [PUB-SUB Websocket Client] Session for subscription ID : 5f6c6575546668007f998efe was close. Reason: Closed abnormally..

[2021-01-13T14:38:00.956+0000] [] [FINE] [] [org.glassfish.grizzly.ssl.SSLBaseFilter] [tid: _ThreadID=381 _ThreadName=Grizzly(1)] [timeMillis: 1610548680956] [levelValue: 500] [CLASSNAME: org.glassfish.grizzly.ssl.SSLBaseFilter] [METHODNAME: silentRehandshake] [[
  Error during graceful ssl connection close
javax.net.ssl.SSLException: SSL wrap error: Inbound connection is closed
    at org.glassfish.grizzly.ssl.SSLBaseFilter.doHandshakeStep(SSLBaseFilter.java:685)
    at org.glassfish.grizzly.ssl.SSLFilter.doHandshakeStep(SSLFilter.java:308)
    at org.glassfish.grizzly.ssl.SSLBaseFilter.doHandshakeSync(SSLBaseFilter.java:583)
    at org.glassfish.grizzly.ssl.SSLBaseFilter.silentRehandshake(SSLBaseFilter.java:807)
    at org.glassfish.grizzly.ssl.SSLBaseFilter.unwrapAll(SSLBaseFilter.java:415)
    at org.glassfish.grizzly.ssl.SSLBaseFilter.handleRead(SSLBaseFilter.java:297)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:524)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549)
    at java.base/java.lang.Thread.run(Thread.java:834)
]]

Signed-off-by: Andrew Pielage pandrex247@hotmail.com

Pandrex247 commented 3 years ago

Travis build failed on installing JDK 8