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

flex index test failure in build sanity

    XMLWordPrintable

Details

    • Untriaged
    • 1
    • Yes

    Description

      Started seeing this issue from 7.0.0-2945 in build sanity:

      18:12:01 ======================================================================
      18:12:01 FAIL: test_flex_with_napa_dataset (tuqquery.flex_index_phase1.FlexIndexTests)
      18:12:01 ----------------------------------------------------------------------
      18:12:01 Traceback (most recent call last):
      18:12:01 File "pytests/tuqquery/flex_index_phase1.py", line 483, in test_flex_with_napa_dataset
      18:12:01 name="default_index", source_name=self.bucket_name, doc_count=self.num_items)
      18:12:01 File "pytests/tuqquery/tuq.py", line 461, in create_fts_index
      18:12:01 self.wait_for_fts_indexing_complete(fts_index, doc_count)
      18:12:01 File "pytests/tuqquery/tuq.py", line 479, in wait_for_fts_indexing_complete
      18:12:01 doc_count))
      18:12:01 AssertionError: FTS indexing did not complete. FTS index count : 9777, Bucket count : 10000
      18:12:01
      18:12:01 ----------------------------------------------------------------------

      From FTS logs:

      20-08-25T17:57:57.162-07:00 [INFO] app_herder: indexing proceeding, indexes: 3, waiting: 1, usage: 89385208
      2020-08-25T17:57:57.163-07:00 [INFO] app_herder: indexing proceeding, indexes: 3, waiting: 0, usage: 89385208
      2020-08-25T17:59:26.946-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:26.971-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:26.989-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.090-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.090-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.090-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.090-07:00 [INFO] main: meh.OnFeedError, srcType: gocbcore, err: EOF |

      {"bucket":"default","last_dispatched_to":"172.23.105.151:11210","last_dispatched_from":"172.23.105.153:48978","last_connection_id":"827611409df2fab5/7e5f3a8aac3fdcad"}

      2020-08-25T17:59:27.093-07:00 [INFO] main: meh.OnFeedError, VerifySourceNotExists, srcType: gocbcore, gone: true, indexUUID:
      2020-08-25T17:59:27.093-07:00 [INFO] main: meh.OnFeedError, DeleteAllIndexFromSource, srcType: gocbcore, bucketName: default, bucketUUID: e87cf2fc8ec8cf490334f8547c691e3d
      2020-08-25T17:59:27.096-07:00 [INFO] manager_api: starting index definition deletion, indexType: fulltext-index, indexName: default_index, indexUUID: 18facb87f1f8d166
      2020-08-25T17:59:27.099-07:00 [INFO] cfg_metakv: Set, key: indexDefs, cas: 1, split: false, nodeUUID: 83d1ce30f1a4ee4d26f7d962309a490e
      2020-08-25T17:59:27.099-07:00 [INFO] cfg_metakv: Set path: /fts/cbgt/cfg/indexDefs
      2020-08-25T17:59:27.102-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
      2020-08-25T17:59:27.112-07:00 [INFO] cfg_metakv: Set, key: indexDefs, cas: 1, split: false, nodeUUID: 83d1ce30f1a4ee4d26f7d962309a490e
      2020-08-25T17:59:27.112-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
      2020-08-25T17:59:27.112-07:00 [INFO] ctl: kickIndexDefs, kind: cfgEvent
      2020-08-25T17:59:27.112-07:00 [INFO] cfg_metakv: Set path: /fts/cbgt/cfg/indexDefs
      2020-08-25T17:59:27.117-07:00 [INFO] manager_api: bumped indexDefs, indexDefsUUID: 58b43fe92c76e856
      2020-08-25T17:59:27.117-07:00 [INFO] manager_api: DeleteAllIndexFromSource, index deletions completed
      2020-08-25T17:59:27.118-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
      2020-08-25T17:59:27.144-07:00 [INFO] ctl: kickIndexDefs, kind: cfgEvent
      2020-08-25T17:59:27.147-07:00 [INFO] ctl: kickIndexDefs, kind: cfgEvent
      2020-08-25T17:59:27.155-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/indexDefs, key: indexDefs, deletion: false
      2020-08-25T17:59:27.157-07:00 [INFO] planner: nodesRemove: []string(nil)
      2020-08-25T17:59:27.157-07:00 [INFO] planner: step planner
      2020-08-25T17:59:27.161-07:00 [INFO] ctl: kickIndexDefs, kind: cfgEvent
      2020-08-25T17:59:27.169-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.170-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.170-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.170-07:00 [INFO] main: meh.OnFeedError, srcType: gocbcore, err: EOF |

      {"bucket":"default","last_dispatched_to":"172.23.107.160:11210","last_dispatched_from":"172.23.105.153:38796","last_connection_id":"c8e26a4259479010/176aad354912a236"}

      2020-08-25T17:59:27.173-07:00 [INFO] main: meh.OnFeedError, VerifySourceNotExists, srcType: gocbcore, gone: true, indexUUID:
      2020-08-25T17:59:27.173-07:00 [INFO] main: meh.OnFeedError, DeleteAllIndexFromSource, srcType: gocbcore, bucketName: default, bucketUUID: e87cf2fc8ec8cf490334f8547c691e3d
      2020-08-25T17:59:27.177-07:00 [ERRO] (GOCBCORE) Pipeline client `172.23.107.160:11210/0xc0004f8410` failed to shut down errored client socket (close tcp 172.23.105.153:38796->172.23.107.160:11210: use of closed network connection) – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.188-07:00 [INFO] planner: nodesRemove: []string(nil)
      2020-08-25T17:59:27.188-07:00 [INFO] planner: step planner
      2020-08-25T17:59:27.232-07:00 [INFO] cfg_metakv: Set, key: planPIndexes, cas: 4e, split: true, nodeUUID: 83d1ce30f1a4ee4d26f7d962309a490e
      2020-08-25T17:59:27.246-07:00 [INFO] cfg_metakv_lean: setLeanPlan, val: {"uuid":"4d2aa943ea9826b9","planPIndexes":{},"implVersion":"5.5.0","warnings":{}}
      2020-08-25T17:59:27.248-07:00 [INFO] cfg_metakv_lean: setLeanPlan, curMetaKvPlanKey set, val:

      {"path":"/fts/cbgt/cfg/planPIndexesLean/planPIndexesLean-c738ae19c1d00f67cfaeee99b0b081e4-1598403567246/","uuid":"4d2aa943ea9826b9","implVersion":"5.5.0"}

      2020-08-25T17:59:27.250-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/curMetaKvPlanKey, key: curMetaKvPlanKey, deletion: false
      2020-08-25T17:59:27.262-07:00 [INFO] cfg_metakv_lean: purgeOrphanedLeanPlans, purged path: /fts/cbgt/cfg/planPIndexesLean/planPIndexesLean-3c2ad32e9106db3948646a4a5aef6581-1598403466061/
      2020-08-25T17:59:27.267-07:00 [INFO] cfg_metakv_lean: purgeOrphanedLeanPlans, purged path: /fts/cbgt/cfg/planPIndexesLean/planPIndexesLean-67667e6462a2428a6084d98d64217438-1598403466093/
      2020-08-25T17:59:27.287-07:00 [INFO] janitor: awakes, op: kick, msg: cfg changed, key: curMetaKvPlanKey
      2020-08-25T17:59:27.287-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/planPIndexesLean/planPIndexesLean-3c2ad32e9106db3948646a4a5aef6581-1598403466061/default_index, key: planPIndexesLean/planPIndexesLean-3c2ad32e9106db3948646a4a5aef6581-1598403466061/default_index, deletion: true
      2020-08-25T17:59:27.319-07:00 [INFO] cfg_metakv: metaKVCallback, path: /fts/cbgt/cfg/planPIndexesLean/planPIndexesLean-67667e6462a2428a6084d98d64217438-1598403466093/default_index, key: planPIndexesLean/planPIndexesLean-67667e6462a2428a6084d98d64217438-1598403466093/default_index, deletion: true
      2020-08-25T17:59:27.331-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.332-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.332-07:00 [INFO] main: meh.OnFeedError, srcType: gocbcore, err: EOF |

      {"bucket":"default","last_dispatched_to":"172.23.105.153:11210","last_dispatched_from":"172.23.105.153:55168","last_connection_id":"87ce3ffd0c72fd1b/a4dd8102a5a2a567"}

      2020-08-25T17:59:27.332-07:00 [ERRO] (GOCBCORE) memdClient read failure: EOF – cbgt.GocbcoreLogger.Log() at gocbcore_helper.go:635
      2020-08-25T17:59:27.346-07:00 [INFO] main: meh.OnFeedError, VerifySourceNotExists, srcType: gocbcore, gone: true, indexUUID:
      2020-08-25T17:59:27.346-07:00 [INFO] main: meh.OnFeedError, DeleteAllIndexFromSource, srcType: gocbcore, bucketName: default, bucketUUID: e87cf2fc8ec8cf490334f8547c691e3d
      2020-08-25T17:59:27.386-07:00 [INFO] janitor: pindexes to remove: 3

      Last good build: 7.0.0-2934

      It is intermittent though - 2947 was clean and 2948 it started happening again - so marking it as critical only

      Change log between 2934 and 2945:

      MB-37816 - Fix bleveMaxResultWindow checks with keyset pagination
      MB-40768 - FTS upgrade handling for new zap disk format in CC
      MB-37285: Enabling OSO Backfill for GOCBCORE feeds

      Attachments

        Issue Links

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

          Activity

            Build 7.0.0-2942 introduces OSO backfill within FTS, can anyone confirm if 7.0.0-2941 works well?

            abhinav Abhinav Dangeti added a comment - Build 7.0.0-2942 introduces OSO backfill within FTS, can anyone confirm if 7.0.0-2941 works well?

            There is a blocker issue with query node, so we won't be able to run with 7.0.0-2941

            But we did run with with 7.0.0-2934 where issue wasn't seen

            girish.benakappa Girish Benakappa added a comment - There is a blocker issue with query node, so we won't be able to run with 7.0.0-2941 But we did run with with 7.0.0-2934 where issue wasn't seen

            Ok thanks Girish Benakappa.

            Hey Jim Walker, I haven't looked into the SDK/FTS side of things entirely yet but wanted to ask you a question - now this is something I've noticed the last time I enabled OSO backfill as well, I see that several streams receive a "Request canceled" mid way during streaming.

            2020-08-25T17:57:53.548-07:00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 337, err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go:710
            2020-08-25T17:57:53.548-07:00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 275, err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go:710
            2020-08-25T17:57:53.548-07:00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 339, err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go:710
            2020-08-25T17:57:53.548-07:00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 340, err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go:710 

            Is this something that is always client initiated or could the server cancel on requests too?

            abhinav Abhinav Dangeti added a comment - Ok thanks Girish Benakappa . Hey Jim Walker , I haven't looked into the SDK/FTS side of things entirely yet but wanted to ask you a question - now this is something I've noticed the last time I enabled OSO backfill as well, I see that several streams receive a "Request canceled" mid way during streaming. 2020 - 08 -25T17: 57 : 53.548 - 07 : 00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 337 , err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go: 710 2020 - 08 -25T17: 57 : 53.548 - 07 : 00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 275 , err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go: 710 2020 - 08 -25T17: 57 : 53.548 - 07 : 00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 339 , err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go: 710 2020 - 08 -25T17: 57 : 53.548 - 07 : 00 [WARN] feed_dcp_gocbcore: Received error on DCP stream for vb: 340 , err: request canceled -- cbgt.(*GocbcoreDCPFeed).initiateStreamEx.func1() at feed_dcp_gocbcore.go: 710 Is this something that is always client initiated or could the server cancel on requests too?

            I see the "request canceled" connection restarts even without OSOBackfill, let me find out more on why this is happening.

            abhinav Abhinav Dangeti added a comment - I see the "request canceled" connection restarts even without OSOBackfill, let me find out more on why this is happening.

            I do have a fix up to avoid notifying the janitor more than once in case of errors seen while processing DCP messages: http://review.couchbase.org/c/cbgt/+/135209 (believe this should fix situations where the feed is accidentally closed and not restarted)

            I don't however have an answer yet on why we see "request canceled" on certain streams causing the feed to be restarted.

            abhinav Abhinav Dangeti added a comment - I do have a fix up to avoid notifying the janitor more than once in case of errors seen while processing DCP messages:  http://review.couchbase.org/c/cbgt/+/135209  (believe this should fix situations where the feed is accidentally closed and not restarted) I don't however have an answer yet on why we see "request canceled" on certain streams causing the feed to be restarted.

            Build couchbase-server-7.0.0-2969 contains cbgt commit 3c15199 with commit message:
            MB-41144: Notify manager only once on feed closure

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-2969 contains cbgt commit 3c15199 with commit message: MB-41144 : Notify manager only once on feed closure

            Hey Girish Benakappa, would you give this test a re-run with build 7.0.0-2969?

            abhinav Abhinav Dangeti added a comment - Hey Girish Benakappa , would you give this test a re-run with build 7.0.0-2969?

            For the requests being canceled - found what looks like it can be an SDK issue and we'll investigating that with: GOCBC-983

            abhinav Abhinav Dangeti added a comment - For the requests being canceled - found what looks like it can be an SDK issue and we'll investigating that with: GOCBC-983

            Hi Abhinav Dangeti the issue is still seen after 7.0.0-2969 too. The more recent one - 7.0.0-2988

            mihir.kamdar Mihir Kamdar (Inactive) added a comment - Hi Abhinav Dangeti the issue is still seen after 7.0.0-2969 too. The more recent one - 7.0.0-2988

            Yes Mihir Kamdar, as I pointed out earlier - believe I've found the cause to be a bug within gocbcore - GOCBC-983 (test blocker).

            abhinav Abhinav Dangeti added a comment - Yes Mihir Kamdar , as I pointed out earlier - believe I've found the cause to be a bug within gocbcore - GOCBC-983 (test blocker).

            Thanks Abhinav

            mihir.kamdar Mihir Kamdar (Inactive) added a comment - Thanks Abhinav

            Build couchbase-server-7.0.0-3012 contains cbgt commit 3776e77 with commit message:
            MB-41144: Bump up gocbcore version for GOCBC-984

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-3012 contains cbgt commit 3776e77 with commit message: MB-41144 : Bump up gocbcore version for GOCBC-984

            Verified as closed on 7.0.0-3029

            mihir.kamdar Mihir Kamdar (Inactive) added a comment - Verified as closed on 7.0.0-3029

            People

              abhinav Abhinav Dangeti
              arunkumar Arunkumar Senthilnathan (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty