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

Duplicate named index created on same collection during upgrade from 7.0.3 to 7.0.4

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Duplicate
    • 7.0.3, 7.0.4
    • None
    • secondary-index
    • CBS-7.0.3-7031
      CBS-7.0.4-7261
    • Untriaged
    • Centos 64-bit
    • 1
    • Unknown

    Description

      While testing the below scenario, there are duplicate named secondary indexes exist on same collection for different fields. This was a random tests and no clear path is there to reproduce the scenario. I have provide the detailed description of all the operation I have performed during test

      Steps to reproduce:

      1. Create a 6 node cluster with 7.0.3 - kv-kv-index-index-n1ql-n1ql
      2. Load some data say 10k to collection
      3. create few indexes on some field

        CREATE INDEX `idx_0_0` ON `test`.`test_scope_1`.`test_collection_1`(`Field_4`)

      4. Now run parallel queries to create few indexes and scan request with request_plus consistency while upgrading one node for each of the service. Have an index definition with the different field but same name also.

      CREATE INDEX `idx_0_0` ON `test`.`test_scope_1`.`test_collection_1`(`Field_10`)

      #  Duplicated named index would be created on the same collection.

      1. An explain for below queries refers to same index

        explain select * from `test`.`test_scope_1`.`test_collection_1` where Field_10 is not null;
         
        [
          {
            "plan": {
              "#operator": "Sequence",
              "~children": [
                {
                  "#operator": "IndexScan3",
                  "bucket": "test",
                  "index": "idx_0_0",
                  "index_id": "fb1c043e857b1e47",
                  "index_projection": {
                    "primary_key": true
                  },
                  "keyspace": "test_collection_1",
                  "namespace": "default",
                  "scope": "test_scope_1",
                  "spans": [
                    {
                      "exact": true,
                      "range": [
                        {
                          "inclusion": 0,
                          "low": "null"
                        }
                      ]
                    }
                  ],
                  "using": "gsi"
                },
                {
                  "#operator": "Fetch",
                  "bucket": "test",
                  "keyspace": "test_collection_1",
                  "namespace": "default",
                  "scope": "test_scope_1"
                },
                {
                  "#operator": "Parallel",
                  "~child": {
                    "#operator": "Sequence",
                    "~children": [
                      {
                        "#operator": "Filter",
                        "condition": "((`test_collection_1`.`Field_10`) is not null)"
                      },
                      {
                        "#operator": "InitialProject",
                        "result_terms": [
                          {
                            "expr": "self",
                            "star": true
                          }
                        ]
                      }
                    ]
                  }
                }
              ]
            },
            "text": "select * from `test`.`test_scope_1`.`test_collection_1` where Field_10 is not null;"
          }
        ]
         
         
        explain select * from `test`.`test_scope_1`.`test_collection_1` where Field_4 is not null;
         
        [
          {
            "plan": {
              "#operator": "Sequence",
              "~children": [
                {
                  "#operator": "IndexScan3",
                  "bucket": "test",
                  "index": "idx_0_0",
                  "index_id": "5b1de9b8fc2e8e3f",
                  "index_projection": {
                    "primary_key": true
                  },
                  "keyspace": "test_collection_1",
                  "namespace": "default",
                  "scope": "test_scope_1",
                  "spans": [
                    {
                      "exact": true,
                      "range": [
                        {
                          "inclusion": 0,
                          "low": "null"
                        }
                      ]
                    }
                  ],
                  "using": "gsi"
                },
                {
                  "#operator": "Fetch",
                  "bucket": "test",
                  "keyspace": "test_collection_1",
                  "namespace": "default",
                  "scope": "test_scope_1"
                },
                {
                  "#operator": "Parallel",
                  "~child": {
                    "#operator": "Sequence",
                    "~children": [
                      {
                        "#operator": "Filter",
                        "condition": "((`test_collection_1`.`Field_4`) is not null)"
                      },
                      {
                        "#operator": "InitialProject",
                        "result_terms": [
                          {
                            "expr": "self",
                            "star": true
                          }
                        ]
                      }
                    ]
                  }
                }
              ]
            },
            "text": "select * from `test`.`test_scope_1`.`test_collection_1` where Field_4 is not null;"
          }
        ]

      Logs are available at - 
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.107.zip
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.108.zip
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.109.zip
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.110.zip
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.111.zip
      https://cb-engineering.s3.amazonaws.com/upgrade_from_7.0.3_to_7.0.4/collectinfo-2022-04-20T062423-ns_1%40172.23.136.112.zip

      Attachments

        Issue Links

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

          Activity

            FYI, There is no 'Field_10' in any of the document.

            hemant.rajput Hemant Rajput added a comment - FYI, There is no 'Field_10' in any of the document.
            amit.kulkarni Amit Kulkarni added a comment - - edited

            The two index creations for index "idx_0_0". The first index gets created on node 136.110.

            query.log

            cbcollect_info_ns_1@172.23.136.111_20220420-062423/ns_server.query.log:2022-04-19T23:16:05.542-07:00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ...
             
            cbcollect_info_ns_1@172.23.136.111_20220420-062423/ns_server.query.log:2022-04-19T23:16:58.116-07:00 [Info] CreateIndex 18094342069441732167 test test_scope_1 test_collection_1/idx_0_0 using:GSI exprType:N1QL whereExpr:<ud>()</ud> secExprs:<ud>([`Field_10`])</ud> desc:[false] isPrimary:false scheme:SINGLE  partitionKeys:<ud>([])</ud> with: - elapsed(52.574553423s) err(<nil>)
            

            indexer.log

            cbcollect_info_ns_1@172.23.136.110_20220420-062423/ns_server.indexer.log:2022-04-19T23:16:06.848-07:00 [Info] clustMgrAgent::OnIndexCreate Notification Received for Create Index DefnId: 18094342069441732167 Name: idx_0_0 Using: plasma Bucket: test Scope/Id: test_scope_1/8 Collection/Id: test_collection_1/8 IsPrimary: false NumReplica: 0 InstVersion: 0 
             
            cbcollect_info_ns_1@172.23.136.110_20220420-062423/ns_server.indexer.log:2022-04-19T23:16:06.855-07:00 [Info] clustMgrAgent::OnIndexCreate Success for Create Index DefnId: 18094342069441732167 Name: idx_0_0 Using: plasma Bucket: test Scope/Id: test_scope_1/8 Collection/Id: test_collection_1/8 IsPrimary: false NumReplica: 0 InstVersion: 0
            

            Second index creation is triggered more than 2 mins later.

            cbcollect_info_ns_1@172.23.136.112_20220420-062423/ns_server.query.log:2022-04-19T23:18:49.336-07:00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ...
             
            cbcollect_info_ns_1@172.23.136.112_20220420-062423/ns_server.query.log:2022-04-19T23:18:49.360-07:00 [Info] CreateIndex 0 test test_scope_1 test_collection_1/idx_0_0 using:GSI exprType:N1QL whereExpr:<ud>()</ud> secExprs:<ud>([`Field_4`])</ud> desc:[false] isPrimary:false scheme:SINGLE  partitionKeys:<ud>([])</ud> with: - elapsed(23.714681ms) err(Encountered transient error.  Index creation will be retried in background.  Error: Index idx_0_0 will retry building in the background for reason: Build Already In Progress. Keyspace test:test_scope_1:test_collection_1.
            

            During second index creation, indexer node 136.110 is unhealthy. So it does not take part in distributed lock.

            2022-04-19T23:18:49.323-07:00 [Warn] node 3 status: "unhealthy"
            2022-04-19T23:18:49.323-07:00 [Info] Refreshed Indexer List: [172.23.136.109:9100]
             
            2022-04-19T23:18:49.336-07:00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ...
            2022-04-19T23:18:49.336-07:00 [Info] send prepare create request to watcher 172.23.136.109:9100
            2022-04-19T23:18:49.337-07:00 [Info] Indexer 172.23.136.109:9100 accept prepare request. Index (test, test_scope_1, test_collection_1, idx_0_0)
            2022-04-19T23:18:49.337-07:00 [Info] Skipping planner for creation of the index test:test_scope_1:test_collection_1:idx_0_0
            2022-04-19T23:18:49.338-07:00 [Info] send commit create request to watcher 172.23.136.109:9100 defnID 6565660812490214975
            

            From the indexer logs on node 136.110, it looks like the indexer may not be running when the second index was getting created.

            2022-04-19T23:18:22.597-07:00 [Info] TK StreamBegin MAINT_STREAM test 378 26848047857137 3245 1 172.23.136.107:8091. HWT [3244-3245,3245].
            Initializing write barrier = 8000
            2022-04-19T23:19:27.122-07:00 [Info] Indexer started with command line: [/opt/couchbase/bin/indexer -adminPort=9100 -scanPort=9101 -httpPort=9102 -streamInitPort=9103 -streamCatchupPort=9104 -streamMaintPort=9105 --httpsPort=19102 --certFile=/opt/couchbase/var/lib/couchbase/config/memcached-cert.pem --keyFile=/opt/couchbase/var/lib/couchbase/config/memcached-key.pem -ipv4=required -ipv6=optional -vbuckets=1024 -cluster=127.0.0.1:8091 -storageDir=/opt/couchbase/var/lib/couchbase/data/@2i -diagDir=/opt/couchbase/var/lib/couchbase/crash -logDir=/opt/couchbase/var/lib/couchbase/logs -nodeUUID=eebb214d559b6261322ec2461c963225 -isEnterprise=true]
            

            Looks like Couchbase Server was shutdown during this time (as per ns_server info logs).

            [ns_server:info,2022-04-19T23:18:22.850-07:00,ns_1@172.23.136.110:ns_couchdb_port<0.8130.0>:ns_port_server:handle_info:146]Got {exit_status,0} from port ns_couchdb. Exiting normally
            ns_couchdb<0.8130.0>: [os_mon] cpu supervisor port (cpu_sup): Erlang has closed
            ns_couchdb<0.8130.0>: [os_mon] memory supervisor port (memsup): Erlang has closed
             
            [ns_server:info,2022-04-19T23:18:22.856-07:00,ns_1@172.23.136.110:<0.9.0>:ns_bootstrap:stop:39]Successfully stopped ns_server
            [ns_server:info,2022-04-19T23:19:23.574-07:00,nonode@nohost:<0.140.0>:ns_server:init_logging:118]Started & configured logging
            

            As the host node for the first index idx_0_0, is unhealthy (stopped), there is no way to know about presence of the first index. Hence this is expected behaviour.

            Duplicate of MB-46007.

            amit.kulkarni Amit Kulkarni added a comment - - edited The two index creations for index "idx_0_0". The first index gets created on node 136.110. query.log cbcollect_info_ns_1 @172 .23. 136 .111_20220420- 062423 /ns_server.query.log: 2022 - 04 -19T23: 16 : 05.542 - 07 : 00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ...   cbcollect_info_ns_1 @172 .23. 136 .111_20220420- 062423 /ns_server.query.log: 2022 - 04 -19T23: 16 : 58.116 - 07 : 00 [Info] CreateIndex 18094342069441732167 test test_scope_1 test_collection_1/idx_0_0 using:GSI exprType:N1QL whereExpr:<ud>()</ud> secExprs:<ud>([`Field_10`])</ud> desc:[ false ] isPrimary: false scheme:SINGLE partitionKeys:<ud>([])</ud> with: - elapsed( 52 .574553423s) err(<nil>) indexer.log cbcollect_info_ns_1 @172 .23. 136 .110_20220420- 062423 /ns_server.indexer.log: 2022 - 04 -19T23: 16 : 06.848 - 07 : 00 [Info] clustMgrAgent::OnIndexCreate Notification Received for Create Index DefnId: 18094342069441732167 Name: idx_0_0 Using: plasma Bucket: test Scope/Id: test_scope_1/ 8 Collection/Id: test_collection_1/ 8 IsPrimary: false NumReplica: 0 InstVersion: 0   cbcollect_info_ns_1 @172 .23. 136 .110_20220420- 062423 /ns_server.indexer.log: 2022 - 04 -19T23: 16 : 06.855 - 07 : 00 [Info] clustMgrAgent::OnIndexCreate Success for Create Index DefnId: 18094342069441732167 Name: idx_0_0 Using: plasma Bucket: test Scope/Id: test_scope_1/ 8 Collection/Id: test_collection_1/ 8 IsPrimary: false NumReplica: 0 InstVersion: 0 Second index creation is triggered more than 2 mins later. cbcollect_info_ns_1 @172 .23. 136 .112_20220420- 062423 /ns_server.query.log: 2022 - 04 -19T23: 18 : 49.336 - 07 : 00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ...   cbcollect_info_ns_1 @172 .23. 136 .112_20220420- 062423 /ns_server.query.log: 2022 - 04 -19T23: 18 : 49.360 - 07 : 00 [Info] CreateIndex 0 test test_scope_1 test_collection_1/idx_0_0 using:GSI exprType:N1QL whereExpr:<ud>()</ud> secExprs:<ud>([`Field_4`])</ud> desc:[ false ] isPrimary: false scheme:SINGLE partitionKeys:<ud>([])</ud> with: - elapsed( 23 .714681ms) err(Encountered transient error. Index creation will be retried in background. Error: Index idx_0_0 will retry building in the background for reason: Build Already In Progress. Keyspace test:test_scope_1:test_collection_1. During second index creation, indexer node 136.110 is unhealthy. So it does not take part in distributed lock. 2022 - 04 -19T23: 18 : 49.323 - 07 : 00 [Warn] node 3 status: "unhealthy" 2022 - 04 -19T23: 18 : 49.323 - 07 : 00 [Info] Refreshed Indexer List: [ 172.23 . 136.109 : 9100 ]   2022 - 04 -19T23: 18 : 49.336 - 07 : 00 [Info] CreateIndex test test_scope_1 test_collection_1 idx_0_0 ... 2022 - 04 -19T23: 18 : 49.336 - 07 : 00 [Info] send prepare create request to watcher 172.23 . 136.109 : 9100 2022 - 04 -19T23: 18 : 49.337 - 07 : 00 [Info] Indexer 172.23 . 136.109 : 9100 accept prepare request. Index (test, test_scope_1, test_collection_1, idx_0_0) 2022 - 04 -19T23: 18 : 49.337 - 07 : 00 [Info] Skipping planner for creation of the index test:test_scope_1:test_collection_1:idx_0_0 2022 - 04 -19T23: 18 : 49.338 - 07 : 00 [Info] send commit create request to watcher 172.23 . 136.109 : 9100 defnID 6565660812490214975 From the indexer logs on node 136.110, it looks like the indexer may not be running when the second index was getting created. 2022 - 04 -19T23: 18 : 22.597 - 07 : 00 [Info] TK StreamBegin MAINT_STREAM test 378 26848047857137 3245 1 172.23 . 136.107 : 8091 . HWT [ 3244 - 3245 , 3245 ]. Initializing write barrier = 8000 2022 - 04 -19T23: 19 : 27.122 - 07 : 00 [Info] Indexer started with command line: [/opt/couchbase/bin/indexer -adminPort= 9100 -scanPort= 9101 -httpPort= 9102 -streamInitPort= 9103 -streamCatchupPort= 9104 -streamMaintPort= 9105 --httpsPort= 19102 --certFile=/opt/couchbase/var/lib/couchbase/config/memcached-cert.pem --keyFile=/opt/couchbase/var/lib/couchbase/config/memcached-key.pem -ipv4=required -ipv6=optional -vbuckets= 1024 -cluster= 127.0 . 0.1 : 8091 -storageDir=/opt/couchbase/var/lib/couchbase/data/ @2i -diagDir=/opt/couchbase/var/lib/couchbase/crash -logDir=/opt/couchbase/var/lib/couchbase/logs -nodeUUID=eebb214d559b6261322ec2461c963225 -isEnterprise= true ] Looks like Couchbase Server was shutdown during this time (as per ns_server info logs). [ns_server:info, 2022 - 04 -19T23: 18 : 22.850 - 07 : 00 ,ns_1 @172 .23. 136.110 :ns_couchdb_port< 0.8130 . 0 >:ns_port_server:handle_info: 146 ]Got {exit_status, 0 } from port ns_couchdb. Exiting normally ns_couchdb< 0.8130 . 0 >: [os_mon] cpu supervisor port (cpu_sup): Erlang has closed ns_couchdb< 0.8130 . 0 >: [os_mon] memory supervisor port (memsup): Erlang has closed   [ns_server:info, 2022 - 04 -19T23: 18 : 22.856 - 07 : 00 ,ns_1 @172 .23. 136.110 :< 0.9 . 0 >:ns_bootstrap:stop: 39 ]Successfully stopped ns_server [ns_server:info, 2022 - 04 -19T23: 19 : 23.574 - 07 : 00 ,nonode @nohost :< 0.140 . 0 >:ns_server:init_logging: 118 ]Started & configured logging As the host node for the first index idx_0_0, is unhealthy (stopped), there is no way to know about presence of the first index. Hence this is expected behaviour. Duplicate of MB-46007 .
            wayne Wayne Siu added a comment -

            Closing as a dup of MB-46007

            wayne Wayne Siu added a comment - Closing as a dup of MB-46007

            People

              amit.kulkarni Amit Kulkarni
              hemant.rajput Hemant Rajput
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty