MongoMemoryServer.create unusually slow in v10

[Marchelune]

Hi there 👋 !

Versions

• NodeJS: 20.12.1
• mongodb-memory-server-*: 10.0.0 and 10.0.1
• mongodb(the binary version): 0.0.0 (default)
• mongodb(the js package): (irrelevant)
• system: MacOS 14.1.1 (23B81)

package: mongo-memory-server

What is the Problem?

I've been using this lovely package for a while for unit tests (thank you so much 🙏). I recently upgrade to the v10 (well, 10.0.1) and noticed my test were significantly longer. I realised that the startup of the in-memory mongo server took much more than usual.
There's always a "cold start" for the first run, but usually in v9 my mac would have the server ready in 80-90ms. Now it takes between 900ms and 1300ms before the promise resolves.

Code Example

// test/mongo.spec.js
const { MongoMemoryServer } = require('mongodb-memory-server');

describe('test mongo-server', () => {
    // NB: the first run of this fails on my side with either v9 or v10, but subsequent runs in v9 are <100ms for me
    it('should not take more that 200ms', async () => {
        const start = Date.now();
        const server = await MongoMemoryServer.create();
        const ellapsed = Date.now() - start;
        await server.stop();

        expect(ellapsed).toBeLessThan(200);
    });
});

FYI the package.json:

{
  "name": "test-mongo-in-memory",
  "version": "1.0.0",
  "main": "index.js",
  "scripts": {
    "test": "jest"
  },
  "keywords": [],
  "author": "",
  "license": "ISC",
  "description": "",
  "dependencies": {
    "jest": "^29.7.0",
    "mongodb-memory-server": "^9.4.1"
  }
}

Debug Output

Debug Output

  MongoMS:ResolveConfig Debug Mode Enabled, through package.json +0ms
  MongoMS:MongoMemoryServer create: Called .create() method +0ms
  MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method +0ms
  MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method +0ms
  MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false +0ms
  MongoMS:DryMongoBinary generateOptions +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +1ms
  MongoMS:DryMongoBinary generatePaths {
  version: '7.0.11',
  downloadDir: '',
  os: { os: 'darwin' },
  platform: 'darwin',
  arch: 'arm64',
  systemBinary: ''
} +0ms
  MongoMS:DryMongoBinary getBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  homeCache: '/Users/my-user-name/.cache/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  modulesCache: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11',
  relative: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  resolveConfig: ''
}  +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in modulesCache: "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +0ms
  MongoMS:GetPort getFreePort: found free port 61168, in cache and not custom: false +0ms
  MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 61168,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'wiredTiger',
    replSet: undefined,
    dbPath: '/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8',
    tmpDir: '/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8',
    keyfileLocation: undefined,
    launchTimeout: undefined,
    args: undefined,
    auth: false
  },
  binary: undefined,
  spawn: undefined
} +4ms
  MongoMS:MongoInstance create: Called .create() method +0ms
  MongoMS:MongoInstance Mongo[61168]: start +0ms
  MongoMS:MongoBinary getPath +0ms
  MongoMS:DryMongoBinary generateOptions +2ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms
  MongoMS:DryMongoBinary generatePaths {
  version: '7.0.11',
  downloadDir: '',
  os: { os: 'darwin' },
  platform: 'darwin',
  arch: 'arm64',
  systemBinary: ''
} +0ms
  MongoMS:DryMongoBinary getBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  homeCache: '/Users/my-user-name/.cache/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  modulesCache: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11',
  relative: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  resolveConfig: ''
}  +1ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in modulesCache: "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +0ms
  MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "7.0.11",
  "downloadDir": "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server",
  "os": {
    "os": "darwin"
  },
  "platform": "darwin",
  "arch": "arm64",
  "systemBinary": "",
  "checkMD5": true
} +1ms
  MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "7.0.11" +0ms
  MongoMS:DryMongoBinary generateOptions +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms
  MongoMS:DryMongoBinary generatePaths {
  version: '7.0.11',
  downloadDir: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server',
  os: { os: 'darwin' },
  platform: 'darwin',
  arch: 'arm64',
  systemBinary: ''
} +0ms
  MongoMS:DryMongoBinary getBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  homeCache: '/Users/my-user-name/.cache/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  modulesCache: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11',
  relative: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  resolveConfig: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11'
}  +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +0ms
  MongoMS:DryMongoBinary locateBinary: running generateDownloadPath +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms
  MongoMS:DryMongoBinary generatePaths {
  version: '7.0.11',
  downloadDir: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server',
  os: { os: 'darwin' },
  platform: 'darwin',
  arch: 'arm64',
  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: {
  homeCache: '/Users/my-user-name/.cache/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  modulesCache: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11',
  relative: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/mongodb-binaries/mongod-arm64-darwin-7.0.11',
  resolveConfig: '/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11'
}  +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +0ms
  MongoMS:DryMongoBinary locateBinary: found binary at "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +1ms
  MongoMS:MongoBinary getPath: Mongod binary path: "/Users/my-user-name/Documents/Temp/test-mongo-in-memory/node_modules/.cache/mongodb-memory-server/mongod-arm64-darwin-7.0.11" +2ms
  MongoMS:MongoInstance Mongo[61168]: start: Starting Processes +3ms
  MongoMS:MongoInstance Mongo[61168]: _launchMongod: Launching Mongod Process +0ms
  MongoMS:MongoInstance Mongo[61168]: prepareCommandArgs +0ms
  MongoMS:MongoInstance Mongo[61168]: prepareCommandArgs: final argument array:["--port","61168","--dbpath","/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8","--storageEngine","wiredTiger","--bind_ip","127.0.0.1","--noauth"] +0ms
  MongoMS:MongoInstance Mongo[61168]: _launchKiller: Launching Killer Process (parent: 50137, child: 50170) +2ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.640+02:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"thread1","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":21},"outgoing":{"minWireVersion":6,"maxWireVersion":21},"isInternalClient":true}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.640+02:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"thread1","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}"" +106ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.642+02:00"},"s":"I",  "c":"NETWORK",  "id":4648602, "ctx":"thread1","msg":"Implicit TCP FastOpen in use."}"" +2ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","namespace":"config.tenantMigrationDonors"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","namespace":"config.tenantMigrationRecipients"}}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"thread1","msg":"Multi threading initialized"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"TENANT_M", "id":7091600, "ctx":"thread1","msg":"Starting TenantMigrationAccessBlockerRegistry"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":50170,"port":61168,"dbPath":"/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8","architecture":"64-bit","host":"Remis-MacBook-Pro.local"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"7.0.11","gitVersion":"f451220f0df2b9dfe073f1521837f8ec5c208a8c","modules":[],"allocator":"system","environment":{"distarch":"aarch64","target_arch":"aarch64"}}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Mac OS X","version":"23.1.0"}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:40.643+02:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":61168},"security":{"authorization":"disabled"},"storage":{"dbPath":"/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8","engine":"wiredTiger"}}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.644+02:00"},"s":"I",  "c":"NETWORK",  "id":5693100, "ctx":"initandlisten","msg":"Asio socket.set_option failed with std::system_error","attr":{"note":"acceptor TCP fast open","option":{"level":6,"name":261,"data":"00 04 00 00"},"error":{"what":"set_option: Invalid argument","message":"Invalid argument","category":"asio.system","value":22}}}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:40.644+02:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=15872M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,remove=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=2000),statistics_log=(wait=0),json_output=(error,message),verbose=[recovery_progress:1,checkpoint_progress:1,compact_progress:1,backup:0,checkpoint:0,compact:0,evict:0,history_store:0,recovery:0,rts:0,salvage:0,tiered:0,timestamp:0,transaction:0,verify:0,log:0],"}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.298+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":298066,"thread":"50170:0x1d6f0dec0","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery log replay has successfully finished and ran for 0 milliseconds"}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.298+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":298172,"thread":"50170:0x1d6f0dec0","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global recovery timestamp: (0, 0)"}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.298+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":298189,"thread":"50170:0x1d6f0dec0","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global oldest timestamp: (0, 0)"}}}"" +654ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.298+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":298228,"thread":"50170:0x1d6f0dec0","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery was completed successfully and took 0ms, including 0ms for the log replay, 0ms for the rollback to stable, and 0ms for the checkpoint."}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.319+02:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":675}}"" +21ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.319+02:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.356+02:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"73657337-ddf1-4eb4-8eea-17176201fde3"}},"options":{"uuid":{"$uuid":"73657337-ddf1-4eb4-8eea-17176201fde3"}}}}"" +37ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"73657337-ddf1-4eb4-8eea-17176201fde3"}},"namespace":"admin.system.version","index":"_id_","ident":"index-1--8556849059353303232","collectionIdent":"collection-0--8556849059353303232","commitTimestamp":null}}"" +21ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"REPL",     "id":20459,   "ctx":"initandlisten","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"7.0"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"REPL",     "id":5853300, "ctx":"initandlisten","msg":"current featureCompatibilityVersion value","attr":{"featureCompatibilityVersion":"7.0","context":"setFCV"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":21},"outgoing":{"minWireVersion":6,"maxWireVersion":21},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":21,"maxWireVersion":21},"outgoing":{"minWireVersion":21,"maxWireVersion":21},"isInternalClient":true}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":21,"maxWireVersion":21},"outgoing":{"minWireVersion":21,"maxWireVersion":21},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":21,"maxWireVersion":21},"outgoing":{"minWireVersion":21,"maxWireVersion":21},"isInternalClient":true}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"REPL",     "id":5853300, "ctx":"initandlisten","msg":"current featureCompatibilityVersion value","attr":{"featureCompatibilityVersion":"7.0","context":"startup"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"CONTROL",  "id":6608200, "ctx":"initandlisten","msg":"Initializing cluster server parameters from disk"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.377+02:00"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8/diagnostic.data"}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.378+02:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"ab519d2e-3fe9-4d21-acd9-1bb183e50123"}},"options":{"capped":true,"size":10485760}}}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"ab519d2e-3fe9-4d21-acd9-1bb183e50123"}},"namespace":"local.startup_log","index":"_id_","ident":"index-3--8556849059353303232","collectionIdent":"collection-2--8556849059353303232","commitTimestamp":null}}"" +20ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled","oldState":"ConfigPreStart"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-61168.sock"}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":61168,"ssl":"off"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"CONTROL",  "id":8423403, "ctx":"initandlisten","msg":"mongod startup complete","attr":{"Summary of time elapsed":{"Startup from clean shutdown?":true,"Statistics":{"Transport layer setup":"1 ms","Run initial syncer crash recovery":"0 ms","Create storage engine lock file in the data directory":"0 ms","Get metadata describing storage engine":"0 ms","Create storage engine":"711 ms","Write current PID to file":"0 ms","Write a new metadata for storage engine":"0 ms","Initialize FCV before rebuilding indexes":"0 ms","Drop abandoned idents and get back indexes that need to be rebuilt or builds that need to be restarted":"0 ms","Rebuild indexes for collections":"0 ms","Load cluster parameters from disk for a standalone":"0 ms","Build user and roles graph":"0 ms","Set up the background thread pool responsible for waiting for opTimes to be majority committed":"0 ms","Initialize information needed to make a mongod instance shard aware":"0 ms","Start up the replication coordinator":"0 ms","Start transport layer":"0 ms","_initAndListen total elapsed time":"755 ms"}}}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.398+02:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"LogicalSessionCacheRefresh","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"15eb7558-b015-4d9c-869e-7cd77279e8e9"}},"options":{}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: constructor: Instance is ready! +0ms
  MongoMS:MongoInstance Mongo[61168]: start: Processes Started +1ms
  MongoMS:MongoMemoryServer Mongo[61168]: _startUpInstance: Instance Started, createAuth: "false" +870ms
  MongoMS:MongoMemoryServer Mongo[61168]: start: Instance fully Started +0ms
  MongoMS:MongoMemoryServer Mongo[61168]: stop: Called .stop() method +0ms
  MongoMS:MongoMemoryServer Mongo[61168]: stop: Stopping MongoDB server on port 61168 with pid 50170 +0ms
  MongoMS:MongoInstance Mongo[61168]: stop +0ms
  MongoMS:utils Mongo[61168] killProcess: mongodProcess: sending "SIGINT" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.398+02: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"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"CONTROL",  "id":23377,   "ctx":"SignalHandler","msg":"Received signal","attr":{"signal":2,"error":"Interrupt: 2"}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"CONTROL",  "id":23381,   "ctx":"SignalHandler","msg":"will terminate after current cmd ends"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"SignalHandler","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":15000}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"REPL",     "id":4794602, "ctx":"SignalHandler","msg":"Attempting to enter quiesce mode"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"-",        "id":6371601, "ctx":"SignalHandler","msg":"Shutting down the FLE Crud thread pool"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"SignalHandler","msg":"Shutting down the MirrorMaestro"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.399+02:00"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"SignalHandler","msg":"Shutting down the WaitForMajorityService"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.400+02:00"},"s":"I",  "c":"CONTROL",  "id":4784903, "ctx":"SignalHandler","msg":"Shutting down the LogicalSessionCache"}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.420+02:00"},"s":"I",  "c":"REPL",     "id":7360102, "ctx":"LogicalSessionCacheRefresh","msg":"Added oplog entry for create to transaction","attr":{"namespace":"config.$cmd","uuid":{"uuid":{"$uuid":"15eb7558-b015-4d9c-869e-7cd77279e8e9"}},"object":{"create":"system.sessions","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}}}}"" +20ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.420+02:00"},"s":"I",  "c":"REPL",     "id":7360100, "ctx":"LogicalSessionCacheRefresh","msg":"Added oplog entry for createIndexes to transaction","attr":{"namespace":"config.$cmd","uuid":{"uuid":{"$uuid":"15eb7558-b015-4d9c-869e-7cd77279e8e9"}},"object":{"createIndexes":"system.sessions","v":2,"key":{"lastUse":1},"name":"lsidTTLIndex","expireAfterSeconds":1800}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.430+02:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"15eb7558-b015-4d9c-869e-7cd77279e8e9"}},"namespace":"config.system.sessions","index":"_id_","ident":"index-5--8556849059353303232","collectionIdent":"collection-4--8556849059353303232","commitTimestamp":null}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.430+02:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"15eb7558-b015-4d9c-869e-7cd77279e8e9"}},"namespace":"config.system.sessions","index":"lsidTTLIndex","ident":"index-6--8556849059353303232","collectionIdent":"collection-4--8556849059353303232","commitTimestamp":null}}"" +10ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"SignalHandler","msg":"Shutdown: going to close listening sockets"}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"NETWORK",  "id":23017,   "ctx":"listener","msg":"removing socket file","attr":{"path":"/tmp/mongodb-61168.sock"}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"SignalHandler","msg":"Shutting down the global connection pool"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784906, "ctx":"SignalHandler","msg":"Shutting down the FlowControlTicketholder"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"-",        "id":20520,   "ctx":"SignalHandler","msg":"Stopping further Flow Control ticket acquisitions."}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784908, "ctx":"SignalHandler","msg":"Shutting down the PeriodicThreadToAbortExpiredTransactions"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"REPL",     "id":4784909, "ctx":"SignalHandler","msg":"Shutting down the ReplicationCoordinator"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"SHARDING", "id":4784910, "ctx":"SignalHandler","msg":"Shutting down the ShardingInitializationMongoD"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"REPL",     "id":4784911, "ctx":"SignalHandler","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"-",        "id":4784912, "ctx":"SignalHandler","msg":"Killing all operations for shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"-",        "id":4695300, "ctx":"SignalHandler","msg":"Interrupted all currently running operations","attr":{"opsKilled":3}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"TENANT_M", "id":5093807, "ctx":"SignalHandler","msg":"Shutting down all TenantMigrationAccessBlockers on global shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"ASIO",     "id":22582,   "ctx":"TenantMigrationBlockerNet","msg":"Killing all outstanding egress activity."}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"ASIO",     "id":6529201, "ctx":"SignalHandler","msg":"Network interface redundant shutdown","attr":{"state":"Stopped"}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"ASIO",     "id":22582,   "ctx":"SignalHandler","msg":"Killing all outstanding egress activity."}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"COMMAND",  "id":4784913, "ctx":"SignalHandler","msg":"Shutting down all open transactions"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"REPL",     "id":4784914, "ctx":"SignalHandler","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"INDEX",    "id":4784915, "ctx":"SignalHandler","msg":"Shutting down the IndexBuildsCoordinator"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"SignalHandler","msg":"Shutting down the ReplicaSetMonitor"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"SignalHandler","msg":"Shutting down the MigrationUtilExecutor"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"ASIO",     "id":22582,   "ctx":"MigrationUtil-TaskExecutor","msg":"Killing all outstanding egress activity."}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"COMMAND",  "id":4784923, "ctx":"SignalHandler","msg":"Shutting down the ServiceEntryPoint"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784927, "ctx":"SignalHandler","msg":"Shutting down the HealthLog"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784928, "ctx":"SignalHandler","msg":"Shutting down the TTL monitor"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"INDEX",    "id":3684100, "ctx":"SignalHandler","msg":"Shutting down TTL collection monitor thread"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"INDEX",    "id":3684101, "ctx":"SignalHandler","msg":"Finished shutting down TTL collection monitor thread"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":6278511, "ctx":"SignalHandler","msg":"Shutting down the Change Stream Expired Pre-images Remover"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784929, "ctx":"SignalHandler","msg":"Acquiring the global lock for shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"CONTROL",  "id":4784930, "ctx":"SignalHandler","msg":"Shutting down the storage engine"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22320,   "ctx":"SignalHandler","msg":"Shutting down journal flusher thread"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22321,   "ctx":"SignalHandler","msg":"Finished shutting down journal flusher thread"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22322,   "ctx":"SignalHandler","msg":"Shutting down checkpoint thread"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22323,   "ctx":"SignalHandler","msg":"Finished shutting down checkpoint thread"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22261,   "ctx":"SignalHandler","msg":"Timestamp monitor shutting down"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":20282,   "ctx":"SignalHandler","msg":"Deregistering all the collections"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22317,   "ctx":"SignalHandler","msg":"WiredTigerKVEngine shutting down"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22318,   "ctx":"SignalHandler","msg":"Shutting down session sweeper thread"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.431+02:00"},"s":"I",  "c":"STORAGE",  "id":22319,   "ctx":"SignalHandler","msg":"Finished shutting down session sweeper thread"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.436+02:00"},"s":"I",  "c":"STORAGE",  "id":4795902, "ctx":"SignalHandler","msg":"Closing WiredTiger","attr":{"closeConfig":"leak_memory=true,use_timestamp=false,"}}"" +5ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.437+02:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "ctx":"SignalHandler","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":437405,"thread":"50170:0x16d0bf000","session_name":"close_ckpt","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 34, snapshot max: 34 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}}}"" +1ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.508+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"SignalHandler","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":508584,"thread":"50170:0x16d0bf000","session_name":"WT_CONNECTION.close","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"shutdown checkpoint has successfully finished and ran for 71 milliseconds"}}}"" +71ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.508+02:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"SignalHandler","msg":"WiredTiger message","attr":{"message":{"ts_sec":1727444501,"ts_usec":508688,"thread":"50170:0x16d0bf000","session_name":"WT_CONNECTION.close","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"shutdown was completed successfully and took 72ms, including 0ms for the rollback to stable, and 71ms for the checkpoint."}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"STORAGE",  "id":4795901, "ctx":"SignalHandler","msg":"WiredTiger closed","attr":{"durationMillis":106}}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"STORAGE",  "id":22279,   "ctx":"SignalHandler","msg":"shutdown: removing fs lock..."}"" +34ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"-",        "id":4784931, "ctx":"SignalHandler","msg":"Dropping the scope cache for shutdown"}
  MongoMS:MongoInstance {"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"FTDC",     "id":20626,   "ctx":"SignalHandler","msg":"Shutting down full-time diagnostic data capture"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"SignalHandler","msg":"Now exiting"}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"CONTROL",  "id":8423404, "ctx":"SignalHandler","msg":"mongod shutdown complete","attr":{"Summary of time elapsed":{"Statistics":{"Enter terminal shutdown":"0 ms","Step down the replication coordinator for shutdown":"0 ms","Time spent in quiesce mode":"0 ms","Shut down FLE Crud subsystem":"0 ms","Shut down MirrorMaestro":"0 ms","Shut down WaitForMajorityService":"0 ms","Shut down the logical session cache":"31 ms","Shut down the transport layer":"1 ms","Shut down the global connection pool":"0 ms","Shut down the flow control ticket holder":"0 ms","Kill all operations for shutdown":"0 ms","Shut down all tenant migration access blockers on global shutdown":"0 ms","Shut down all open transactions":"0 ms","Acquire the RSTL for shutdown":"0 ms","Shut down the IndexBuildsCoordinator and wait for index builds to finish":"0 ms","Shut down the replica set monitor":"0 ms","Shut down the migration util executor":"0 ms","Shut down the health log":"0 ms","Shut down the TTL monitor":"0 ms","Shut down expired pre-images and documents removers":"0 ms","Shut down the storage engine":"111 ms","Wait for the oplog cap maintainer thread to stop":"0 ms","Shut down full-time data capture":"0 ms","shutdownTask total elapsed time":"143 ms"}}}}"" +0ms
  MongoMS:MongoInstance Mongo[61168]: stdoutHandler: ""{"t":{"$date":"2024-09-27T15:41:41.542+02:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"SignalHandler","msg":"Shutting down","attr":{"exitCode":0}}"" +0ms
  MongoMS:utils Mongo[61168] killProcess: mongodProcess: got exit signal, Code: 0, Signal: null +145ms
  MongoMS:MongoInstance Mongo[61168]: closeHandler: code: "0", signal: "null" +2ms
  MongoMS:utils Mongo[61168] killProcess: killerProcess: sending "SIGINT" +0ms
  MongoMS:utils Mongo[61168] killProcess: killerProcess: got exit signal, Code: 0, Signal: null +2ms
  MongoMS:MongoInstance Mongo[61168]: stop: Instance Finished Shutdown +2ms
  MongoMS:MongoMemoryServer Mongo[61168]: cleanup: { doCleanup: true, force: false } +148ms
  MongoMS:MongoMemoryServer Mongo[61168]: cleanup: removing tmpDir at /var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/mongo-mem-TpDc3wXVWxc8 +0ms

Do you know why it happenes?

Nope - I haven't digged through the source though. My initial thought was that something previously cached in the startup procedure pre-v10, isn't anymore.

[hasezoey]

because you are using MMS 10.x and the default binary of 7.0.x (currently 7.0.11 in 10.0.x), you are using (default) storage engine wiredTiger(disk based) instead of the previous ephemeralForTest(mostly ram based) because mongodb 7.0 removed that storage engine. there is another ram storage engine available, but only for business mongodb (which this package does not use).

the workarounds are:

• work with the new storage engine and set your database path (by default the temporary storage of your OS, in your case it is /var/folders/pg/t48q3kmx7l1_2_t4nzfd7zf80000gn/T/ according to the provided logs) to a tmpfs or equivalent, if possible
• explicitly set the mongodb version to use to 6.x or earlier (via config option VERSION))

Note that there has been a note in the Migrate to version 10.0.0 guide.

[Marchelune]

thanks @hasezoey !
I did see the note but overlooked the down-the-line impact of that binary upgrade.
I'll probably stick to v6 for now because I'm not sure yet how to setup an in-memory storage consistent across dev OS and CI vms.

[christophehurpeau]

If it helps here how we configured ramdisk for both mac and circleci:

Mac

scripts/mkramdisk.sh

#!/bin/sh

# https://superuser.com/questions/456803/create-ram-disk-mount-to-specific-folder-in-osx

ramfs_size_mb=2048
mount_point=/tmp/rdisk

ramfs_size_sectors=$((${ramfs_size_mb}*1024*1024/512))
ramdisk_dev=`hdid -nomount ram://${ramfs_size_sectors}`

newfs_hfs -v 'ram disk' ${ramdisk_dev}
mkdir -p ${mount_point}
mount -o noatime -t hfs ${ramdisk_dev} ${mount_point}

echo "remove with:"
echo "umount ${mount_point}"
echo "diskutil eject ${ramdisk_dev}"

Run this script before running tests

CircleCI

/mnt/ramdisk is available, see https://circleci.com/docs/using-docker/#ram-disks

create MongoMemoryServer

get tmpdir:

const baseTmpdir = (() => {
  if (platform === "darwin") {
    const rdiskPath = "/tmp/rdisk";
    if (!fsSync.existsSync(rdiskPath)) {
      throw new Error(
        rdiskPath + " does not exist. Execute script mkramdisk.sh first."
      );
    }
    return rdiskPath;
  }

  if (process.env.CI) {
    const rdiskPath = "/mnt/ramdisk";

    if (!fsSync.existsSync(rdiskPath)) {
      throw new Error(
        rdiskPath +
          " does not exist. Check circle doc: https://circleci.com/docs/using-docker/#ram-disks."
      );
    }
    return rdiskPath;
  }

  console.warn(
    'It seems you are not on a "darwin" platform or CI environment, falling back to tmp directory. Tests might be slower that expected.'
  );

  return tmpdir();
})();

        const dbPath = path.join(baseTmpdir, `${i}`);
        await fs.mkdir(dbPath, { recursive: true });
        return MongoMemoryServer.create({
          instance: {
            port: 5100 + i,
            dbPath,
          },
          binary: {
            version: "7.0.12",
          },
      });