Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Replication Stops After 0 byte reads #155

Closed
lambmj opened this issue Oct 11, 2013 · 13 comments
Closed

Replication Stops After 0 byte reads #155

lambmj opened this issue Oct 11, 2013 · 13 comments
Milestone

Comments

@lambmj
Copy link
Contributor

lambmj commented Oct 11, 2013

In our app, if we start the app and there's no data to replicate to or from the device and the app remains in the foreground for more than a minute, ChangeTracker will warn about 0 byte reads. After that, no data is replicated until the app is suspended and resumed.

We've seen this problem in the stable and master branch (commit d577c26). The only change we made to CBL was to change #if 0 to #if 1 on line 73 of CBLAuthorizer.m. In our configuration, nginx is used to handle ssl and to proxy sync_gateway.

Here's what we're seeing with logging turned on for ChangeTracker using the stable branch:

  1. App startup.
08:11:43.911| Replication: CBL_Puller[https://learntest.infinitecampus.com/learning/] took 0.112 sec; error=(null)
08:11:43.947| Replication: CBL_Pusher[https://learntest.infinitecampus.com/learning/] took 0.128 sec; error=(null)
08:11:45.713| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Starting...
08:11:45.715| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
08:11:45.717| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Started... <https://learntest.infinitecampus.com/learning/_changes?feed=normal&heartbeat=300000&style=all_docs&limit=100&filter=sync_gateway/bychannel&channels=phagen>
08:11:45.720| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Event 1 on <__NSCFInputStream: 0x1755d060>
2013-10-09 08:11:45.733 Teacher[13128:60b] sync in progress, percentDone = 0.000000
08:11:48.819| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: HasBytesAvailable <__NSCFInputStream: 0x1755d060>
08:11:48.828| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning] got status 200
08:11:48.828| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: read 4096 bytes
08:11:48.829| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: HasBytesAvailable <__NSCFInputStream: 0x1755d060>
08:11:48.830| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: read 2436 bytes
08:11:48.830| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: EndEncountered <__NSCFInputStream: 0x1755d060>
08:11:48.830| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Got entire body, 6532 bytes
08:11:48.835| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Starting...
08:11:48.837| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
08:11:48.838| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Started... <https://learntest.infinitecampus.com/learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=phagen:9573&limit=100&filter=sync_gateway/bychannel&channels=phagen>
08:11:48.841| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Event 1 on <__NSCFInputStream: 0x17539c70>
  1. After a minute of idle time, these messages are logged by ChangeTracker and replication stops.
08:12:48.956| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: HasBytesAvailable <__NSCFInputStream: 0x17539c70>
08:12:48.965| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning] got status 200
08:12:48.965| WARNING*** : CBLSocketChangeTracker[0x17548680 learning]: input stream read returned 0
08:12:48.966| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: read 0 bytes
08:12:48.966| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: EndEncountered <__NSCFInputStream: 0x17539c70>
08:12:48.966| ChangeTracker: CBLSocketChangeTracker[0x17548680 learning]: Got entire body, 0 bytes
08:12:48.971| WARNING*** : CBLSocketChangeTracker[0x17548680 learning]: Unparseable response:
08:12:48.971| WARNING*** : CBLSocketChangeTracker[0x17548680 learning]: Server error: JSON parse error: The operation couldn’t be completed. (Cocoa error 3840.)

If we suspend and resume the app, the replications restart. If data is replicated to/from the device during the first minute, the problem doesn't occur.

I made a quick hack to CBLChangeTracker to restart the replication when this condition occurs.

diff --git a/Source/ChangeTracker/CBLSocketChangeTracker.m b/Source/ChangeTracker/CBLSocketChangeTracker.m
index f6b5133..a58d242 100644
--- a/Source/ChangeTracker/CBLSocketChangeTracker.m
+++ b/Source/ChangeTracker/CBLSocketChangeTracker.m
@@ -286,7 +286,9 @@
     BOOL restart = NO;
     NSString* errorMessage = nil;
     NSInteger numChanges = [self receivedPollResponse: input errorMessage: &errorMessage];
