libPusher doesn't seem to have any timeouts on initial connection?
Closed this issue · 5 comments
A tester reported to me that while they were testing the app, it didn't seem to react to any changes on the server for a period of 20-30 minutes (which it should have done since they're supposed to be sent through a Pusher channel).
I have Logentries logs configured there, so I checked them, and it seems that the Pusher client has been trying to connect for 20 minutes and didn't give up during that period. Shouldn't there be some kind of timeouts configured to detect such cases?
This is what I normally get with a good connection:
2015-07-30 13:57:03:369 [INFO] OrderManager: Application became active
2015-07-30 13:57:03:370 [INFO] Order Pusher connecting to order_113155
2015-07-30 13:57:04:522 [INFO] Order Pusher connected successfully
2015-07-30 13:57:04:522 [INFO] OrderManager: Reloading order to check if we haven't missed any updates
And this is what happened in Logentries:
28 Jul 2015 18:30:00.336 [level:INFO] OrderManager: Application became active
28 Jul 2015 18:30:00.336 [level:INFO] Order Pusher connecting to order_113134
28 Jul 2015 18:47:21.096 [level:INFO] Order tracking screen: disabling minimized mode
28 Jul 2015 18:50:00.397 [level:INFO] Stopping ETA timer
28 Jul 2015 18:50:00.397 [level:INFO] OrderManager: Application became inactive
28 Jul 2015 18:50:00.397 [level:INFO] Order Pusher disconnecting from order_113134
"Order Pusher connecting" is called before pusher.connect(), and "Order Pusher connected" is called in pusher(connectionDidConnect:). I also have callbacks set up for pusher(connection:didDisconnectWithError:), pusher(connection:failedWithError:), pusher(didFailToSubscribeToChannel:withError:) and pusher(didReceiveErrorEvent:), and these weren't called during that period.
I'm also setting these timeouts on the Pusher client object, but they don't seem to change anything in this case:
pusher.connection.activityTimeout = 30.0
pusher.connection.pongTimeout = 15.0
Another time it did time out but only after 20 minutes:
28 Jul 2015 22:36:17.004 [level:INFO] Order Pusher connecting to order_113139
28 Jul 2015 22:36:17.004 [level:INFO] OrderManager: Order 113139 was updated: BeingPrepared
28 Jul 2015 22:36:17.004 [level:INFO] Order tracking screen: current order: 113139 (BeingPrepared)
28 Jul 2015 22:36:17.004 [level:INFO] Starting ETA timer, ETA: 2015-07-28 20:56:15 +0000
28 Jul 2015 22:56:07.081 [level:WARN] Order Pusher failed to connect because of error: Error Domain=NSPOSIXErrorDomain Code=60 "The operation couldn’t be completed. Operation timed out"
28 Jul 2015 22:56:07.283 [level:INFO] OrderManager: Reloading order to check if we haven't missed any updates
And a moment later it timed out only after a minute or so:
28 Jul 2015 22:56:22.085 [level:INFO] Order Pusher reconnecting
28 Jul 2015 22:56:22.271 [level:INFO] Order Pusher connecting to order_113139
28 Jul 2015 22:57:37.129 [level:WARN] Order Pusher failed to connect because of error: Error Domain=NSPOSIXErrorDomain Code=60 "The operation couldn’t be completed. Operation timed out"
28 Jul 2015 22:57:37.327 [level:INFO] OrderManager: Reloading order to check if we haven't missed any updates
I guess it might depend on whether it's getting some tiny bits of data during that period, but never getting a whole response, vs. not getting anything at all?
And here, a different error code after 5 minutes:
28 Jul 2015 23:24:06.764 [level:INFO] Order Pusher connecting to order_113142
28 Jul 2015 23:24:06.764 [level:INFO] OrderManager: Order 113142 was updated: WaitingForDriver
28 Jul 2015 23:24:06.764 [level:INFO] Order tracking screen: current order: 113142 (WaitingForDriver)
28 Jul 2015 23:24:06.764 [level:INFO] Starting ETA timer, ETA: 2015-07-28 21:48:37 +0000
28 Jul 2015 23:26:38.940 [level:INFO] Order tracking screen: enabling minimized mode
28 Jul 2015 23:26:40.015 [level:INFO] Order tracking screen: disabling minimized mode
28 Jul 2015 23:29:07.654 [level:WARN] Order Pusher failed to connect because of error: Error Domain=kCFErrorDomainCFNetwork Code=2 "The operation couldn’t be completed. (kCFErrorDomainCFNetwork error 2.)" UserInfo=0x178072fc0 {kCFGetAddrInfoFailureKey=8}
This seems like pretty strange behaviour. I know this is an old issue so it might not be relevant anymore, but have you seen anything like this since @mackuba ?
Closing for now - feel free to reopen if still relevant.