Sync Gateway sometimes returns incorrect last_seq

[paulharter]

Hi

I was writing some test against couchbase and sync gateway and found the I could predictably cause the sync gateway to return incorrect changes. Jens suggested that it might be the Sync Gateway cache not updating.

This happened when I ran the same setup code for two tests. I hadn’t cleared out the previous tests setup as this is hard to do with couchbase/syncgateway (I would be really nice to have a rest call to flush the underlying bucket and clear the sg cache. Does this exist?), but it was fine for these tests. It look like the point at which this fails is where the setup runs for a second time. Might the updating of documents with identical content or the removal and recreation of identical documents, which would then happen upset the gateway cache? I noticed that the cas is a natural key so that identical docs have the same cas. Maybe different revisions with the same cas upset the cache somehow?

Thanks

Paul

Details:

Couchbase Sync Gateway/master(1c6559c)
Couchbase Server Version: 3.0.1 Community Edition (build-1444)

I ended up with 12 documents (apart from _sync…) in Couchbase and sync gateway sees all 12 documents in the web UI

domain_test
internetstore_test
login::paul
login::test
network_test_default
node_test_default_default
person_test
project_09498dc4-0b54-46c3-80f6-9b3872c642e1
project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9
rackspacestore_test_project_09498dc4-0b54-46c3-80f6-9b3872c642e1
rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9
test_person

but curl changes only gets up to seq 1::24

Pauls-MacBook-Pro :: ~ » curl http://test:[email protected]:4985/sync_gateway/_changes
{"results":[
{"seq":"1","id":"person_test","changes":[{"rev":"1-a01b606dcacbe367b3c52b216c194b0e"}]}
,{"seq":"1::4","id":"node_test_default_default","changes":[{"rev":"1-b4e12fd0a26beb9a017efda88819be45"}]}
,{"seq":"1::5","id":"internetstore_test","changes":[{"rev":"1-336709c219a8871e7196d36ee38aee25"}]}
,{"seq":"1::12","id":"project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9","changes":[{"rev":"1-7ff3b679bc713830e43e89e66102ce8c"}]}
,{"seq":"1::13","id":"rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9","changes":[{"rev":"1-45974c6dfb7866c714d9fe79b61c6e5c"}]}
,{"seq":"1::14","id":"network_test_default","changes":[{"rev":"2-3f6ad532c71b690a23dcb1ff20a182e0"}]}
,{"seq":"1::15","id":"domain_test","changes":[{"rev":"3-2ad6d45370e35802e3fc8ad431e9eb02"}]}
,{"seq":"1::17","id":"login::test","changes":[{"rev":"3-077f1af1c8dfcac9cd7945c81d25a77f"}]}
,{"seq":"1::18","id":"_user/test","changes":[{"rev":""}]}
,{"seq":"1::19","id":"test_person","changes":[{"rev":"2-f0260d3518ce306b546ead27495f512d"}]}
,{"seq":"1::21","id":"login::paul","changes":[{"rev":"3-87168ce4e953735bbe600851be715279"}]}
,{"seq":"1::22","id":"_user/paul","changes":[{"rev":""}]}
,{"seq":"1::23","id":"project_09498dc4-0b54-46c3-80f6-9b3872c642e1","changes":[{"rev":"1-ac99f4ea1244cd8873f1249f5b01f341"}]}
,{"seq":"1::24","id":"rackspacestore_test_project_09498dc4-0b54-46c3-80f6-9b3872c642e1","changes":[{"rev":"1-dab4414f5a0ec87a6febf4bb1adcf2a4"}]}
],
"last_seq":"1::24"}

The sequence actually goes higher

These docs don’t appear:

project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9
rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9

Neither do modifications to other existing documents.

below is the sync gateway log - things after #39 don't show up in the changes feed

2015/05/21 07:36:01.064306 Enabling logging: [REST]
2015/05/21 07:36:01.064411 ==== Couchbase Sync Gateway/master(1c6559c) ====
2015/05/21 07:36:01.064820 Configured Go to use all 8 CPUs; setenv GOMAXPROCS to override this
2015/05/21 07:36:01.065034 Opening db /sync_gateway as bucket "sync_gateway", pool "default", server http://172.17.0.4:8091
2015/05/21 07:36:01.065135 Opening Couchbase database sync_gateway on http://172.17.0.4:8091
2015/05/21 07:36:01.180682 Starting admin server on :4985
2015/05/21 07:36:01.190867 Starting server on :4984 ...
2015/05/21 07:37:10.857521 HTTP: #1: GET /sync_gateway/ (ADMIN)
2015/05/21 07:37:10.866304 HTTP: #2: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:10.869766 HTTP: #2: --> 404 missing (3.5 ms)
2015/05/21 07:37:10.874267 HTTP: #3: GET /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:10.875679 HTTP: #3: --> 404 missing (1.4 ms)
2015/05/21 07:37:10.879863 HTTP: #4: GET /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:10.881246 HTTP: #4: --> 404 missing (1.4 ms)
2015/05/21 07:37:10.887680 HTTP: #5: PUT /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:10.953905 HTTP: #6: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:10.955150 HTTP: #6: --> 404 missing (1.3 ms)
2015/05/21 07:37:10.959771 HTTP: #7: PUT /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:10.976718 HTTP: #8: GET /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:10.978159 HTTP: #8: --> 404 missing (1.5 ms)
2015/05/21 07:37:10.983763 HTTP: #9: GET /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:10.985238 HTTP: #9: --> 404 missing (1.5 ms)
2015/05/21 07:37:10.988741 HTTP: #10: PUT /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:10.993701 HTTP: #11: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:11.000563 HTTP: #12: GET /sync_gateway/node_test_default_default (ADMIN)
2015/05/21 07:37:11.003144 HTTP: #12: --> 404 missing (2.6 ms)
2015/05/21 07:37:11.008679 HTTP: #13: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:11.014033 HTTP: #14: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:11.024604 HTTP: #15: GET /sync_gateway/node_test_default_default (ADMIN)
2015/05/21 07:37:11.025871 HTTP: #15: --> 404 missing (1.3 ms)
2015/05/21 07:37:11.034258 HTTP: #16: PUT /sync_gateway/node_test_default_default (ADMIN)
2015/05/21 07:37:11.046557 HTTP: #17: GET /sync_gateway/internetstore_test (ADMIN)
2015/05/21 07:37:11.049950 HTTP: #17: --> 404 missing (3.4 ms)
2015/05/21 07:37:11.053536 HTTP: #18: GET /sync_gateway/internetstore_test (ADMIN)
2015/05/21 07:37:11.054222 HTTP: #18: --> 404 missing (0.7 ms)
2015/05/21 07:37:11.058226 HTTP: #19: PUT /sync_gateway/internetstore_test (ADMIN)
2015/05/21 07:37:11.065562 HTTP: #20: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:11.078904 HTTP: #21: PUT /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:11.098058 HTTP: #22: GET /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:11.109774 HTTP: #23: GET /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:11.110329 HTTP: #23: --> 404 missing (0.6 ms)
2015/05/21 07:37:11.112709 HTTP: #24: GET /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:11.113563 HTTP: #24: --> 404 missing (0.9 ms)
2015/05/21 07:37:11.118465 HTTP: #25: PUT /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:11.129309 HTTP: #26: PUT /sync_gateway/_user/test (ADMIN)
2015/05/21 07:37:11 go-couchbase: call to ViewCustom("sync_gateway", "access") in github.com/couchbase/sync_gateway/db.(*DatabaseContext).ComputeChannelsForPrincipal took 598.855649ms
2015/05/21 07:37:11.883537 HTTP: #27: GET /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:11.885840 HTTP: #27: --> 404 missing (2.3 ms)
2015/05/21 07:37:11.894626 HTTP: #28: GET /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:11.896198 HTTP: #28: --> 404 missing (1.6 ms)
2015/05/21 07:37:11.903840 HTTP: #29: PUT /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:11.914833 HTTP: #30: GET /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:11.918336 HTTP: #30: --> 404 missing (3.6 ms)
2015/05/21 07:37:11.923373 HTTP: #31: GET /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:11.925981 HTTP: #31: --> 404 missing (2.6 ms)
2015/05/21 07:37:11.933683 HTTP: #32: PUT /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:11.943772 HTTP: #33: PUT /sync_gateway/_user/paul (ADMIN)
2015/05/21 07:37:12.203967 HTTP: #34: GET /sync_gateway/project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9 (ADMIN)
2015/05/21 07:37:12.206690 HTTP: #34: --> 404 missing (2.7 ms)
2015/05/21 07:37:12.214743 HTTP: #35: PUT /sync_gateway/project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9 (ADMIN)
2015/05/21 07:37:12.354550 HTTP: #36: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:12.365781 HTTP: #37: GET /sync_gateway/rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9 (ADMIN)
2015/05/21 07:37:12.366549 HTTP: #37: --> 404 missing (0.8 ms)
2015/05/21 07:37:12.369851 HTTP: #38: GET /sync_gateway/rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9 (ADMIN)
2015/05/21 07:37:12.370397 HTTP: #38: --> 404 missing (0.6 ms)
2015/05/21 07:37:12.375758 HTTP: #39: PUT /sync_gateway/rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9 (ADMIN)
2015/05/21 07:37:13.476730 HTTP: #40: GET /sync_gateway/ (ADMIN)
2015/05/21 07:37:13.483274 HTTP: #41: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:13.489114 HTTP: #42: GET /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:13.493864 HTTP: #43: GET /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:13.498000 HTTP: #44: GET /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:13.508739 HTTP: #45: PUT /sync_gateway/network_test_default (ADMIN)
2015/05/21 07:37:13.519950 HTTP: #46: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:13.529891 HTTP: #47: GET /sync_gateway/node_test_default_default (ADMIN)
2015/05/21 07:37:13.536388 HTTP: #48: GET /sync_gateway/internetstore_test (ADMIN)
2015/05/21 07:37:13.544227 HTTP: #49: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:13.553485 HTTP: #50: PUT /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:13.565561 HTTP: #51: GET /sync_gateway/person_test (ADMIN)
2015/05/21 07:37:13.574855 HTTP: #52: GET /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:13.584280 HTTP: #53: DELETE /sync_gateway/login::test?rev=1-17696f06cc4b28e396f896c553d82797 (ADMIN)
2015/05/21 07:37:13.595006 HTTP: #54: GET /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:13.600582 HTTP: #54: --> 404 deleted (5.6 ms)
2015/05/21 07:37:13.608188 HTTP: #55: PUT /sync_gateway/login::test (ADMIN)
2015/05/21 07:37:13.621684 HTTP: #56: PUT /sync_gateway/_user/test (ADMIN)
2015/05/21 07:37:13.978736 HTTP: #57: GET /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:13.983465 HTTP: #58: GET /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:13.993473 HTTP: #59: PUT /sync_gateway/test_person (ADMIN)
2015/05/21 07:37:14.004323 HTTP: #60: GET /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:14.014123 HTTP: #61: DELETE /sync_gateway/login::paul?rev=1-9244ed3c71a38d87a2f94d3b0da416a2 (ADMIN)
2015/05/21 07:37:14.023987 HTTP: #62: GET /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:14.025165 HTTP: #62: --> 404 deleted (1.2 ms)
2015/05/21 07:37:14.031279 HTTP: #63: PUT /sync_gateway/login::paul (ADMIN)
2015/05/21 07:37:14.043938 HTTP: #64: PUT /sync_gateway/_user/paul (ADMIN)
2015/05/21 07:37:14.423575 HTTP: #65: GET /sync_gateway/project_09498dc4-0b54-46c3-80f6-9b3872c642e1 (ADMIN)
2015/05/21 07:37:14.424488 HTTP: #65: --> 404 missing (0.9 ms)
2015/05/21 07:37:14.434697 HTTP: #66: PUT /sync_gateway/project_09498dc4-0b54-46c3-80f6-9b3872c642e1 (ADMIN)
2015/05/21 07:37:14.446359 HTTP: #67: GET /sync_gateway/domain_test (ADMIN)
2015/05/21 07:37:14.457145 HTTP: #68: GET /sync_gateway/rackspacestore_test_project_09498dc4-0b54-46c3-80f6-9b3872c642e1 (ADMIN)
2015/05/21 07:37:14.460404 HTTP: #68: --> 404 missing (3.2 ms)
2015/05/21 07:37:14.464909 HTTP: #69: GET /sync_gateway/rackspacestore_test_project_09498dc4-0b54-46c3-80f6-9b3872c642e1 (ADMIN)
2015/05/21 07:37:14.465403 HTTP: #69: --> 404 missing (0.5 ms)
2015/05/21 07:37:14.470055 HTTP: #70: PUT /sync_gateway/rackspacestore_test_project_09498dc4-0b54-46c3-80f6-9b3872c642e1 (ADMIN)

[adamcfraser]

Can you run the same test with Changes+ and Cache+ logging enabled for Sync Gateway? That will shed some light on what the cache is doing:

You can do that either through your sync gateway config, like:
"log":["Changes+","Cache+"],

If you're not using a custom config file, let me know and I can share examples on how to set logging via the admin API.

[paulharter]

Hi Adam,

I'll do it first thing tomorrow

Thanks

P

[paulharter]

Hi Adam,

I've run this test several times this morning and the problem seems to have gone away! I am now getting the correct last_seq back. To re-run the test I rebuilt the docker I was running sync gateway from to update the logging as you asked. It looks like there was something I had managed to do to that installation of sync gateway that was causing it to fail, unfortunately I didn't think of this and threw away the image to change the logging.

This is good as the problem has gone away, but bad as I cannot reproduce the problem that may recur.

I am going to be doing more testing over the next few days and will let you know if this problem does come back.

Thanks

Paul

[paulharter]

One thought - Is there a way to quickly and reliably reset the state of the both couchbase and sync gateway for testing short of a reinstall? How to you do this internally?

Thanks

P

[zgramana]

We typically use the in-memory walrus bucket so that restarting SG gives you an empty database.

[paulharter]

I'm using Couchbase views much of the time so I can't use walrus like this.

If I flush the Couchbase bucket and restart Sync Gateway will this reset all Sync Gateway state?

[adamcfraser]

Yes - Sync Gateway doesn't persist any state other than what's in the bucket, aside from what's in memory. Stopping Sync Gateway, flushing the bucket, then restarting Sync Gateway is my usual approach for doing a full reset when testing.

[adamcfraser]

@paulharter If it's possible to share your sync function, and some details on the test you were running, I'd like to dig into this a bit more to try to reproduce.

[paulharter]

Hi Adam,

Sure, but its a bit hard to send you the test without sending you quite a lot of code that it's testing.

The sync function is below and I can try to tease out the actual test code if it would help.

I have rerun the test trying if I am missing anything from how I was running it before, but cannot reproduce the error. I am certainly running he same code. The only thing that I think has changed is the actual install of sync gateway, but I might be missing something. Does it really have no other persistent state between restarts? Does it refer back to replication logs?

The other thing I am doing is automatically generating a couple of design docs which I've realised would have been in couchbase all the time. They should be the same but maybe updating them caused problems?

The sync function I was using is minimal, just setting channels and access

function(doc) {
if(doc.type == "project" || doc.type == "domain"){access (doc.access, doc._id);}
channel (doc.channels);
}

I was getting an incorrect last_seq on both 4984 and 4985 so I don't think I simply didn't have permissions to see documents but I was wondering if re-running the "domain" access call might be a cause of problems.

Also I did have trouble getting couchdb to replicate down from sync gateway a couple of times, although programatically it was better. The replication seemed to hang, but I don't know if this could cause problems.

Let me know if you'd like more detail of the test

Paul

[adamcfraser]

Hi Paul,

I haven't been able to reproduce your issue yet either. For the two missing docs:

project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9
rackspacestore_test_project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9

...I'm assuming they would have both have a channels property in the doc of ['project_fa6d79fc-e9b1-4d2f-966b-74e6f3a721f9']? If both project docs were granting access to the same user, you might have been running into the race condition that was fixed with issue #880 (although it would be a bit surprising given the low load).

For your other questions:

• I don't think regeneration of design docs would be likely to cause this particular problem.
• Sync Gateway really doesn't have any persistent state between restarts (other than what's stored in the bucket).

Let me know if you're still not able to reproduce; if so I'll close this ticket for the time being - we can reopen if your issue resurfaces.

[paulharter]

Hi Adam,

I haven't been able to reproduce it either, but thanks for your help in looking at it.

I'll let you know if it occurs again.