WebSocket change tracker connection retry time window

[dreamwords]

We encountered a problem when using the websocket change feed.

If the websocket connection is disconnected, the retry time window will increase, finally it would take 10 minutes to retry the connection. This caused the changes cannot be synced in this period.

I know this is actually not the heart beat re-connection logic, and the websocket connection should not be disconnected. However it's not perfect world :-)

Here's the logs:

19:38:59.952‖ WS: TRACE: -[WebSocket socketDidDisconnect:withError:] error= Socket closed by remote peer
19:38:59.952‖ WS: TRACE: -[WebSocket didCloseWithCode:reason:]
19:38:59.952‖ ChangeTracker: CBLWebSocketChangeTracker[0x109d6e000 frontlog]: disconnected with error 1006 / Socket closed by remote peer
19:38:59.952‖ CBLWebSocketChangeTracker[0x109d6e000 frontlog]: Connection error #17, retrying in 600.0 sec: The operation couldn’t be completed. Socket closed by remote peer
19:38:59.953‖ WS: TRACE: -[WebSocketClient dealloc]
19:38:59.953‖ WS: TRACE: -[WebSocket dealloc]
19:48:59.931‖ ChangeTracker: CBLWebSocketChangeTracker[0x109d6e000 frontlog]: Starting...
19:48:59.931‖ SyncVerbose: CBLWebSocketChangeTracker[0x109d6e000 frontlog]: GET xxxxxxxxxxxx

[ngrtesting]

This is actually a fairly major problem for any app that needs to work reliably on intermittent connections that are typical of mobile devices. Each time CBL detects a connection drop, it doubles the amount of time before it retries the connection, even if the previous attempt was successful. This means that after a while, it can be 10 minutes before a retry and before any replication can take place to update the user's data. It seems that there's a "reset retry delay after successful connection" piece of logic missing from the code.

Here's an example log (which shows up because our NAT router tears down inactive connections after 300 seconds). CBL actually makes a successful connection after each "drop" but doubles (rather than resets) its retry delay:

00:39:52.365‖ CBLWebSocketChangeTracker[0x998ffa0 courses]: Connection error #4, retrying in 16.0 sec: The operation couldn’t be completed. Socket closed by remote peer
00:40:08.451‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: WebSocket opened
00:40:08.478‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: Got a message: []
00:40:08.479‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: read 2 bytes
00:45:08.481‖ CBLWebSocketChangeTracker[0x998ffa0 courses]: Connection error #5, retrying in 32.0 sec: The operation couldn’t be completed. Socket closed by remote peer
00:45:40.580‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: WebSocket opened
00:45:40.616‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: Got a message: []
00:45:40.616‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: read 2 bytes
00:50:40.617‖ CBLWebSocketChangeTracker[0x998ffa0 courses]: Connection error #6, retrying in 64.0 sec: The operation couldn’t be completed. Socket closed by remote peer
00:51:44.696‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: WebSocket opened
00:51:44.724‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: Got a message: []
00:51:44.724‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x998ffa0 courses]: read 2 bytes

[snej]

You're right; the HTTP-based changes-feed tracker resets the _retryCount on success, but the WebSocketChangesTracker didn't. Easily fixed!