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

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 17 (17 by maintainers)

Commits related to this issue

fix #1089 Bind WebsocketServerOperations immediately after the handshake while still in the event loop — committed to reactor/reactor-netty by violetagg 4 years ago
fix #1089 Bind WebsocketServerOperations immediately after the handshake while still in the event loop — committed to reactor/reactor-netty by violetagg 4 years ago
fix #1089 Bind WebsocketServerOperations immediately after the handshake while still in the event loop — committed to reactor/reactor-netty by violetagg 4 years ago

Most upvoted comments

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 May 18, 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 May 12, 2020