Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Support socket.io 3 + starscream 4 #1309

Merged
merged 14 commits into from
Feb 1, 2021
Merged

Support socket.io 3 + starscream 4 #1309

merged 14 commits into from
Feb 1, 2021

Conversation

nuclearace
Copy link
Member

No description provided.

@nuclearace
Copy link
Member Author

nuclearace commented Nov 7, 2020

If anyone wants to test things out. I have published 16.0.0-beta1 to CocoaPods, as well as the v16.0.0-beta1 git tag.

@nuclearace
Copy link
Member Author

Pushed 16.0.0-beta2 with support for connecting with payloads.

@nuclearace
Copy link
Member Author

@darrachequesne just so you're aware, this is coming up soon

@darrachequesne
Copy link
Member

@nuclearace like, already? That's awesome!

Please ping me if you encounter any issue with the migration.

@nuclearace
Copy link
Member Author

@darrachequesne I do have one question regarding the encoding of binary engine messages. Documentation stats that

[
  {
    "type": "message",
    "data": "€"
  },
  {
    "type": "message",
    "data": buffer <01 02 03 04>
  }
]

gets encoded to 4€\x1eb4AQIDBA== in a polling format. However from my testing/experimenting it seems that it gets encoded to 4€\x1ebAQIDBA==. i.e. socket.io 2.0 had a prefix of b4, while 3.0 has a prefix of just b. Is that accurate?

It would match the breakdown given below the string in the documentation, where it only mentions b:

4€\x1eb4AQIDBA==

with

4           => "message" packet type
€
\x1e        => record separator
b           => indicates a base64 packet
AQIDBA==    => buffer content encoded in base64

Might want to update that if so.

Also I noticed the change log mentions always use base64 when encoding a payload with binary data. That's only when dealing with polling, correct? That's what I'm seeing from testing. Just making sure I shouldn't be doing anything fancy like b64 encoding buffers in place and sending in place.

darrachequesne added a commit to socketio/engine.io-protocol that referenced this pull request Nov 9, 2020
@darrachequesne
Copy link
Member

socket.io 2.0 had a prefix of b4, while 3.0 has a prefix of just b. Is that accurate?

That's correct 👍 I've updated the protocol documentation: socketio/engine.io-protocol@567231e

That's only when dealing with polling, correct?

Yes again. In the documentation, the WebSocket transport deals with individual "packets", while the HTTP long-polling transport deals with "payloads" (concatenated packets)

@tatealive
Copy link

Hey guys, thanks for the great work on progressing this!

@darrachequesne
Copy link
Member

@nuclearace hi Erik, I hope you are fine. Is there something I can do to help on this?

For other readers, please note that since version 3.1.0, the Socket.IO server now supports v2 clients:

const io = require("socket.io")({
  allowEIO3: true // false by default
});

Which should help, until the work on the swift client is completed.

@nuclearace
Copy link
Member Author

@darrachequesne Yes I plan to get back to this this week. Apologies all.

I had several family members struck by covid after Thanksgiving continuing through Christmas. All survived with varying levels of lasting issues. This caused friction with an also busy release time at work.

The remaining work is to make this backwards compatible with v2, where the biggest hurdle will just be switching ping mechanisms. But this shouldn't be too hard.

@nuclearace
Copy link
Member Author

nuclearace commented Jan 27, 2021

@darrachequesne Unfortunately I just discovered that the swift client was not sending the EIO param during requests... so that allowEIO3 doesn't seem to work for the Swift client since the server assumes the new version if that param is missing. The good news is that the new version should be coming out today.

Edit: If they manually send the EIO through connectParams, that should work.

@nuclearace
Copy link
Member Author

@darrachequesne I'm running into some weird behavior on 3.1.0 when using allowEIO3: true. It seems that after the upgrade to WebSockets, the server is expecting the new ping system still. Any ideas what I'm doing wrong, or is there some bug here? You can see the WS request is sending both EIO and the sid

Server:

socket.io:server initializing namespace / +0ms
  socket.io:server creating engine.io instance with opts {"allowEIO3":true,"path":"/socket.io"} +1ms
  socket.io:server attaching client serving req handler +6ms
  socket.io:server initializing namespace /swift +1ms
  engine intercepting request for path "/socket.io/" +0ms
  engine handling "GET" http request "/socket.io/?transport=polling&b64=1&EIO=3" +1ms
  engine handshaking client "t_kNG95otZqkbOaoAAAA" +3ms
  engine:socket sending packet "open" ({"sid":"t_kNG95otZqkbOaoAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:polling setting request +0ms
  engine:socket flushing buffer to transport +1ms
  engine:polling writing "96:0{"sid":"t_kNG95otZqkbOaoAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}" +0ms
  engine:socket executing batch send callback +3ms
  socket.io:server incoming connection with id t_kNG95otZqkbOaoAAAA +2s
  socket.io:client connecting to namespace / +0ms
  socket.io:namespace adding socket to nsp / +0ms
  socket.io:socket socket connected - writing packet +0ms
  socket.io:socket join room t_kNG95otZqkbOaoAAAA +0ms
  socket.io:client writing packet {"type":0,"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +0ms
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
  engine:socket sending packet "message" (0) +3ms
handshake {}
undefined
  socket.io:socket join room testRoom +5ms
[Object: null prototype] { transport: 'polling', b64: '1', EIO: '3' }
{
  host: 'localhost:8087',
  accept: '*/*',
  connection: 'keep-alive',
  testing2: 'b/:lah',
  cookie: `myCookie=!*'();:@&=+$,/?%#[]" {}`,
  'accept-language': 'en-us',
  'user-agent': 'Runner (unknown version) CFNetwork/1209.1 Darwin/20.2.0',
  'accept-encoding': 'gzip, deflate',
  testing: 'blah'
}
sid: t_kNG95otZqkbOaoAAAA
got connection
  engine intercepting request for path "/socket.io/" +22ms
  engine handling "GET" http request "/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA" +0ms
  engine setting new request for existing client +0ms
  engine:polling setting request +21ms
  engine:socket flushing buffer to transport +15ms
  engine:polling writing "2:40" +0ms
  engine:socket executing batch send callback +1ms
  engine intercepting request for path "/socket.io/" +4ms
  engine handling "POST" http request "/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA" +0ms
  engine setting new request for existing client +0ms
  engine upgrading existing transport +5ms
  engine:socket might upgrade socket transport from "polling" to "websocket" +8ms
  engine:polling received "1:2" +10ms
  engine:socket packet +1ms
  engine:socket got ping +0ms
  engine:socket sending packet "pong" (undefined) +0ms
  engine intercepting request for path "/socket.io/" +2ms
  engine handling "GET" http request "/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA" +0ms
  engine setting new request for existing client +0ms
  engine:polling setting request +1ms
  engine:socket flushing buffer to transport +1ms
  engine:polling writing "1:3" +0ms
  engine:socket executing batch send callback +0ms
  engine:ws received "2probe" +0ms
  engine:ws writing "3probe" +1ms
  engine intercepting request for path "/socket.io/" +4ms
  engine handling "GET" http request "/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA" +0ms
  engine setting new request for existing client +0ms
  engine:polling setting request +5ms
  engine:socket writing a noop packet to polling for fast upgrade +108ms
  engine:polling writing "1:6" +103ms
  engine:ws received "5" +107ms
  engine:socket got upgrade packet - upgrading +2ms
  engine:polling closing +2ms
  engine:polling transport discarded - closing right away +0ms
  engine:ws received "2" +25s
  engine:socket packet +25s
  engine:socket got ping +0ms
  engine:socket sending packet "pong" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "3" +0ms
  engine:socket writing ping packet - expecting pong within 5000ms +132ms
  engine:socket sending packet "ping" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "2" +132ms
  engine:ws closing +5s
  socket.io:client client close with reason ping timeout +30s
  socket.io:socket closing socket - reason ping timeout +30s
disc

Client:

2021-01-27 13:12:51.914 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: statusChange with data: [connecting, 2]
2021-01-27 13:12:51.914 Runner[43348:673485] LOG SocketIOClient{/}: Joining namespace /
2021-01-27 13:12:51.915 Runner[43348:673485] LOG SocketManager: Tried connecting socket when engine isn't open. Connecting
2021-01-27 13:12:51.915 Runner[43348:673485] LOG SocketManager: Adding engine
2021-01-27 13:12:51.915 Runner[43348:673493] LOG SocketEngine: Starting engine. Server: http://localhost:8087/
2021-01-27 13:12:51.915 Runner[43348:673493] LOG SocketEngine: Handshaking
2021-01-27 13:12:51.925 Runner[43348:673493] LOG SocketEnginePolling: Doing polling GET http://localhost:8087/socket.io/?transport=polling&b64=1&EIO=3
2021-01-27 13:12:51.953 Runner[43348:673493] LOG SocketEnginePolling: Got polling response
2021-01-27 13:12:51.953 Runner[43348:673493] LOG SocketEnginePolling: Got poll message: 96:0{"sid":"t_kNG95otZqkbOaoAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}
2021-01-27 13:12:51.953 Runner[43348:673493] LOG SocketEngine: Got message: 0{"sid":"t_kNG95otZqkbOaoAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: ping with data: []
2021-01-27 13:12:51.955 Runner[43348:673493] LOG SocketEnginePolling: Doing polling GET http://localhost:8087/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: ping with data: []
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketManager: Engine opened Connect
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketIOClient{/}: Socket connected
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: statusChange with data: [connected, 3]
2021-01-27 13:12:51.955 Runner[43348:673493] LOG SocketEngine: Writing poll:  has data: false
2021-01-27 13:12:51.955 Runner[43348:673493] LOG SocketEnginePolling: Sending poll:  as type: 2
2021-01-27 13:12:51.955 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: connect with data: ["/"]
2021-01-27 13:12:51.955 Runner[43348:673493] LOG SocketEnginePolling: Created POST string: 1:2
2021-01-27 13:12:51.956 Runner[43348:673493] LOG SocketEnginePolling: POSTing
2021-01-27 13:12:51.956 Runner[43348:673493] LOG SocketEnginePolling: Doing polling POST http://localhost:8087/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA
2021-01-27 13:12:51.968 Runner[43348:673504] LOG SocketEnginePolling: Got polling response
2021-01-27 13:12:51.968 Runner[43348:673504] LOG SocketEnginePolling: Got poll message: 2:40
2021-01-27 13:12:51.969 Runner[43348:673504] LOG SocketEngine: Got message: 40
2021-01-27 13:12:51.969 Runner[43348:673485] LOG SocketParser: Parsing 0
2021-01-27 13:12:51.969 Runner[43348:673504] LOG SocketEnginePolling: Doing polling GET http://localhost:8087/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA
2021-01-27 13:12:51.969 Runner[43348:673485] LOG SocketParser: Decoded packet as: SocketPacket {type: 0; data: []; id: -1; placeholders: 0; nsp: /}
2021-01-27 13:12:51.974 Runner[43348:673497] LOG SocketEngineWebSocket: Sending ws: probe as type: 2
2021-01-27 13:12:51.974 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: websocketUpgrade with data: [["Sec-WebSocket-Accept": "6ZHQpS2e3RYoJp2uEPtou2m9tKE=", "Upgrade": "websocket", "Connection": "Upgrade"]]
2021-01-27 13:12:51.974 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: websocketUpgrade with data: [["Sec-WebSocket-Accept": "6ZHQpS2e3RYoJp2uEPtou2m9tKE=", "Upgrade": "websocket", "Connection": "Upgrade"]]
2021-01-27 13:12:51.977 Runner[43348:673497] LOG SocketEnginePolling: Got polling response
2021-01-27 13:12:51.977 Runner[43348:673497] LOG SocketEnginePolling: Got poll message: 1:3
2021-01-27 13:12:51.977 Runner[43348:673497] LOG SocketEngine: Got message: 3
2021-01-27 13:12:51.977 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: pong with data: []
2021-01-27 13:12:51.977 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: pong with data: []
2021-01-27 13:12:51.977 Runner[43348:673497] LOG SocketEnginePolling: Doing polling GET http://localhost:8087/socket.io/?transport=polling&b64=1&EIO=3&sid=t_kNG95otZqkbOaoAAAA
ws req: ws://localhost:8087/socket.io/?transport=websocket&EIO=3&sid=t_kNG95otZqkbOaoAAAA
Socket connected
sending tests
In namespace: /
nil
2021-01-27 13:12:51.980 Runner[43348:673504] LOG SocketEngine: Got message: 3probe
2021-01-27 13:12:51.980 Runner[43348:673504] LOG SocketEngine: Received probe response, should upgrade to WebSockets
2021-01-27 13:12:51.980 Runner[43348:673504] LOG SocketEngine: Upgrading transport to WebSockets
2021-01-27 13:12:51.980 Runner[43348:673504] LOG SocketEnginePolling: Sending poll:  as type: 6
2021-01-27 13:12:51.980 Runner[43348:673504] LOG SocketEnginePolling: Created POST string: 1:6
2021-01-27 13:12:51.981 Runner[43348:673504] LOG SocketEnginePolling: POSTing
2021-01-27 13:12:51.981 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: pong with data: []
2021-01-27 13:12:51.981 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: pong with data: []
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEnginePolling: Got polling response
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEnginePolling: Got poll message: 1:6
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEngine: Got message: 6
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEngine: Switching to WebSockets
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEngineWebSocket: Sending ws:  as type: 5
2021-01-27 13:12:52.085 Runner[43348:673505] LOG SocketEngine: Flushing probe wait
2021-01-27 13:13:16.955 Runner[43348:673493] LOG SocketEngine: Writing ws:  has data: false
2021-01-27 13:13:16.955 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: ping with data: []
2021-01-27 13:13:16.955 Runner[43348:673493] LOG SocketEngineWebSocket: Sending ws:  as type: 2
2021-01-27 13:13:16.955 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: ping with data: []
2021-01-27 13:13:16.956 Runner[43348:673493] LOG SocketEngine: Got message: 3
2021-01-27 13:13:16.956 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: pong with data: []
2021-01-27 13:13:16.956 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: pong with data: []
2021-01-27 13:13:17.089 Runner[43348:673493] LOG SocketEngine: Got message: 2
2021-01-27 13:13:17.089 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: ping with data: []
2021-01-27 13:13:17.089 Runner[43348:673485] LOG SocketIOClient{/swift}: Handling event: ping with data: []
Disconnecting socket <SocketIO.SocketIOClient: 0x7fe52bc0ebd0>
Socket / disconnected: Socket Disconnected
2021-01-27 13:13:22.094 Runner[43348:673485] LOG SocketIOClient{/}: Disconnected: Socket Disconnected
2021-01-27 13:13:22.094 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: statusChange with data: [disconnected, 1]
2021-01-27 13:13:22.094 Runner[43348:673485] LOG SocketIOClient{/}: Handling event: disconnect with data: ["Socket Disconnected"]

Process finished with exit code 1

@nuclearace
Copy link
Member Author

nuclearace commented Jan 27, 2021

@darrachequesne it only seems to happen when there's an upgrade happening. Going straight to WS seems to handle ping correctly. Also it seems to occasionally work fine, could there be some race in the upgrade code on the server side?

Edit: Responding to the ping the server sends just causes a transport error... so something weird is going on

engine:ws received "2" +23s
  engine:socket packet +23s
  engine:socket got ping +0ms
  engine:socket sending packet "pong" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "3" +0ms
  engine:socket writing ping packet - expecting pong within 5000ms +36ms
  engine:socket sending packet "ping" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "2" +36ms
  engine:ws received "3" +1ms
  engine:socket packet +1ms
  engine:socket transport error +0ms
  engine:ws closing +0ms
  socket.io:client client close with reason transport error +23s
  socket.io:socket closing socket - reason transport error +25s

@nuclearace nuclearace marked this pull request as ready for review February 1, 2021 14:26
@nuclearace nuclearace merged commit bdcdddf into development Feb 1, 2021
@nuclearace
Copy link
Member Author

v16.0.0 has been published

darrachequesne added a commit to socketio/engine.io that referenced this pull request Feb 2, 2021
There was two issues with this behavior:

- v3 clients (with allowEIO3: true) were also receiving a "ping" after
a successful upgrade, which is incorrect (in v3, it's the client that
sends the "ping", and the server answers with a "pong")

- the ping timer is not reset after upgrade on the client-side, so an
upgrade which took longer than the `pingTimeout` duration could lead to
a "ping timeout" error on the client-side

I think the latter issue is present since the initial implementation.

Related: socketio/socket.io-client-swift#1309 (comment)
@andreiardelean-kwiff
Copy link

SocketIOClientOption.version is not handled in SocketExtensions.swift keyValueToSocketIOClientOption(key: String, value: Any)

@nuclearace
Copy link
Member Author

Thanks for pointing out. I’ll fix that. It would be good to use the typed versions though, the NSdict one was mostly just for compatibility with objc

darrachequesne added a commit to socketio/engine.io that referenced this pull request Jun 6, 2022
There was two issues with this behavior:

- v3 clients (with allowEIO3: true) were also receiving a "ping" after
a successful upgrade, which is incorrect (in v3, it's the client that
sends the "ping", and the server answers with a "pong")

- the ping timer is not reset after upgrade on the client-side, so an
upgrade which took longer than the `pingTimeout` duration could lead to
a "ping timeout" error on the client-side

I think the latter issue is present since the initial implementation.

Related: socketio/socket.io-client-swift#1309 (comment)

Backported from ff2b8ab
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants