Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

MongoMemoryReplSet - TypeError: Cannot read property 'pid' of undefined #666

Closed
jakobo opened this issue Jun 22, 2022 · 12 comments
Closed

MongoMemoryReplSet - TypeError: Cannot read property 'pid' of undefined #666

jakobo opened this issue Jun 22, 2022 · 12 comments
Labels
bug released Pull Request released | Issue is fixed

Comments

@jakobo
Copy link

jakobo commented Jun 22, 2022

Versions

  • NodeJS: 14.19.0
  • mongodb-memory-server-*: ^8.6.1
  • mongodb(the binary version): 0.0.0
  • mongodb(the js package): ^4.7.0
  • system: WSL 2 on Windows Linux Bismuth 4.19.128-microsoft-standard #1 SMP Tue Jun 23 12:58:10 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
  • Test Framework: AVA @ ^4.3.0

package: mongo-memory-server

What is the Problem?

When running tests locally, I will occasionally get an unhandled exception It appears that the isAlive check needs to verify it didn't get back an undefined value.

TypeError: Cannot read property 'pid' of undefined

  › node_modules/mongodb-memory-server-core/src/util/utils.ts:103:29
  › Generator.next (<anonymous>)
  › node_modules/tslib/tslib.js:118:75
  › __awaiter (node_modules/tslib/tslib.js:114:16)
  › killProcess (node_modules/mongodb-memory-server-core/lib/util/utils.js:76:34)
  › MongoInstance.<anonymous> (node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:419:24)
  › Generator.next (<anonymous>)
  › fulfilled (node_modules/tslib/tslib.js:115:62)

Code Example

AVA test

import anytest, { TestFn } from "ava";
import { MongoMemoryReplSet } from "mongodb-memory-server";
import { Queue } from "../src/queue.js";

interface Context {
  rs: MongoMemoryReplSet;
  mongoUri: string;
}

interface SimpleJob {
  success: boolean;
}

const test = anytest as TestFn<Context>;

// create a clean mongo in-memory for every test
test.beforeEach(async (t) => {
  const rs = await MongoMemoryReplSet.create({ replSet: { count: 1 } });
  await rs.waitUntilRunning();
  t.context.mongoUri = rs.getUri();
  t.context.rs = rs;
});

// outlier that ensures replset behavior is working as expected
// all other times, we'll use a 1ms poll interval for speed in tests
test("Leverages a replica set oplog when available", async (t) => {
  const client = new MongoClient(t.context.mongoUri);
  await client.connect();
  await client.db("test").collection("test").insertOne({
    valid: true,
  });
  t.pass();
});

Debug Output

Debug Output 
2022-06-22T00:18:21.954Z MongoMS:ResolveConfig Debug Mode Enabled, through Environment Variable
2022-06-22T00:18:21.955Z MongoMS:ResolveConfig findPackageJson: Found package.json at "/home/jakobo/code/taskless/docqueue/package.json"
2022-06-22T00:18:21.955Z MongoMS:ResolveConfig Debug Mode Enabled, through package.json
2022-06-22T00:18:22.405Z MongoMS:MongoMemoryReplSet create: Called .create() method
2022-06-22T00:18:22.405Z MongoMS:MongoMemoryReplSet start: stopped
2022-06-22T00:18:22.406Z MongoMS:MongoMemoryReplSet initAllServers
2022-06-22T00:18:22.406Z MongoMS:MongoMemoryReplSet initAllServers: starting extra server "1" of "1" (count: 1)
2022-06-22T00:18:22.406Z MongoMS:MongoMemoryReplSet getInstanceOpts: instance opts: {
  auth: false,
  args: [],
  dbName: '',
  ip: '127.0.0.1',
  replSet: 'testset',
  storageEngine: 'ephemeralForTest'
}
2022-06-22T00:18:22.407Z MongoMS:MongoMemoryReplSet initAllServers: waiting for all servers to finish starting
2022-06-22T00:18:22.407Z MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method
2022-06-22T00:18:22.407Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method
2022-06-22T00:18:22.407Z MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false
2022-06-22T00:18:22.409Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 45375,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'ephemeralForTest',
    replSet: 'testset',
    dbPath: '/tmp/mongo-mem--5551-KzmAj1T97Zmz',
    tmpDir: {
      name: '/tmp/mongo-mem--5551-KzmAj1T97Zmz',
      removeCallback: [Function: _cleanupCallback]
    },
    args: [],
    auth: false
  },
  binary: {},
  spawn: {}
}
2022-06-22T00:18:22.409Z MongoMS:MongoInstance create: Called .create() method
2022-06-22T00:18:22.409Z MongoMS:MongoInstance Mongo[45375]: start
2022-06-22T00:18:22.409Z MongoMS:MongoBinary getPath
2022-06-22T00:18:22.409Z MongoMS:DryMongoBinary generateOptions
2022-06-22T00:18:22.410Z MongoMS:utils tryReleaseFile: "/etc/upstream-release/lsb-release" does not exist
2022-06-22T00:18:22.411Z MongoMS:getos getLinuxInformation: Using etcOsRelease
2022-06-22T00:18:22.411Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-22T00:18:22.411Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-22T00:18:22.412Z MongoMS:DryMongoBinary getBinaryName
2022-06-22T00:18:22.412Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.412Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.412Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.412Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: ''
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-22T00:18:22.413Z MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "5.0.8",
  "downloadDir": "/home/jakobo/.cache/mongodb-binaries",
  "os": {
    "os": "linux",
    "dist": "ubuntu",
    "codename": "focal",
    "release": "20.04",
    "id_like": [
      "debian"
    ]
  },
  "platform": "linux",
  "arch": "x64",
  "systemBinary": "",
  "checkMD5": false
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8"
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateOptions
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/home/jakobo/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary getBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8'
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary locateBinary: running generateDownloadPath
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/home/jakobo/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary getBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary combineBinaryName
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8'
}
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-22T00:18:22.413Z MongoMS:DryMongoBinary locateBinary: found binary at "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-22T00:18:22.413Z MongoMS:MongoBinary getPath: Mongod binary path: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-22T00:18:22.413Z MongoMS:MongoInstance Mongo[45375]: start: Starting Processes
2022-06-22T00:18:22.413Z MongoMS:MongoInstance Mongo[45375]: _launchMongod: Launching Mongod Process
2022-06-22T00:18:22.414Z MongoMS:MongoInstance Mongo[45375]: prepareCommandArgs
2022-06-22T00:18:22.414Z MongoMS:MongoInstance Mongo[45375]: prepareCommandArgs: final argument array:["--port","45375","--dbpath","/tmp/mongo-mem--5551-KzmAj1T97Zmz","--replSet","testset","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"]
2022-06-22T00:18:22.419Z MongoMS:MongoInstance Mongo[45375]: _launchKiller: Launching Killer Process (parent: 5551, child: 5569)
2022-06-22T00:18:22.432Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-22T00:18:22.432Z"},"s":"I",  "c":"CONTROL",  "id":5324701, "ctx":"-","msg":"Test storage engine does not support enableMajorityReadConcern=true, forcibly setting to false","attr":{"storageEngine":"ephemeralForTest"}}
{"t":{"$date":"2022-06-22T00:18:22.432Z"},"s":"W",  "c":"CONTROL",  "id":4788401, "ctx":"-","msg":"Lock-free reads is not compatible with enableMajorityReadConcern=false: disabling lock-free reads."}""
2022-06-22T00:18:22.434Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.434-07:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}""
2022-06-22T00:18:22.435Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.435-07:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}""
2022-06-22T00:18:22.435Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.435-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}""
2022-06-22T00:18:22.435Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.435-07:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}""
2022-06-22T00:18:22.437Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.436-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}""
2022-06-22T00:18:22.437Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.437-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}""
2022-06-22T00:18:22.437Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.437-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}""
2022-06-22T00:18:22.437Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.437-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}""
2022-06-22T00:18:22.437Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.437-07:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}""
2022-06-22T00:18:22.438Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.438-07:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":5569,"port":45375,"dbPath":"/tmp/mongo-mem--5551-KzmAj1T97Zmz","architecture":"64-bit","host":"Bismuth"}}
{"t":{"$date":"2022-06-21T17:18:22.438-07:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-06-21T17:18:22.438-07:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
{"t":{"$date":"2022-06-21T17:18:22.438-07:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":45375},"replication":{"replSet":"testset"},"security":{"authorization":"disabled"},"storage":{"dbPath":"/tmp/mongo-mem--5551-KzmAj1T97Zmz","engine":"ephemeralForTest"}}}}""
2022-06-22T00:18:22.443Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.443-07:00"},"s":"W",  "c":"CONTROL",  "id":22178,   "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]}
{"t":{"$date":"2022-06-21T17:18:22.443-07:00"},"s":"W",  "c":"CONTROL",  "id":22184,   "ctx":"initandlisten","msg":"Soft rlimits for open file descriptors too low","attr":{"currentValue":4096,"recommendedMinimum":64000},"tags":["startupWarnings"]}
{"t":{"$date":"2022-06-21T17:18:22.443-07:00"},"s":"I",  "c":"CONTROL",  "id":22197,   "ctx":"initandlisten","msg":"The ephemeralForTest storage engine is for testing only. Do not use in production","tags":["startupWarnings"]}""
2022-06-22T00:18:22.444Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.444-07:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
{"t":{"$date":"2022-06-21T17:18:22.444-07:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}""
2022-06-22T00:18:22.447Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.444-07:00"},"s":"I",  "c":"SHARDING", "id":20997,   "ctx":"initandlisten","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/tmp/mongo-mem--5551-KzmAj1T97Zmz/diagnostic.data"}}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"97ecede9-9dc4-4a11-97e2-e4180cd19eff"}},"options":{"capped":true,"size":10485760}}}
{"t":{"$date":"2022-06-21T17:18:22.445-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"REPL",     "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.oplogTruncateAfterPoint","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e5738410-313c-4325-b11b-12861ef9cd03"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.445-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.445-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.minvalid","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"96d78bc7-91cd-418e-8b14-2ad9536f0dc1"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.446-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.election","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3d5f82f1-9db7-4fa0-8f9d-459031992b2b"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.446-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":21311,   "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":21312,   "ctx":"initandlisten","msg":"Did not find local Rollback ID document at startup. Creating one"}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.rollback.id","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e6429dd6-3363-4589-a043-474222148ae3"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.446-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":21531,   "ctx":"initandlisten","msg":"Initialized the rollback ID","attr":{"rbid":1}}
{"t":{"$date":"2022-06-21T17:18:22.446-07: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"}}}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigUninitialized","oldState":"ConfigStartingUp"}}
{"t":{"$date":"2022-06-21T17:18:22.446-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.views","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c483ac47-e3ae-4d7a-b820-50107d64aef1"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.446-07: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}}""
2022-06-22T00:18:22.447Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.447-07: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"}}""
2022-06-22T00:18:22.448Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.448-07:00"},"s":"I",  "c":"REPL",     "id":40440,   "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}""
2022-06-22T00:18:22.448Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.448-07: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"}}""
2022-06-22T00:18:22.449Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.449-07:00"},"s":"I",  "c":"REPL",     "id":40445,   "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}""
2022-06-22T00:18:22.449Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.449-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-45375.sock"}}""
2022-06-22T00:18:22.449Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.449-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}""
2022-06-22T00:18:22.450Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.450-07:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":45375,"ssl":"off"}}""
2022-06-22T00:18:22.450Z MongoMS:MongoInstance Mongo[45375]: constructor: Instance is ready!
2022-06-22T00:18:22.450Z MongoMS:MongoInstance Mongo[45375]: start: Processes Started
2022-06-22T00:18:22.450Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Instance Started, createAuth: "false"
2022-06-22T00:18:22.450Z MongoMS:MongoMemoryServer Mongo[45375]: start: Instance fully Started
2022-06-22T00:18:22.450Z MongoMS:MongoMemoryReplSet initAllServers: finished starting all servers initially
2022-06-22T00:18:22.450Z MongoMS:MongoMemoryReplSet _initReplSet
2022-06-22T00:18:22.450Z MongoMS:MongoMemoryServer Mongo[45375]: getUri: running undefined undefined
2022-06-22T00:18:22.458Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.453-07:00"},"s":"I",  "c":"-",        "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"KeyNotFound: No keys found after refresh","nextWakeupMillis":200}}""
2022-06-22T00:18:22.465Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.458-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33512","uuid":"6377236f-cddf-42c4-8c85-940216621438","connectionId":1,"connectionCount":1}}
{"t":{"$date":"2022-06-21T17:18:22.465-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:33512","client":"conn1","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.472Z MongoMS:MongoMemoryReplSet _initReplSet: connected
2022-06-22T00:18:22.472Z MongoMS:MongoMemoryReplSet _initReplSet: trying "replSetInitiate"
2022-06-22T00:18:22.474Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.474-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33514","uuid":"ba8d18c5-48ed-4d3a-bebc-1a6b78036952","connectionId":2,"connectionCount":2}}""
2022-06-22T00:18:22.481Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.481-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn2","msg":"client metadata","attr":{"remote":"127.0.0.1:33514","client":"conn2","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.484Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.482-07:00"},"s":"I",  "c":"REPL",     "id":21356,   "ctx":"conn2","msg":"replSetInitiate admin command received from client"}
{"t":{"$date":"2022-06-21T17:18:22.482-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigInitiating","oldState":"ConfigUninitialized"}}
{"t":{"$date":"2022-06-21T17:18:22.482-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"48da9da3-c50d-413f-a988-c76d3abbe533"}},"options":{"uuid":{"$uuid":"48da9da3-c50d-413f-a988-c76d3abbe533"}}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":20459,   "ctx":"conn2","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"5.0"}}
{"t":{"$date":"2022-06-21T17:18:22.483-07: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}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"NETWORK",  "id":22991,   "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":2}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"NETWORK",  "id":22991,   "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":1}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21357,   "ctx":"conn2","msg":"replSetInitiate config object parses ok","attr":{"numMembers":1}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21251,   "ctx":"conn2","msg":"Creating replication oplog","attr":{"oplogSizeMB":398}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.oplog.rs","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"5b582c6e-cbc1-47f7-99d8-9b2c6652b074"}},"options":{"capped":true,"size":417333248,"autoIndexId":false}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.system.replset","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"a12f306e-9403-4381-adb0-f3a50a6cecb0"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn2","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.system.replset","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigInitiating"}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21392,   "ctx":"conn2","msg":"New replica set config in use","attr":{"config":{"_id":"testset","version":1,"term":0,"members":[{"_id":0,"host":"127.0.0.1:45375","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":false,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62b25fcef57202c85fbebd2f"}}}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21393,   "ctx":"conn2","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:45375"}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21306,   "ctx":"conn2","msg":"Starting replication storage threads"}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":4280512, "ctx":"conn2","msg":"No initial sync required. Attempting to begin steady replication"}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"5b730328-938f-455d-ab52-706a0eaacfa6"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.483-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.483-07:00"},"s":"I",  "c":"REPL",     "id":21299,   "ctx":"conn2","msg":"Starting replication fetcher thread"}
{"t":{"$date":"2022-06-21T17:18:22.484-07:00"},"s":"I",  "c":"REPL",     "id":21300,   "ctx":"conn2","msg":"Starting replication applier thread"}
{"t":{"$date":"2022-06-21T17:18:22.484-07:00"},"s":"I",  "c":"REPL",     "id":21301,   "ctx":"conn2","msg":"Starting replication reporter thread"}""
2022-06-22T00:18:22.484Z MongoMS:MongoMemoryReplSet _initReplSet: ReplSet-reconfig finished
2022-06-22T00:18:22.484Z MongoMS:MongoMemoryReplSet _waitForPrimary: Waiting for a Primary
2022-06-22T00:18:22.486Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.486-07:00"},"s":"I",  "c":"REPL",     "id":21224,   "ctx":"OplogApplier-0","msg":"Starting oplog application"}""
2022-06-22T00:18:22.487Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.487-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}
{"t":{"$date":"2022-06-21T17:18:22.487-07: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}}
{"t":{"$date":"2022-06-21T17:18:22.487-07: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}}""
2022-06-22T00:18:22.491Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"ELECTION", "id":21444,   "ctx":"ReplCoord-0","msg":"Dry election run succeeded, running for election","attr":{"newTerm":1}}""
2022-06-22T00:18:22.491Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.491-07: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}}}""
2022-06-22T00:18:22.491Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"ELECTION", "id":21450,   "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":1}}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21106,   "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21359,   "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":6015304, "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21363,   "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21107,   "ctx":"ReplCoord-0","msg":"Stopping replication producer"}""
2022-06-22T00:18:22.491Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.491-07:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":1}}""
2022-06-22T00:18:22.492Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.492-07:00"},"s":"I",  "c":"REPL",     "id":21343,   "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}""
2022-06-22T00:18:22.492Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.492-07:00"},"s":"I",  "c":"REPL",     "id":21344,   "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}""
2022-06-22T00:18:22.492Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.492-07:00"},"s":"I",  "c":"REPL",     "id":21340,   "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":0}}}""
2022-06-22T00:18:22.493Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.493-07:00"},"s":"I",  "c":"REPL",     "id":4508103, "ctx":"OplogApplier-0","msg":"Increment the config term via reconfig"}
{"t":{"$date":"2022-06-21T17:18:22.493-07:00"},"s":"I",  "c":"REPL",     "id":6015313, "ctx":"OplogApplier-0","msg":"Replication config state is Steady, starting reconfig"}""
2022-06-22T00:18:22.493Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.493-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigReconfiguring","oldState":"ConfigSteady"}}
{"t":{"$date":"2022-06-21T17:18:22.493-07:00"},"s":"I",  "c":"REPL",     "id":21353,   "ctx":"OplogApplier-0","msg":"replSetReconfig config object parses ok","attr":{"numMembers":1}}
{"t":{"$date":"2022-06-21T17:18:22.493-07:00"},"s":"I",  "c":"REPL",     "id":51814,   "ctx":"OplogApplier-0","msg":"Persisting new config to disk"}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":6015315, "ctx":"OplogApplier-0","msg":"Persisted new config to disk"}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigReconfiguring"}}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":21392,   "ctx":"OplogApplier-0","msg":"New replica set config in use","attr":{"config":{"_id":"testset","version":1,"term":1,"members":[{"_id":0,"host":"127.0.0.1:45375","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":false,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":500,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0},"replicaSetId":{"$oid":"62b25fcef57202c85fbebd2f"}}}}}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":21393,   "ctx":"OplogApplier-0","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:45375"}}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.transactions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"943764b8-69d1-49fe-80c2-002da630ffda"}},"options":{}}}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.transactions","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.image_collection","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"0147f3ec-cce4-4c7d-a0a3-67e7cc36ad53"}},"options":{}}}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.image_collection","index":"_id_","commitTimestamp":null}}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"STORAGE",  "id":20657,   "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}""
2022-06-22T00:18:22.494Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.system.indexBuilds","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3b0503e2-f095-491d-b196-f340c6864782"}},"options":{}}}""
2022-06-22T00:18:22.495Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"OplogApplier-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.indexBuilds","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.494-07:00"},"s":"I",  "c":"REPL",     "id":21331,   "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}
{"t":{"$date":"2022-06-21T17:18:22.495-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"f43513f8-0e95-43bc-a5ce-5ff8ed457958"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.495-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"monitoring-keys-for-HMAC","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.keys","index":"_id_","commitTimestamp":null}}""
2022-06-22T00:18:22.495Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: emitting "instancePrimary"
2022-06-22T00:18:22.495Z MongoMS:MongoMemoryReplSet _waitForPrimary: detected one primary instance
2022-06-22T00:18:22.495Z MongoMS:MongoMemoryReplSet _initReplSet: running
2022-06-22T00:18:22.497Z MongoMS:MongoMemoryReplSet waitUntilRunning: running
2022-06-22T00:18:22.497Z MongoMS:MongoMemoryReplSet getUri: running
2022-06-22T00:18:22.507Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.497-07:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:33514","uuid":"ba8d18c5-48ed-4d3a-bebc-1a6b78036952","connectionId":2,"connectionCount":1}}
{"t":{"$date":"2022-06-21T17:18:22.498-07:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:33512","uuid":"6377236f-cddf-42c4-8c85-940216621438","connectionId":1,"connectionCount":0}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d0606be4-4a0b-4bd4-8314-c3da573c2a1c"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"38d7d898-ed0d-4e14-adc1-eb1413a36732"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationDonorService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3c69ea18-b5c7-4c4e-8048-913efd7234c7"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.502-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.503-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.503-07:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationRecipientService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}}
{"t":{"$date":"2022-06-21T17:18:22.506-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33516","uuid":"a470931f-57cd-4f9e-a488-be41bd53df62","connectionId":3,"connectionCount":1}}""
2022-06-22T00:18:22.508Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.508-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:33516","client":"conn3","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.510Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.510-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33518","uuid":"44836949-1242-45ec-b2b1-d04d81cdb361","connectionId":4,"connectionCount":2}}
{"t":{"$date":"2022-06-21T17:18:22.510-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33520","uuid":"f693e08a-885d-4b02-bed5-940083eb175e","connectionId":5,"connectionCount":3}}""
2022-06-22T00:18:22.513Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.513-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:33518","client":"conn4","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.516Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.516-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:33520","client":"conn5","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.519Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.518-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.jobs/config","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"344a7772-5d79-4f85-9dac-bd3212bdd2fe"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.519-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs/config","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.519-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs/config","index":"version_-1","commitTimestamp":null}}""
2022-06-22T00:18:22.524Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.523-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.jobs","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"646d2b45-af1e-42d8-8f18-54f8a1f170dc"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.523-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.523-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs","index":"ref_1","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.524-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"f4c5daae-fb0e-4239-ba99-3ac330b2e89f"}},"namespace":"docqueue.jobs","collectionUUID":{"uuid":{"$uuid":"646d2b45-af1e-42d8-8f18-54f8a1f170dc"}},"indexes":1,"firstIndex":{"name":"ack_1"}}}
{"t":{"$date":"2022-06-21T17:18:22.524-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs","index":"ack_1","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.524-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"f4c5daae-fb0e-4239-ba99-3ac330b2e89f"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2022-06-21T17:18:22.524-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"f4c5daae-fb0e-4239-ba99-3ac330b2e89f"}}}}""
2022-06-22T00:18:22.528Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.526-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"90493450-b3e1-4e10-a952-7fa1a7fe760a"}},"namespace":"docqueue.jobs","collectionUUID":{"uuid":{"$uuid":"646d2b45-af1e-42d8-8f18-54f8a1f170dc"}},"indexes":1,"firstIndex":{"name":"deleted_1_visible_1"}}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs","index":"deleted_1_visible_1","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"90493450-b3e1-4e10-a952-7fa1a7fe760a"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"90493450-b3e1-4e10-a952-7fa1a7fe760a"}}}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.jobs/failed","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c336888b-8072-4ac5-a2ee-dfc00c7ab574"}},"options":{}}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs/failed","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.527-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs/failed","index":"ref_1","commitTimestamp":null}}""
2022-06-22T00:18:22.531Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.529-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"05fc41b0-80bc-4a83-bc32-355e224c4bd6"}},"namespace":"docqueue.jobs/failed","collectionUUID":{"uuid":{"$uuid":"c336888b-8072-4ac5-a2ee-dfc00c7ab574"}},"indexes":1,"firstIndex":{"name":"created_1"}}}
{"t":{"$date":"2022-06-21T17:18:22.529-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.jobs/failed","index":"created_1","commitTimestamp":null}}
{"t":{"$date":"2022-06-21T17:18:22.529-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"05fc41b0-80bc-4a83-bc32-355e224c4bd6"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2022-06-21T17:18:22.529-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"05fc41b0-80bc-4a83-bc32-355e224c4bd6"}}}}""
2022-06-22T00:18:22.552Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.550-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:33522","uuid":"46aad608-544b-43c9-a4b6-3ba780bfa0ac","connectionId":6,"connectionCount":4}}""
  ✔ Leverages a replica set oplog when available
2022-06-22T00:18:22.559Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.558-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn6","msg":"client metadata","attr":{"remote":"127.0.0.1:33522","client":"conn6","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-22T00:18:22.561Z MongoMS:MongoInstance Mongo[45375]: stdoutHandler: ""{"t":{"$date":"2022-06-21T17:18:22.561-07:00"},"s":"F",  "c":"-",        "id":23079,   "ctx":"conn6","msg":"Invariant failure","attr":{"expr":"readTs","file":"src/mongo/db/read_concern_mongod.cpp","line":529}}
{"t":{"$date":"2022-06-21T17:18:22.561-07:00"},"s":"F",  "c":"-",        "id":23080,   "ctx":"conn6","msg":"\n\n***aborting after invariant() failure\n\n"}
{"t":{"$date":"2022-06-21T17:18:22.561-07:00"},"s":"F",  "c":"CONTROL",  "id":4757800, "ctx":"conn6","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}""
2022-06-22T00:18:22.561Z MongoMS:MongoInstance Mongo[45375]: constructor: Instance has thrown an Error: Error: Mongod internal error
2022-06-22T00:18:22.561Z MongoMS:MongoInstance Mongo[45375]: stop
2022-06-22T00:18:22.561Z MongoMS:MongoInstance Mongo[45375]: stop: trying shutdownServer
  ─

  1 test passed

Do you know why it happenes?

I think it's because AVA runs its test suites in individual workers and there's a race condition between calling .stop() and ending the process (and triggering the associated killProcess). When I remove the stop call, the test stops being flaky. However, I'm not sure what would cause childProcess to come up as undefined.
@jakobo jakobo added the bug label Jun 22, 2022
@hasezoey
Copy link
Collaborator

hasezoey commented Jun 22, 2022 •
edited

your mongod process is failing:

***aborting after invariant() failure

where exactly are you getting this error message TypeError: Cannot read property 'pid' of undefined in relation to the logs? is it thrown somewhere inbetween lines or after the whole MMS log?

It appears that the isAlive check needs to verify it didn't get back an undefined value.

it seems like to be a race condition so i dont think it is AVA related, will look into this later

@jakobo
Copy link
Author

jakobo commented Jun 22, 2022

where exactly are you getting this error message

After the whole test suite completes, and it's flaky. I can get the error more consistently if I add a hook to AVA to try and stop the server on test complete instead of waiting for the process to end naturally.

test.afterEach(async (t) => {
  await t.context.rs.stop();
});

FWIW, my thoughts on the race condition are based on the fact we can arrive at killProcess several different ways.

@hasezoey
Copy link
Collaborator

FWIW, my thoughts on the race condition are based on the fact we can arrive at killProcess several different ways.

at least in the current code, there are only 2 places where killProcess is actually called, that is once for the instance itself and once for the killer-process (in case the main process dies), and at least from a types perspective is ensured to not be undefined / null

@hasezoey
Copy link
Collaborator

i can not see the actual cause on why mongodProcess is somehow undefined, so i just added a case for it in killProcess

fix will be in 8.7.1 (in some minutes)

@github-actions
Copy link

🎉 This issue has been resolved in version 8.7.1 🎉

The release is available on:

Your semantic-release bot 📦🚀

@github-actions github-actions bot added the released Pull Request released | Issue is fixed label Jun 22, 2022
@jakobo
Copy link
Author

jakobo commented Jun 23, 2022 •
edited

Can confirm this resolved the issue. Over 100 runs, no unhandled exceptions reported outside of the AVA tests.

edit: Also, no stray mongo processes either, so double win.

@hasezoey
Copy link
Collaborator

Can confirm this resolved the issue

good to hear, though personally i am still worried what this ***aborting after invariant() failure is about, because i have actually never seen that before, if you maybe have the time, could you provide a debug log output from the same run just with the 8.7.1 version?

@jakobo
Copy link
Author

jakobo commented Jun 23, 2022

Sure, here's the debug output from 8.7.1

Debug Output 
jakobo  docqueue   main  ~6   14.19.0  ♥ 16:08  MONGOMS_DEBUG=1 yarn ava test/oplog.spec.ts

2022-06-23T23:08:06.810Z MongoMS:ResolveConfig Debug Mode Enabled, through Environment Variable
2022-06-23T23:08:06.810Z MongoMS:ResolveConfig findPackageJson: Found package.json at "/home/jakobo/code/taskless/docqueue/package.json"
2022-06-23T23:08:06.811Z MongoMS:ResolveConfig Debug Mode Enabled, through package.json
2022-06-23T23:08:07.244Z MongoMS:MongoMemoryReplSet create: Called .create() method
2022-06-23T23:08:07.244Z MongoMS:MongoMemoryReplSet start: stopped
2022-06-23T23:08:07.245Z MongoMS:MongoMemoryReplSet initAllServers
2022-06-23T23:08:07.245Z MongoMS:MongoMemoryReplSet initAllServers: starting extra server "1" of "1" (count: 1)
2022-06-23T23:08:07.245Z MongoMS:MongoMemoryReplSet getInstanceOpts: instance opts: {
  auth: false,
  args: [],
  dbName: '',
  ip: '127.0.0.1',
  replSet: '5f874ba8-959c-45c8-9c34-7a118447e491',
  storageEngine: 'wiredTiger'
}
2022-06-23T23:08:07.246Z MongoMS:MongoMemoryReplSet initAllServers: waiting for all servers to finish starting
2022-06-23T23:08:07.246Z MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method
2022-06-23T23:08:07.246Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method
2022-06-23T23:08:07.246Z MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false
2022-06-23T23:08:07.248Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 43989,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'wiredTiger',
    replSet: '5f874ba8-959c-45c8-9c34-7a118447e491',
    dbPath: '/tmp/mongo-mem--9778-TtAGU5iV40AP',
    tmpDir: {
      name: '/tmp/mongo-mem--9778-TtAGU5iV40AP',
      removeCallback: [Function: _cleanupCallback]
    },
    args: [],
    auth: false
  },
  binary: {},
  spawn: {}
}
2022-06-23T23:08:07.248Z MongoMS:MongoInstance create: Called .create() method
2022-06-23T23:08:07.248Z MongoMS:MongoInstance Mongo[43989]: start
2022-06-23T23:08:07.248Z MongoMS:MongoBinary getPath
2022-06-23T23:08:07.248Z MongoMS:DryMongoBinary generateOptions
2022-06-23T23:08:07.249Z MongoMS:utils tryReleaseFile: "/etc/upstream-release/lsb-release" does not exist
2022-06-23T23:08:07.250Z MongoMS:getos getLinuxInformation: Using etcOsRelease
2022-06-23T23:08:07.250Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-23T23:08:07.250Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary getBinaryName
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: ''
}
2022-06-23T23:08:07.251Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.252Z MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "5.0.8",
  "downloadDir": "/home/jakobo/.cache/mongodb-binaries",
  "os": {
    "os": "linux",
    "dist": "ubuntu",
    "codename": "focal",
    "release": "20.04",
    "id_like": [
      "debian"
    ]
  },
  "platform": "linux",
  "arch": "x64",
  "systemBinary": "",
  "checkMD5": false
}
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8"
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateOptions
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/home/jakobo/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary getBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8'
}
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary locateBinary: running generateDownloadPath
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/home/jakobo/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary getBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8'
}
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.252Z MongoMS:DryMongoBinary locateBinary: found binary at "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.252Z MongoMS:MongoBinary getPath: Mongod binary path: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.252Z MongoMS:MongoInstance Mongo[43989]: start: Starting Processes
2022-06-23T23:08:07.252Z MongoMS:MongoInstance Mongo[43989]: _launchMongod: Launching Mongod Process
2022-06-23T23:08:07.253Z MongoMS:MongoInstance Mongo[43989]: prepareCommandArgs
2022-06-23T23:08:07.253Z MongoMS:MongoInstance Mongo[43989]: prepareCommandArgs: final argument array:["--port","43989","--dbpath","/tmp/mongo-mem--9778-TtAGU5iV40AP","--replSet","5f874ba8-959c-45c8-9c34-7a118447e491","--storageEngine","wiredTiger","--bind_ip","127.0.0.1","--noauth"]
2022-06-23T23:08:07.259Z MongoMS:MongoInstance Mongo[43989]: _launchKiller: Launching Killer Process (parent: 9778, child: 9790)
2022-06-23T23:08:07.274Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.268-07:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2022-06-23T16:08:07.269-07: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}}}
{"t":{"$date":"2022-06-23T16:08:07.270-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-06-23T16:08:07.270-07:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}""
2022-06-23T23:08:07.275Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.274-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-06-23T16:08:07.274-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-06-23T16:08:07.274-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
{"t":{"$date":"2022-06-23T16:08:07.274-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2022-06-23T16:08:07.274-07:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}""
2022-06-23T23:08:07.276Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.275-07:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":9790,"port":43989,"dbPath":"/tmp/mongo-mem--9778-TtAGU5iV40AP","architecture":"64-bit","host":"Bismuth"}}
{"t":{"$date":"2022-06-23T16:08:07.275-07:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-06-23T16:08:07.275-07:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
{"t":{"$date":"2022-06-23T16:08:07.275-07:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":43989},"replication":{"replSet":"5f874ba8-959c-45c8-9c34-7a118447e491"},"security":{"authorization":"disabled"},"storage":{"dbPath":"/tmp/mongo-mem--9778-TtAGU5iV40AP","engine":"wiredTiger"}}}}""
2022-06-23T23:08:07.281Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.277-07:00"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2022-06-23T16:08:07.277-07:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=3468M,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],"}}""
2022-06-23T23:08:07.395Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.394-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1656025687:394984][9790:0x7fc5264a9c80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
{"t":{"$date":"2022-06-23T16:08:07.395-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1656025687:395033][9790:0x7fc5264a9c80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}""
2022-06-23T23:08:07.401Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.400-07:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":123}}
{"t":{"$date":"2022-06-23T16:08:07.400-07:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}""
2022-06-23T23:08:07.417Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.417-07:00"},"s":"I",  "c":"STORAGE",  "id":4366408, "ctx":"initandlisten","msg":"No table logging settings modifications are required for existing WiredTiger tables","attr":{"loggingEnabled":false}}""
2022-06-23T23:08:07.418Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.418-07:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}""
2022-06-23T23:08:07.421Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.421-07:00"},"s":"W",  "c":"CONTROL",  "id":22178,   "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]}
{"t":{"$date":"2022-06-23T16:08:07.421-07:00"},"s":"W",  "c":"CONTROL",  "id":22184,   "ctx":"initandlisten","msg":"Soft rlimits for open file descriptors too low","attr":{"currentValue":4096,"recommendedMinimum":64000},"tags":["startupWarnings"]}""
2022-06-23T23:08:07.426Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.426-07:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
{"t":{"$date":"2022-06-23T16:08:07.426-07:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}""
2022-06-23T23:08:07.427Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.427-07:00"},"s":"I",  "c":"SHARDING", "id":20997,   "ctx":"initandlisten","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}
{"t":{"$date":"2022-06-23T16:08:07.427-07:00"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/tmp/mongo-mem--9778-TtAGU5iV40AP/diagnostic.data"}}
{"t":{"$date":"2022-06-23T16:08:07.427-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"dc6fbf2f-5c1d-4215-8f97-02c74e5ef3ba"}},"options":{"capped":true,"size":10485760}}}""
2022-06-23T23:08:07.439Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.439-07: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}}""
2022-06-23T23:08:07.440Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.440-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}""
2022-06-23T23:08:07.440Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.440-07:00"},"s":"I",  "c":"REPL",     "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}""
2022-06-23T23:08:07.441Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.441-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.oplogTruncateAfterPoint","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"30223cfa-5cb3-4ffc-adf1-9df76e0cbf97"}},"options":{}}}""
2022-06-23T23:08:07.449Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.449-07: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}}""
2022-06-23T23:08:07.450Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.450-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.minvalid","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"04896c7c-84cd-4654-8ec3-d644ed709b03"}},"options":{}}}""
2022-06-23T23:08:07.451Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.451-07: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}}""
2022-06-23T23:08:07.458Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.458-07: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}}""
2022-06-23T23:08:07.459Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.459-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.replset.election","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"97d411e2-1f75-44c3-af9c-8fdbca54c779"}},"options":{}}}""
2022-06-23T23:08:07.468Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.468-07: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}}""
2022-06-23T23:08:07.469Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.469-07:00"},"s":"I",  "c":"REPL",     "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"}""
2022-06-23T23:08:07.469Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.469-07:00"},"s":"I",  "c":"REPL",     "id":21311,   "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}""
2022-06-23T23:08:07.469Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.469-07:00"},"s":"I",  "c":"REPL",     "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}""
2022-06-23T23:08:07.469Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.469-07:00"},"s":"I",  "c":"REPL",     "id":21312,   "ctx":"initandlisten","msg":"Did not find local Rollback ID document at startup. Creating one"}""
2022-06-23T23:08:07.470Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.470-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.rollback.id","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"20aad71c-cbc5-4fb2-946b-5aa914519ea2"}},"options":{}}}""
2022-06-23T23:08:07.478Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.478-07: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}}""
2022-06-23T23:08:07.479Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.479-07:00"},"s":"I",  "c":"REPL",     "id":21531,   "ctx":"initandlisten","msg":"Initialized the rollback ID","attr":{"rbid":1}}""
2022-06-23T23:08:07.479Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.479-07: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"}}}""
2022-06-23T23:08:07.480Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.480-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigUninitialized","oldState":"ConfigStartingUp"}}""
2022-06-23T23:08:07.480Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.480-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.system.views","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"5459d490-b14c-440d-a554-fce9dac42b44"}},"options":{}}}""
2022-06-23T23:08:07.489Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.489-07: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}}""
2022-06-23T23:08:07.496Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.496-07: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"}}""
2022-06-23T23:08:07.497Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.496-07:00"},"s":"I",  "c":"REPL",     "id":40440,   "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}""
2022-06-23T23:08:07.497Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.497-07: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"}}""
2022-06-23T23:08:07.497Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.497-07:00"},"s":"I",  "c":"REPL",     "id":40445,   "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}""
2022-06-23T23:08:07.498Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.498-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-43989.sock"}}""
2022-06-23T23:08:07.498Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.498-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}""
2022-06-23T23:08:07.498Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.498-07:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":43989,"ssl":"off"}}""
2022-06-23T23:08:07.498Z MongoMS:MongoInstance Mongo[43989]: constructor: Instance is ready!
2022-06-23T23:08:07.498Z MongoMS:MongoInstance Mongo[43989]: start: Processes Started
2022-06-23T23:08:07.498Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Instance Started, createAuth: "false"
2022-06-23T23:08:07.498Z MongoMS:MongoMemoryServer Mongo[43989]: start: Instance fully Started
2022-06-23T23:08:07.498Z MongoMS:MongoMemoryReplSet initAllServers: finished starting all servers initially
2022-06-23T23:08:07.499Z MongoMS:MongoMemoryReplSet _initReplSet
2022-06-23T23:08:07.499Z MongoMS:MongoMemoryServer Mongo[43989]: getUri: running undefined undefined
2022-06-23T23:08:07.514Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.514-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46206","uuid":"e5f6b43b-f815-42a7-94a4-7b150a693002","connectionId":1,"connectionCount":1}}""
2022-06-23T23:08:07.526Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.525-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:46206","client":"conn1","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.532Z MongoMS:MongoMemoryReplSet _initReplSet: connected
2022-06-23T23:08:07.533Z MongoMS:MongoMemoryReplSet _initReplSet: trying "replSetInitiate"
2022-06-23T23:08:07.535Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.534-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46208","uuid":"d3b6f3f5-b8cd-4fc1-9fc3-27efc2afe6b7","connectionId":2,"connectionCount":2}}""
2022-06-23T23:08:07.542Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.541-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn2","msg":"client metadata","attr":{"remote":"127.0.0.1:46208","client":"conn2","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.543Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.543-07:00"},"s":"I",  "c":"REPL",     "id":21356,   "ctx":"conn2","msg":"replSetInitiate admin command received from client"}
{"t":{"$date":"2022-06-23T16:08:07.543-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigInitiating","oldState":"ConfigUninitialized"}}
{"t":{"$date":"2022-06-23T16:08:07.543-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"0b4d014e-05bb-40e6-a5bb-8c04a1fe0e45"}},"options":{"uuid":{"$uuid":"0b4d014e-05bb-40e6-a5bb-8c04a1fe0e45"}}}}""
2022-06-23T23:08:07.554Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.553-07: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}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"REPL",     "id":20459,   "ctx":"conn2","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"5.0"}}
{"t":{"$date":"2022-06-23T16:08:07.553-07: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}}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"NETWORK",  "id":22991,   "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":2}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"NETWORK",  "id":22991,   "ctx":"conn2","msg":"Skip closing connection for connection","attr":{"connectionId":1}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"REPL",     "id":21357,   "ctx":"conn2","msg":"replSetInitiate config object parses ok","attr":{"numMembers":1}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"REPL",     "id":21251,   "ctx":"conn2","msg":"Creating replication oplog","attr":{"oplogSizeMB":8624}}
{"t":{"$date":"2022-06-23T16:08:07.553-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.oplog.rs","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e4431624-c0b4-4421-9bd0-0ca625de023a"}},"options":{"capped":true,"size":9042963046,"autoIndexId":false}}}""
2022-06-23T23:08:07.559Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.558-07:00"},"s":"I",  "c":"STORAGE",  "id":22383,   "ctx":"conn2","msg":"The size storer reports that the oplog contains","attr":{"numRecords":0,"dataSize":0}}
{"t":{"$date":"2022-06-23T16:08:07.558-07:00"},"s":"I",  "c":"STORAGE",  "id":22382,   "ctx":"conn2","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}""
2022-06-23T23:08:07.561Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.561-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1656025687:561796][9790:0x7fc50e377700], 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"}}""
2022-06-23T23:08:07.583Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.583-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.system.replset","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"a4c8ebea-05ac-456f-a3a0-cac349df7f3e"}},"options":{}}}""
2022-06-23T23:08:07.591Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.591-07: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":1656025687,"i":1}}}}""
2022-06-23T23:08:07.592Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.592-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1656025687:592833][9790:0x7fc50e377700], 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"}}""
2022-06-23T23:08:07.604Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.604-07:00"},"s":"I",  "c":"REPL",     "id":5872101, "ctx":"conn2","msg":"Taking a stable checkpoint for replSetInitiate"}
{"t":{"$date":"2022-06-23T16:08:07.604-07:00"},"s":"I",  "c":"REPL",     "id":5872100, "ctx":"conn2","msg":"Updating commit point for initiate","attr":{"_lastCommittedOpTimeAndWallTime":"{ ts: Timestamp(1656025687, 1), t: -1 }, 2022-06-23T16:08:07.591-07:00"}}""
2022-06-23T23:08:07.604Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.604-07:00"},"s":"I",  "c":"STORAGE",  "id":22310,   "ctx":"conn2","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1656025687,"i":1}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1656025687,"i":1}}}}""
2022-06-23T23:08:07.604Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.604-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":"[1656025687:604756][9790:0x7fc51dc97700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 79, snapshot max: 79 snapshot count: 0, oldest timestamp: (1656025687, 1) , meta checkpoint timestamp: (1656025687, 1) base write gen: 1"}}""
2022-06-23T23:08:07.609Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.609-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"conn2","msg":"WiredTiger message","attr":{"message":"[1656025687:609294][9790:0x7fc50e377700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 81, snapshot max: 81 snapshot count: 0, oldest timestamp: (1656025687, 1) , meta checkpoint timestamp: (1656025687, 1) base write gen: 1"}}""
2022-06-23T23:08:07.612Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.612-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"conn2","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigInitiating"}}""
2022-06-23T23:08:07.613Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.612-07:00"},"s":"I",  "c":"REPL",     "id":21392,   "ctx":"conn2","msg":"New replica set config in use","attr":{"config":{"_id":"5f874ba8-959c-45c8-9c34-7a118447e491","version":1,"term":0,"members":[{"_id":0,"host":"127.0.0.1:43989","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":"62b4f2571da9600a47090b61"}}}}}""
2022-06-23T23:08:07.613Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.613-07:00"},"s":"I",  "c":"REPL",     "id":21393,   "ctx":"conn2","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:43989"}}""
2022-06-23T23:08:07.613Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.613-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}""
2022-06-23T23:08:07.613Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.613-07:00"},"s":"I",  "c":"REPL",     "id":21306,   "ctx":"conn2","msg":"Starting replication storage threads"}""
2022-06-23T23:08:07.614Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.614-07:00"},"s":"I",  "c":"REPL",     "id":4280512, "ctx":"conn2","msg":"No initial sync required. Attempting to begin steady replication"}
{"t":{"$date":"2022-06-23T16:08:07.614-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"conn2","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}}""
2022-06-23T23:08:07.614Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.614-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn2","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c78cb802-272c-4ab6-8b3b-dac650600259"}},"options":{}}}""
2022-06-23T23:08:07.622Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.622-07: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}}""
2022-06-23T23:08:07.623Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"REPL",     "id":21299,   "ctx":"conn2","msg":"Starting replication fetcher thread"}""
2022-06-23T23:08:07.623Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"REPL",     "id":21300,   "ctx":"conn2","msg":"Starting replication applier thread"}
{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"REPL",     "id":21301,   "ctx":"conn2","msg":"Starting replication reporter thread"}
{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"REPL",     "id":21224,   "ctx":"OplogApplier-0","msg":"Starting oplog application"}
{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}
{"t":{"$date":"2022-06-23T16:08:07.623-07: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}}
{"t":{"$date":"2022-06-23T16:08:07.623-07: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}}
{"t":{"$date":"2022-06-23T16:08:07.623-07:00"},"s":"I",  "c":"ELECTION", "id":21444,   "ctx":"ReplCoord-0","msg":"Dry election run succeeded, running for election","attr":{"newTerm":1}}
{"t":{"$date":"2022-06-23T16:08:07.623-07: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}}}""
2022-06-23T23:08:07.624Z MongoMS:MongoMemoryReplSet _initReplSet: ReplSet-reconfig finished
2022-06-23T23:08:07.625Z MongoMS:MongoMemoryReplSet _waitForPrimary: Waiting for a Primary
2022-06-23T23:08:07.625Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"ELECTION", "id":21450,   "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":1}}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21106,   "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21359,   "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":6015304, "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21363,   "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21107,   "ctx":"ReplCoord-0","msg":"Stopping replication producer"}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":1}}
{"t":{"$date":"2022-06-23T16:08:07.624-07:00"},"s":"I",  "c":"REPL",     "id":21343,   "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":21344,   "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":21340,   "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":0}}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":4508103, "ctx":"OplogApplier-0","msg":"Increment the config term via reconfig"}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":6015313, "ctx":"OplogApplier-0","msg":"Replication config state is Steady, starting reconfig"}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigReconfiguring","oldState":"ConfigSteady"}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":21353,   "ctx":"OplogApplier-0","msg":"replSetReconfig config object parses ok","attr":{"numMembers":1}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":51814,   "ctx":"OplogApplier-0","msg":"Persisting new config to disk"}""
2022-06-23T23:08:07.625Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":6015315, "ctx":"OplogApplier-0","msg":"Persisted new config to disk"}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"OplogApplier-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigReconfiguring"}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":21392,   "ctx":"OplogApplier-0","msg":"New replica set config in use","attr":{"config":{"_id":"5f874ba8-959c-45c8-9c34-7a118447e491","version":1,"term":1,"members":[{"_id":0,"host":"127.0.0.1:43989","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":"62b4f2571da9600a47090b61"}}}}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":21393,   "ctx":"OplogApplier-0","msg":"Found self in config","attr":{"hostAndPort":"127.0.0.1:43989"}}
{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"REPL",     "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}""
2022-06-23T23:08:07.626Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.625-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.transactions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"0890ac08-c63e-458c-b5c2-ee35f1b0b996"}},"options":{}}}""
2022-06-23T23:08:07.633Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.633-07: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":1656025687,"i":3}}}}""
2022-06-23T23:08:07.633Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.633-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.image_collection","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"413c2fc1-2b69-4563-82b9-1a53c30247fb"}},"options":{}}}""
2022-06-23T23:08:07.642Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.642-07: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":1656025687,"i":4}}}}""
2022-06-23T23:08:07.642Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.642-07:00"},"s":"I",  "c":"REPL",     "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}""
2022-06-23T23:08:07.643Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.642-07:00"},"s":"I",  "c":"STORAGE",  "id":20657,   "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}
{"t":{"$date":"2022-06-23T16:08:07.642-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"OplogApplier-0","msg":"createCollection","attr":{"namespace":"config.system.indexBuilds","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"8662b6ad-a0a8-4d60-9eb1-692506c6ab19"}},"options":{}}}""
2022-06-23T23:08:07.650Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.650-07: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":1656025687,"i":6}}}}""
2022-06-23T23:08:07.651Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.651-07:00"},"s":"I",  "c":"REPL",     "id":21331,   "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}""
2022-06-23T23:08:07.651Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: emitting "instancePrimary"
2022-06-23T23:08:07.651Z MongoMS:MongoMemoryReplSet _waitForPrimary: detected one primary instance
2022-06-23T23:08:07.651Z MongoMS:MongoMemoryReplSet _initReplSet: running
2022-06-23T23:08:07.653Z MongoMS:MongoMemoryReplSet getUri: running
2022-06-23T23:08:07.657Z MongoMS:MongoMemoryServer create: Called .create() method
2022-06-23T23:08:07.657Z MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method
2022-06-23T23:08:07.657Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method
2022-06-23T23:08:07.657Z MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false
2022-06-23T23:08:07.658Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 42955,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'wiredTiger',
    replSet: undefined,
    dbPath: '/tmp/mongo-mem--9778-28B1kFzZP4pw',
    tmpDir: {
      name: '/tmp/mongo-mem--9778-28B1kFzZP4pw',
      removeCallback: [Function: _cleanupCallback]
    },
    args: undefined,
    auth: undefined
  },
  binary: undefined,
  spawn: undefined
}
2022-06-23T23:08:07.658Z MongoMS:MongoInstance create: Called .create() method
2022-06-23T23:08:07.658Z MongoMS:MongoInstance Mongo[42955]: start
2022-06-23T23:08:07.658Z MongoMS:MongoBinary getPath
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary generateOptions
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary getBinaryName
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.658Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: ''
}
2022-06-23T23:08:07.660Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.652-07:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:46206","uuid":"e5f6b43b-f815-42a7-94a4-7b150a693002","connectionId":1,"connectionCount":1}}
{"t":{"$date":"2022-06-23T16:08:07.656-07:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:46208","uuid":"d3b6f3f5-b8cd-4fc1-9fc3-27efc2afe6b7","connectionId":2,"connectionCount":0}}
{"t":{"$date":"2022-06-23T16:08:07.656-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"d3f88209-5aea-48f2-877c-69fc986217d3"}},"options":{}}}
{"t":{"$date":"2022-06-23T16:08:07.657-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46210","uuid":"89a30d4d-b9fb-4d33-ae69-c1d59697a8cd","connectionId":3,"connectionCount":1}}
{"t":{"$date":"2022-06-23T16:08:07.658-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"1cb68ff1-cb59-49fc-af85-7f4e9c5f322c"}},"options":{}}}
{"t":{"$date":"2022-06-23T16:08:07.658-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"2b202efa-baf1-48f8-aa9e-e415f4e7a090"}},"options":{}}}""
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.661Z MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "5.0.8",
  "downloadDir": "/home/jakobo/.cache/mongodb-binaries",
  "os": {
    "os": "linux",
    "dist": "ubuntu",
    "codename": "focal",
    "release": "20.04",
    "id_like": [
      "debian"
    ]
  },
  "platform": "linux",
  "arch": "x64",
  "systemBinary": "",
  "checkMD5": false
}
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8"
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary generateOptions
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/home/jakobo/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'ubuntu',
    codename: 'focal',
    release: '20.04',
    id_like: [ 'debian' ]
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-06-23T23:08:07.661Z MongoMS:DryMongoBinary getBinaryName
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary combineBinaryName
2022-06-23T23:08:07.662Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  modulesCache: '/home/jakobo/code/taskless/docqueue/node_modules/.cache/mongodb-memory-server/mongod-x64-ubuntu-5.0.8',
  relative: '/home/jakobo/code/taskless/docqueue/mongodb-binaries/mongod-x64-ubuntu-5.0.8',
  resolveConfig: '/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8'
}
2022-06-23T23:08:07.662Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.661-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:46210","client":"conn3","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.664Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.664Z MongoMS:DryMongoBinary locateBinary: Requested Version found in cache: "[5.0.8, /home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8]"
2022-06-23T23:08:07.664Z MongoMS:MongoBinary getPath: Mongod binary path: "/home/jakobo/.cache/mongodb-binaries/mongod-x64-ubuntu-5.0.8"
2022-06-23T23:08:07.664Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.664-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46212","uuid":"7f5f4062-6656-4e10-9aa7-ac45bea162c3","connectionId":4,"connectionCount":2}}""
2022-06-23T23:08:07.664Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.664-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46214","uuid":"ada094f1-75cc-4198-9cf6-465df9e43df2","connectionId":5,"connectionCount":3}}""
2022-06-23T23:08:07.664Z MongoMS:MongoInstance Mongo[42955]: start: Starting Processes
2022-06-23T23:08:07.664Z MongoMS:MongoInstance Mongo[42955]: _launchMongod: Launching Mongod Process
2022-06-23T23:08:07.664Z MongoMS:MongoInstance Mongo[42955]: prepareCommandArgs
2022-06-23T23:08:07.665Z MongoMS:MongoInstance Mongo[42955]: prepareCommandArgs: final argument array:["--port","42955","--dbpath","/tmp/mongo-mem--9778-28B1kFzZP4pw","--storageEngine","wiredTiger","--bind_ip","127.0.0.1","--noauth"]
2022-06-23T23:08:07.669Z MongoMS:MongoInstance Mongo[42955]: _launchKiller: Launching Killer Process (parent: 9778, child: 9873)
2022-06-23T23:08:07.684Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.665-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:46212","client":"conn4","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}
{"t":{"$date":"2022-06-23T16:08:07.665-07: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":1656025687,"i":7}}}}
{"t":{"$date":"2022-06-23T16:08:07.667-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:46214","client":"conn5","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}
{"t":{"$date":"2022-06-23T16:08:07.680-07: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":1656025687,"i":11}}}}
{"t":{"$date":"2022-06-23T16:08:07.680-07: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":1656025687,"i":11}}}}
{"t":{"$date":"2022-06-23T16:08:07.680-07:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationRecipientService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}}""
2022-06-23T23:08:07.686Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.680-07:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2022-06-23T16:08:07.680-07:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2022-06-23T16:08:07.685-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-06-23T16:08:07.686-07:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}""
2022-06-23T23:08:07.686Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.686-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/config","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"9f76625c-3f3b-4d4c-9a64-7f9d5d16e5d4"}},"options":{}}}""
2022-06-23T23:08:07.688Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":9873,"port":42955,"dbPath":"/tmp/mongo-mem--9778-28B1kFzZP4pw","architecture":"64-bit","host":"Bismuth"}}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.8","gitVersion":"c87e1c23421bf79614baf500fda6622bd90f674e","openSSLVersion":"OpenSSL 1.1.1f  31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
{"t":{"$date":"2022-06-23T16:08:07.687-07:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"127.0.0.1","port":42955},"security":{"authorization":"disabled"},"storage":{"dbPath":"/tmp/mongo-mem--9778-28B1kFzZP4pw","engine":"wiredTiger"}}}}
{"t":{"$date":"2022-06-23T16:08:07.688-07:00"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2022-06-23T16:08:07.688-07:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=3468M,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],"}}""
2022-06-23T23:08:07.717Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.717-07: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":1656025687,"i":13}}}}
{"t":{"$date":"2022-06-23T16:08:07.717-07: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":1656025687,"i":13}}}}
{"t":{"$date":"2022-06-23T16:08:07.717-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"b4860d41-078d-4f4e-9b93-13c68cbef2d7"}},"options":{}}}""
2022-06-23T23:08:07.728Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.728-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/config","index":"_id_","commitTimestamp":{"$timestamp":{"t":1656025687,"i":16}}}}""
2022-06-23T23:08:07.729Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.729-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/config","index":"version_-1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":16}}}}""
2022-06-23T23:08:07.752Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.751-07: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":1656025687,"i":17}}}}
{"t":{"$date":"2022-06-23T16:08:07.751-07: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":1656025687,"i":17}}}}
{"t":{"$date":"2022-06-23T16:08:07.751-07:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationDonorService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}""
2022-06-23T23:08:07.756Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.756-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"8d6a3aa8-4a6a-43e2-907b-96ca989b113a"}},"options":{}}}""
2022-06-23T23:08:07.775Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.775-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","index":"_id_","commitTimestamp":{"$timestamp":{"t":1656025687,"i":19}}}}""
2022-06-23T23:08:07.776Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.776-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","index":"ref_1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":19}}}}""
2022-06-23T23:08:07.780Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.780-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"3afedc42-128d-4708-8395-2dedf2ac6236"}},"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","collectionUUID":{"uuid":{"$uuid":"8d6a3aa8-4a6a-43e2-907b-96ca989b113a"}},"indexes":1,"firstIndex":{"name":"ack_1"}}}""
2022-06-23T23:08:07.789Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.789-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","index":"ack_1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":20}}}}
{"t":{"$date":"2022-06-23T16:08:07.789-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"3afedc42-128d-4708-8395-2dedf2ac6236"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2022-06-23T16:08:07.789-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"3afedc42-128d-4708-8395-2dedf2ac6236"}}}}""
2022-06-23T23:08:07.791Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.791-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"4ebe2d86-ad8f-4857-9915-ce1ba423d32c"}},"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","collectionUUID":{"uuid":{"$uuid":"8d6a3aa8-4a6a-43e2-907b-96ca989b113a"}},"indexes":1,"firstIndex":{"name":"deleted_1__id_1_visible_1"}}}""
2022-06-23T23:08:07.801Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.801-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325","index":"deleted_1__id_1_visible_1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":21}}}}
{"t":{"$date":"2022-06-23T16:08:07.801-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"4ebe2d86-ad8f-4857-9915-ce1ba423d32c"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2022-06-23T16:08:07.801-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"4ebe2d86-ad8f-4857-9915-ce1ba423d32c"}}}}""
2022-06-23T23:08:07.807Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.806-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn5","msg":"createCollection","attr":{"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/failed","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"9a791329-a402-481a-a42c-9a72c5cba5cc"}},"options":{}}}""
2022-06-23T23:08:07.819Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.819-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/failed","index":"_id_","commitTimestamp":{"$timestamp":{"t":1656025687,"i":23}}}}""
2022-06-23T23:08:07.819Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.819-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/failed","index":"ref_1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":23}}}}""
2022-06-23T23:08:07.821Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.821-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn5","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"d6e21211-d324-4438-bbec-5bda030784e9"}},"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/failed","collectionUUID":{"uuid":{"$uuid":"9a791329-a402-481a-a42c-9a72c5cba5cc"}},"indexes":1,"firstIndex":{"name":"created_1"}}}""
2022-06-23T23:08:07.825Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.825-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn5","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.5a1dd4d5-5327-4136-bda9-423a81931325/failed","index":"created_1","commitTimestamp":{"$timestamp":{"t":1656025687,"i":24}}}}""
2022-06-23T23:08:07.826Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.826-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn5","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"d6e21211-d324-4438-bbec-5bda030784e9"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}""
2022-06-23T23:08:07.826Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.826-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn5","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"d6e21211-d324-4438-bbec-5bda030784e9"}}}}""
2022-06-23T23:08:07.849Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.848-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:46216","uuid":"3a214f6b-0415-4e99-9481-07fc42a5e98e","connectionId":6,"connectionCount":4}}""
2022-06-23T23:08:07.857Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.853-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1656025687:853583][9873:0x7f4741571c80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
{"t":{"$date":"2022-06-23T16:08:07.853-07:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1656025687:853623][9873:0x7f4741571c80], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}""
2022-06-23T23:08:07.863Z MongoMS:MongoInstance Mongo[43989]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.855-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn6","msg":"client metadata","attr":{"remote":"127.0.0.1:46216","client":"conn6","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
  ✔ Leverages the oplog to minimize polling (212ms)
2022-06-23T23:08:07.868Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.864-07:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":176}}
{"t":{"$date":"2022-06-23T16:08:07.864-07:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}""
2022-06-23T23:08:07.878Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.878-07:00"},"s":"I",  "c":"STORAGE",  "id":4366408, "ctx":"initandlisten","msg":"No table logging settings modifications are required for existing WiredTiger tables","attr":{"loggingEnabled":true}}
{"t":{"$date":"2022-06-23T16:08:07.878-07:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}""
2022-06-23T23:08:07.884Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.884-07:00"},"s":"W",  "c":"CONTROL",  "id":22178,   "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]}
{"t":{"$date":"2022-06-23T16:08:07.884-07:00"},"s":"W",  "c":"CONTROL",  "id":22184,   "ctx":"initandlisten","msg":"Soft rlimits for open file descriptors too low","attr":{"currentValue":4096,"recommendedMinimum":64000},"tags":["startupWarnings"]}""
2022-06-23T23:08:07.885Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.885-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"bbe5f839-78ec-4394-a58f-6ec47c050cda"}},"options":{"uuid":{"$uuid":"bbe5f839-78ec-4394-a58f-6ec47c050cda"}}}}""
2022-06-23T23:08:07.893Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.892-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.version","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-23T16:08:07.892-07:00"},"s":"I",  "c":"REPL",     "id":20459,   "ctx":"initandlisten","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"5.0"}}
{"t":{"$date":"2022-06-23T16:08:07.892-07:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","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}}}
{"t":{"$date":"2022-06-23T16:08:07.893-07:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2022-06-23T16:08:07.893-07:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
{"t":{"$date":"2022-06-23T16:08:07.893-07:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}""
2022-06-23T23:08:07.894Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.894-07:00"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/tmp/mongo-mem--9778-28B1kFzZP4pw/diagnostic.data"}}
{"t":{"$date":"2022-06-23T16:08:07.894-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"a908a678-7475-44a4-9f18-363c31a85e00"}},"options":{"capped":true,"size":10485760}}}""
2022-06-23T23:08:07.905Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.905-07: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}}""
2022-06-23T23:08:07.906Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.906-07:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled","oldState":"ConfigPreStart"}}""
2022-06-23T23:08:07.911Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.911-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"LogicalSessionCacheRefresh","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"a7bede9b-7afa-4da5-b07b-f81b2468c9bb"}},"options":{}}}""
2022-06-23T23:08:07.911Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.911-07: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"}}""
2022-06-23T23:08:07.912Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.912-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-42955.sock"}}
{"t":{"$date":"2022-06-23T16:08:07.912-07:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
{"t":{"$date":"2022-06-23T16:08:07.912-07:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":42955,"ssl":"off"}}""
2022-06-23T23:08:07.912Z MongoMS:MongoInstance Mongo[42955]: constructor: Instance is ready!
2022-06-23T23:08:07.912Z MongoMS:MongoInstance Mongo[42955]: start: Processes Started
2022-06-23T23:08:07.912Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Instance Started, createAuth: "false"
2022-06-23T23:08:07.912Z MongoMS:MongoMemoryServer Mongo[42955]: start: Instance fully Started
2022-06-23T23:08:07.912Z MongoMS:MongoMemoryServer Mongo[42955]: getUri: running undefined undefined
2022-06-23T23:08:07.914Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.914-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:49818","uuid":"27a971de-e22d-441e-96fe-e97c2f503543","connectionId":1,"connectionCount":1}}""
2022-06-23T23:08:07.915Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.915-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:49818","client":"conn1","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.917Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.916-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:49820","uuid":"7e478a64-efad-4d68-a106-db69bd0870f9","connectionId":2,"connectionCount":2}}
{"t":{"$date":"2022-06-23T16:08:07.917-07:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:49822","uuid":"269532f0-3560-4878-920b-8f68b964ac53","connectionId":3,"connectionCount":3}}""
2022-06-23T23:08:07.917Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.917-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn2","msg":"client metadata","attr":{"remote":"127.0.0.1:49820","client":"conn2","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.918Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.918-07:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:49822","client":"conn3","doc":{"driver":{"name":"nodejs","version":"4.7.0"},"os":{"type":"Linux","name":"linux","architecture":"x64","version":"4.19.128-microsoft-standard"},"platform":"Node.js v14.19.0, LE (unified)|Node.js v14.19.0, LE (unified)"}}}""
2022-06-23T23:08:07.919Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.919-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn3","msg":"createCollection","attr":{"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/config","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e4ef2265-3541-4997-9ce8-73a2f4333b46"}},"options":{}}}""
2022-06-23T23:08:07.932Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.932-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2022-06-23T16:08:07.932-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"lsidTTLIndex","commitTimestamp":null}}""
2022-06-23T23:08:07.944Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.944-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/config","index":"_id_","commitTimestamp":null}}""
2022-06-23T23:08:07.945Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.945-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/config","index":"version_-1","commitTimestamp":null}}""
2022-06-23T23:08:07.946Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.946-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn3","msg":"createCollection","attr":{"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"708fe771-6498-4018-a287-d3023ddc6004"}},"options":{}}}""
2022-06-23T23:08:07.965Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.965-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","index":"_id_","commitTimestamp":null}}""
2022-06-23T23:08:07.965Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.965-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","index":"ref_1","commitTimestamp":null}}""
2022-06-23T23:08:07.966Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.966-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn3","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"c1b7d2d6-dc66-4f09-b453-4649bebfc83b"}},"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","collectionUUID":{"uuid":{"$uuid":"708fe771-6498-4018-a287-d3023ddc6004"}},"indexes":1,"firstIndex":{"name":"ack_1"}}}""
2022-06-23T23:08:07.972Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.972-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","index":"ack_1","commitTimestamp":null}}""
2022-06-23T23:08:07.972Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.972-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn3","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"c1b7d2d6-dc66-4f09-b453-4649bebfc83b"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}""
2022-06-23T23:08:07.972Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.972-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn3","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"c1b7d2d6-dc66-4f09-b453-4649bebfc83b"}}}}""
2022-06-23T23:08:07.973Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.973-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn3","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"87b64502-7610-4c3d-b4cf-c0e0cac0b786"}},"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","collectionUUID":{"uuid":{"$uuid":"708fe771-6498-4018-a287-d3023ddc6004"}},"indexes":1,"firstIndex":{"name":"deleted_1__id_1_visible_1"}}}""
2022-06-23T23:08:07.985Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.985-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d","index":"deleted_1__id_1_visible_1","commitTimestamp":null}}""
2022-06-23T23:08:07.985Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.985-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn3","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"87b64502-7610-4c3d-b4cf-c0e0cac0b786"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}""
2022-06-23T23:08:07.985Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.985-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn3","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"87b64502-7610-4c3d-b4cf-c0e0cac0b786"}}}}""
2022-06-23T23:08:07.986Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:07.986-07:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"conn3","msg":"createCollection","attr":{"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/failed","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"acafd74d-5811-4738-805f-697e767ae79d"}},"options":{}}}""
2022-06-23T23:08:08.017Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.017-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/failed","index":"_id_","commitTimestamp":null}}""
2022-06-23T23:08:08.017Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.017-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/failed","index":"ref_1","commitTimestamp":null}}""
2022-06-23T23:08:08.018Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.018-07:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"conn3","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"886365a6-b861-42eb-b102-da0a6f016ca7"}},"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/failed","collectionUUID":{"uuid":{"$uuid":"acafd74d-5811-4738-805f-697e767ae79d"}},"indexes":1,"firstIndex":{"name":"created_1"}}}""
2022-06-23T23:08:08.024Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.024-07:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"conn3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"docqueue.f3e01699-44d0-4f74-b088-c4fc3b4a796d/failed","index":"created_1","commitTimestamp":null}}""
2022-06-23T23:08:08.025Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.025-07:00"},"s":"I",  "c":"INDEX",    "id":20440,   "ctx":"conn3","msg":"Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"886365a6-b861-42eb-b102-da0a6f016ca7"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}""
2022-06-23T23:08:08.025Z MongoMS:MongoInstance Mongo[42955]: stdoutHandler: ""{"t":{"$date":"2022-06-23T16:08:08.025-07:00"},"s":"I",  "c":"INDEX",    "id":20447,   "ctx":"conn3","msg":"Index build: completed","attr":{"buildUUID":{"uuid":{"$uuid":"886365a6-b861-42eb-b102-da0a6f016ca7"}}}}""
  ✔ Won't run without a replica set (370ms)
  ─

  2 tests passed

