Uploaded image for project: 'Percona Server for MongoDB'
  1. Percona Server for MongoDB
  2. PSMDB-191

3.6 MongoRocks PeriodicKillSecondaries:ValidateCollections test hook fails

    XMLWordPrintable

    Details

    • Type: Admin & Maintenance Task
    • Status: Done
    • Priority: Medium
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      This fails in current v3.6 branch and also in Igor's fix-reindex branch, it doesn't fail for WiredTiger.
      Test suite is: replica_sets_kill_secondaries_jscore_passthrough
      Can be observed here:
      fix-reindex branch: https://jenkins.percona.com/view/PSMDB-3.6/job/percona-server-for-mongodb-3.6-param/71/testReport/
      v3.6 branch: https://jenkins.percona.com/view/PSMDB-3.6/job/percona-server-for-mongodb-3.6-param/72/testReport/

      Looks like this:

      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.390+0100 I COMMAND  [conn14] CMD: validate local.replset.oplogTruncateAfterPoint
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.390+0100 I INDEX    [conn14] validating collection local.replset.oplogTruncateAfterPoint
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.390+0100 I INDEX    [conn14] validating index local.replset.oplogTruncateAfterPoint.$_id_
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.390+0100 I INDEX    [conn14] validating collection local.replset.oplogTruncateAfterPoint failed
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100 Collection validation failed with response: {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "ns" : "local.replset.oplogTruncateAfterPoint",
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "nInvalidDocuments" : NumberLong(0),
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "nrecords" : 0,
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "nIndexes" : 1,
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "keysPerIndex" : {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100     "local.replset.oplogTruncateAfterPoint.$_id_" : 1
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   },
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "indexDetails" : {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100     "local.replset.oplogTruncateAfterPoint.$_id_" : {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100       "valid" : false
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100     }
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   },
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.392+0100   "valid" : false,
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "warnings" : [ ],
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "errors" : [
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100     "one or more indexes contain invalid index entries."
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   ],
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "advice" : "A corrupt namespace has been detected. See http://dochub.mongodb.org/core/data-recovery for recovery steps.",
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "ok" : 1,
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "operationTime" : Timestamp(1517816287, 1),
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   "$clusterTime" : {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100     "clusterTime" : Timestamp(1517816287, 1),
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100     "signature" : {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100       "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100       "keyId" : NumberLong(0)
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100     }
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100   }
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.393+0100 }
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100 Printing indexes in: local.replset.oplogTruncateAfterPoint
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100 [
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100   {
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100     "v" : 2,
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100     "key" : {
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I COMMAND  [conn14] CMD: validate local.startup_log
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100       "_id" : 1
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100     },
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating collection local.startup_log
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100     "name" : "_id_",
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating index local.startup_log.$_id_
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100     "ns" : "local.replset.oplogTruncateAfterPoint"
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validated collection local.startup_log
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100   }
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I COMMAND  [conn14] CMD: validate local.system.replset
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.394+0100 ]
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating collection local.system.replset
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.395+0100 Printing the first 100 documents in: local.replset.oplogTruncateAfterPoint
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating index local.system.replset.$_id_
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validated collection local.system.replset
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I COMMAND  [conn14] CMD: validate local.system.rollback.id
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating collection local.system.rollback.id
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validating index local.system.rollback.id.$_id_
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.394+0100 I INDEX    [conn14] validated collection local.system.rollback.id
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.396+0100 I NETWORK  [conn13] end connection 127.0.0.1:38724 (6 connections now open)
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.396+0100 I NETWORK  [conn14] end connection 127.0.0.1:38726 (5 connections now open)
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.397+0100 assert: command failed: { "ok" : 0 } : Collection validation failed
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.397+0100 _getErrorWithCode@src/mongo/shell/utils.js:25:13
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.397+0100 doassert@src/mongo/shell/assert.js:16:14
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.397+0100 assert.commandWorked@src/mongo/shell/assert.js:403:5
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.397+0100 @jstests/hooks/run_validate_collections.js:117:13
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 @jstests/hooks/run_validate_collections.js:116:9
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 @jstests/hooks/run_validate_collections.js:5:2
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 2018-02-05T08:38:07.397+0100 E QUERY    [thread1] Error: command failed: { "ok" : 0 } : Collection validation failed :
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 _getErrorWithCode@src/mongo/shell/utils.js:25:13
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.398+0100 I NETWORK  [conn11] end connection 127.0.0.1:38720 (4 connections now open)
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 doassert@src/mongo/shell/assert.js:16:14
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 assert.commandWorked@src/mongo/shell/assert.js:403:5
      [ReplicaSetFixture:job1:primary] 2018-02-05T08:38:07.398+0100 I NETWORK  [conn12] end connection 127.0.0.1:38722 (3 connections now open)
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 @jstests/hooks/run_validate_collections.js:117:13
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 @jstests/hooks/run_validate_collections.js:116:9
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.398+0100 @jstests/hooks/run_validate_collections.js:5:2
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.399+0100 failed to load: jstests/hooks/run_validate_collections.js
      [ReplicaSetFixture:job2:secondary] 2018-02-05T08:38:07.403+0100 I REPL     [replication-0] Completing collection drop for test.system.drop.1517816234i59t1.collation with drop optime { ts: Timestamp(1517816234, 59), t: 1 } (notification optime: { ts: Timestamp(1517816259, 1), t: 2 })
      [ReplicaSetFixture:job2:secondary] 2018-02-05T08:38:07.403+0100 I STORAGE  [replication-0] Finishing collection drop for test.system.drop.1517816234i59t1.collation (6106879f-15b9-4c5e-b9b4-efea9505f35d).
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries:ValidateCollections] 2018-02-05T08:38:07.400+0100 Full collection validation after running 'mr1:PeriodicKillSecondaries' failed
      Traceback (most recent call last):
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/hooks/jsfile.py", line 52, in after_test
          self._after_test_impl(test, test_report, description)
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/hooks/jsfile.py", line 40, in _after_test_impl
          self.hook_test_case.run_test()
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/testcases/jstest.py", line 273, in run_test
          self._run_single_copy()
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/testcases/jstest.py", line 228, in _run_single_copy
          test_case.run_test()
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/testcases/jstest.py", line 123, in run_test
          self._execute(shell)
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/testcases/interface.py", line 124, in _execute
          raise self.failureException("%s failed" % (self.shortDescription()))
      AssertionError: JSTest jstests/hooks/run_validate_collections.js failed
      [PeriodicKillSecondaries:job0:js7:PeriodicKillSecondaries:CheckReplDBHash] 2018-02-05T08:38:07.503+0100 ReplSetTest awaitReplication: checking secondaries against latest primary optime { "ts" : Timestamp(1517816286, 72), "t" : NumberLong(2) }
      [executor:js_test:job1] 2018-02-05T08:38:07.556+0100 mr1:PeriodicKillSecondaries:ValidateCollections ran in 0.31 seconds.
      [PeriodicKillSecondaries:job1:mr1:PeriodicKillSecondaries] 2018-02-05T08:38:07.557+0100 Encountered an error running PeriodicKillSecondaries.
      Traceback (most recent call last):
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py", line 91, in _run
          self._validate_collections(test_report)
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/hooks/periodic_kill_secondaries.py", line 174, in _validate_collections
          validate_test_case.after_test(self.hook_test_case, test_report)
        File "/home/plavi/test/psmdb/bin/percona-server-mongodb-3.6.1-1.0-beta/buildscripts/resmokelib/testing/hooks/jsfile.py", line 61, in after_test
          raise errors.StopExecution(err.args[0])
      StopExecution: JSTest jstests/hooks/run_validate_collections.js failed
      [executor:js_test:job1] 2018-02-05T08:38:07.604+0100 mr1:PeriodicKillSecondaries ran in 16.62 seconds.
      [executor:js_test:job1] 2018-02-05T08:38:07.604+0100 Received a StopExecution exception: JSTest jstests/hooks/run_validate_collections.js failed.
      [ReplicaSetFixture:job1] Stopping all members of the replica set...
      [ReplicaSetFixture:job1:secondary] Stopping mongod on port 20251 with pid 32331...
      [ReplicaSetFixture:job1:secondary] 2018-02-05T08:38:07.606+0100 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
      

        Attachments

          Activity

            People

            Assignee:
            denis.protivenskii Denis Protivenskii (Inactive)
            Reporter:
            tomislav.plavcic@percona.com Tomislav Plavcic
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 3 days, 6 hours
                3d 6h

                  Smart Checklist