Sync gateway 2.1 /understanding deduplication

We have the client reporting cancellation of reservation which seems to be user request being cancelled.
Client exception logged from kafka:
“ActionName” : “MoveNext”,
“QueryParameter” : “RESERVATION::P2BP4E”,
“MachineName” : “******”,
“Bucket” : “dbpi”,
“LoggingContext” : “8d5e2fd1-b74d-48ac-bfa3-20a69685dd9e::::0::”,
“DeviceId” : “8d5e2fd1-b74d-48ac-bfa3-20a69685dd9e”,
“PreviousRevision” : “5-9f3ca3e819dd264a6447b7e9c7b49d0c”,
“Class” : “ReservationCouchbase”,
“Key” : “RESERVATION::P2BP4E”,
“TransactionId” : “77f67d9b-8130-4f26-bfd2-80cfb357f559”
},
“message” : "{“Timestamp”:“2020-02-10T11:37:53.9212774-05:00”,“Level”:“Warning”,“MessageTemplate”:“Task was canceled in - Save Reservation {Key} from {Bucket}. {PreviousRevision}”,“RenderedMessage”:“Task was canceled in - Save Reservation \“RESERVATION::P2BP4E\” from \“dbpi\”. \“5-9f3ca3e819dd264a6447b7e9c7b49d0c\””,“Exception”:“System.Threading.Tasks.TaskCanceledException: A task was canceled.\r\n at United.Mobile.Couchbase.SyncGatewayRESTClient.d__171.MoveNext()\\r\\n--- End of stack trace from previous location where exception was thrown ---\\r\\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\\r\\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\\r\\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\\r\\n at United.Mobile.Couchbase.SyncGatewayRESTClient.<PutDocumentAsync>d__161.MoveNext()\r\n— End of stack trace from previous location where exception was thrown —\r\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()\\r\\n at United.Mobile.Reservation.Couchbase.ReservationCouchbase.<SetReservationAsync>d__12.MoveNext()\",\"Properties\":{\"Key\":\"RESERVATION::P2BP4E\",\"Bucket\":\"dbpi\",\"PreviousRevision\":\"5-9f3ca3e819dd264a6447b7e9c7b49d0c\",\"ActionName\":\"MoveNext\",\"Class\":\"ReservationCouchbase\",\"QueryParameter\":\"RESERVATION::P2BP4E\",\"DeviceId\":\"8d5e2fd1-b74d-48ac-bfa3-20a69685dd9e\",\"LoggingContext\":\"8d5e2fd1-b74d-48ac-bfa3-20a69685dd9e::::0::\",\"TransactionId\":\"77f67d9b-8130-4f26-bfd2-80cfb357f559\",\"MachineName\":\"VCLD34PSALHAP13\",\"ExceptionDetail\":{\"Type\":\"System.Threading.Tasks.TaskCanceledException\",\"HResult\":-2146233029,\"Message\":\"A task was canceled.\",\"Source\":\"United.Mobile.Couchbase\",\"CancellationToken\":\"CancellationRequested: true\",\"Task\":{\"Id\":-2126385971,\"Status\":\"Canceled\",\"CreationOptions\":\"None\"}}}}\r\n", "type" : "UMACA_ORLEANS", "Timestamp" : "2020-02-10T11:37:53.9212774-05:00", "Exception" : "System.Threading.Tasks.TaskCanceledException: A task was canceled.\r\n at United.Mobile.Couchbase.SyncGatewayRESTClient.<PutDocumentUsingSyncGatewayAsync>d__171.MoveNext()\r\n— End of stack trace from previous location where exception was thrown —\r\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n at United.Mobile.Couchbase.SyncGatewayRESTClient.d__161.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()\r\n at United.Mobile.Reservation.Couchbase.ReservationCouchbase.d__12.MoveNext()”,
“message_size” : 2131,
“MessageTemplate” : “Task was canceled in - Save Reservation {Key} from {Bucket}. {PreviousRevision}”,
“kafka_offset” : “266864942”,

Sync_gateway logs:
2020-02-10T09:46:01.876-06:00 [INF] HTTP: #75032666: GET /dbpi/RESERVATION::P2BP4E?show_exp=true (as ADMIN)
2020-02-10T09:46:01.877-06:00 [INF] HTTP: #75032665: --> 404 missing (2.5 ms)
2020-02-10T09:46:01.877-06:00 [INF] HTTP+: #75032647: --> 200 (10.2 ms)
2020-02-10T09:46:01.879-06:00 [INF] HTTP: #75032667: GET /dbpu/_user/PU_XD913535@04127978-6216-435A-A440-8EC8A027A1BD (as ADMIN)
2020-02-10T09:46:01.879-06:00 [INF] HTTP: #75032668: GET /dbpu/HOMESCREENADVISORY?show_exp=true (as ADMIN)
2020-02-10T09:46:01.879-06:00 [INF] HTTP: #75032669: GET /dbpi/RESERVATION::GWMFKT?show_exp=true (as ADMIN)
2020-02-10T09:46:01.879-06:00 [INF] HTTP+: #75032663: --> 200 (5.0 ms)
2020-02-10T09:46:01.879-06:00 [INF] Cache: Received deduplicated #7872952617 for (“LOOKUP::USER::BEJCY3” / “4-30181e7f3293b7682e50dc13ad3b0568”)
2020-02-10T09:46:01.880-06:00 [INF] Cache: Received deduplicated #7872952632 for (“LOOKUP::USER::BEJCY3” / “4-30181e7f3293b7682e50dc13ad3b0568”)
2020-02-10T09:46:01.880-06:00 [INF] Cache: Received deduplicated #7872952634 for (“LOOKUP::USER::BEJCY3” / “4-30181e7f3293b7682e50dc13ad3b0568”)
2020-02-10T09:46:01.880-06:00 [INF] Cache: Received #7872952641 after 0ms (“LOOKUP::USER::BEJCY3” / “4-30181e7f3293b7682e50dc13ad3b0568”)
2020-02-10T09:46:01.880-06:00 [INF] Cache: Deferring #7872952641 (2601 now waiting for #7872950034#7872950034)
2020-02-10T09:46:01.880-06:00 [INF] HTTP+: #75032667: --> 200 (0.9 ms)
2020-02-10T09:46:01.881-06:00 [INF] HTTP+: #75032668: --> 200 (1.9 ms)
2020-02-10T09:46:01.881-06:00 [INF] Cache: Received #7872952602 after 0ms (“CONTEXTUALAWARENESSCARD::JKM11237@F15CBFDE-B271-4C26-BEED-E89A7F0E1C7C” / “36-fa37f51fc47c8f558547626dbce6fc63”)
2020-02-10T09:46:01.881-06:00 [INF] Cache: Deferring #7872952602 (2602 now waiting for #7872950034#7872950034)
2020-02-10T09:46:01.881-06:00 [INF] HTTP: #75032670: GET /dbpu/_user/PU_XD913535@04127978-6216-435A-A440-8EC8A027A1BD (as ADMIN)
2020-02-10T09:46:01.881-06:00 [INF] Cache: Received #1792660192 after 0ms (“CSLCACHE::STATUS::RESERVATION::K1BK1G” / “1-012dd4b7026f61cd54bf4f90015fd818”)

Does anyone know what is happening when this is seen in the logs" Cache: Received deduplicated #7872952632 for (“LOOKUP::USER::BEJCY3” / “4-30181e7f3293b7682e50dc13ad3b0568”)"

Thanks.

So, the deduplication should be completely unrelated to the first message you’ve shared. The first bit appears to be an issue in a client you’re using to talk to Sync Gateway’s REST API.

Moving on to what deduplication is: Sync Gateway listens to changes in the Couchbase Server bucket via DCP and uses this feed of changes to build a cache of the most recent changes organised by channel. (It also uses this feed to import any documents written by Couchbase SDKs, but that’s not directly relevant here).

All documents that have either been written or imported by a Sync Gateway instance have a sequence number assigned, which is unique and monotonically increasing. Theoretically then, all Sync Gateway needs to do is listen to the DCP feed and hear about each sequence number in order and cache them as appropriate. In practice, Sync Gateway has to handle multiple feeds and then enforce ordering (which is where the Deferring messages in your logs come from), but this is somewhat orthogonal. The key point is that Sync Gateway expects to see every sequence number come over DCP from Couchbase Server.

DCP, however, has an efficiency measure that can affect this - if the same document is mutated several times in quick succession, these can be coalesced into one. E.g. {"foo": 1} -> {"foo": 2} -> {"foo": 3} -> {"foo": 4} might be sent across DCP as {"foo": 1}, {"foo": 4} or just {"foo": 4}. As long as the end state is consistent, DCP has done it’s job. This aspect of DCP is called deduplication.

This poses a problem for Sync Gateway. If node SG1 writes the above changes, and SG2 only hears about {"foo": 1} and {"foo": 4}, there are 2 sequence numbers (for {"foo": 2} and {"foo": 3}) which SG2 would try to wait for, even though it will never receive them.

To avoid this, SG1 maintains a list in the document of “recent sequence numbers this document previously had”, or recent_sequences. When SG2 receives {"foo": 4} at (let’s say) sequence 123, and is still waiting for sequences 121 and 122, it can see that these sequences are actually for older versions of this document and therefore it can stop waiting for them and move on.

In your case, the logs say that for revision 4-30181e7f3293b7682e50dc13ad3b0568 of that particular document, Sync Gateway was able to find 3 sequences in the recent_sequences that it was waiting for, and can now stop waiting for them (in this case, that would be revisions 1-... to 3-...).

Hope that helps explain the process a bit more!