Uploaded image for project: 'Couchbase Lite'
  1. Couchbase Lite
  2. CBL-222

CBL push replication is not replicating doc updates with delta sync after CBL upgrade

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Not a Bug
    • 2.6.0, 2.5.0
    • 2.6.0
    • iOS
    • Security Level: Public
    • None
    • CBL iOS - 2.6.0-141
      SG - 2.5.1-11
      CBS - 6.0.1-2037
      iPhone-8-plus emulator

    Description

      CBL push replication is not replicating doc updates with delta sync after CBL upgrade.

      This is what I'm trying to do in CBL upgrade test -
      1. Migrate older-pre-built db to a provided cbl apps
      2. Start the replication and replicate db to cluster
      3. Running all query tests
      4. Perform mutation operations
      a. Add new docs and replicate to cluster
      b. Update docs for migrated db and replicate to cluster <-- Failing here
      c. Delete docs from migrated db and replicate to cluster

      ERROR:
      > assert "new_field" in sg_data, "Updated docs failed to get replicated"
      E AssertionError: Updated docs failed to get replicated
      E assert 'new_field' in {'_id': 'route_57637', '_rev': '1-53c9a41c517273c178023f50d4c22d82b2abca09', '_revisions':

      {'ids': ['53c9a41c517273c178023f50d4c22d82b2abca09'], 'start': 1}

      , 'airline': 'UA', ...}

      Code Snippet:

      # updating old docs
          repl_config = replicator.configure(cbl_db, sg_blip_url, replication_type="push", 
                                                               continuous=True, replicator_authenticator=replicator_authenticator)
          repl = replicator.create(repl_config)
          doc_ids_to_update = random.sample(cbl_doc_ids, 5)
          docs = db.getDocuments(cbl_db, doc_ids_to_update)
          for doc_id in docs:
              log_info("Updating CBL Doc - {}".format(doc_id))
              data = docs[doc_id]
              data["new_field"] = "test_string_for_{}".format(doc_id)
              db.updateDocument(cbl_db, doc_id=doc_id, data=data)
       
          replicator.start(repl)
          replicator.wait_until_replicator_idle(repl)
          replicator.stop(repl)
       
          cbs_docs = sg_client.get_all_docs(sg_admin_url, sg_db, session)["rows"]
          cbs_doc_ids = [doc["id"] for doc in cbs_docs]
       
          for doc_id in doc_ids_to_update:
              log_info("Checking for updates in doc on CBS: {}".format(doc_id))
              sg_data = sg_client.get_doc(url=sg_admin_url, db=sg_db, doc_id=doc_id, auth=session)
              assert "new_field" in sg_data, "Updated docs failed to get replicated"
          new_cbl_doc_ids = db.getDocIds(cbl_db, limit=40000)
      

      Command to run test -
      pytest -s --timeout 3600 --base-liteserv-version=2.5.0 --upgraded-liteserv-version=2.6.0-141 --liteserv-host=10.100.174.204 --liteserv-port=8080 --liteserv-platform=ios --xattrs --skip-provisioning --no-conflicts --enable-file-logging --encrypted-db --delta-sync --encrypted-db-password=password --sync-gateway-version=2.5.1-11 --mode=cc --server-version=6.0.1-2037 testsuites/CBLTester/upgrade_tests/test_cbl_upgrade.py -k test_upgrade_cbl

      Test is passing without --delta-sync.

      Jenkins job for this test will give a detailed look into the test flow - http://uberjenkins.sc.couchbase.com:8080/view/03%20CBL-2.x/job/CBL_upgrade/42/console

      PS: Tested only on iOS, will update status about other platform later.

      Attachments

        1. cbcollect_info.zip
          11.94 MB
        2. logs1565086375.916285.zip
          11.48 MB
        3. python_client.log
          141 kB
        4. route_5164.png
          route_5164.png
          197 kB
        5. sgcollect_info.zip
          17.74 MB
        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          ben.brooks Ben Brooks added a comment - - edited

          I think this is a channel/authentication issue on the autotest user, but can't immediately think of an explanation as to why it works when delta sync is turned off.

           

          A quick glance through the SG logs show we never recieve a rev for the second revision of the doc specified in the description[1] ... but there are quite a few instances of "404 Document revision is not accessible" for other docs being updated.

          I can see these docs belong in the "*" channel at rev 1, and it doesn't look like the test is removing or modifying any channels on docs. The "autotest" user only has access to channel "!".

          2019-08-06T03:13:49.598-07:00 [INF] HTTP:  #001: POST /db/_user/ (as ADMIN)
          2019-08-06T03:13:49.603-07:00 [INF] Access: Computed channels for "autotest": !:1
          2019-08-06T03:13:49.607-07:00 [INF] Access: Computed roles for "autotest":  

          2019-08-06T03:21:10.965-07:00 [DBG] WS+: c:[45b26621] Received frame: MSG#7~ (flags=    1000, length=33)
          2019-08-06T03:21:10.965-07:00 [DBG] WSFrame+: c:[45b26621] Incoming BLIP Request: MSG#7~
          2019-08-06T03:21:10.965-07:00 [DBG] SyncMsg+: c:[45b26621] #7: Type:rev Id:route_50214 Rev:2-150ff12292a580563c55974d531d5095af740de5 DeltaSrc:1-812acd0757f13d741547b575a697d99086c9c880 Sequence:31601  User:autotest
          2019-08-06T03:21:10.966-07:00 [DBG] CRUD+: c:[45b26621] Did not update document "route_50214" w/ xattr: 404 Document revision is not accessible
          2019-08-06T03:21:10.966-07:00 [INF] SyncMsg: c:[45b26621] #7: Type:rev   --> 404 Document revision is not accessible Time:1.381134ms User:autotest
          2019-08-06T03:21:10.966-07:00 [DBG] WS+: c:[45b26621] Push ERR#7
          2019-08-06T03:21:10.966-07:00 [DBG] WS+: c:[45b26621] Sending frame: ERR#7 (flags=      10, size=   69) 

          273963:2019-08-06T03:15:21.468-07:00 [DBG] SyncMsg+: c:[66d4a38a] #19629: Type:rev Id:route_50214 Rev:1-812acd0757f13d741547b575a697d99086c9c880 Sequence:19505  User:autotest
          273971:2019-08-06T03:15:21.469-07:00 [DBG] CRUD+: c:[66d4a38a] Invoking sync on doc "route_50214" rev 1-812acd0757f13d741547b575a697d99086c9c880
          273976:2019-08-06T03:15:21.469-07:00 [DBG] CRUD+: Backed up revision body "route_50214"/"1-812acd0757f13d741547b575a697d99086c9c880" (1351 bytes, ttl:86400)
          274013:2019-08-06T03:15:21.473-07:00 [DBG] CRUD+: c:[66d4a38a] Saving doc (seq: #19507, id: route_50214 rev: 1-812acd0757f13d741547b575a697d99086c9c880)
          274014:2019-08-06T03:15:21.474-07:00 [INF] CRUD: c:[66d4a38a] Stored doc "route_50214" / "1-812acd0757f13d741547b575a697d99086c9c880" as #19507
          ...
          2019-08-06T03:15:21.475-07:00 [INF] Cache: Received #19507 after   1ms ("route_50214" / "1-812acd0757f13d741547b575a697d99086c9c880")
          ...
          2019-08-06T03:15:21.475-07:00 [INF] Cache: #19507 ==> channels {*}
          ...
          443817:2019-08-06T03:21:10.965-07:00 [DBG] SyncMsg+: c:[45b26621] #7: Type:rev Id:route_50214 Rev:2-150ff12292a580563c55974d531d5095af740de5 DeltaSrc:1-812acd0757f13d741547b575a697d99086c9c880 Sequence:31601  User:autotest
          443818:2019-08-06T03:21:10.966-07:00 [DBG] CRUD+: c:[45b26621] Did not update document "route_50214" w/ xattr: 404 Document revision is not accessible 

           

           

          [1]

          $ rg 'route_57637' sg_debug.log
          350050:2019-08-06T03:15:43.852-07:00 [DBG] SyncMsg+: c:[66d4a38a] #25076: Type:rev Id:route_57637 Rev:1-53c9a41c517273c178023f50d4c22d82b2abca09 Sequence:24925  User:autotest
          350053:2019-08-06T03:15:43.852-07:00 [DBG] CRUD+: c:[66d4a38a] Invoking sync on doc "route_57637" rev 1-53c9a41c517273c178023f50d4c22d82b2abca09
          350056:2019-08-06T03:15:43.852-07:00 [DBG] CRUD+: Backed up revision body "route_57637"/"1-53c9a41c517273c178023f50d4c22d82b2abca09" (865 bytes, ttl:86400)
          350059:2019-08-06T03:15:43.853-07:00 [DBG] CRUD+: c:[66d4a38a] Saving doc (seq: #24924, id: route_57637 rev: 1-53c9a41c517273c178023f50d4c22d82b2abca09)
          350060:2019-08-06T03:15:43.853-07:00 [INF] CRUD: c:[66d4a38a] Stored doc "route_57637" / "1-53c9a41c517273c178023f50d4c22d82b2abca09" as #24924
          350065:2019-08-06T03:15:43.854-07:00 [INF] Cache: Received #24924 after   1ms ("route_57637" / "1-53c9a41c517273c178023f50d4c22d82b2abca09")

          ben.brooks Ben Brooks added a comment - - edited I think this is a channel/authentication issue on the autotest user, but can't immediately think of an explanation as to why it works when delta sync is turned off.   A quick glance through the SG logs show we never recieve a rev for the second revision of the doc specified in the description [1] ... but there are quite a few instances of " 404 Document revision is not accessible " for other docs being updated. I can see these docs belong in the " * " channel at rev 1, and it doesn't look like the test is removing or modifying any channels on docs. The " autotest " user only has access to channel " ! ". 2019 - 08 -06T03: 13 : 49.598 - 07 : 00 [INF] HTTP: # 001 : POST /db/_user/ (as ADMIN) 2019 - 08 -06T03: 13 : 49.603 - 07 : 00 [INF] Access: Computed channels for "autotest" : !: 1 2019 - 08 -06T03: 13 : 49.607 - 07 : 00 [INF] Access: Computed roles for "autotest" : 2019 - 08 -06T03: 21 : 10.965 - 07 : 00 [DBG] WS+: c:[45b26621] Received frame: MSG# 7 ~ (flags= 1000 , length= 33 ) 2019 - 08 -06T03: 21 : 10.965 - 07 : 00 [DBG] WSFrame+: c:[45b26621] Incoming BLIP Request: MSG# 7 ~ 2019 - 08 -06T03: 21 : 10.965 - 07 : 00 [DBG] SyncMsg+: c:[45b26621] # 7 : Type:rev Id:route_50214 Rev: 2 -150ff12292a580563c55974d531d5095af740de5 DeltaSrc: 1 -812acd0757f13d741547b575a697d99086c9c880 Sequence: 31601 User:autotest 2019 - 08 -06T03: 21 : 10.966 - 07 : 00 [DBG] CRUD+: c:[45b26621] Did not update document "route_50214" w/ xattr: 404 Document revision is not accessible 2019 - 08 -06T03: 21 : 10.966 - 07 : 00 [INF] SyncMsg: c:[45b26621] # 7 : Type:rev --> 404 Document revision is not accessible Time: 1 .381134ms User:autotest 2019 - 08 -06T03: 21 : 10.966 - 07 : 00 [DBG] WS+: c:[45b26621] Push ERR# 7 2019 - 08 -06T03: 21 : 10.966 - 07 : 00 [DBG] WS+: c:[45b26621] Sending frame: ERR# 7 (flags= 10 , size= 69 ) 273963 : 2019 - 08 -06T03: 15 : 21.468 - 07 : 00 [DBG] SyncMsg+: c:[66d4a38a] # 19629 : Type:rev Id:route_50214 Rev: 1 -812acd0757f13d741547b575a697d99086c9c880 Sequence: 19505 User:autotest 273971 : 2019 - 08 -06T03: 15 : 21.469 - 07 : 00 [DBG] CRUD+: c:[66d4a38a] Invoking sync on doc "route_50214" rev 1 -812acd0757f13d741547b575a697d99086c9c880 273976 : 2019 - 08 -06T03: 15 : 21.469 - 07 : 00 [DBG] CRUD+: Backed up revision body "route_50214" / "1-812acd0757f13d741547b575a697d99086c9c880" ( 1351 bytes, ttl: 86400 ) 274013 : 2019 - 08 -06T03: 15 : 21.473 - 07 : 00 [DBG] CRUD+: c:[66d4a38a] Saving doc (seq: # 19507 , id: route_50214 rev: 1 -812acd0757f13d741547b575a697d99086c9c880) 274014 : 2019 - 08 -06T03: 15 : 21.474 - 07 : 00 [INF] CRUD: c:[66d4a38a] Stored doc "route_50214" / "1-812acd0757f13d741547b575a697d99086c9c880" as # 19507 ... 2019 - 08 -06T03: 15 : 21.475 - 07 : 00 [INF] Cache: Received # 19507 after 1ms ( "route_50214" / "1-812acd0757f13d741547b575a697d99086c9c880" ) ... 2019 - 08 -06T03: 15 : 21.475 - 07 : 00 [INF] Cache: # 19507 ==> channels {*} ... 443817 : 2019 - 08 -06T03: 21 : 10.965 - 07 : 00 [DBG] SyncMsg+: c:[45b26621] # 7 : Type:rev Id:route_50214 Rev: 2 -150ff12292a580563c55974d531d5095af740de5 DeltaSrc: 1 -812acd0757f13d741547b575a697d99086c9c880 Sequence: 31601 User:autotest 443818 : 2019 - 08 -06T03: 21 : 10.966 - 07 : 00 [DBG] CRUD+: c:[45b26621] Did not update document "route_50214" w/ xattr: 404 Document revision is not accessible     [1] $ rg 'route_57637' sg_debug.log 350050 : 2019 - 08 -06T03: 15 : 43.852 - 07 : 00 [DBG] SyncMsg+: c:[66d4a38a] # 25076 : Type:rev Id:route_57637 Rev: 1 -53c9a41c517273c178023f50d4c22d82b2abca09 Sequence: 24925 User:autotest 350053 : 2019 - 08 -06T03: 15 : 43.852 - 07 : 00 [DBG] CRUD+: c:[66d4a38a] Invoking sync on doc "route_57637" rev 1 -53c9a41c517273c178023f50d4c22d82b2abca09 350056 : 2019 - 08 -06T03: 15 : 43.852 - 07 : 00 [DBG] CRUD+: Backed up revision body "route_57637" / "1-53c9a41c517273c178023f50d4c22d82b2abca09" ( 865 bytes, ttl: 86400 ) 350059 : 2019 - 08 -06T03: 15 : 43.853 - 07 : 00 [DBG] CRUD+: c:[66d4a38a] Saving doc (seq: # 24924 , id: route_57637 rev: 1 -53c9a41c517273c178023f50d4c22d82b2abca09) 350060 : 2019 - 08 -06T03: 15 : 43.853 - 07 : 00 [INF] CRUD: c:[66d4a38a] Stored doc "route_57637" / "1-53c9a41c517273c178023f50d4c22d82b2abca09" as # 24924 350065 : 2019 - 08 -06T03: 15 : 43.854 - 07 : 00 [INF] Cache: Received # 24924 after 1ms ( "route_57637" / "1-53c9a41c517273c178023f50d4c22d82b2abca09" )

          So, I've re-ran the test after discussing with Ben Brooks, adding channel [*] to the user and the test passed

          http://uberjenkins.sc.couchbase.com:8080/view/03%20CBL-2.x/job/CBL_upgrade/47/console

          Although, both Ben Brooks and I think that there is an underlying issue, as why the test passed without delta-sync and failed with it. Let me know if anything is required from me.

          hemant.rajput Hemant Rajput added a comment - So, I've re-ran the test after discussing with Ben Brooks , adding channel [*] to the user and the test passed http://uberjenkins.sc.couchbase.com:8080/view/03%20CBL-2.x/job/CBL_upgrade/47/console Although, both Ben Brooks and I think that there is an underlying issue, as why the test passed without delta-sync and failed with it. Let me know if anything is required from me.

          looks like this is tested against SGW 2.5.1-11 . We have last delta sync fix on 2.5.1-12. Not sure if the fix on 2.5.1-12 matters, can you test with latest build of 2.5.1?

           

          sridevi.saragadam Sridevi Saragadam (Inactive) added a comment - looks like this is tested against SGW 2.5.1-11 . We have last delta sync fix on 2.5.1-12. Not sure if the fix on 2.5.1-12 matters, can you test with latest build of 2.5.1?  

          Tested agains SGW-2.5.1-12 as well, seeing the same behaviour.

           

          http://uberjenkins.sc.couchbase.com:8080/view/03%20CBL-2.x/job/CBL_upgrade/48/console

          hemant.rajput Hemant Rajput added a comment - Tested agains SGW-2.5.1-12 as well, seeing the same behaviour.   http://uberjenkins.sc.couchbase.com:8080/view/03%20CBL-2.x/job/CBL_upgrade/48/console
          Jayahari.Vavachan Jay Vavachan added a comment - - edited

          Couldn't find anything useful information from the logs, we are getting a `HTTP 404 'Document revision is not accessible` when sending revision.

          Assigning to Adam, to further investigate from SG side.

          Jayahari.Vavachan Jay Vavachan added a comment - - edited Couldn't find anything useful information from the logs, we are getting a `HTTP 404 'Document revision is not accessible` when sending revision. Assigning to Adam, to further investigate from SG side.
          adamf Adam Fraser added a comment - - edited

          Hemant Rajput In Ben's update above, he mentions that revision 2 is being written as a user that doesn't have read access to revision 1. That sounds to me like the underlying test failure here, but SG is working as intended. When delta sync is enabled, SG doesn't accept deltas when the client doesn't have access to the source revision for the delta, to prevent leaking data about previous revisions in the scenario where the user has write and not read access (i.e. this case).

          It's expected that this would pass with delta sync disabled, as Sync Gateway will allow users to write full documents when they don't have access to the ancestor, as there's no information leak in that scenario.

          For this test in particular, it looks to me like you should be writing revision 1 to the public channel [!], so that user autotest can successfully write rev 2 when delta sync is enabled.

          adamf Adam Fraser added a comment - - edited Hemant Rajput In Ben's update above, he mentions that revision 2 is being written as a user that doesn't have read access to revision 1. That sounds to me like the underlying test failure here, but SG is working as intended. When delta sync is enabled, SG doesn't accept deltas when the client doesn't have access to the source revision for the delta, to prevent leaking data about previous revisions in the scenario where the user has write and not read access (i.e. this case). It's expected that this would pass with delta sync disabled, as Sync Gateway will allow users to write full documents when they don't have access to the ancestor, as there's no information leak in that scenario. For this test in particular, it looks to me like you should be writing revision 1 to the public channel [!] , so that user autotest can successfully write rev 2 when delta sync is enabled.
          ben.brooks Ben Brooks added a comment - - edited

          Ah yeah, that explanation above makes sense regarding the difference between deltas on and off.

          I didn't know a doc could be written to an ancestor that the user didn't have access to.
          Sidenote: I guess this can be locked down via the sync function if that behaviour is desired?

          ben.brooks Ben Brooks added a comment - - edited Ah yeah, that explanation above makes sense regarding the difference between deltas on and off. I didn't know a doc could be written to an ancestor that the user didn't have access to. Sidenote: I guess this can be locked down via the sync function if that behaviour is desired?

          The explanation above make sense. Hence closing the ticket.

           

          PS: I've already added the channel access to SG user for our test.

          hemant.rajput Hemant Rajput added a comment - The explanation above make sense. Hence closing the ticket.   PS: I've already added the channel access to SG user for our test.

          People

            hemant.rajput Hemant Rajput
            hemant.rajput Hemant Rajput
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty