Continuous replication stops with no warning/error

[Andrew]

We have an iOS application which is set up for one-way, continuous, pull replication and are experiencing an issue whereby replication runs for a while and then just stops.

The failure appears to happen when the replication is idle for more than 5 minutes. From examining the logs at both ends, it seems that CBL is not reliably detecting that a WebSocket has closed and just sits there waiting for more updates (which, without a WebSocket, never arrive). There are no retries or errors logged by CBL – in fact nothing is logged at all after the sync-gateway logs a “WebSocket closed” message – and changes on the server are no longer replicated to the device.

By way of example, the sync-gateway logs typically show:

12:11:08.505349 HTTP:  #134: GET /courses/_local/1c07c124ecf0f2bcdd2f04aa2d01877a95f89fcb
12:11:08.505499 HTTP+: #134:     --> 200   (0.0 ms)
12:11:08.505645 HTTP:  #135: GET /courses/_local/2ea8ff117644aa8087bc1d953fbb331b36f1904f
12:11:08.505749 HTTP+: #135:     --> 200   (0.0 ms)
12:11:08.957366 HTTP:  #136: GET /courses/_changes?feed=websocket
12:11:08.957464 HTTP+: #136:     --> 101 Upgraded to WebSocket protocol  (0.0 ms)
12:11:08.991339 Changes: MultiChangesFeed({*}, {Since:370 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:true Terminator:0xc2108632a0}) ...
12:11:08.991380 Changes+: MultiChangesFeed: channels expand to *:1 ...
12:11:08.991391 Changes+: MultiChangesFeed waiting...
12:11:08.991398 Changes+: Waiting for "courses-sync"'s count to pass 327
12:16:08.991729 HTTP+: #136:     --> WebSocket closed

At this point, CBL will *occasionally* detect the socket has gone away, re-establish connection and log: 

12:16:13.080‖ ChangeTracker: CBLWebSocketChangeTracker[0x8d44570 courses]: disconnected with error 1006 / Socket closed by remote peer
12:16:13.081‖ CBLWebSocketChangeTracker[0x8d44570 courses]: Connection error #1, retrying in 2.0 sec: The operation couldn’t be completed. Socket closed by remote peer
12:16:15.083‖ ChangeTracker: CBLWebSocketChangeTracker[0x8d44570 courses]: Starting...
12:16:15.083‖ SyncVerbose: CBLWebSocketChangeTracker[0x8d44570 courses]: GET //xxxxx.xxxxx.co.uk:4984/courses/_changes?feed=websocket
12:16:15.085‖ ChangeTracker: CBLWebSocketChangeTracker[0x8d44570 courses]: Started... <http://xxxxx.xxxxx.co.uk:4984/courses/_changes?feed=websocket>
12:16:15.174‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x8d44570 courses]: WebSocket opened
12:16:15.204‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x8d44570 courses]: Got a message: []
12:16:15.205‖ ChangeTrackerVerbose: CBLWebSocketChangeTracker[0x8d44570 courses]: read 2 bytes
12:16:15.205‖ ChangeTracker: CBLWebSocketChangeTracker[0x8d44570 courses]: caught up!

Generally, though, CBL does nothing. No further messages appear in the log – ever – and replication is silently dead until the app goes through a background/foreground cycle, at which point replication is restarted.

Interestingly – and perhaps significantly – if we enable logging for “WS” the problem is *much* less likely to occur (although it still does after 30 minutes or so). I can’t begin to imagine why this would be – unless there’s some kind of subtle timing issue at work here.

Anyway, I guess there are two questions:

1. Is the Sync Gateway deliberately closing the WebSocket after 300 seconds and is this normal behaviour when replication is idle? (From looking at the code, I would say yes, this is the default timeout).

2. Why is CBL unreliably detecting the socket closure and allowing the replication to silently fail with no retry? And why does switching on WS logging appear to help?

It’s entirely possible that we don’t have something set up correctly but I’m struggling to see what. I’ve tried the latest CBL build from Jenkins (no difference), sync-gateway is at 1.0.0-23.

Any thoughts gratefully received!

[Jens Alfke]

On Jul 15, 2014, at 5:16 AM, Andrew <ngrte...@googlemail.com> wrote:

The failure appears to happen when the replication is idle for more than 5 minutes. From examining the logs at both ends, it seems that CBL is not reliably detecting that a WebSocket has closed and just sits there waiting for more updates (which, without a WebSocket, never arrive).

This sounds sort of like issue #335, where the retry interval for the WebSocket connection doesn’t reset after a successful connection (which was fixed a few days ago), but you say that CBL never retries?

What I’m suspecting (see below for why) is that something’s wrong with connectivity between CBL and the Gateway — packets aren’t making it through. What’s the network environment like?

1. Is the Sync Gateway deliberately closing the WebSocket after 300 seconds and is this normal behaviour when replication is idle? (From looking at the code, I would say yes, this is the default timeout).

The _changes options are sort of confusing and I just checked with the CouchDB docs to refresh my memory. The ?timeout= parameter will close the connection if no events are sent in that interval; but the ?heartbeat= parameter “overrides any timeout to keep the feed alive indefinitely.” (Note the “else” at changes_api.go:223.) CBL always specifies a heartbeat, so the timeout should never occur.

Now, the heartbeat used by CBL is 300 seconds (CBLChangeTracker.m:27). If the gateway is notifying that the WebSocket connection closed after 300 seconds, what’s likely happening is that connectivity to the client was lost — it sent a heartbeat (an empty message) and never got a TCP ACK packet in response, so the kernel closed the socket.

2. Why is CBL unreliably detecting the socket closure and allowing the replication to silently fail with no retry? And why does switching on WS logging appear to help?

Well, in a situation where connectivity is lost, TCP only detects the problem when it tries to send data and doesn’t get an ACK. I think that the WebSocket client code is in a state where it’s just waiting passively for messages to arrive, so it doesn’t send data on its own and the socket won’t realize something’s wrong. (IIRC, TCP will eventually send a packet after a long idle time, but it’s something like 90 minutes.)

—Jens

[Andrew]

On Tuesday, July 15, 2014 5:44:42 PM UTC+1, Jens Alfke wrote:

 

This sounds sort of like issue #335, where the retry interval for the WebSocket connection doesn’t reset after a successful connection (which was fixed a few days ago), but you say that CBL never retries?

Yes I'm familiar with that issue, but I think it's separate. With #335, CBL sees the disconnect correctly but just incorrectly keeps waiting for longer before retyring. With our case, it never gets that far - it never retries.
 

What I’m suspecting (see below for why) is that something’s wrong with connectivity between CBL and the Gateway — packets aren’t making it through. What’s the network environment like?

App running in the iPad simulator -> NAT router -> high-speed fibre -> internet -> AWS EC2 instance (Ubuntu). The connection is pretty robust to be honest.

Now, the heartbeat used by CBL is 300 seconds (CBLChangeTracker.m:27). If the gateway is notifying that the WebSocket connection closed after 300 seconds, what’s likely happening is that connectivity to the client was lost — it sent a heartbeat (an empty message) and never got a TCP ACK packet in response, so the kernel closed the socket.

I guess it's possible that something along the way (NAT router or AWS maybe) is actively involved in the socket and is hauling down what it considers to be an inactive connection/translation. If it were running to the same 300 second timeout, it would possibly explain why sometimes the Sync Gateway connection closed message gets through to CBL and sometimes it doesn't. Is there any way of adjusting the Sync Gateway heartbeat without rebuilding it to see if that's the case?

.. in a situation where connectivity is lost, TCP only detects the problem when it tries to send data and doesn’t get an ACK. I think that the WebSocket client code is in a state where it’s just waiting passively for messages to arrive, so it doesn’t send data on its own and the socket won’t realize something’s wrong. (IIRC, TCP will eventually send a packet after a long idle time, but it’s something like 90 minutes.)

Ah. But, more generally, isn't that exactly what CBL should be managing? By definition, it's going to be running on devices that are likely to have less than perfect connections. In that scenario, the passive WebSocket mode, where CBL takes no responsibility for checking the connection or attempting its own heartbeat, seems destined to go horribly wrong at some point! Or am I missing something obvious?

[Jens Alfke]

On Jul 15, 2014, at 2:30 PM, Andrew <ngrte...@googlemail.com> wrote:

I guess it's possible that something along the way (NAT router or AWS maybe) is actively involved in the socket and is hauling down what it considers to be an inactive connection/translation.

I recall another developer having issues with AWS closing idle sockets; but in that case I think it was clear to both sides of the connection what happened (the socket was explicitly closed, instead of packets just not arriving any longer.) So this seems different.

Is there any way of adjusting the Sync Gateway heartbeat without rebuilding it to see if that's the case?

The heartbeat interval is actually a parameter sent by the client in the request for the changes feed. It’s exposed in the API as an optional property you can set in the CBLReplication’s options dictionary, kCBLReplicatorOption_Heartbeat. The value is an NSNumber whose units are milliseconds.

Ah. But, more generally, isn't that exactly what CBL should be managing? By definition, it's going to be running on devices that are likely to have less than perfect connections. In that scenario, the passive WebSocket mode, where CBL takes no responsibility for checking the connection or attempting its own heartbeat, seems destined to go horribly wrong at some point! Or am I missing something obvious?

Yes, you’re right. But I don’t remember another case where there’s trouble because of packets just getting dropped. Usually if there’s a situation like that (like losing connectivity) the network interface state will change, which CBL will detect and automatically take the replication offline. I’m not sure what’s going on here.

—Jens