2

I am using nodejs with socket.io and express frame work. Following is the log output I get, when I run command

DEBUG=* /bin/www

Following is the log output.

  engine intercepting request for path "/socket.io/" +2m
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=1414498393419-0" +0ms
  engine handshaking client "WECN1dP0tobacKc8AAAB" +1ms
  engine:socket sending packet "open" ({"sid":"WECN1dP0tobacKc8AAAB","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}) +0ms
  engine:polling setting request +0ms
  engine:socket flushing buffer to transport +0ms
  engine:polling writing "  �0{"sid":"WECN1dP0tobacKc8AAAB","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +1ms
  engine:socket executing batch send callback +1ms
  socket.io:server incoming connection with id WECN1dP0tobacKc8AAAB +2.5m
  socket.io:client connecting to namespace / +1.3m
  socket.io:namespace adding socket to nsp / +2.5m
  socket.io:socket socket connected - writing packet +1.3m
  socket.io:socket joining room WECN1dP0tobacKc8AAAB +0ms
  socket.io:client writing packet {"type":0,"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +2.5m
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
  engine:socket sending packet "message" (0) +1ms
  socket.io:socket joined room WECN1dP0tobacKc8AAAB +5ms
  engine intercepting request for path "/socket.io/" +140ms
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=1414498393557-1&sid=WECN1dP0tobacKc8AAAB" +0ms
  engine setting new request for existing client +1ms
  engine:polling setting request +0ms
  engine:socket flushing buffer to transport +0ms
  engine:polling writing "�40" +0ms
  engine:socket executing batch send callback +0ms
  engine upgrading existing transport +39ms
  engine:socket might upgrade socket transport from "polling" to "websocket" +0ms
  engine intercepting request for path "/socket.io/" +16ms
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=1414498393618-2&sid=WECN1dP0tobacKc8AAAB" +0ms
  engine setting new request for existing client +0ms
  engine:polling setting request +0ms
  engine:ws received "2probe" +2ms
  engine:ws writing "3probe" +0ms
  engine:socket writing a noop packet to polling for fast upgrade +100ms
  engine:polling writing "�6" +0ms
  engine:ws received "5" +4ms
  engine:socket got upgrade packet - upgrading +0ms
  engine:ws received "2" +25s
  engine:socket packet +0ms
  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:ws received "2" +25s
  engine:socket packet +0ms
  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:ws received "2" +25s
  engine:socket packet +0ms
  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:ws received "2" +25s
  engine:socket packet +0ms
  engine:socket got ping +0ms
  engine:socket sending packet "pong" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "3" +1ms

I don't see any log message that confirms transport upgrade. Also the ping-pong messages keep happening.

Does this mean the websocket transport is established ?

Venkat Kotra
  • 10,413
  • 3
  • 49
  • 53

1 Answers1

2

Yes, it uses polling first and then upgrades to websocket. I'm sure if you connect with a browser or use wireshark you see the "HTTP/1.1 101 Switching Protocols" message from the server. Also you see in the logs "engine:ws" which implies the websocket is working. If you still are not sure you can also print out the type of transport (e.g. on disconnect). This is server side code (socket.io 1.1.0):

  socket.on('disconnect', function () {
    console.log(socket.id + ' disconnect ('+ socket.client.conn.transport.constructor.name +')';
  });
DerM
  • 1,497
  • 1
  • 14
  • 27
  • Hi. If you see the log `Bug engine:ws writing "3probe" +0ms` comes before `engine:socket writing a noop packet to polling for fast upgrade +100ms`. i.e even before the attempt to upgrade from polling to websocket. Which means that appearance of `engine:ws` does not mean transport has shifted to websocket – Venkat Kotra Oct 30 '14 at 09:51
  • Yes, that's true it doesn't mean the transport has shifted in general. But in the end of the log it logs pretty good. Anyway I would just try the debug output of the socket transport type. I use it in my server and when a client connects it's polling and we he disconnects it's websocket. – DerM Oct 30 '14 at 10:15