Reactor-netty: Server side websocket connection establishment race condition
I'm using WebFlux as a websocket client/server using reactor-netty. After I upgraded spring boot from 2.2.2.RELEASE to 2.2.7.RELEASE, some of my websocket request/response integration tests started failing sporadically due to a client side timeouts (meaning the server did not respond to a request sent by the client).
After extensive debugging, I believe I've identified the cause of the sporadic failures to be a race condition on the websocket server side within reactor-netty.
The integration tests start sending requests to a websocket connection as soon as the websocket handshake is complete. It appears that in some cases, the websocket server has not fully initialized itself, and drops the first request. Any requests sent on the connection after the websocket server has fully initialized will be processed successfully.
Here are some annotated client/server logs for a single connection where the first message is dropped, but subsequent request/responses work...
# Connection establishment, and websocket handshake
# client 0xa998e190
# server 0xe75c311c
# Everything until the next comment is the same for both success and failure cases.
23:19:56.106 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190] Created a new pooled channel, now 1 active connections and 0 inactive connections
23:19:56.107 [or-http-epoll-3] reactor.netty.tcp.SslProvider : [id: 0xa998e190] SSL enabled using engine SSLEngineImpl and SNI localhost:35094
23:19:56.107 [or-http-epoll-3] reactor.netty.channel.BootstrapHandlers : [id: 0xa998e190] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer#0 = reactor.netty.resources.PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.107 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190] REGISTERED
23:19:56.107 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190] CONNECT: localhost/127.0.0.1:35094
23:19:56.108 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Registering pool release on close event for channel
23:19:56.108 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Channel connected, now 1 active connections and 0 inactive connections
23:19:56.109 [or-http-epoll-1] reactor.netty.tcp.SslProvider : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] SSL enabled using engine SSLEngineImpl
23:19:56.109 [or-http-epoll-1] r.n.http.server.HttpServerOperations : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] New http connection, requesting read
23:19:56.109 [or-http-epoll-1] reactor.netty.channel.BootstrapHandlers : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.109 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] REGISTERED
23:19:56.109 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] ACTIVE
23:19:56.111 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] ACTIVE
23:19:56.188 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ COMPLETE
23:19:56.191 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.197 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.238 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
23:19:56.238 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ COMPLETE
23:19:56.305 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
23:19:56.305 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] onStateChange(PooledConnection{channel=[id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094]}, [connected])
23:19:56.305 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094]}}, [configured])
23:19:56.305 [or-http-epoll-3] r.netty.http.client.HttpClientConnect : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Handler is being applied: {uri=https://localhost:35094/, method=GET}
23:19:56.305 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094]}}, [request_prepared])
23:19:56.306 [or-http-epoll-3] reactor.netty.ReactorNetty : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Added encoder [reactor.left.httpAggregator] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, reactor.left.httpAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.306 [or-http-epoll-3] r.n.http.client.HttpClientOperations : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Attempting to perform websocket handshake with https://localhost:35094/
23:19:56.306 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] WRITE: 328B
23:19:56.306 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] FLUSH
23:19:56.306 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.411 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ: 328B
23:19:56.411 [or-http-epoll-1] r.n.http.server.HttpServerOperations : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Increasing pending responses, now 1
23:19:56.411 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@1cd40ae3
23:19:56.431 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ COMPLETE
23:19:56.497 [undedElastic-16] reactor.netty.ReactorNetty : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Removed handler: reactor.left.httpTrafficHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.497 [undedElastic-16] reactor.netty.ReactorNetty : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Non Removed handler: reactor.left.httpMetricsHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.504 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] WRITE: 450B
23:19:56.504 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] FLUSH
23:19:56.506 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ: 450B
23:19:56.506 [or-http-epoll-3] r.n.resources.PooledConnectionProvider : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] onStateChange(ws{uri=/, connection=PooledConnection{channel=[id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094]}}, [response_received])
23:19:56.507 [or-http-epoll-3] reactor.netty.ReactorNetty : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Added decoder [WebSocketFrameAggregator] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ws-decoder, ws-encoder, WebSocketFrameAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.508 [or-http-epoll-3] reactor.netty.channel.FluxReceive : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
# Everything above this line is the same for both the success/failure conditions.
# At this point, the websocket session is established, and the client sends its first request.
23:19:56.509 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] WRITE: 21B
23:19:56.509 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.509 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] FLUSH
# The server reads the request, and appears to drop it.
# In this failure case, the request read happens _before_ the server adds a decoder and subscribes an inbound receiver (see next comment).
23:19:56.511 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ: 21B
23:19:56.511 [or-http-epoll-1] reactor.netty.channel.FluxReceive : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Dropping frame BinaryWebSocketFrame(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 15, cap: 15)), 0 in buffer
23:19:56.511 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ COMPLETE
# Now the server adds a decoder, and subscribes an inbound receiver.
# The previously read request is not delivered to this decoder / subscriber.
23:19:56.522 [undedElastic-16] reactor.netty.ReactorNetty : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Added decoder [WebSocketFrameAggregator] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, wsencoder, wsdecoder, WebSocketFrameAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.526 [or-http-epoll-1] reactor.netty.channel.FluxReceive : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
# Subsequent requests sent from the client are handled by the server properly.
23:20:11.517 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] WRITE: 27B
23:20:11.517 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] FLUSH
23:20:11.517 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ: 27B
23:20:11.531 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] WRITE: 19B
23:20:11.532 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] READ COMPLETE
23:20:11.532 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] FLUSH
23:20:11.533 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ: 19B
23:20:11.534 [or-http-epoll-3] reactor.netty.http.client.HttpClient : [id: 0xa998e190, L:/127.0.0.1:54894 - R:localhost/127.0.0.1:35094] READ COMPLETE
For comparison, here are some annotated client/server logs for a single connection where the first message succeeds...
# Connection establishment, and websocket handshake
# client 0xb009f203
# server 0x3d9137d5
# Everything until the next comment is the same for both success and failure cases.
23:19:56.123 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203] Created a new pooled channel, now 7 active connections and 0 inactive connections
23:19:56.123 [or-http-epoll-2] reactor.netty.tcp.SslProvider : [id: 0xb009f203] SSL enabled using engine SSLEngineImpl and SNI localhost:35094
23:19:56.123 [or-http-epoll-2] reactor.netty.channel.BootstrapHandlers : [id: 0xb009f203] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer#0 = reactor.netty.resources.PooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.123 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203] REGISTERED
23:19:56.130 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203] CONNECT: localhost/127.0.0.1:35094
23:19:56.189 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Registering pool release on close event for channel
23:19:56.189 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Channel connected, now 7 active connections and 0 inactive connections
23:19:56.190 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] ACTIVE
23:19:56.200 [or-http-epoll-1] reactor.netty.tcp.SslProvider : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] SSL enabled using engine SSLEngineImpl
23:19:56.200 [or-http-epoll-1] r.n.http.server.HttpServerOperations : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] New http connection, requesting read
23:19:56.200 [or-http-epoll-1] reactor.netty.channel.BootstrapHandlers : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.201 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] REGISTERED
23:19:56.201 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] ACTIVE
23:19:56.351 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ COMPLETE
23:19:56.381 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.401 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.439 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
23:19:56.439 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ COMPLETE
23:19:56.460 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
23:19:56.460 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] onStateChange(PooledConnection{channel=[id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094]}, [connected])
23:19:56.460 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094]}}, [configured])
23:19:56.460 [or-http-epoll-2] r.netty.http.client.HttpClientConnect : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Handler is being applied: {uri=https://localhost:35094/, method=GET}
23:19:56.460 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094]}}, [request_prepared])
23:19:56.460 [or-http-epoll-2] reactor.netty.ReactorNetty : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Added encoder [reactor.left.httpAggregator] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, reactor.left.httpAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.460 [or-http-epoll-2] r.n.http.client.HttpClientOperations : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Attempting to perform websocket handshake with https://localhost:35094/
23:19:56.468 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] WRITE: 328B
23:19:56.468 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] FLUSH
23:19:56.475 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.486 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ: 328B
23:19:56.486 [or-http-epoll-1] r.n.http.server.HttpServerOperations : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Increasing pending responses, now 1
23:19:56.486 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@1cd40ae3
23:19:56.487 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ COMPLETE
23:19:56.508 [undedElastic-18] reactor.netty.ReactorNetty : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Removed handler: reactor.left.httpTrafficHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.508 [undedElastic-18] reactor.netty.ReactorNetty : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Non Removed handler: reactor.left.httpMetricsHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.511 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] WRITE: 450B
23:19:56.511 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] FLUSH
# Everything above this line is the same for both the success/failure conditions.
# At this point, the websocket session is established.
# In this success case, the server adds a decoder, and subscribes the inbound receiver _before_ the client sends the first request (see next comment).
23:19:56.523 [undedElastic-18] reactor.netty.ReactorNetty : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Added decoder [WebSocketFrameAggregator] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, wsencoder, wsdecoder, WebSocketFrameAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.526 [or-http-epoll-1] reactor.netty.channel.FluxReceive : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
23:19:56.538 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ: 450B
23:19:56.539 [or-http-epoll-2] r.n.resources.PooledConnectionProvider : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] onStateChange(ws{uri=/, connection=PooledConnection{channel=[id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094]}}, [response_received])
23:19:56.539 [or-http-epoll-2] reactor.netty.ReactorNetty : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Added decoder [WebSocketFrameAggregator] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ws-decoder, ws-encoder, WebSocketFrameAggregator, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
23:19:56.540 [or-http-epoll-2] reactor.netty.channel.FluxReceive : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
# Now the client sends the first request, and the server responds successfully.
23:19:56.540 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] WRITE: 21B
23:19:56.540 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ COMPLETE
23:19:56.540 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] FLUSH
23:19:56.581 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ: 21B
23:19:56.583 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] WRITE: 29B
23:19:56.584 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ COMPLETE
23:19:56.584 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] FLUSH
23:19:56.584 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ: 29B
23:19:56.662 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] READ COMPLETE
# Subsequent requests also succeed.
23:20:11.545 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] WRITE: 27B
23:20:11.545 [or-http-epoll-2] reactor.netty.http.client.HttpClient : [id: 0xb009f203, L:/127.0.0.1:54898 - R:localhost/127.0.0.1:35094] FLUSH
23:20:11.545 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ: 27B
23:20:11.547 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] WRITE: 19B
23:20:11.547 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] READ COMPLETE
23:20:11.547 [or-http-epoll-1] reactor.netty.http.server.HttpServer : [id: 0x3d9137d5, L:/127.0.0.1:35094 - R:/127.0.0.1:54898] FLUSH
I never encountered this behavior on the old versions I was using.
Expected Behavior
Websocket server should receive and be able to respond to the first request sent by a client after the websocket handshake
Actual Behavior
Websocket server is occasionally dropping the first request, and not allowing user code to respond to it.
Steps to Reproduce
Use WebFlux websocket client to establish a connection to a WebFlux websocket server.
Send a request from the client to a server.
Occasionally the server will not process the first request.
I can't submit my existing integration test, but I'll see if I can come up with one that reproduces this behavior.
Possible Solution
I haven't dug into the code yet. I can dig in more if you can provide some pointers on where to look.
Your Environment
openjdk version "11.0.7" 2020-04-14
CentOS Linux release 7.7.1908
I'm using dependency management from spring boot, and not overriding any dependency versions, so that means the following libraries were upgraded:
| | Old (working) | New (not working)|
| ---- | ---- | ---- |
| spring-boot | 2.2.2.RELEASE | 2.2.7.RELEASE |
| spring-webflux |5.2.2.RELEASE | 5.2.6.RELEASE |
| reactor-netty | 0.9.2.RELEASE | 0.9.7.RELEASE |
| netty |4.1.43.Final | 4.1.49.Final |
typbug
philsttr
All 17 comments
I also had some other integration tests fail that were using HTTP (not websocket) under similar circumstances. I haven't debugged that case as much, but they look eerily similar.
philsttr
on 12 May 2020
I just noticed that in some of the successful cases, the log events for "Removed handler", "Non Removed handler", and "Added decoder" occur on on the server's http-epoll thread, rather than a boundedElastic thread as seen in the examples above.
In the failure cases, they are always on a boundedElastic thread.
I haven't found out why sometimes they're on an http-epoll thread, and sometimes they're on a boundedElastic thread.
Perhaps when these events are on a boundedElastic thread, rather than an http-epoll thread, there is a higher chance of the first request being dropped.
philsttr
on 12 May 2020
@philsttr that's interesting as Reactor Netty does not use Schedulers.boundedElastic. If you can extract some reproducible example it will be really helpful.
violetagg
on 12 May 2020
👍1
Still debugging...
It looks like it's getting scheduled on the boundedElastic scheduler by the InMemoryWebSessionStore from spring-web.
philsttr
on 12 May 2020
So you are using this to transfer attributes from a WebSession into the WebSocketSession? I'm just confirming the access to session attributes on a WebSocket handshake is expected.
rstoyanchev
on 12 May 2020
@rstoyanchev I'm not using that, at least not that I'm aware of.
I am using the spring security oauth 2 resource server, and it is authenticating the websocket upgrade request. It looks like it utilizes the session as part of its authentication flow.
Here's the isolated test case that I'm working on... websocket-demo.zip
It executes a lot of connections in parallel. Only a few connections will execute those tasks on the boundedElastic scheduler, but I have not been able to get the out-of-order problem to reproduce yet. I feel like I'm close though.
Be aware, it spews a bunch of logs since wiretap and debug are enabled.
Also, my original integration tests only reproduce the out-of-order problem on linux. I have not reproduced it on Windows. Perhaps because epoll is used on linux, and nio on windows. I do see the usage of the boundedElastic scheduler on windows though.
philsttr
on 12 May 2020
The test is green for me (Linux here). Are you able to narrow it down to a specific Boot version? You could further vary specific library versions to see which one might make a difference.
rstoyanchev
on 13 May 2020
The use of boundedElastic for the WebSession id was done in 5.2.2 which was picked up in Boot 2.2.2 but you're saying on 2.2.2 it worked fine.
rstoyanchev
on 13 May 2020
Yeah, the boundedElastic thing might be a red herring. It's just something I noticed in the logs that might be contributing to the out-of-order behavior I am seeing in my original integration tests. Let me ask another question... should the usage of boundedElastic() in WebSession affect the scheduler on which the "Removed handler", "Non Removed handler", and "Added decoder" events occur? It's a little surprising that sometimes they execute on boundedElastic, and sometimes they execute on an http-epoll thread. I would have thought it would be more deterministic.
It's a bit difficult for me to vary specific versions, because I keep running into various other bugs that have since been fixed in the most recent releases. (That's one of the reasons I had to wait to upgrade until spring-boot 2.2.7). It's a time consuming process.
I'm still working to narrow it down. It doesn't happen every time, so this is a painful process.
philsttr
on 13 May 2020
@philsttr I would say that the logs below should not be a problem.
23:19:56.497 [undedElastic-16] reactor.netty.ReactorNetty : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Removed handler: reactor.left.httpTrafficHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
23:19:56.497 [undedElastic-16] reactor.netty.ReactorNetty : [id: 0xe75c311c, L:/127.0.0.1:35094 - R:/127.0.0.1:54894] Non Removed handler: reactor.left.httpMetricsHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
These handlers are removed just before the handshake
https://github.com/reactor/reactor-netty/blob/aeae1c7107cc6b452194da55dd20772f45426eab/src/main/java/reactor/netty/http/server/WebsocketServerOperations.java#L87-L88
so we should not receive any frame until we send that the connection is upgraded.
I'm still debugging and I will you keep posted as soon as I find something.
violetagg
on 15 May 2020
@philsttr will you be able to test PR #1096
violetagg
on 15 May 2020
Yes, I can test it early next week. I鈥檓 off today.
Thanks for investigating!
philsttr
on 15 May 2020
@violetagg , It looks like PR #1096 fixes the problem. I ran the integration tests repeatedly overnight with the fix, and the problem never occurred. Thank you!
philsttr
on 18 May 2020
@philsttr that's great! thanks for testing it.
violetagg
on 18 May 2020
Fixed in 0.8.x with bae8fd072017ff81a83e6897b7869c87a6f6261c and then forward merge to 0.9.x and master
violetagg
on 18 May 2020
edit: ignore this comment (or rather, the previous version of this comment). maven decided to pull down a snapshot version that did not have the fix applied, rather than using the one I built. All is well.
philsttr
on 19 May 2020
🎉1
👍1
@philsttr thanks for verifying!
violetagg
on 19 May 2020
Was this page helpful?
0 / 5 - 0 ratings
Related issues
rreynaud
路
3Comments
philwebb
路
3Comments
sdeleuze
路
7Comments
be-hase
路
6Comments
smaldini
路
3Comments
Most helpful comment
edit: ignore this comment (or rather, the previous version of this comment). maven decided to pull down a snapshot version that did not have the fix applied, rather than using the one I built. All is well.