@hasezoey
Copy link
Collaborator

Sure, here's the debug output from 8.7.1

thanks, from what i can tell in that log, it seems like first a ReplSet is started, but never stopped and inbetween a normal Instance is started and also never stopped, also .stop does not even seem to be called at all (not just not being able to kill it)

@jakobo
Copy link
Author

jakobo commented Jun 24, 2022

The tests are now also published @ https://github.com/jakobo/docmq/blob/59650157a5ee95ce5c336874fa3c9c6764ec77bf/test/oplog.spec.ts. I ended up removing the .stop() call completely, instead letting AVA trigger all the cleanup. I also took advice from another thread to use .before() instead of .beforeEach() w/ custom collection names in order to reduce the number of replica sets generated on test run.

@hasezoey
Copy link
Collaborator

I ended up removing the .stop() call completely, instead letting AVA trigger all the cleanup

i do not recommend this, because ava may just kill everything instead of doing actual cleanup, because mongodb always requires a database path (which is automatically generated) but if stop is not called, then no cleanup of those files happens (even if using ephermeralForTest, this can accumulate)

jakobo added a commit to jakobo/docmq that referenced this issue Jun 26, 2022
@jakobo
fix: Adds ReplSet shutdown to tests
416606f 
Based on advice from @hasezoey, this adds a shutdown step to the after()
cleanup to ensure all temp files are removed as part of the test
completion step.

ref: nodkz/mongodb-memory-server#666 (comment)
@jakobo
Copy link
Author

jakobo commented Jun 26, 2022 •
edited

if stop is not called, then no cleanup of those files happens (even if using ephermeralForTest...)

Makes sense. FWIW, we added the stop calls in, and it is still terminating cleanly without the flakiness. 🎉 So it appears the undefined check was sufficient for whatever was causing the early abort action.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug released Pull Request released | Issue is fixed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jakobo @hasezoey