search

typegoose / mongodb-memory-server

Manage & spin up mongodb server binaries with zero(or slight) configuration for tests.
https://typegoose.github.io/mongodb-memory-server/
MIT License
2.6k stars 187 forks source link

MongoMemoryServer.create unusually slow in v10 #889

Closed Marchelune closed 1 month ago

Marchelune commented 1 month ago

Hi there 👋 !

Versions

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 ```txt 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 commented 1 month ago

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:

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

Marchelune commented 1 month ago

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 commented 1 week ago

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",
          },
      });