{"action":"created","issue":{"url":"https://api.github.com/repos/couchbase/sync_gateway/issues/2078","repository_url":"https://api.github.com/repos/couchbase/sync_gateway","labels_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/2078/labels{/name}","comments_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/2078/comments","events_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/2078/events","html_url":"https://github.com/couchbase/sync_gateway/issues/2078","id":176398685,"number":2078,"title":"CoucbaseLite-IOS, _changes?longpoll with SG channels management","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,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-09-12T15:00:17Z","updated_at":"2016-09-12T20:42:47Z","closed_at":null,"body":"Hello,\r\n\r\nOrigin of the work, around issues #1865 and #2074, was to replicate an issue occuring time to time on our alpha environment. Today with fix for #1865, all logs activated + additional traces we had again the issue. Looking to the logs I realised that couchbaselite is using longpoll, meaning that a since value is provided in the requests which close itself very quickly (two docs let say).\r\nBefore digging further in the logs and providing whatever would be necessary for your investigation, I have the strange feeling that below case is not handled, am I right?\r\n\r\n\tlongpoll since = 25000, user x\r\n\t25001: doc1 grants channel access but is not in a channel visible by user x (i.e. not sent)\r\n\t25002: doc2 sent to user x\r\n\tlongpoll close\r\n\tlongpoll since = 25002, user x\t\r\n\tdocuments in channel granted by 25001 with a seq id below 25002 will not be sent because since is 25002? Is this what is happening? At least this is what I seems to see in logs.\r\n\r\nAnd here some logs extract:\r\n\r\n\tGrant access doc #279255\r\n\tLine 1049: \tLine 9135: 2016-09-12T12:18:05.222Z Access: Doc \"6ffbed60e5a62578235788e252485783\" grants channel access: map[be3b68a6-5dec-40ea-a264-db02abe0ef5e:TB=-UQgHTJrIn2bHPi1nFB9E7O:279255,TM=-UQgHTJrIn2bHPi1nFB9E7O:279255,TU=3af379ab-ab24-4e20-b422-db2e9bf24dca:279255]\r\n\tLine 1050: \tLine 9139: 2016-09-12T12:18:05.247Z Access: Rev \"6ffbed60e5a62578235788e252485783\"/\"1-51f43490f90658ff55bdf03b2ca7daff\" invalidates channels of [be3b68a6-5dec-40ea-a264-db02abe0ef5e]\r\n\tLine 1052: \tLine 9141: 2016-09-12T12:18:05.247Z Access: Invalidate access of \"be3b68a6-5dec-40ea-a264-db02abe0ef5e\"\r\n\r\n\tChannel TB=-UQgHTJrIn2bHPi1nFB9E7O:279255,TM=-UQgHTJrIn2bHPi1nFB9E7O:279255 not seen by reload user\r\n\tLine 1058: \tLine 9178: 2016-09-12T12:18:05.957Z Changes+: MultiChangesFeed waiter has changed...   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\tLine 1059: \tLine 9179: 2016-09-12T12:18:05.957Z Changes+: MultiChangesFeed reloading user &{roleImpl:{Name_:be3b68a6-5dec-40ea-a264-db02abe0ef5e ExplicitChannels_: Channels_:!:1,TB=-hq9v2xkUD5Wfg1PIsa70Bn:279248,TM=-hq9v2xkUD5Wfg1PIsa70Bn:279248,TU=cbe2bd39-79de-4486-a3e0-9970f6145e54:279248,U=400:279244 Sequence_:279243 PreviousChannels_:} userImplBody:{Email_:qauser57636@xxxx.com Disabled_:false PasswordHash_:[36 50 97 36 49 48 36 106 50 100 71 80 120 73 104 53 82 105 98 66 66 78 80 75 119 101 81 73 117 90 102 112 46 70 113 66 89 87 68 48 114 111 102 111 47 73 49 121 48 49 73 99 65 119 89 73 89 67 122 50] OldPasswordHash_:<nil> ExplicitRoles_:public:279243 RolesSince_:public:279243 OldExplicitRoles_:[]} auth:0xc823a0c300 roles:[]}, no change\r\n\r\n\tSend doc #279256 which is also in channel U=400\r\n\tLine 1079: \tLine 9201: 2016-09-12T12:18:05.957Z Changes+: Sending seq:279256 from channel U=400 user   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\r\n\tLine 1100: \tLine 9352: 2016-09-12T12:18:06.193Z Access: Computed channels for \"be3b68a6-5dec-40ea-a264-db02abe0ef5e\": !:1,TB=-UQgHTJrIn2bHPi1nFB9E7O:279255,TB=-hq9v2xkUD5Wfg1PIsa70Bn:279248,TM=-UQgHTJrIn2bHPi1nFB9E7O:279255,TM=-hq9v2xkUD5Wfg1PIsa70Bn:279248,TU=3af379ab-ab24-4e20-b422-db2e9bf24dca:279255,TU=cbe2bd39-79de-4486-a3e0-9970f6145e54:279248,U=400:279244\r\n\tLine 1101: \tLine 9353: 2016-09-12T12:18:06.193Z Bucket: Update(\"_sync:user:be3b68a6-5dec-40ea-a264-db02abe0ef5e\", 0, ...) --> <nil> [89.232761ms]\r\n\r\n\tLine 1102: \tLine 9354: 2016-09-12T12:18:06.193Z HTTP:  #73129: GET /xxxx/202d0c0f0e49ea3b35adc56688ff004c?rev=1-e9b88282f42781197b150f0195d9c71e&revs=true&attachments=true  (as be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\tLine 1103: \tLine 9357: 2016-09-12T12:18:06.220Z Bucket: Update(\"_sync:user:be3b68a6-5dec-40ea-a264-db02abe0ef5e\", 0, ...) --> CAS quit [228.21µs]\r\n\r\n\tLongpoll reset with since = 279256\r\n\tLine 1104: \tLine 9358: 2016-09-12T12:18:06.220Z HTTP:  #73130: POST /xxxx/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=279256  (as be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\t\r\n\tNow channels are found\r\n\tLine 1107: \tLine 9363: 2016-09-12T12:18:06.221Z Changes+: MultiChangesFeed: channels expand to channels.TimedSet{\"TB=xxxxWorld\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442cb}, \"TM=-hq9v2xkUD5Wfg1PIsa70Bn\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d0}, \"U=400\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442cc}, \"TB=-UQgHTJrIn2bHPi1nFB9E7O\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d7}, \"TB=-hq9v2xkUD5Wfg1PIsa70Bn\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d0}, \"TU=cbe2bd39-79de-4486-a3e0-9970f6145e54\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d0}, \"!\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x1}, \"TU=3af379ab-ab24-4e20-b422-db2e9bf24dca\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d7}, \"TM=-UQgHTJrIn2bHPi1nFB9E7O\":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x442d7}} ...   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\t\r\n\tBut they are not considered as new.... \r\n\tLine 1114: \tLine 9373: 2016-09-12T12:18:06.222Z Changes+: MultiChangesFeed processing channel TM=-UQgHTJrIn2bHPi1nFB9E7O seqat {VbNo:<nil> Sequence:279255} user   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\tLine 1115: \tLine 9374: 2016-09-12T12:18:06.222Z Changes+: MultiChangesFeed no backfill channel TM=-UQgHTJrIn2bHPi1nFB9E7O chanOpts {Since:279256 Limit:0 Conflicts:true IncludeDocs:false Wait:false Continuous:false Terminator:0xc821042c00 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:true} user   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)\r\n\tLine 1116: \tLine 9375: 2016-09-12T12:18:06.222Z Changes: [changesFeed] Found 0 changes for channel TM=-UQgHTJrIn2bHPi1nFB9E7O and user   (to be3b68a6-5dec-40ea-a264-db02abe0ef5e)"},"comment":{"url":"https://api.github.com/repos/couchbase/sync_gateway/issues/comments/246486015","html_url":"https://github.com/couchbase/sync_gateway/issues/2078#issuecomment-246486015","issue_url":"https://api.github.com/repos/couchbase/sync_gateway/issues/2078","id":246486015,"user":{"login":"adamcfraser","id":8866453,"avatar_url":"https://avatars.githubusercontent.com/u/8866453?v=3","gravatar_id":"","url":"https://api.github.com/users/adamcfraser","html_url":"https://github.com/adamcfraser","followers_url":"https://api.github.com/users/adamcfraser/followers","following_url":"https://api.github.com/users/adamcfraser/following{/other_user}","gists_url":"https://api.github.com/users/adamcfraser/gists{/gist_id}","starred_url":"https://api.github.com/users/adamcfraser/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/adamcfraser/subscriptions","organizations_url":"https://api.github.com/users/adamcfraser/orgs","repos_url":"https://api.github.com/users/adamcfraser/repos","events_url":"https://api.github.com/users/adamcfraser/events{/privacy}","received_events_url":"https://api.github.com/users/adamcfraser/received_events","type":"User","site_admin":false},"created_at":"2016-09-12T20:42:47Z","updated_at":"2016-09-12T20:42:47Z","body":"I think this highlights a gap in the solution that was provided for #1865.  Currently a longpoll (or continuous) changes feed is doing the following, when coming out of a waiting state:\r\n1. Wait ends\r\n2. Reload the user (when needed) \r\n3. Identify current cached sequence\r\n4. Send changes up to the current cached sequence, for each channel\r\n\r\nThe gap here is for changes that are indexed/cached between steps #2 and #3 - they can result in missed channel backfills in the scenario you've outlined.  It may be sufficient to reverse the order of #2 and #3.  I need to do some work to verify there aren't any problematic scenarios with those two steps reversed - and whether that's a better solution to the problem described in https://github.com/couchbase/sync_gateway/issues/2068."}}
{"actor":{"display_login":"adamcfraser"}}