Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-48166

Scary-looking message about removed setParameter showing up in test logs

    XMLWordPrintableJSON

Details

    • Icon: Improvement Improvement
    • Resolution: Duplicate
    • Icon: Major - P3 Major - P3
    • None
    • None
    • Replication
    • None
    • Replication
    • 11

    Description

      Every test that uses a ReplSetTest is now logging a command failure message during test cleanup (example included below) about the removed 'waitForStepDownOnNonCommandShutdown' setParameter.  This has started becoming a red herring in build failure diagnosis, causing people to lose time investigating this even though it is expected.  It would be nice if we could prevent those messages from showing up in logs given that the failure is expected due to SERVER-47797.

       

      Example logs:

      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.007+0100 ReplSetTest stopSet disabling 'waitForStepDownOnNonCommandShutdown' on EC2AMAZ-DL1PJ4J:21770
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.008+0100 assert: command failed: {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.008+0100 	"ok" : 0,
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"errmsg" : "attempted to set unrecognized parameter [waitForStepDownOnNonCommandShutdown], use help:true to see options ",
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"$gleStats" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		"lastOpTime" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"ts" : Timestamp(1588916704, 15),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"t" : NumberLong(1)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		"electionId" : ObjectId("7fffffff0000000000000001")
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"lastCommittedOpTime" : Timestamp(1588916714, 12),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"$configServerState" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		"opTime" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"ts" : Timestamp(1588916716, 1),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"t" : NumberLong(1)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		}
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"$clusterTime" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		"clusterTime" : Timestamp(1588916716, 1),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		"signature" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 			"keyId" : NumberLong(0)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 		}
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 	"operationTime" : Timestamp(1588916714, 12)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.009+0100 }
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 _getErrorWithCode@src/mongo/shell/utils.js:25:13
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 doassert@src/mongo/shell/assert.js:18:14
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 _assertCommandWorked@src/mongo/shell/assert.js:663:17
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 assert.commandWorked@src/mongo/shell/assert.js:755:16
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 ReplSetTest/this.stopSet/<@src/mongo/shell/replsettest.js:3023:25
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 asCluster@src/mongo/shell/replsettest.js:173:20
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 ReplSetTest/this.stopSet@src/mongo/shell/replsettest.js:3017:13
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 ShardingTest/this.stop@src/mongo/shell/shardingtest.js:407:17
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 @jstests\sharding\single_shard_transaction_without_majority_reads_lagged.js:89:1
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 @jstests\sharding\single_shard_transaction_without_majority_reads_lagged.js:16:2
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 ReplSetTest stopSet disabling 'waitForStepDownOnNonCommandShutdown' on EC2AMAZ-DL1PJ4J:21771
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 assert: command failed: {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"ok" : 0,
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"errmsg" : "attempted to set unrecognized parameter [waitForStepDownOnNonCommandShutdown], use help:true to see options ",
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"$gleStats" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 		"lastOpTime" : Timestamp(0, 0),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 		"electionId" : ObjectId("000000000000000000000000")
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"lastCommittedOpTime" : Timestamp(1588916714, 12),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"$configServerState" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 		"opTime" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 			"ts" : Timestamp(1588916703, 7),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 			"t" : NumberLong(1)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 		}
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 	"$clusterTime" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.010+0100 		"clusterTime" : Timestamp(1588916714, 12),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 		"signature" : {
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 			"keyId" : NumberLong(0)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 		}
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 	},
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 	"operationTime" : Timestamp(1588916714, 12)
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 }
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 _getErrorWithCode@src/mongo/shell/utils.js:25:13
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 doassert@src/mongo/shell/assert.js:18:14
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 _assertCommandWorked@src/mongo/shell/assert.js:663:17
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 assert.commandWorked@src/mongo/shell/assert.js:755:16
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 ReplSetTest/this.stopSet/<@src/mongo/shell/replsettest.js:3023:25
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 asCluster@src/mongo/shell/replsettest.js:173:20
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 ReplSetTest/this.stopSet@src/mongo/shell/replsettest.js:3017:13
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 ShardingTest/this.stop@src/mongo/shell/shardingtest.js:407:17
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 @jstests\sharding\single_shard_transaction_without_majority_reads_lagged.js:89:1
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 @jstests\sharding\single_shard_transaction_without_majority_reads_lagged.js:16:2
      [js_test:single_shard_transaction_without_majority_reads_lagged] 2020-05-08T06:45:17.011+0100 ReplSetTest stopSet validating all replica set nodes before stopping them.
      

      Attachments

        Activity

          People

            backlog-server-repl Backlog - Replication Team
            spencer@mongodb.com Spencer Brody (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: