Replication could not be cancelled properly

J Chris Anderson added a comment - 24/Aug/11 1:24 PM We are currently pointing the big array of test we already have for the server product, at the mobile product. I expect it to point at a lot of things like this. For issues like this (core logic), it is helpful when reporting, to see if it reproduces when run against Couchbase Single as well, or if it is specific to iOS, Android, or both. We'll track this one down, hopefully as part of a larger batch we find with the test suite.

Andreas Klöber added a comment - 01/Sep/11 6:52 AM Retest with version 44a47ce-git: concerning 1. and 2.: Now the cancellation request is accepted almost immediately (no blocking for 15 seconds) concerning 3.: The thread still blocks in infinitely (local disk size remains unchanged) So the main problem still exists!

Andreas Klöber added a comment - 01/Sep/11 12:37 PM Followup concerning 1.: Blocking when replication is cancelled still occures in conjunction with the behavior described in CBMA-4 .

J Chris Anderson added a comment - 02/Sep/11 9:30 PM So it looks like this has been narrowed down to something like: canceling a replication which is otherwise stuck, fails. As soon as we have a test case which can reliably get replication stuck, we'll see what we can do about how a cancel request is handled in that case.

Andreas Klöber added a comment - 12/Sep/11 2:33 AM No, it hasn't been narrowed down to "canceling a replication which is otherwise stuck, fails". Only the blocking for a certain amount of time (see 1.) has been improved, but it still occurs in conjunction with CBMA-4 . That is what my comment on 01/Sep/11 was about. The major part of this issue, is the blocking of the calling thread to _replicate, allthough the replication has been cancelled (see 3.). Furthermore, when using Android's HTTP client implementation, it is not possible to cancel the request ourselves, because of another Android-specific bug (see http://code.google.com/p/android/issues/detail?id=7933; fixed in Gingerbread). So it is not possible to implement some kind of workaround to cancel the request explicitely.

Dale Harvey added a comment - 12/Sep/11 7:14 PM - edited 1. Further HTTP-GET calls to the local database URL (sent peridodically to get the local disk_size for estimating replication progress) are blocked This is unrelated to replication and if you see this behavior again it would be useful to file separately, it may be an issue in the http client as its sounds unfamiliar to the server. 3. Anyway, the thread that initiated the replication still blocks. No response, indicating that replication has been terminated, is delivered back to the client. The local disk_size stays unchanged. The replication cancels fine, however the client that made is never notified of the cancellation, this is fixed in http://review.couchbase.org/#change,9532

Andreas Klöber added a comment - 10/Oct/11 1:34 AM - edited Retest with latest developer preview: The cancellation command blocks for approx. 5s and succeeds afterwards (on previous releases the cancellation command had been cancelled in less than 1s). The replication thread still blocks infinitely. Regarding Dale's comment: Is this still a server-side issue? If so, when will the fix on the server-side be released?

J Chris Anderson added a comment - 10/Oct/11 9:29 AM We should verify if this fix has indeed been merged to the Android branch, and retest.

Marty Schoch added a comment - 11/Oct/11 2:50 PM I verified Dale's commit is on the Android branch. When I run the following test against my local Couchbase 2.0.0-dev4 I see the behavior described in the bug report, the first request blocks forever. However, when I run this against the Android Couchbase, I see the request return immediately with the correct error message from Dale's commit. After redirecting the ports to Android device I run: curl -H "Content-Type: application/json" -X POST -d '{"source":" http://couchbase.ic.ht/grocery-sync ","target":"repl"}' http://localhost:5985/_replicate This startes a non-continuous replication that will block until complete. Then in another window: curl -H "Content-Type: application/json" -X POST -d '{"source":" http://couchbase.ic.ht/grocery-sync ","target":"repl", "cancel":true}' http://localhost:5985/_replicate Which immediately returns: {"ok":true,"_local_id":"4973799a394eea2471aaa1b74ff144bd"} Then looking back at the first console I see: {"error":"cancelled"} Which is the message you would expect to see based on Dale's commit.

Marty Schoch added a comment - 11/Oct/11 3:18 PM I've also added a test to our workload tester app: https://github.com/mschoch/CouchbaseAndroidTester The test: https://github.com/mschoch/CouchbaseAndroidTester/blob/master/src/com/couchbase/androidtester/workloads/impl/CancelPullReplication.java implements my understanding of the scenario using Ektorp. Ektorp is using the Android version of HttpClient. The output I see from this test is: 10-11 16:07:38.460: VERBOSE/CouchbaseTester(2725): Couchbase has started 10-11 16:07:46.270: VERBOSE/CouchbaseTester(2725): Starting Replication 10-11 16:07:48.270: VERBOSE/CouchbaseTester(2725): Starting Replication Cancelation 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): Replication Error: 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): org.ektorp.DbAccessException: org.ektorp.android.http.AndroidHttpResponse@406e08b0 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): URI: /_replicate 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): Response Body: 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): { 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): "error" : "cancelled" 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): } 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at org.ektorp.http.StdResponseHandler.createDbAccessException(StdResponseHandler.java:44) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at org.ektorp.http.StdResponseHandler.error(StdResponseHandler.java:62) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at org.ektorp.http.RestTemplate.handleResponse(RestTemplate.java:98) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at org.ektorp.http.RestTemplate.post(RestTemplate.java:57) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at org.ektorp.impl.StdCouchDbInstance.replicate(StdCouchDbInstance.java:84) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at com.couchbase.androidtester.workloads.impl.CancelPullReplication$1.run(CancelPullReplication.java:35) 10-11 16:07:48.970: VERBOSE/CouchbaseTester(2725): at java.lang.Thread.run(Thread.java:1020) 10-11 16:07:49.700: VERBOSE/CouchbaseTester(2725): Finished Replication Cancelation: true It seems to be behaving as expected in my tests.

Dale Harvey added a comment - 12/Oct/11 8:54 AM To reproduce you need to block the replication requests from happening in the middle of the process (I turn off my wifi), the replicator will then start retrying with an exponential backoff if you cancel the replication during that period it cancels fine however forgets to notify the client that made the request original request. I managed to reproduce it just now, the above patch fixed it for certain situations but not all it seems. To make it clear nothing is ever blocked inside couch and the replication is cancelled fine, its purely an issue with notifying the client that it was cancelled, looking into the patch now

Dale Harvey added a comment - 12/Oct/11 12:08 PM After spending a lot of time testing this, it looks like marty was right, my original test was against an old codebase, on the current android release I cannot reproduce a situation where the client never gets notified of a replication success / failure. If the replicator source loses connectivity then the request can take around 4/5 minutes to fail due to the exponential backoff, but if its cancelled / fails or succeeds it is be notified immediately.

Perry Krug added a comment - 18/Oct/11 8:58 AM This is still not working for the customer. It may be related to cancelling a replication when multiple replications are going on...have you tested that scenario?

Marty Schoch added a comment - 01/Nov/11 2:19 PM Test case for reproducing this issue

Marty Schoch added a comment - 01/Nov/11 2:20 PM I attached the testcase for reproducing this issue. In my tests the responses are just delayed, not blocked forever... In my testing I've found: 10-26 10:39:50.820: INFO/ CBMA-3 (19101): 9: starting replication 10-26 10:39:52.830: INFO/ CBMA-3 (19101): 9: starting replication cancellation 10-26 10:39:53.110: INFO/ CBMA-3 (19101): 9: response of replication cancel request: {"ok":true,"_local_id":"6d460892957bdfd5e1726b1b68bc0e8b"} 10-26 10:45:04.320: INFO/ CBMA-3 (19101): 10: starting replication 10-26 10:45:06.330: INFO/ CBMA-3 (19101): 10: starting replication cancellation 10-26 10:45:06.660: INFO/ CBMA-3 (19101): 10: response of replication cancel request: {"ok":true,"_local_id":"6d460892957bdfd5e1726b1b68bc0e8b"} 10-26 10:45:41.650: INFO/ CBMA-3 (19101): 11: starting replication 10-26 10:45:43.650: INFO/ CBMA-3 (19101): 11: starting replication cancellation 10-26 10:45:44.190: INFO/ CBMA-3 (19101): 11: response of replication cancel request: {"ok":true,"_local_id":"6d460892957bdfd5e1726b1b68bc0e8b"} 10-26 10:45:44.210: INFO/ CBMA-3 (19101): 10: response of replication request: {"error":"cancelled"} 10-26 10:45:44.210: INFO/ CBMA-3 (19101): 9: response of replication request: {"error":"cancelled"} 10-26 10:45:44.220: INFO/ CBMA-3 (19101): 11: response of replication request: {"error":"cancelled"} In this round of testing the first 8 tries all behaved as expected. On try 9 the {"error":"cancelled"} did not show up. Notice I waited about 5 minutes and it still did not arrive. At that point I started try 10, this seemed to be stuck just like try 9 (though I only waited 40 seconds). I then started try 11. This seemed to somehow free things up as tries 9, 10 and 11 all got the {"error":"cancelled"} message at this time. I ran through the test again paying closer attention to the CouchDB log and I see: 10-26 11:36:05.180: DEBUG/CouchDB(21069): [debug] [<0.132.0>] httpd 500 error response: 10-26 11:36:05.180: DEBUG/CouchDB(21069): {"error":"cancelled"} 10-26 11:36:05.180: DEBUG/CouchDB(21069): [debug] [<0.141.0>] httpd 500 error response: 10-26 11:36:05.180: DEBUG/CouchDB(21069): {"error":"cancelled"} 10-26 11:36:05.190: DEBUG/CouchDB(21069): [debug] [<0.127.0>] httpd 500 error response: 10-26 11:36:05.190: DEBUG/CouchDB(21069): {"error":"cancelled"} So it looks to me like the messages are getting held up inside CouchDB and its doesn't appear to be a problem with HttpClient on Android.