search

10gen / mongo-orchestration

Apache License 2.0
7 stars 11 forks source link

Windows SSL replica set frequently fails to start with MongoDB 4.3 latest #274

Closed ShaneHarvey closed 4 years ago

ShaneHarvey commented 4 years ago

MO can't connect to a member in the set after restarting it because each isMaster handshake fails with SSL handshake failed: ('_ssl.c:711: The handshake operation timed out',)

MO log:

2019-10-28 21:57:07,941 [INFO] mongo_orchestration.servers:404 - Attempting to connect to localhost:27018
2019-10-28 21:57:08,013 [INFO] mongo_orchestration.servers:411 - Attempting to send shutdown command to localhost:27018
2019-10-28 21:57:08,766 [DEBUG] mongo_orchestration.process:201 - mprocess(name=u'C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/mongodb/bin\\mongod', config_path='c:\\data\\mci\\7d54fa139e431db2aa86a0243115ae88\\drivers-tools\\.evergreen\\orchestration\\db\\mongo-fhh3od', port=27018, timeout=300)
2019-10-28 21:57:08,766 [DEBUG] mongo_orchestration.process:213 - execute process: C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/mongodb/bin\mongod --config c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-fhh3od --port 27018
2019-10-28 21:57:08,767 [DEBUG] mongo_orchestration.process:145 - wait for 27018
2019-10-28 21:57:10,865 [DEBUG] mongo_orchestration.process:227 - process 'C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/mongodb/bin\mongod' has started: pid=2732, host=localhost:27018
2019-10-28 21:57:10,865 [DEBUG] mongo_orchestration.servers:346 - pid=2732, hostname=localhost:27018
.
.
.
2019-10-28 22:00:10,928 [ERROR] mongo_orchestration.servers:358 - isMaster command failed:
Traceback (most recent call last):
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 355, in start
    self.run_command('isMaster')
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 276, in run_command
    result = getattr(self.connection.admin, mode)(command, name, **d)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 206, in connection
    connected(c)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\common.py", line 136, in connected
    client.admin.command('ismaster')
  File "C:\Python27\lib\site-packages\pymongo\database.py", line 513, in command
    with client._socket_for_reads(read_preference) as (sock_info, slave_ok):
  File "C:\Python27\Lib\contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "C:\Python27\lib\site-packages\pymongo\mongo_client.py", line 904, in _socket_for_reads
    with self._get_socket(read_preference) as sock_info:
  File "C:\Python27\Lib\contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "C:\Python27\lib\site-packages\pymongo\mongo_client.py", line 868, in _get_socket
    server = self._get_topology().select_server(selector)
  File "C:\Python27\lib\site-packages\pymongo\topology.py", line 214, in select_server
    address))
  File "C:\Python27\lib\site-packages\pymongo\topology.py", line 189, in select_servers
    self._error_message(selector))
ServerSelectionTimeoutError: SSL handshake failed: ('_ssl.c:711: The handshake operation timed out',)
2019-10-28 22:00:10,928 [ERROR] mongo_orchestration.servers:368 - Could not start Server. Please find server log below.
=====================================================
.
.
.
2019-10-28T21:57:08.809+0000 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2019-10-28T21:57:08.809+0000 D1 NETWORK  [main] Client Certificate Name: C=US,ST=New York,L=New York City,O=MongoDB,OU=Drivers,CN=localhost
2019-10-28T21:57:08.809+0000 D1 NETWORK  [main] Server Certificate Name: C=US,ST=New York,L=New York City,O=MongoDB,OU=Drivers,CN=localhost
2019-10-28T21:57:08.809+0000 D1 NETWORK  [main] Server Certificate Expiration: 2039-05-22T22:32:56.000+0000
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] MongoDB starting : pid=2732 port=27018 dbpath=c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-hchf4n 64-bit host=WIN-TM3AGLOO2G4
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] db version v4.3.0-1939-g428532a
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] git version: 428532a09119970372d0ae613b0d206cf3e14a8d
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] allocator: tcmalloc
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] modules: enterprise 
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] build environment:
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten]     distmod: windows-64
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten]     distarch: x86_64
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten]     target_arch: x86_64
2019-10-28T21:57:09.291+0000 I  CONTROL  [initandlisten] options: { config: "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-fhh3od", net: { bindIp: "127.0.0.1,::1", compression: { compressors: "zstd,zlib,snappy,noop" }, ipv6: true, port: 27018, tls: { CAFile: "C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/.evergreen/x509gen/ca.pem", allowConnectionsWithoutCertificates: true, certificateKeyFile: "C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/.evergreen/x509gen/server.pem", mode: "requireTLS" } }, replication: { enableMajorityReadConcern: true, oplogSizeMB: 500, replSet: "repl0" }, security: { keyFile: "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\tmpwgsyep\key" }, setParameter: { enableTestCommands: "1", maxTransactionLockRequestTimeoutMillis: "25", transactionLifetimeLimitSeconds: "3" }, storage: { dbPath: "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-hchf4n", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-hchf4n\mongod.log", verbosity: 1 } }
2019-10-28T21:57:09.293+0000 I  STORAGE  [initandlisten] Detected data files in c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-hchf4n created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.

.
.
.
2019-10-28T21:57:10.756+0000 I  CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: config.system.sessions does not exist
2019-10-28T21:57:10.756+0000 I  NETWORK  [initandlisten] waiting for connections on port 27018 ssl
2019-10-28T21:57:10.790+0000 D1 NETWORK  [replexec-0] connected to server localhost:27017
2019-10-28T21:57:10.826+0000 I  NETWORK  [listener] connection accepted from [::1]:49349 #3 (1 connection now open)
2019-10-28T21:57:10.863+0000 D1 NETWORK  [replexec-0] connected to server localhost:27019
2019-10-28T21:57:10.864+0000 D1 REPL     [replexec-0] Updated term in topology coordinator to 0 due to new config
2019-10-28T21:57:10.864+0000 I  REPL     [replexec-0] New replica set config in use: { _id: "repl0", version: 1, protocolVersion: 1, writeConcernMajorityJournalDefault: true, members: [ { _id: 0, host: "localhost:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: { ordinal: "one", dc: "ny" }, slaveDelay: 0, votes: 1 }, { _id: 1, host: "localhost:27018", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: { ordinal: "two", dc: "pa" }, slaveDelay: 0, votes: 1 }, { _id: 2, host: "localhost:27019", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, catchUpTimeoutMillis: -1, catchUpTakeoverDelayMillis: 30000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('5db76424835dc53d55a7de9e') } }
2019-10-28T21:57:10.864+0000 I  REPL     [replexec-0] This node is localhost:27018 in the config
2019-10-28T21:57:10.864+0000 I  REPL     [replexec-0] transition to STARTUP2 from STARTUP
2019-10-28T21:57:10.865+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:49342 #4 (2 connections now open)
2019-10-28T21:57:10.865+0000 D1 EXECUTOR [replexec-1] starting thread in pool replexec
2019-10-28T21:57:10.865+0000 I  NETWORK  [conn4] end connection 127.0.0.1:49342 (1 connection now open)
2019-10-28T21:57:10.865+0000 D1 EXECUTOR [replexec-2] starting thread in pool replexec
2019-10-28T21:57:10.866+0000 D1 REPL     [replexec-0] Updating term from 0 to 1
2019-10-28T21:57:10.866+0000 D1 REPL     [replexec-0] Current term is now 1
2019-10-28T21:57:10.866+0000 I  REPL     [replexec-0] Starting replication storage threads
2019-10-28T21:57:10.866+0000 I  CONNPOOL [Replication] Connecting to localhost:27017
2019-10-28T21:57:10.867+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:49350 #5 (2 connections now open)
2019-10-28T21:57:40.865+0000 D1 EXECUTOR [replexec-1] Reaping this thread; next thread reaped no earlier than 2019-10-28T21:58:10.865+0000
2019-10-28T21:57:40.865+0000 D1 EXECUTOR [replexec-1] shutting down thread in pool replexec
2019-10-28T21:58:10.865+0000 D1 EXECUTOR [replexec-2] Reaping this thread; next thread reaped no earlier than 2019-10-28T21:58:40.865+0000
2019-10-28T21:58:10.865+0000 D1 EXECUTOR [replexec-2] shutting down thread in pool replexec

2019-10-28 22:00:10,930 [ERROR] mongo_orchestration.apps:68 - <function rs_create at 0x00000000023E6588>
Traceback (most recent call last):
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\__init__.py", line 66, in wrap
    return f(*arg, **kwd)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\replica_sets.py", line 80, in rs_create
    result = _rs_create(data)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\replica_sets.py", line 37, in _rs_create
    rs_id = ReplicaSets().create(params)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\replica_sets.py", line 643, in create
    repl = ReplicaSet(rs_params)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\replica_sets.py", line 138, in __init__
    server.restart(config_callback=add_auth)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 445, in restart
    return self.start(timeout)
  File "c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 380, in start
    LOG_FILE + ' for more details.')
  File "<string>", line 2, in reraise
TimeoutError: Could not start Server. Please check server log located in c:\data\mci\7d54fa139e431db2aa86a0243115ae88\drivers-tools\.evergreen\orchestration\db\mongo-hchf4n\mongod.log or the mongo-orchestration log in C:/data/mci/7d54fa139e431db2aa86a0243115ae88/drivers-tools/.evergreen/orchestration\server.log for more details.
2019-10-28 22:00:10,930 [DEBUG] mongo_orchestration.apps:55 - send_result(500)

Seen in Motor here: https://evergreen.mongodb.com/task/motor_test_win__ssl~ssl_tox_env_win~tornado5_py36_os~win_test_latest_replica_set_163c56f6cc61bd5bc142e94c0e28ca2bed2951da_19_10_28_21_49_34

ShaneHarvey commented 4 years ago

Interesting thing here is that the last log line of the server is timestamped at 21:58:10 but mongo-orchestration is still attempting (and failing) to connect from 21:57:40 to the final failure at 22:00:10. It appears that the mongod is stalled.

ShaneHarvey commented 4 years ago

All Windows+SSL topologies are now failing. The is the error when attempting to start a standalone server:

ServerSelectionTimeoutError: localhost:27017: [Errno 10061] No connection could be made because the target machine actively refused it
2019-11-08 22:56:55,615 [ERROR] mongo_orchestration.servers:358 - isMaster command failed:
Traceback (most recent call last):
  File "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 355, in start
    self.run_command('isMaster')
  File "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 276, in run_command
    result = getattr(self.connection.admin, mode)(command, name, **d)
  File "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 206, in connection
    connected(c)
  File "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\common.py", line 136, in connected
    client.admin.command('ismaster')
  File "C:\Python27\lib\site-packages\pymongo\database.py", line 513, in command
    with client._socket_for_reads(read_preference) as (sock_info, slave_ok):
  File "C:\Python27\Lib\contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "C:\Python27\lib\site-packages\pymongo\mongo_client.py", line 904, in _socket_for_reads
    with self._get_socket(read_preference) as sock_info:
  File "C:\Python27\Lib\contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "C:\Python27\lib\site-packages\pymongo\mongo_client.py", line 868, in _get_socket
    server = self._get_topology().select_server(selector)
  File "C:\Python27\lib\site-packages\pymongo\topology.py", line 214, in select_server
    address))
  File "C:\Python27\lib\site-packages\pymongo\topology.py", line 189, in select_servers
    self._error_message(selector))
ServerSelectionTimeoutError: localhost:27017: [Errno 10061] No connection could be made because the target machine actively refused it
2019-11-08 22:56:55,615 [ERROR] mongo_orchestration.servers:368 - Could not start Server. Please find server log below.
=====================================================
2019-11-08 22:56:55,615 [ERROR] mongo_orchestration.servers:371 - 2019-11-08T22:53:52.114+0000 D1 CONTROL  [main] Loading library: Schannel.dll
2019-11-08T22:53:52.285+0000 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2019-11-08T22:53:52.747+0000 D1 NETWORK  [main] Client Certificate Name: C=US,ST=New York,L=New York City,O=MongoDB,OU=Drivers,CN=localhost
2019-11-08T22:53:52.747+0000 D1 NETWORK  [main] Server Certificate Name: C=US,ST=New York,L=New York City,O=MongoDB,OU=Drivers,CN=localhost
2019-11-08T22:53:52.747+0000 D1 NETWORK  [main] Server Certificate Expiration: 2039-05-22T22:32:56.000+0000
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] MongoDB starting : pid=1444 port=27017 dbpath=c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\db\mongo-vxltec 64-bit host=WIN-VKATQONG442
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] db version v4.3.0-2084-g6ef06c9
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] git version: 6ef06c9093462bec22c2219c341b0219f1864cca
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] allocator: tcmalloc
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] modules: enterprise 
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] build environment:
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten]     distmod: windows-64
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten]     distarch: x86_64
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten]     target_arch: x86_64
2019-11-08T22:53:52.747+0000 I  CONTROL  [initandlisten] options: { config: "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\db\mongo-hnhkvs", net: { bindIp: "127.0.0.1,::1", compression: { compressors: "zstd,zlib,snappy,noop" }, ipv6: true, port: 27017, tls: { CAFile: "C:/data/mci/db0e56ad7f7f3e9c9801f00b59c62dd2/drivers-tools/.evergreen/x509gen/ca.pem", allowConnectionsWithoutCertificates: true, certificateKeyFile: "C:/data/mci/db0e56ad7f7f3e9c9801f00b59c62dd2/drivers-tools/.evergreen/x509gen/server.pem", mode: "requireTLS" } }, replication: { enableMajorityReadConcern: true, oplogSizeMB: 100 }, setParameter: { enableTestCommands: "1", maxTransactionLockRequestTimeoutMillis: "25", transactionLifetimeLimitSeconds: "3" }, storage: { dbPath: "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\db\mongo-vxltec", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "c:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\.evergreen\orchestration\db\mongo-vxltec\mongod.log", verbosity: 1 } }
2019-11-08T22:53:52.747+0000 I  STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3327M,cache_overflow=(file_max=0M),session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],
2019-11-08T22:53:52.814+0000 I  STORAGE  [initandlisten] WiredTiger message [1573253632:814200][1444:2003185440], txn-recover: Set global recovery timestamp: (0,0)
2019-11-08T22:53:52.826+0000 I  RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2019-11-08T22:53:52.826+0000 D1 COMMAND  [WTIdleSessionSweeper] BackgroundJob starting: WTIdleSessionSweeper
2019-11-08T22:53:52.826+0000 D1 STORAGE  [WTIdleSessionSweeper] starting WTIdleSessionSweeper thread
2019-11-08T22:53:52.840+0000 D1 COMMAND  [WTJournalFlusher] BackgroundJob starting: WTJournalFlusher
2019-11-08T22:53:52.840+0000 D1 STORAGE  [WTJournalFlusher] starting WTJournalFlusher thread
2019-11-08T22:53:52.840+0000 I  STORAGE  [initandlisten] Timestamp monitor starting
2019-11-08T22:53:52.840+0000 D1 COMMAND  [WTCheckpointThread] BackgroundJob starting: WTCheckpointThread
2019-11-08T22:53:52.840+0000 D1 STORAGE  [WTCheckpointThread] starting WTCheckpointThread thread
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] 
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] ** NOTE: This is a development version (4.3.0-2084-g6ef06c9) of MongoDB.
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] **       Not recommended for production.
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] 
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2019-11-08T22:53:52.846+0000 I  CONTROL  [initandlisten] 
2019-11-08T22:53:52.846+0000 D1 COMMAND  [SNMPAgent] BackgroundJob starting: SNMPAgent
2019-11-08T22:53:52.846+0000 D1 NETWORK  [SNMPAgent] SNMPAgent not enabled
2019-11-08T22:53:52.847+0000 D1 -        [initandlisten] reloading view catalog for database admin
2019-11-08T22:53:52.847+0000 I  STORAGE  [initandlisten] createCollection: admin.system.version with provided UUID: 78fce329-3ebb-4b0a-afdd-a1638757227c and options: { uuid: UUID("78fce329-3ebb-4b0a-afdd-a1638757227c") }
2019-11-08T22:53:52.847+0000 D1 STORAGE  [initandlisten] stored meta data for admin.system.version @ RecordId(1)
2019-11-08T22:53:52.853+0000 D1 STORAGE  [initandlisten] admin.system.version: clearing plan cache - collection info cache reset
2019-11-08T22:53:52.853+0000 D1 STORAGE  [initandlisten] Registering collection admin.system.version with UUID 78fce329-3ebb-4b0a-afdd-a1638757227c
2019-11-08T22:53:52.853+0000 D1 STORAGE  [initandlisten] create uri: table:index-1-4439905848283707543 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8),log=(enabled=true)
2019-11-08T22:53:52.859+0000 D1 STORAGE  [initandlisten] admin.system.version: clearing plan cache - collection info cache reset
2019-11-08T22:53:52.859+0000 I  INDEX    [initandlisten] index build: done building index _id_ on ns admin.system.version
2019-11-08T22:53:52.860+0000 I  SHARDING [initandlisten] Marking collection admin.system.version as collection version: <unsharded>
2019-11-08T22:53:52.860+0000 I  COMMAND  [initandlisten] setting featureCompatibilityVersion to 4.4
2019-11-08T22:53:52.860+0000 D1 -        [initandlisten] reloading view catalog for database local
2019-11-08T22:53:52.860+0000 I  SHARDING [initandlisten] Marking collection local.system.replset as collection version: <unsharded>
2019-11-08T22:53:52.860+0000 D1 STORAGE  [initandlisten]     Recovering database: admin
2019-11-08T22:53:52.861+0000 D1 STORAGE  [initandlisten] done repairDatabases
2019-11-08T22:53:52.861+0000 I  STORAGE  [initandlisten] Flow Control is enabled on this deployment.
2019-11-08T22:53:52.861+0000 I  SHARDING [initandlisten] Marking collection admin.system.roles as collection version: <unsharded>
2019-11-08T22:53:52.861+0000 I  COMMAND  [initandlisten] command admin.system.roles command: find { find: "system.roles", $db: "admin" } planSummary: EOF keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:107 locks:{ ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 2 } }, Mutex: { acquireCount: { r: 1 } } } storage:{} protocol:op_msg 0ms
2019-11-08T22:53:52.862+0000 D1 ACCESS   [initandlisten] There were no users to pin, not starting tracker thread
2019-11-08T22:53:52.863+0000 D1 STORAGE  [initandlisten] create collection local.startup_log { capped: true, size: 10485760 }
2019-11-08T22:53:52.863+0000 I  STORAGE  [initandlisten] createCollection: local.startup_log with generated UUID: cb54f66c-d316-49cd-baab-a423a971ea78 and options: { capped: true, size: 10485760 }
2019-11-08T22:53:52.863+0000 D1 STORAGE  [initandlisten] stored meta data for local.startup_log @ RecordId(3)
2019-11-08T22:53:52.868+0000 D1 STORAGE  [initandlisten] local.startup_log: clearing plan cache - collection info cache reset
2019-11-08T22:53:52.868+0000 D1 STORAGE  [initandlisten] Registering collection local.startup_log with UUID cb54f66c-d316-49cd-baab-a423a971ea78
2019-11-08T22:53:52.868+0000 D1 STORAGE  [initandlisten] create uri: table:index-3-4439905848283707543 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8),log=(enabled=true)
2019-11-08T22:53:52.873+0000 D1 STORAGE  [initandlisten] local.startup_log: clearing plan cache - collection info cache reset
2019-11-08T22:53:52.873+0000 I  INDEX    [initandlisten] index build: done building index _id_ on ns local.startup_log
2019-11-08T22:53:52.873+0000 I  SHARDING [initandlisten] Marking collection local.startup_log as collection version: <unsharded>
2019-11-08T22:53:53.973+0000 I  FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory 'c:/data/mci/db0e56ad7f7f3e9c9801f00b59c62dd2/drivers-tools/.evergreen/orchestration/db/mongo-vxltec/diagnostic.data'
2019-11-08T22:53:53.974+0000 D1 COMMAND  [TTLMonitor] BackgroundJob starting: TTLMonitor
2019-11-08T22:53:53.974+0000 D1 COMMAND  [ClientCursorMonitor] BackgroundJob starting: ClientCursorMonitor
2019-11-08T22:53:53.974+0000 D1 COMMAND  [PeriodicTaskRunner] BackgroundJob starting: PeriodicTaskRunner
2019-11-08T22:53:53.975+0000 I  SHARDING [LogicalSessionCacheRefresh] Marking collection config.system.sessions as collection version: <unsharded>
2019-11-08T22:53:53.975+0000 D1 -        [LogicalSessionCacheRefresh] User Assertion: NamespaceNotFound: ns does not exist: config.system.sessions src\mongo\db\commands\list_indexes.cpp 155
2019-11-08T22:53:53.975+0000 D1 -        [LogicalSessionCacheReap] User Assertion: NamespaceNotFound: ns does not exist: config.system.sessions src\mongo\db\commands\list_indexes.cpp 155
2019-11-08T22:53:53.975+0000 I  NETWORK  [initandlisten] Listening on 127.0.0.1
2019-11-08T22:53:53.975+0000 D1 COMMAND  [LogicalSessionCacheRefresh] assertion while executing command 'listIndexes' on database 'config' with arguments '{ listIndexes: "system.sessions", cursor: {}, $db: "config" }': NamespaceNotFound: ns does not exist: config.system.sessions
2019-11-08T22:53:53.975+0000 D1 COMMAND  [LogicalSessionCacheReap] assertion while executing command 'listIndexes' on database 'config' with arguments '{ listIndexes: "system.sessions", cursor: {}, $db: "config" }': NamespaceNotFound: ns does not exist: config.system.sessions
2019-11-08T22:53:53.975+0000 I  COMMAND  [LogicalSessionCacheReap] command config.system.sessions command: listIndexes { listIndexes: "system.sessions", cursor: {}, $db: "config" } numYields:0 ok:0 errMsg:"ns does not exist: config.system.sessions" errName:NamespaceNotFound errCode:26 reslen:134 locks:{ ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 2 } } } protocol:op_msg 0ms
2019-11-08T22:53:53.975+0000 I  NETWORK  [initandlisten] Listening on ::1
2019-11-08T22:53:53.975+0000 D1 -        [LogicalSessionCacheReap] User Assertion: NamespaceNotFound: config.system.sessions does not exist src\mongo\db\sessions_collection_standalone.cpp 79
2019-11-08T22:53:53.975+0000 I  COMMAND  [LogicalSessionCacheRefresh] command config.system.sessions command: listIndexes { listIndexes: "system.sessions", cursor: {}, $db: "config" } numYields:0 ok:0 errMsg:"ns does not exist: config.system.sessions" errName:NamespaceNotFound errCode:26 reslen:134 locks:{ ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 2 } } } protocol:op_msg 0ms
2019-11-08T22:53:53.976+0000 D1 -        [LogicalSessionCacheRefresh] User Assertion: NamespaceNotFound: config.system.sessions does not exist src\mongo\db\sessions_collection_standalone.cpp 79
2019-11-08T22:53:53.976+0000 I  CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: config.system.sessions does not exist
2019-11-08T22:53:53.976+0000 I  NETWORK  [initandlisten] waiting for connections on port 27017 ssl
2019-11-08T22:53:53.976+0000 D1 -        [LogicalSessionCacheRefresh] reloading view catalog for database config
2019-11-08T22:53:53.976+0000 I  STORAGE  [LogicalSessionCacheRefresh] createCollection: config.system.sessions with provided UUID: ee3534bf-fe69-4fe1-9652-781928c36568 and options: { uuid: UUID("ee3534bf-fe69-4fe1-9652-781928c36568") }
2019-11-08T22:53:53.976+0000 D1 STORAGE  [LogicalSessionCacheRefresh] stored meta data for config.system.sessions @ RecordId(4)
2019-11-08T22:53:53.982+0000 D1 STORAGE  [LogicalSessionCacheRefresh] config.system.sessions: clearing plan cache - collection info cache reset
2019-11-08T22:53:53.982+0000 D1 STORAGE  [LogicalSessionCacheRefresh] Registering collection config.system.sessions with UUID ee3534bf-fe69-4fe1-9652-781928c36568
2019-11-08T22:53:53.982+0000 D1 STORAGE  [LogicalSessionCacheRefresh] create uri: table:index-5-4439905848283707543 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8),log=(enabled=true)
2019-11-08T22:53:53.987+0000 D1 STORAGE  [LogicalSessionCacheRefresh] config.system.sessions: clearing plan cache - collection info cache reset
2019-11-08T22:53:53.987+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: done building index _id_ on ns config.system.sessions
2019-11-08T22:53:53.987+0000 I  INDEX    [LogicalSessionCacheRefresh] Registering index build: 5c9cd46b-57e0-4789-8a25-5cfe38ed744d
2019-11-08T22:53:53.988+0000 D1 STORAGE  [LogicalSessionCacheRefresh] create uri: table:index-6-4439905848283707543 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8),log=(enabled=true)
2019-11-08T22:53:53.999+0000 D1 STORAGE  [LogicalSessionCacheRefresh] created temporary record store: internal-7-4439905848283707543
2019-11-08T22:53:53.999+0000 D1 STORAGE  [LogicalSessionCacheRefresh] config.system.sessions: clearing plan cache - collection info cache reset
2019-11-08T22:53:53.999+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: starting on config.system.sessions properties: { v: 2, key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } using method: Hybrid
2019-11-08T22:53:53.999+0000 I  INDEX    [LogicalSessionCacheRefresh] build may temporarily use up to 500 megabytes of RAM
2019-11-08T22:53:53.999+0000 I  STORAGE  [LogicalSessionCacheRefresh] Index build initialized: 5c9cd46b-57e0-4789-8a25-5cfe38ed744d: config.system.sessions (ee3534bf-fe69-4fe1-9652-781928c36568 ): indexes: 1
2019-11-08T22:53:53.999+0000 I  INDEX    [LogicalSessionCacheRefresh] Waiting for index build to complete: 5c9cd46b-57e0-4789-8a25-5cfe38ed744d
2019-11-08T22:53:53.999+0000 D1 EXECUTOR [IndexBuildsCoordinatorMongod-0] starting thread in pool IndexBuildsCoordinatorMongod
2019-11-08T22:53:53.999+0000 I  INDEX    [IndexBuildsCoordinatorMongod-0] index build: collection scan done. scanned 0 total records in 0 seconds
2019-11-08T22:53:53.999+0000 D1 INDEX    [IndexBuildsCoordinatorMongod-0] index build: inserting from external sorter into index: lsidTTLIndex
2019-11-08T22:53:54.000+0000 I  INDEX    [IndexBuildsCoordinatorMongod-0] index build: inserted 0 keys from external sorter into index in 0 seconds
2019-11-08T22:53:54.000+0000 I  SHARDING [ftdc] Marking collection local.oplog.rs as collection version: <unsharded>
2019-11-08T22:53:54.003+0000 D1 INDEX    [IndexBuildsCoordinatorMongod-0] index build: drain applied 0 side writes (inserted: 0, deleted: 0) for 'lsidTTLIndex' in 0 ms
2019-11-08T22:53:54.003+0000 D1 INDEX    [IndexBuildsCoordinatorMongod-0] index build: drain applied 0 side writes (inserted: 0, deleted: 0) for 'lsidTTLIndex' in 0 ms
2019-11-08T22:53:54.003+0000 D1 INDEX    [IndexBuildsCoordinatorMongod-0] index build: drain applied 0 side writes (inserted: 0, deleted: 0) for 'lsidTTLIndex' in 0 ms
2019-11-08T22:53:54.003+0000 I  INDEX    [IndexBuildsCoordinatorMongod-0] index build: done building index lsidTTLIndex on ns config.system.sessions
2019-11-08T22:53:54.004+0000 D1 STORAGE  [IndexBuildsCoordinatorMongod-0] config.system.sessions: clearing plan cache - collection info cache reset
2019-11-08T22:53:54.006+0000 D1 STORAGE  [IndexBuildsCoordinatorMongod-0] WT drop of table:internal-7-4439905848283707543 res 0
2019-11-08T22:53:54.006+0000 D1 STORAGE  [IndexBuildsCoordinatorMongod-0] ~WiredTigerRecordStore for temporary ident: internal-7-4439905848283707543
2019-11-08T22:53:54.006+0000 I  STORAGE  [IndexBuildsCoordinatorMongod-0] Index build completed successfully: 5c9cd46b-57e0-4789-8a25-5cfe38ed744d: config.system.sessions ( ee3534bf-fe69-4fe1-9652-781928c36568 ). Index specs built: 1. Indexes in catalog before build: 1. Indexes in catalog after build: 2
2019-11-08T22:53:54.007+0000 I  INDEX    [LogicalSessionCacheRefresh] Index build completed: 5c9cd46b-57e0-4789-8a25-5cfe38ed744d
2019-11-08T22:53:54.007+0000 I  COMMAND  [LogicalSessionCacheRefresh] command config.system.sessions command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:132 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 3 } }, ReplicationStateTransition: { acquireCount: { w: 4 } }, Global: { acquireCount: { r: 1, w: 3 } }, Database: { acquireCount: { r: 1, w: 3, W: 1 } }, Collection: { acquireCount: { r: 2, w: 1, W: 2 } }, Mutex: { acquireCount: { r: 5 } } } flowControl:{ acquireCount: 2 } storage:{} protocol:op_msg 30ms
2019-11-08T22:53:54.253+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:49241 #1 (1 connection now open)
2019-11-08T22:53:54.253+0000 I  NETWORK  [conn1] end connection 127.0.0.1:49241 (0 connections now open)
2019-11-08T22:53:54.585+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:49242 #2 (1 connection now open)
2019-11-08T22:53:54.665+0000 F  CONTROL  [conn2] *** unhandled exception (access violation) at 0x0000000000000000, terminating
2019-11-08T22:53:54.665+0000 F  CONTROL  [conn2] *** access violation was a DEP violation at 0x0
2019-11-08T22:53:54.665+0000 F  CONTROL  [conn2] *** stack trace for unhandled exception:
2019-11-08T22:53:54.836+0000 I  -        [conn2]                                                                                                                                        ???
mongod.exe    ...\src\mongo\util\net\ssl\detail\impl\schannel.ipp(334)                                                                 asio::ssl::detail::SSLHandshakeManager::doServerHandshake+0x1b6
mongod.exe    ...\src\mongo\util\net\ssl\detail\impl\schannel.ipp(100)                                                                 asio::ssl::detail::SSLHandshakeManager::nextHandshake+0x18d
mongod.exe    ...\src\mongo\util\net\ssl\detail\impl\engine_schannel.ipp(103)                                                          asio::ssl::detail::engine::handshake+0x34
mongod.exe    ...\src\mongo\util\net\ssl\detail\io.hpp(38)                                                                             asio::ssl::detail::io<asio::basic_stream_socket<asio::generic::stream_protocol>,asio::ssl::detail::buffered_handshake_op<asio::mutable_buffers_1> >+0x63
mongod.exe    ...\src\mongo\transport\session_asio.h(617)                                                                              <lambda_3301ff84a878097d756749b8837dd279>::operator()+0xa6
mongod.exe    ...\src\mongo\transport\session_asio.h(623)                                                                              mongo::transport::TransportLayerASIO::ASIOSession::maybeHandshakeSSLForIngress<asio::mutable_buffers_1>+0x2d8
mongod.exe    ...\src\mongo\util\future_impl.h(893)                                                                                    <lambda_e8e27e0b91d6204c863d3216e6eb1b5f>::operator()+0x39
mongod.exe    ...\src\mongo\transport\session_asio.h(402)                                                                              mongo::transport::TransportLayerASIO::ASIOSession::read<asio::mutable_buffers_1>+0xcb
mongod.exe    ...\src\mongo\transport\session_asio.h(355)                                                                              mongo::transport::TransportLayerASIO::ASIOSession::sourceMessageImpl+0x80
mongod.exe    ...\src\mongo\transport\session_asio.h(142)                                                                              mongo::transport::TransportLayerASIO::ASIOSession::sourceMessage+0x53
mongod.exe    ...\src\mongo\transport\service_state_machine.cpp(307)                                                                   <lambda_5064a192bae23f40a4fe23ce2b3de124>::operator()+0x66
mongod.exe    ...\src\mongo\transport\service_state_machine.cpp(517)                                                                   mongo::ServiceStateMachine::_runNextInGuard+0x127
mongod.exe    c:\program files (x86)\microsoft visual studio\2017\professional\vc\tools\msvc\14.16.27023\include\functional(16707566)  std::_Func_impl_no_alloc<<lambda_b23af5efc3b61ab25bff0c3bcd13382b>,void>::_Do_call+0x5d
mongod.exe    ...\src\mongo\transport\service_executor_synchronous.cpp(125)                                                            <lambda_472996f9e6b00ec91d31b43a6cde81f7>::operator()+0x13d
mongod.exe    c:\program files (x86)\microsoft visual studio\2017\professional\vc\tools\msvc\14.16.27023\include\thr\xthread(230)      std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_a107131b0689d694f9bc602dd323d0cb> >,std::default_delete<std::tuple<<lambda_a107131b0689d694f9bc602dd323d0cb> > > > >::_Go+0x80
mongod.exe    c:\program files (x86)\microsoft visual studio\2017\professional\vc\tools\msvc\14.16.27023\include\thr\xthread(209)      std::_Pad::_Call_func+0x9
ucrtbase.DLL                                                                                                                           o__realloc_base+0x60
kernel32.dll                                                                                                                           BaseThreadInitThunk+0xd
2019-11-08T22:53:54.836+0000 I  CONTROL  [conn2] writing minidump diagnostic file C:\data\mci\db0e56ad7f7f3e9c9801f00b59c62dd2\drivers-tools\mongodb\bin\mongod.2019-11-08T22-53-54.mdmp
2019-11-08T22:53:55.164+0000 F  CONTROL  [conn2] *** immediate exit due to unhandled exception
ShaneHarvey commented 4 years ago

Opened https://jira.mongodb.org/browse/SERVER-44572

ShaneHarvey commented 4 years ago

Resolution: MongoDB 4.3 raised the minimum supported Windows version to 10.