maccman/juggernaut — Issue #112: Push sometime doesn't work…
Author: Sephi-Chan
Created: 2011-12-22 11:36:20+00:00
State: open

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