{"action":"created","issue":{"url":"https://api.github.com/repos/couchbase/sync_gateway/issues/1865","repository_url":"https://api.github.com/repos/couchbase/sync_gateway","labels_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/1865/labels{/name}","comments_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/1865/comments","events_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/1865/events","html_url":"https://github.com/couchbase/sync_gateway/issues/1865","id":159781903,"number":1865,"title":"One shot replication of granting access doc can lead to miss documents","user":{"login":"Crapulax","id":15442005,"avatar_url":"https://avatars.githubusercontent.com/u/15442005?v=3","gravatar_id":"","url":"https://api.github.com/users/Crapulax","html_url":"https://github.com/Crapulax","followers_url":"https://api.github.com/users/Crapulax/followers","following_url":"https://api.github.com/users/Crapulax/following{/other_user}","gists_url":"https://api.github.com/users/Crapulax/gists{/gist_id}","starred_url":"https://api.github.com/users/Crapulax/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Crapulax/subscriptions","organizations_url":"https://api.github.com/users/Crapulax/orgs","repos_url":"https://api.github.com/users/Crapulax/repos","events_url":"https://api.github.com/users/Crapulax/events{/privacy}","received_events_url":"https://api.github.com/users/Crapulax/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2016-06-11T16:43:04Z","updated_at":"2016-06-14T17:38:56Z","closed_at":null,"body":"Hello,\r\n\r\nWhen you one shot a granting access document you might not receive on resumed replications all documents in the channel since channel exists. This issue is critical. For one who might asked, we do a one shot replication because of issue https://github.com/couchbase/sync_gateway/issues/1720#issuecomment-214552671\r\nI can send full logs in pivate mode.\r\nAs a side note, although I have no evidence of it, this might also happen without the one shot replication. We did observed in the past such missing doc issue while not using yet the one shot for granting documents.\r\n\r\nIn substance when the channel change notification is arriving after the user reload  function on the one shot replication feed, the information saying that this channel is new to the user is lost for ever.\r\nIn file db.changes.go\r\nfunc (db *Database) SimpleMultiChangesFeed(chans base.Set, options ChangesOptions) (<-chan *ChangeEntry, error) {\r\n..\r\nwaitForChanges\r\n..\r\n// if notifications on channel changes are already arrived it is ok, otherwise BOOM, no change found\r\nuserChangeCount, addedChannels, err = db.checkForUserUpdates(userChangeCount, changeWaiter, to)\r\n\r\n\r\nExtract from logs (SG 1.2.0 with a few additional traces):\r\n1)\t User 31dc30d3-2017-41f6-a5a5-e7c5f0e0e847 creates document -AHVbFZo38w8oZpLwHBsi_5\r\nLine 10901: doc id:-AHVbFZo38w8oZpLwHBsi_5\r\n\tLine 10904: doc Owner_id:31dc30d3-2017-41f6-a5a5-e7c5f0e0e847\r\n// Note the first document sequence for this channel 26998\r\n\tLine 10915: 2016-06-11T15:51:50.085Z Cache: **SAVING #26998**\r\n\r\n2)\tOne shot replication of the granting document from user 0ce0266a-f159-4fd7-8f53-9ee86952809f:\r\n// Open one shot replication (session id = 65  this is my added counter on logs, user 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\nLine 12406: 2016-06-11T15:52:47.304Z Changes: MultiChangesFeed({*}, {Since:27007 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc820c8f500 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n// Check accessible channels so far so good:\r\nLine 12411: 2016-06-11T15:52:47.307Z Changes+: MultiChangesFeed: handle channel ! options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 1 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\nLine 12419: 2016-06-11T15:52:47.314Z Changes+: MultiChangesFeed: handle channel 0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\nLine 12423: 2016-06-11T15:52:47.322Z Changes+: MultiChangesFeed: handle channel MU=0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\nLine 12427: 2016-06-11T15:52:47.323Z Changes+: MultiChangesFeed: handle channel BI=d42059482b607e73fd77184611e6795d options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27007 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n// going in wait mode\r\n\tLine 12428: 2016-06-11T15:52:47.324Z Changes+: MultiChangesFeed waiting...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n\t// granting document received\r\n\tLine 12434: ************************************ debut INVITE ************\r\n\tLine 12436: doc id:d42059482b607e73fd77184611e6795d\r\n\tLine 12437: doc Channel:-AHVbFZo38w8oZpLwHBsi_5\r\n\tLine 12438: doc invitedUser_id:0ce0266a-f159-4fd7-8f53-9ee86952809f\r\n\tLine 12444: 2016-06-11T15:52:47.700Z CRUD+: Saving old revision \"d42059482b607e73fd77184611e6795d\" / \"1-2054afc9e117d3549604c5cfaca477e5\" (271 bytes)\r\n\t// Access to channel AHVbFZo38w8oZpLwHBsi_5 granted to user 0ce0266a-f159-4fd7-8f53-9ee86952809f as expected\r\nLine 12446: 2016-06-11T15:52:47.706Z Access: Doc \"d42059482b607e73fd77184611e6795d\" grants channel access: map[**0ce0266a-f159-4fd7-8f53-9ee86952809f:BB=-AHVbFZo38w8oZpLwHBsi_5:27008**,BI=d42059482b607e73fd77184611e6795d:27007 31dc30d3-2017-41f6-a5a5-e7c5f0e0e847:BI=d42059482b607e73fd77184611e6795d:27007]\r\n\tLine 12449: 2016-06-11T15:52:47.707Z Cache: SAVING #27008\r\nLine 12450: 2016-06-11T15:52:47.707Z Access: Invalidate access of \"0ce0266a-f159-4fd7-8f53-9ee86952809f\"\r\nLine 12453: 2016-06-11T15:52:47.708Z Auth: Saved _sync:user:0ce0266a-f159-4fd7-8f53-9ee86952809f: {\"name\":\"0ce0266a-f159-4fd7-8f53-9ee86952809f\",\"all_channels\":null,\"sequence\":27004,\"passwordhash_bcrypt\":\"JDJhJDEwJFJIYnlCd0tTOHJtNXZ5SjJKV3JYUC5XcFd6bTJsRTUwSzJZNW8xam4xM3VTYlB4TWN5Vk5l\",\"explicit_roles\":{\"public\":27004},\"rolesSince\":{\"public\":27004}}\r\nLine 12454: 2016-06-11T15:52:47.785Z Access: Computed channels for \"0ce0266a-f159-4fd7-8f53-9ee86952809f\": !:1,0ce0266a-f159-4fd7-8f53-9ee86952809f:27005,BB=-AHVbFZo38w8oZpLwHBsi_5:27008,BI=d42059482b607e73fd77184611e6795d:27007,MU=0ce0266a-f159-4fd7-8f53-9ee86952809f:27005\r\n\r\n\t// Access channels under recomputation\r\n\tLine 12459: 2016-06-11T15:52:48.021Z Changes+: Notifying that \"xxxx\" changed (keys=\"{*, BI=d42059482b607e73fd77184611e6795d}\") count=21\r\n\r\n\t// and of wait, computing changes, **NO CHANGE FOUND YET** reloading user found no changes in channels… (this skipped trace was added in code)\r\n\tLine 12461: 2016-06-11T15:52:48.021Z Changes+: MultiChangesFeed reloading user skipped newcount is 18, userCount is 18   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n\t// The notification on the change on the channel is now taking place but AFTER RELOAD ends\r\n\t**Line 12488: 2016-06-11T15:52:48.026Z Changes+: Notifying that \"xxxx\" changed (keys=\"{_sync:user:0ce0266a-f159-4fd7-8f53-9ee86952809f}\") count=22**\r\n\tLine 12527: 2016-06-11T15:52:48.041Z Changes+: MultiChangesFeed: handle channel MU=0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12532: 2016-06-11T15:52:48.042Z Changes+: MultiChangesFeed: handle channel ! options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 1 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12537: 2016-06-11T15:52:48.046Z Changes+: MultiChangesFeed: handle channel BI=d42059482b607e73fd77184611e6795d options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27007 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12542: 2016-06-11T15:52:48.047Z Changes+: MultiChangesFeed: handle channel 0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x697f, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820c8f500), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n\t// One shot replication finished\r\nLine 12544: 2016-06-11T15:52:48.049Z Changes: MultiChangesFeed done, reason is Continuous %!d(bool=false), sentSomething %!d(bool=true) ...   (to 65 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n\t// New replication starts\r\n\tLine 12550: 2016-06-11T15:52:48.288Z Changes: MultiChangesFeed({*}, {Since:27008 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc821469bc0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12555: 2016-06-11T15:52:48.292Z Changes+: MultiChangesFeed: handle channel ! options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6980, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821469bc0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 1 ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12559: 2016-06-11T15:52:48.294Z Changes+: MultiChangesFeed: handle channel 0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6980, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821469bc0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n// Here is the ISSUE: newly channel created get a start sequence set to 27008!!! Document with start sequence 26998 will never be sent….\r\n\tLine 12563: 2016-06-11T15:52:48.298Z Changes+: MultiChangesFeed: handle channel **BB=-AHVbFZo38w8oZpLwHBsi_5** options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, ** #Seq:0x6980**, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821469bc0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is **27008** ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n\tLine 12567: 2016-06-11T15:52:48.298Z Changes+: MultiChangesFeed: handle channel BI=d42059482b607e73fd77184611e6795d options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6980, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821469bc0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27007 ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\tLine 12571: 2016-06-11T15:52:48.301Z Changes+: MultiChangesFeed: handle channel MU=0ce0266a-f159-4fd7-8f53-9ee86952809f options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6980, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821469bc0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27005 ...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\t\tLine 12576: 2016-06-11T15:52:48.306Z Changes+: MultiChangesFeed waiting...   (to 71 0ce0266a-f159-4fd7-8f53-9ee86952809f)\r\n\r\n3)\tThe exact same scenario with user ff83e059-12f0-4d24-b30d-db6dab317c78 but this time the channel notification gets sent before the user reload and channel is handled correctly\r\nLine 13584: 2016-06-11T15:54:10.476Z Changes: MultiChangesFeed({*}, {Since:27014 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc821c76000 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13592: 2016-06-11T15:54:10.482Z Changes+: MultiChangesFeed: handle channel MU=ff83e059-12f0-4d24-b30d-db6dab317c78 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27012 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13596: 2016-06-11T15:54:10.491Z Changes+: MultiChangesFeed: handle channel BI=368b028f4a0e91576a8e50cf0f4abcca options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27014 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13600: 2016-06-11T15:54:10.492Z Changes+: MultiChangesFeed: handle channel ff83e059-12f0-4d24-b30d-db6dab317c78 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27012 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13605: 2016-06-11T15:54:10.492Z Changes+: MultiChangesFeed: handle channel ! options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 1 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13606: 2016-06-11T15:54:10.493Z Changes+: MultiChangesFeed waiting...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13612: ************************************ debut INVITE ************\r\n\tLine 13614: doc id:368b028f4a0e91576a8e50cf0f4abcca\r\n\tLine 13615: doc xxxChannel:-AHVbFZo38w8oZpLwHBsi_5\r\n\t\r\n\tLine 13622: 2016-06-11T15:54:10.803Z CRUD+: Saving old revision \"368b028f4a0e91576a8e50cf0f4abcca\" / \"1-a49528a86b6a43a553064da12b0b3ecb\" (271 bytes)\r\n\tLine 13627: 2016-06-11T15:54:10.804Z Cache: SAVING #27015\r\n\tLine 13646: ************************************ debut xxxx *************\r\n\tLine 13655: 2016-06-11T15:54:11.467Z Cache: SAVING #27016\r\n\tLine 13658: ************************************ debut MESSAGE\r\n\tLine 13670: 2016-06-11T15:54:11.472Z Cache: SAVING #27017\r\n\tLine 13681: 2016-06-11T15:54:16.191Z Changes+: Notifying that \"xxxx\" changed (keys=\"{_sync:user:ff83e059-12f0-4d24-b30d-db6dab317c78}\") count=34\r\n\tLine 13694: 2016-06-11T15:54:16.191Z Changes+: Notifying that \"xxx\" changed (keys=\"{*, BB=-AHVbFZo38w8oZpLwHBsi_5, BI=368b028f4a0e91576a8e50cf0f4abcca, ff83e059-12f0-4d24-b30d-db6dab317c78}\") count=35\r\n\t**Line 13697: 2016-06-11T15:54:16.192Z Changes+: Notifying that \"xxx\" changed (keys=\"{*, BB=-AHVbFZo38w8oZpLwHBsi_5}\") count=36**\r\n\tLine 13736: 2016-06-11T15:54:16.197Z Changes+: **New channels found after user   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78) reload: {BB=-AHVbFZo38w8oZpLwHBsi_5}**\r\n\tLine 13741: 2016-06-11T15:54:16.200Z Changes+: MultiChangesFeed: handle channel MU=ff83e059-12f0-4d24-b30d-db6dab317c78 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27012 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\r\n\t// This time the trigger by is set and makes the document search done since channel beginning\r\n\tLine 13745: 2016-06-11T15:54:16.200Z Cache: getCachedChanges(\"BB=-AHVbFZo38w8oZpLwHBsi_5\", {0 **27015** 0 0 <nil> <nil> %!d(string=) 0 0 0 %!d(string=)}) --> ** #6 changes valid from #1**\r\n\tLine 13747: 2016-06-11T15:54:16.200Z Changes+: MultiChangesFeed: handle channel BB=-AHVbFZo38w8oZpLwHBsi_5 options are db.ChangesOptions{Since:db.SequenceID{SeqType:0, TriggeredBy:0x6987, LowSeq:0x0, Seq:0x0, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27015 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\r\n\tLine 13789: 2016-06-11T15:54:16.215Z Changes+: MultiChangesFeed: handle channel ! options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 1 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13805: 2016-06-11T15:54:16.218Z Changes+: MultiChangesFeed: handle channel BI=368b028f4a0e91576a8e50cf0f4abcca options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27014 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13811: 2016-06-11T15:54:16.218Z Changes+: MultiChangesFeed: handle channel ff83e059-12f0-4d24-b30d-db6dab317c78 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6986, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc821c76000), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27012 ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\r\n//End of one shot replication\t\r\nLine 13828: 2016-06-11T15:54:16.240Z Changes: MultiChangesFeed done, reason is Continuous %!d(bool=false), sentSomething %!d(bool=true) ...   (to 92 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\r\n// New session\t\r\nLine 13836: 2016-06-11T15:54:16.482Z Changes: MultiChangesFeed({*}, {Since:27017 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc820a571a0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ...   (to 98 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13840: 2016-06-11T15:54:16.489Z Changes+: MultiChangesFeed: handle channel MU=ff83e059-12f0-4d24-b30d-db6dab317c78 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6989, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820a571a0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27012 ...   (to 98 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n\tLine 13844: 2016-06-11T15:54:16.491Z Changes+: MultiChangesFeed: handle channel BB=-AHVbFZo38w8oZpLwHBsi_5 options are db.ChangesOptions{Since:db.SequenceID{SeqType:1, TriggeredBy:0x0, LowSeq:0x0, Seq:0x6989, Clock:base.SequenceClock(nil), TriggeredByClock:base.SequenceClock(nil), ClockHash:\"\", SequenceHasher:(*db.sequenceHasher)(nil), vbNo:0x0, TriggeredByVbNo:0x0, LowHash:\"\"}, Limit:0, Conflicts:true, IncludeDocs:false, Wait:false, Continuous:false, Terminator:(chan bool)(0xc820a571a0), HeartbeatMs:0x493e0, TimeoutMs:0x493e0, ActiveOnly:false} seAdded is 27015 ...   (to 98 ff83e059-12f0-4d24-b30d-db6dab317c78)\r\n…\r\n"},"comment":{"url":"https://api.github.com/repos/couchbase/sync_gateway/issues/comments/225957936","html_url":"https://github.com/couchbase/sync_gateway/issues/1865#issuecomment-225957936","issue_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/1865","id":225957936,"user":{"login":"Crapulax","id":15442005,"avatar_url":"https://avatars.githubusercontent.com/u/15442005?v=3","gravatar_id":"","url":"https://api.github.com/users/Crapulax","html_url":"https://github.com/Crapulax","followers_url":"https://api.github.com/users/Crapulax/followers","following_url":"https://api.github.com/users/Crapulax/following{/other_user}","gists_url":"https://api.github.com/users/Crapulax/gists{/gist_id}","starred_url":"https://api.github.com/users/Crapulax/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Crapulax/subscriptions","organizations_url":"https://api.github.com/users/Crapulax/orgs","repos_url":"https://api.github.com/users/Crapulax/repos","events_url":"https://api.github.com/users/Crapulax/events{/privacy}","received_events_url":"https://api.github.com/users/Crapulax/received_events","type":"User","site_admin":false},"created_at":"2016-06-14T17:38:55Z","updated_at":"2016-06-14T17:38:55Z","body":"Hello Adam,\r\n\r\nThanks for taking care of this issue.\r\n- We are using SG 1.2.0\r\n- The workflow we have put in place is the following:\r\n   - replication in both directions up and running in continuous mode\r\n   - update 'Invite' document with a status granting the channel (BB=xxx)\r\n   - stop continuous replication to SYNC (keep the replication FROM sync up)\r\n   - start a one shot replication to sync with continuous false and the invite doc id:\r\nreplications[TOSYNC] = {\r\n                    continuous: true,\r\n                    source: localdbname,\r\n                    target: {headers: xxxxx, url: myContext.syncURL + myContext.syncDBName}\r\n                };\r\nif (whichRepli === ONESHOT) {\r\n                    if (docids) { // Contain the invite doc id\r\n                        replications[TOSYNC].doc_ids = docids;\r\n                        replications[TOSYNC].continuous = false;\r\n                    }\r\n... start one shot replication\r\n\r\n   - wait for the one shot replication to have nothing to do (by monitoring _active_tasks)\r\n\r\n   - when above is true restart continuous replication to SYNC and creates document which required the granted channel\r\n\r\nNote that since we put this in place, and also when we run in above race issue, channel access is correctly granted as all documents sent are accepted by the sync function.\r\nI have digged further on the issue and you are fully right the backfill trigger is missed. I am not sure on how the different SG routines interacts but it looks like the channel update as new information get lost.\r\n\r\nAlso if just after the (Auth: Saved _sync:user:xxx trace) channels list is updated with current value then there is another issue. Because at that point we sore in  couchbase DB that channel XX sequence = current sequence while, if it is a new channel, old docs still need to be sent. If for whatever reason the SG is stopped at that point documents are lost. I do not want to look arrogant or whatever as I have just started digging into SG source code but it might be preferable ever not to store the cur seq for new channels here but the original start SEQ or just not the channel at all.\r\n\r\nAs an additional information we can easily reproduce the issue when the users accepting the invitation has just been created and when there are attachments involved. For attachments I guess that they are slowing down some functions for the new user maybe also. But I have no evidence at all that they are required to reproduce the issue.\r\n\r\nIf you need something else or more details, feel free I will be happy to help you helping us :)\r\n\r\nBrgds"}}
{"actor":{"display_login":"Crapulax"}}