Socket occasionally stuck on Android 2.3 browser

[mokesmokes]

Here's a scenario that occurs in about 20% of cases with Android 2.3 browser (using engine.io 0.6.3 in a WebView in an app)

1. Opening socket, 'polling' is the only transport, upgrade=false
2. Immediately upon 'open' event I have a message to send
3. In 20% of the cases - nothing happens, onreadystatechange never called, though engine.io client debug log says the xhr was sent.
4. Server logs show the new connection and the initial GET poll, but my message never arrives.

Notes:

• closing the socket and reopening it works, though subsequent re-opens do occasionally hit the same bug (in my case I always have a message to send as soon as the socket is open).
• if the socket connects cleanly, and the initial message goes through - all is apparently fine, until the following close/open, where there is a chance for it to happen again
• if I delay the first message send by 100ms after the open event it fails much less, if I delay by 200ms it has not (yet) failed. Perhaps some race condition between the initial poll packet and my first message?
• I have not seen it occur in other polling browsers - e.g. Android 4.x, or with websockets

[rauchg]

Thanks a lot for the thorough report. Does the server end respond in 100% of the cases? Can you analyze the network traffic?

[mokesmokes]

Here is the server side log, then nada: (let me know if any more data can help). BTW - from my experience, network logs won't help. When onreadystatechange is never called, the request was killed browser side (e.g. I've seen it on CORS issues, etc - not the case here).

Sat, 24 Aug 2013 20:10:30 GMT engine:core intercepting request for path "/engine.io/"
Sat, 24 Aug 2013 20:10:30 GMT engine handling "GET" http request "/engine.io/?EIO=2&transport=polling&t=1377375261374"
Sat, 24 Aug 2013 20:10:30 GMT engine handshaking client "HKXi8uwDMWnAPlvbAAC7"
Sat, 24 Aug 2013 20:10:30 GMT engine:socket sending packet "open" ({"sid":"HKXi8uwDMWnAPlvbAAC7","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000})
Sat, 24 Aug 2013 20:10:30 GMT engine:polling setting request
Sat, 24 Aug 2013 20:10:30 GMT engine:polling setting handshake request
Sat, 24 Aug 2013 20:10:30 GMT engine:socket flushing buffer to transport
Sat, 24 Aug 2013 20:10:30 GMT engine:polling writing "97:0{"sid":"HKXi8uwDMWnAPlvbAAC7","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}"
Sat, 24 Aug 2013 20:10:30 GMT engine:socket executing batch send callback
Sat, 24 Aug 2013 20:10:30 GMT engine:core intercepting request for path "/engine.io/"
Sat, 24 Aug 2013 20:10:30 GMT engine handling "GET" http request "/engine.io/?EIO=2&transport=polling&t=1377375262252&sid=HKXi8uwDMWnAPlvbAAC7"
Sat, 24 Aug 2013 20:10:30 GMT engine setting new request for existing client
Sat, 24 Aug 2013 20:10:30 GMT engine:polling setting request

Here is the client side, it's a bit mangled since the built-in debug code doesn't work (no console.log in this WebView, so the parameters become a mess). That's all there is - 25 seconds after the message send attempt the socket tries to send a ping, that doesn't seem to go anywhere. If I close and re-open the socket then the bug may or may not occur, again.

 {"0":"engine-client:socket creating transport \"%s\" +0ms","1":"polling"}
 {"0":"engine.io-client:polling polling +0ms"}
{"0":"engine.io-client:polling-xhr xhr poll +0ms"}
 {"0":"engine.io-client:polling-xhr sending xhr with url %s | data %s +27ms","1":"https://mydomain.net/engine.io/?EIO=2&transport=polling&t=1377297286212","2":null}
{"0":"engine.io-client:polling polling got data %s +870ms","1":"97:0{\"sid\":\"-huVMBGEnBgJQRAFAAAR\",\"upgrades\":[\"websocket\"],\"pingInterval\":25000,\"pingTimeout\":60000}"}
 {"0":"engine-client:socket socket receive: type \"%s\", data \"%s\" +994ms","1":"open","2":"{\"sid\":\"-huVMBGEnBgJQRAFAAAR\",\"upgrades\":[\"websocket\"],\"pingInterval\":25000,\"pingTimeout\":60000}"}
{"0":"engine-client:socket socket open +2ms"}
{"0":"engine.io-client:polling polling +15ms"}
 {"0":"engine.io-client:polling-xhr xhr poll +862ms"}
{"0":"engine.io-client:polling-xhr sending xhr with url %s | data %s +6ms","1":"https://mydomain.net/engine.io/?EIO=2&transport=polling&t=1377297287099&sid=-huVMBGEnBgJQRAFAAAR","2":null}
{"0":"engine-client:socket flushing %d packets in socket +42ms","1":1}
{"0":"engine.io-client:polling-xhr sending xhr with url %s | data %s +25ms","1":"https://mydomain.net/engine.io/?EIO=2&transport=polling&t=1377297287122&sid=-huVMBGEnBgJQRAFAAAR","2":"243:4THIS_IS_A_MESSAGE_THAT_SOMETIMES_GOES_NOWHERE"}

[mokesmokes]

This is still an issue in 1.1.0. I just noticed in my Android code that I'm delaying the first message after open by 300ms. If I remove this artificial delay, about 10-20% of the time the Android 2.3 browser doesn't do anything when socket.send is called. This is an issue only after the open event - after that all is good.

[rase-]

Weird. Does this still happen? Specific to Android 2.3 (not in newer browsers)?

[mokesmokes]

@rase- yes, very weird. Unfortunately I don't have access to an Android 2.3 device at the moment, but as you can see this was still occurring fairly recently. This was occurring on a Nexus S running 2.3.6. Never seen it happen with Android 4+. I will try again if I get my Gingerbread device back.

[rase-]

Thanks for getting back to me @mokesmokes. Unfortunately I don't have access to an Android 2.3 device either. Browserstack has 2.3 so I'll see if I can debug via that.

@guille, we should set that up in zuul as an alternate test suite or something.

[rase-]

@mokesmokes have you still had this happen to you lately (new releases)?

[mokesmokes]

@rase- I'll give it a shot in a few days. I've always been working around it by delaying the first message, as noted above.

[Remo]

@rase- I haven't seen any issues with polling and 1.3.6, but feature detection seems to fail. When I specify ['websocket', 'polling'] it fails, but it works when I put polling first.

[darrachequesne]

Closed due to inactivity, please reopen if needed.