Uploaded image for project: 'Python Driver'
  1. Python Driver
  2. PYTHON-2589

mongo-orchestration fails to start latest replica set clusters: Could not actualize replica set configuration

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None

      mongo-orchestration fails to start latest replica set clusters:

      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,644 [DEBUG] mongo_orchestration.replica_sets:273 - run_command(replSetGetStatus, None, False, None)
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,644 [DEBUG] mongo_orchestration.replica_sets:444 - connection(None, Primary(), 300)
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,652 [DEBUG] mongo_orchestration.replica_sets:279 - command result: {'set': 'repl0', 'date': datetime.datetime(2021, 2, 26, 18, 55, 10, 651000), 'myState': 1, 'term': 1, 'syncSourceHost': '', 'syncSourceId': -1, 'heartbeatIntervalMillis': 2000, 'majorityVoteCount': 2, 'writeMajorityCount': 2, 'votingMembersCount': 3, 'writableVotingMembersCount': 3, 'optimes': {'lastCommittedOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'lastCommittedWallTime': datetime.datetime(2021, 2, 26, 18, 55, 9, 736000), 'readConcernMajorityOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'appliedOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'durableOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'lastAppliedWallTime': datetime.datetime(2021, 2, 26, 18, 55, 9, 736000), 'lastDurableWallTime': datetime.datetime(2021, 2, 26, 18, 55, 9, 736000)}, 'lastStableRecoveryTimestamp': Timestamp(1614365650, 1), 'electionCandidateMetrics': {'lastElectionReason': 'electionTimeout', 'lastElectionDate': datetime.datetime(2021, 2, 26, 18, 50, 10, 625000), 'electionTerm': 1, 'lastCommittedOpTimeAtElection': {'ts': Timestamp(0, 0), 't': -1}, 'lastSeenOpTimeAtElection': {'ts': Timestamp(1614365399, 1), 't': -1}, 'numVotesNeeded': 2, 'priorityAtElection': 1.0, 'electionTimeoutMillis': 10000, 'numCatchUpOps': 0, 'newTermStartDate': datetime.datetime(2021, 2, 26, 18, 50, 10, 640000), 'wMajorityWriteAvailabilityDate': datetime.datetime(2021, 2, 26, 18, 50, 10, 926000)}, 'members': [{'_id': 0, 'name': 'localhost:27017', 'health': 1.0, 'state': 1, 'stateStr': 'PRIMARY', 'uptime': 314, 'optime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'optimeDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'syncSourceHost': '', 'syncSourceId': -1, 'infoMessage': '', 'electionTime': Timestamp(1614365410, 1), 'electionDate': datetime.datetime(2021, 2, 26, 18, 50, 10), 'configVersion': 1, 'configTerm': 1, 'self': True, 'lastHeartbeatMessage': ''}, {'_id': 1, 'name': 'localhost:27018', 'health': 1.0, 'state': 2, 'stateStr': 'SECONDARY', 'uptime': 311, 'optime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'optimeDurable': {'ts': Timestamp(1614365709, 1), 't': 1}, 'optimeDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'optimeDurableDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'lastHeartbeat': datetime.datetime(2021, 2, 26, 18, 55, 10, 632000), 'lastHeartbeatRecv': datetime.datetime(2021, 2, 26, 18, 55, 10, 134000), 'pingMs': 0, 'lastHeartbeatMessage': '', 'syncSourceHost': 'localhost:27019', 'syncSourceId': 2, 'infoMessage': '', 'configVersion': 1, 'configTerm': 1}, {'_id': 2, 'name': 'localhost:27019', 'health': 1.0, 'state': 2, 'stateStr': 'SECONDARY', 'uptime': 311, 'optime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'optimeDurable': {'ts': Timestamp(1614365709, 1), 't': 1}, 'optimeDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'optimeDurableDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'lastHeartbeat': datetime.datetime(2021, 2, 26, 18, 55, 10, 632000), 'lastHeartbeatRecv': datetime.datetime(2021, 2, 26, 18, 55, 9, 143000), 'pingMs': 0, 'lastHeartbeatMessage': '', 'syncSourceHost': 'localhost:27017', 'syncSourceId': 0, 'infoMessage': '', 'configVersion': 1, 'configTerm': 1}], 'ok': 1.0, '$clusterTime': {'clusterTime': Timestamp(1614365709, 1), 'signature': {'hash': b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', 'keyId': 0}}, 'operationTime': Timestamp(1614365709, 1)}
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,652 [DEBUG] mongo_orchestration.replica_sets:273 - run_command(serverStatus, None, False, 0)
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,652 [DEBUG] mongo_orchestration.replica_sets:444 - connection(localhost:27017, Primary(), 300)
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,652 [DEBUG] mongo_orchestration.replica_sets:461 - connection to the localhost:27017
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,658 [DEBUG] mongo_orchestration.replica_sets:279 - command result: {'host': 'ip-10-122-5-14', 'version': '4.9.0-alpha5-40-g6e41691', 'process': 'mongod', ... 'repl': {'topologyVersion': {'processId': ObjectId('603942d500513aeb39f2fbde'), 'counter': 6}, 'hosts': ['localhost:27017', 'localhost:27018', 'localhost:27019'], 'setName': 'repl0', 'setVersion': 1, 'isWritablePrimary': True, 'secondary': False, 'primary': 'localhost:27017', 'tags': {'dc': 'ny', 'ordinal': 'one'}, 'me': 'localhost:27017', 'electionId': ObjectId('7fffffff0000000000000001'), 'lastWrite': {'opTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'lastWriteDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'majorityOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'majorityWriteDate': datetime.datetime(2021, 2, 26, 18, 55, 9)}, 'primaryOnlyServices': {'TenantMigrationDonorService': 0, 'TenantMigrationRecipientService': 0}, 'rbid': 1}, ..., 'ok': 1.0, '$clusterTime': {'clusterTime': Timestamp(1614365709, 1), 'signature': {'hash': b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', 'keyId': 0}}, 'operationTime': Timestamp(1614365709, 1)}
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,658 [DEBUG] mongo_orchestration.replica_sets:375 - member 0 repl info: {'topologyVersion': {'processId': ObjectId('603942d500513aeb39f2fbde'), 'counter': 6}, 'hosts': ['localhost:27017', 'localhost:27018', 'localhost:27019'], 'setName': 'repl0', 'setVersion': 1, 'isWritablePrimary': True, 'secondary': False, 'primary': 'localhost:27017', 'tags': {'dc': 'ny', 'ordinal': 'one'}, 'me': 'localhost:27017', 'electionId': ObjectId('7fffffff0000000000000001'), 'lastWrite': {'opTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'lastWriteDate': datetime.datetime(2021, 2, 26, 18, 55, 9), 'majorityOpTime': {'ts': Timestamp(1614365709, 1), 't': 1}, 'majorityWriteDate': datetime.datetime(2021, 2, 26, 18, 55, 9)}, 'primaryOnlyServices': {'TenantMigrationDonorService': 0, 'TenantMigrationRecipientService': 0}, 'rbid': 1}
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,658 [DEBUG] mongo_orchestration.replica_sets:599 - real_member_info(0): {'_id': 0, 'server_id': '58b64c4b-9786-4de2-9641-f5c94fa643ed', 'mongodb_uri': 'mongodb://localhost:27017', 'procInfo': {'name': '/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/mongo-driver/../drivers-tools/mongodb/bin/mongod', 'params': {'oplogSize': 500, 'logappend': True, 'verbose': 'v', 'bind_ip': '127.0.0.1,::1', 'replSet': 'repl0', 'ipv6': True, 'journal': True, 'port': 27017, 'dbpath': '/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/db/mongod-yj_prh42', 'logpath': '/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/db/mongod-yj_prh42/mongod.log', 'setParameter': {'enableTestCommands': 1, 'transactionLifetimeLimitSeconds': 3, 'maxTransactionLockRequestTimeoutMillis': 25, 'periodicNoopIntervalSecs': 1, 'writePeriodicNoops': 1}, 'networkMessageCompressors': 'zstd,zlib,snappy,noop', 'enableMajorityReadConcern': True}, 'alive': True, 'optfile': '/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/db/mongo-srzwvepd', 'pid': 6355}, 'statuses': {'primary': True, 'mongos': False}, 'mongodb_auth_uri': 'mongodb://bob:pwd123@localhost:27017/?authSource=admin', 'rsInfo': {'tags': {'dc': 'ny', 'ordinal': 'one'}, 'secondary': False, 'primary': False}}
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,658 [DEBUG] mongo_orchestration.replica_sets:602 - secondaryDelaySecs: 0 ! = None
      [2021/02/26 18:55:19.024] 2021-02-26 18:55:10,658 [ERROR] mongo_orchestration.apps:68 - <function rs_create at 0x7fe075441620>
      [2021/02/26 18:55:19.024] Traceback (most recent call last):
      [2021/02/26 18:55:19.024]   File "/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/venv/lib/python3.6/site-packages/mongo_orchestration/apps/__init__.py", line 66, in wrap
      [2021/02/26 18:55:19.024]     return f(*arg, **kwd)
      [2021/02/26 18:55:19.024]   File "/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/venv/lib/python3.6/site-packages/mongo_orchestration/apps/replica_sets.py", line 80, in rs_create
      [2021/02/26 18:55:19.024]     result = _rs_create(data)
      [2021/02/26 18:55:19.025]   File "/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/venv/lib/python3.6/site-packages/mongo_orchestration/apps/replica_sets.py", line 37, in _rs_create
      [2021/02/26 18:55:19.025]     rs_id = ReplicaSets().create(params)
      [2021/02/26 18:55:19.025]   File "/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/venv/lib/python3.6/site-packages/mongo_orchestration/replica_sets.py", line 643, in create
      [2021/02/26 18:55:19.025]     repl = ReplicaSet(rs_params)
      [2021/02/26 18:55:19.025]   File "/data/mci/6fe922c7e915e9d0959422d92c0b77ab/src/go.mongodb.org/drivers-tools/.evergreen/orchestration/venv/lib/python3.6/site-packages/mongo_orchestration/replica_sets.py", line 93, in __init__
      [2021/02/26 18:55:19.025]     "Could not actualize replica set configuration.")
      [2021/02/26 18:55:19.025] mongo_orchestration.errors.ReplicaSetError: Could not actualize replica set configuration.
      [2021/02/26 18:55:19.025] 2021-02-26 18:55:10,658 [DEBUG] mongo_orchestration.apps:55 - send_result(500)
      

      https://evergreen.mongodb.com/task/mongo_go_driver_tests_42_plus_zlib_zstd_support__version~latest_os_ssl_32~ubuntu1604_64_go_1_15_test_replicaset_auth_nossl_1c2620e3a8f77b00a25cfe95032e2783606d003c_21_02_26_18_45_02

      The problem was caused by SERVER-52349 where the server changed to start reporting slaveDelay as secondaryDelaySecs in replSetGetConfig.

            Assignee:
            shane.harvey@mongodb.com Shane Harvey
            Reporter:
            shane.harvey@mongodb.com Shane Harvey
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: