Sync gateway _changes feed and pull replication does not return all documents up to the latest sequence


#1

Sync gateway is not returning all documents a user has access to when doing a pull replication on our couchbase lite ios client, and when doing a _changes feed request using the sync gateway REST API. I can see that it is also returning the incorrect last_seq value for a user. Our use case is this:

  1. A user is granted access to a bunch of channels, e.g. channel1, channel2, channel3
  2. The user does a pull replication filtered to only return documents from channel1.
  3. The result is that even though there are four documents in channel1, the user only gets 1 of them.
  4. When doing a _changes request with filter=sync_gateway/bychannel&channels=channel1 I see the same thing, we only get that same one document from channel1 even though there are four in the channel. So I’m pretty sure the issue is with sync gateway.
    POSSIBLE PROBLEMS: I can see that the sequence values of the documents not being returned are higher than the last_seq value returned by the _changes call. I don’t know why it thinks the last_seq is lower than it actually is, how do I get it to fix the last_seq value and actually return all documents? I specified no ‘since’ parameter in my request, and if I specify a since param larger than the last_seq returned but less than the sequence value of the documents not being returned I get nothing.

Our current production environment is Sync Gateway Enterprise v1.0.3 with couchbase lite ios v1.0.4. We cannot update to couchbase lite 1.1.0 yet because it has a few bugs in it we need to fix first. We have tried updating to Sync gateway to v1.1.0 on our development environment, and to see if it would fix this problem I updated to sync gateway enterprise v1.1.0 on our staging environment, but I still had the same problem. Is there something I need to do after updating to sync gateway v1.1.0 to get it to fix the actual last_seq value?

Thanks,
Alex


"_changes" feed not 100% reliable
#2

I think the two things you’re seeing - missing documents, and low last_seq - are both just symptoms of the same underlying problem: Sync Gateway not treating the missing documents as assigned to that channel.

A couple of questions:

  1. Do you see the documents if you issue a _changes request against the Admin API, with no channel filter?
    If so, it means Sync Gateway is aware of the documents, but doesn’t think they belong to the channel. I’d recommend reviewing the documents’ channel assignment. However, if you don’t see the docs in that request:
  2. Does the problem persist after a Sync Gateway restart? It sounds like it does, if you’re seeing the same problem on 1.1.0?

Thanks,
Adam


#3

I tried running it against the admin channel but got the exact same results. I also tried restarting sync gateway but it still returned the same results. On the admin channel too it still shows the wrong last_seq for that channel list. E.g.:
{
"_id": “docId”,
"_rev": “1-0989825d53d5a75b988f4af582a7f0cd”,
"_sync": {
“rev”: “1-0989825d53d5a75b988f4af582a7f0cd”,
“sequence”: 2812498,
“history”: {
“revs”: [
“1-0989825d53d5a75b988f4af582a7f0cd”
],
“parents”: [
-1
],
“bodies”: [
""
],
“channels”: [
[
“e3c02cb1-4b69-4b69-89ab-cda07a187823_3415”,
“user_e3c02cb1-4b69-4b69-89ab-cda07a187823”
]
]
},
“channels”: {
“e3c02cb1-4b69-4b69-89ab-cda07a187823_3415”: null,
“user_e3c02cb1-4b69-4b69-89ab-cda07a187823”: null
},
“time_saved”: “2015-08-17T01:47:09.49429Z”
},
{ DOCUMENT BODY}
}

I ran a _changes request with channels list including e3c02cb1-4b69-4b69-89ab-cda07a187823_3415, and it did not return the above document, and it said last_seq was 2762321, even though that document’s sequence number is 2812498.


#4

Are you able to provide any Sync Gateway log output associated with the _changes request?


#5

We currently have these log flags enabled: CRUD REST+ Shadow Access

The only output I see in the sync gateway log is the request itself:

2015-08-24T17:02:16.703Z HTTP:  #001: GET /todos/_changes?filter=sync_gateway/bychannel&channels=e3c02cb1-4b69-4b69-89ab-cda07a187823_0000,e3c02cb1-4b69-4b69-89ab-cda07a187823_3315,e3c02cb1-4b69-4b69-89ab-cda07a187823_3415,e3c02cb1-4b69-4b69-89ab-cda07a187823_3515  (ADMIN)

#6

I added some more log flags and I now see this:

2015-08-24T17:39:06.712Z HTTP:  #001: GET /todos/_changes?filter=sync_gateway/bychannel&channels=e3c02cb1-4b69-4b69-89ab-cda07a187823_0000,e3c02cb1-4b69-4b69-89ab-cda07a187823_3315,e3c02cb1-4b69-4b69-89ab-cda07a187823_3415,e3c02cb1-4b69-4b69-89ab-cda07a187823_3515  (ADMIN)
2015-08-24T17:39:06.713Z Changes: MultiChangesFeed({e3c02cb1-4b69-4b69-89ab-cda07a187823_0000, e3c02cb1-4b69-4b69-89ab-cda07a187823_3315, e3c02cb1-4b69-4b69-89ab-cda07a187823_3415, e3c02cb1-4b69-4b69-89ab-cda07a187823_3515}, {Since:0 Limit:0 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc2082a03c0 HeartbeatMs:0 TimeoutMs:300000}) ... 
2015-08-24T17:39:06.713Z Changes+: MultiChangesFeed: channels expand to channels.TimedSet{"e3c02cb1-4b69-4b69-89ab-cda07a187823_3515":0x0, "e3c02cb1-4b69-4b69-89ab-cda07a187823_0000":0x0, "e3c02cb1-4b69-4b69-89ab-cda07a187823_3315":0x0, "e3c02cb1-4b69-4b69-89ab-cda07a187823_3415":0x0} ... 
2015-08-24T17:39:06.713Z Cache: getCachedChanges("e3c02cb1-4b69-4b69-89ab-cda07a187823_0000", {0 0 0}) --> 0 changes valid from #2762342
2015-08-24T17:39:06.713Z Cache:   Querying 'channels' view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_0000" (start=#1, end=#2762342, limit=0)
2015-08-24T17:39:06.784Z Cache:     Got 2 rows from view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_0000": #1607815 ... #2762341
2015-08-24T17:39:06.784Z Cache:   Initialized cache of "e3c02cb1-4b69-4b69-89ab-cda07a187823_0000" with 2 entries from view (#1607815--#2762341)
2015-08-24T17:39:06.784Z Cache: GetChangesInChannel("e3c02cb1-4b69-4b69-89ab-cda07a187823_0000") --> 2 rows
2015-08-24T17:39:06.784Z Cache: getCachedChanges("e3c02cb1-4b69-4b69-89ab-cda07a187823_3315", {0 0 0}) --> 0 changes valid from #2762342
2015-08-24T17:39:06.784Z Cache:   Querying 'channels' view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3315" (start=#1, end=#2762342, limit=0)
2015-08-24T17:39:06.854Z Cache:     Got 1 rows from view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3315": #2650411 ... #2650411
2015-08-24T17:39:06.855Z Cache:   Initialized cache of "e3c02cb1-4b69-4b69-89ab-cda07a187823_3315" with 1 entries from view (#2650411--#2650411)
2015-08-24T17:39:06.855Z Cache: GetChangesInChannel("e3c02cb1-4b69-4b69-89ab-cda07a187823_3315") --> 1 rows
2015-08-24T17:39:06.855Z Cache: getCachedChanges("e3c02cb1-4b69-4b69-89ab-cda07a187823_3415", {0 0 0}) --> 0 changes valid from #2762342
2015-08-24T17:39:06.855Z Cache:   Querying 'channels' view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3415" (start=#1, end=#2762342, limit=0)
2015-08-24T17:39:06.928Z Cache:     Got 1 rows from view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3415": #2650404 ... #2650404
2015-08-24T17:39:06.929Z Cache:   Initialized cache of "e3c02cb1-4b69-4b69-89ab-cda07a187823_3415" with 1 entries from view (#2650404--#2650404)
2015-08-24T17:39:06.929Z Cache: GetChangesInChannel("e3c02cb1-4b69-4b69-89ab-cda07a187823_3415") --> 1 rows
2015-08-24T17:39:06.929Z Cache: getCachedChanges("e3c02cb1-4b69-4b69-89ab-cda07a187823_3515", {0 0 0}) --> 0 changes valid from #2762342
2015-08-24T17:39:06.929Z Cache:   Querying 'channels' view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3515" (start=#1, end=#2762342, limit=0)
2015-08-24T17:39:07.006Z Cache:     Got no rows from view for "e3c02cb1-4b69-4b69-89ab-cda07a187823_3515"
2015-08-24T17:39:07.006Z Cache: GetChangesInChannel("e3c02cb1-4b69-4b69-89ab-cda07a187823_3515") --> 0 rows
2015-08-24T17:39:07.006Z Changes+: MultiChangesFeed sending &{Seq:1607815 ID:3b85d6bc436891ada3d8136d9d47b891 Deleted:false Removed:{} Doc:map[] Changes:[map[rev:1-69190c899cad91614dddb78888313f5a]] Err:<nil> branched:false} 
2015-08-24T17:39:07.006Z Changes+: MultiChangesFeed sending &{Seq:2650404 ID:befb15bca1b3c2efc5be9fafa6dcf16e Deleted:false Removed:{} Doc:map[] Changes:[map[rev:1-d90699e6e37a151f6fa2a5996c16a4cb]] Err:<nil> branched:false} 
2015-08-24T17:39:07.006Z Changes+: MultiChangesFeed sending &{Seq:2650411 ID:fb288689651790e45641f76ea38658be Deleted:false Removed:{} Doc:map[] Changes:[map[rev:1-0ef499b72f3cd6eb859690f98ea78c0e]] Err:<nil> branched:false} 
2015-08-24T17:39:07.006Z Changes+: MultiChangesFeed sending &{Seq:2762341 ID:e3c02cb1-4b69-4b69-89ab-cda07a187823 Deleted:false Removed:{} Doc:map[] Changes:[map[rev:102-8165d5c3fadebe3dfb7d35e6df672cfb]] Err:<nil> branched:true} 
2015-08-24T17:39:07.006Z Changes: MultiChangesFeed done 

It is only returning four docs, but I can see in the db there are more. For one of the channels I was focusing on it had at least 4 docs it should be returning, and it only returned 1 of them.


#7

This seems like it’s potentially a valid issue, so moving the discussion to github:


#8

Also not sure if it’s related or not but I did do a _resync operation a few days ago.