Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

[馃悰 Bug]: WebSocket incorrectly assumes final frame in multi-frame text send #11408

Closed
EndPositive opened this issue Dec 10, 2022 · 7 comments

Comments

@EndPositive
Copy link

EndPositive commented Dec 10, 2022

What happened?

Since 4.5.2 (i.e. JDK11 client), we've been experiencing an issue with the WebSocket. In this case, large messages sent over the WebSocket proxy (i.e. Selenium Hub + Selenium Node configuration), the receiver incorrectly assumes that the received frame is final. This results in a JSON decoding error in the string builder, which in turn results in the socket closing.

Notably, in the logs of the Chrome Node, there is first a "Frame is not final" message, but then we see that the WebSocket assumes that it was actually a final part:

Final part of text message received. Calling listener with
{"error":{"code":-32700,"message":"JSON: string literal expected at position 16383"}}

Duhh, it's not possible to decode the JSON when you're missing the rest of the message..

I'm not at all fluent with Java, so not able to test further unfortunately.

How can we reproduce the issue?

* Start a Selenium Hub + Selenium Chrome Node configuration
* Create a Selenium session with your favorite Selenium Client and extract the WebSocket URL.
* Start a Puppeteer or Playwright session using that WebSocket URL.
* Send an extremely large message (e.g. with Puppeteer page.evaluate("large thing"))
* See a timeout on that command (since the socket between hub and node closed up).

See https://github.com/EndPositive/selenium-bug

Relevant log output

-----------------
SELENIUM NODE
-----------------
14:52:24.808 DEBUG [JdkHttpClient$5.send] - Sending text message: "[very long json text]"
14:52:24.816 DEBUG [WebSocketImpl.sendText] - [nioEventLoopGroup-3-2] [18s 109ms] [WebSocket] enter send text 70 payload length=2155833 last=true
14:52:24.816 DEBUG [TransportImpl.sendText] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] enter send text 70 message.length=2155833 last=true
14:52:24.816 DEBUG [TransportImpl$SendTask.run] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] enter send task
14:52:24.816 DEBUG [TransportImpl$SendTask.run] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] load message
14:52:24.816 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] encode text src=[pos=0 lim=2155833 cap=2155833] last=true dst=java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
14:52:24.816 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] put
14:52:24.816 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] mask
14:52:24.816 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] moreText
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] frame #0
14:52:24.817 DEBUG [MessageEncoder.setupHeader] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] frame opcode=TEXT fin=false len=16384
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] put
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] mask
14:52:24.817 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] enter writing
14:52:24.817 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] write state: AVAILABLE
14:52:24.817 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] writing to the channel
14:52:24.817 DEBUG [RawChannelTube.write] - [nioEventLoopGroup-3-2] [18s 109ms] [WebSocket] RawChannelTube(SocketTube(2)) write: writing 16384
14:52:24.817 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [18s 109ms] SocketTube(2) trying to write: 16384
14:52:24.817 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [18s 109ms] SocketTube(2) wrote: 16384
14:52:24.817 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [nioEventLoopGroup-3-2] [18s 109ms] SocketTube(2) write: requesting more...
14:52:24.817 DEBUG [RawChannelTube$WriteSubscription.request] - [nioEventLoopGroup-3-2] [18s 109ms] [WebSocket] RawChannelTube(SocketTube(2)) WriteSubscription::request 1
14:52:24.817 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [18s 109ms] SocketTube(2) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.817 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [18s 109ms] SocketTube(2) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.817 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] 16384 bytes written
14:52:24.817 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] finished writing to the channel
14:52:24.817 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 109ms] [Transport] exit writing
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] encode text src=[pos=16382 lim=2155833 cap=2155833] last=true dst=java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] put
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] mask
14:52:24.817 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 109ms] [Output] moreText
14:52:24.818 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 110ms] [Output] frame #1
...........................
14:52:24.825 DEBUG [WebSocketImpl$ReceiveTask.processError] - [HttpClient-2-SelectorManager] [18s 118ms] [WebSocket] failing jdk.internal.net.http.websocket.WebSocketImpl@336ac432[uri=ws://172.21.0.3:5555/session/dc6bf428c14d9ea6a6945f3ff9f80ee0/se/cdp] with error=java.net.ProtocolException statusCode=1002
14:52:24.825 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] frame #13
14:52:24.825 DEBUG [MessageEncoder.setupHeader] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] frame opcode=CONTINUATION fin=false len=16384
14:52:24.825 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] put
14:52:24.825 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] mask
14:52:24.825 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] enter writing
14:52:24.825 DEBUG [TransportImpl.sendClose] - [HttpClient-2-SelectorManager] [18s 118ms] [Transport] enter send close 71 statusCode=1002 reason.length=0
14:52:24.825 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] write state: AVAILABLE
14:52:24.826 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] writing to the channel
14:52:24.826 DEBUG [TransportImpl.sendClose] - [HttpClient-2-SelectorManager] [18s 118ms] [Transport] exit send close 71 returned jdk.internal.net.http.common.MinimalFuture@38096b3b[Not completed] (id=221)
14:52:24.826 DEBUG [RawChannelTube.write] - [nioEventLoopGroup-3-2] [18s 118ms] [WebSocket] RawChannelTube(SocketTube(2)) write: writing 16384
14:52:24.826 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [18s 118ms] SocketTube(2) trying to write: 16384
14:52:24.826 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [18s 118ms] SocketTube(2) wrote: 16384
14:52:24.826 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [nioEventLoopGroup-3-2] [18s 118ms] SocketTube(2) write: requesting more...
14:52:24.826 DEBUG [RawChannelTube$WriteSubscription.request] - [nioEventLoopGroup-3-2] [18s 118ms] [WebSocket] RawChannelTube(SocketTube(2)) WriteSubscription::request 1
14:52:24.826 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [18s 118ms] SocketTube(2) leaving requestMore:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
14:52:24.826 DEBUG [WebSocketImpl$ReceiveTask.processError] - [HttpClient-2-SelectorManager] [18s 118ms] [WebSocket] enter onError 434 error=java.net.ProtocolException
14:52:24.826 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [18s 118ms] SocketTube(2) leaving w.onNext Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
14:52:24.826 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] 16384 bytes written
14:52:24.826 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] finished writing to the channel
14:52:24.826 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [18s 118ms] [Transport] exit writing
14:52:24.826 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] encode text src=[pos=229346 lim=2155833 cap=2155833] last=true dst=java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
14:52:24.826 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] put
14:52:24.826 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] mask
14:52:24.826 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 118ms] [Output] moreText
14:52:24.826 DEBUG [JdkHttpClient$4.onError] - An error has occurred: null
java.net.ProtocolException
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.processError(WebSocketImpl.java:487)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.run(WebSocketImpl.java:454)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.trySetState(WebSocketImpl.java:837)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.signalError(WebSocketImpl.java:714)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$SignallingMessageConsumer.onError(WebSocketImpl.java:825)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReceiveTask.run(TransportImpl.java:671)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReadEvent.handle(TransportImpl.java:762)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.checkEvents(RawChannelTube.java:174)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.onNext(RawChannelTube.java:204)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.onNext(RawChannelTube.java:157)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:844)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:763)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:957)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:912)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:912)
Caused by: jdk.internal.net.http.websocket.FailWebSocketException: Unexpected frame CONTINUATION (fin=false)
	at java.net.http/jdk.internal.net.http.websocket.MessageDecoder.opcode(MessageDecoder.java:133)
	at java.net.http/jdk.internal.net.http.websocket.Frame$Reader.readFrame(Frame.java:391)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReceiveTask.run(TransportImpl.java:665)
	... 20 more
14:52:24.826 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [18s 119ms] [Output] frame #14
14:52:24.827 DEBUG [MessageEncoder.setupHeader] - [nioEventLoopGroup-3-2] [18s 119ms] [Output] frame opcode=CONTINUATION fin=false len=16384
14:52:24.827 WARN [ProxyWebsocketsIntoGrid$ForwardingListener.onError] - Error proxying websocket command
java.net.ProtocolException
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.processError(WebSocketImpl.java:487)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.run(WebSocketImpl.java:454)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.trySetState(WebSocketImpl.java:837)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.signalError(WebSocketImpl.java:714)
	at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$SignallingMessageConsumer.onError(WebSocketImpl.java:825)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReceiveTask.run(TransportImpl.java:671)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReadEvent.handle(TransportImpl.java:762)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.checkEvents(RawChannelTube.java:174)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.onNext(RawChannelTube.java:204)
	at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.onNext(RawChannelTube.java:157)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:844)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:763)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:957)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:912)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:912)
Caused by: jdk.internal.net.http.websocket.FailWebSocketException: Unexpected frame CONTINUATION (fin=false)
	at java.net.http/jdk.internal.net.http.websocket.MessageDecoder.opcode(MessageDecoder.java:133)
	at java.net.http/jdk.internal.net.http.websocket.Frame$Reader.readFrame(Frame.java:391)
	at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReceiveTask.run(TransportImpl.java:665)
	... 20 more



-----------------
CHROME NODE
-----------------
14:52:24.818 WARN [MessageInboundConverter.channelRead0] - Frame is not final. Chaos may ensue
14:52:24.818 DEBUG [JdkHttpClient$5.send] - Sending text message: "[first 16382 bytes of msg]"
14:52:24.819 DEBUG [WebSocketImpl.sendText] - [nioEventLoopGroup-3-2] [14s 892ms] [WebSocket] enter send text 70 payload length=16382 last=true
14:52:24.819 DEBUG [TransportImpl.sendText] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] enter send text 70 message.length=16382 last=true
14:52:24.819 DEBUG [TransportImpl$SendTask.run] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] enter send task
14:52:24.819 DEBUG [TransportImpl$SendTask.run] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] load message
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] encode text src=[pos=0 lim=16382 cap=16382] last=true dst=java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] put
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] mask
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] moreText
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] frame #0
14:52:24.819 DEBUG [MessageEncoder.setupHeader] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] frame opcode=TEXT fin=true len=16384
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] put
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] mask
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] enter writing
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] write state: AVAILABLE
14:52:24.819 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] writing to the channel
14:52:24.819 DEBUG [RawChannelTube.write] - [nioEventLoopGroup-3-2] [14s 892ms] [WebSocket] RawChannelTube(SocketTube(3)) write: writing 16384
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) trying to write: 16384
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) wrote: 16384
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) write: requesting more...
14:52:24.819 DEBUG [RawChannelTube$WriteSubscription.request] - [nioEventLoopGroup-3-2] [14s 892ms] [WebSocket] RawChannelTube(SocketTube(3)) WriteSubscription::request 1
14:52:24.819 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.819 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.819 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] 16384 bytes written
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] finished writing to the channel
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] exit writing
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] encode text src=[pos=16382 lim=16382 cap=16382] last=true dst=java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] put
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] mask
14:52:24.819 DEBUG [MessageEncoder.encodeText] - [nioEventLoopGroup-3-2] [14s 892ms] [Output] moreText
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] enter writing
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] write state: AVAILABLE
14:52:24.819 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [14s 892ms] [Transport] writing to the channel
14:52:24.819 DEBUG [RawChannelTube.write] - [nioEventLoopGroup-3-2] [14s 892ms] [WebSocket] RawChannelTube(SocketTube(3)) write: writing 8
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) trying to write: 8
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) wrote: 8
14:52:24.819 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) write: requesting more...
14:52:24.819 DEBUG [RawChannelTube$WriteSubscription.request] - [nioEventLoopGroup-3-2] [14s 892ms] [WebSocket] RawChannelTube(SocketTube(3)) WriteSubscription::request 1
14:52:24.819 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.819 DEBUG [SocketTube.debugState] - [nioEventLoopGroup-3-2] [14s 892ms] SocketTube(3) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.819 DEBUG [TransportImpl.write] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] 8 bytes written
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] finished writing to the channel
14:52:24.819 DEBUG [TransportImpl$SendTask.tryCompleteWrite] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] exit writing
14:52:24.819 DEBUG [TransportImpl$SendTask.removeAndComplete] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] removeAndComplete error=null
14:52:24.819 DEBUG [TransportImpl$SendTask.run] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] exit send task
14:52:24.819 DEBUG [TransportImpl.sendText] - [nioEventLoopGroup-3-2] [14s 893ms] [Transport] exit send text 70 returned jdk.internal.net.http.common.MinimalFuture@2a7f8319[Completed normally] (id=222)
14:52:24.819 DEBUG [WebSocketImpl.sendText] - [nioEventLoopGroup-3-2] [14s 893ms] [WebSocket] exit send text 70 returned jdk.internal.net.http.common.MinimalFuture@2a7f8319[Completed normally] (id=222)
14:52:24.819 DEBUG [JdkHttpClient$5.send] - Websocket response to org.openqa.selenium.remote.http.TextMessage@20adecec read in 0ms
14:52:24.820 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [14s 893ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@29ea46e8 for 0 (false)
14:52:24.820 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-3-SelectorManager] [14s 893ms] SocketTube(3) read bytes: 87
14:52:24.820 DEBUG [RawChannelTube$ReadSubscriber.onNext] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) ReadSubscriber::onNext 87 bytes
14:52:24.820 DEBUG [RawChannelTube$ReadSubscriber.checkEvents] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) ReadSubscriber: handling event
14:52:24.820 DEBUG [TransportImpl$ReadEvent.handle] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] read event
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] enter receive task
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] receive state: AVAILABLE
14:52:24.820 DEBUG [RawChannelTube.read] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) read
14:52:24.820 DEBUG [RawChannelTube.read] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) read: 87
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] remaining bytes received 87
14:52:24.820 DEBUG [MessageDecoder.fin] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] fin true
14:52:24.820 DEBUG [MessageDecoder.rsv1] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] rsv1 false
14:52:24.820 DEBUG [MessageDecoder.rsv2] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] rsv2 false
14:52:24.820 DEBUG [MessageDecoder.rsv3] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] rsv3 false
14:52:24.820 DEBUG [MessageDecoder.opcode] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] opcode TEXT
14:52:24.820 DEBUG [MessageDecoder.mask] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] mask false
14:52:24.820 DEBUG [MessageDecoder.payloadLen] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] payloadLen 85
14:52:24.820 DEBUG [MessageDecoder.payloadData] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] payload java.nio.HeapByteBufferR[pos=2 lim=87 cap=87]
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] enter receive task
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] receive state: TEXT
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.processText] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] enter onText 434 payload.length=85 last=true
14:52:24.820 DEBUG [JdkHttpClient$4.onText] - Text message received. Appending data
14:52:24.820 DEBUG [JdkHttpClient$4.onText] - Final part of text message received. Calling listener with {"error":{"code":-32700,"message":"JSON: string literal expected at position 16383"}}
14:52:24.820 DEBUG [WebSocketImpl.request] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] request 1
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.processText] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] exit onText 434 returned null
14:52:24.820 DEBUG [WebSocketImpl.tryChangeState] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] change state from TEXT to IDLE true
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] receive state: IDLE
14:52:24.820 DEBUG [WebSocketImpl.tryChangeState] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] change state from IDLE to WAITING true
14:52:24.820 DEBUG [TransportImpl.request] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] request 1
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] exit receive task
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] enter receive task
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] receive state: WAITING
14:52:24.820 DEBUG [WebSocketImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] exit receive task
14:52:24.820 DEBUG [WebSocketImpl.tryChangeState] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] change state from WAITING to TEXT true
14:52:24.820 DEBUG [MessageDecoder.endFrame] - [HttpClient-3-SelectorManager] [14s 893ms] [Input] end frame
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] receive state: UNREGISTERED
14:52:24.820 DEBUG [RawChannelTube.registerEvent] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) register read event
14:52:24.820 DEBUG [RawChannelTube.registerEvent] - [HttpClient-3-SelectorManager] [14s 893ms] [WebSocket] RawChannelTube(SocketTube(3)) readSubscription: requesting 1
14:52:24.820 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-3-SelectorManager] [14s 893ms] SocketTube(3) got some demand for reading
14:52:24.820 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-3-SelectorManager] [14s 893ms] SocketTube(3) resuming read event
14:52:24.820 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [14s 893ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@29ea46e8 for 1 (false)
14:52:24.820 DEBUG [SocketTube.debugState] - [HttpClient-3-SelectorManager] [14s 893ms] SocketTube(3) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] exit receive task
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] enter receive task
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] receive state: WAITING
14:52:24.820 DEBUG [TransportImpl$ReceiveTask.run] - [HttpClient-3-SelectorManager] [14s 893ms] [Transport] exit receive task
14:52:24.820 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-3-SelectorManager] [14s 893ms] SocketTube(3) resuming read event
14:52:24.820 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-3-SelectorManager] [14s 893ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@29ea46e8 for 1 (false)
14:52:24.820 DEBUG [SocketTube.debugState] - [HttpClient-3-SelectorManager] [14s 894ms] SocketTube(3) leaving read() loop after onNext:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:52:24.820 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [14s 894ms] HttpClientImpl(3) next timeout: 0
14:52:24.820 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [14s 894ms] HttpClientImpl(3) next expired: 0
14:52:24.820 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-3-SelectorManager] [14s 894ms] HttpClientImpl(3) Next deadline is 3000
14:52:24.828 DEBUG [RequestConverter.channelInactive] - Channel became inactive.

Operating System

Docker

Selenium version

4.7.0

What are the browser(s) and version(s) where you see this issue?

Chrome 108.0

What are the browser driver(s) and version(s) where you see this issue?

Remote CDP

Are you using Selenium Grid?

4.7.1

@github-actions
Copy link

@EndPositive, thank you for creating this issue. We will troubleshoot it as soon as we can.


Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

@diemol
Copy link
Member

diemol commented Dec 10, 2022

Do you have a test that can reproduce the issue so we can fix it?

@EndPositive
Copy link
Author

Here's a minimal example: https://github.com/EndPositive/selenium-bug

@EndPositive
Copy link
Author

Workaround for me is to increase the frame size: -Djdk.httpclient.websocket.intermediateBufferSize=3000000

@pujagani
Copy link
Contributor

Thank you for sharing the details. I think I have seen this issue once when large payloads were shared during a DevTools session. However, I would like to use an example that produces the error consistently. I appreciate the code shared but I am not fluent in go. I understand what the code is doing roughly but can you help me understand it better so I can translate it to Java code? It is easier to debug and fix that way. I would like to understand what the code is doing and at what point do you see the error. Any particular CDP APIs that trigger this error?
Thank you!

@diemol
Copy link
Member

diemol commented Jan 9, 2023

Closing as we did not get more information.

@wodyjowski
Copy link

Issue seems to persists in selenium-hub > 4.5.0.
I've created an example you can execute: https://github.com/wodyjowski/playwright-selenium-grid-ws-issue
Example provided by @EndPositive seems pretty straight forward.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

4 participants