-    if (numChanges < 0) {
+    if (input.length == 0) {
+        restart = YES;
+    } else if (numChanges < 0) {
         // Oops, unparseable response. See if it gets special handling:
         if ([self handleInvalidResponse: input])
             return;
@snej
Copy link
Contributor

snej commented Oct 15, 2013

The 0-byte read just seems to indicate EOF; I see these in normal circumstances as well. The stream is supposed to send a separate callback for that, but I think because this is going through the CFHTTPStream layer it might behave differently.

There are known issues where network intermediaries will kill the connection — the -handleInvalidResponse method attempts to work around this by detecting situations we've run into before. But in your situation it sounds like the stream is closed before any response body is received at all.

How is the device reaching the server — through what sort of network, proxies, etc.? It looks as though some intermediary is aggressively killing idle socket connections.

@snej
Copy link
Contributor

snej commented Oct 15, 2013

FYI, I took out the "read 0 bytes" warning a few weeks ago because it's harmless (commit 9f24e35.)

@lambmj
Copy link
Contributor Author

lambmj commented Oct 15, 2013

Thanks, I've changed the title of the issue to reflect that the warning is no longer there.

We're using nginx for SSL and to proxy sync_gateway as described briefly above.

In our case the consequences are far from harmless as replication stops until the user kills the app and restarts it or backgrounds the app and resumes it. Here's a trace created less than a week ago using commit d577c26.

12:16:00.993∥ Sync: App activated -- restarting all replications
12:16:00.993∥ Sync: ReplicatorManager scanning existing _replicator docs...
12:16:00.994∥ Sync: ReplicatorManager: {5D613642-AF27-4237-A84C-2B1552DA0AB4 #2-fcb10d1020f2d5d919c54923a5061ac4} was created
12:16:00.994∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] STARTING ...
12:16:00.996∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Reachability state = <learntest.infinitecampus.com>:unreachable (00)
12:16:00.996∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #2-fcb10d1020f2d5d919c54923a5061ac4} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605";
    "_replication_state" = triggered;
    "_replication_state_time" = 1381338960;
}
12:16:01.002∥ Sync: ReplicatorManager: {72F9C062-076B-415D-BDD4-5B1A8727D7BB #2-95394b0d3e4c0e780f965f1718ef833a} was created
12:16:01.002∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/] STARTING ...
12:16:01.004∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: Reachability state = <learntest.infinitecampus.com>:reachable (02)
12:16:01.004∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: Going online
12:16:01.006∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
12:16:01.007∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
12:16:01.007∥ Sync: ReplicatorManager: Updating {72F9C062-076B-415D-BDD4-5B1A8727D7BB #2-95394b0d3e4c0e780f965f1718ef833a} with {
    "_replication_id" = "4336BB26-197D-4B5E-8B0D-121E8495D30B";
    "_replication_state" = triggered;
    "_replication_state_time" = 1381338961;
}
12:16:01.009∥ Sync: ReplicatorManager done scanning.
12:16:01.009∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Reachability state = <learntest.infinitecampus.com>:reachable (02)
12:16:01.009∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Going online
12:16:01.010∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
12:16:01.010∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
12:16:01.011∥ Sync: ReplicatorManager: Updating {72F9C062-076B-415D-BDD4-5B1A8727D7BB #3-2098c2037648ac0d7ad9b63d8c83ee42} with {
    "_replication_id" = "4336BB26-197D-4B5E-8B0D-121E8495D30B";
}
12:16:01.011∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #3-581141cdd963eba9f03b7345c7273c03} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605";
}
12:16:06.581∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Logging in with CBLBasicAuthorizer at /_session ...
12:16:07.458∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: Logging in with CBLBasicAuthorizer at /_session ...
12:16:11.843∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Successfully logged in!
12:16:11.858∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Replicating from lastSequence=(null)
12:16:12.691∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: Successfully logged in!
12:16:12.711∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: Replicating from lastSequence=(null)
12:16:12.712∥ Sync: CBL_Pusher[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
12:16:12.712∥ Sync: ReplicatorManager: Updating {72F9C062-076B-415D-BDD4-5B1A8727D7BB #3-2098c2037648ac0d7ad9b63d8c83ee42} with {
    "_replication_id" = "4336BB26-197D-4B5E-8B0D-121E8495D30B";
}
12:16:15.959∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Received 8 changes
12:16:15.959∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (0/8, active=1 (batch=8, net=1), online=1)
12:16:15.959∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: Caught up with changes!
12:16:15.960∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] queued 8 remote revisions from seq=045150170:135 (3 in bulk, 5 individually)
12:16:15.960∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] bulk-fetching 3 remote revisions...
12:16:15.962∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #3-581141cdd963eba9f03b7345c7273c03} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605";
}
12:16:15.990∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] inserted 1 revs in 0.007 sec (150.5/sec)
12:16:15.990∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (1/8, active=1 (batch=0, net=5), online=1)
12:16:15.991∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #3-581141cdd963eba9f03b7345c7273c03} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605";
}
12:16:16.021∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] checking 3 bulk-fetched remote revisions
12:16:16.021∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] bulk-fetch didn't work for 1 of 3 revs; getting individually
12:16:17.007∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] inserted 7 revs in 0.016 sec (441.5/sec)
12:16:17.007∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (1/8, active=0 (batch=0, net=0), online=1)
12:16:17.007∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (8/8, active=0 (batch=0, net=0), online=1)
12:16:17.007∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #3-581141cdd963eba9f03b7345c7273c03} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605";
}


12:16:22.007∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/] checkpointing sequence=045150170:11683
12:17:15.998∥ �WARNING*** : CBLSocketChangeTracker[0xb1a10f0 learning]: Unparseable response:

12:17:15.999∥ �WARNING*** : CBLSocketChangeTracker[0xb1a10f0 learning]: Server error: JSON parse error: The operation couldn’t be completed. (Cocoa error 3840.)
12:17:15.999∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: ChangeTracker stopped; error=Error Domain=CBLChangeTracker Code=589 "The operation couldn’t be completed. (CBLChangeTracker error 589.)"
12:17:15.999∥ Sync: CBL_Puller[https://learntest.infinitecampus.com/learning/]: postProgressChanged (8/8, active=0 (batch=0, net=0), online=1)
12:17:15.999∥ Sync: ReplicatorManager: Updating {5D613642-AF27-4237-A84C-2B1552DA0AB4 #3-581141cdd963eba9f03b7345c7273c03} with {
    "_replication_id" = "8B1244AD-BC9B-4221-BD8D-6DE215758605”;

@snej
Copy link
Contributor

snej commented Oct 15, 2013

We're using nginx for SSL and to proxy sync_gateway as described briefly above.

Is the device connecting over WiFi or cell? If the latter, what carrier? Something is killing the socket after a minute of idle time. Is there some setting in nginx that could be doing that?

@lambmj
Copy link
Contributor Author

lambmj commented Oct 16, 2013

The device is connected over WiFi. The same problem occurs in the simulator as well as on a device. We do configure ssl and proxies but little else. Our original nginx config can be found here.

I did find that I can control the behavior in nginx by adding proxy_read_timeout to each sync_gateway proxy. I can't find a means of turning the timeout off completely, but I can set it to a very large number, e.g one week.

    location  /learning {
        proxy_pass http://127.0.0.1:3984/learning;
        proxy_read_timeout 168h;
    }

This will work but I question the behavior where CBL silently stops the replication when it encounters this condition. There's no doubt that others will encounter the same problem. It seems to me that CBL should either (a) restart the connection or (b) provide a notification that an error has occurred that an app can monitor so that the app can restart the connection.

@snej
Copy link
Contributor

snej commented Oct 17, 2013

If you change that setting, does it make this problem go away?

I can work on making the replicator recover better, but I'd still like to know where this socket disconnect came from...

@snej
Copy link
Contributor

snej commented Oct 17, 2013

Actually, something else must be going wrong if the client doesn't receive any response data before the socket is closed. Both CouchDB and the Sync Gateway will immediately send back the opening of the JSON response — {"results":[ — and then wait for changes to appear before sending back the rest. CBLSocketChangeTracker checks for that response data, and if it's already received that prologue before the socket went bye-bye it knows it's talking to a real server and will retry.

tl;dr: From your logs it looks like the client reads the initial changes feed fine, but then when it makes another request to wait for future changes, the socket never connects properly, never receives the expected initial data, and gets killed after a minute.

Does the Sync Gateway log the second _changes request at all?

@lambmj
Copy link
Contributor Author

lambmj commented Oct 17, 2013

Yes. Here's a run I made just now with the default nginx timeout in place. The run was made using the stable branch with the patch above in place.

xcode log

10:02:29.904| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Starting...
10:02:29.905| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
10:02:29.905| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Started... <https://learndev.infinitecampus.com/learning/_changes?feed=normal&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady>
10:02:29.905| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Event 1 on <__NSCFInputStream: 0xb895eb0>
2013-10-17 10:02:29.912 Teacher[20031:70b] sync in progress, percentDone = 0.000000
10:02:30.038| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: HasBytesAvailable <__NSCFInputStream: 0xb895eb0>
10:02:30.042| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning] got status 200
10:02:30.042| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: read 33 bytes
10:02:30.042| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: EndEncountered <__NSCFInputStream: 0xb895eb0>
10:02:30.042| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Got entire body, 33 bytes
10:02:30.043| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Starting...
10:02:30.043| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
10:02:30.043| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Started... <https://learndev.infinitecampus.com/learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady>
10:02:30.043| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Event 1 on <__NSCFInputStream: 0xba8da60>
2013-10-17 10:02:30.043 Teacher[20031:70b] sync completed
10:03:30.272| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: HasBytesAvailable <__NSCFInputStream: 0xba8da60>
10:03:30.277| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning] got status 200
10:03:30.277| �WARNING*** : CBLSocketChangeTracker[0xb88bea0 learning]: input stream read returned 0
10:03:30.277| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: read 0 bytes
10:03:30.277| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: EndEncountered <__NSCFInputStream: 0xba8da60>
10:03:30.277| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Got entire body, 0 bytes
10:03:30.278| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Starting...
10:03:30.279| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
10:03:30.279| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Started... <https://learndev.infinitecampus.com/learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady>
10:03:30.279| ChangeTracker: CBLSocketChangeTracker[0xb88bea0 learning]: Event 1 on <__NSCFInputStream: 0xba8cc70>

