ws stream closed before upgrade

[christian3042]

This issue is related to #479 After the fix of 0.16.2 the application still sometimes gets stuck. However, the issue occurred probably also before 0.16.2.

The following issue was noticed:

2025-04-08T13:08:12.710241Z DEBUG upgrade_handshake{sid="snkfowfKD3UvA4GF"}: engineioxide::transport::ws: websocket connection upgrade 2025-04-08T13:08:12.719410Z DEBUG engineioxide::transport::polling: [sid=snkfowfKD3UvA4GF] polling request 2025-04-08T13:08:12.719452Z DEBUG engineioxide::transport::polling::payload::encoder: encoding payload with v4 encoder 2025-04-08T13:08:12.719459Z DEBUG engineioxide::transport::polling::payload::encoder: sending packet: None 2025-04-08T13:08:12.728063Z DEBUG upgrade_handshake{sid="snkfowfKD3UvA4GF"}: engineioxide::socket: [sid=snkfowfKD3UvA4GF] sending packet: Noop 2025-04-08T13:08:12.728119Z DEBUG engineioxide::transport::polling::payload::encoder: sending packet: [Noop] 2025-04-08T13:08:12.728130Z DEBUG engineioxide::transport::polling: [sid=snkfowfKD3UvA4GF] sending data: b"6" 2025-04-08T13:08:12.757339Z DEBUG engineioxide::transport::polling: [sid=snkfowfKD3UvA4GF] polling request 2025-04-08T13:08:12.757370Z DEBUG engineioxide::transport::polling::payload::encoder: encoding payload with v4 encoder 2025-04-08T13:08:12.757378Z DEBUG engineioxide::transport::polling::payload::encoder: sending packet: None 2025-04-08T13:08:57.668557Z DEBUG upgrade_handshake{sid="snkfowfKD3UvA4GF"}: engineioxide::transport::ws: ws stream closed before upgrade 2025-04-08T13:08:57.668898Z DEBUG engineioxide::transport::ws: ws closed with error: Upgrade 2025-04-08T13:08:58.918140Z DEBUG on_connect{sid="cfidtrx4k1huLfN5"}: socketioxide::client: eio socket connect 2025-04-08T13:08:58.918171Z DEBUG on_connect{sid="cfidtrx4k1huLfN5"}: socketioxide::client: spawning connect timeout task 2025-04-08T13:08:58.918312Z DEBUG engineioxide::socket: heartbeat sender routine started sid=cfidtrx4k1huLfN5 2025-04-08T13:08:58.919444Z TRACE engineioxide::socket: emitting ping sid=cfidtrx4k1huLfN5 2025-04-08T13:08:58.919464Z TRACE engineioxide::socket: waiting for pong sid=cfidtrx4k1huLfN5 2025-04-08T13:08:58.941519Z DEBUG engineioxide::transport::polling::payload: decoding payload Some("text/plain;charset=UTF-8") 2025-04-08T13:08:58.941556Z DEBUG engineioxide::transport::polling::payload::decoder: decoding payload with v4 decoder

Sometimes the upgrade does not work and it runs into a timeout.
Attached you can find the extended log with the application data removed.

server-logs.txt
client.har.txt

Please let me know, if any additional information is required.

Versions:

• Socketioxide version: 0.16.2
• Http lib: axum 0.8.3
• Socket.io client version 4.8.1

[Totodore]

Hey @christian3042,
The timestamp on the logs are not corresponding with the .har traces:
2025-04-08T13:08:12.710241Z vs Tue, 08 Apr 2025 13:33:54 GMT

Also I would need to have the full logs in a file (at the same time than the .har traces). And also if possible a ws screenshot with the init messages and the timestamps (websocket messages are not shared in the .har traces).

Currently I can't do much with what you provided. Thanks for your report though!

[christian3042]

Hi @Totodore, thanks for the response. Sorry for providing mismatched logfiles. This time I checked it and the logs are in sync. I ran the server and client on my local machine with test data only. The full logs, without removing any application data, are provided from starting the application until the issue occurrs. Also the screenshots from the ws traffic, not being logged to the .har file, are provided.

output.log.2025-04-28.txt
localhost_Archive [25-04-28 17-26-43].har.txt

It took longer to reproduce the issue, in comparison to the deployment on a vServer, but it still occurrs.

This is all I can provide for the moment. I tried to enable the logging on client side, however, wasn't able to output the debug() logs from the socket.io-client when running my Angular application. I created a discussion for further help here: socketio/socket.io#5338
Not sure if logging the output within an Angular application is possible with the current implementation or if I'm doing something wrong.

[christian3042]

Hi @Totodore,

I was further investigating the issue with Wireshark and logged the network traffic between client and server, which I had deployed on my local machine. I could reproduce the issue and recorded it. You can find the file in the attachment.

As usually I tried to reload the browser a few times, until the issue occurred, so the upper part (above package 464) of the Wireshark recording should not be relevant. With package 464 the client starts to build up the connection. Upgrade options etc. are exchanged, bearer token is sent in package 480 and in package 493 the upgrade to the websocket is requested. In 495 the 101 response with switching protocols is received and after that, 2 and 3 probes are being exchanged via websocket between client and server. However, with package 501, the client sends another GET polling request after the 2probe and 3probe have already occurred via the WebSocket protocol, but before the upgrade (5) package has been sent by the client. This request seems not to be answered by the server with a NOOP (6), as it should be, according to the protocol. As a result, the client seems to wait for the NOOP package and does not send the upgrade package (5), which ultimately leads to a timeout.
The connection close appears in package 582. After the connection close, a new websocket connection gets established successfully and the requested data is sent to the client.

My assumption is, that the server side only sends NOOP packages to GET requests until data gets send through the websocket connection, but is not responding to GET requests, that have been sent by the client before the client sends the upgrade (5) via websocket and after the websocket connection is already active.

I would be really great, if you could have a look by yourself. The Wireshark recording should provide a much clearer picture on what's going on in comparison to the browser logging and screenshots. Also filtering in Wireshark for HTTP and Websocket can help to reduce the amount of displayed packages to the relevant ones. Don't mind the GET ... .components.ts requests, these are only Angular related ones.

socketioxide-0-17-2-dump.pcapng.txt

Please remove the .txt at the end, as it is not a supported file type.

I used the following versions:
socketioxide 0.17.2
socket.io-client 4.8.1
Wireshark 4.2.2

[Totodore]

Hi @christian3042, thanks for the details and the hint you provided. This greatly helped me to find the bug you reported. Could you try to use socketioxide on the branch #554 and tell me if it fixed your issue?

[christian3042]

Hi @Totodore thanks for providing the fix. However, I cannot build the project with the given branch. I'm facing the following error message:

error[E0599]: the method `with` exists for fn item `fn(SocketRef) {on_connect}`, but its trait bounds were not satisfied
  --> src/main.rs:59:27
   |
59 |     io.ns("/", on_connect.with(authenticate_middleware));
   |                           ^^^^ method cannot be called on `fn(SocketRef) {on_connect}` due to unsatisfied trait bounds
   |
   = note: the following trait bounds were not satisfied:
           `fn(SocketRef) {on_connect}: tracing::Subscriber`
           which is required by `fn(SocketRef) {on_connect}: SubscriberExt`
           `&fn(SocketRef) {on_connect}: tracing::Subscriber`
           which is required by `&fn(SocketRef) {on_connect}: SubscriberExt`
           `&mut fn(SocketRef) {on_connect}: tracing::Subscriber`
           which is required by `&mut fn(SocketRef) {on_connect}: SubscriberExt`

For more information about this error, try `rustc --explain E0599`.
error: could not compile `erp-rust` (bin "erp-rust") due to 1 previous error
[Finished running. Exit status: 101]

It didn't look like something has changed in the branch regarding the ConnectHandler. However, removing the authentication_handler and making the on_connect method async, helped at least to build the project. But without the authentication in place I cannot run my application. My methods look as following:

main:

    let (websocket_layer, io) = SocketIo::builder().with_state(config.clone()).build_layer();
...
    io.ns("/", on_connect.with(authenticate_middleware)); <-- Invalid ConnectMiddleware
...

pub fn on_connect(socket: SocketRef) {
    register_listeners(&socket);
}

pub fn authenticate_middleware(s: SocketRef, Data(auth): Data<Auth>) -> Result<(), anyhow::Error> {
    let binding = auth.token.unwrap();
    let mut authenticated = false;

    let length = "Bearer ".len();
    if binding.len() > length {
        let token = binding[length..].trim_start();

        let token_data = decode::<Claims>(token, &KEYS.decoding, &Validation::default());
        match token_data {
            Ok(r) => {
                authenticated = true;
                let claims: Claims = r.claims;
                s.extensions.insert(claims);
            }
            Err(_) => {
                authenticated = false;
            }
        }
    }

    if authenticated {
        Ok(())
    } else {
        Err(anyhow!("Authentication failed!"))
    }
}

I also updated to the latest rust 1.88 and ran a cargo update, but it didn't help.

[Totodore]

Oh, yes it is because on the main branch there is a breaking change. All handlers and middlewares must be async. @christian3042

[christian3042]

Thanks, I made it run and tested it. Unfortunately, the issue still occurs. Attached the Wireshark traffic with the fix-branch deployed. The issue starts ocurring from package 883. For me it looks like that not both packages, 904 and 905 are being answered with a 200 OK.

socketioxide-fix-upgrade.pcapng.txt

[Totodore]

I have made another fix, could you retry please? If it's still doesn't work could you also provide:

• The server logs for engineioxide at the TRACE level
• The client logs for socket.io

[christian3042]

Attached the server log and wireshark recording. I cannot provide the client side logs, as they are not showing up in my Angular application. To make this work, I guess I would have to write a client in node.js without Angular, as the socket.io-client does not seem to allow passing a debug instance. So if the issue still does not get tracked down, I can try to write a node.js client. This however, would take some time.

start package: 202
connection close: 433

wireshark.pcapng.txt
server-logs.txt

[Totodore]

And did you try with the latest changes? You need to do a cargo update to sync the branch.