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’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[🐛 Bug]: WebSockets broken since 4.5.0 #11590

Closed
wodyjowski opened this issue Jan 24, 2023 · 11 comments · Fixed by #11962
Closed

[🐛 Bug]: WebSockets broken since 4.5.0 #11590

wodyjowski opened this issue Jan 24, 2023 · 11 comments · Fixed by #11962

Comments

@wodyjowski
Copy link

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

@github-actions
Copy link

@wodyjowski, 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!

@titusfortner
Copy link
Member

  1. Please provide a reproducible example, in a core Selenium language
  2. Does increasing the frame buffer size help?

@wodyjowski
Copy link
Author

Hi @titusfortner

  1. By core Selenium language you mean Java?
  2. Yes, as stated in issue I linked - [🐛 Bug]: WebSocket incorrectly assumes final frame in multi-frame text send #11408 (comment)

@titusfortner
Copy link
Member

  1. Java, Ruby, Python, JS, .NET
  2. The comment you linked is someone else suggesting it fixed things for them, i was checking to see if that fixed things for you as well.

There's a reason we closed that issue— we didn't get enough information to continue investigating. You recreated it, but did not provide any additional info. If we don't get a way we can reproduce this, we'll end up closing this one as well.

@evertones
Copy link

Hello @titusfortner.

Java, Ruby, Python, JS, .NET

Does it have to be written with Selenium?
I could easily reproduce with a test written in Scala and Playwright.

The comment you linked is someone else suggesting it fixed things for them, i was checking to see if that fixed things for you as well.

I can confirm that the fix suggested by EndPositive in this comment fixes the problem.

I have mentioned it in the existing issue opened with the playwright team:

There's a reason we closed that issue— we didn't get enough information to continue investigating. You recreated it, but did not provide any additional info. If we don't get a way we can reproduce this, we'll end up closing this one as well.

I'm not sure who should be responsible for this.
If Selenium does not officially support Playwright, maybe the information about the parameter to increase the WebSocket size should be added to Playwright's documentation and that would become a requirement for Playwright to use Selenium Grid.

@diemol
Copy link
Member

diemol commented Feb 19, 2023

Does it have to be written with Selenium?
I could easily reproduce with a test written in Scala and Playwright.

Yes, because we do not have related issues reported with Selenium code.

I'm not sure who should be responsible for this.
If Selenium does not officially support Playwright, maybe the information about the parameter to increase the WebSocket size should be added to Playwright's documentation and that would become a requirement for Playwright to use Selenium Grid.

We do support the use cases around Selenium, there is no official integration between Selenium Grid and Playwright. It just seems they found a way to leverage the exposed websockets because for now Selenium uses CDP under the hood to serve some use cases. Nevertheless, given that Selenium relies on standards, the team is working with the Browser Testing and Tools Working Group to replace in the future the CDP integration with BiDi. So, even if the issue is fixed now with that workaround, it will break in the future again.

All this is to say that we have been always open for collaboration with the Playwright team, if they want to contribute to fix this issue, we'd be happy to review the pull request. And ideally they want to contribute to BiDi, so this use case they offer to their users relies on standards and won't break in the future again.

I will close this issue and when they open a PR, they can reference it as background. Thank you!

@diemol diemol closed this as completed Feb 19, 2023
@wodyjowski
Copy link
Author

wodyjowski commented Apr 20, 2023

@diemol @titusfortner example in .NET: https://github.com/wodyjowski/SeleniumIssue
Please reopen this issue 🙏

@diemol diemol added this to the 4.10 milestone Apr 24, 2023
@diemol diemol reopened this Apr 24, 2023
@joerg1985
Copy link
Member

I think the jdk client is splitting huge messages to multiple smaller frames. The MessageInboundConverter should handle the ContinuationWebSocketFrames and have a text and a binary buffer to collect the frames until the final fragment is received. When the message is completely received the fireChannelRead should be called with the complete message.

This assumption is based on the netty javadoc and might be wrong.

@diemol
Copy link
Member

diemol commented Apr 25, 2023

I see the return code 1002 in the logs, which says:

1002

      1002 indicates that an endpoint is terminating the connection due
      to a protocol error.

So I am not sure if it is the browser endpoint closing the socket in an unexpected way.

Copy link

github-actions bot commented Dec 9, 2023

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked and limited conversation to collaborators Dec 9, 2023
@diemol
Copy link
Member

diemol commented Jul 12, 2024

Just FYI, I left this comment wrt using Grid with Playwright.

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

Successfully merging a pull request may close this issue.

5 participants