sync_gateway.log

10:02:15.664292 HTTP:  #14853: POST /learning/_session  (ADMIN)
10:02:15.808902 HTTP:  #14854: GET /learning/_local/9a2431877aed7d2697619798236032830f3ff163  (as cbrady)
10:02:15.808967 HTTP:  #14855: GET /learning/_local/62acf8f3690df5914ee8f53a15f38d1ce2a8b229  (as cbrady)
10:02:15.940335 HTTP:  #14856: GET /learning/_changes?feed=normal&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady  (as cbrady)
10:02:16.070012 HTTP:  #14857: GET /learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady  (as cbrady)
10:03:16.302013 HTTP:  #14858: GET /learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1219&limit=100&filter=sync_gateway/bychannel&channels=cbrady  (as cbrady)

@snej
Copy link
Contributor

snej commented Oct 17, 2013

OK, I finally think I have an idea what's going on here.

Hypothesis: your nginx proxy is handling an HTTP chunked-mode response by buffering up the data until it's complete, and only then sending it on. This approach doesn't work well with an open-ended response like a longpoll — the server won't pass on the beginning of the response until an indefinite amount of time later when the server sends the changes. (I've run into this behavior twice now in different HTTP parsers, one of them being Apple's NSURLConnection.)

Experiment: Try bypassing nginx and making the iOS device connect directly to the Sync Gateway. The problem should go away.

