Skip to content

[🐛 Bug]: WebSockets broken since 4.5.0 #11590

Closed
#11962
Closed
[🐛 Bug]: WebSockets broken since 4.5.0#11590
#11962
Labels
B-gridEverything grid and server relatedI-defectSomething is not working as intended
@wodyjowski

Description

@wodyjowski
wodyjowski
opened on Jan 24, 2023

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.

This is a copy-paste from #11408 as the issue still persists.

Running the grid with hub in version 4.5.0 fixes the issue:

version: "3"
services:
  selenium-hub:
    image: selenium/hub:4.5.0
    container_name: selenium-hub
    ports:
      - "4444:4444"
    environment:
      - GRID_TIMEOUT=30
      - GRID_BROWSER_TIMEOUT=600

  selenium-node-chrome2:
    image: selenium/node-chrome:4.7.2
    shm_size: 2g
    depends_on:
      - selenium-hub
    environment:
      - SE_NODE_MAX_SESSIONS=2
      - SE_EVENT_BUS_HOST=selenium-hub
      - SE_EVENT_BUS_PUBLISH_PORT=4442
      - SE_EVENT_BUS_SUBSCRIBE_PORT=4443
      - SE_NODE_GRID_URL=http://localhost:4444

I know that you don't support either Playwright or Puppeteer but it looks like an issue with general websocket communication.

How can we reproduce the issue?

Example in GO:
https://github.com/EndPositive/selenium-bug

Example in JS:
https://github.com/wodyjowski/playwright-selenium-grid-ws-issue

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

Windows 11

Selenium version

Any version of selenium/hub > 4.5.0

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

Any version of selenium/hub > 4.5.0

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

Any version of selenium/hub > 4.5.0

Are you using Selenium Grid?

Any version of selenium/hub > 4.5.0

Metadata

Metadata

Assignees

No one assigned

    Labels

    B-gridEverything grid and server relatedI-defectSomething is not working as intended

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions