couchbase-lite-ios and tcp keep-alive timeout

[MobDev]

Hey guys, I am using couchbase-lite-ios and seeing some weird behavior on tcp connections. Could you please help me to understand this.
 
After minimizing iOS App, TCP connection on the server is open for approximately 5-6 mins. if I close the App TCP connection is closes right away.

I am not using continuous replication and I have tried stopping replication as well.

Thanks a lot.

Cheers,
Dev

 

[MobDev]

I am using netstat -an | grep 4984 | grep ESTABLISHED to check open connection on the server.

Also why is tcp connection keeps open for approx 5 mins?

Thanks

[Jens Alfke]

On Feb 24, 2015, at 1:29 PM, MobDev <ehdev...@gmail.com> wrote:

After minimizing iOS App, TCP connection on the server is open for approximately 5-6 mins. if I close the App TCP connection is closes right away.

By “minimize” you mean backgrounding the app, i.e. returning to the springboard or launching another app, right?

And by “closing” I think you mean double-tapping Home and then swiping up on the app … this kills the process so I’m not surprised it closes the socket too :)

I am not using continuous replication and I have tried stopping replication as well.

A continuous pull replication will leave a socket open (a WebSocket on /dbname/_changes) until stopped.

A non-continuous pull replication doesn’t leave anything open (it makes a regular HTTP GET to /dbname/_changes.)

So this is unexpected … can you find out what HTTP request was made by this open socket?

Also, enabling SyncVerbose and RemoteRequest logging will show information about what connections are being made.

—Jens

[MobDev]

Thank you for response Jens.

Yes, by minimize I meant background app.
Yes, by closing I meant double-tap swipe up

Yes, that's what I was thinking how is tcp connection is closed when I kill the app.

Following is the http request.

*****************************************************

	GET /mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8 HTTP/1.1
Host	10.3.4.60:4984
Accept	application/json
Cookie	SyncGatewaySession=6190a2ba06f145704801a687bdbf81a43ce56cdf
User-Agent	CouchbaseLite/1.0.3 (iOS)
Accept-Language	en-us
Accept-Encoding	gzip, deflate
Connection	keep-alive

*****************************************************

Apologies for the long logs

Following are SyncVerbose | RemoteRequest logs

2015-02-25 17:25:52.410 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:52.411 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: GET _local/345aa64dcacc56c1dcdebf264e90053d1d9504d2
2015-02-25 17:25:52.411 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Starting...
2015-02-25 17:25:52.412 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:52.416 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:52.417 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: GET _local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8
2015-02-25 17:25:52.417 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Starting...
2015-02-25 17:25:52.418 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:52.471 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Got response, status 200
2015-02-25 17:25:52.472 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Finished loading
2015-02-25 17:25:52.473 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: Received 0 revs
2015-02-25 17:25:52.474 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
2015-02-25 17:25:52.474 TestApp[279:27123] Replication: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/] took 0.059 sec; error=(null)
2015-02-25 17:25:52.476 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Got response, status 200
2015-02-25 17:25:52.476 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Finished loading
2015-02-25 17:25:52.477 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/] starting ChangeTracker: mode=0, since=2730
2015-02-25 17:25:52.478 TestApp[279:27123] SyncVerbose: CBLSocketChangeTracker[0x174172840 mcd_sync_gateway]: POST //10.3.4.60:4984/mcd_sync_gateway/_changes
2015-02-25 17:25:52.553 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/1, active=1 (batch=0, net=2), online=1)
2015-02-25 17:25:52.553 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: Received #2731 {716FD4A7-C7BA-4BED-9B57-859D3939EAB0 #10-20d8ccc3aaa3016305110ba2ac306fc9}
2015-02-25 17:25:52.555 TestApp[279:27123] SyncVerbose: *** CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: BEGIN processInbox (1 sequences)
2015-02-25 17:25:52.555 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: Looking up (
    "{716FD4A7-C7BA-4BED-9B57-859D3939EAB0 #10-20d8ccc3aaa3016305110ba2ac306fc9}"
)
2015-02-25 17:25:52.556 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (1/1, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:52.557 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: no new remote revisions to fetch
2015-02-25 17:25:52.557 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: Setting lastSequence to 2731 (from 2730)
2015-02-25 17:25:52.557 TestApp[279:27123] SyncVerbose: *** CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: END processInbox (lastSequence=2731)
2015-02-25 17:25:52.557 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (1/1, active=0 (batch=0, net=0), online=1)
2015-02-25 17:25:52.558 TestApp[279:27123] Replication: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/] took 0.152 sec; error=(null)
2015-02-25 17:25:52.558 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: PUT _local/345aa64dcacc56c1dcdebf264e90053d1d9504d2
2015-02-25 17:25:52.559 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Starting...
2015-02-25 17:25:52.633 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Got response, status 201
2015-02-25 17:25:52.633 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Finished loading
2015-02-25 17:25:56.159 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.159 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: GET _local/345aa64dcacc56c1dcdebf264e90053d1d9504d2
2015-02-25 17:25:56.159 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Starting...
2015-02-25 17:25:56.161 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.166 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.167 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: GET _local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8
2015-02-25 17:25:56.167 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Starting...
2015-02-25 17:25:56.167 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.194 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Got response, status 200
2015-02-25 17:25:56.194 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/345aa64dcacc56c1dcdebf264e90053d1d9504d2]: Finished loading
2015-02-25 17:25:56.195 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/] starting ChangeTracker: mode=0, since=2731
2015-02-25 17:25:56.196 TestApp[279:27123] SyncVerbose: CBLSocketChangeTracker[0x17016e700 mcd_sync_gateway]: POST //10.3.4.60:4984/mcd_sync_gateway/_changes
2015-02-25 17:25:56.201 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Got response, status 200
2015-02-25 17:25:56.202 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[GET http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Finished loading
2015-02-25 17:25:56.203 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: Received 1 revs
2015-02-25 17:25:56.204 TestApp[279:27123] SyncVerbose: *** CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: BEGIN processInbox (1 sequences)
2015-02-25 17:25:56.204 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: POST _revs_diff
2015-02-25 17:25:56.204 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_revs_diff]: Starting...
2015-02-25 17:25:56.205 TestApp[279:27123] SyncVerbose: *** CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: END processInbox (lastSequence=12)
2015-02-25 17:25:56.239 TestApp[279:27123] SyncVerbose: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
2015-02-25 17:25:56.239 TestApp[279:27123] Replication: CBL_Puller[http://10.3.4.60:4984/mcd_sync_gateway/] took 0.084 sec; error=(null)
2015-02-25 17:25:56.261 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_revs_diff]: Got response, status 200
2015-02-25 17:25:56.261 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_revs_diff]: Finished loading
2015-02-25 17:25:56.265 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: Sending (
    "{716FD4A7-C7BA-4BED-9B57-859D3939EAB0 #11-8d487a51e6bacb9ad8f61c7a26bcaae4}"
)
2015-02-25 17:25:56.265 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (0/1, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.265 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: POST _bulk_docs
2015-02-25 17:25:56.266 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_bulk_docs]: Starting...
2015-02-25 17:25:56.377 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_bulk_docs]: Got response, status 201
2015-02-25 17:25:56.378 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[POST http://10.3.4.60:4984/mcd_sync_gateway/_bulk_docs]: Finished loading
2015-02-25 17:25:56.380 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: Setting lastSequence to 13 (from 12)
2015-02-25 17:25:56.381 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: Sent (
    "{716FD4A7-C7BA-4BED-9B57-859D3939EAB0 #11-8d487a51e6bacb9ad8f61c7a26bcaae4}"
)
2015-02-25 17:25:56.382 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (1/1, active=1 (batch=0, net=1), online=1)
2015-02-25 17:25:56.382 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: postProgressChanged (1/1, active=0 (batch=0, net=0), online=1)
2015-02-25 17:25:56.382 TestApp[279:27123] Replication: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/] took 0.219 sec; error=(null)
2015-02-25 17:25:56.383 TestApp[279:27123] SyncVerbose: CBL_Pusher[http://10.3.4.60:4984/mcd_sync_gateway/]: PUT _local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8
2015-02-25 17:25:56.384 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Starting...
2015-02-25 17:25:56.449 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Got response, status 201
2015-02-25 17:25:56.450 TestApp[279:27123] RemoteRequest: CBLRemoteJSONRequest[PUT http://10.3.4.60:4984/mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8]: Finished loading


Thanks a lot


Cheers,
Dev

[Jens Alfke]

> GET /mcd_sync_gateway/_local/ec8541ac462a90968e7c035e0a80f7b16b7d49a8 HTTP/1.1

That’s just a tiny request to get a checkpoint from the server (a hundred bytes or so.) There were probably further requests sent over that socket using KeepAlive; did you look for those?

> Following are SyncVerbose | RemoteRequest logs

Are these the complete logs? I don’t see the messages I’d expect to see at the start of replication. And at the end of the logs you posted, the replicator is still active (if it had stopped there would have been messages saying so.)

(Actually I’m not seeing “Sync” log messages. Normally setting SyncVerbose should also enable Sync; could you enable it as well?)

—Jens