Conclusions (assuming the hypothesis is validated):

  1. CBLSocketChangeTracker should handle this case: if it gets disconnected, and the HTTP headers were received but the response is empty, it should do the same thing as if it had received the {"results":[ prologue, on the assumption that a proxy might not have passed it through. That is, it should retry the connection. This is functionally equivalent to your hack, but cleaner.
  2. Sync Gateway needs to support the heartbeat request parameter, which periodically sends a CRLF to stop proxies from timing out idle sockets. The change tracker uses a 5-minute heartbeat by default, but if it gets cut off earlier than that it will switch to a shorter one to work around the problem.

@snej
Copy link
Contributor

snej commented Oct 17, 2013

Heartbeat support is couchbase/sync_gateway#164.

@lambmj
Copy link
Contributor Author

lambmj commented Oct 17, 2013

I think your hypothesis is correct. Here are the results going directly against sync_gateway:

xcode log

14:08:25.038| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Starting...
14:08:25.039| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
14:08:25.039| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Started... <http://learndev.infinitecampus.com:3984/learning/_changes?feed=normal&heartbeat=300000&style=all_docs&since=cbrady:1224&limit=100&filter=sync_gateway/bychannel&channels=cbrady>
14:08:25.039| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Event 1 on <__NSCFInputStream: 0xa7a1d20>
14:08:25.156| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: HasBytesAvailable <__NSCFInputStream: 0xa7a1d20>
14:08:25.156| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning] got status 200
14:08:25.156| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: read 14 bytes
14:08:25.158| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: HasBytesAvailable <__NSCFInputStream: 0xa7a1d20>
14:08:25.862| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: read 19 bytes
14:08:25.863| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: HasBytesAvailable <__NSCFInputStream: 0xa7a1d20>
14:08:25.863| �WARNING*** : CBLSocketChangeTracker[0xa79e930 learning]: input stream read returned 0
14:08:25.863| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: read 0 bytes
14:08:25.863| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: EndEncountered <__NSCFInputStream: 0xa7a1d20>
14:08:25.863| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Got entire body, 33 bytes
14:08:25.863| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Starting...
14:08:25.864| ChangeTracker: Changes feed using proxy {
    kCFProxyTypeKey = kCFProxyTypeNone;
}
14:08:25.864| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Started... <http://learndev.infinitecampus.com:3984/learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1224&limit=100&filter=sync_gateway/bychannel&channels=cbrady>
14:08:26.552| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: Event 1 on <__NSCFInputStream: 0xb1502e0>
14:08:26.609| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: HasBytesAvailable <__NSCFInputStream: 0xb1502e0>
14:08:26.609| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning] got status 200
14:08:26.609| ChangeTracker: CBLSocketChangeTracker[0xa79e930 learning]: read 14 bytes

sync_gateway log

14:08:11.026672 HTTP:  #125: GET /learning/_changes?feed=normal&heartbeat=300000&style=all_docs&since=cbrady:1224&limit=100&filter=sync_gateway/bychannel&channels=cbrady  (as cbrady)
14:08:11.027377 HTTP:  #126: POST /learning/_revs_diff  (as cbrady)
14:08:12.480142 HTTP:  #127: GET /learning/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=cbrady:1224&limit=100&filter=sync_gateway/bychannel&channels=cbrady  (as cbrady)

@snej snej closed this as completed in 88f59f7 Oct 17, 2013
@snej
Copy link
Contributor

snej commented Oct 17, 2013

I also added heartbeat support to the gateway. If you can update your gateway, please try with nginx and the connections shouldn't be dropped anymore, because the server will be sending a CRLF every 30 seconds.

@lambmj
Copy link
Contributor Author

lambmj commented Oct 29, 2013

Just got back to this, sorry for the delay. For reference, I'm using CBL 4f82865 and sync_gateway 27d9611146251fa58b32839b552b26be8874a43a.

The sync_gateway fix (f9d4aa5ba40d143815f07008580b5145e3dcde21) works great as long as the heartbeat sent by CBL is changed. This change is needed because sync_gateway will use heartbeat via h.getRestrictedIntQuery("heartbeat", ...) if it is present in the request. Currently CBLChangeTracker.m is sending the default value of (5 * 60.0). I changed the default value to (25.0).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants