Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-48713

[Ephemeral] Rev id going backwards for SyncWrite add

    XMLWordPrintable

Details

    • Untriaged
    • Centos 64-bit
    • 1
    • No

    Description

      Build: 7.0.2-6683

      Steps to reproduce:

      1. Create a doc using Sync_Write (MAJORITY)
      2. Delete the same doc using non-sync delete operation
      3. Create the same same using sync_write (MAJORITY)

      Observation:

      Rev Id of the document after step#3 remains 2 instead of '3'

      Impact

      Revision id (revid) is primarily used for XDCR conflict resolution. Documents which are affected by this issue may not have the correct update selected if the same key exists on an XDCR target Bucket.

      Ref: MB-48179

       

      Attachments

        Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            ashwin.govindarajulu Ashwin Govindarajulu created issue -
            ashwin.govindarajulu Ashwin Govindarajulu made changes -
            Field Original Value New Value
            Priority Major [ 3 ] Critical [ 2 ]

            Reproduced the issue and kept the cluster intact for further debugging.

            Doc_id : test_doc0

            {
              "meta": {
                "id": "test_docs0",
                "rev": "2-16a9e34873a900000000000002000000",
                "expiration": 0,
                "flags": 33554432,
                "type": "json"
              },
              "xattrs": {}
            }

            cbcollect logs:
            https://cb-engineering.s3.amazonaws.com/revId_issue/collectinfo-2021-10-01T112054-ns_1%40172.23.105.155.zip
            https://cb-engineering.s3.amazonaws.com/revId_issue/collectinfo-2021-10-01T112054-ns_1%40172.23.105.211.zip

            ashwin.govindarajulu Ashwin Govindarajulu added a comment - Reproduced the issue and kept the cluster intact for further debugging. Doc_id : test_doc0 { "meta": { "id": "test_docs0", "rev": "2-16a9e34873a900000000000002000000", "expiration": 0, "flags": 33554432, "type": "json" }, "xattrs": {} } cbcollect logs: https://cb-engineering.s3.amazonaws.com/revId_issue/collectinfo-2021-10-01T112054-ns_1%40172.23.105.155.zip https://cb-engineering.s3.amazonaws.com/revId_issue/collectinfo-2021-10-01T112054-ns_1%40172.23.105.211.zip
            drigby Dave Rigby added a comment -

            James Harrison Could you take a look please?

            drigby Dave Rigby added a comment - James Harrison Could you take a look please?
            drigby Dave Rigby made changes -
            Assignee Daniel Owen [ owend ] James Harrison [ james.harrison ]
            owend Daniel Owen made changes -
            Priority Critical [ 2 ] Blocker [ 1 ]
            james.harrison James Harrison added a comment - - edited

            Attempted repros in unit test and with modified go repro code from MB-48179 haven't demonstrated the issue yet.

            For reference, with the go code against an ephemeral node (Ashwin Govindarajulu mentioned this is more reliably demonstrated under ephemeral) the hashtable state is as follows for each stage:

            # After sync write
            $ cbstats -u Administrator -p asdasd localhost:12002 raw "_hash-dump 644"
             vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:0 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values:
                OSV @0x10fd8de40 .C. W.R.Cp. temp:    seq:2 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 1
                OSV @0x1102059e0 .C. W.R.Pc. temp:    seq:1 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0
             
            # After delete
             vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:1 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values:
                OSV @0x10fd8de40 ... WDR.Cm. temp:    seq:3 rev:2 cas:1633090625222148096 key:"cid:0x0:daniel, size:7" del_time:1633090624 age:0 fc:0 vallen:0 prepareSeqno: 1
                OSV @0x1102059e0 .C. W.R.Pc. temp:    seq:1 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0
             
            # After sync write 2
             vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:0 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values:
                OSV @0x10fd8de40 .C. W.R.Cp. temp:    seq:5 rev:3 cas:1633090655223808000 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:1 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 4
                OSV @0x1102059e0 .C. W.R.Pc. temp:    seq:4 rev:3 cas:1633090655223808000 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:5 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0
            

            This is as expected; there's likely more specific conditions required to hit the issue.

            Current suspicion is that something might go wrong if the delete is purged before the prepare.

            james.harrison James Harrison added a comment - - edited Attempted repros in unit test and with modified go repro code from MB-48179 haven't demonstrated the issue yet. For reference, with the go code against an ephemeral node ( Ashwin Govindarajulu mentioned this is more reliably demonstrated under ephemeral) the hashtable state is as follows for each stage: # After sync write $ cbstats -u Administrator -p asdasd localhost:12002 raw "_hash-dump 644" vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:0 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values: OSV @0x10fd8de40 .C. W.R.Cp. temp: seq:2 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 1 OSV @0x1102059e0 .C. W.R.Pc. temp: seq:1 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0   # After delete vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:1 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values: OSV @0x10fd8de40 ... WDR.Cm. temp: seq:3 rev:2 cas:1633090625222148096 key:"cid:0x0:daniel, size:7" del_time:1633090624 age:0 fc:0 vallen:0 prepareSeqno: 1 OSV @0x1102059e0 .C. W.R.Pc. temp: seq:1 rev:1 cas:1633090595216424960 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:4 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0   # After sync write 2 vb:644: HashTable[0x110861a20] with numItems:2 numInMemory:2 numDeleted:0 numNonResident:0 numTemp:0 numSystemItems:0 numPreparedSW:1 values: OSV @0x10fd8de40 .C. W.R.Cp. temp: seq:5 rev:3 cas:1633090655223808000 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:1 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 4 OSV @0x1102059e0 .C. W.R.Pc. temp: seq:4 rev:3 cas:1633090655223808000 key:"cid:0x0:daniel, size:7" exp:0 age:0 fc:5 vallen:52 val age:0 :"������������ <cut>" prepareSeqno: 0 This is as expected; there's likely more specific conditions required to hit the issue. Current suspicion is that something might go wrong if the delete is purged before the prepare.

            Confirmed in unit testing that ephemeral behaviour differs when adding an item and finding just a completed prepare, vs a completed prepare and deleted item - a similar result to MB-48179 through a rather different path.

            Ashwin Govindarajulu if this does reproduce under a couchstore bucket then this is at least two separate problems, as the above is only applicable to ephemeral.

            james.harrison James Harrison added a comment - Confirmed in unit testing that ephemeral behaviour differs when adding an item and finding just a completed prepare, vs a completed prepare and deleted item - a similar result to MB-48179 through a rather different path. Ashwin Govindarajulu if this does reproduce under a couchstore bucket then this is at least two separate problems, as the above is only applicable to ephemeral.

            Unfortunately, the repro may in fact represent a separate issue; the rev seqno returns to 1, rather than 2, and relies upon ephemeral metadata purging - for which I believe the default age set by ns_server is a day (in contrast to memcached's default of 60s) and as I understand the QE test was definitely not long-running enough for that.

            james.harrison James Harrison added a comment - Unfortunately, the repro may in fact represent a separate issue; the rev seqno returns to 1, rather than 2, and relies upon ephemeral metadata purging - for which I believe the default age set by ns_server is a day (in contrast to memcached's default of 60s) and as I understand the QE test was definitely not long-running enough for that.

            For reference this is the end state of the HT in the QE cluster:

                OSV @0x7f49fde043c0 ..J W.R.Pc. temp:    seq:491 rev:2 cas:1633086240216121344 key:"cid:0x0:test_docs0, size:11" exp:0 age:0 fc:5 vallen:2 val age:0 :"{}" prepareSeqno: 0
                OSV @0x7f49fde04420 ..J W.R.Cp. temp:    seq:492 rev:2 cas:1633086240216121344 key:"cid:0x0:test_docs0, size:11" exp:0 age:0 fc:1 vallen:2 val age:0 :"{}" prepareSeqno: 491
            

            This looks similar to what would be expected if the delete never occurred.

            james.harrison James Harrison added a comment - For reference this is the end state of the HT in the QE cluster: OSV @0x7f49fde043c0 ..J W.R.Pc. temp: seq:491 rev:2 cas:1633086240216121344 key:"cid:0x0:test_docs0, size:11" exp:0 age:0 fc:5 vallen:2 val age:0 :"{}" prepareSeqno: 0 OSV @0x7f49fde04420 ..J W.R.Cp. temp: seq:492 rev:2 cas:1633086240216121344 key:"cid:0x0:test_docs0, size:11" exp:0 age:0 fc:1 vallen:2 val age:0 :"{}" prepareSeqno: 491 This looks similar to what would be expected if the delete never occurred.

            Locally reproduced the original issue - it's a bug with add specifically. Investigating further.

            james.harrison James Harrison added a comment - Locally reproduced the original issue - it's a bug with add specifically. Investigating further.
            james.harrison James Harrison added a comment - - edited

            kv_engine/engines/ep/src/vbucket.cc

            3477
                    if (v->isTempDeletedItem()) {
            3478
                        itm.setRevSeqno(v->getRevSeqno() + 1);
            3479
                    } else {
            3480
                        itm.setRevSeqno(ht.getMaxDeletedRevSeqno() + 1);
            3481
                    }
            3482
             
            3483
                    if (!v->isTempItem()) {
            3484
                        itm.setRevSeqno(v->getRevSeqno() + 1);
            3485
                    }
            

            The correct revSeqno of 3 is set by itm.setRevSeqno(ht.getMaxDeletedRevSeqno() + 1);, but is then overwritten.

            v here is the completed prepare from the original sync write, selected by selectSVToModify because this is a sync write add. It has a rev seqno of 1, but the committed, deleted value which is also present has a rev seqno of 2.

            In general, completed prepares may be arbitrarily older than the committed value, and probably should not be used as the source of a revSeqno.

            james.harrison James Harrison added a comment - - edited kv_engine/engines/ep/src/vbucket.cc 3477 if (v->isTempDeletedItem()) { 3478 itm.setRevSeqno(v->getRevSeqno() + 1); 3479 } else { 3480 itm.setRevSeqno(ht.getMaxDeletedRevSeqno() + 1); 3481 } 3482   3483 if (!v->isTempItem()) { 3484 itm.setRevSeqno(v->getRevSeqno() + 1); 3485 } The correct revSeqno of 3 is set by itm.setRevSeqno(ht.getMaxDeletedRevSeqno() + 1); , but is then overwritten. v here is the completed prepare from the original sync write, selected by selectSVToModify because this is a sync write add. It has a rev seqno of 1, but the committed, deleted value which is also present has a rev seqno of 2. In general, completed prepares may be arbitrarily older than the committed value, and probably should not be used as the source of a revSeqno.
            wayne Wayne Siu made changes -
            Link This issue blocks MB-46308 [ MB-46308 ]
            wayne Wayne Siu made changes -
            Labels durability functional-test approved-for-7.0.2 durability functional-test
            owend Daniel Owen made changes -
            Due Date 06/Oct/21

            Build couchbase-server-7.0.2-6701 contains kv_engine commit d7889ff with commit message:
            MB-48713: Set correct revSeqno for sync write add for Ephemeral

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.2-6701 contains kv_engine commit d7889ff with commit message: MB-48713 : Set correct revSeqno for sync write add for Ephemeral

            Merged for 7.0.2, merging forward for Neo.

            james.harrison James Harrison added a comment - Merged for 7.0.2, merging forward for Neo.

            Validated the fix using both Couchbase + Ephemeral buckets on 7.0.2-6703.

            ashwin.govindarajulu Ashwin Govindarajulu added a comment - Validated the fix using both Couchbase + Ephemeral buckets on 7.0.2-6703.

            Build couchbase-server-7.1.0-1468 contains kv_engine commit d7889ff with commit message:
            MB-48713: Set correct revSeqno for sync write add for Ephemeral

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.1.0-1468 contains kv_engine commit d7889ff with commit message: MB-48713 : Set correct revSeqno for sync write add for Ephemeral
            wayne Wayne Siu made changes -
            Link This issue blocks MB-47673 [ MB-47673 ]
            wayne Wayne Siu made changes -
            Labels approved-for-7.0.2 durability functional-test approved-for-6.6.4 approved-for-7.0.2 durability functional-test

            Build couchbase-server-6.6.4-9922 contains kv_engine commit aa44e45 with commit message:
            MB-48713: [BP] Set correct revSeqno for sync write add for Ephemeral

            build-team Couchbase Build Team added a comment - Build couchbase-server-6.6.4-9922 contains kv_engine commit aa44e45 with commit message: MB-48713 : [BP] Set correct revSeqno for sync write add for Ephemeral

            Fix merged for 6.6.4, 7.0.2, Neo.

            james.harrison James Harrison added a comment - Fix merged for 6.6.4, 7.0.2, Neo.
            james.harrison James Harrison made changes -
            Assignee James Harrison [ james.harrison ] Ashwin Govindarajulu [ ashwin.govindarajulu ]
            Resolution Fixed [ 1 ]
            Status Open [ 1 ] Resolved [ 5 ]

            Validated 6.6.4 build 9922 

            ashwin.govindarajulu Ashwin Govindarajulu added a comment - Validated 6.6.4 build 9922  
            ashwin.govindarajulu Ashwin Govindarajulu made changes -
            Status Resolved [ 5 ] Closed [ 6 ]

            Build couchbase-server-7.0.3-7005 contains kv_engine commit aa44e45 with commit message:
            MB-48713: [BP] Set correct revSeqno for sync write add for Ephemeral

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.3-7005 contains kv_engine commit aa44e45 with commit message: MB-48713 : [BP] Set correct revSeqno for sync write add for Ephemeral

            Build couchbase-server-7.1.0-1769 contains kv_engine commit aa44e45 with commit message:
            MB-48713: [BP] Set correct revSeqno for sync write add for Ephemeral

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.1.0-1769 contains kv_engine commit aa44e45 with commit message: MB-48713 : [BP] Set correct revSeqno for sync write add for Ephemeral
            wayne Wayne Siu made changes -
            Link This issue blocks MB-50048 [ MB-50048 ]
            drigby Dave Rigby made changes -
            Link This issue relates to MB-48179 [ MB-48179 ]
            drigby Dave Rigby made changes -
            Summary rev ids going backwards - non-sync-write delete [Ephemeral] Rev id going backwards for SyncWrite add
            drigby Dave Rigby made changes -
            Description Build: 7.0.2-6683

            Steps to reproduce:
             # Create a doc using Sync_Write (MAJORITY)
             # Delete the same doc using non-sync delete operation
             # Create the same same using sync_write (MAJORITY)

            Observation:

            Rev Id of the document after step#3 remains 2 instead of '3'

            Ref: MB-48179

             
            Build: 7.0.2-6683

            *Steps to reproduce*:
             # Create a doc using Sync_Write (MAJORITY)
             # Delete the same doc using non-sync delete operation
             # Create the same same using sync_write (MAJORITY)

            Observation:

            Rev Id of the document after step#3 remains 2 instead of '3'

            *Impact*

            Revision id (revid) is primarily used for XDCR conflict resolution. Documents which are affected by this issue may not have the correct update selected if the same key exists on an XDCR target Bucket.

            Ref: MB-48179

             
            drigby Dave Rigby made changes -
            Description Build: 7.0.2-6683

            *Steps to reproduce*:
             # Create a doc using Sync_Write (MAJORITY)
             # Delete the same doc using non-sync delete operation
             # Create the same same using sync_write (MAJORITY)

            Observation:

            Rev Id of the document after step#3 remains 2 instead of '3'

            *Impact*

            Revision id (revid) is primarily used for XDCR conflict resolution. Documents which are affected by this issue may not have the correct update selected if the same key exists on an XDCR target Bucket.

            Ref: MB-48179

             
            Build: 7.0.2-6683

            *Steps to reproduce*:
             # Create a doc using Sync_Write (MAJORITY)
             # Delete the same doc using non-sync delete operation
             # Create the same same using sync_write (MAJORITY)

            *Observation*:

            Rev Id of the document after step#3 remains 2 instead of '3'

            *Impact*

            Revision id (revid) is primarily used for XDCR conflict resolution. Documents which are affected by this issue may not have the correct update selected if the same key exists on an XDCR target Bucket.

            Ref: MB-48179

             

            People

              ashwin.govindarajulu Ashwin Govindarajulu
              ashwin.govindarajulu Ashwin Govindarajulu
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                PagerDuty