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.59k stars 187 forks source link

MongoMemoryReplSet dbName is always default empty string (Prisma doesn't like it) #667

Closed peacechen closed 2 years ago

peacechen commented 2 years ago

Versions

package: mongo-memory-server

What is the Problem?

Passing dbName to MongoMemoryReplSet.create() doesn't reflect in the URI returned by getUri(). The dbName in the connection string appears as the default empty string: mongod.getUri() returns mongodb://127.0.0.1:27099/?replicaSet=replica

Prisma refuses to connect with that connection string, complaining that it's invalid. Connecting with MongoDB Compass is unsuccessful as well. I've tried to manually insert the dbName ("test") in the connection string but that fails to connect as well. Prisma is able to connect to a "real" local mongodb instance with a replica set. This setup with mongo-memory-server is for integration testing.

Code Example

      const mongodRepl = await MongoMemoryReplSet.create({
        instanceOpts: [{
          port: 27019,
        }],
        replSet: {
          dbName: "test",
          name: "replica",
          storageEngine: "wiredTiger",
        },
      });

Debug Output

Debug Output ```txt MongoMS:ResolveConfig Debug Mode Enabled, through Environment Variable +0ms MongoMS:ResolveConfig findPackageJson: Found package.json at "..../package.json" +1ms MongoMS:ResolveConfig Debug Mode Enabled, through package.json +1ms MongoMS:MongoMemoryReplSet create: Called .create() method +0ms MongoMS:MongoMemoryReplSet start: stopped +1ms MongoMS:MongoMemoryReplSet initAllServers +1ms MongoMS:MongoMemoryReplSet initAllServers: starting special server "1" of "1" from instanceOpts (count: 1): { port: 27099 } +0ms MongoMS:MongoMemoryReplSet getInstanceOpts: instance opts: { auth: false, args: [], dbName: 'test', ip: '127.0.0.1', replSet: 'replica', storageEngine: 'wiredTiger', port: 27099 } +2ms MongoMS:MongoMemoryReplSet initAllServers: waiting for all servers to finish starting +0ms 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: 27099, dbName: 'test', ip: '127.0.0.1', storageEngine: 'wiredTiger', replSet: 'replica', dbPath: '/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI', tmpDir: { name: '/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI', removeCallback: [Function: _cleanupCallback] }, args: [], auth: false }, binary: {}, spawn: {} } +4ms MongoMS:MongoInstance create: Called .create() method +0ms MongoMS:MongoInstance Mongo[27099]: start +1ms MongoMS:MongoBinary getPath +0ms MongoMS:DryMongoBinary generateOptions +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +1ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '', os: { os: 'darwin' }, platform: 'darwin', arch: 'x64', systemBinary: '' } +0ms MongoMS:DryMongoBinary getBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +1ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary combineBinaryName +0ms MongoMS:DryMongoBinary generateDownloadPath: Paths: { legacyHomeCache: '..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8', modulesCache: '..../node_modules/.cache/mongodb-memory-server/mongod-x64-darwin-5.0.8', relative: '..../mongodb-binaries/mongod-x64-darwin-5.0.8', resolveConfig: '' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8" +3ms MongoMS:MongoBinary getPath: MongoBinary options: { "version": "5.0.8", "downloadDir": "..../.cache/mongodb-binaries", "os": { "os": "darwin" }, "platform": "darwin", "arch": "x64", "systemBinary": "", "checkMD5": false } +5ms MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8" +1ms MongoMS:DryMongoBinary generateOptions +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '..../.cache/mongodb-binaries', os: { os: 'darwin' }, platform: 'darwin', 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: '..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8', modulesCache: '..../node_modules/.cache/mongodb-memory-server/mongod-x64-darwin-5.0.8', relative: '..../mongodb-binaries/mongod-x64-darwin-5.0.8', resolveConfig: '..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8" +1ms MongoMS:DryMongoBinary locateBinary: running generateDownloadPath +0ms MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms MongoMS:DryMongoBinary generatePaths { version: '5.0.8', downloadDir: '..../.cache/mongodb-binaries', os: { os: 'darwin' }, platform: 'darwin', 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: .....cache/mongodb-binaries/mongod-x64-darwin-5.0.8', modulesCache: '..../node_modules/.cache/mongodb-memory-server/mongod-x64-darwin-5.0.8', relative: ..../mongodb-binaries/mongod-x64-darwin-5.0.8', resolveConfig: '..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8' } +0ms MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8" +1ms MongoMS:DryMongoBinary locateBinary: found binary at "..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8" +0ms MongoMS:MongoBinary getPath: Mongod binary path: "..../.cache/mongodb-binaries/mongod-x64-darwin-5.0.8" +3ms MongoMS:MongoInstance Mongo[27099]: start: Starting Processes +9ms MongoMS:MongoInstance Mongo[27099]: _launchMongod: Launching Mongod Process +0ms MongoMS:MongoInstance Mongo[27099]: prepareCommandArgs +0ms MongoMS:MongoInstance Mongo[27099]: prepareCommandArgs: final argument array:["--port","27099","--dbpath","/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI","--replSet","replica","--storageEngine","wiredTiger","--bind_ip","127.0.0.1","--noauth"] +0ms MongoMS:MongoInstance Mongo[27099]: _launchKiller: Launching Killer Process (parent: 55108, child: 55111) +6ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.632-05: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}}}"" +123ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.638-05:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}"" +4ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.645-05:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}"" +7ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.646-05:00"},"s":"I", "c":"NETWORK", "id":4648602, "ctx":"main","msg":"Implicit TCP FastOpen in use."}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.649-05:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.650-05:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.650-05:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:40.650-05:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.651-05:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.651-05:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":55111,"port":27099,"dbPath":"/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI","architecture":"64-bit","host":"My-MBP.lan"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.651-05:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","modules":[],"allocator":"system","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:40.651-05:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Mac OS X","version":"19.6.0"}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:40.651-05:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":27099},"replication":{"replSet":"replica"},"security":{"authorization":"disabled"},"storage":{"dbPath":"/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI","engine":"wiredTiger"}}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.655-05: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}}}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:40.656-05:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7680M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=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=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.249-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1655994521:249900][55111:0x11665fdc0], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.249-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1655994521:249971][55111:0x11665fdc0], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}"" +594ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.259-05:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":603}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.260-05:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.275-05:00"},"s":"I", "c":"STORAGE", "id":4366408, "ctx":"initandlisten","msg":"No table logging settings modifications are required for existing WiredTiger tables","attr":{"loggingEnabled":false}}"" +15ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.276-05:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.277-05:00"},"s":"W", "c":"CONTROL", "id":22184, "ctx":"initandlisten","msg":"Soft rlimits for open file descriptors too low","attr":{"currentValue":24576,"recommendedMinimum":64000},"tags":["startupWarnings"]}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.280-05:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.280-05:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.282-05:00"},"s":"I", "c":"SHARDING", "id":20997, "ctx":"initandlisten","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}"" +2ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.282-05:00"},"s":"I", "c":"FTDC", "id":20625, "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/folders/lv/vn7ch3nn04sctx2bjkq_5s640000gn/T/mongo-mem--55108-5IMUctZ5h7wI/diagnostic.data"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.283-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"4c535936-c813-4127-ab84-ac169dd1d19d"}},"options":{"capped":true,"size":10485760}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.294-05: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}}"" +11ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.295-05:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.295-05:00"},"s":"I", "c":"REPL", "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.295-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.oplogTruncateAfterPoint","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"b58c03cc-bacc-46f6-8c77-74b690a4cf89"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.296-05:00"},"s":"I", "c":"-", "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"ReadConcernMajorityNotAvailableYet: Read concern majority reads are currently not possible.","nextWakeupMillis":200}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.306-05: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}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.306-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.minvalid","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d2200221-2a1d-454d-a000-30dbe5582946"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.316-05: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}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.317-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.election","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"6991a2a2-a3c4-47da-a2c0-aa800a4ec1d7"}},"options":{}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.328-05: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}}"" +11ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.328-05:00"},"s":"I", "c":"REPL", "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.328-05:00"},"s":"I", "c":"REPL", "id":21311, "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.328-05:00"},"s":"I", "c":"REPL", "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.328-05: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-06-23T09:28:41.329-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.rollback.id","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"7253b0d7-516b-4551-9040-e554ee1c9f00"}},"options":{}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.339-05: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}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.339-05:00"},"s":"I", "c":"REPL", "id":21531, "ctx":"initandlisten","msg":"Initialized the rollback ID","attr":{"rbid":1}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.339-05: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"}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.339-05:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigUninitialized","oldState":"ConfigStartingUp"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.339-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.views","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"9362bf4e-061b-4a3d-aa3a-77f2e9080903"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.351-05: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}}"" +12ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.353-05:00"},"s":"I", "c":"REPL", "id":40440, "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.354-05:00"},"s":"I", "c":"REPL", "id":40445, "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.356-05:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27099.sock"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.356-05:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.356-05:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":27099,"ssl":"off"}}"" +1ms MongoMS:MongoInstance Mongo[27099]: constructor: Instance is ready! +1ms MongoMS:MongoInstance Mongo[27099]: start: Processes Started +0ms MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Instance Started, createAuth: "false" +862ms MongoMS:MongoMemoryServer Mongo[27099]: start: Instance fully Started +1ms MongoMS:MongoMemoryReplSet initAllServers: finished starting all servers initially +868ms MongoMS:MongoMemoryReplSet _initReplSet +1ms MongoMS:MongoMemoryServer Mongo[27099]: getUri: running undefined undefined +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.356-05: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"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.357-05: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":"2022-06-23T09:28:41.378-05:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:62814","uuid":"83a0c8e5-0a82-4a61-9fb9-f0ad79e17e26","connectionId":1,"connectionCount":1}}"" +21ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.385-05:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:62814","client":"conn1","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Darwin","name":"darwin","architecture":"x64","version":"19.6.0"},"platform":"Node.js v18.2.0, LE (unified)|Node.js v18.2.0, LE (unified)"}}}"" +7ms MongoMS:MongoMemoryReplSet _initReplSet: connected +33ms MongoMS:MongoMemoryReplSet _initReplSet: trying "replSetInitiate" +2ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.397-05:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:62815","uuid":"5ecb2ad0-79e1-402e-b9ad-da040d64a429","connectionId":2,"connectionCount":2}}"" +13ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.398-05:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn2","msg":"client metadata","attr":{"remote":"127.0.0.1:62815","client":"conn2","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Darwin","name":"darwin","architecture":"x64","version":"19.6.0"},"platform":"Node.js v18.2.0, LE (unified)|Node.js v18.2.0, LE (unified)"}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.400-05:00"},"s":"I", "c":"REPL", "id":21356, "ctx":"conn2","msg":"replSetInitiate admin command received from client"}"" +2ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.400-05:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigInitiating","oldState":"ConfigUninitialized"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.400-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"9be56d97-ad2a-49b9-b198-b4e455b5a651"}},"options":{"uuid":{"$uuid":"9be56d97-ad2a-49b9-b198-b4e455b5a651"}}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.411-05: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}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.411-05:00"},"s":"I", "c":"REPL", "id":20459, "ctx":"conn2","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"5.0"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.411-05: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-06-23T09:28:41.411-05:00"},"s":"I", "c":"NETWORK", "id":22991, "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":2}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.411-05:00"},"s":"I", "c":"NETWORK", "id":22991, "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":1}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.412-05:00"},"s":"I", "c":"REPL", "id":21357, "ctx":"conn2","msg":"replSetInitiate config object parses ok","attr":{"numMembers":1}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.412-05:00"},"s":"I", "c":"REPL", "id":21251, "ctx":"conn2","msg":"Creating replication oplog","attr":{"oplogSizeMB":192}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.412-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.oplog.rs","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"5766d82f-edd8-4dfc-be98-7ed8bce1dfd8"}},"options":{"capped":true,"size":201326592,"autoIndexId":false}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.417-05:00"},"s":"I", "c":"STORAGE", "id":22383, "ctx":"conn2","msg":"The size storer reports that the oplog contains","attr":{"numRecords":0,"dataSize":0}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.417-05:00"},"s":"I", "c":"STORAGE", "id":22382, "ctx":"conn2","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}"" +6ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.424-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1655994521:424596][55111:0x700005536000], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 68, snapshot max: 68 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}}"" +6ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.462-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.system.replset","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"373f2659-66fa-4150-9653-62504c717b6e"}},"options":{}}}"" +39ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.475-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"conn2","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.system.replset","index":"_id_","commitTimestamp":{"$timestamp":{"t":1655994521,"i":1}}}}"" +12ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.477-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1655994521:477959][55111:0x700005536000], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 77, snapshot max: 77 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.497-05:00"},"s":"I", "c":"REPL", "id":5872101, "ctx":"conn2","msg":"Taking a stable checkpoint for replSetInitiate"}"" +19ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.497-05:00"},"s":"I", "c":"REPL", "id":5872100, "ctx":"conn2","msg":"Updating commit point for initiate","attr":{"_lastCommittedOpTimeAndWallTime":"{ ts: Timestamp(1655994521, 1), t: -1 }, 2022-06-23T09:28:41.474-05:00"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.497-05:00"},"s":"I", "c":"STORAGE", "id":22310, "ctx":"conn2","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1655994521,"i":1}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1655994521,"i":1}}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.498-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1655994521:498053][55111:0x700005536000], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 79, snapshot max: 79 snapshot count: 0, oldest timestamp: (1655994521, 1) , meta checkpoint timestamp: (1655994521, 1) base write gen: 1"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigInitiating"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"conn2","msg":"New replica set config in use","attr":{"config":{"_id":"replica","version":1,"term":0,"members":[{"_id":0,"host":"127.0.0.1:27099","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62b478993b8edd8b072126d3"}}}}}"" +8ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":"[1655994521:506321][55111:0x7000043d6000], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 81, snapshot max: 81 snapshot count: 0, oldest timestamp: (1655994521, 1) , meta checkpoint timestamp: (1655994521, 1) base write gen: 1"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"conn2","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:27099"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":21306, "ctx":"conn2","msg":"Starting replication storage threads"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":4280512, "ctx":"conn2","msg":"No initial sync required. Attempting to begin steady replication"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.506-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"9f9ab0bc-f978-4bff-82ad-8f5a9017e2ec"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.507-05: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":400}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.522-05: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}}"" +15ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.522-05:00"},"s":"I", "c":"REPL", "id":21299, "ctx":"conn2","msg":"Starting replication fetcher thread"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.522-05:00"},"s":"I", "c":"REPL", "id":21300, "ctx":"conn2","msg":"Starting replication applier thread"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.523-05:00"},"s":"I", "c":"REPL", "id":21301, "ctx":"conn2","msg":"Starting replication reporter thread"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.523-05:00"},"s":"I", "c":"REPL", "id":21224, "ctx":"OplogApplier-0","msg":"Starting oplog application"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.523-05:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn2","msg":"Slow query","attr":{"type":"command","ns":"local.system.replset","command":{"replSetInitiate":{"_id":"replica","members":[{"_id":0,"host":"127.0.0.1:27099"}],"writeConcernMajorityJournalDefault":true,"settings":{"electionTimeoutMillis":500}},"$db":"admin"},"numYields":0,"reslen":38,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":15}},"ReplicationStateTransition":{"acquireCount":{"w":16}},"Global":{"acquireCount":{"r":8,"w":6,"W":2}},"Database":{"acquireCount":{"r":6,"w":6,"R":1}},"Collection":{"acquireCount":{"r":2,"w":5}},"Mutex":{"acquireCount":{"r":12}},"oplog":{"acquireCount":{"w":1}}},"flowControl":{"acquireCount":5,"timeAcquiringMicros":4},"storage":{},"remote":"127.0.0.1:62815","protocol":"op_msg","durationMillis":122}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.523-05:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}"" +1ms MongoMS:MongoMemoryReplSet _initReplSet: ReplSet-reconfig finished +132ms MongoMS:MongoMemoryReplSet _waitForPrimary: Waiting for a Primary +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.524-05: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-06-23T09:28:41.524-05: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-06-23T09:28:41.524-05: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-06-23T09:28:41.524-05: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}}}"" +2ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"ELECTION", "id":21450, "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":1}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21106, "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21359, "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05: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-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21363, "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"ReplCoord-0","msg":"Stopping replication producer"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":1}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":0}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":4508103, "ctx":"OplogApplier-0","msg":"Increment the config term via reconfig"} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":6015313, "ctx":"OplogApplier-0","msg":"Replication config state is Steady, starting reconfig"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigReconfiguring","oldState":"ConfigSteady"}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":21353, "ctx":"OplogApplier-0","msg":"replSetReconfig config object parses ok","attr":{"numMembers":1}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.527-05:00"},"s":"I", "c":"REPL", "id":51814, "ctx":"OplogApplier-0","msg":"Persisting new config to disk"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.530-05:00"},"s":"I", "c":"REPL", "id":6015315, "ctx":"OplogApplier-0","msg":"Persisted new config to disk"}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.530-05: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-06-23T09:28:41.530-05:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"OplogApplier-0","msg":"New replica set config in use","attr":{"config":{"_id":"replica","version":1,"term":1,"members":[{"_id":0,"host":"127.0.0.1:27099","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62b478993b8edd8b072126d3"}}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.530-05:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"OplogApplier-0","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:27099"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.530-05:00"},"s":"I", "c":"REPL", "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.530-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.transactions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"87595453-b102-4a48-aee4-5dccde676909"}},"options":{}}}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.542-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.transactions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1655994521,"i":3}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.542-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.image_collection","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3706a507-f265-4989-841b-893724f3ec9a"}},"options":{}}}"" +12ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.552-05: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":{"$timestamp":{"t":1655994521,"i":4}}}}"" +10ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.552-05:00"},"s":"I", "c":"REPL", "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.552-05:00"},"s":"I", "c":"STORAGE", "id":20657, "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}"" +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.552-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.system.indexBuilds","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d5254243-81c7-4f89-bf68-15c762a9360e"}},"options":{}}}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.564-05: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":{"$timestamp":{"t":1655994521,"i":6}}}}"" +11ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.565-05:00"},"s":"I", "c":"REPL", "id":21331, "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}"" +1ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: emitting "instancePrimary" +0ms MongoMS:MongoMemoryReplSet _waitForPrimary: detected one primary instance +39ms MongoMS:MongoMemoryReplSet _initReplSet: running +0ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.565-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"f956af48-29ce-4341-89f0-495e381da854"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.566-05:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:62814","uuid":"83a0c8e5-0a82-4a61-9fb9-f0ad79e17e26","connectionId":1,"connectionCount":1}}"" +3ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.568-05:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:62815","uuid":"5ecb2ad0-79e1-402e-b9ad-da040d64a429","connectionId":2,"connectionCount":0}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.569-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3d52ee29-1c2e-41a1-9bda-ece255fba2d2"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.569-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"545907af-bdab-483d-81e9-3d629fcca074"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.588-05: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":{"$timestamp":{"t":1655994521,"i":7}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.602-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"_id_","commitTimestamp":{"$timestamp":{"t":1655994521,"i":11}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.602-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","commitTimestamp":{"$timestamp":{"t":1655994521,"i":11}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.603-05:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationRecipientService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.607-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"_id_","commitTimestamp":{"$timestamp":{"t":1655994521,"i":12}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.607-05:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","commitTimestamp":{"$timestamp":{"t":1655994521,"i":12}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.607-05:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"5667956b-8fb1-42d2-b4bc-cc43de26dd13"}},"options":{}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.626-05: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":{"$timestamp":{"t":1655994521,"i":15}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.626-05: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":{"$timestamp":{"t":1655994521,"i":15}}}} MongoMS:MongoInstance {"t":{"$date":"2022-06-23T09:28:41.626-05:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationDonorService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}"" +65ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.926-05:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:62821","uuid":"636fdce2-76b5-46dd-a864-26cc9d51fef7","connectionId":3,"connectionCount":1}}"" +293ms MongoMS:MongoInstance Mongo[27099]: stdoutHandler: ""{"t":{"$date":"2022-06-23T09:28:41.926-05:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:62821","client":"conn3","doc":{"driver":{"name":"mongo-rust-driver|Prisma","version":"2.1.0"},"os":{"type":"macos","architecture":"x86_64","version":"10.15.6"}}}}"" +0ms MongoMS:MongoMemoryReplSet stop: called by manual +357ms MongoMS:MongoMemoryServer Mongo[27099]: stop: Called .stop() method +591ms MongoMS:MongoMemoryServer Mongo[27099]: stop: Stopping MongoDB server on port 27099 with pid 55111 +0ms MongoMS:MongoInstance Mongo[27099]: stop +25ms MongoMS:MongoInstance Mongo[27099]: stop: trying shutdownServer +0ms ```

Do you know why it happenes?

no

hasezoey commented 2 years ago

Connecting with MongoDB Compass is unsuccessful as well.

this is likely because the mongodb instance MMS creates is only started while the nodejs process is running or until .stop is called

Passing dbName to MongoMemoryReplSet.create() doesn't reflect in the URI returned by getUri()

this was a change to make the URI both consumable by mongodb and other consumers like mongoose, because the db means different things in different drivers, a db can still get appended when passing in a string argument to getUri

the dbName property itself is currently unused because it this, may change it the future though

peacechen commented 2 years ago

a db can still get appended when passing in a string argument to getUri

Thanks for that suggestion. I passed in the dbName to getUri: mongod.getUri("test")

...which returns mongodb://127.0.0.1:27099/test?replicaSet=replica. This is working for a single test as far as I can tell. There are some other issues with prisma's db migration in the jest test setup that I need to figure out.

hasezoey commented 2 years ago

The tests' beforeEach() calls MongoMemoryReplSet.create(), and the afterEach calls mongod.stop(true);. What's the right way to terminate mongo-memory-server between tests, or should it not stop between tests?

i know it is now deleted, but i just want to note: it is not recommended to so often start a instance / stop a instance, because that can really prolong tests and it greatly increases the chances of a failure (like a operation timeout, which is not uncommon), which can fail a entire suite if a single one of them errors

if you use jest, i would recommend reading and applying Integration with Test Runners: jest

peacechen commented 2 years ago

Thanks @hasezoey

github-actions[bot] commented 2 years ago

Marking Issue as stale, will be closed in 7 days if no more activity is seen

github-actions[bot] commented 2 years ago

Closing Issue because it is marked as stale