diff --git a/buildSrc/src/main/kotlin/Constants.kt b/buildSrc/src/main/kotlin/Constants.kt index 5eddee5..a3b0fe6 100644 --- a/buildSrc/src/main/kotlin/Constants.kt +++ b/buildSrc/src/main/kotlin/Constants.kt @@ -1,7 +1,7 @@ object Consts { const val releaseGroup = "com.piasy" const val releaseName = "kmp-socketio" - const val releaseVersion = "1.4.2" + const val releaseVersion = "1.4.3" val androidNS = "$releaseGroup.${releaseName.replace('-', '.')}" } diff --git a/docs/ut-case-analysis/cc-opus-result-good.md b/docs/ut-case-analysis/cc-opus-result-good.md new file mode 100644 index 0000000..d98528f --- /dev/null +++ b/docs/ut-case-analysis/cc-opus-result-good.md @@ -0,0 +1,155 @@ +完整分析 + +测试用例 reconnectManually 逻辑 + +1. 创建 socket 并连接 +2. 第一次 CONNECT 回调 → socket.close() +3. DISCONNECT 回调 → 注册新的 CONNECT 监听 → socket.open() (手动重连) +4. 第二次 CONNECT 回调 → socket.close()，向队列 offer("done") +5. values.take() 阻塞等待 "done" + +--- +Transport 实例总览 + +┌──────────┬────────────────────┬──────────────────────┬────────────────────┬─────────────────────┐ +│ 日志 │ 第一次连接 Polling │ 第一次连接 WS Probe │ 第二次连接 Polling │ 第二次连接 WS Probe │ +├──────────┼────────────────────┼──────────────────────┼────────────────────┼─────────────────────┤ +│ good.log │ polling@709407350 │ websocket@2087361714 │ polling@969147974 │ websocket@590078241 │ +├──────────┼────────────────────┼──────────────────────┼────────────────────┼─────────────────────┤ +│ err.log │ polling@1929439163 │ websocket@260110639 │ polling@2125549749 │ websocket@897766716 │ +└──────────┴────────────────────┴──────────────────────┴────────────────────┴─────────────────────┘ + +--- +关键发现：Manager 共享 scope + +Manager.kt:100: +val socket = EngineSocket(uri, opt, scope) // Manager 把自己的 scope 传给每个新的 EngineSocket + +每次 Manager.open() 创建新的 EngineSocket 实例，但传入的是同一个 scope。这个 scope 同时也会传给所有 Transport（factory.create(name, opts, scope, rawMessage)，见 EngineSocket.kt:222）。这意味着：新旧连接的所有 +Transport 共享同一个 CoroutineScope。 + +--- +good.log 执行流程（成功路径） + +第一次连接 + +1. polling@709407350 创建并打开，发起 GET 握手请求 +2. 收到 Open 包（sid=npUAHeAD7Xe4wi4TAAAA），polling@709407350 状态 OPENING → OPEN +3. EngineSocket onOpen，发送 Socket.IO Connect(40)，同时启动 probe：创建 websocket@2087361714，发起 WS 握手 +4. polling@709407350 继续 poll，收到 40{"sid":"I6cxDxOi1VMI0lYEAAAB"} → Socket onConnect + +第一次断开（socket.close()） + +5. Socket close → Manager 发送 Disconnect(41) → polling@709407350 send +6. Manager destroy/close/cleanUp +7. EngineSocket.close()：state=OPEN, writeBuffer 非空(有 41 在发送中), upgrading=false + - 注册 once(EVENT_DRAIN, ...) 等待 drain +8. Socket onClose: io client disconnect + +手动重连 + +9. Socket.open() → Manager.open(state=CLOSED) → 创建新的 EngineSocket（state=INIT） +10. 新 EngineSocket setTransport(polling@969147974) → 发起新的 GET 握手 + +旧连接清理（关键时序） + +11. websocket@2087361714 WS 101 握手成功，onOpen（时间戳 488） +12. Probe 发送 2probe +13. 旧 EngineSocket 的 drain 先于 probe pong 到达（时间戳 490）： + - polling@709407350 POST 41 返回 OK → onDrain → emit(EVENT_DRAIN) + - close 的 drain handler 检查 upgrading == false ✓ + - 直接调用 closeAction() → onClose("force close") + - onClose 关闭 polling@709407350，清空 writeBuffer +14. websocket@2087361714 后续收到 3probe pong，但 probe handler 发现 socket 已 closed → 中止 + +第二次连接正常完成 + +15. polling@969147974 收到新 Open（sid=Q5cmf6rvfmLGKrBHAAAC），正常连接 +16. 收到 Socket.IO Connect → Socket onConnect（sid=0_W1hJWvCHgoG_ktAAAD） +17. 收到 42["message","hello client"] → 回调触发 socket.close()，offer("done") → 测试通过 + +成功的关键：drain 在 probe pong 之前触发 → upgrading=false → 直接关闭，不走 upgrade 路径。 + +--- +err.log 执行流程（失败路径） + +第一次连接（与 good.log 相同，直到 close） + +1-4. 与 good.log 相同：polling@1929439163 建立连接，Socket onConnect（sid=Q_xqaV-43ilrJOWWAAAB） + +第一次断开 + +5-8. 与 good.log 相同：发送 41，EngineSocket.close() 注册 drain handler + +手动重连 + +9-10. 与 good.log 相同：创建新 EngineSocket，setTransport(polling@2125549749) + +关键时序差异！ + +11. websocket@260110639 WS 101 握手成功，onOpen（时间戳 698） +12. Probe 发送 2probe（ioScope.launch 异步发送，此处 ioScope 协程 A 启动） +13. Probe pong 先于 drain 到达（时间戳 702）： + - 收到 3probe → EngineSocket probe transport websocket pong + - upgrading = true ← 关键状态变更 + - 开始 pause polling@1929439163 +14. polling@1929439163 POST 41 返回 OK → onDrain（时间戳 705）： + - drain handler 检查 upgrading == true → 走 waitForUpgrade() 路径 + - 注册 once(EVENT_UPGRADE, cleanupAndClose) 和 once(EVENT_UPGRADE_ERROR, cleanupAndClose) +15. Pause 完成（时间戳 705）： + - polling@1929439163 paused + - EngineSocket changing transport and sending upgrade packet + - 在 websocket@260110639 上注册 once(EVENT_DRAIN, upgradeHandler) + - 发送 Upgrade 包 5（ioScope.launch 异步发送，协程 B 启动） +16. Upgrade 包的 ioScope 协程 B 完成 → scope.launch 发布 drain 事件（时间戳 705，line 321）： + - websocket@260110639 doSend 1 packets finish（第一个 finish） + - emit(EVENT_DRAIN, 1) on websocket@260110639 + - Emitter 快照 listeners：onceCallbacks[EVENT_DRAIN] = [upgradeHandler] + - upgradeHandler 执行： +a. emit(EVENT_UPGRADE, transport) → cleanupAndClose 触发： + - onClose("force close") + - writeBuffer.clear(), prevBufferLen = 0 + - state = State.CLOSED +b. setTransport(websocket@260110639) → 在 websocket@260110639 上添加新的持久 EVENT_DRAIN callback listener（On.on → transport.on） +c. upgrading = false, flush() → state CLOSED 忽略 +17. 2probe 的 ioScope 协程 A 延迟完成 → scope.launch 发布 drain 事件（时间戳 712，line 405）： + - websocket@260110639 doSend 1 packets finish（第二个 finish） + - emit(EVENT_DRAIN, 1) on websocket@260110639 + - Emitter 快照 listeners：callbacks[EVENT_DRAIN] = [setTransport 刚注册的持久 listener] + - setTransport 的 listener 调用 onDrain(1) + - onDrain: prevBufferLen=0, writeBuffer.size=0, len=1 + - writeBuffer.removeAt(0) → ArrayDeque is empty 💥 CRASH + +Exception: java.util.NoSuchElementException: ArrayDeque is empty. + at EngineSocket.onDrain(EngineSocket.kt:280) + at EngineSocket$setTransport$1.call(EngineSocket.kt:246) + at Emitter.emit(Emitter.kt:136) + at WebSocket$doSend$2$3.invokeSuspend(WebSocket.kt:172) + +崩溃后的连锁反应 + +18. 异常发生在 scope.launch（WebSocket.kt:169）内部，scope 是 Manager 的共享 scope +19. 未捕获的异常导致 共享 scope 的 Job 被取消 +20. 第二次连接的 polling@2125549749 虽然收到了 HTTP GET 响应（40{"sid":"N11GQoFftXqh9245AAAD"}，line 457），但 scope.launch { onPollComplete(...) } 无法执行（scope 已取消） +21. onPollComplete 从未被调用（日志中完全没有出现第二次连接的 onPollComplete） +22. 第二次连接永远无法收到 Socket.IO Connect → Socket onConnect 不触发 → "done" 永远不会 offer → 测试 7 秒超时 + +--- +根因总结 + +存在两层竞态条件： + +竞态 1：Close-drain vs Probe-pong +- EngineSocket.close() 注册 drain handler，其中检查 upgrading 决定走哪条路径 +- probe() 中收到 pong 会设置 upgrading = true +- 如果 drain 先于 pong → upgrading=false → 直接关闭（good.log） +- 如果 pong 先于 drain → upgrading=true → 走 upgrade 路径，最终调用 setTransport(websocket) + +竞态 2：2probe-drain vs Upgrade-drain +- websocket@260110639 的 doSend 被调用了两次：一次发 2probe，一次发 Upgrade +- 每次 doSend 都在 ioScope.launch 中异步发送数据，完成后通过 scope.launch 发射 EVENT_DRAIN +- 这两个 ioScope.launch 的完成顺序不确定 +- 如果 Upgrade 的 drain 先触发：upgradeHandler 消费了 once listener → setTransport 注册了新的持久 drain listener +- 然后 2probe 的 drain 延迟触发：hit 到 setTransport 注册的新 listener → onDrain(1) 在空 writeBuffer 上操作 → 崩溃 + +致命后果：崩溃发生在 Manager 共享的 CoroutineScope 中（Manager.kt:100 将同一个 scope 传给新旧 EngineSocket），导致整个 scope 被取消，新连接的所有协程调度都失效，测试超时。 diff --git a/docs/ut-case-analysis/err.log b/docs/ut-case-analysis/err.log new file mode 100644 index 0000000..672d881 --- /dev/null +++ b/docs/ut-case-analysis/err.log @@ -0,0 +1,489 @@ +2026-02-01T07:33:00.5236510Z ConnectionTest[jvm] > reconnectManually[jvm] STANDARD_OUT +2026-02-01T07:33:00.5236820Z 1769931180437 I TestConnection Starting server ... +2026-02-01T07:33:00.5237520Z 1769931180437 E Transport websocket@1696140781 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:33:00.5237990Z 1769931180437 I Transport websocket@1696140781 onClose +2026-02-01T07:33:00.7239180Z 1769931180644 I TestConnection SERVER ERR: 2026-02-01T07:33:00.644Z socket.io:server initializing namespace / +2026-02-01T07:33:00.7342520Z 1769931180645 I TestConnection SERVER ERR: 2026-02-01T07:33:00.645Z socket.io:server creating engine.io instance with opts {"pingInterval":2000,"cleanupEmptyChildNamespaces":false,"path":"/socket.io"} +2026-02-01T07:33:00.7360710Z 1769931180646 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server attaching client serving req handler +2026-02-01T07:33:00.7361560Z 1769931180646 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /foo +2026-02-01T07:33:00.7362340Z 1769931180647 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /timeout_socket +2026-02-01T07:33:00.7363130Z 1769931180647 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /valid +2026-02-01T07:33:00.7363880Z 1769931180647 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /asd +2026-02-01T07:33:00.7364610Z 1769931180647 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /abc +2026-02-01T07:33:00.7365710Z 1769931180647 I TestConnection SERVER ERR: 2026-02-01T07:33:00.646Z socket.io:server initializing namespace /no +2026-02-01T07:33:00.7366450Z 1769931180662 I TestConnection SERVER OUT: Socket.IO server listening on port 3000 +2026-02-01T07:33:00.7367020Z 1769931180662 I TestConnection SERVER OUT: https server listening on port 8443 + + + + + + + + + + + +2026-02-01T07:33:00.7367680Z 1769931180663 I IO socket: uri http://localhost:3000/, opt com.piasy.kmp.socketio.socketio.IO$Options@311b50f9 +2026-02-01T07:33:00.7368230Z 1769931180663 I IO socket newConn, sameNsp false +2026-02-01T07:33:00.7368610Z 1769931180663 I Manager socket: nsp /, auth {} +2026-02-01T07:33:00.7369030Z 1769931180664 I Socket open: connected false, io reconnecting false +2026-02-01T07:33:00.7369440Z 1769931180664 I Socket subEvents: subs 0 +2026-02-01T07:33:00.7369860Z 1769931180664 I Manager open, state INIT, uri http://localhost:3000/ +2026-02-01T07:33:00.7370280Z 1769931180664 I EngineSocket open: state INIT +2026-02-01T07:33:00.7370660Z 1769931180664 I EngineSocket createTransport polling +2026-02-01T07:33:00.7371060Z 1769931180665 I EngineSocket setTransport polling +2026-02-01T07:33:00.7371430Z 1769931180665 D Transport polling@1929439163 open +2026-02-01T07:33:00.7371820Z 1769931180665 D Transport polling@1929439163 poll start +2026-02-01T07:33:00.7372540Z 1769931180665 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling, data null, headers {Accept=[*/*]} +2026-02-01T07:33:00.7373300Z 1769931180665 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:33:00.7373690Z METHOD: GET +2026-02-01T07:33:00.7373920Z COMMON HEADERS +2026-02-01T07:33:00.7374150Z -> Accept: */* +2026-02-01T07:33:00.7374380Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.7374640Z CONTENT HEADERS +2026-02-01T07:33:00.7374870Z -> Content-Length: 0 +2026-02-01T07:33:00.7375120Z BODY Content-Type: null +2026-02-01T07:33:00.7375370Z BODY START +2026-02-01T07:33:00.7375540Z +2026-02-01T07:33:00.7375680Z BODY END +2026-02-01T07:33:00.7376250Z 1769931180678 I TestConnection SERVER ERR: 2026-02-01T07:33:00.678Z socket.io:server incoming connection with id Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7376820Z 1769931180679 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.7377090Z METHOD: GET +2026-02-01T07:33:00.7377430Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:33:00.7377770Z COMMON HEADERS +2026-02-01T07:33:00.7378160Z -> Connection: keep-alive +2026-02-01T07:33:00.7378420Z -> Content-Length: 117 +2026-02-01T07:33:00.7378730Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7379070Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.7379360Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.7379650Z -> cache-control: no-store +2026-02-01T07:33:00.7380010Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7380300Z BODY START +2026-02-01T07:33:00.7380830Z 0{"sid":"Seja1HgqfCyOAv0qAAAA","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000} +2026-02-01T07:33:00.7381300Z BODY END +2026-02-01T07:33:00.7381870Z 1769931180679 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling response: 200 OK +2026-02-01T07:33:00.7383380Z 1769931180680 D Transport polling@1929439163 onPollComplete: state OPENING, `0{"sid":"Seja1HgqfCyOAv0qAAAA","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000}` +2026-02-01T07:33:00.7384200Z 1769931180680 I Transport polling@1929439163 onOpen, state OPENING +2026-02-01T07:33:00.7385010Z 1769931180680 D Transport polling@1929439163 onPacket Open(sid=Seja1HgqfCyOAv0qAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.7386160Z 1769931180680 D EngineSocket transport on packet Open(sid=Seja1HgqfCyOAv0qAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.7387180Z 1769931180680 D EngineSocket onPacket Open(sid=Seja1HgqfCyOAv0qAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.7387790Z 1769931180680 I EngineSocket onOpen +2026-02-01T07:33:00.7388200Z 1769931180680 I Manager onOpen, state OPENING +2026-02-01T07:33:00.7388530Z 1769931180680 I Manager cleanUp +2026-02-01T07:33:00.7388820Z 1769931180680 I Socket onOpen +2026-02-01T07:33:00.7389300Z 1769931180680 D Manager send packets [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:33:00.7389990Z 1769931180680 D EngineSocket sendPackets: state OPEN, [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:33:00.7390740Z 1769931180680 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:33:00.7391430Z 1769931180680 D Transport polling@1929439163 send: state OPEN, 1 packets +2026-02-01T07:33:00.7391880Z 1769931180680 I EngineSocket starting upgrade probes +2026-02-01T07:33:00.7392300Z 1769931180680 I EngineSocket probing transport 'websocket' +2026-02-01T07:33:00.7392730Z 1769931180680 I EngineSocket createTransport websocket +2026-02-01T07:33:00.7393730Z 1769931180681 D Transport polling@1929439163 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA, data 40, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:33:00.7394600Z 1769931180681 D Transport websocket@260110639 open +2026-02-01T07:33:00.7395250Z 1769931180681 I Transport websocket@260110639 doOpen ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7395870Z 1769931180681 D Transport polling@1929439163 poll start +2026-02-01T07:33:00.7396670Z 1769931180681 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA, data null, headers {Accept=[*/*]} +2026-02-01T07:33:00.7397580Z 1769931180681 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7398040Z METHOD: POST +2026-02-01T07:33:00.7398270Z COMMON HEADERS +2026-02-01T07:33:00.7398490Z -> Accept: */* +2026-02-01T07:33:00.7398730Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.7398990Z CONTENT HEADERS +2026-02-01T07:33:00.7399220Z -> Content-Length: 2 +2026-02-01T07:33:00.7399520Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7400020Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7400310Z BODY START +2026-02-01T07:33:00.7400520Z 40 +2026-02-01T07:33:00.7400730Z BODY END +2026-02-01T07:33:00.7401220Z 1769931180681 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7401680Z METHOD: GET +2026-02-01T07:33:00.7401910Z COMMON HEADERS +2026-02-01T07:33:00.7402130Z -> Accept: */* +2026-02-01T07:33:00.7402370Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.7402630Z CONTENT HEADERS +2026-02-01T07:33:00.7402870Z -> Content-Length: 0 +2026-02-01T07:33:00.7403120Z BODY Content-Type: null +2026-02-01T07:33:00.7403370Z BODY START +2026-02-01T07:33:00.7403540Z +2026-02-01T07:33:00.7403680Z BODY END +2026-02-01T07:33:00.7404160Z 1769931180682 I Net REQUEST: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7404610Z METHOD: GET +2026-02-01T07:33:00.7404830Z COMMON HEADERS +2026-02-01T07:33:00.7405050Z -> Accept: */* +2026-02-01T07:33:00.7405290Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.7405540Z CONTENT HEADERS +2026-02-01T07:33:00.7405780Z -> Connection: Upgrade +2026-02-01T07:33:00.7406100Z -> Sec-WebSocket-Key: MTQ3YTY2NWRiZGRlMjdjYQ== +2026-02-01T07:33:00.7406450Z -> Sec-WebSocket-Version: 13 +2026-02-01T07:33:00.7406720Z -> Upgrade: websocket +2026-02-01T07:33:00.7406980Z BODY Content-Type: null +2026-02-01T07:33:00.7407290Z BODY START +2026-02-01T07:33:00.7407470Z +2026-02-01T07:33:00.7407600Z BODY END +2026-02-01T07:33:00.7408090Z 1769931180687 I TestConnection SERVER ERR: 2026-02-01T07:33:00.687Z socket.io:client connecting to namespace / +2026-02-01T07:33:00.7408820Z 1769931180687 I TestConnection SERVER ERR: 2026-02-01T07:33:00.687Z socket.io:namespace adding socket to nsp / +2026-02-01T07:33:00.7409310Z 1769931180689 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.7409580Z METHOD: POST +2026-02-01T07:33:00.7410020Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7410420Z COMMON HEADERS +2026-02-01T07:33:00.7410660Z -> Connection: keep-alive +2026-02-01T07:33:00.7410930Z -> Content-Length: 2 +2026-02-01T07:33:00.7411210Z -> Content-Type: text/html +2026-02-01T07:33:00.7411590Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.7411940Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.7412230Z -> cache-control: no-store +2026-02-01T07:33:00.7412530Z BODY Content-Type: text/html +2026-02-01T07:33:00.7412790Z BODY START +2026-02-01T07:33:00.7413000Z ok +2026-02-01T07:33:00.7413200Z BODY END +2026-02-01T07:33:00.7413850Z 1769931180689 D Transport polling@1929439163 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA response: 200 OK +2026-02-01T07:33:00.7414630Z 1769931180690 D EngineSocket onDrain: prevBufferLen 1, writeBuffer.size 1, len 1 +2026-02-01T07:33:00.7415140Z 1769931180690 D EngineSocket onDrain fire socket drain event +2026-02-01T07:33:00.7415760Z 1769931180691 I TestConnection SERVER ERR: 2026-02-01T07:33:00.689Z socket.io:socket socket connected - writing packet +2026-02-01T07:33:00.7416610Z 1769931180691 I TestConnection SERVER ERR: 2026-02-01T07:33:00.689Z socket.io:socket join room Q_xqaV-43ilrJOWWAAAB +2026-02-01T07:33:00.7417230Z 1769931180692 I TestConnection SERVER OUT: on connection +2026-02-01T07:33:00.7417600Z 1769931180692 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.7417870Z METHOD: GET +2026-02-01T07:33:00.7418290Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.7418700Z COMMON HEADERS +2026-02-01T07:33:00.7418930Z -> Connection: keep-alive +2026-02-01T07:33:00.7419200Z -> Content-Length: 32 +2026-02-01T07:33:00.7419510Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7419840Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.7420340Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.7420640Z -> cache-control: no-store +2026-02-01T07:33:00.7420980Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.7421330Z BODY START +2026-02-01T07:33:00.7421600Z 40{"sid":"Q_xqaV-43ilrJOWWAAAB"} +2026-02-01T07:33:00.7421860Z BODY END +2026-02-01T07:33:00.7422530Z 1769931180693 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA response: 200 OK +2026-02-01T07:33:00.7423400Z 1769931180693 D Transport polling@1929439163 onPollComplete: state OPEN, `40{"sid":"Q_xqaV-43ilrJOWWAAAB"}` +2026-02-01T07:33:00.7424200Z 1769931180694 D Transport polling@1929439163 onPacket Message(payload=Connect(namespace=/, payload={"sid":"Q_xqaV-43ilrJOWWAAAB"})) +2026-02-01T07:33:00.7425050Z 1769931180694 D EngineSocket transport on packet Message(payload=Connect(namespace=/, payload={"sid":"Q_xqaV-43ilrJOWWAAAB"})) +2026-02-01T07:33:00.8931220Z 1769931180694 D EngineSocket onPacket Message(payload=Connect(namespace=/, payload={"sid":"Q_xqaV-43ilrJOWWAAAB"})) +2026-02-01T07:33:00.8932300Z 1769931180694 D Manager on EngineSocket data class org.hildan.socketio.SocketIOPacket$Connect +2026-02-01T07:33:00.8933060Z 1769931180694 D Socket onPacket: nsp /, Connect(namespace=/, payload={"sid":"Q_xqaV-43ilrJOWWAAAB"}) +2026-02-01T07:33:00.8933700Z 1769931180694 I Socket onConnect sid Q_xqaV-43ilrJOWWAAAB +2026-02-01T07:33:00.8934700Z 1769931180694 D Transport polling@1929439163 poll start + + + + + + + + + + + +2026-02-01T07:33:00.8935110Z 1769931180694 I Socket close: connected true +2026-02-01T07:33:00.8935620Z 1769931180694 D Manager send packets [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:33:00.8936330Z 1769931180694 D EngineSocket sendPackets: state OPEN, [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:33:00.8937100Z 1769931180694 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:33:00.8937730Z 1769931180694 D Transport polling@1929439163 send: state OPEN, 1 packets +2026-02-01T07:33:00.8938080Z 1769931180694 I Manager destroy +2026-02-01T07:33:00.8938320Z 1769931180694 I Manager close +2026-02-01T07:33:00.8938550Z 1769931180694 I Manager cleanUp +2026-02-01T07:33:00.8938960Z 1769931180694 I EngineSocket close: state OPEN, writeBuffer.size 1, upgrading: false +2026-02-01T07:33:00.8939480Z 1769931180694 I EngineSocket close waiting drain event +2026-02-01T07:33:00.8939840Z 1769931180694 I Socket onClose: `io client disconnect` + + + + + + + + + + + +2026-02-01T07:33:00.8940330Z 1769931180695 I Socket open: connected false, io reconnecting false +2026-02-01T07:33:00.8940690Z 1769931180695 I Socket subEvents: subs 0 +2026-02-01T07:33:00.8941190Z 1769931180695 I Manager open, state CLOSED, uri http://localhost:3000/ +2026-02-01T07:33:00.8941610Z 1769931180695 I EngineSocket open: state INIT +2026-02-01T07:33:00.8941990Z 1769931180695 I EngineSocket createTransport polling +2026-02-01T07:33:00.8942450Z 1769931180695 I EngineSocket setTransport polling +2026-02-01T07:33:00.8942900Z 1769931180695 D Transport polling@2125549749 open +2026-02-01T07:33:00.8943350Z 1769931180695 D Transport polling@2125549749 poll start +2026-02-01T07:33:00.8944260Z 1769931180695 D Transport polling@2125549749 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling, data null, headers {Accept=[*/*]} +2026-02-01T07:33:00.8945590Z 1769931180696 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA, data null, headers {Accept=[*/*]} +2026-02-01T07:33:00.8947250Z 1769931180696 D Transport polling@1929439163 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA, data 41, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:33:00.8948530Z 1769931180696 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.8949270Z METHOD: GET +2026-02-01T07:33:00.8949450Z COMMON HEADERS +2026-02-01T07:33:00.8949640Z -> Accept: */* +2026-02-01T07:33:00.8949840Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.8950060Z CONTENT HEADERS +2026-02-01T07:33:00.8950300Z -> Content-Length: 0 +2026-02-01T07:33:00.8950520Z BODY Content-Type: null +2026-02-01T07:33:00.8950740Z BODY START +2026-02-01T07:33:00.8950850Z +2026-02-01T07:33:00.8950920Z BODY END +2026-02-01T07:33:00.8951460Z 1769931180697 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.8951970Z METHOD: POST +2026-02-01T07:33:00.8952140Z COMMON HEADERS +2026-02-01T07:33:00.8952320Z -> Accept: */* +2026-02-01T07:33:00.8952520Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.8952850Z CONTENT HEADERS +2026-02-01T07:33:00.8953050Z -> Content-Length: 2 +2026-02-01T07:33:00.8953340Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.8953700Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.8953970Z BODY START +2026-02-01T07:33:00.8954130Z 41 +2026-02-01T07:33:00.8954280Z BODY END +2026-02-01T07:33:00.8954620Z 1769931180698 I Transport websocket@260110639 onOpen, state OPENING +2026-02-01T07:33:00.8955190Z 1769931180698 I EngineSocket probe transport websocket opened, failed: false +2026-02-01T07:33:00.8955950Z 1769931180698 D Transport websocket@260110639 send: state OPEN, 1 packets +2026-02-01T07:33:00.8956520Z 1769931180698 D Transport websocket@260110639 doSend 1 packets start +2026-02-01T07:33:00.8957110Z 1769931180698 D Transport websocket@260110639 doSend: Ping(payload=probe), `2probe` +2026-02-01T07:33:00.8957770Z 1769931180699 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:33:00.8958200Z METHOD: GET +2026-02-01T07:33:00.8958370Z COMMON HEADERS +2026-02-01T07:33:00.8958560Z -> Accept: */* +2026-02-01T07:33:00.8958750Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.8958970Z CONTENT HEADERS +2026-02-01T07:33:00.8959170Z -> Content-Length: 0 +2026-02-01T07:33:00.8959380Z BODY Content-Type: null +2026-02-01T07:33:00.8959590Z BODY START +2026-02-01T07:33:00.8959700Z +2026-02-01T07:33:00.8959770Z BODY END +2026-02-01T07:33:00.8960050Z 1769931180699 I Net RESPONSE: 101 Switching Protocols +2026-02-01T07:33:00.8960340Z METHOD: GET +2026-02-01T07:33:00.8960790Z FROM: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.8961220Z COMMON HEADERS +2026-02-01T07:33:00.8961410Z -> Connection: Upgrade +2026-02-01T07:33:00.8961760Z -> Sec-WebSocket-Accept: qTvE3g1lVYQ+i9N8oTZY+/9ZuhY= +2026-02-01T07:33:00.8962080Z -> Upgrade: websocket +2026-02-01T07:33:00.8962310Z BODY Content-Type: null +2026-02-01T07:33:00.8962510Z BODY START +2026-02-01T07:33:00.8962620Z +2026-02-01T07:33:00.8962680Z BODY END +2026-02-01T07:33:00.8962920Z 1769931180700 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.8963170Z METHOD: GET +2026-02-01T07:33:00.8963610Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.8964050Z COMMON HEADERS +2026-02-01T07:33:00.8964240Z -> Connection: keep-alive +2026-02-01T07:33:00.8964480Z -> Content-Length: 28 +2026-02-01T07:33:00.8964770Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.8965100Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.8965380Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.8965650Z -> cache-control: no-store +2026-02-01T07:33:00.8965970Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.8966240Z BODY START +2026-02-01T07:33:00.8966460Z 42["message","hello client"] +2026-02-01T07:33:00.8966680Z BODY END +2026-02-01T07:33:00.8967440Z 1769931180702 D Transport polling@1929439163 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA response: 200 OK +2026-02-01T07:33:00.8968520Z 1769931180702 D Transport websocket@260110639 Receive frame: Frame TEXT (fin=true, buffer len = 6) +2026-02-01T07:33:00.8969160Z 1769931180702 D Transport websocket@260110639 onWsText: `3probe` +2026-02-01T07:33:00.8969720Z 1769931180702 D Transport websocket@260110639 onPacket Pong(payload=probe) +2026-02-01T07:33:00.8970250Z 1769931180702 I EngineSocket probe transport websocket pong +2026-02-01T07:33:00.8970750Z 1769931180702 I EngineSocket pausing current transport polling +2026-02-01T07:33:00.8971200Z 1769931180702 I Transport polling@1929439163 pause +2026-02-01T07:33:00.8971650Z 1769931180702 I Transport polling@1929439163 pause: wait polling +2026-02-01T07:33:00.8972170Z 1769931180702 I Transport polling@1929439163 pause: wait writing +2026-02-01T07:33:00.8972850Z 1769931180703 D Transport polling@1929439163 onPollComplete: state PAUSED, `42["message","hello client"]` +2026-02-01T07:33:00.8973860Z 1769931180703 D Transport polling@1929439163 onPacket Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:33:00.8974940Z 1769931180703 D EngineSocket transport on packet Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:33:00.8975970Z 1769931180703 D EngineSocket onPacket Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:33:00.8976810Z 1769931180703 I Transport polling@1929439163 pause: pre-pause polling complete +2026-02-01T07:33:00.8977480Z 1769931180703 I Transport polling@1929439163 onPollComplete ignore poll, state PAUSED +2026-02-01T07:33:00.8978300Z 1769931180703 I TestConnection SERVER ERR: 2026-02-01T07:33:00.701Z socket.io:socket got packet {"type":1,"nsp":"/"} +2026-02-01T07:33:00.8979180Z 1769931180703 I TestConnection SERVER ERR: 2026-02-01T07:33:00.701Z socket.io:socket got disconnect packet +2026-02-01T07:33:00.8980160Z 1769931180703 I TestConnection SERVER ERR: 2026-02-01T07:33:00.701Z socket.io:socket closing socket - reason client namespace disconnect +2026-02-01T07:33:00.8980890Z 1769931180703 I TestConnection SERVER OUT: disconnect +2026-02-01T07:33:00.8981240Z 1769931180704 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.8981480Z METHOD: POST +2026-02-01T07:33:00.8981940Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA +2026-02-01T07:33:00.8982360Z COMMON HEADERS +2026-02-01T07:33:00.8982570Z -> Connection: keep-alive +2026-02-01T07:33:00.8982810Z -> Content-Length: 2 +2026-02-01T07:33:00.8983060Z -> Content-Type: text/html +2026-02-01T07:33:00.8983340Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.8983640Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.8983980Z -> cache-control: no-store +2026-02-01T07:33:00.8984370Z BODY Content-Type: text/html +2026-02-01T07:33:00.8984690Z BODY START +2026-02-01T07:33:00.8984940Z ok +2026-02-01T07:33:00.8985230Z BODY END +2026-02-01T07:33:00.8986100Z 1769931180704 D Transport polling@1929439163 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Seja1HgqfCyOAv0qAAAA response: 200 OK +2026-02-01T07:33:00.8987160Z 1769931180705 D EngineSocket onDrain: prevBufferLen 1, writeBuffer.size 1, len 1 +2026-02-01T07:33:00.8987750Z 1769931180705 D EngineSocket onDrain fire socket drain event +2026-02-01T07:33:00.8988240Z 1769931180705 I EngineSocket close waiting drain success +2026-02-01T07:33:00.8988660Z 1769931180705 I EngineSocket close waiting upgrade +2026-02-01T07:33:00.8989170Z 1769931180705 I Transport polling@1929439163 pause: pre-pause writing complete +2026-02-01T07:33:00.8989640Z 1769931180705 I Transport polling@1929439163 paused +2026-02-01T07:33:00.8990090Z 1769931180705 I EngineSocket changing transport and sending upgrade packet +2026-02-01T07:33:00.8990640Z 1769931180705 D Transport websocket@260110639 send: state OPEN, 1 packets +2026-02-01T07:33:00.8991280Z 1769931180705 D Transport websocket@260110639 doSend 1 packets start +2026-02-01T07:33:00.8991800Z 1769931180705 D Transport websocket@260110639 doSend: Upgrade, `5` +2026-02-01T07:33:00.9001220Z 1769931180705 D Transport websocket@260110639 doSend 1 packets finish +2026-02-01T07:33:00.9001680Z 1769931180705 I EngineSocket upgrade packet send success +2026-02-01T07:33:00.9002110Z 1769931180705 I EngineSocket close waiting upgrade success +2026-02-01T07:33:00.9002600Z 1769931180705 I EngineSocket socket closing - telling transport to close +2026-02-01T07:33:00.9003040Z 1769931180705 I EngineSocket onClose force close +2026-02-01T07:33:00.9003450Z 1769931180705 I Transport polling@1929439163 close, state PAUSED +2026-02-01T07:33:00.9003870Z 1769931180705 I EngineSocket setTransport websocket +2026-02-01T07:33:00.9004290Z 1769931180705 I EngineSocket clearing existing transport polling +2026-02-01T07:33:00.9004990Z 1769931180705 D EngineSocket flush: state CLOSED, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 0 +2026-02-01T07:33:00.9005960Z 1769931180705 I EngineSocket flush ignored: state CLOSED, transport.writable true, upgrading false, writeBuffer.size 0, prevBufferLen 0 +2026-02-01T07:33:00.9006570Z 1769931180709 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.9006810Z METHOD: GET +2026-02-01T07:33:00.9007120Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:33:00.9007430Z COMMON HEADERS +2026-02-01T07:33:00.9007750Z -> Connection: keep-alive +2026-02-01T07:33:00.9007970Z -> Content-Length: 117 +2026-02-01T07:33:00.9008250Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9008530Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.9008750Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.9008990Z -> cache-control: no-store +2026-02-01T07:33:00.9009250Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9009480Z BODY START +2026-02-01T07:33:00.9009970Z 0{"sid":"dmV9BCqOzfrS4jISAAAC","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000} +2026-02-01T07:33:00.9010420Z BODY END +2026-02-01T07:33:00.9010960Z 1769931180709 D Transport polling@2125549749 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling response: 200 OK +2026-02-01T07:33:00.9012090Z 1769931180710 D Transport polling@2125549749 onPollComplete: state OPENING, `0{"sid":"dmV9BCqOzfrS4jISAAAC","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000}` +2026-02-01T07:33:00.9013180Z 1769931180710 I TestConnection SERVER ERR: 2026-02-01T07:33:00.707Z socket.io:server incoming connection with id dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9013810Z 1769931180710 I Transport polling@2125549749 onOpen, state OPENING +2026-02-01T07:33:00.9014750Z 1769931180710 D Transport polling@2125549749 onPacket Open(sid=dmV9BCqOzfrS4jISAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.9015870Z 1769931180710 D EngineSocket transport on packet Open(sid=dmV9BCqOzfrS4jISAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.9016920Z 1769931180710 D EngineSocket onPacket Open(sid=dmV9BCqOzfrS4jISAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:33:00.9017520Z 1769931180710 I EngineSocket onOpen +2026-02-01T07:33:00.9017820Z 1769931180710 I Manager onOpen, state OPENING +2026-02-01T07:33:00.9018090Z 1769931180710 I Manager cleanUp +2026-02-01T07:33:00.9018330Z 1769931180710 I Socket onOpen +2026-02-01T07:33:00.9018770Z 1769931180710 D Manager send packets [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:33:00.9019470Z 1769931180710 D EngineSocket sendPackets: state OPEN, [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:33:00.9020240Z 1769931180710 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:33:00.9021100Z 1769931180710 D Transport polling@2125549749 send: state OPEN, 1 packets +2026-02-01T07:33:00.9021510Z 1769931180710 I EngineSocket starting upgrade probes +2026-02-01T07:33:00.9021880Z 1769931180710 I EngineSocket probing transport 'websocket' +2026-02-01T07:33:00.9022280Z 1769931180710 I EngineSocket createTransport websocket +2026-02-01T07:33:00.9023260Z 1769931180710 D Transport polling@2125549749 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC, data 40, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:33:00.9024100Z 1769931180710 D Transport websocket@897766716 open +2026-02-01T07:33:00.9024790Z 1769931180710 I Transport websocket@897766716 doOpen ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9025400Z 1769931180710 D Transport polling@2125549749 poll start +2026-02-01T07:33:00.9026220Z 1769931180710 D Transport polling@2125549749 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC, data null, headers {Accept=[*/*]} +2026-02-01T07:33:00.9027160Z 1769931180711 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9027590Z METHOD: POST +2026-02-01T07:33:00.9027740Z COMMON HEADERS +2026-02-01T07:33:00.9027890Z -> Accept: */* +2026-02-01T07:33:00.9028140Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.9028340Z CONTENT HEADERS +2026-02-01T07:33:00.9028510Z -> Content-Length: 2 +2026-02-01T07:33:00.9028760Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9029060Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9029300Z BODY START +2026-02-01T07:33:00.9029440Z 40 +2026-02-01T07:33:00.9029560Z BODY END +2026-02-01T07:33:00.9030020Z 1769931180711 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9030440Z METHOD: GET +2026-02-01T07:33:00.9030590Z COMMON HEADERS +2026-02-01T07:33:00.9030730Z -> Accept: */* +2026-02-01T07:33:00.9030900Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.9031090Z CONTENT HEADERS +2026-02-01T07:33:00.9031260Z -> Content-Length: 0 +2026-02-01T07:33:00.9031450Z BODY Content-Type: null +2026-02-01T07:33:00.9031620Z BODY START +2026-02-01T07:33:00.9031710Z +2026-02-01T07:33:00.9031770Z BODY END +2026-02-01T07:33:00.9032230Z 1769931180711 I Net REQUEST: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9032650Z METHOD: GET +2026-02-01T07:33:00.9032790Z COMMON HEADERS +2026-02-01T07:33:00.9033030Z -> Accept: */* +2026-02-01T07:33:00.9033200Z -> Accept-Charset: UTF-8 +2026-02-01T07:33:00.9033380Z CONTENT HEADERS +2026-02-01T07:33:00.9033560Z -> Connection: Upgrade +2026-02-01T07:33:00.9033840Z -> Sec-WebSocket-Key: Y2EyNTQ0MDUxY2Q2YWU5Yg== +2026-02-01T07:33:00.9034130Z -> Sec-WebSocket-Version: 13 +2026-02-01T07:33:00.9034340Z -> Upgrade: websocket +2026-02-01T07:33:00.9034530Z BODY Content-Type: null +2026-02-01T07:33:00.9034720Z BODY START +2026-02-01T07:33:00.9034810Z +2026-02-01T07:33:00.9034880Z BODY END +2026-02-01T07:33:00.9035180Z 1769931180712 D Transport websocket@260110639 doSend 1 packets finish +2026-02-01T07:33:00.9035700Z 1769931180712 D EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1 +2026-02-01T07:33:00.9035980Z +2026-02-01T07:33:00.9036220Z ConnectionTest[jvm] > reconnectManually[jvm] STANDARD_ERROR +2026-02-01T07:33:00.9036890Z Exception in thread "DefaultDispatcher-worker-10 @coroutine#1018" java.util.NoSuchElementException: ArrayDeque is empty. +2026-02-01T07:33:00.9037580Z at kotlin.collections.ArrayDeque.removeFirst(ArrayDeque.kt:146) +2026-02-01T07:33:00.9038120Z at com.piasy.kmp.socketio.engineio.EngineSocket.onDrain(EngineSocket.kt:280) +2026-02-01T07:33:00.9038800Z at com.piasy.kmp.socketio.engineio.EngineSocket.access$onDrain(EngineSocket.kt:17) +2026-02-01T07:33:00.9039430Z at com.piasy.kmp.socketio.engineio.EngineSocket$setTransport$1.call(EngineSocket.kt:246) +2026-02-01T07:33:00.9040020Z at com.piasy.kmp.socketio.emitter.Emitter.emit$lambda$0$0(Emitter.kt:128) +2026-02-01T07:33:00.9040500Z at com.piasy.kmp.socketio.emitter.Emitter.emit(Emitter.kt:136) +2026-02-01T07:33:00.9041100Z at com.piasy.kmp.socketio.engineio.transports.WebSocket$doSend$2$3.invokeSuspend(WebSocket.kt:172) +2026-02-01T07:33:00.9041800Z at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:34) +2026-02-01T07:33:00.9042380Z at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:100) +2026-02-01T07:33:00.9042960Z at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:124) +2026-02-01T07:33:00.9043480Z at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:89) +2026-02-01T07:33:00.9044050Z at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:586) +2026-02-01T07:33:00.9044770Z at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:829) +2026-02-01T07:33:00.9045500Z at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:717) +2026-02-01T07:33:00.9046190Z at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:704) +2026-02-01T07:33:00.9047230Z Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [CoroutineId(1018), "coroutine#1018":StandaloneCoroutine{Cancelling}@21fcd395, siowkr] +2026-02-01T07:33:00.9047840Z +2026-02-01T07:33:00.9048090Z ConnectionTest[jvm] > reconnectManually[jvm] STANDARD_OUT +2026-02-01T07:33:00.9048470Z 1769931180719 I Net RESPONSE: 101 Switching Protocols +2026-02-01T07:33:00.9048720Z METHOD: GET +2026-02-01T07:33:00.9049110Z FROM: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9049480Z COMMON HEADERS +2026-02-01T07:33:00.9049660Z -> Connection: Upgrade +2026-02-01T07:33:00.9049960Z -> Sec-WebSocket-Accept: Gl5wjD1ueqsgyaQv5J8q6c8Rowo= +2026-02-01T07:33:00.9050230Z -> Upgrade: websocket +2026-02-01T07:33:00.9050430Z BODY Content-Type: null +2026-02-01T07:33:00.9050600Z BODY START +2026-02-01T07:33:00.9050690Z +2026-02-01T07:33:00.9050740Z BODY END +2026-02-01T07:33:00.9051230Z 1769931180721 I TestConnection SERVER ERR: 2026-02-01T07:33:00.716Z socket.io:client connecting to namespace / +2026-02-01T07:33:00.9051980Z 1769931180721 I TestConnection SERVER ERR: 2026-02-01T07:33:00.716Z socket.io:namespace adding socket to nsp / +2026-02-01T07:33:00.9052750Z 1769931180721 I TestConnection SERVER ERR: 2026-02-01T07:33:00.716Z socket.io:socket socket connected - writing packet +2026-02-01T07:33:00.9053510Z 1769931180721 I TestConnection SERVER ERR: 2026-02-01T07:33:00.716Z socket.io:socket join room N11GQoFftXqh9245AAAD +2026-02-01T07:33:00.9054020Z 1769931180721 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.9054220Z METHOD: GET +2026-02-01T07:33:00.9054600Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9054960Z COMMON HEADERS +2026-02-01T07:33:00.9055140Z -> Connection: keep-alive +2026-02-01T07:33:00.9055340Z -> Content-Length: 32 +2026-02-01T07:33:00.9055580Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9055880Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.9056110Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.9056340Z -> cache-control: no-store +2026-02-01T07:33:00.9056620Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:33:00.9056850Z BODY START +2026-02-01T07:33:00.9057060Z 40{"sid":"N11GQoFftXqh9245AAAD"} +2026-02-01T07:33:00.9057260Z BODY END +2026-02-01T07:33:00.9057910Z 1769931180721 D Transport polling@2125549749 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC response: 200 OK +2026-02-01T07:33:00.9058590Z 1769931180722 I Net RESPONSE: 200 OK +2026-02-01T07:33:00.9058810Z METHOD: POST +2026-02-01T07:33:00.9059190Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC +2026-02-01T07:33:00.9059560Z COMMON HEADERS +2026-02-01T07:33:00.9059720Z -> Connection: keep-alive +2026-02-01T07:33:00.9059940Z -> Content-Length: 2 +2026-02-01T07:33:00.9060170Z -> Content-Type: text/html +2026-02-01T07:33:00.9060410Z -> Date: Sun, 01 Feb 2026 07:33:00 GMT +2026-02-01T07:33:00.9060650Z -> Keep-Alive: timeout=5 +2026-02-01T07:33:00.9060880Z -> cache-control: no-store +2026-02-01T07:33:00.9061110Z BODY Content-Type: text/html +2026-02-01T07:33:00.9061310Z BODY START +2026-02-01T07:33:00.9061440Z ok +2026-02-01T07:33:00.9061580Z BODY END +2026-02-01T07:33:00.9062220Z 1769931180723 D Transport polling@2125549749 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=dmV9BCqOzfrS4jISAAAC response: 200 OK +2026-02-01T07:33:00.9062910Z 1769931180723 I TestConnection SERVER OUT: on connection +2026-02-01T07:33:02.8069430Z 1769931182680 D Transport websocket@260110639 Receive frame: Frame TEXT (fin=true, buffer len = 1) +2026-02-01T07:33:07.9015420Z 1769931187766 I TestConnection Stopping server ... +2026-02-01T07:33:07.9016240Z 1769931187772 E Transport websocket@260110639 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:33:07.9017610Z 1769931187773 E Transport websocket@897766716 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:33:07.9018120Z +2026-02-01T07:33:07.9018470Z ConnectionTest[jvm] > reconnectManually[jvm] FAILED +2026-02-01T07:33:07.9019060Z org.junit.runners.model.TestTimedOutException: test timed out after 7000 milliseconds +2026-02-01T07:33:07.9019700Z at java.base@17.0.17/jdk.internal.misc.Unsafe.park(Native Method) +2026-02-01T07:33:07.9020350Z at java.base@17.0.17/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341) +2026-02-01T07:33:07.9021190Z at java.base@17.0.17/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506) +2026-02-01T07:33:07.9022050Z at java.base@17.0.17/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3465) +2026-02-01T07:33:07.9022840Z at java.base@17.0.17/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3436) +2026-02-01T07:33:07.9023750Z at java.base@17.0.17/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1630) +2026-02-01T07:33:07.9024630Z at java.base@17.0.17/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:435) +2026-02-01T07:33:07.9025360Z at app//io.socket.client.ConnectionTest.reconnectManually(ConnectionTest.java:379) +2026-02-01T07:33:07.9025790Z \ No newline at end of file diff --git a/docs/ut-case-analysis/good.log b/docs/ut-case-analysis/good.log new file mode 100644 index 0000000..c465e3c --- /dev/null +++ b/docs/ut-case-analysis/good.log @@ -0,0 +1,559 @@ +2026-02-01T07:49:45.2820570Z ConnectionTest[jvm] > reconnectManually[jvm] STANDARD_OUT +2026-02-01T07:49:45.2820900Z 1769932185188 I TestConnection Starting server ... +2026-02-01T07:49:45.2821390Z 1769932185192 E Transport websocket@680004828 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:49:45.2821860Z 1769932185192 I Transport websocket@680004828 onClose +2026-02-01T07:49:45.6182720Z 1769932185402 I TestConnection SERVER ERR: 2026-02-01T07:49:45.400Z socket.io:server initializing namespace / +2026-02-01T07:49:45.6284760Z 1769932185403 I TestConnection SERVER ERR: 2026-02-01T07:49:45.402Z socket.io:server creating engine.io instance with opts {"pingInterval":2000,"cleanupEmptyChildNamespaces":false,"path":"/socket.io"} +2026-02-01T07:49:45.6384890Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server attaching client serving req handler +2026-02-01T07:49:45.6485710Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /foo +2026-02-01T07:49:45.6587040Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /timeout_socket +2026-02-01T07:49:45.6687340Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /valid +2026-02-01T07:49:45.6788730Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /asd +2026-02-01T07:49:45.6889580Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /abc +2026-02-01T07:49:45.6990630Z 1769932185404 I TestConnection SERVER ERR: 2026-02-01T07:49:45.404Z socket.io:server initializing namespace /no +2026-02-01T07:49:45.7091270Z 1769932185421 I TestConnection SERVER OUT: Socket.IO server listening on port 3000 +2026-02-01T07:49:45.7192550Z 1769932185421 I TestConnection SERVER OUT: https server listening on port 8443 + + + + + + + + + + + +2026-02-01T07:49:45.7294190Z 1769932185422 I IO socket: uri http://localhost:3000/, opt com.piasy.kmp.socketio.socketio.IO$Options@9300d60 +2026-02-01T07:49:45.7386710Z 1769932185422 I IO socket newConn, sameNsp false +2026-02-01T07:49:45.7387340Z 1769932185423 I Manager socket: nsp /, auth {} +2026-02-01T07:49:45.7387930Z 1769932185431 I Socket open: connected false, io reconnecting false +2026-02-01T07:49:45.7388460Z 1769932185431 I Socket subEvents: subs 0 +2026-02-01T07:49:45.7389010Z 1769932185431 I Manager open, state INIT, uri http://localhost:3000/ +2026-02-01T07:49:45.7389520Z 1769932185431 I EngineSocket open: state INIT +2026-02-01T07:49:45.7390020Z 1769932185431 I EngineSocket createTransport polling +2026-02-01T07:49:45.7390510Z 1769932185432 I EngineSocket setTransport polling +2026-02-01T07:49:45.7390960Z 1769932185432 D Transport polling@709407350 open +2026-02-01T07:49:45.7391360Z 1769932185432 D Transport polling@709407350 poll start +2026-02-01T07:49:45.7392130Z 1769932185433 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7393260Z 1769932185434 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:49:45.7393670Z METHOD: GET +2026-02-01T07:49:45.7393900Z COMMON HEADERS +2026-02-01T07:49:45.7395700Z -> Accept: */* +2026-02-01T07:49:45.7395960Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7396220Z CONTENT HEADERS +2026-02-01T07:49:45.7396460Z -> Content-Length: 0 +2026-02-01T07:49:45.7396720Z BODY Content-Type: null +2026-02-01T07:49:45.7396970Z BODY START +2026-02-01T07:49:45.7397140Z +2026-02-01T07:49:45.7397280Z BODY END +2026-02-01T07:49:45.7397950Z 1769932185454 I TestConnection SERVER ERR: 2026-02-01T07:49:45.453Z socket.io:server incoming connection with id npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7398560Z 1769932185456 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7398850Z METHOD: GET +2026-02-01T07:49:45.7399200Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:49:45.7399550Z COMMON HEADERS +2026-02-01T07:49:45.7399790Z -> Connection: keep-alive +2026-02-01T07:49:45.7400070Z -> Content-Length: 117 +2026-02-01T07:49:45.7400380Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7400720Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7401090Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7401380Z -> cache-control: no-store +2026-02-01T07:49:45.7401760Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7402050Z BODY START +2026-02-01T07:49:45.7402570Z 0{"sid":"npUAHeAD7Xe4wi4TAAAA","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000} +2026-02-01T07:49:45.7403040Z BODY END +2026-02-01T07:49:45.7403610Z 1769932185456 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling response: 200 OK +2026-02-01T07:49:45.7404840Z 1769932185459 D Transport polling@709407350 onPollComplete: state OPENING, `0{"sid":"npUAHeAD7Xe4wi4TAAAA","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000}` +2026-02-01T07:49:45.7405680Z 1769932185460 I Transport polling@709407350 onOpen, state OPENING +2026-02-01T07:49:45.7406650Z 1769932185460 D Transport polling@709407350 onPacket Open(sid=npUAHeAD7Xe4wi4TAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7415390Z 1769932185460 D EngineSocket transport on packet Open(sid=npUAHeAD7Xe4wi4TAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7416460Z 1769932185460 D EngineSocket onPacket Open(sid=npUAHeAD7Xe4wi4TAAAA, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7417100Z 1769932185460 I EngineSocket onOpen +2026-02-01T07:49:45.7417580Z 1769932185460 I Manager onOpen, state OPENING +2026-02-01T07:49:45.7417930Z 1769932185460 I Manager cleanUp +2026-02-01T07:49:45.7418230Z 1769932185460 I Socket onOpen +2026-02-01T07:49:45.7418720Z 1769932185460 D Manager send packets [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:49:45.7419410Z 1769932185460 D EngineSocket sendPackets: state OPEN, [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:49:45.7420180Z 1769932185460 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:49:45.7420810Z 1769932185460 D Transport polling@709407350 send: state OPEN, 1 packets +2026-02-01T07:49:45.7421270Z 1769932185460 I EngineSocket starting upgrade probes +2026-02-01T07:49:45.7421700Z 1769932185460 I EngineSocket probing transport 'websocket' +2026-02-01T07:49:45.7422140Z 1769932185460 I EngineSocket createTransport websocket +2026-02-01T07:49:45.7423100Z 1769932185460 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA, data 40, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7424170Z 1769932185460 D Transport websocket@2087361714 open +2026-02-01T07:49:45.7424850Z 1769932185460 I Transport websocket@2087361714 doOpen ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7425480Z 1769932185460 D Transport polling@709407350 poll start +2026-02-01T07:49:45.7428680Z 1769932185460 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7429640Z 1769932185461 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7430110Z METHOD: POST +2026-02-01T07:49:45.7430340Z COMMON HEADERS +2026-02-01T07:49:45.7430580Z -> Accept: */* +2026-02-01T07:49:45.7430840Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7432520Z CONTENT HEADERS +2026-02-01T07:49:45.7433520Z -> Content-Length: 2 +2026-02-01T07:49:45.7433860Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7434590Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7435920Z BODY START +2026-02-01T07:49:45.7438170Z 40 +2026-02-01T07:49:45.7438450Z BODY END +2026-02-01T07:49:45.7438990Z 1769932185461 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7439480Z METHOD: GET +2026-02-01T07:49:45.7440250Z COMMON HEADERS +2026-02-01T07:49:45.7440490Z -> Accept: */* +2026-02-01T07:49:45.7440740Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7441230Z CONTENT HEADERS +2026-02-01T07:49:45.7441480Z -> Content-Length: 0 +2026-02-01T07:49:45.7441740Z BODY Content-Type: null +2026-02-01T07:49:45.7441990Z BODY START +2026-02-01T07:49:45.7442160Z +2026-02-01T07:49:45.7442300Z BODY END +2026-02-01T07:49:45.7443390Z 1769932185462 I Net REQUEST: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7443950Z METHOD: GET +2026-02-01T07:49:45.7444170Z COMMON HEADERS +2026-02-01T07:49:45.7444410Z -> Accept: */* +2026-02-01T07:49:45.7444710Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7444970Z CONTENT HEADERS +2026-02-01T07:49:45.7445210Z -> Connection: Upgrade +2026-02-01T07:49:45.7445540Z -> Sec-WebSocket-Key: MTA0ZmY5ZjMwN2FiNjdlNA== +2026-02-01T07:49:45.7445900Z -> Sec-WebSocket-Version: 13 +2026-02-01T07:49:45.7446180Z -> Upgrade: websocket +2026-02-01T07:49:45.7446450Z BODY Content-Type: null +2026-02-01T07:49:45.7446700Z BODY START +2026-02-01T07:49:45.7447030Z +2026-02-01T07:49:45.7447390Z BODY END +2026-02-01T07:49:45.7449370Z 1769932185469 I TestConnection SERVER ERR: 2026-02-01T07:49:45.469Z socket.io:client connecting to namespace / +2026-02-01T07:49:45.7450210Z 1769932185469 I TestConnection SERVER ERR: 2026-02-01T07:49:45.469Z socket.io:namespace adding socket to nsp / +2026-02-01T07:49:45.7450780Z 1769932185475 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7451080Z METHOD: POST +2026-02-01T07:49:45.7451600Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7452130Z COMMON HEADERS +2026-02-01T07:49:45.7452450Z -> Connection: keep-alive +2026-02-01T07:49:45.7452780Z -> Content-Length: 2 +2026-02-01T07:49:45.7453120Z -> Content-Type: text/html +2026-02-01T07:49:45.7453440Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7453740Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7454020Z -> cache-control: no-store +2026-02-01T07:49:45.7454320Z BODY Content-Type: text/html +2026-02-01T07:49:45.7454590Z BODY START +2026-02-01T07:49:45.7454800Z ok +2026-02-01T07:49:45.7455010Z BODY END +2026-02-01T07:49:45.7455670Z 1769932185475 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA response: 200 OK +2026-02-01T07:49:45.7456490Z 1769932185477 D EngineSocket onDrain: prevBufferLen 1, writeBuffer.size 1, len 1 +2026-02-01T07:49:45.7457240Z 1769932185477 D EngineSocket onDrain fire socket drain event +2026-02-01T07:49:45.7457680Z 1769932185477 I TestConnection SERVER OUT: on connection +2026-02-01T07:49:45.7458060Z 1769932185478 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7458330Z METHOD: GET +2026-02-01T07:49:45.7458760Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7459190Z COMMON HEADERS +2026-02-01T07:49:45.7459440Z -> Connection: keep-alive +2026-02-01T07:49:45.7459720Z -> Content-Length: 32 +2026-02-01T07:49:45.7460090Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7460450Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7460740Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7461050Z -> cache-control: no-store +2026-02-01T07:49:45.7461390Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7461690Z BODY START +2026-02-01T07:49:45.7461970Z 40{"sid":"I6cxDxOi1VMI0lYEAAAB"} +2026-02-01T07:49:45.7462240Z BODY END +2026-02-01T07:49:45.7462910Z 1769932185478 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA response: 200 OK +2026-02-01T07:49:45.7463880Z 1769932185479 D Transport polling@709407350 onPollComplete: state OPEN, `40{"sid":"I6cxDxOi1VMI0lYEAAAB"}` +2026-02-01T07:49:45.7464710Z 1769932185479 D Transport polling@709407350 onPacket Message(payload=Connect(namespace=/, payload={"sid":"I6cxDxOi1VMI0lYEAAAB"})) +2026-02-01T07:49:45.7465590Z 1769932185479 D EngineSocket transport on packet Message(payload=Connect(namespace=/, payload={"sid":"I6cxDxOi1VMI0lYEAAAB"})) +2026-02-01T07:49:45.7466570Z 1769932185479 D EngineSocket onPacket Message(payload=Connect(namespace=/, payload={"sid":"I6cxDxOi1VMI0lYEAAAB"})) +2026-02-01T07:49:45.7467340Z 1769932185479 D Manager on EngineSocket data class org.hildan.socketio.SocketIOPacket$Connect +2026-02-01T07:49:45.7468060Z 1769932185479 D Socket onPacket: nsp /, Connect(namespace=/, payload={"sid":"I6cxDxOi1VMI0lYEAAAB"}) +2026-02-01T07:49:45.7468650Z 1769932185479 I Socket onConnect sid I6cxDxOi1VMI0lYEAAAB +2026-02-01T07:49:45.7469080Z 1769932185479 D Transport polling@709407350 poll start + + + + + + + + + + + +2026-02-01T07:49:45.7469470Z 1769932185480 I Socket close: connected true +2026-02-01T07:49:45.7469950Z 1769932185480 D Manager send packets [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:49:45.7470610Z 1769932185480 D EngineSocket sendPackets: state OPEN, [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:49:45.7471360Z 1769932185480 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:49:45.7472020Z 1769932185480 D Transport polling@709407350 send: state OPEN, 1 packets +2026-02-01T07:49:45.7472440Z 1769932185480 I Manager destroy +2026-02-01T07:49:45.7472770Z 1769932185480 I Manager close +2026-02-01T07:49:45.7473090Z 1769932185480 I Manager cleanUp +2026-02-01T07:49:45.7473600Z 1769932185480 I EngineSocket close: state OPEN, writeBuffer.size 1, upgrading: false +2026-02-01T07:49:45.7474100Z 1769932185480 I EngineSocket close waiting drain event +2026-02-01T07:49:45.7474520Z 1769932185480 I Socket onClose: `io client disconnect` +2026-02-01T07:49:45.7475140Z 1769932185477 I TestConnection SERVER ERR: 2026-02-01T07:49:45.474Z socket.io:socket socket connected - writing packet +2026-02-01T07:49:45.7475930Z 1769932185480 I TestConnection SERVER ERR: 2026-02-01T07:49:45.474Z socket.io:socket join room I6cxDxOi1VMI0lYEAAAB +2026-02-01T07:49:45.7476830Z 1769932185481 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7481980Z 1769932185481 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA, data 41, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7483610Z 1769932185481 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7484110Z METHOD: GET +2026-02-01T07:49:45.7484330Z COMMON HEADERS +2026-02-01T07:49:45.7484560Z -> Accept: */* +2026-02-01T07:49:45.7484800Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7485340Z CONTENT HEADERS +2026-02-01T07:49:45.7485590Z -> Content-Length: 0 +2026-02-01T07:49:45.7485850Z BODY Content-Type: null +2026-02-01T07:49:45.7486100Z BODY START +2026-02-01T07:49:45.7486280Z +2026-02-01T07:49:45.7486410Z BODY END +2026-02-01T07:49:45.7486920Z 1769932185481 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7487480Z METHOD: POST +2026-02-01T07:49:45.7487710Z COMMON HEADERS +2026-02-01T07:49:45.7487940Z -> Accept: */* +2026-02-01T07:49:45.7493890Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7494160Z CONTENT HEADERS +2026-02-01T07:49:45.7494410Z -> Content-Length: 2 +2026-02-01T07:49:45.7494760Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7495130Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7495440Z BODY START +2026-02-01T07:49:45.7495670Z 41 +2026-02-01T07:49:45.7495870Z BODY END + + + + + + + + + + +2026-02-01T07:49:45.7496230Z 1769932185483 I Socket open: connected false, io reconnecting false +2026-02-01T07:49:45.7496700Z 1769932185483 I Socket subEvents: subs 0 +2026-02-01T07:49:45.7497150Z 1769932185483 I Manager open, state CLOSED, uri http://localhost:3000/ +2026-02-01T07:49:45.7497620Z 1769932185484 I EngineSocket open: state INIT +2026-02-01T07:49:45.7498010Z 1769932185484 I EngineSocket createTransport polling +2026-02-01T07:49:45.7498570Z 1769932185484 I EngineSocket setTransport polling +2026-02-01T07:49:45.7498960Z 1769932185484 D Transport polling@969147974 open +2026-02-01T07:49:45.7499560Z 1769932185484 D Transport polling@969147974 poll start +2026-02-01T07:49:45.7500330Z 1769932185484 D Transport polling@969147974 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7501190Z 1769932185484 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:49:45.7501610Z METHOD: GET +2026-02-01T07:49:45.7501840Z COMMON HEADERS +2026-02-01T07:49:45.7502080Z -> Accept: */* +2026-02-01T07:49:45.7502330Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7502600Z CONTENT HEADERS +2026-02-01T07:49:45.7502840Z -> Content-Length: 0 +2026-02-01T07:49:45.7503100Z BODY Content-Type: null +2026-02-01T07:49:45.7503350Z BODY START +2026-02-01T07:49:45.7503520Z +2026-02-01T07:49:45.7503660Z BODY END +2026-02-01T07:49:45.7503980Z 1769932185485 I Net RESPONSE: 101 Switching Protocols +2026-02-01T07:49:45.7504300Z METHOD: GET +2026-02-01T07:49:45.7504740Z FROM: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7505380Z COMMON HEADERS +2026-02-01T07:49:45.7505620Z -> Connection: Upgrade +2026-02-01T07:49:45.7505970Z -> Sec-WebSocket-Accept: wQD0iEl4+5SOoN9JjTrVMh6be7U= +2026-02-01T07:49:45.7506320Z -> Upgrade: websocket +2026-02-01T07:49:45.7506570Z BODY Content-Type: null +2026-02-01T07:49:45.7506890Z BODY START +2026-02-01T07:49:45.7507340Z +2026-02-01T07:49:45.7507510Z BODY END +2026-02-01T07:49:45.7507880Z 1769932185488 I Transport websocket@2087361714 onOpen, state OPENING +2026-02-01T07:49:45.7508400Z 1769932185488 I EngineSocket probe transport websocket opened, failed: false +2026-02-01T07:49:45.7508940Z 1769932185488 D Transport websocket@2087361714 send: state OPEN, 1 packets +2026-02-01T07:49:45.7509540Z 1769932185488 D Transport websocket@2087361714 doSend 1 packets start +2026-02-01T07:49:45.7510080Z 1769932185488 D Transport websocket@2087361714 doSend: Ping(payload=probe), `2probe` +2026-02-01T07:49:45.7510690Z 1769932185489 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7510970Z METHOD: POST +2026-02-01T07:49:45.7511650Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7512010Z COMMON HEADERS +2026-02-01T07:49:45.7512290Z -> Connection: keep-alive +2026-02-01T07:49:45.7512570Z -> Content-Length: 2 +2026-02-01T07:49:45.7513850Z -> Content-Type: text/html +2026-02-01T07:49:45.7514490Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7516360Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7519710Z -> cache-control: no-store +2026-02-01T07:49:45.7520300Z BODY Content-Type: text/html +2026-02-01T07:49:45.7621080Z BODY START +2026-02-01T07:49:45.7623400Z ok +2026-02-01T07:49:45.7623630Z BODY END +2026-02-01T07:49:45.7624380Z 1769932185489 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA response: 200 OK +2026-02-01T07:49:45.7625100Z 1769932185490 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7625380Z METHOD: GET +2026-02-01T07:49:45.7625840Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7626270Z COMMON HEADERS +2026-02-01T07:49:45.7626520Z -> Connection: keep-alive +2026-02-01T07:49:45.7626800Z -> Content-Length: 28 +2026-02-01T07:49:45.7627120Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7627480Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7627780Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7628090Z -> cache-control: no-store +2026-02-01T07:49:45.7628420Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7628720Z BODY START +2026-02-01T07:49:45.7628980Z 42["message","hello client"] +2026-02-01T07:49:45.7629550Z BODY END +2026-02-01T07:49:45.7629950Z 1769932185490 D Transport websocket@2087361714 doSend 1 packets finish +2026-02-01T07:49:45.7630530Z 1769932185490 D EngineSocket onDrain: prevBufferLen 1, writeBuffer.size 1, len 1 +2026-02-01T07:49:45.7631040Z 1769932185490 D EngineSocket onDrain fire socket drain event +2026-02-01T07:49:45.7631480Z 1769932185490 I EngineSocket close waiting drain success +2026-02-01T07:49:45.7631960Z 1769932185490 I EngineSocket socket closing - telling transport to close +2026-02-01T07:49:45.7632420Z 1769932185490 I EngineSocket onClose force close +2026-02-01T07:49:45.7632840Z 1769932185490 I Transport polling@709407350 close, state OPEN +2026-02-01T07:49:45.7633340Z 1769932185490 I Transport polling@709407350 doClose on OPEN state, closing +2026-02-01T07:49:45.7633870Z 1769932185490 I Transport polling@709407350 doClose writing close packet +2026-02-01T07:49:45.7634700Z 1769932185490 D Transport polling@709407350 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA response: 200 OK +2026-02-01T07:49:45.7635490Z 1769932185490 E EngineSocket probe transport websocket, but socket closed +2026-02-01T07:49:45.7636630Z 1769932185490 I Transport websocket@2087361714 close, state OPEN +2026-02-01T07:49:45.7637070Z 1769932185490 I Transport websocket@2087361714 doClose +2026-02-01T07:49:45.7637610Z 1769932185490 E EngineSocket probe transport websocket failed because of error: socket closed +2026-02-01T07:49:45.7638390Z 1769932185490 D Transport polling@709407350 onPollComplete: state CLOSING, `42["message","hello client"]` +2026-02-01T07:49:45.7639520Z 1769932185491 D Transport polling@709407350 onPacket Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:49:45.7640270Z 1769932185491 I Transport polling@709407350 onPollComplete ignore poll, state CLOSING +2026-02-01T07:49:45.7641330Z 1769932185491 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA, data 1, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7642630Z 1769932185491 I TestConnection SERVER ERR: 2026-02-01T07:49:45.487Z socket.io:socket got packet {"type":1,"nsp":"/"} +2026-02-01T07:49:45.7643360Z 1769932185491 I TestConnection SERVER ERR: 2026-02-01T07:49:45.487Z socket.io:socket got disconnect packet +2026-02-01T07:49:45.7644170Z 1769932185491 I TestConnection SERVER ERR: 2026-02-01T07:49:45.487Z socket.io:socket closing socket - reason client namespace disconnect +2026-02-01T07:49:45.7645050Z 1769932185491 I TestConnection SERVER ERR: 2026-02-01T07:49:45.488Z socket.io:server incoming connection with id Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7645670Z 1769932185492 I TestConnection SERVER OUT: disconnect +2026-02-01T07:49:45.7646270Z 1769932185496 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7646740Z METHOD: POST +2026-02-01T07:49:45.7646960Z COMMON HEADERS +2026-02-01T07:49:45.7647190Z -> Accept: */* +2026-02-01T07:49:45.7647450Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7647710Z CONTENT HEADERS +2026-02-01T07:49:45.7647950Z -> Content-Length: 1 +2026-02-01T07:49:45.7648250Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7648620Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7648910Z BODY START +2026-02-01T07:49:45.7649310Z 1 +2026-02-01T07:49:45.7649530Z BODY END +2026-02-01T07:49:45.7650050Z 1769932185498 D Transport websocket@2087361714 Receive frame: Frame TEXT (fin=true, buffer len = 6) +2026-02-01T07:49:45.7650540Z 1769932185498 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7650820Z METHOD: GET +2026-02-01T07:49:45.7651160Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling +2026-02-01T07:49:45.7651500Z COMMON HEADERS +2026-02-01T07:49:45.7651880Z -> Connection: keep-alive +2026-02-01T07:49:45.7652170Z -> Content-Length: 117 +2026-02-01T07:49:45.7652480Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7652830Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7653120Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7653400Z -> cache-control: no-store +2026-02-01T07:49:45.7653730Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7654020Z BODY START +2026-02-01T07:49:45.7654540Z 0{"sid":"Q5cmf6rvfmLGKrBHAAAC","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000} +2026-02-01T07:49:45.7655020Z BODY END +2026-02-01T07:49:45.7655590Z 1769932185498 D Transport polling@969147974 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling response: 200 OK +2026-02-01T07:49:45.7656390Z 1769932185499 E Transport websocket@2087361714 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:49:45.7658670Z 1769932185499 D Transport websocket@2087361714 onWsText: `3probe` +2026-02-01T07:49:45.7660790Z 1769932185499 D Transport websocket@2087361714 onPacket Pong(payload=probe) +2026-02-01T07:49:45.7661480Z 1769932185500 I Transport websocket@2087361714 onClose +2026-02-01T07:49:45.7662370Z 1769932185500 D Transport polling@969147974 onPollComplete: state OPENING, `0{"sid":"Q5cmf6rvfmLGKrBHAAAC","upgrades":["websocket"],"pingInterval":2000,"pingTimeout":20000,"maxPayload":1000000}` +2026-02-01T07:49:45.7663210Z 1769932185500 I Transport polling@969147974 onOpen, state OPENING +2026-02-01T07:49:45.7664030Z 1769932185500 D Transport polling@969147974 onPacket Open(sid=Q5cmf6rvfmLGKrBHAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7665210Z 1769932185500 D EngineSocket transport on packet Open(sid=Q5cmf6rvfmLGKrBHAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7668320Z 1769932185500 D EngineSocket onPacket Open(sid=Q5cmf6rvfmLGKrBHAAAC, upgrades=[websocket], pingInterval=2000, pingTimeout=20000, maxPayload=1000000) +2026-02-01T07:49:45.7669570Z 1769932185500 I EngineSocket onOpen +2026-02-01T07:49:45.7669930Z 1769932185500 I Manager onOpen, state OPENING +2026-02-01T07:49:45.7670280Z 1769932185500 I Manager cleanUp +2026-02-01T07:49:45.7670580Z 1769932185500 I Socket onOpen +2026-02-01T07:49:45.7671060Z 1769932185500 D Manager send packets [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:49:45.7671750Z 1769932185500 D EngineSocket sendPackets: state OPEN, [Message(payload=Connect(namespace=/, payload=null))] +2026-02-01T07:49:45.7672520Z 1769932185500 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:49:45.7673150Z 1769932185500 D Transport polling@969147974 send: state OPEN, 1 packets +2026-02-01T07:49:45.7673610Z 1769932185500 I EngineSocket starting upgrade probes +2026-02-01T07:49:45.7674050Z 1769932185500 I EngineSocket probing transport 'websocket' +2026-02-01T07:49:45.7674470Z 1769932185500 I EngineSocket createTransport websocket +2026-02-01T07:49:45.7674880Z 1769932185500 D Transport websocket@590078241 open +2026-02-01T07:49:45.7675830Z 1769932185500 D Transport polling@969147974 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC, data 40, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7676940Z 1769932185500 I Transport websocket@590078241 doOpen ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7677560Z 1769932185500 D Transport polling@969147974 poll start +2026-02-01T07:49:45.7678370Z 1769932185500 D Transport polling@969147974 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7679420Z 1769932185503 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7679920Z METHOD: POST +2026-02-01T07:49:45.7680160Z COMMON HEADERS +2026-02-01T07:49:45.7680390Z -> Accept: */* +2026-02-01T07:49:45.7680640Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7680900Z CONTENT HEADERS +2026-02-01T07:49:45.7681140Z -> Content-Length: 2 +2026-02-01T07:49:45.7681450Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7681820Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7682120Z BODY START +2026-02-01T07:49:45.7682330Z 40 +2026-02-01T07:49:45.7682540Z BODY END +2026-02-01T07:49:45.7683080Z 1769932185507 I TestConnection SERVER ERR: 2026-02-01T07:49:45.505Z socket.io:client client close with reason transport close +2026-02-01T07:49:45.7683860Z 1769932185509 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7684320Z METHOD: GET +2026-02-01T07:49:45.7684550Z COMMON HEADERS +2026-02-01T07:49:45.7684780Z -> Accept: */* +2026-02-01T07:49:45.7685030Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7685350Z CONTENT HEADERS +2026-02-01T07:49:45.7685580Z -> Content-Length: 0 +2026-02-01T07:49:45.7685840Z BODY Content-Type: null +2026-02-01T07:49:45.7686090Z BODY START +2026-02-01T07:49:45.7686260Z +2026-02-01T07:49:45.7686400Z BODY END +2026-02-01T07:49:45.7686940Z 1769932185511 I TestConnection SERVER ERR: 2026-02-01T07:49:45.509Z socket.io:client connecting to namespace / +2026-02-01T07:49:45.7687450Z 1769932185511 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7687740Z METHOD: POST +2026-02-01T07:49:45.7688240Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA +2026-02-01T07:49:45.7688710Z COMMON HEADERS +2026-02-01T07:49:45.7688950Z -> Connection: keep-alive +2026-02-01T07:49:45.7689230Z -> Content-Length: 2 +2026-02-01T07:49:45.7689510Z -> Content-Type: text/html +2026-02-01T07:49:45.7689830Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7690120Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7690420Z -> cache-control: no-store +2026-02-01T07:49:45.7690860Z BODY Content-Type: text/html +2026-02-01T07:49:45.7691120Z BODY START +2026-02-01T07:49:45.7691330Z ok +2026-02-01T07:49:45.7691540Z BODY END +2026-02-01T07:49:45.7692190Z 1769932185511 D Transport polling@709407350 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=npUAHeAD7Xe4wi4TAAAA response: 200 OK +2026-02-01T07:49:45.7692880Z 1769932185511 I TestConnection SERVER OUT: on connection +2026-02-01T07:49:45.7693250Z 1769932185511 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7693580Z METHOD: POST +2026-02-01T07:49:45.7694010Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7694420Z COMMON HEADERS +2026-02-01T07:49:45.7694670Z -> Connection: keep-alive +2026-02-01T07:49:45.7694930Z -> Content-Length: 2 +2026-02-01T07:49:45.7695220Z -> Content-Type: text/html +2026-02-01T07:49:45.7695530Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7695820Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7696120Z -> cache-control: no-store +2026-02-01T07:49:45.7696410Z BODY Content-Type: text/html +2026-02-01T07:49:45.7696670Z BODY START +2026-02-01T07:49:45.7696900Z ok +2026-02-01T07:49:45.7697110Z BODY END +2026-02-01T07:49:45.7697770Z 1769932185512 D Transport polling@969147974 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC response: 200 OK +2026-02-01T07:49:45.7698450Z 1769932185512 I Transport polling@709407350 onClose +2026-02-01T07:49:45.7698940Z 1769932185512 D EngineSocket onDrain: prevBufferLen 1, writeBuffer.size 1, len 1 +2026-02-01T07:49:45.7699450Z 1769932185512 D EngineSocket onDrain fire socket drain event +2026-02-01T07:49:45.7700180Z 1769932185511 I TestConnection SERVER ERR: 2026-02-01T07:49:45.509Z socket.io:namespace adding socket to nsp / +2026-02-01T07:49:45.7700970Z 1769932185513 I TestConnection SERVER ERR: 2026-02-01T07:49:45.509Z socket.io:socket socket connected - writing packet +2026-02-01T07:49:45.7701740Z 1769932185513 I TestConnection SERVER ERR: 2026-02-01T07:49:45.509Z socket.io:socket join room 0_W1hJWvCHgoG_ktAAAD +2026-02-01T07:49:45.7702490Z 1769932185513 I Net REQUEST: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7702950Z METHOD: GET +2026-02-01T07:49:45.7703170Z COMMON HEADERS +2026-02-01T07:49:45.7703400Z -> Accept: */* +2026-02-01T07:49:45.7703650Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7703910Z CONTENT HEADERS +2026-02-01T07:49:45.7704150Z -> Connection: Upgrade +2026-02-01T07:49:45.7704490Z -> Sec-WebSocket-Key: NTE4Y2I5YTRkNzc5MDdlMw== +2026-02-01T07:49:45.7704850Z -> Sec-WebSocket-Version: 13 +2026-02-01T07:49:45.7705130Z -> Upgrade: websocket +2026-02-01T07:49:45.7705410Z BODY Content-Type: null +2026-02-01T07:49:45.7705660Z BODY START +2026-02-01T07:49:45.7705840Z +2026-02-01T07:49:45.7705980Z BODY END +2026-02-01T07:49:45.7706240Z 1769932185515 I Net RESPONSE: 200 OK +2026-02-01T07:49:45.7706530Z METHOD: GET +2026-02-01T07:49:45.7706970Z FROM: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7707390Z COMMON HEADERS +2026-02-01T07:49:45.7707630Z -> Connection: keep-alive +2026-02-01T07:49:45.7707910Z -> Content-Length: 61 +2026-02-01T07:49:45.7708230Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7708580Z -> Date: Sun, 01 Feb 2026 07:49:45 GMT +2026-02-01T07:49:45.7708880Z -> Keep-Alive: timeout=5 +2026-02-01T07:49:45.7709180Z -> cache-control: no-store +2026-02-01T07:49:45.7709510Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7709820Z BODY START +2026-02-01T07:49:45.7710490Z 40{"sid":"0_W1hJWvCHgoG_ktAAAD"}42["message","hello client"] +2026-02-01T07:49:45.7710900Z BODY END +2026-02-01T07:49:45.7711570Z 1769932185515 D Transport polling@969147974 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC response: 200 OK +2026-02-01T07:49:45.7712790Z 1769932185516 D Transport polling@969147974 onPollComplete: state OPEN, `40{"sid":"0_W1hJWvCHgoG_ktAAAD"}42["message","hello client"]` +2026-02-01T07:49:45.7713740Z 1769932185516 D Transport polling@969147974 onPacket Message(payload=Connect(namespace=/, payload={"sid":"0_W1hJWvCHgoG_ktAAAD"})) +2026-02-01T07:49:45.7714600Z 1769932185516 D EngineSocket transport on packet Message(payload=Connect(namespace=/, payload={"sid":"0_W1hJWvCHgoG_ktAAAD"})) +2026-02-01T07:49:45.7715420Z 1769932185516 D EngineSocket onPacket Message(payload=Connect(namespace=/, payload={"sid":"0_W1hJWvCHgoG_ktAAAD"})) +2026-02-01T07:49:45.7716160Z 1769932185516 D Manager on EngineSocket data class org.hildan.socketio.SocketIOPacket$Connect +2026-02-01T07:49:45.7716850Z 1769932185516 D Socket onPacket: nsp /, Connect(namespace=/, payload={"sid":"0_W1hJWvCHgoG_ktAAAD"}) +2026-02-01T07:49:45.7717400Z 1769932185516 I Socket onConnect sid 0_W1hJWvCHgoG_ktAAAD +2026-02-01T07:49:45.7718110Z 1769932185516 D Transport polling@969147974 onPacket Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:49:45.7719030Z 1769932185516 D EngineSocket transport on packet Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:49:45.7719950Z 1769932185516 D EngineSocket onPacket Message(payload=Event(namespace=/, ackId=null, payload=["message","hello client"])) +2026-02-01T07:49:45.7720670Z 1769932185516 D Manager on EngineSocket data class org.hildan.socketio.SocketIOPacket$Event +2026-02-01T07:49:45.7721350Z 1769932185516 D Socket onPacket: nsp /, Event(namespace=/, ackId=null, payload=["message","hello client"]) +2026-02-01T07:49:45.7722130Z 1769932185516 D Socket onEvent Event(namespace=/, ackId=null, payload=["message","hello client"]) +2026-02-01T07:49:45.7722680Z 1769932185516 D Transport polling@969147974 poll start +2026-02-01T07:49:45.7723070Z 1769932185516 I Socket close: connected true +2026-02-01T07:49:45.7723540Z 1769932185516 D Manager send packets [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:49:45.7724180Z 1769932185516 D EngineSocket sendPackets: state OPEN, [Message(payload=Disconnect(namespace=/))] +2026-02-01T07:49:45.7724930Z 1769932185516 D EngineSocket flush: state OPEN, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 1 +2026-02-01T07:49:45.7725580Z 1769932185516 D Transport polling@969147974 send: state OPEN, 1 packets +2026-02-01T07:49:45.7726000Z 1769932185516 I Manager destroy +2026-02-01T07:49:45.7726310Z 1769932185516 I Manager close +2026-02-01T07:49:45.7726610Z 1769932185516 I Manager cleanUp +2026-02-01T07:49:45.7727090Z 1769932185517 I EngineSocket close: state OPEN, writeBuffer.size 1, upgrading: false +2026-02-01T07:49:45.7727600Z 1769932185517 I EngineSocket close waiting drain event +2026-02-01T07:49:45.7728010Z 1769932185517 I Socket onClose: `io client disconnect` +2026-02-01T07:49:45.7728960Z 1769932185517 D Transport polling@969147974 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC, data 41, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7730190Z 1769932185517 D Transport polling@969147974 doRequest GET http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC, data null, headers {Accept=[*/*]} +2026-02-01T07:49:45.7731140Z 1769932185517 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7731610Z METHOD: POST +2026-02-01T07:49:45.7731880Z COMMON HEADERS +2026-02-01T07:49:45.7732110Z -> Accept: */* +2026-02-01T07:49:45.7738030Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7738420Z CONTENT HEADERS +2026-02-01T07:49:45.7738670Z -> Content-Length: 2 +2026-02-01T07:49:45.7738990Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7739570Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7739870Z BODY START +2026-02-01T07:49:45.7740080Z 41 +2026-02-01T07:49:45.7740290Z BODY END +2026-02-01T07:49:45.7740800Z 1769932185517 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7741260Z METHOD: GET +2026-02-01T07:49:45.7741480Z COMMON HEADERS +2026-02-01T07:49:45.7741700Z -> Accept: */* +2026-02-01T07:49:45.7741940Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7742200Z CONTENT HEADERS +2026-02-01T07:49:45.7742440Z -> Content-Length: 0 +2026-02-01T07:49:45.7742690Z BODY Content-Type: null +2026-02-01T07:49:45.7742940Z BODY START +2026-02-01T07:49:45.7743120Z +2026-02-01T07:49:45.7743250Z BODY END +2026-02-01T07:49:45.7743550Z 1769932185520 I TestConnection Stopping server ... +2026-02-01T07:49:45.7743940Z 1769932185520 I Socket close: connected false +2026-02-01T07:49:45.7744270Z 1769932185520 I Manager destroy +2026-02-01T07:49:45.7744580Z 1769932185520 I Manager close +2026-02-01T07:49:45.7744880Z 1769932185520 I Manager cleanUp +2026-02-01T07:49:45.7745230Z 1769932185520 I Net RESPONSE: 101 Switching Protocols +2026-02-01T07:49:45.7745540Z METHOD: GET +2026-02-01T07:49:45.7745970Z FROM: ws://localhost:3000/socket.io/?EIO=4&transport=websocket&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7746380Z COMMON HEADERS +2026-02-01T07:49:45.7746630Z -> Connection: Upgrade +2026-02-01T07:49:45.7746980Z -> Sec-WebSocket-Accept: gqdRMIp8SZvjpcEb1mjbZBf5UNA= +2026-02-01T07:49:45.7747320Z -> Upgrade: websocket +2026-02-01T07:49:45.7747580Z BODY Content-Type: null +2026-02-01T07:49:45.7747830Z BODY START +2026-02-01T07:49:45.7748000Z +2026-02-01T07:49:45.7748130Z BODY END +2026-02-01T07:49:45.7748570Z 1769932185521 I Transport websocket@590078241 onOpen, state OPENING +2026-02-01T07:49:45.7749110Z 1769932185521 I EngineSocket probe transport websocket opened, failed: false +2026-02-01T07:49:45.7749650Z 1769932185521 D Transport websocket@590078241 send: state OPEN, 1 packets +2026-02-01T07:49:45.7750150Z 1769932185521 D Transport websocket@590078241 doSend 1 packets start +2026-02-01T07:49:45.7750690Z 1769932185521 D Transport websocket@590078241 doSend: Ping(payload=probe), `2probe` +2026-02-01T07:49:45.7751370Z 1769932185523 D Transport websocket@590078241 doSend 1 packets finish +2026-02-01T07:49:45.7752000Z 1769932185526 E Transport websocket@590078241 Receive error while reading websocket frame: `Channel was closed` +2026-02-01T07:49:45.7752550Z 1769932185526 I Transport websocket@590078241 onClose +2026-02-01T07:49:45.7753060Z 1769932185526 E EngineSocket probe transport websocket, but transport closed +2026-02-01T07:49:45.7753570Z 1769932185526 I Transport websocket@590078241 close, state CLOSED +2026-02-01T07:49:45.7754150Z 1769932185526 E EngineSocket probe transport websocket failed because of error: transport closed +2026-02-01T07:49:45.7755190Z 1769932185526 I Net REQUEST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC failed with exception: io.ktor.utils.io.ClosedByteChannelException: Connection reset +2026-02-01T07:49:45.7756510Z 1769932185526 I Net REQUEST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC failed with exception: io.ktor.utils.io.ClosedByteChannelException: Connection reset +2026-02-01T07:49:45.7757410Z 1769932185526 E Transport polling@969147974 onError `http exception: Connection reset` +2026-02-01T07:49:45.7758000Z 1769932185526 E EngineSocket transport onError: `http exception: Connection reset` +2026-02-01T07:49:45.7758610Z 1769932185526 I EngineSocket onClose transport onError: `http exception: Connection reset` +2026-02-01T07:49:45.7759150Z 1769932185526 I Transport polling@969147974 close, state OPEN +2026-02-01T07:49:45.7759640Z 1769932185526 I Transport polling@969147974 doClose on OPEN state, closing +2026-02-01T07:49:45.7760270Z 1769932185526 I Transport polling@969147974 doClose writing close packet +2026-02-01T07:49:45.7760850Z 1769932185527 E Transport polling@969147974 onError `http exception: Connection reset` +2026-02-01T07:49:45.7761870Z 1769932185527 D Transport polling@969147974 doRequest POST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC, data 1, headers {Content-type=[text/plain;charset=UTF-8], Accept=[*/*]} +2026-02-01T07:49:45.7762880Z 1769932185527 I Net REQUEST: http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC +2026-02-01T07:49:45.7763350Z METHOD: POST +2026-02-01T07:49:45.7763570Z COMMON HEADERS +2026-02-01T07:49:45.7763810Z -> Accept: */* +2026-02-01T07:49:45.7764050Z -> Accept-Charset: UTF-8 +2026-02-01T07:49:45.7764320Z CONTENT HEADERS +2026-02-01T07:49:45.7764550Z -> Content-Length: 1 +2026-02-01T07:49:45.7764870Z -> Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7765240Z BODY Content-Type: text/plain; charset=UTF-8 +2026-02-01T07:49:45.7765540Z BODY START +2026-02-01T07:49:45.7765750Z 1 +2026-02-01T07:49:45.7765950Z BODY END +2026-02-01T07:49:45.7766940Z 1769932185528 I Net REQUEST http://localhost:3000/socket.io/?EIO=4&transport=polling&sid=Q5cmf6rvfmLGKrBHAAAC failed with exception: java.net.ConnectException: Connection refused +2026-02-01T07:49:45.7767830Z 1769932185528 E Transport polling@969147974 onError `http exception: Connection refused` +2026-02-01T07:49:45.7768190Z \ No newline at end of file diff --git a/docs/ut-case-analysis/kimi-code-result-bad.txt b/docs/ut-case-analysis/kimi-code-result-bad.txt new file mode 100644 index 0000000..530cf1c --- /dev/null +++ b/docs/ut-case-analysis/kimi-code-result-bad.txt @@ -0,0 +1,174 @@ + 详细分析报告：reconnectManually 测试偶现失败问题 + + 一、测试用例逻辑 + + reconnectManually 测试的核心逻辑： + + 1. 第一次连接：调用 socket.open() → 等待 EVENT_CONNECT → 调用 socket.close() + 2. 第二次连接：收到 EVENT_DISCONNECT 后 → 再次调用 socket.open() → 等待 EVENT_CONNECT → 调用 socket.close() → 测试完成 + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 二、关键 Transport 实例说明 + + 根据日志中的 hash 值，我整理出以下 transport 实例： + + 日志文件 Transport 实例 类型 用途 + ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ + good.log polling@709407350 Polling 第一次连接的初始 transport + websocket@2087361714 WebSocket 第一次连接的 probe transport（升级失败） + polling@969147974 Polling 第二次连接的 transport + websocket@590078241 WebSocket 第二次连接的 probe transport + err.log polling@1929439163 Polling 第一次连接的初始 transport + websocket@260110639 WebSocket 第一次连接的 probe transport（升级成功但引发崩溃） + polling@2125549749 Polling 第二次连接的 transport + websocket@897766716 WebSocket 第二次连接的 probe transport + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 三、正常情况（good.log）的执行流程分析 + + [第一次连接] + 1. polling@709407350: INIT → OPENING → OPEN (发送 Connect 包) + 2. 启动 upgrade probe: 创建 websocket@2087361714 + 3. websocket@2087361714: OPENING → OPEN → 发送 probe ping + 4. 此时 socket.close() 被调用，开始关闭流程 + 5. polling@709407350: 进入 CLOSING → 发送 Disconnect 包 → 收到 drain → 关闭 + 6. websocket@2087361714: 因 socket 关闭而关闭 (probe 失败: "socket closed") + + [第二次连接] + 7. 创建新的 polling@969147974: INIT → OPENING → OPEN + 8. 启动 upgrade probe: 创建 websocket@590078241 + 9. polling@969147974 正常处理数据 + 10. 测试完成，停止服务器 + + 关键点：在 good.log 中，第一次连接的 WebSocket probe (websocket@2087361714) 在成功前就被 socket 关闭流程中断了，没有完成升级。 + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 四、失败情况（err.log）的执行流程分析 + + [第一次连接] + 1. polling@1929439163: INIT → OPENING → OPEN (发送 Connect 包) + 2. 启动 upgrade probe: 创建 websocket@260110639 + 3. socket.close() 被调用，但此时 writeBuffer 有待发送数据 (Disconnect 包) + 4. EngineSocket 进入 "waiting drain" 状态 + + [关键问题时间点] + 5. websocket@260110639 在 socket 等待 drain 期间完成了 WebSocket 握手 (101 Switching Protocols) + 6. websocket@260110639: 发送 probe ping → 收到 probe pong → 升级流程开始 + 7. EngineSocket 状态: CLOSING，但 upgrade 流程仍在进行！ + 8. polling@1929439163 被 pause() → 进入 PAUSED 状态 + 9. EngineSocket "close waiting upgrade"（在 CLOSING 状态下等待升级） + + [严重问题] + 10. websocket@260110639 发送 upgrade 包成功 → 触发 drain 事件 + 11. onDrain 被调用: prevBufferLen=0, writeBuffer.size=0, len=1 + 12. 尝试 writeBuffer.removeAt(0) 但队列为空！ + 13. 抛出 NoSuchElementException: ArrayDeque is empty + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 五、根本问题分析 + + 5.1 问题核心：状态竞争条件 + + 问题场景：在 socket.close() 被调用后，如果此时： + + 1. writeBuffer 非空（有待发送的 Disconnect 包） + 2. 但 WebSocket probe 恰好在此时完成了握手并收到 pong + 3. 升级流程会启动（upgrading = true） + + 代码路径分析： + + 在 EngineSocket.close() 方法中（第 180-196 行）： + + if (writeBuffer.isNotEmpty()) { + once(EVENT_DRAIN, object : Listener { + override fun call(vararg args: Any) { + if (upgrading) { // <- 此时 upgrading 可能为 true + waitForUpgrade() + } else { + closeAction() + } + } + }) + } + + 在 probe() 方法中（第 402-455 行），当 probe 成功后： + + transport.once(EVENT_DRAIN, object : Listener { + override fun call(vararg args: Any) { + emit(EVENT_UPGRADE, transport) + setTransport(transport) // <- 这会替换 transport + // ... + flush() // <- 新 transport 的 flush + } + }) + + 5.2 崩溃的直接原因 + + 在 onDrain 方法中（第 277-290 行）： + + private fun onDrain(len: Int) { + for (i in 1..len) { + writeBuffer.removeAt(0) // <- 崩溃点！当 writeBuffer 为空时抛出异常 + } + } + + 为什么会空？ + + 1. 第一次 close() 时，writeBuffer 有 1 个 Disconnect 包 + 2. polling transport 发送 Disconnect 并触发 drain + 3. 但在 drain 事件触发前，WebSocket probe 完成了并调用 setTransport(transport) + 4. 新 transport 的 flush 可能修改了 prevBufferLen 或触发了额外的 drain 事件 + 5. 导致 onDrain 被调用时，writeBuffer 已经被清空 + + 5.3 关键日志对比 + + 时间点 good.log (正常) err.log (失败) + ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ + Socket close 在 WebSocket probe 成功前 在 WebSocket probe 成功后 + polling 状态 直接 CLOSING → 关闭 PAUSED (因 upgrade 而暂停) + upgrade 完成 否 是 + 后续流程 直接关闭 尝试 setTransport + flush + drain 处理 正常处理 Disconnect 的 drain 异常的 drain (buffer 不匹配) + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 六、状态变化时序图 + + [good.log - 正常关闭] + polling@709407350: OPEN ──→ CLOSING ──→ 发送 Disconnect ──→ drain ──→ CLOSED + ↑ + websocket@2087361714: OPENING (probe 进行中) + │ + 收到 socket closed 错误，probe 失败 + + [err.log - 异常关闭] + polling@1929439163: OPEN ──→ CLOSING ──→ pause ──→ PAUSED ──→ 关闭 + ↑ ↑ + websocket@260110639: OPENING ──→ OPEN ──→ probe pong ──→ upgrade + │ + ↓ + setTransport() + │ + flush() [新 transport] + │ + onDrain(len=1) ← 异常！ + │ + writeBuffer 已空 + + ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── + 七、总结 + + 根本原因：EngineSocket.close() 和 probe() 的 upgrade 流程之间存在竞争条件。当 socket 正在关闭（有未发送数据等待 drain）时，如果 probe transport 成功完成，会触发升级流程。此时： + + 1. upgrading 被设为 true + 2. 原 polling transport 被 pause + 3. 新 WebSocket transport 被设置并触发 flush + 4. 这导致 onDrain 在错误的时机被调用，writeBuffer 和 prevBufferLen 状态不一致 + 5. 最终 ArrayDeque.removeFirst() 在空队列上抛出 NoSuchElementException + + 触发条件：这是一个时序相关的竞态条件，取决于： + + • WebSocket probe 完成的时间点 + • socket.close() 调用的时间点 + • 网络延迟和调度顺序 + + 这就是为什么该问题是偶现的。 \ No newline at end of file diff --git a/docs/ut-case-analysis/kmp-socketio-ut-case-analysis.txt b/docs/ut-case-analysis/kmp-socketio-ut-case-analysis.txt new file mode 100644 index 0000000..d3966ad --- /dev/null +++ b/docs/ut-case-analysis/kmp-socketio-ut-case-analysis.txt @@ -0,0 +1,75 @@ +good + + polling@709407350 709407350 第一次连接的主 transport + 创建 → 连接 → 连接成功，poll 到 Open 包，含 upgrade → 发送 Connect 包 → poll 到 Connect 包 → emit EVENT_CONNECT → 关闭 → 发送 Disconnect 包 → emit EVENT_DISCONNECT → 发送 Disconnect 包完成 → poll 到 Event 包（hello client），且不再继续 poll → 发送 Close 包 → 关闭完成 + websocket@2087361714 2087361714 第一次连接的 probe transport + 创建 → 连接 → 连接成功 → 发送 Ping 包（probe） → 发送成功 → 关闭 → 收到 Pong 包（probe） → 读报错，ws 关闭 → 关闭完成 + ws 在收到 Pong 包之前就关闭了，没出问题 + + polling@969147974 969147974 第二次连接（reconnect）的 transport 在第一次连接关闭后创建 + websocket@590078241 590078241 第二次连接的 probe transport 创建 → probe 成功 → 发送 upgrade packet → 问题源 + + +err + + polling@1929439163 1929439163 第一次连接的主 transport + 创建 → 连接 → 连接成功，poll 到 Open 包，含 upgrade → 发送 Connect 包 → poll 到 Connect 包 → emit EVENT_CONNECT → 关闭 → 发送 Disconnect 包 → emit EVENT_DISCONNECT → pause → poll 到 Event 包（hello client），且不再继续 poll → 发送 Disconnect 包完成 → pause 完成 → 发送 close 包 → 关闭完成 + websocket@260110639 260110639 第一次连接的 probe transport + 创建 → 连接 → 连接成功 → 发送 Ping 包（probe） → 发送成功 → 收到 Pong 包（probe） → 发送 Upgrade 包 → 发送 Upgrade 包成功，触发 EVENT_DRAIN → onDrain: prevBufferLen 0, writeBuffer.size 0, len 1，触发问题！ + ws 关闭前先收到 Pong 包、进行 upgrade，Upgrade 包的 EVENT_DRAIN 引发了问题。 + 先收到了 polling 的 Disconnect 包的 EVENT_DRAIN，后收到 ws Upgrade 包的 EVENT_DRAIN。 + + polling@2125549749 2125549749 第二次连接（reconnect）的 transport 在第一次连接关闭后创建 + +close 时，先发 Disconnect 包，如果是 polling 还要发 Close 包。 +probe 时，先 ws 连接，成功后发送 Ping，收到 Pong 后，pause polling，再发送 Upgrade 包，发送成功（EVENT_DRAIN）后把 EngineSocket 的 transport 切换为 ws。 + +出问题时： + ws 连接 + EngineSocket close，但要等 EngineSocket 的 EVENT_DRAIN（Disconnect 待发送） + polling 发 Disconnect + ws 连接成功 + ws 发 Ping + ws 收到 Pong + polling pause，但要等 poll 和 write (Disconnect) + polling poll 完成，且不再继续 poll + polling write 完成，触发 polling 的 EVENT_DRAIN，进而触发 EngineSocket 的 EVENT_DRAIN + EngineSocket 正常处理 EVENT_DRAIN + EngineSocket close 等到了 drain，但还要等 upgrade + polling pause 完成 + 监听 ws 的 EVENT_DRAIN，用于切换 transport + ws 发 Upgrade + ws 发 Ping 完成，触发 ws 的 EVENT_DRAIN + 把 EngineSocket 的 transport 切换为 ws + ws 发 Upgrade 完成，再次触发 ws 的 EVENT_DRAIN，进而触发 EngineSocket 的 EVENT_DRAIN + EngineSocket 处理 EVENT_DRAIN 时报错！ + + *两个 ws 的 EVENT_DRAIN，不一定是 Ping 的先还是 Upgrade 的先，总之先监听（用于切换 transport），后来了两个 EVENT_DRAIN，第二个引发了问题。 + +问题关键在于 ws 的 Ping 和 Upgrade 会连续发送，而两次 EVENT_DRAIN 的顺序和「监听 ws 的 EVENT_DRAIN 用于切换 transport」的顺序无法保证。 + Ping (probe) 需要 EVENT_DRAIN 吗？不触发 EVENT_DRAIN 可以规避此问题。 + 改成监听 Ping & Upgrade 的 drain 同时满足，也能解决此问题。 + +此外，这个用例只是同一个 Socket 实例，close 后立马 open，但 EngineSocket 实例是两个，不会有干扰。 + +============================================================================== +下面是逐步问不靠谱的 Kimi 的对话 +============================================================================== + +帮我排查一下 kmp-socketio 这个项目一个偶现的 ut 失败问题，其中 good.log 是 ut case 通过时的完整日志，err.log 则是这个 case 失败时打印的日志 + +我觉得你的分析不严谨，我需要你细致分析日志里面关于 transport 实例、行为的过程，Transport polling@ 和 Transport polling@ 开头的日志，@ 后面跟着的是 transport 实例的 hash 值，不同的 hash 值表明是不同的实例，请严谨地分析日志内容，以及代码里打印对应日志的逻辑，帮我彻底梳理确认整个测试用例的执行过程，以及 transport 状态的变化。 + +项目的代码逻辑我有些记不清了，你可以帮我分析总结一下连接、probe、upgrade 的逻辑吗？并且要结合上面你分析的问题原因的过程。注意只做分析，不要进行修复。 + +你分析的 T1~T12 是按先后顺序的吗？ + +============================================================================== +下面是考 AI 的提问 +============================================================================== + +帮我排查一下 kmp-socketio 这个项目一个偶现的 ut 失败问题，其中 good.log 是 ut case 通过时的完整日志，err.log 则是这个 case 失败时打印的日志。 +我需要你细致分析日志里面关于 transport 实例、行为的过程，Transport polling@ 和 Transport websocket@ 开头的日志，@ 后面跟着的是 transport 实例的 hash 值，不同的 hash 值表明是不同的实例，请严谨地分析日志内容，以及代码里打印对应日志的逻辑，帮我彻底梳理确认整个测试用例的执行过程，以及 transport 状态的变化。 +注意只做分析，不要进行修复。 + +============================================================================== diff --git a/docs/ut-case-analysis/openclaw-kimi-result-good.md b/docs/ut-case-analysis/openclaw-kimi-result-good.md new file mode 100644 index 0000000..7951f4f --- /dev/null +++ b/docs/ut-case-analysis/openclaw-kimi-result-good.md @@ -0,0 +1,327 @@ +# kmp-socketio reconnectManually UT 失败问题分析报告 + +## 测试用例流程概述 + +`reconnectManually` 测试用例的执行流程： +1. **第一次连接**: `socket.open()` 建立初始连接 (polling → websocket probe) +2. **第一次关闭**: 连接成功后立即 `socket.close()` +3. **重连**: 在 `EVENT_DISCONNECT` 回调中再次调用 `socket.open()` +4. **第二次关闭**: 重连成功后关闭 socket，测试结束 + +--- + +## 问题现象 + +异常信息： +``` +java.util.NoSuchElementException: ArrayDeque is empty. + at kotlin.collections.ArrayDeque.removeFirst(ArrayDeque.kt:146) + at com.piasy.kmp.socketio.engineio.EngineSocket.onDrain(EngineSocket.kt:280) +``` + +发生在 `onDrain` 方法中，当尝试从 `writeBuffer` 移除元素时，但 `writeBuffer` 已经为空。 + +--- + +## 关键 Transport 实例分析 (err.log) + +### 第一个连接生命周期 +| 时间戳 | Transport | 事件 | +|--------|-----------|------| +| 0665ms | polling@1929439163 | 创建并打开 | +| 0680ms | polling@1929439163 | 收到 Open 包，连接建立 | +| 0680ms | websocket@260110639 | 创建（probe） | +| 0694ms | polling@1929439163 | 发送 Disconnect，开始关闭 | +| 0695ms | polling@2125549749 | **新的 transport 创建（重连）** | +| 0698ms | websocket@260110639 | probe 完成，准备 upgrade | +| 0705ms | websocket@260110639 | 成为主 transport，替换 polling | +| 0712ms | websocket@260110639 | **发送完成触发 onDrain(1)，但 writeBuffer 为空 → 异常** | + +--- + +## 根因分析：竞态条件 + +### 1. 时序问题 + +在 `err.log` 中，关键的时间竞态： + +``` +0694ms: socket.close() 被调用 + └─ EngineSocket.close() 发现 writeBuffer 有 1 个包（Disconnect） + └─ 等待 drain 事件... + +0695ms: 重连开始，创建 polling@2125549749 + └─ 调用 setTransport()，为新 transport 注册事件监听器 + +0696ms: polling@1929439163 完成发送 Disconnect，触发 EVENT_DRAIN(1) + └─ onDrain(1): writeBuffer 从 1 变为 0，触发 EVENT_DRAIN + └─ close() 继续执行，发现 upgrading=true，等待 upgrade... + +0698ms: websocket@260110639 probe 完成 +0705ms: upgrade 流程执行 setTransport(websocket) + └─ 为 websocket@260110639 注册 EVENT_DRAIN 监听器 + +0705ms: websocket@260110639 发送 upgrade 包完成 + └─ 在 ioScope 中异步触发 EVENT_DRAIN(1) + +0712ms: scope.launch 执行，触发 EVENT_DRAIN(1) + └─ 新注册的监听器接收到事件，调用 onDrain(1) + └─ **但此时 writeBuffer 已经是空的（之前被清空了）** + └─ **抛出 NoSuchElementException** +``` + +### 2. 代码层面的问题 + +#### onDrain 方法的假设 + +```kotlin +@WorkThread +private fun onDrain(len: Int) { + // 假设：writeBuffer 中至少有 len 个元素 + for (i in 1..len) { + writeBuffer.removeAt(0) // 当 writeBuffer 为空时崩溃 + } + prevBufferLen -= len + // ... +} +``` + +`onDrain` 假设 `writeBuffer` 中的元素数量与 `len` 参数匹配。但这个假设在以下场景下会被打破： + +1. **Transport 切换期间**：旧的 transport 完成了它自己的发送，触发了 `EVENT_DRAIN` +2. **Buffer 已被清空**：在 `close()` 流程中，`writeBuffer` 可能已经被 drain +3. **事件监听器已更换**：`setTransport()` 为新 transport 注册了监听器，但旧的异步事件可能到达 + +#### WebSocket.doSend 的异步特性 + +```kotlin +ioScope.launch { + // 发送操作在 ioScope 中异步执行 + for (pkt in packets) { + // ... + } + + scope.launch { + // 回调在 scope 中执行，可能延迟 + emit(EVENT_DRAIN, packets.size) // 可能延迟到 setTransport 之后 + } +} +``` + +`EVENT_DRAIN` 的触发是异步的，可能在 `setTransport` 完成之后。此时： +- 新 transport 的事件监听器已注册 +- 但事件来自旧的（或正在升级的）transport +- `writeBuffer` 的状态已经不匹配 + +### 3. 成功场景 (good.log) vs 失败场景 (err.log) + +| 场景 | socket 关闭时机 | websocket probe 结果 | 是否触发异常 | +|------|----------------|---------------------|------------| +| **失败 (err.log)** | probe 进行中关闭 | probe 在关闭后完成，触发 upgrade | ✅ 是 | +| **成功 (good.log)** | probe 进行中关闭 | probe 被中断（"socket closed"） | ❌ 否 | + +在成功的场景中，websocket probe 在 socket 关闭时被中断，不会完成 upgrade 流程，因此不会触发那个导致异常的 `EVENT_DRAIN`。 + +--- + +## Transport 状态转换图 + +### 失败场景的详细状态转换 + +``` +[第一次连接建立] + │ + ├─ polling@1929439163: INIT → OPENING → OPEN + ├─ websocket@260110639: 创建作为 probe (OPENING) + │ +[第一次 socket.close()] + │ + ├─ EngineSocket.state: OPEN → CLOSING + ├─ polling@1929439163: 发送 Disconnect 包 + ├─ 等待 drain 事件... + │ +[重连开始 - 在 DISCONNECT 回调中] + │ + ├─ polling@2125549749: 创建（新的 transport） + ├─ setTransport(polling@2125549749): 注册新监听器 + │ +[polling@1929439163 发送完成] + │ + ├─ EVENT_DRAIN(1) → onDrain(1): writeBuffer 从 1→0 + ├─ close() 继续: 发现 upgrading=true，等待 upgrade + │ +[websocket probe 完成 - 在关闭之后！] + │ + ├─ websocket@260110639: 发送 Pong probe 成功 + ├─ upgrade 流程开始 + ├─ pause polling@1929439163 + ├─ setTransport(websocket@260110639): 为 websocket 注册监听器 + │ └─ subs 现在包含 websocket 的监听器 + ├─ websocket@260110639: 发送 upgrade 包 + │ +[websocket 发送完成 - 异步回调] + │ + ├─ (在 ioScope 中) 发送完成 + ├─ (在 scope.launch 中) emit(EVENT_DRAIN, 1) + │ └─ 此时 subs 中有 websocket 的监听器 + │ └─ 调用 onDrain(1) + │ └─ writeBuffer 已经是空的！ + │ └─ **抛出 NoSuchElementException** +``` + +--- + +## 关键代码路径 + +### 1. EngineSocket.close() + +```kotlin +fun close() { + // ... + if (writeBuffer.isNotEmpty()) { + once(EVENT_DRAIN, object : Listener { + override fun call(vararg args: Any) { + if (upgrading) { + // 等待 upgrade 完成 + once(EVENT_UPGRADE, cleanupAndClose) + } else { + closeAction() // 最终调用 onClose + } + } + }) + } + // ... +} +``` + +### 2. EngineSocket.setTransport() + +```kotlin +private fun setTransport(transport: Transport) { + // 清理旧 transport 的监听器 + for (sub in subs) { sub.destroy() } + subs.clear() + + this.transport = transport + + // 为新 transport 注册监听器 + subs.add(On.on(transport, Transport.EVENT_DRAIN, object : Listener { + override fun call(vararg args: Any) { + if (args.isNotEmpty() && args[0] is Int) { + onDrain(args[0] as Int) // 可能接收到来自其他 transport 的事件 + } + } + })) + // ... +} +``` + +### 3. WebSocket.doSend() + +```kotlin +override fun doSend(packets: List>) { + writable = false + + ioScope.launch { + for (pkt in packets) { + if (state != State.OPEN) { break } // 检查状态，但可能已过时 + // ... 发送 + } + + scope.launch { + emit(EVENT_DRAIN, packets.size) // 异步触发，可能在 setTransport 之后 + } + } +} +``` + +--- + +## 总结 + +这是一个**竞态条件 (Race Condition)** 导致的偶现问题： + +1. **触发条件**： + - Socket 在 websocket probe 进行中时关闭 + - WebSocket probe 在 socket 关闭后才完成 + - Upgrade 流程在 close 等待期间完成 + +2. **根本原因**： + - `onDrain` 方法假设 `writeBuffer` 中的元素数量与 `len` 参数匹配 + - 但 transport 切换期间，异步事件可能导致 `onDrain` 被调用时 `writeBuffer` 已被清空 + - `setTransport` 为新 transport 注册监听器，但可能接收到来自旧 transport 的异步事件 + +3. **为何是偶现**： + - 取决于 websocket probe 完成和 socket 关闭的时序 + - 如果 probe 在关闭前被中断，不会触发问题 + - 如果 probe 在关闭后完成，就会触发异常 + +4. **问题本质**： + - Transport 生命周期管理和事件处理的竞态条件 + - 异步事件（`EVENT_DRAIN`）与同步状态（`writeBuffer`）不同步 + +============================================================================== +追问： +但是在 EngineSocket.kt 的 probe 函数里， +transport.once(EVENT_DRAIN, object : Listener { + override fun call(vararg args: Any) { + Logging.info(TAG, "upgrade packet send success") + emit(EVENT_UPGRADE, transport) + setTransport(transport) + cleaned = true + upgrading = false + flush() + } +}) +transport.send(listOf(EngineIOPacket.Upgrade))setTransport 应该是在 Upgrade 包对应的 EVENT_DRAIN 事件真的收到之后，才会执行的啊，也不用管 WebSocket.doSend 和 EVENT_DRAIN 触发是否异步，这个先后顺序是保证了的啊，为什么 EVENT_DRAIN 来了之后，还有 EVENT_DRAIN 呢？ +============================================================================== +它提到 emit 的实现有可能问题：如果 EventEmitter 的实现是在 emit 过程中实时遍历监听器列表（而不是事先复制） +============================================================================== +进一步追问：你能看看 emit 的实现方式是哪种吗？ +============================================================================== +然后它就开始不停猜测、推翻、再猜测，最终给出了正确的分析结果 +============================================================================== + +好的，让我重新仔细分析 err.log 和 WebSocket.kt 的实现。 +我现在明白了！关键线索在日志的最后部分：0705ms: Transport websocket@260110639 doSend 1 packets finish ← Upgrade 发送完成 +0705ms: EngineSocket upgrade packet send success ← 触发 setTransport +0705ms: EngineSocket setTransport websocket ← 注册新监听器 + +... + +0712ms: Transport websocket@260110639 doSend 1 packets finish ← Ping 发送完成！ +0712ms: EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1 ← 崩溃！问题根源：两次 doSend 调用产生了两个独立的 EVENT_DRAIN 事件！ +完整时序分析0698ms: websocket 打开，probe 开始 + ├─ transport.send(listOf(ping)) → 启动第一次 doSend (Ping) + │ └─ ioScope.launch { 发送 Ping... } → 在后台线程执行 + │ +0702ms: 收到 Pong 响应 + ├─ transport.send(listOf(Upgrade)) → 启动第二次 doSend (Upgrade) + │ └─ ioScope.launch { 发送 Upgrade... } → 在后台线程执行 + │ +0705ms: Upgrade 发送完成（先完成！） + ├─ emit(EVENT_DRAIN, 1) → 触发 probe 的 once 监听器 + ├─ setTransport(websocket) → 为 websocket 注册 onDrain 监听器 + │ +0712ms: Ping 发送完成（后完成！） + └─ emit(EVENT_DRAIN, 1) → 触发 setTransport 中注册的监听器 + └─ onDrain(1) → writeBuffer 已空，崩溃！根本原因 +probe 中发送了两个包：先 Ping，收到 Pong 后再 Upgrade +两次 doSend 是异步的：都在 ioScope.launch 中执行 +完成顺序不确定：虽然 Ping 先发送，但 Upgrade 可能先完成（网络/调度原因） +**两个独立的 emit**：setTransport 在第一个 emit 中执行，但第二个 emit 触发时新监听器已存在 +所以你的原始分析是正确的——这是一个竞态条件问题！ +修复建议在 onDrain 中添加防御性检查： +private fun onDrain(len: Int) { + if (writeBuffer.size < len) { + Logging.error(TAG, "onDrain: buffer underflow, writeBuffer.size ${writeBuffer.size}, len $len") + return // 或抛出更有意义的异常 + } + for (i in 1..len) { + writeBuffer.removeAt(0) + } + // ... +} + +或者在 setTransport 中记录当前 transport，在 onDrain 中检查事件来源是否匹配当前的 transport。 +这是一个经典的异步竞态问题：两次异步操作，先开始的反而后完成，导致事件处理器的状态不一致。 diff --git a/docs/ut-case-analysis/opencode-kimi-result-bad.md b/docs/ut-case-analysis/opencode-kimi-result-bad.md new file mode 100644 index 0000000..a7d1f2f --- /dev/null +++ b/docs/ut-case-analysis/opencode-kimi-result-bad.md @@ -0,0 +1,110 @@ +KMP-SocketIO 偶现 UT 失败分析报告 +1. 测试用例说明 +测试: reconnectManually (ConnectionTest.java:354-380) +执行流程: +1. 首次 socket.open() 建立连接 +2. 首次连接成功后 socket.close() 关闭 +3. 收到 EVENT_DISCONNECT 后再次 socket.open() 重新连接 +4. 第二次连接成功后关闭并结束 +2. Transport 实例日志格式 +源自 Transport.kt (line 153-165): +protected fun logI(log: String) { + Logging.info(TAG, "$name@${hashCode()} $log") +} +- @ 后面的数字是对象的 hashCode() +- 用于区分不同 Transport 实例 +- 例如: polling@1929439163 vs polling@709407350 是两个不同的实例 +3. Transport 状态机 +enum class State { INIT, OPENING, OPEN, CLOSING, CLOSED, PAUSED } +状态转换: + +| 操作 | 从状态 | 到状态 | 触发条件 | +|------|--------|--------|----------| +| open() | INIT/CLOSED | OPENING | 初始化连接 | +| onOpen() | OPENING | OPEN | 握手成功 | +| close() | OPENING/OPEN | CLOSING | 主动关闭 | +| onClose() | any | CLOSED | 关闭完成 | +| pause() | OPEN | PAUSED | 升级过程中暂停 | + +4. 关键差异对比 +good.log（正常执行） + +| Transport 实例 | 生命周期 | 关键事件 | +|---------------|----------|----------| +| polling@709407350 | OPEN → CLOSING → Closed | 首次连接 | +| websocket@2087361714 | OPEN → Closed | 探测未完成的 WebSocket | +| polling@969147974 | OPEN → Closed | 第二次连接 | + +特点: 首次连接在 WebSocket 升级完成前就关闭了，没有进入 upgrade 流程 + +err.log（失败执行） + +| Transport 实例 | 生命周期 | 关键事件 | +|---------------|----------|----------| +| polling@1929439163 | OPEN → PAUSED → Closed | 首次连接（关键：进入 PAUSED 状态）| +| websocket@260110639 | OPEN → send upgrade → CRASH | 探测成功，但升级时崩溃 | + +特点: WebSocket 探测成功收到 PONG，polling 进入 PAUSED 状态，发送 upgrade 包后崩溃 +5. 崩溃根因分析 +崩溃堆栈: +java.util.NoSuchElementException: ArrayDeque is empty + at com.piasy.kmp.socketio.engineio.EngineSocket.onDrain(EngineSocket.kt:280) +崩溃代码位置 (EngineSocket.kt:277-290): +private fun onDrain(len: Int) { + Logging.debug(TAG) { "onDrain: prevBufferLen $prevBufferLen, writeBuffer.size ${writeBuffer.size}, len $len" } + for (i in 1..len) { + writeBuffer.removeAt(0) // <-- 崩溃点 + } + prevBufferLen -= len + ... +} +触发时序 (err.log 时间戳 1769931180705 附近): +1769931180702 I EngineSocket probe transport websocket pong <- 探测成功 +1769931180702 I EngineSocket pausing current transport polling <- 开始暂停 +1769931180703 I Transport polling@1929439163 paused <- polling 已暂停 +1769931180705 I EngineSocket changing transport and sending upgrade packet +1769931180705 D Transport websocket@260110639 send: state OPEN, 1 packets +1769931180705 D Transport websocket@260110639 doSend 1 packets start +1769931180705 D Transport websocket@260110639 doSend: Upgrade, `5` +1769931180705 I EngineSocket upgrade packet send success +1769931180705 I EngineSocket close waiting upgrade success +1769931180705 I EngineSocket socket closing - telling transport to close +1769931180705 I EngineSocket onClose force close +1769931180705 I Transport polling@1929439163 close, state PAUSED +1769931180705 I EngineSocket setTransport websocket <- 切换 transport +... +1769931180712 D EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1 <- 问题！ +问题分析: +1. onDrain(len=1) 被调用，期望从 writeBuffer 移除 1 个元素 +2. 但此时 writeBuffer.size=0 且 prevBufferLen=0 +3. 尝试从空 ArrayDeque 移除元素导致崩溃 +并发竞态条件: +WebSocket.doSend 在 ioScope（IO 线程）执行： +ioScope.launch { + // 发送数据... + scope.launch { + writable = true + emit(EVENT_DRAIN, packets.size) // 跨线程回调 + } +} +当以下情况同时发生时： +- WebSocket 正在发送 upgrade 包 +- EngineSocket 被关闭 (setTransport 被调用) +- writeBuffer 被清空 +onDrain 收到 drain 事件时 buffer 已被清空，导致崩溃。 +6. 正常与失败的本质区别 + +| 条件 | good.log | err.log | +|------|----------|---------| +| WebSocket 探测 | 未完成（无 PONG） | 成功完成（有 PONG） | +| polling 状态 | 未进入 PAUSED | 进入 PAUSED 状态 | +| 升级流程 | 未触发 | 触发但崩溃 | +| 关闭时机 | 探测完成前 | 探测完成后 | + +根本差异: 时序差异导致一个走了 upgrade 路径（失败），一个没走（成功）。 +7. 结论 +这是一个并发时序竞态问题： +- 触发条件: 在 WebSocket 升级过程中（从 polling 切换到 websocket 时），如果发生 socket 关闭 +- 崩溃原因: onDrain 回调尝试从已被清空的 writeBuffer 移除元素 +- 偶现原因: 依赖于 IO 线程与工作线程的执行时序，只在特定时间窗口内触发 +不涉及修复，仅做分析。 \ No newline at end of file diff --git a/docs/ut-case-analysis/trae-gpt-5.2-codex-result-bad.md b/docs/ut-case-analysis/trae-gpt-5.2-codex-result-bad.md new file mode 100644 index 0000000..e39e357 --- /dev/null +++ b/docs/ut-case-analysis/trae-gpt-5.2-codex-result-bad.md @@ -0,0 +1,129 @@ +**结论总览** +- 两份日志的核心差异出现在“首次连接后立即断开 → 立刻手动重连”阶段：good.log 中没有发生 transport upgrade 成功切换；err.log 中 upgrade 成功切换触发了 WebSocket 的 drain 回调，随后 EngineSocket.onDrain 发生队列越界异常，测试挂死超时。 +- 失败路径里出现“Transport polling@1929439163 pause → paused → EngineSocket changing transport and sending upgrade packet → Transport websocket@260110639 doSend 1 packets finish → EngineSocket onDrain… → NoSuchElementException”，这是导致用例挂起的直接原因。 +- 通过代码可确认：Transport 的日志均由 Transport.logI/logD/logE 打印，hash 即实例 hashCode（见 [Transport.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/Transport.kt#L153-L165)）；PollingXHR 和 WebSocket 各自的生命周期日志由其 doOpen/doSend/doClose/poll/onPollComplete/pause 等调用链触发（见 [PollingXHR.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/PollingXHR.kt#L62-L218)、[WebSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L35-L183)）。 + +**用例意图与关键流程** +- 用例是 ConnectionTest.reconnectManually：第一次 connect 后立刻 close；收到 disconnect 后再 open，第二次 connect 后再 close 并完成队列通知（见 [ConnectionTest.java](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/jvmTest/java/io/socket/client/ConnectionTest.java#L353-L380)）。 +- EngineSocket.open 会先创建 polling transport 并 open，收到 Open 包后进入 OPEN，然后触发 upgrade probe（如果可升级）（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L356-L404)）。 +- probe 成功后：暂停当前 polling → 发送 Upgrade 包 → drain 回来后 setTransport(websocket) 并 flush（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L411-L523)）。 + +**good.log 关键时序梳理（Transport 实例级别）** +- 初次连接（polling@709407350） + - open → poll start → doRequest GET → onPollComplete(Open) → onOpen → send(Connect) → poll start → doRequest GET/POST。 + - 触发 upgrade probe：创建 websocket@2087361714，但在 close 过程中被关闭，出现 “probe transport websocket, but socket closed”。 + - Socket 在收到 Connect 后立即 close，EngineSocket close 导致 polling@709407350 close，状态进入 CLOSING，并发送 Close 包（见 “doClose writing close packet”）。 +- 第二次连接（polling@969147974） + - new EngineSocket open → polling@969147974 open → onPollComplete(Open) → send Connect → probe websocket@590078241。 + - close 触发后 polling@969147974 close；随后服务端停止导致 Connection reset/Connection refused 报错，但发生在用例已经完成之后（good.log 末尾）。 + +**err.log 关键时序梳理（Transport 实例级别）** +- 初次连接（polling@1929439163） + - open → onPollComplete(Open) → send Connect → poll start。 + - Socket 在 connect 后立即 close，触发 send Disconnect，然后 EngineSocket close 等待 drain。 +- upgrade 探测成功并切换（websocket@260110639） + - probe 期间收到 Pong probe（websocket@260110639 onPacket Pong），进入 pause：polling@1929439163 pause → wait polling/writing → onPollComplete(state=PAUSED, Event message) → paused。 + - 然后 “changing transport and sending upgrade packet”，websocket@260110639 doSend Upgrade 包，doSend finish 触发 drain。 +- 失败触发点 + - drain 事件调用 EngineSocket.onDrain，日志显示 “EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1”，随后 ArrayDeque.removeFirst 异常（见 err.log 409-413）。 + - 这对应 [EngineSocket.onDrain](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L290) 中 `for (i in 1..len) writeBuffer.removeAt(0)`：len=1 但 buffer 空。 +- 之后用例等待 `values.take()` 超时（err.log 479-488），表现为超时失败。 + +**Transport 日志与代码对应关系** +- `Transport polling@... open`：Transport.open() → logD("open")（见 [Transport.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/Transport.kt#L51-L58)）。 +- `poll start / onPollComplete / doRequest ...`：PollingXHR.poll / onPollComplete / doRequest（见 [PollingXHR.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/PollingXHR.kt#L67-L173)）。 +- `send: state OPEN, 1 packets`：Transport.send → logD（见 [Transport.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/Transport.kt#L61-L68)）。 +- `pause / pause: wait polling / pause: wait writing / paused`：PollingXHR.pause（见 [PollingXHR.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/PollingXHR.kt#L25-L59)）。 +- `doSend ... finish`（WebSocket）：WebSocket.doSend 发包后 emit(EVENT_DRAIN)（见 [WebSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L133-L173)）。 +- `EngineSocket onDrain ...`：EngineSocket.onDrain 删除 writeBuffer 头部数据（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L290)）。 + +**完整执行过程对比与状态变化** +- good.log：第一次连接在 upgrade 还未完成时即 close；probe 中 websocket 触发“socket closed”被关闭，polling 进入 close 流程后结束。第二次连接走一遍类似流程，事件顺序完整，无异常。 +- err.log：第一次连接 close 过程中，upgrade probe 刚好成功进入“pause → upgrade packet send → setTransport”链路，导致 websocket 的 drain 回调在 writeBuffer 为空时触发，抛异常后逻辑中断，导致 reconnectManually 没有走到第二次 connect 的 close + values.offer，最终超时。 + +**可以确定的关键差异点** +- good.log 没有出现 `pause/paused/upgrade packet send success`，说明 upgrade 没成功完成；err.log 完整出现这些日志，说明 upgrade 成功路径与 close 并发交错。 +- err.log 中 `EngineSocket close waiting drain success` 与 `EngineSocket close waiting upgrade` 同时出现，说明 close 正在等待 drain/upgrade，而 upgrade 已触发 websocket drain，这直接命中了 onDrain 的空队列路径。 + +如果你需要，我可以进一步把 good/err 两条日志中每个 transport 实例（polling@709..., websocket@208..., polling@969..., websocket@590... vs polling@192..., websocket@260..., polling@212..., websocket@897...)的完整事件序列按时间线整理成表格，便于定位每个实例的状态迁移轨迹。 + +============================================================================== + +问题的根因是什么呢？ + +============================================================================== + +根因是：**EngineSocket 的发送队列(writeBuffer)与 drain 回调(len)之间的状态/并发一致性被破坏，导致 onDrain 在队列为空时仍按 len=1 去弹出元素，抛出 NoSuchElementException，进而让协程异常中断、用例卡死超时**。 + +把 err.log 里的关键链路严格串起来就是： + +- WebSocket upgrade 成功路径触发：`probe transport websocket pong` → `pausing current transport polling` → `polling pause ... paused` → `changing transport and sending upgrade packet` → `Transport websocket@260110639 doSend ... Upgrade, 5`。 +- WebSocket.doSend 在发送完成后会 `emit(EVENT_DRAIN, packets.size)`，这里 `packets.size == 1`（见 [WebSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L133-L173)）。 +- EngineSocket 订阅 transport 的 drain 事件后会调用 `onDrain(len)`（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L227-L274)），而 onDrain 会执行： + + - `for (i in 1..len) writeBuffer.removeAt(0)`（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L290)） + +- err.log 在崩溃前打印了：`EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1`，这意味着 **EngineSocket 当时并没有任何待发送包(writeBuffer 空、prevBufferLen=0)**，但 drain 回调却告诉它“已 drain 了 1 个包”，于是 removeFirst 直接炸掉（异常栈也指向 EngineSocket.kt:280）。 + +为什么这会“偶现”： +- 只有在一个很窄的竞态窗口里才会发生：**测试用例第一次 connect 后立刻 close**，同时 **upgrade probe 恰好完成并发送 Upgrade 包**。good.log 里 upgrade 没跑完（或被 close 打断），所以不会走到 websocket drain → EngineSocket.onDrain 的这条路径；err.log 里 upgrade 恰好跑完并发出了 drain，于是触发了这个一致性问题。 + +一句话归因：**EngineSocket 把“transport drain 事件”当成了“自己 writeBuffer 的 drain”，但在 upgrade/close 交错时，transport 可能 drain 的是并不来自 writeBuffer 的包（Upgrade probe 包），从而导致 onDrain 对空队列执行 remove。** + +============================================================================== + +但在 `/Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L444-453` 这里，我是等到了 websocket 发送 upgrade 包的 drain 事件了才会 setTransport 啊，那 upgrade 包的 drain 事件就不应该影响到 EngineSocket 啊 + +============================================================================== + +你说得对：**L444 那个 once(EVENT_DRAIN)** 只是“升级包发送完成后再 setTransport”的保护，它本身不该直接影响 EngineSocket 的写队列。问题出在**另一个 drain 事件**上，而且日志已经明确指出是 **setTransport 里注册的 drain 回调**触发了异常。 + +**关键点** +- 异常栈显示触发点是 `EngineSocket$setTransport$1.call`（也就是 setTransport 里绑定的 drain 监听）： + [EngineSocket.kt:L243-L249](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L243-L249) +- err.log 中 **setTransport 已经发生在 07:33:00.900387**，而真正触发崩溃的 drain 是 **07:33:00.903518** 之后的那个： + - `D Transport websocket@260110639 doSend 1 packets finish` + - `D EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1` + - 随后抛出 ArrayDeque is empty + 这说明 **触发 onDrain 的 drain 事件发生在 setTransport 之后**。 + +**为什么会这样** +- WebSocket 的 `doSend` 结束时会 `emit(EVENT_DRAIN, packets.size)`，无论这个 send 是否来自 EngineSocket 的 writeBuffer。 + [WebSocket.kt:L169-L173](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L169-L173) +- 一旦 `setTransport(transport)` 执行，就把 **transport 的 drain** 绑定到 `EngineSocket.onDrain`。 + [EngineSocket.kt:L243-L247](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L243-L247) +- `EngineSocket.onDrain` 假设 drain 的 len 对应 **writeBuffer**，直接 `removeAt(0)`： + [EngineSocket.kt:L276-L281](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L281) +- 但在这个偶发路径里，**writeBuffer 已经为空**（日志里 `prevBufferLen 0, writeBuffer.size 0`），而 transport 仍然发出了 drain(len=1)，于是下溢。 + +**这与你说的 L444 的关系** +- L444 的 once(EVENT_DRAIN) **只保证 upgrade 包发送成功后才 setTransport**，没问题。 +- 但 **setTransport 后**，该 transport 的任何 drain 都会进入 EngineSocket.onDrain，这已经不是“升级包的 drain 事件”了，而是 **transport 的 drain 事件被“误认为”是 writeBuffer 的 drain**。 + +**一句话总结** +- 根因不是 L444 的等待机制，而是：**setTransport 后，WebSocket transport 发出的 drain 事件并不一定对应 EngineSocket.writeBuffer，却仍被 onDrain 当作 writeBuffer drain 处理**，在 close + upgrade 并发窗口里触发空队列 remove。 + +============================================================================== + +可是我的预期是只有 Upgrade 包对应的 drain 监听到之后，才会 setTransport 啊，而这之后预期就不会有 drain 事件里啊，因为没有任何发包的记录了啊 + +============================================================================== + +你这个预期在“同步逻辑”层面是合理的，但 **日志和源码证明 drain 事件是异步投递的**，所以会在 setTransport 之后才到达，即使它对应的是 **刚才那个 Upgrade 包**。 + +**为什么 setTransport 后仍会收到 drain** +- WebSocket 的发送是异步的：`doSend` 里用 `ioScope.launch` 发送，然后再 `scope.launch { emit(EVENT_DRAIN, packets.size) }`（见 [WebSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L133-L173)）。 + 这意味着 **Upgrade 包的 drain 可能晚于 setTransport 发生**。 +- 日志时间线刚好说明了这一点： + - `07:33:00.899180 doSend: Upgrade, 5` + - `07:33:00.900387 EngineSocket setTransport websocket` + - `07:33:00.903518 Transport websocket@260110639 doSend 1 packets finish` + - `07:33:00.903570 EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1` +- 所以 **这个 drain 就是 Upgrade 包的 drain，只是它在 setTransport 之后到达**。并不是“没有任何发包记录”，日志里确实有 `doSend 1 packets finish`。 + +**为什么它会影响 EngineSocket** +- 一旦 `setTransport` 执行，EngineSocket 就订阅了 transport 的 drain，并把它直接映射到 `EngineSocket.onDrain`（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L243-L247)）。 +- 但 EngineSocket.onDrain 默认认为 drain 一定对应 writeBuffer（见 [EngineSocket.kt](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L281)），而这次 drain 实际是 **upgrade 包**，不是 writeBuffer 中的包，导致空队列被弹出。 + +**一句话总结** +- 你的预期在“事件因果”上没错，但 **事件的投递时序是异步的**：Upgrade 包的 drain 发生在 setTransport 之后到达，于是被 EngineSocket 当成 writeBuffer drain 处理，触发了异常。 diff --git a/docs/ut-case-analysis/trae-kimi-result-bad.md b/docs/ut-case-analysis/trae-kimi-result-bad.md new file mode 100644 index 0000000..81188f8 --- /dev/null +++ b/docs/ut-case-analysis/trae-kimi-result-bad.md @@ -0,0 +1,300 @@ +## 详细分析报告：kmp-socketio 偶现 UT 失败问题 + +### 测试用例概述 + +测试用例 `reconnectManually` 的逻辑是： +1. 创建 socket 连接 +2. 第一次连接成功后立即关闭 (`socket.close()`) +3. 在 `EVENT_DISCONNECT` 回调中重新打开连接 (`socket.open()`) +4. 第二次连接成功后关闭并结束测试 + +--- + +### 一、Good Log 分析（成功场景） + +在 good.log 中，有两个主要的连接生命周期： + +#### 第一次连接生命周期 + +| 时间 | Transport 实例 | 事件 | 说明 | +|------|---------------|------|------| +| 1769932185432 | polling@709407350 | open | 创建第一个 polling transport | +| 1769932185432 | polling@709407350 | poll start | 开始轮询 | +| 1769932185456 | polling@709407350 | onOpen | 收到 Open packet，状态变为 OPEN | +| 1769932185460 | websocket@2087361714 | open | 创建 probing websocket | +| 1769932185480 | polling@709407350 | send | 发送 Disconnect packet | +| 1769932185480 | Manager | destroy/close/cleanUp | 开始关闭流程 | +| 1769932185490 | EngineSocket | close waiting drain | 等待 drain 事件 | +| 1769932185490 | polling@709407350 | close | 关闭 polling transport | +| 1769932185490 | websocket@2087361714 | close | 关闭 probing websocket（probe 失败）| + +**关键点**：在第一次连接关闭时，websocket probe 正在进行中，但 socket 关闭导致 probe 失败。 + +#### 第二次连接生命周期 + +| 时间 | Transport 实例 | 事件 | 说明 | +|------|---------------|------|------| +| 1769932185483 | polling@969147974 | open | 创建新的 polling transport（不同 hash）| +| 1769932185500 | polling@969147974 | onOpen | 连接成功 | +| 1769932185500 | websocket@590078241 | open | 创建新的 probing websocket | +| 1769932185516 | polling@969147974 | send | 发送 Disconnect | +| 1769932185516 | Manager | destroy/close | 关闭 | +| 1769932185520 | TestConnection | Stopping server | 测试结束 | + +**Good log 的关键特征**： +- 两次连接使用了完全不同的 transport 实例（不同的 hash 值） +- 第一次关闭时，websocket probe 被中断，但没有触发 transport 切换 +- 第二次连接是全新的 EngineSocket 实例 + + +toolName: todo_write + +status: success + +Todos updated: 5 items + +### 二、Error Log 分析（失败场景） + +#### 第一次连接生命周期 + +| 时间 | Transport 实例 | 事件 | 说明 | +|------|---------------|------|------| +| 1769931180665 | polling@1929439163 | open | 创建第一个 polling transport | +| 1769931180680 | polling@1929439163 | onOpen | 连接成功 | +| 1769931180681 | websocket@260110639 | open | 创建 probing websocket | +| 1769931180694 | polling@1929439163 | send | 发送 Disconnect packet | +| 1769931180694 | Manager | destroy/close/cleanUp | 开始关闭流程 | +| 1769931180694 | EngineSocket | close waiting drain | 等待 drain 事件 | + +#### 关键差异点 - 时序问题 + +在 err.log 中，**在第一次连接关闭期间，websocket probe 成功了**： + +``` +1769931180698 I Transport websocket@260110639 onOpen, state OPENING +1769931180698 I EngineSocket probe transport websocket opened, failed: false +1769931180698 D Transport websocket@260110639 send: state OPEN, 1 packets +1769931180698 D Transport websocket@260110639 doSend: Ping(payload=probe), `2probe` +1769931180702 D Transport websocket@260110639 onWsText: `3probe` +1769931180702 D Transport websocket@260110639 onPacket Pong(payload=probe) +1769931180702 I EngineSocket probe transport websocket pong +1769931180702 I EngineSocket pausing current transport polling +1769931180702 I Transport polling@1929439163 pause +``` + +**这是关键差异**：在失败场景中，websocket probe 在 socket 关闭流程中成功了，触发了 transport 升级流程。 + +#### Transport 升级流程（在关闭过程中！） + +``` +1769931180702 I EngineSocket pausing current transport polling +1769931180702 I Transport polling@1929439163 pause: wait polling +1769931180702 I Transport polling@1929439163 pause: wait writing +1769931180703 D Transport polling@1929439163 onPollComplete: state PAUSED +1769931180703 I Transport polling@1929439163 pause: pre-pause polling complete +1769931180705 I Transport polling@1929439163 pause: pre-pause writing complete +1769931180705 I Transport polling@1929439163 paused +1769931180705 I EngineSocket changing transport and sending upgrade packet +1769931180705 D Transport websocket@260110639 send: state OPEN, 1 packets <-- 发送 upgrade packet +1769931180705 D Transport websocket@260110639 doSend: Upgrade, `5` +1769931180705 I EngineSocket upgrade packet send success +1769931180705 I EngineSocket close waiting upgrade success +1769931180705 I EngineSocket socket closing - telling transport to close +1769931180705 I EngineSocket onClose force close +1769931180705 I Transport polling@1929439163 close, state PAUSED <-- 关闭旧 transport +1769931180705 I EngineSocket setTransport websocket <-- 切换到新 transport +``` + +#### 第二次连接开始（在第一次的升级过程中！） + +``` +1769931180695 I Socket open: connected false, io reconnecting false +1769931180695 I EngineSocket createTransport polling +1769931180695 I EngineSocket setTransport polling +1769931180695 D Transport polling@2125549749 open <-- 新的 polling transport！ +``` + +**关键问题**：第二次连接在第一次连接的升级/关闭过程中开始了！ + +#### 异常发生 + +``` +1769931180705 I EngineSocket setTransport websocket +1769931180705 I EngineSocket clearing existing transport polling +1769931180705 D EngineSocket flush: state CLOSED, writable true, upgrading false, prevBufferLen 0, writeBuffer.size 0 +1769931180705 I EngineSocket flush ignored: state CLOSED, transport.writable true, upgrading false, writeBuffer.size 0, prevBufferLen 0 +1769931180709 D Transport polling@2125549749 doRequest GET ... response: 200 OK <-- 第二个连接的 polling 收到响应 +... +1769931180712 D Transport websocket@260110639 doSend 1 packets finish <-- 第一个连接的 websocket 发送完成 +1769931180712 D EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1 <-- onDrain 被调用！ +``` + +**异常栈**： +``` +Exception in thread "DefaultDispatcher-worker-10 @coroutine#1018" java.util.NoSuchElementException: ArrayDeque is empty. + at kotlin.collections.ArrayDeque.removeFirst(ArrayDeque.kt:146) + at com.piasy.kmp.socketio.engineio.EngineSocket.onDrain(EngineSocket.kt:280) +``` + + +toolName: todo_write + +status: success + +Todos updated: 5 items + +### 三、关键差异对比 + +| 维度 | Good Log（成功） | Err Log（失败） | +|------|-----------------|-----------------| +| **第一次连接关闭时** | websocket probe 被中断，未成功 | websocket probe 成功，触发升级流程 | +| **Transport 切换时机** | 无切换（probe 失败） | 在关闭过程中发生切换 | +| **第二次连接启动时机** | 第一次完全关闭后 | 第一次关闭/升级过程中 | +| **并发情况** | 无并发问题 | 两个 EngineSocket 实例并发操作 | +| **writeBuffer 状态** | 正常 | 被错误地操作（空队列 remove）| + +### 四、onDrain 异常根本原因分析 + +查看代码 [EngineSocket.kt:276-290](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L290)： + +```kotlin +@WorkThread +private fun onDrain(len: Int) { + Logging.debug(TAG) { "onDrain: prevBufferLen $prevBufferLen, writeBuffer.size ${writeBuffer.size}, len $len" } + for (i in 1..len) { + writeBuffer.removeAt(0) // 第280行，抛出异常 + } + prevBufferLen -= len + // ... +} +``` + +异常发生时的状态（从日志推断）： + +``` +EngineSocket onDrain: prevBufferLen 0, writeBuffer.size 0, len 1 +``` + +**问题分析**： + +1. **writeBuffer 是 ArrayDeque**，在 [EngineSocket.kt:54](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L54) 定义： + ```kotlin + internal val writeBuffer = ArrayDeque>() + ``` + +2. **事件监听器注册问题**： + - 在 `setTransport` 方法中，为 transport 注册了 `EVENT_DRAIN` 监听器 + - 监听器通过 `On.on(transport, Transport.EVENT_DRAIN, ...)` 注册 + +3. **并发/时序问题**： + - 第一个 EngineSocket（transport: websocket@260110639）在发送 upgrade packet 后，等待 drain 事件 + - 第二个 EngineSocket（transport: polling@2125549749）被创建，有自己的 writeBuffer + - **关键**：第一个 EngineSocket 的 websocket transport 完成发送后，触发了 drain 事件 + - 但此时第一个 EngineSocket 的 writeBuffer 已经被清空（因为在关闭流程中） + +4. **为什么 len=1 但 writeBuffer 为空？** + + 看 [WebSocket.doSend](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L140-L172)： + ```kotlin + override fun doSend(packets: List>) { + logD { "doSend ${packets.size} packets start" } + writable = false + ioScope.launch { + // ... 发送逻辑 ... + scope.launch { + logD { "doSend ${packets.size} packets finish" } + writable = true + emit(EVENT_DRAIN, packets.size) // 发送完成后触发 drain + } + } + } + ``` + + websocket 在发送完成时会触发 `EVENT_DRAIN` 事件，并传递 `packets.size` 作为参数。 + +5. **问题根源**： + - 在 probe 成功后的升级流程中，第一个 EngineSocket 发送了 upgrade packet（1个 packet） + - 但在 drain 事件触发前，socket 进入了关闭流程，`writeBuffer` 被清空 + - 当 drain 事件最终触发时，`len=1`（发送时的 packet 数量），但 `writeBuffer` 已经被清空 + + +toolName: todo_write + +status: success + +Todos updated: 5 items + +### 五、问题根因总结 + +#### 核心问题 + +这是一个**竞态条件（Race Condition）**问题，发生在以下场景： + +1. **触发条件**：第一次连接关闭时，websocket probe 恰好成功 +2. **升级流程启动**：`probe` 方法中的 `onTransportOpen` 回调被触发，开始 transport 升级 +3. **关闭流程与升级流程并发**： + - 关闭流程：调用 `close()` → `closeAction()` → 清空 writeBuffer + - 升级流程：发送 upgrade packet → 等待 drain 事件 → 切换 transport +4. **时序问题**：upgrade packet 发送完成（触发 drain 事件）发生在 writeBuffer 被清空之后 + +#### 详细时序 + +``` +时间点 T1: socket.close() 被调用 + ↓ +时间点 T2: EngineSocket.close() 开始 + - 状态变为 CLOSING + - 如果 writeBuffer 不为空，等待 drain 事件 + ↓ +时间点 T3: websocket probe 成功（在另一个协程中） + - 触发 onTransportOpen + - 调用 currentTransport.pause() + ↓ +时间点 T4: pause 完成，发送 upgrade packet + - transport.send(listOf(EngineIOPacket.Upgrade)) + - prevBufferLen = writeBuffer.size (可能是 0 或 1) + ↓ +时间点 T5: close 流程继续 + - writeBuffer 被清空（通过 onDrain 或直接清空） + ↓ +时间点 T6: upgrade packet 发送完成 + - WebSocket.doSend 中的 ioScope.launch 完成 + - 触发 EVENT_DRAIN，len=1 + ↓ +时间点 T7: onDrain(1) 被调用 + - prevBufferLen = 0, writeBuffer.size = 0 + - 尝试 writeBuffer.removeAt(0) → 抛出 NoSuchElementException +``` + +#### 为什么这是偶现的 + +这个 bug 是**时序敏感的**： + +- 如果 websocket probe 在 `socket.close()` 调用前完成 → 正常升级，无问题 +- 如果 websocket probe 在 `socket.close()` 调用后、但 `pause` 前完成 → 触发此 bug +- 如果 websocket probe 在 `pause` 完成后才收到 pong → probe 失败，无问题（如 good.log） + +#### 涉及的关键代码位置 + +1. **[EngineSocket.probe](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L401-L522)** - probe 逻辑 +2. **[EngineSocket.close](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L147-L197)** - 关闭逻辑 +3. **[EngineSocket.onDrain](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L276-L290)** - drain 事件处理 +4. **[EngineSocket.setTransport](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt#L227-L274)** - transport 切换 +5. **[WebSocket.doSend](file:///Users/linker/Downloads/personal/kmp-socketio-ut-case/kmp-socketio/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt#L140-L172)** - 异步发送逻辑 + + +toolName: todo_write + +status: success + +Todos updated: 5 items + +--- + +## 分析完成 + +以上是对 kmp-socketio 项目偶现 UT 失败问题的完整分析。问题的本质是： + +**在 socket 关闭流程中，如果 websocket probe 恰好在此时成功，会导致 transport 升级流程与关闭流程产生竞态条件，最终触发 `ArrayDeque.removeFirst` 异常。** + +这是一个时序敏感的并发问题，解释了为什么该 UT 是"偶现"失败的。 \ No newline at end of file diff --git a/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt b/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt index 36daca4..787ebcc 100644 --- a/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt +++ b/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/EngineSocket.kt @@ -415,8 +415,7 @@ class EngineSocket( return } - val ping = EngineIOPacket.Ping(PROBE) - transport.send(listOf(ping)) + transport.send(listOf(EngineIOPacket.Ping(PROBE))) transport.once(Transport.EVENT_PACKET, object : Listener { override fun call(vararg args: Any) { if (failed) { diff --git a/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt b/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt index c73aa2f..340d988 100644 --- a/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt +++ b/kmp-socketio/src/commonMain/kotlin/com/piasy/kmp/socketio/engineio/transports/WebSocket.kt @@ -1,5 +1,6 @@ package com.piasy.kmp.socketio.engineio.transports +import com.piasy.kmp.socketio.engineio.EngineSocket import com.piasy.kmp.socketio.engineio.IoThread import com.piasy.kmp.socketio.engineio.State import com.piasy.kmp.socketio.engineio.Transport @@ -136,6 +137,11 @@ open class WebSocket( logD { "doSend ${packets.size} packets start" } writable = false + // Check if this is a probe ping - if so, skip drain event to avoid race condition + val isProbePing = packets.size == 1 + && packets[0] is EngineIOPacket.Ping + && (packets[0] as EngineIOPacket.Ping).payload == EngineSocket.PROBE + ioScope.launch { for (pkt in packets) { if (state != State.OPEN) { @@ -169,7 +175,11 @@ open class WebSocket( scope.launch { logD { "doSend ${packets.size} packets finish" } writable = true - emit(EVENT_DRAIN, packets.size) + // Skip drain event for probe ping to avoid race condition between + // probe ping drain and upgrade drain - see docs/ut-case-analysis/ + if (!isProbePing) { + emit(EVENT_DRAIN, packets.size) + } } } }