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

Travel-sample Bucket does not load successfully

    XMLWordPrintable

Details

    Description

      Loaded sample Bucket - Travel sample and no items count observed for it.

      When tried to access its data from Document error observed as:

      Query: select meta().id from `travel-sample`.`_default`.`_default` data order by meta().id limit 200 offset 0
      Code: 4000
      Message: "Primary index def_primary not online."

      On Indexes Status observed as created as "21.5K mutations remaining".

      In Logs , Event failed to load travel sample with below error:

      2021-02-22T01:52:18.688-08:00 (REST) (Attempt 1) (GET) (404) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:18.688-08:00 WARN: (REST) (Attempt 1) (GET) Request to endpoint '/pools/default/buckets/travel-sample' failed with status code 404 -- rest.(*Request).Execute() at request.go:142
      2021-02-22T01:52:18.688-08:00 Bucket travel-sample does not exist, creating one with the specified settings
      2021-02-22T01:52:18.688-08:00 (REST) (Attempt 1) (POST) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets'
      2021-02-22T01:52:18.718-08:00 (REST) (Attempt 1) (POST) (202) Received response from 'http://172.23.96.228:8091/pools/default/buckets'
      2021-02-22T01:52:19.721-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:19.735-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:20.721-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:20.738-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:21.727-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:21.746-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:22.721-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:22.728-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:22.729-08:00 (Plan) (Bucket) Successfully ensured bucket 'travel-sample' exists | {"number":1,"duration":"4.0430114s"}
      2021-02-22T01:52:22.729-08:00 (Plan) (Bucket) Automatically creating/editing scopes/collections for bucket 'travel-sample'
      2021-02-22T01:52:22.729-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:22.736-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:22.736-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes'
      2021-02-22T01:52:22.738-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes'
      2021-02-22T01:52:22.738-08:00 (REST) (Attempt 1) (POST) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes/%40ensureManifest/0'
      2021-02-22T01:52:22.741-08:00 (REST) (Attempt 1) (POST) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes/%40ensureManifest/0'
      2021-02-22T01:52:22.742-08:00 (REST) (Attempt 1) (PUT) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes?validOnUid=0'
      2021-02-22T01:52:22.781-08:00 (REST) (Attempt 1) (PUT) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes?validOnUid=0'
      2021-02-22T01:52:22.783-08:00 (REST) (Attempt 1) (POST) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes/%40ensureManifest/1'
      2021-02-22T01:52:25.334-08:00 (REST) (Attempt 1) (POST) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample/scopes/%40ensureManifest/1'
      2021-02-22T01:52:25.334-08:00 (Plan) (Bucket) Successfully created/edited scopes/collections for bucket 'travel-sample' | {"number":2,"duration":"2.6049829s"}
      2021-02-22T01:52:25.334-08:00 (Plan) (Bucket) Transferring bucket configuration for bucket 'travel-sample'
      2021-02-22T01:52:25.335-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:25.375-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:25.376-08:00 Editing bucket to conform with settings provided
      2021-02-22T01:52:25.376-08:00 (REST) (Attempt 1) (POST) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:25.471-08:00 (REST) (Attempt 1) (POST) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:26.482-08:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:26.499-08:00 (REST) (Attempt 1) (GET) (200) Received response from 'http://172.23.96.228:8091/pools/default/buckets/travel-sample'
      2021-02-22T01:52:26.500-08:00 (Plan) (Bucket) Successfully transferred bucket configuration for bucket 'travel-sample' | {"number":3,"duration":"1.165999s"}
      2021-02-22T01:52:26.500-08:00 (Plan) (Index) Transferring views definitions for bucket 'travel-sample'
      2021-02-22T01:52:27.142-08:00 (Plan) (Index) Successfully transferred views definitions for bucket 'travel-sample' | {"number":4,"duration":"641.9958ms"}
      2021-02-22T01:52:27.142-08:00 (Plan) (Query) Executing queries for bucket 'travel-sample'
      2021-02-22T01:52:57.931-08:00 JSON import failed: 0 documents were imported, 0 documents failed to be imported
      JSON import failed: 0 documents were imported, 0 documents failed to be imported
      2021-02-22T01:52:57.931-08:00 JSON import failed: failed to execute cluster operations: failed to execute bucket operation for bucket 'travel-sample': failed to execute queries for bucket 'travel-sample': failed to execute queries against sink bucket: failed to execute query: ambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"ambiguous timeout"}},"OperationID":"http","Opaque":"1207c833-bc51-4fa5-b866-52e44ecd673f","TimeObserved":30000018100,"RetryReasons":null,"RetryAttempts":0,"LastDispatchedTo":"http://172.23.96.228:8093","LastDispatchedFrom":"","LastConnectionID":""} | {"statement":"CREATE PRIMARY INDEX def_primary on `travel-sample` USING GSI WITH {\"defer_build\":true}","client_context_id":"1207c833-bc51-4fa5-b866-52e44ecd673f"}
      
      

      Attachments

        For Gerrit Dashboard: MB-44493
        # Subject Branch Project Status CR V

        Activity

          I observe:

          [error_logger:error,2021-02-23T09:55:24.951Z,ns_1@127.0.0.1:<0.2341.0>:ale_error_logger_handler:do_log:107]
          =========================CRASH REPORT=========================
           crasher:
           initial call: samples_loader_tasks:perform_loading_task/2
           pid: <0.2341.0>
           registered_name: []
           exception exit: {failed_to_load_samples,1,
           <<"2021-02-23T09:54:51.019+00:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://127.0.0.1:8091/pools/default/nodeServices'\n2021-02-23T09:54:51.021+00:00 (REST) (Attempt 1) (GET) "...>>}
           in function samples_loader_tasks:perform_loading_task/2 (src/samples_loader_tasks.erl, line 148)
          ...
          [ns_server:debug,2021-02-23T09:55:24.951Z,ns_1@127.0.0.1:samples_loader_tasks<0.448.0>:samples_loader_tasks:handle_info:72]Consumed exit signal from samples loading task travel-sample: {'EXIT',
           <0.2341.0>,
           {failed_to_load_samples,
          ...
          2021-02-23T09:54:54.798+00:00 (Plan) (Query) Executing queries for bucket 'travel-sample'
          2021-02-23T09:55:24.944+00:00 JSON import failed: 0 documents were imported, 0 documents failed to be imported
          JSON import failed: 0 documents were imported, 0 documents failed to be imported

          in the debug.log.

          This first fails in 4503. According to the change log:

           

          $ curl -o - http://172.23.126.166/builds/latestbuilds/couchbase-server/cheshire-cat/4503/CHANGELOG
          changed projects :
          backup changed from 925a3c66ccbe26e1e6dce31c39256425442f5f1d to master
           [+] 2bcbb36f MB-44439 Validate that the --threads argument has a sane value
          goproj/src/github.com/couchbase/query changed from 3f71b58ec8122dfea6eb9038f628a8df2b10687c to master
           [+] 722a8f6e MB-38653. Transactional statement rest values
          kv_engine changed from e0a6dbb4d90202aa6e957871bbb78222cf94b1f0 to master
           [+] 858ac67e0 MB-42224: Remove CouchKVStore::commit2couchstore
           [+] e8a8a808b MB-44140: Make KVStore::getCollectionsManifest return status
           [+] 5335b0327 MB-44255: Add _vbucket-details so that we can dump seqlist
          

           

          If I extract the sample ZIP and run cbimport on the command line, the documents do import OK.

          Donald.haggart Donald Haggart added a comment - I observe: [error_logger:error,2021-02-23T09:55:24.951Z,ns_1@127.0.0.1:<0.2341.0>:ale_error_logger_handler:do_log:107] =========================CRASH REPORT========================= crasher: initial call: samples_loader_tasks:perform_loading_task/2 pid: <0.2341.0> registered_name: [] exception exit: {failed_to_load_samples,1, <<"2021-02-23T09:54:51.019+00:00 (REST) (Attempt 1) (GET) Dispatching request to 'http://127.0.0.1:8091/pools/default/nodeServices'\n2021-02-23T09:54:51.021+00:00 (REST) (Attempt 1) (GET) "...>>} in function samples_loader_tasks:perform_loading_task/2 (src/samples_loader_tasks.erl, line 148) ... [ns_server:debug,2021-02-23T09:55:24.951Z,ns_1@127.0.0.1:samples_loader_tasks<0.448.0>:samples_loader_tasks:handle_info:72]Consumed exit signal from samples loading task travel-sample: {'EXIT', <0.2341.0>, {failed_to_load_samples, ... 2021-02-23T09:54:54.798+00:00 (Plan) (Query) Executing queries for bucket 'travel-sample' 2021-02-23T09:55:24.944+00:00 JSON import failed: 0 documents were imported, 0 documents failed to be imported JSON import failed: 0 documents were imported, 0 documents failed to be imported in the debug.log. This first fails in 4503 . According to the change log:   $ curl -o - http://172.23.126.166/builds/latestbuilds/couchbase-server/cheshire-cat/4503/CHANGELOG changed projects : backup changed from 925a3c66ccbe26e1e6dce31c39256425442f5f1d to master [+] 2bcbb36f MB-44439 Validate that the --threads argument has a sane value goproj/src/github.com/couchbase/query changed from 3f71b58ec8122dfea6eb9038f628a8df2b10687c to master [+] 722a8f6e MB-38653. Transactional statement rest values kv_engine changed from e0a6dbb4d90202aa6e957871bbb78222cf94b1f0 to master [+] 858ac67e0 MB-42224: Remove CouchKVStore::commit2couchstore [+] e8a8a808b MB-44140: Make KVStore::getCollectionsManifest return status [+] 5335b0327 MB-44255: Add _vbucket-details so that we can dump seqlist   If I extract the sample ZIP and run cbimport on the command line, the documents do import OK.

          Sitaram Vemulapalli if I back-out MB-38653, the samples load.  Do you think you could help take a look to see what's going awry here?

          I can see in the query.log:

          2021-02-23T11:33:45.587+00:00 [Info] CreateIndex travel-sample _default _default def_primary ...
          2021-02-23T11:33:45.587+00:00 [Info] send prepare create request to watcher 127.0.0.1:9100
          2021-02-23T11:33:45.591+00:00 [Info] Indexer 127.0.0.1:9100 accept prepare request. Index (travel-sample, _default, _default, def_primary)
          2021-02-23T11:33:45.591+00:00 [Info] Skipping planner for creation of the index travel-sample:_default:_default:def_primary
          2021-02-23T11:33:45.591+00:00 [Info] send commit create request to watcher 127.0.0.1:9100
          2021-02-23T11:33:45.614+00:00 [Info] CreateIndex 12618860922728152625 travel-sample _default _default/def_primary using:GSI exprType
          :N1QL whereExpr:<ud>()</ud> secExprs:<ud>([])</ud> desc:[] isPrimary:true scheme:SINGLE  partitionKeys:<ud>([])</ud> with:{"defer_build":true} - elapsed(27.118263ms) err(<nil>)
          2021-02-23T11:33:45.614+00:00 [Info] metadata provider version changed 8 -> 11
          2021-02-23T11:33:45.614+00:00 [Info] switched currmeta from 8 -> 11 force false 
          2021-02-23T11:33:45.614+00:00 [Info] GsiClient::UpdateUsecjson: using collatejson as data format between indexer and GsiClient
          

          so it appears to execute successfully and request the commit.  I don't see any difference in the logged messages with it backed out.

          The CreatePrimaryIndex execution completes without error and the indexer.log shows a successful OPCODE_COMMIT_CREATE_INDEX, but no sign of the subsequent index creation statements, so the flow back from CreatePrimaryIndex must be influencing things.

          Donald.haggart Donald Haggart added a comment - Sitaram Vemulapalli if I back-out MB-38653, the samples load.  Do you think you could help take a look to see what's going awry here? I can see in the query.log: 2021-02-23T11:33:45.587+00:00 [Info] CreateIndex travel-sample _default _default def_primary ... 2021-02-23T11:33:45.587+00:00 [Info] send prepare create request to watcher 127.0.0.1:9100 2021-02-23T11:33:45.591+00:00 [Info] Indexer 127.0.0.1:9100 accept prepare request. Index (travel-sample, _default, _default, def_primary) 2021-02-23T11:33:45.591+00:00 [Info] Skipping planner for creation of the index travel-sample:_default:_default:def_primary 2021-02-23T11:33:45.591+00:00 [Info] send commit create request to watcher 127.0.0.1:9100 2021-02-23T11:33:45.614+00:00 [Info] CreateIndex 12618860922728152625 travel-sample _default _default/def_primary using:GSI exprType :N1QL whereExpr:<ud>()</ud> secExprs:<ud>([])</ud> desc:[] isPrimary:true scheme:SINGLE partitionKeys:<ud>([])</ud> with:{"defer_build":true} - elapsed(27.118263ms) err(<nil>) 2021-02-23T11:33:45.614+00:00 [Info] metadata provider version changed 8 -> 11 2021-02-23T11:33:45.614+00:00 [Info] switched currmeta from 8 -> 11 force false 2021-02-23T11:33:45.614+00:00 [Info] GsiClient::UpdateUsecjson: using collatejson as data format between indexer and GsiClient so it appears to execute successfully and request the commit.  I don't see any difference in the logged messages with it backed out. The CreatePrimaryIndex execution completes without error and the indexer.log shows a successful OPCODE_COMMIT_CREATE_INDEX, but no sign of the subsequent index creation statements, so the flow back from CreatePrimaryIndex must be influencing things.

          Worth noting that the authentication method used from running it from the command line and how it's executed by the cluster manager is different. Not sure if that is related given that it looks to accept the 1st operation.

          pvarley Patrick Varley added a comment - Worth noting that the authentication method used from running it from the command line and how it's executed by the cluster manager is different. Not sure if that is related given that it looks to accept the 1st operation.

          Build couchbase-server-7.0.0-4524 contains query commit cfc667f with commit message:
          MB-44493 Ensure prepared output persists

          build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-4524 contains query commit cfc667f with commit message: MB-44493 Ensure prepared output persists

          Sanity test are showing green now

          pierre.regazzoni Pierre Regazzoni added a comment - Sanity test are showing green now

          People

            pierre.regazzoni Pierre Regazzoni
            deepika.verma Deepika Verma (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty