I have the following problem:
client: Rust/wasm
server: Rust/x86_64
server side: I have log msgs claiming that tokio/tungesnite has sent messages.
client side: no msgs are being printed for receiving msgs
Both client & server side are printing log msgs asserting that the ws connection has been opened.
Question: what tool can I use to examine what happened to the websocket msgs the server claimed to have sent ?
Is that a helpful answer to your question?
See also the chrome developer tools docs:
Interesting:
Request Method: GET
Status Code: 101 Switching Protocols
^-- Does this mean my serer side (tokio / hyper / tungstenite) somehow did not complete the "upgrade http to websocket" process ?
Is it pending after 101 Switching Protocols or are you seeing any messages? If the handshake does not complete, maybe try deactivating your firewall?
It is stuck at (for minutes) at "101 Switching Protocols"
This is really helpful; thanks! I'm going to go stare at my hyper / tokio / tungstenite code a bit to see what's going on there.
Quoting: WebSockets tutorial: How to go real-time with Node and React - LogRocket Blog.
Once the request is accepted in the server (after necessary validations in production), the handshake is fulfilled with status code
101(switching protocols). If you see anything other than status code101in the browser, the WebSocket upgrade has failed, and the normal HTTP semantics will be followed.
I am no longer confident that "101 switching protocols" means something went wrong. how confident at you? What is the "correct" status code for a websocket ?
Oh no, this is absolutely correct that you see 101 switching protocols. This happens when your http request for the websocket connection is upgraded to a websocket. Only when you don't see anything happen afterwards (if your connection is stuck pending on protocol switching) there went something wrong with the handshake. (The first thing I do on such errors is disabling my firewall which more often than not is the culprit behind connectivity issues during development).
Are there more chrome flags I can look,into ?
tcpdump is showing that Rust/x86_64 is sending data to Rust/wasm32/Chrome on the wss port. For some reason, these are not being interpreted as msgs.
Right now:
on port https://9090:
Rust/wasm32/Chrome can send http requests
Rust/x86_64 can respond
Rust/wasm32/Chrome can open wss
Rust/x86_64 will also open websocket
Rust/wasm32/Chrome can send data on wss, Rust/x86_64 will receive
Rust/x86_64 tries to send data in respond on wss, tcpdump shows packets beint sent; Rust/wasm32/Chrome does not see it
Does it show packets being received again? I still believe there is someone between your browser and your server that is dropping incoming packets...
I have refactored code so that 9090 is wss only, regular http traffic is on 8080
This is log of tcpdump. I do not know difference of 'sent' vs 'received again' ; does tcpdump show that ?
cpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
06:16:52.712469 IP 127.0.0.1.45708 > 127.0.0.1.9090: Flags [P.], seq 1647320834:1647320864, ack 2762297653, win 0, options [nop,nop,TS val 4262128213 ecr 4262087416], length 30
06:16:52.712569 IP 127.0.0.1.9090 > 127.0.0.1.45708: Flags [R], seq 2762297653, win 0, length 0
06:16:53.462788 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [S], seq 1690290263, win 65495, options [mss 65495,sackOK,TS val 4262128963 ecr 0,nop,wscale 7], length 0
06:16:53.462805 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [S.], seq 698107113, ack 1690290264, win 65483, options [mss 65495,sackOK,TS val 4262128963 ecr 4262128963,nop,wscale 7], length 0
06:16:53.462818 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 1, win 512, options [nop,nop,TS val 4262128963 ecr 4262128963], length 0
06:16:53.462997 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [P.], seq 1:518, ack 1, win 512, options [nop,nop,TS val 4262128963 ecr 4262128963], length 517
06:16:53.463006 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], ack 518, win 508, options [nop,nop,TS val 4262128963 ecr 4262128963], length 0
06:16:53.465078 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 1:4732, ack 518, win 512, options [nop,nop,TS val 4262128965 ecr 4262128963], length 4731
06:16:53.465091 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 4732, win 489, options [nop,nop,TS val 4262128965 ecr 4262128965], length 0
06:16:53.465451 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [P.], seq 518:582, ack 4732, win 512, options [nop,nop,TS val 4262128966 ecr 4262128965], length 64
06:16:53.465714 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 4732:5144, ack 582, win 512, options [nop,nop,TS val 4262128966 ecr 4262128966], length 412
06:16:53.465753 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [P.], seq 582:1105, ack 5144, win 509, options [nop,nop,TS val 4262128966 ecr 4262128966], length 523
06:16:53.466267 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 5144:5332, ack 1105, win 512, options [nop,nop,TS val 4262128966 ecr 4262128966], length 188
06:16:53.475630 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [P.], seq 1105:1161, ack 5332, win 512, options [nop,nop,TS val 4262128976 ecr 4262128966], length 56
06:16:53.475644 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 5332:5368, ack 1161, win 512, options [nop,nop,TS val 4262128976 ecr 4262128976], length 36
06:16:53.515731 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 5368, win 512, options [nop,nop,TS val 4262129016 ecr 4262128976], length 0
06:16:53.515747 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 5368:5500, ack 1161, win 512, options [nop,nop,TS val 4262129016 ecr 4262129016], length 132
06:16:53.515756 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 5500, win 511, options [nop,nop,TS val 4262129016 ecr 4262129016], length 0
06:16:54.129078 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 5500:38268, ack 1161, win 512, options [nop,nop,TS val 4262129629 ecr 4262129016], length 32768
06:16:54.129110 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 38268, win 379, options [nop,nop,TS val 4262129629 ecr 4262129629], length 0
06:16:54.129163 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 38268:71036, ack 1161, win 512, options [nop,nop,TS val 4262129629 ecr 4262129629], length 32768
06:16:54.129168 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 71036:71124, ack 1161, win 512, options [nop,nop,TS val 4262129629 ecr 4262129629], length 88
06:16:54.129182 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 71036, win 123, options [nop,nop,TS val 4262129629 ecr 4262129629], length 0
06:16:54.129664 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 71124, win 512, options [nop,nop,TS val 4262129630 ecr 4262129629], length 0
06:16:54.129718 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 71124:103892, ack 1161, win 512, options [nop,nop,TS val 4262129630 ecr 4262129630], length 32768
06:16:54.129731 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 103892:136660, ack 1161, win 512, options [nop,nop,TS val 4262129630 ecr 4262129630], length 32768
06:16:54.129996 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 136660, win 0, options [nop,nop,TS val 4262129630 ecr 4262129630], length 0
06:16:54.130198 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 136660, win 379, options [nop,nop,TS val 4262129630 ecr 4262129630], length 0
06:16:54.130218 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 136660:169428, ack 1161, win 512, options [nop,nop,TS val 4262129630 ecr 4262129630], length 32768
06:16:54.130442 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 169428, win 512, options [nop,nop,TS val 4262129631 ecr 4262129630], length 0
06:16:54.130471 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 169428:202196, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130479 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 202196:234964, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130488 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 234964, win 0, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130524 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 234964, win 379, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130545 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 234964:267732, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130583 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 267732, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130618 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 267732:300500, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130628 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 300500:333268, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130637 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 300500, win 1535, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130714 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 333268:366036, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130725 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 366036:398804, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130734 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 398804:431572, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130743 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 431572:464340, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130752 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 333268, win 2559, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130817 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 464340:497108, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130828 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 497108:529876, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130837 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 529876:562644, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130846 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 562644:595412, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130855 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 595412:628180, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130863 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 366036, win 3582, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130906 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 628180:660948, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130918 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 660948:693716, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130927 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 693716:726484, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130935 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 398804, win 4605, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.130967 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 726484:759252, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.130977 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 759252:792020, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131000 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 431572, win 5628, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131032 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 792020:824788, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131043 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 824788:857556, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131051 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 464340, win 6651, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131058 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 497108, win 7674, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131064 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 529876, win 8698, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131071 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 562644, win 9721, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131077 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 595412, win 10744, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131084 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 857556:890324, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131083 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 628180, win 11767, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131088 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 660948, win 12790, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131095 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 693716, win 13813, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131104 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 890324:923092, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131101 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 726484, win 14837, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131106 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 759252, win 15860, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131112 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 792020, win 16883, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131115 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [.], seq 923092:955860, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
06:16:54.131118 IP 127.0.0.1.51438 > 127.0.0.1.9090: Flags [.], ack 824788, win 17906, options [nop,nop,TS val 4262129631 ecr 4262129631], length 0
06:16:54.131123 IP 127.0.0.1.9090 > 127.0.0.1.51438: Flags [P.], seq 955860:988628, ack 1161, win 512, options [nop,nop,TS val 4262129631 ecr 4262129631], length 32768
You can set filters to only show certain packages. I think tcpdump -i lo tcp and src host 127.0.0.1 and port 9090 would show only the packages that are received from your server (and should be available to your browser). I could be wrong though, I haven't done much tcp sniffing lately. Anyway, if I'm right then the packets are received back on loopback anyway (all the packets with 127.0.0.1.9090 as src (left-hand side of the >)).
Have you tried using unencrypted websockets?
I have not tested plain websockets.
However, I just ran
websocat wss://...:9090/wss_proxy
and yeah, it gets the first msg the server sends
I'm executing this in the Chrome dev console:
var socket = new WebSocket(url);
socket.addEventListener("message", (event) => {
console.log("Message from server: ", event.data);
});
which returns
undefined
VM224:3 Message from server: from servfer
So apparently, from the Chrome console, I can talk to wss, and get a msg back. But if I connect from Rust/wasm code, it does not even show up in the network tab.
WSS supposedly has no same-origin; but I wonder if there is some security misconfiguration where (1) it allows from dev console but (2) blocks from webpages ?
I am not confident that I understand what you mean by "received again". But the tcpdump output does provide you with information about which direction the packets are going (.9090 > ... is server-to-client and ... > .9090 is client-to-server), whether it contains data (P flag), whether it is a reset (R flag), or a connection request (S flag), etc.
What your tcpdump sample shows is that there is quite a bit of chatter between a server and a single client. Including several packets that have 32 KB payloads. The total duration of the conversation captured lasts about 668 ms. And the server is the last side to send a payload, which the client does not acknowledge in the log... (I cannot assess the completeness of this capture.)
To be honest, neither do I. I was referencing:
There is something very weird going on where:
So for some definition of "sent" and 'received", Rust/x86_64 sent, but Rust/wasm32/Chrome did not receive.
===
This makes everything even more weird:
var socket = new WebSocket(url);
socket.addEventListener("message", (event) => {
console.log("*** Message from server: ", event.data);
});
pub fn do_stuff(url: &str) {
let ws = WebSocket::new(url).unwrap();
ws.set_binary_type(web_sys::BinaryType::Arraybuffer);
let cloned_ws = ws.clone();
let onmessage_callback = Closure::<dyn FnMut(_)>::new(move |e: MessageEvent| {
web_sys::console::log_2(&"handwritten got back: {:?}".into(), &e);});
ws.set_onmessage(Some(onmessage_callback.as_ref().unchecked_ref()));
onmessage_callback.forget();
let onerror_callback = Closure::<dyn FnMut(_)>::new(move |e: ErrorEvent| {
web_sys::console::log_2(&"handwritten error event: {:?}".into(), &e);});
ws.set_onerror(Some(onerror_callback.as_ref().unchecked_ref()));
onerror_callback.forget();
let cloned_ws = ws.clone();
let onopen_callback = Closure::<dyn FnMut()>::new(move || {
web_sys::console::log_1(&"handwritten socket opened".into());});
ws.set_onopen(Some(onopen_callback.as_ref().unchecked_ref()));
onopen_callback.forget();}
I suppose that leaves us with the possibility that the async receiver in the client is unable to make progress for some reason.
What strikes me as unusual in the tcpdump output is that the client doesn't even acknowledge the last packet from the server. If the socket is closed, we would expect the OS to respond with a reset. If the client is unable to accept any more packets, we would expect to see some kind of back-pressure. What we do see is the receive window slowly increase until the client stops acknowledging packets entirely. This is the kernel sending ACK packets, not the Rust/WASM code.
It's possible that the Rust/WASM isn't actually consuming data from the stream, nor has it closed the socket. The kernel buffer fills up and can no longer accept more incoming packets.
The client initiates the connection with the window scaling option set to 7, so we need to reinterpret the win value on each packet. The last packet sent from the client has win 17906, which we multiply by 2**7 to arrive at about 2.2 MB that the kernel has consumed and is presumably sitting in the buffer waiting for the client code to consume.
So that's the clue; what does your async receive loop look like?
This is my fault for not being clear. The tcpdump log is NOT complete. The serer is sending a 16MB msg (chunk data for local world state).
Let me get back to you on this. I have 3 minimal Rust/wasm32/Websocket examples that "works" (gets msg from server). However, the one that fails (no msg from server, not evein Chrome network debug panel) is buried / interleaved with a bunch of other code that I need to refactor.
Thanks for your help; now that I have a "working" and "broken" example both in Rust, I should be able to binary search / diff my way to the bug.
@jofas @parasyte : Thank you for your help & patience.
I figured out what went wrong: race condition.
I had an async block which infinite-loops the CPU. Imagine
async fn foo() { loop {}}
(except the bug wasn't obvious, it was a poorly written BUSY polling loop)
Once we hit this async block, game over -- the wasm thread just runs, control never returns to JS, etc ...
The client opens the ws w/ server, client sends msg, then client hits infinite-loop, not receiving any server msgs.
This also consistent with @parasyte 's observation of the tcp msgs being sent, but no response.
this is also consistent with all my "small examples of WS" working; they were either (1) running before the wasm-infinite-loop was hit or (2) I guess the dev console is a different thread? Or maybe due to the page being in an iframe -- not sure why the dev console was responsive.