Stopping replica instances times out (MongoDB 4.8.0 close times-out) #676
Comments
|
please provide more of the debug output, just this section is not enough also just to be on the same page: debug's times reference the last message form the same namespace |
|
@hasezoey updated the log output 👍 I know the times are a reference but these particular lines: MongoMS:utils Mongo[46089] killProcess: given childProcess's PID was not alive anymore +35s
MongoMS:utils Mongo[46089] killProcess: given childProcess's PID was not alive anymore +0msMight indicate something is not working as expected. |
|
from what i can tell from the updated log, i dont see anything actually wrong, though the following line is weird that it has 30s
also are you sure you are spinning up 2 servers? because the log indicates that just one is ever started (also, dont use even numbers in replsets, use odd numbers) PS: how are you shutting down the instance? in a |
|
I initially had the teardown on I've also created a blank project with minimal dependencies and run tests with 2, 3 and 5 replicas and the behavior is the same. They all show this 30s+ delay on the first cleanup. MongoMS:utils Mongo[38679] killProcess: given childProcess's PID was not alive anymore +34s
MongoMS:utils Mongo[38679] killProcess: given childProcess's PID was not alive anymore +1ms
MongoMS:MongoInstance Mongo[38679]: stop: Instance Finished Shutdown +29s
MongoMS:utils Mongo[40985] killProcess: given childProcess's PID was not alive anymore +2ms
MongoMS:utils Mongo[40985] killProcess: given childProcess's PID was not alive anymore +0ms
MongoMS:MongoInstance Mongo[40985]: stop: Instance Finished Shutdown +2ms
MongoMS:utils Mongo[40627] killProcess: given childProcess's PID was not alive anymore +505ms
MongoMS:utils Mongo[40627] killProcess: given childProcess's PID was not alive anymore +0ms
MongoMS:MongoInstance Mongo[40627]: stop: Instance Finished Shutdown +505ms
MongoMS:utils Mongo[46429] killProcess: given childProcess's PID was not alive anymore +18ms
MongoMS:utils Mongo[46429] killProcess: given childProcess's PID was not alive anymore +0ms
MongoMS:MongoInstance Mongo[46429]: stop: Instance Finished Shutdown +18ms
MongoMS:utils Mongo[35083] killProcess: given childProcess's PID was not alive anymore +0ms
MongoMS:utils Mongo[35083] killProcess: given childProcess's PID was not alive anymore +0ms
MongoMS:MongoInstance Mongo[35083]: stop: Instance Finished Shutdown +0ms
MongoMS:MongoMemoryReplSet cleanup for "5" servers +32s
MongoMS:MongoMemoryReplSet cleanup: { doCleanup: true, force: false } +0ms
MongoMS:MongoMemoryServer Mongo[40985]: cleanup: { doCleanup: true, force: false } +32s
MongoMS:MongoMemoryServer Mongo[40985]: cleanup: removing tmpDir at /tmp/mongo-mem--2024-T9vXYeqZiY3h +0ms
MongoMS:MongoMemoryServer Mongo[38679]: cleanup: { doCleanup: true, force: false } +4ms
MongoMS:MongoMemoryServer Mongo[38679]: cleanup: removing tmpDir at /tmp/mongo-mem--2024-812QcQU40dOi +0ms
MongoMS:MongoMemoryServer Mongo[35083]: cleanup: { doCleanup: true, force: false } +1ms
MongoMS:MongoMemoryServer Mongo[35083]: cleanup: removing tmpDir at /tmp/mongo-mem--2024-5SLv5xFRCkM9 +0ms
MongoMS:MongoMemoryServer Mongo[46429]: cleanup: { doCleanup: true, force: false } +2ms
MongoMS:MongoMemoryServer Mongo[46429]: cleanup: removing tmpDir at /tmp/mongo-mem--2024-HQaehJtth6eI +0ms
MongoMS:MongoMemoryServer Mongo[40627]: cleanup: { doCleanup: true, force: false } +1ms
MongoMS:MongoMemoryServer Mongo[40627]: cleanup: removing tmpDir at /tmp/mongo-mem--2024-bCR88P45aF4z +0ms
mongo memory server stopped
Done in 36.33s. |
|
Just ran a test on a GitHub Actions runner and the behavior is the same: Test Suites: 3 passed, 3 total
Tests: 3 passed, 3 total
Snapshots: 0 total
Time: 11.994 s
Ran all test suites.
Done in 54.39s.As you can see, the tests completed on |
|
could you provide your mentioned test repository for me to investigate? |
|
Of course: https://github.com/stgogm/mongoms-issue-676 Added you to the repo as well so you can check the actions logs. |
|
Can reproduce and i also dont see any misconfiguration. After some testing i noticed that the problem is the mongodb nodejs driver, because reverting it from opened a mongodb issue: https://jira.mongodb.org/browse/NODE-4429 |
|
Thank you so much @hasezoey ! |
hasezoey
added
not a MMS issue
hasezoey
changed the title
|
for now i have put a workaround in place: 8a5552a (only with 8.8.0) that pins the version to 4.7.x |
|
Apparently, the bug in mongodb has been fixed with version 4.9.0 |
|
🎉 This issue has been resolved in version 8.9.0-beta.3 🎉 The release is available on:
Your semantic-release bot 📦🚀 |
|
🎉 This issue has been resolved in version 8.9.0 🎉 The release is available on:
Your semantic-release bot 📦🚀 |
Versions
package: mongo-memory-server
What is the Problem?
When stopping a replica set (
MongoMemoryReplSet), in takes about 30s to complete (timing out?). Does not happen with single instance (MongoMemoryServer).Code Example
Debug Output
Debug Output
MongoMS:ResolveConfig Debug Mode Enabled, through Environment Variable +0ms MongoMS:ResolveConfig findPackageJson: Found package.json at "/app/package.json" +1ms MongoMS:ResolveConfig Debug Mode Enabled, through package.json +1ms MongoMS:MongoMemoryReplSet create: Called .create() method +0ms MongoMS:MongoMemoryReplSet start: stopped +5ms MongoMS:MongoMemoryReplSet initAllServers +0ms MongoMS:MongoMemoryReplSet initAllServers: starting extra server "1" of "1" (count: 1) +1ms MongoMS:MongoMemoryReplSet getInstanceOpts: instance opts: { auth: false, args: [], dbName: '', ip: '127.0.0.1', replSet: 'testset', storageEngine: 'ephemeralForTest' } +0ms MongoMS:MongoMemoryReplSet initAllServers: waiting for all servers to finish starting +1ms MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method +0ms MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method +1ms MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false +0ms MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: { instance: { port: 46089, dbName: '', ip: '127.0.0.1', storageEngine: 'ephemeralForTest', replSet: 'testset', dbPath: '/tmp/mongo-mem--36645-g4AXNa5QUjfK', tmpDir: { name: '/tmp/mongo-mem--36645-g4AXNa5QUjfK', removeCallback: [Function: _cleanupCallback] }, args: [], auth: false }, binary: {}, spawn: {} } +3ms MongoMS:MongoInstance create: Called .create() method +0ms MongoMS:MongoInstance Mongo[46089]: start +0ms MongoMS:MongoBinary getPath +0ms MongoMS:DryMongoBinary generateOptions +0ms MongoMS:utils tryReleaseFile: "/etc/upstream-release/lsb-release" does not exist +0ms MongoMS:getos getLinuxInformation: Using etcOsRelease +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +2ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '', os: { os: 'linux', dist: 'debian', codename: 'buster', release: '10', id_like: undefined }, platform: 'linux', arch: 'x64', systemBinary: '' } +0ms MongoMS:DryMongoBinary getBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generateDownloadPath: Paths: { legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8', modulesCache: '/app/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8', relative: '/app/mongodb-binaries/mongod-x64-debian-5.0.8', resolveConfig: '' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +1ms MongoMS:MongoBinary getPath: MongoBinary options: { "version": "5.0.8", "downloadDir": "/root/.cache/mongodb-binaries", "os": { "os": "linux", "dist": "debian", "codename": "buster", "release": "10" }, "platform": "linux", "arch": "x64", "systemBinary": "", "checkMD5": false } +3ms MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8" +0ms MongoMS:DryMongoBinary generateOptions +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '/root/.cache/mongodb-binaries', os: { os: 'linux', dist: 'debian', codename: 'buster', release: '10', id_like: undefined }, platform: 'linux', arch: 'x64', systemBinary: '' } +0ms MongoMS:DryMongoBinary getBinaryName +1ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generateDownloadPath: Paths: { legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8', modulesCache: '/app/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8', relative: '/app/mongodb-binaries/mongod-x64-debian-5.0.8', resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +0ms MongoMS:DryMongoBinary locateBinary: running generateDownloadPath +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '/root/.cache/mongodb-binaries', os: { os: 'linux', dist: 'debian', codename: 'buster', release: '10', id_like: undefined }, platform: 'linux', arch: 'x64', systemBinary: '' } +0ms MongoMS:DryMongoBinary getBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generateDownloadPath: Paths: { legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8', modulesCache: '/app/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8', relative: '/app/mongodb-binaries/mongod-x64-debian-5.0.8', resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +1ms MongoMS:DryMongoBinary locateBinary: found binary at "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +0ms MongoMS:MongoBinary getPath: Mongod binary path: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +2ms MongoMS:MongoInstance Mongo[46089]: start: Starting Processes +6ms MongoMS:MongoInstance Mongo[46089]: _launchMongod: Launching Mongod Process +0ms MongoMS:MongoInstance Mongo[46089]: prepareCommandArgs +0ms MongoMS:MongoInstance Mongo[46089]: prepareCommandArgs: final argument array:["--port","46089","--dbpath","/tmp/mongo-mem--36645-g4AXNa5QUjfK","--replSet","testset","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"] +0ms MongoMS:MongoInstance Mongo[46089]: _launchKiller: Launching Killer Process (parent: 36645, child: 36695) +14ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.221Z"},"s":"I", "c":"CONTROL", "id":5324701, "ctx":"-","msg":"Test storage engine does not support enableMajorityReadConcern=true, forcibly setting to false","attr":{"storageEngine":"ephemeralForTest"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.221Z"},"s":"W", "c":"CONTROL", "id":4788401, "ctx":"-","msg":"Lock-free reads is not compatible with enableMajorityReadConcern=false: disabling lock-free reads."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.221+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}"" +53ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.222+00:00"},"s":"I", "c":"NETWORK", "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.223+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.223+00:00"},"s":"I", "c":"NETWORK", "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}"" +2ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.224+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.224+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":36695,"port":46089,"dbPath":"/tmp/mongo-mem--36645-g4AXNa5QUjfK","architecture":"64-bit","host":"da0b1fdec342"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","openSSLVersion":"OpenSSL 1.1.1n 15 Mar 2022","modules":[],"allocator":"tcmalloc","environment":{"distmod":"debian10","distarch":"x86_64","target_arch":"x86_64"}}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"PRETTY_NAME=\"Debian GNU/Linux 10 (buster)\"","version":"Kernel 5.15.0-41-generic"}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.225+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":46089},"replication":{"replSet":"testset"},"security":{"authorization":"disabled"},"storage":{"dbPath":"/tmp/mongo-mem--36645-g4AXNa5QUjfK","engine":"ephemeralForTest"}}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.237+00:00"},"s":"W", "c":"CONTROL", "id":22138, "ctx":"initandlisten","msg":"You are running this process as the root user, which is not recommended","tags":["startupWarnings"]}"" +12ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.237+00:00"},"s":"I", "c":"CONTROL", "id":22197, "ctx":"initandlisten","msg":"The ephemeralForTest storage engine is for testing only. Do not use in production","tags":["startupWarnings"]}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.237+00:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.237+00:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.238+00:00"},"s":"I", "c":"SHARDING", "id":20997, "ctx":"initandlisten","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.238+00:00"},"s":"I", "c":"FTDC", "id":20625, "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/tmp/mongo-mem--36645-g4AXNa5QUjfK/diagnostic.data"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.238+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d9967b5f-fd33-4e4a-9607-f9d571d158b0"}},"options":{"capped":true,"size":10485760}}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.239+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.startup_log","index":"_id_","commitTimestamp":null}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.239+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.239+00:00"},"s":"I", "c":"-", "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"KeyNotFound: No keys found after refresh","nextWakeupMillis":200}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"REPL", "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.oplogTruncateAfterPoint","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"19b2e36e-a7a6-4df4-9404-c1266d07fc7e"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.oplogTruncateAfterPoint","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.minvalid","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"2115a57f-e0b4-4c55-b5bd-10e322568370"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.minvalid","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.election","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c040d0e1-9549-41f7-861a-8757e8fa8749"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.240+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.election","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":21311, "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":21312, "ctx":"initandlisten","msg":"Did not find local Rollback ID document at startup. Creating one"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.rollback.id","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"63ae7b92-aeae-41d0-a84f-2f4aa8256e56"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.system.rollback.id","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":21531, "ctx":"initandlisten","msg":"Initialized the rollback ID","attr":{"rbid":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":21313, "ctx":"initandlisten","msg":"Did not find local replica set configuration document at startup","attr":{"error":{"code":47,"codeName":"NoMatchingDocument","errmsg":"Did not find replica set configuration document in local.system.replset"}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigUninitialized","oldState":"ConfigStartingUp"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.views","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"44856212-f1c5-4bc3-882e-a768fc49ec01"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.241+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.system.views","index":"_id_","commitTimestamp":null}}"" +2ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.242+00:00"},"s":"I", "c":"CONTROL", "id":20714, "ctx":"LogicalSessionCacheRefresh","msg":"Failed to refresh session cache, will try again at the next refresh interval","attr":{"error":"NotYetInitialized: Replication has not yet been configured"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.242+00:00"},"s":"I", "c":"REPL", "id":40440, "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.242+00:00"},"s":"I", "c":"CONTROL", "id":20712, "ctx":"LogicalSessionCacheReap","msg":"Sessions collection is not set up; waiting until next sessions reap interval","attr":{"error":"NamespaceNotFound: config.system.sessions does not exist"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.242+00:00"},"s":"I", "c":"REPL", "id":40445, "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.243+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-46089.sock"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.243+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.243+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":46089,"ssl":"off"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: constructor: Instance is ready! +0ms MongoMS:MongoInstance Mongo[46089]: start: Processes Started +0ms MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Instance Started, createAuth: "false" +95ms MongoMS:MongoMemoryServer Mongo[46089]: start: Instance fully Started +0ms MongoMS:MongoMemoryReplSet initAllServers: finished starting all servers initially +99ms MongoMS:MongoMemoryReplSet _initReplSet +1ms MongoMS:MongoMemoryServer Mongo[46089]: getUri: running undefined undefined +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.255+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60718","uuid":"81f44cc8-6e8b-4cee-8755-327f2fcbb090","connectionId":1,"connectionCount":1}}"" +16ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.259+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:60718","client":"conn1","doc":{"driver":{"name":"nodejs","version":"4.8.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"5.15.0-41-generic"},"platform":"Node.js v16.15.1, LE (unified)|Node.js v16.15.1, LE (unified)"}}}"" +0ms MongoMS:MongoMemoryReplSet _initReplSet: connected +19ms MongoMS:MongoMemoryReplSet _initReplSet: trying "replSetInitiate" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.265+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60720","uuid":"5c81997c-02d1-4a67-aae2-b3496f60cd32","connectionId":2,"connectionCount":2}}"" +6ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.266+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn2","msg":"client metadata","attr":{"remote":"127.0.0.1:60720","client":"conn2","doc":{"driver":{"name":"nodejs","version":"4.8.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"5.15.0-41-generic"},"platform":"Node.js v16.15.1, LE (unified)|Node.js v16.15.1, LE (unified)"}}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.267+00:00"},"s":"I", "c":"REPL", "id":21356, "ctx":"conn2","msg":"replSetInitiate admin command received from client"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.267+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigInitiating","oldState":"ConfigUninitialized"}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.267+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"7cd5f562-3864-4066-b2d2-5d50c1b59f1d"}},"options":{"uuid":{"$uuid":"7cd5f562-3864-4066-b2d2-5d50c1b59f1d"}}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"conn2","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.version","index":"_id_","commitTimestamp":null}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":20459, "ctx":"conn2","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"5.0"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"NETWORK", "id":4915702, "ctx":"conn2","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"NETWORK", "id":22991, "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":2}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"NETWORK", "id":22991, "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21357, "ctx":"conn2","msg":"replSetInitiate config object parses ok","attr":{"numMembers":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21251, "ctx":"conn2","msg":"Creating replication oplog","attr":{"oplogSizeMB":1600}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.oplog.rs","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"08e5bd51-2be9-44bd-bde7-6fd724421ccd"}},"options":{"capped":true,"size":1678245888,"autoIndexId":false}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.system.replset","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d7c415fd-7ce3-4328-aaa5-67246ff7ba26"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"conn2","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.system.replset","index":"_id_","commitTimestamp":null}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigInitiating"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"conn2","msg":"New replica set config in use","attr":{"config":{"_id":"testset","version":1,"term":0,"members":[{"_id":0,"host":"127.0.0.1:46089","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":false,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62d043e261622f7b93645b1c"}}}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"conn2","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:46089"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21306, "ctx":"conn2","msg":"Starting replication storage threads"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":4280512, "ctx":"conn2","msg":"No initial sync required. Attempting to begin steady replication"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"98cc68e9-9026-4577-becf-1167c179455b"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"conn2","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.initialSyncId","index":"_id_","commitTimestamp":null}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.268+00:00"},"s":"I", "c":"REPL", "id":21299, "ctx":"conn2","msg":"Starting replication fetcher thread"}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21300, "ctx":"conn2","msg":"Starting replication applier thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21301, "ctx":"conn2","msg":"Starting replication reporter thread"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21224, "ctx":"OplogApplier-0","msg":"Starting oplog application"}"" +0ms MongoMS:MongoMemoryReplSet _initReplSet: ReplSet-reconfig finished +6ms MongoMS:MongoMemoryReplSet _waitForPrimary: Waiting for a Primary +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"ELECTION", "id":4615652, "ctx":"OplogApplier-0","msg":"Starting an election, since we've seen no PRIMARY in election timeout period","attr":{"electionTimeoutPeriodMillis":500}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"ELECTION", "id":21438, "ctx":"OplogApplier-0","msg":"Conducting a dry run election to see if we could be elected","attr":{"currentTerm":0}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"ELECTION", "id":21444, "ctx":"ReplCoord-0","msg":"Dry election run succeeded, running for election","attr":{"newTerm":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"ELECTION", "id":6015300, "ctx":"ReplCoord-0","msg":"Storing last vote document in local storage for my election","attr":{"lastVote":{"term":1,"candidateIndex":0}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"ELECTION", "id":21450, "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21106, "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21359, "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015304, "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21363, "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"ReplCoord-0","msg":"Stopping replication producer"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":0}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":4508103, "ctx":"OplogApplier-0","msg":"Increment the config term via reconfig"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015313, "ctx":"OplogApplier-0","msg":"Replication config state is Steady, starting reconfig"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigReconfiguring","oldState":"ConfigSteady"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21353, "ctx":"OplogApplier-0","msg":"replSetReconfig config object parses ok","attr":{"numMembers":1}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":51814, "ctx":"OplogApplier-0","msg":"Persisting new config to disk"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015315, "ctx":"OplogApplier-0","msg":"Persisted new config to disk"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigReconfiguring"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"OplogApplier-0","msg":"New replica set config in use","attr":{"config":{"_id":"testset","version":1,"term":1,"members":[{"_id":0,"host":"127.0.0.1:46089","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":false,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62d043e261622f7b93645b1c"}}}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"OplogApplier-0","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:46089"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.269+00:00"},"s":"I", "c":"REPL", "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.transactions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d3c2d590-1bb1-4ba0-9558-635a7e3c4e7f"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.transactions","index":"_id_","commitTimestamp":null}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.image_collection","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e63fc9af-cccf-412a-bd5b-328e0c1b995c"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.image_collection","index":"_id_","commitTimestamp":null}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"REPL", "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20657, "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.system.indexBuilds","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"4da81224-f5c8-426a-915b-8df8f4251945"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.indexBuilds","index":"_id_","commitTimestamp":null}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"REPL", "id":21331, "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: emitting "instancePrimary" +0ms MongoMS:MongoMemoryReplSet _waitForPrimary: detected one primary instance +0ms MongoMS:MongoMemoryReplSet _initReplSet: running +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"1e2452d5-0214-4b02-9310-712cc4ef4a59"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"8784aa2a-7141-4121-a8c5-9db9b7cb30c5"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.270+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"61391091-d5fe-4f88-a5e5-d829a70ddb42"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"monitoring-keys-for-HMAC","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.keys","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationRecipientService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d9a533d0-2f7e-4221-8047-0d3f68d234f5"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"_id_","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","commitTimestamp":null}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationDonorService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:14.271+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:60718","uuid":"81f44cc8-6e8b-4cee-8755-327f2fcbb090","connectionId":1,"connectionCount":1}}"" +2ms MongoMS:MongoMemoryReplSet getUri: running +3ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:14.272+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:60720","uuid":"5c81997c-02d1-4a67-aae2-b3496f60cd32","connectionId":2,"connectionCount":0}}"" +258ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:17.486+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60722","uuid":"11ecf4ed-8c60-4cc1-961b-d07b6d8d31c9","connectionId":3,"connectionCount":1}}"" +3s MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:17.491+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:60722","client":"conn3","doc":{"driver":{"name":"nodejs|Mongoose","version":"4.5.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"5.15.0-41-generic"},"platform":"Node.js v16.15.1, LE (unified)","version":"4.5.0|6.3.9"}}}"" +5ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:17.509+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn3","msg":"Connection ended","attr":{"remote":"127.0.0.1:60722","uuid":"11ecf4ed-8c60-4cc1-961b-d07b6d8d31c9","connectionId":3,"connectionCount":0}}"" +18ms PASS src/examples/examples.service.spec.ts PASS src/examples/examples.controller.spec.ts Test Suites: 2 passed, 2 total Tests: 2 passed, 2 total Snapshots: 0 total Time: 4.114 s Ran all test suites. MongoMS:MongoMemoryReplSet stop: called by manual +4s MongoMS:MongoMemoryServer Mongo[46089]: stop: Called .stop() method +4s MongoMS:MongoMemoryServer Mongo[46089]: stop: Stopping MongoDB server on port 46089 with pid 36695 +0ms MongoMS:MongoInstance Mongo[46089]: stop +895ms MongoMS:MongoInstance Mongo[46089]: stop: trying shutdownServer +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.406+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60724","uuid":"c7e51f55-2066-41ce-a8fc-bd76cfca691d","connectionId":4,"connectionCount":1}}"" +3ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.407+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:60724","client":"conn4","doc":{"driver":{"name":"nodejs","version":"4.8.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"5.15.0-41-generic"},"platform":"Node.js v16.15.1, LE (unified)|Node.js v16.15.1, LE (unified)"}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.409+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60726","uuid":"2d0acf77-171e-4493-b743-0becfb6b1a99","connectionId":5,"connectionCount":2}}"" +2ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.409+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:60726","client":"conn5","doc":{"driver":{"name":"nodejs","version":"4.8.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"5.15.0-41-generic"},"platform":"Node.js v16.15.1, LE (unified)|Node.js v16.15.1, LE (unified)"}}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"COMMAND", "id":4695400, "ctx":"conn5","msg":"Terminating via shutdown command","attr":{"force":true,"timeoutSecs":1}}"" +2ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":4794602, "ctx":"conn5","msg":"Attempting to enter quiesce mode"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"COMMAND", "id":4784901, "ctx":"conn5","msg":"Shutting down the MirrorMaestro"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":40441, "ctx":"conn5","msg":"Stopping TopologyVersionObserver"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":40447, "ctx":"TopologyVersionObserver","msg":"Stopped TopologyVersionObserver"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"SHARDING", "id":4784902, "ctx":"conn5","msg":"Shutting down the WaitForMajorityService"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"CONTROL", "id":4784903, "ctx":"conn5","msg":"Shutting down the LogicalSessionCache"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"NETWORK", "id":20562, "ctx":"conn5","msg":"Shutdown: going to close listening sockets"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"NETWORK", "id":23017, "ctx":"listener","msg":"removing socket file","attr":{"path":"/tmp/mongodb-46089.sock"}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"NETWORK", "id":4784905, "ctx":"conn5","msg":"Shutting down the global connection pool"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"CONTROL", "id":4784906, "ctx":"conn5","msg":"Shutting down the FlowControlTicketholder"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"-", "id":20520, "ctx":"conn5","msg":"Stopping further Flow Control ticket acquisitions."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":4784907, "ctx":"conn5","msg":"Shutting down the replica set node executor"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"ReplNodeDbWorkerNetwork","msg":"Killing all outstanding egress activity."}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":4784909, "ctx":"conn5","msg":"Shutting down the ReplicationCoordinator"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":5074000, "ctx":"conn5","msg":"Shutting down the replica set aware services."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"REPL", "id":5123006, "ctx":"conn5","msg":"Shutting down PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","numInstances":0,"numOperationContexts":0}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.411+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"TenantMigrationRecipientServiceNetwork","msg":"Killing all outstanding egress activity."}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":5123006, "ctx":"conn5","msg":"Shutting down PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","numInstances":0,"numOperationContexts":0}}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"TenantMigrationDonorServiceNetwork","msg":"Killing all outstanding egress activity."}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":21328, "ctx":"conn5","msg":"Shutting down replication subsystems"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":21302, "ctx":"conn5","msg":"Stopping replication reporter thread"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":21303, "ctx":"conn5","msg":"Stopping replication fetcher thread"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":21304, "ctx":"conn5","msg":"Stopping replication applier thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:18.412+00:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"BackgroundSync","msg":"Stopping replication producer"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":21225, "ctx":"OplogApplier-0","msg":"Finished oplog application"}"" +859ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":5698300, "ctx":"conn5","msg":"Stopping replication applier writer pool"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":21307, "ctx":"conn5","msg":"Stopping replication storage threads"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"OplogApplierNetwork","msg":"Killing all outstanding egress activity."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"conn5","msg":"Killing all outstanding egress activity."}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"ReplCoordExternNetwork","msg":"Killing all outstanding egress activity."}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"ReplNetwork","msg":"Killing all outstanding egress activity."}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"SHARDING", "id":4784910, "ctx":"conn5","msg":"Shutting down the ShardingInitializationMongoD"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":4784911, "ctx":"conn5","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"-", "id":4784912, "ctx":"conn5","msg":"Killing all operations for shutdown"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"-", "id":4695300, "ctx":"conn5","msg":"Interrupted all currently running operations","attr":{"opsKilled":4}} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"TENANT_M", "id":5093807, "ctx":"conn5","msg":"Shutting down all TenantMigrationAccessBlockers on global shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"COMMAND", "id":4784913, "ctx":"conn5","msg":"Shutting down all open transactions"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":4784914, "ctx":"conn5","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"INDEX", "id":4784915, "ctx":"conn5","msg":"Shutting down the IndexBuildsCoordinator"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":4784916, "ctx":"conn5","msg":"Reacquiring the ReplicationStateTransitionLock for shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":4784917, "ctx":"conn5","msg":"Attempting to mark clean shutdown"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"NETWORK", "id":4784918, "ctx":"conn5","msg":"Shutting down the ReplicaSetMonitor"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.271+00:00"},"s":"I", "c":"REPL", "id":4784920, "ctx":"conn5","msg":"Shutting down the LogicalTimeValidator"}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"SHARDING", "id":4784921, "ctx":"conn5","msg":"Shutting down the MigrationUtilExecutor"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"ASIO", "id":22582, "ctx":"MigrationUtil-TaskExecutor","msg":"Killing all outstanding egress activity."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"COMMAND", "id":4784923, "ctx":"conn5","msg":"Shutting down the ServiceEntryPoint"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":4784925, "ctx":"conn5","msg":"Shutting down free monitoring"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":20609, "ctx":"conn5","msg":"Shutting down free monitoring"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":4784927, "ctx":"conn5","msg":"Shutting down the HealthLog"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":4784928, "ctx":"conn5","msg":"Shutting down the TTL monitor"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"INDEX", "id":3684100, "ctx":"conn5","msg":"Shutting down TTL collection monitor thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"INDEX", "id":3684101, "ctx":"conn5","msg":"Finished shutting down TTL collection monitor thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":4784929, "ctx":"conn5","msg":"Acquiring the global lock for shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"CONTROL", "id":4784930, "ctx":"conn5","msg":"Shutting down the storage engine"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"STORAGE", "id":22320, "ctx":"conn5","msg":"Shutting down journal flusher thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"STORAGE", "id":22321, "ctx":"conn5","msg":"Finished shutting down journal flusher thread"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"STORAGE", "id":20282, "ctx":"conn5","msg":"Deregistering all the collections"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"STORAGE", "id":22279, "ctx":"conn5","msg":"shutdown: removing fs lock..."} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"-", "id":4784931, "ctx":"conn5","msg":"Dropping the scope cache for shutdown"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"FTDC", "id":4784926, "ctx":"conn5","msg":"Shutting down full-time data capture"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"FTDC", "id":20626, "ctx":"conn5","msg":"Shutting down full-time diagnostic data capture"} MongoMS:MongoInstance {"t":{"$date":"2022-07-14T16:27:19.272+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn4","msg":"Connection ended","attr":{"remote":"127.0.0.1:60724","uuid":"c7e51f55-2066-41ce-a8fc-bd76cfca691d","connectionId":4,"connectionCount":1}}"" +1ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.273+00:00"},"s":"I", "c":"CONTROL", "id":20565, "ctx":"conn5","msg":"Now exiting"}"" +0ms MongoMS:MongoInstance Mongo[46089]: stdoutHandler: ""{"t":{"$date":"2022-07-14T16:27:19.273+00:00"},"s":"I", "c":"CONTROL", "id":23138, "ctx":"conn5","msg":"Shutting down","attr":{"exitCode":0}}"" +0ms MongoMS:MongoInstance Mongo[46089]: closeHandler: "0" "null" +3ms MongoMS:utils Mongo[46089] killProcess: given childProcess's PID was not alive anymore +35s MongoMS:utils Mongo[46089] killProcess: given childProcess's PID was not alive anymore +0ms MongoMS:MongoInstance Mongo[46089]: stop: Instance Finished Shutdown +30s MongoMS:MongoMemoryReplSet cleanup for "1" servers +31s MongoMS:MongoMemoryReplSet cleanup: { doCleanup: true, force: false } +0ms MongoMS:MongoMemoryServer Mongo[46089]: cleanup: { doCleanup: true, force: false } +31s MongoMS:MongoMemoryServer Mongo[46089]: cleanup: removing tmpDir at /tmp/mongo-mem--36645-g4AXNa5QUjfK +1msDo you know why it happenes?
no
The text was updated successfully, but these errors were encountered: