Handshake sometime fail in Chrome

[Sephi-Chan]

Hello,

Since some time, I noticed that push sometime doesn't work. It's quite embarassing.
It happens with Chrome (version 16.0.912.63) on Mac OS (10.7.2).

Here is the log of a successful sequence

12:24:24 juggernaut.1  |    debug - client authorized
12:24:24 juggernaut.1  |    info  - handshake authorized 9774492831265597113


12:24:24 juggernaut.1  |    debug - setting request GET /socket.io/1/websocket/9774492831265597113
12:24:24 juggernaut.1  |    debug - set heartbeat interval for client 9774492831265597113
12:24:24 juggernaut.1  |    warn  - websocket connection invalid
12:24:24 juggernaut.1  |    info  - transport end
12:24:24 juggernaut.1  |    debug - set close timeout for client 9774492831265597113
12:24:24 juggernaut.1  |    debug - cleared close timeout for client 9774492831265597113
12:24:24 juggernaut.1  |    debug - cleared heartbeat interval for client 9774492831265597113
12:24:24 juggernaut.1  |    debug - client authorized for


12:24:34 juggernaut.1  |    debug - setting request GET /socket.io/1/xhr-polling/9774492831265597113?t=1324553074949
12:24:34 juggernaut.1  |    debug - setting poll timeout
12:24:34 juggernaut.1  |    debug - clearing poll timeout
12:24:34 juggernaut.1  |    debug - xhr-polling writing 1::
12:24:34 juggernaut.1  |    debug - set close timeout for client 9774492831265597113
12:24:34 juggernaut.1  |    debug - xhr-polling received data packet 3:::{"type":"subscribe","channel":"games/23"}
12:24:34 juggernaut.1  | 22 Dec 12:24:34 - Received: {"type":"subscribe","channel":"games/23"}
12:24:34 juggernaut.1  | 22 Dec 12:24:34 - Client subscribing to: games/23
12:24:34 juggernaut.1  |    debug - setting request GET /socket.io/1/xhr-polling/9774492831265597113?t=1324553074954
12:24:34 juggernaut.1  |    debug - setting poll timeout
12:24:34 juggernaut.1  |    debug - discarding transport
12:24:34 juggernaut.1  |    debug - cleared close timeout for client 9774492831265597113


12:24:35 juggernaut.1  | 22 Dec 12:24:35 - Received: {"channels":["games/23"],"data":{"eventType":"ATTACK_REPORT","attacker":{"unitsLoss":3,"territoryId":1,"color":"blue","winner":true,"unitsCount":11,"remainingUnitsCount":8},"target":{"unitsLoss":4,"territoryId":30,"color":"blue"}}}
12:24:35 juggernaut.1  | 22 Dec 12:24:35 - Publishing to channels: games/23 : [object Object]


12:24:35 juggernaut.1  |    debug - xhr-polling writing 3:::{"data":{"eventType":"ATTACK_REPORT","attacker":{"unitsLoss":3,"territoryId":1,"color":"blue","winner":true,"unitsCount":11,"remainingUnitsCount":8},"target":{"unitsLoss":4,"territoryId":30,"color":"blue"}},"channel":"games/23"}
12:24:35 juggernaut.1  |    debug - set close timeout for client 9774492831265597113


12:24:35 juggernaut.1  |    debug - setting request GET /socket.io/1/xhr-polling/9774492831265597113?t=1324553075335
12:24:35 juggernaut.1  |    debug - setting poll timeout
12:24:35 juggernaut.1  |    debug - discarding transport
12:24:35 juggernaut.1  |    debug - cleared close timeout for client 9774492831265597113

Then the log for a failing sequence

12:29:57 juggernaut.1  |    debug - clearing poll timeout
12:29:57 juggernaut.1  |    info  - transport end
12:29:57 juggernaut.1  |    debug - set close timeout for client 14668823361830559941
12:29:57 juggernaut.1  |    debug - cleared close timeout for client 14668823361830559941
12:29:57 juggernaut.1  |    debug - discarding transport


12:29:58 juggernaut.1  |    debug - setting request GET /socket.io/1/websocket/20410946011839022462
12:29:58 juggernaut.1  |    debug - set heartbeat interval for client 20410946011839022462
12:29:58 juggernaut.1  |    warn  - websocket connection invalid
12:29:58 juggernaut.1  |    info  - transport end
12:29:58 juggernaut.1  |    debug - set close timeout for client 20410946011839022462
12:29:58 juggernaut.1  |    debug - cleared close timeout for client 20410946011839022462
12:29:58 juggernaut.1  |    debug - cleared heartbeat interval for client 20410946011839022462
12:29:58 juggernaut.1  |    debug - client authorized for


12:30:05 juggernaut.1  | 22 Dec 12:30:05 - Received: {"channels":["games/23"],"data":{"eventType":"ATTACK_REPORT","attacker":{"unitsLoss":0,"territoryId":1,"color":"blue","winner":true,"unitsCount":11,"remainingUnitsCount":11},"target":{"unitsLoss":4,"territoryId":30,"color":"blue"}}}
12:30:05 juggernaut.1  | 22 Dec 12:30:05 - Publishing to channels: games/23 : [object Object]


12:30:08 juggernaut.1  |    debug - setting request GET /socket.io/1/xhr-polling/20410946011839022462?t=1324553408108
12:30:08 juggernaut.1  |    debug - setting poll timeout
12:30:08 juggernaut.1  |    debug - clearing poll timeout
12:30:08 juggernaut.1  |    debug - xhr-polling writing 1::
12:30:08 juggernaut.1  |    debug - set close timeout for client 20410946011839022462
12:30:08 juggernaut.1  |    debug - xhr-polling received data packet 3:::{"type":"subscribe","channel":"games/23"}
12:30:08 juggernaut.1  | 22 Dec 12:30:08 - Received: {"type":"subscribe","channel":"games/23"}
12:30:08 juggernaut.1  | 22 Dec 12:30:08 - Client subscribing to: games/23
12:30:08 juggernaut.1  |    debug - setting request GET /socket.io/1/xhr-polling/20410946011839022462?t=1324553408112
12:30:08 juggernaut.1  |    debug - setting poll timeout
12:30:08 juggernaut.1  |    debug - discarding transport
12:30:08 juggernaut.1  |    debug - cleared close timeout for client 20410946011839022462

The main difference I can see is the absence of handshake.

Any idea? :s

[jskulski]

This was just merged in which fixed a problem with chrome 16. Upgrades to the latest socket.io. Update and try again?

#113

[Sephi-Chan]

Thanks, it is good! :)