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

MongoMemoryServer.create hanging in Docker #710

Closed
AustinMutschler opened this issue Oct 28, 2022 · 31 comments
Closed

MongoMemoryServer.create hanging in Docker #710

AustinMutschler opened this issue Oct 28, 2022 · 31 comments
Labels
bug stale This Issue is outdated and will likely be closed if no further comments are given

Comments

@AustinMutschler
Copy link

AustinMutschler commented Oct 28, 2022

Versions

  • NodeJS: 14.20.1
  • mongodb-memory-server: 8.9.3
  • mongodb(the binary version): 0.0.0
  • mongoose: 6.6.0
  • system: MacOS Monterey -> Docker node:14.20.1-bullseye-slim AMD64

package: mongo-memory-server

What is the Problem?

When running my Express application in Docker for local development and running jest test command; mongodb-memory-server stalls at const mongod = await MongoMemoryServer.create();

Code Example

// mock-db.js
const mongoose = require('mongoose');
const { MongoMemoryServer } = require('mongodb-memory-server');

module.exports.setUp = async () => {
  const mongod = await MongoMemoryServer.create();
  const uri = mongod.getUri();

  await mongoose.connect(uri, {
    useNewUrlParser: true,
  });
};
// test.js

describe('Tests', () => {
  jest.setTimeout(100000);

  test('test 1', async () => {
    await db.setUp();
    await request(app)
      .get("/api/v1/document")
      .set(header)
      .expect((response) => {
        expect(response.status).toBe(200);
      });
  });
});

Debug Output

Debug Output
  MongoMS:ResolveConfig Debug Mode Enabled, through package.json +0ms
  MongoMS:MongoMemoryServer create: Called .create() method +0ms
  MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method +2ms
  MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method +2ms
  MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false +2ms
  MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 33933,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'ephemeralForTest',
    replSet: undefined,
    dbPath: '/tmp/mongo-mem--5281-8pCZ60aOpRyc',
    tmpDir: {
      name: '/tmp/mongo-mem--5281-8pCZ60aOpRyc',
      removeCallback: [Function: _cleanupCallback]
    },
    keyfileLocation: undefined,
    args: undefined,
    auth: false
  },
  binary: undefined,
  spawn: undefined
} +30ms
  MongoMS:MongoInstance create: Called .create() method +0ms
  MongoMS:MongoInstance Mongo[33933]: start +2ms
  MongoMS:MongoBinary getPath +0ms
  MongoMS:DryMongoBinary generateOptions +0ms
  MongoMS:utils tryReleaseFile: "/etc/upstream-release/lsb-release" does not exist +0ms
  MongoMS:getos getLinuxInformation: Using etcOsRelease +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +108ms
  MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
} +3ms
  MongoMS:DryMongoBinary getBinaryName +2ms
  MongoMS:DryMongoBinary combineBinaryName +7ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: ''
}  +1ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +10ms
  MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "5.0.8",
  "downloadDir": "/root/.cache/mongodb-binaries",
  "os": {
    "os": "linux",
    "dist": "debian",
    "codename": "bullseye",
    "release": "11"
  },
  "platform": "linux",
  "arch": "x64",
  "systemBinary": "",
  "checkMD5": false
} +138ms
  MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8" +5ms
  MongoMS:DryMongoBinary generateOptions +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +1ms
  MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/root/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
} +1ms
  MongoMS:DryMongoBinary getBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty +0ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8'
}  +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +4ms
  MongoMS:DryMongoBinary locateBinary: running generateDownloadPath +2ms
  MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true" +0ms
  MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/root/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
} +1ms
  MongoMS:DryMongoBinary getBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty +0ms
  MongoMS:DryMongoBinary combineBinaryName +1ms
  MongoMS:DryMongoBinary combineBinaryName +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8'
}  +0ms
  MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +1ms
  MongoMS:DryMongoBinary locateBinary: found binary at "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +0ms
  MongoMS:MongoBinary getPath: Mongod binary path: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8" +19ms
  MongoMS:MongoInstance Mongo[33933]: start: Starting Processes +161ms
  MongoMS:MongoInstance Mongo[33933]: _launchMongod: Launching Mongod Process +1ms
  MongoMS:MongoInstance Mongo[33933]: prepareCommandArgs +3ms
  MongoMS:MongoInstance Mongo[33933]: prepareCommandArgs: final argument array:["--port","33933","--dbpath","/tmp/mongo-mem--5281-8pCZ60aOpRyc","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"] +1ms
  MongoMS:MongoInstance Mongo[33933]: _launchKiller: Launching Killer Process (parent: 5281, child: 6853) +19ms

Do you know why it happenes?

I have been trying to debug this for some time but with no luck. I have gone through the stack to see if I could spot the problem. At the surface level of the issue await MongoMemoryServer.create() is not returning anything.

When diving into the code I noticed that this._startUpInstance(forceSamePort) is the last area of code being executed.

The code below is never being called

this.stateChange(MongoMemoryServerStates.running);
this.debug('start: Instance fully Started');

As a result return instance is not called.

yield instance.start();
return instance;

At first glance, I do not see any errors in the logs which would be causing this issue.

This issue does not happen when running the tests locally on my M1 Macbook Pro.

Steps I have taken

  1. I have made sure that node_modules is not linked to the local filesystem and that they are installed when building the compose file.
  2. I am installing the required Debian package apt-get install libaio1
@hasezoey
Copy link
Member

from what i can tell from the logs, it seems like the binary is found and tried to be started, but then it seems like the log gets cut-off, without any indication on what happened (MMS has logs for successful and error-ed child-processes)

can you maybe confirm that the following are actually the last lines of the debug output?

  MongoMS:MongoInstance Mongo[33933]: prepareCommandArgs: final argument array:["--port","33933","--dbpath","/tmp/mongo-mem--5281-8pCZ60aOpRyc","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"] +1ms
  MongoMS:MongoInstance Mongo[33933]: _launchKiller: Launching Killer Process (parent: 5281, child: 6853) +19ms

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 28, 2022

from what i can tell from the logs, it seems like the binary is found and tried to be started, but then it seems like the log gets cut-off, without any indication on what happened (MMS has logs for successful and error-ed child-processes)

can you maybe confirm that the following are actually the last lines of the debug output?

  MongoMS:MongoInstance Mongo[33933]: prepareCommandArgs: final argument array:["--port","33933","--dbpath","/tmp/mongo-mem--5281-8pCZ60aOpRyc","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"] +1ms
  MongoMS:MongoInstance Mongo[33933]: _launchKiller: Launching Killer Process (parent: 5281, child: 6853) +19ms

Yes these are the last lines of the log. Jest timeout happens well after the last log. I also found this odd as it felt like there should be more. When I tried to debug within the package I could only get so far.


Screen Shot 2022-10-28 at 7 23 31 AM

I have also noticed the .cache does not get created in the node_modules directory although I am not sure exactly when the package attempts to do that. The container does not have a user so it defaults to root for this local dockerfile.

@hasezoey
Copy link
Member

I have also noticed the .cache does not get created in the node_modules directory although I am not sure exactly when the package attempts to do that.

it only attempts to create the folder when it is downloading, but as noted earlier the binary already exists at /root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 (meaning ~/.cache is used)

Yes these are the last lines of the log. Jest timeout happens well after the last log. I also found this odd as it felt like there should be more. When I tried to debug within the package I could only get so far.

just to be sure, could you try doing your test command >> log.txt / your test command | tee log.txt (putting output directly into a file, which is not a TTY) to be sure jest does not accidentally overwrite any lines?


For now i will try to add a timeout to not leave it hanging (default of 10s timeout)

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 28, 2022

I have also noticed the .cache does not get created in the node_modules directory although I am not sure exactly when the package attempts to do that.

it only attempts to create the folder when it is downloading, but as noted earlier the binary already exists at /root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 (meaning ~/.cache is used)

Yes these are the last lines of the log. Jest timeout happens well after the last log. I also found this odd as it felt like there should be more. When I tried to debug within the package I could only get so far.

just to be sure, could you try doing your test command >> log.txt / your test command | tee log.txt (putting output directly into a file, which is not a TTY) to be sure jest does not accidentally overwrite any lines?

For now i will try to add a timeout to not leave it hanging (default of 10s timeout)

After piping the output to a file I am getting the same results with the logs ending after Launching Killer Process

2022-10-28T18:37:30.162Z MongoMS:ResolveConfig Debug Mode Enabled, through package.json
2022-10-28T18:37:33.723Z MongoMS:ResolveConfig Debug Mode Enabled, through package.json
2022-10-28T18:37:33.880Z MongoMS:ResolveConfig Debug Mode Enabled, through package.json
2022-10-28T18:37:34.814Z MongoMS:MongoMemoryServer create: Called .create() method
2022-10-28T18:37:34.825Z MongoMS:MongoMemoryServer Mongo[unknown]: start: Called .start() method
2022-10-28T18:37:34.833Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Called MongoMemoryServer._startUpInstance() method
2022-10-28T18:37:34.844Z MongoMS:MongoMemoryServer Mongo[unknown]: getStartOptions: forceSamePort: false
2022-10-28T18:37:34.877Z MongoMS:MongoMemoryServer Mongo[unknown]: _startUpInstance: Creating new MongoDB instance with options: {
  instance: {
    port: 38667,
    dbName: '',
    ip: '127.0.0.1',
    storageEngine: 'ephemeralForTest',
    replSet: undefined,
    dbPath: '/tmp/mongo-mem--45284-6BRbSp5aBXK6',
    tmpDir: {
      name: '/tmp/mongo-mem--45284-6BRbSp5aBXK6',
      removeCallback: [Function: _cleanupCallback]
    },
    keyfileLocation: undefined,
    args: undefined,
    auth: false
  },
  binary: undefined,
  spawn: undefined
}
2022-10-28T18:37:34.905Z MongoMS:MongoInstance create: Called .create() method
2022-10-28T18:37:34.913Z MongoMS:MongoInstance Mongo[38667]: start
2022-10-28T18:37:34.924Z MongoMS:MongoBinary getPath
2022-10-28T18:37:34.937Z MongoMS:DryMongoBinary generateOptions
2022-10-28T18:37:35.049Z MongoMS:utils tryReleaseFile: "/etc/upstream-release/lsb-release" does not exist
2022-10-28T18:37:35.110Z MongoMS:getos getLinuxInformation: Using etcOsRelease
2022-10-28T18:37:35.135Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-10-28T18:37:35.137Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-10-28T18:37:35.139Z MongoMS:DryMongoBinary getBinaryName
2022-10-28T18:37:35.176Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.177Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.178Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.179Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: ''
} 
2022-10-28T18:37:35.222Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in legacyHomeCache: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
2022-10-28T18:37:35.226Z MongoMS:MongoBinary getPath: MongoBinary options: {
  "version": "5.0.8",
  "downloadDir": "/root/.cache/mongodb-binaries",
  "os": {
    "os": "linux",
    "dist": "debian",
    "codename": "bullseye",
    "release": "11"
  },
  "platform": "linux",
  "arch": "x64",
  "systemBinary": "",
  "checkMD5": false
}
2022-10-28T18:37:35.236Z MongoMS:DryMongoBinary locateBinary: Trying to locate Binary for version "5.0.8"
2022-10-28T18:37:35.236Z MongoMS:DryMongoBinary generateOptions
2022-10-28T18:37:35.238Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-10-28T18:37:35.239Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/root/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-10-28T18:37:35.240Z MongoMS:DryMongoBinary getBinaryName
2022-10-28T18:37:35.242Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.242Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.243Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-10-28T18:37:35.243Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.243Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.243Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8'
} 
2022-10-28T18:37:35.272Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
2022-10-28T18:37:35.281Z MongoMS:DryMongoBinary locateBinary: running generateDownloadPath
2022-10-28T18:37:35.282Z MongoMS:DryMongoBinary generateDownloadPath: Generating Download Path, preferGlobal: "true"
2022-10-28T18:37:35.282Z MongoMS:DryMongoBinary generatePaths {
  version: '5.0.8',
  downloadDir: '/root/.cache/mongodb-binaries',
  os: {
    os: 'linux',
    dist: 'debian',
    codename: 'bullseye',
    release: '11',
    id_like: undefined
  },
  platform: 'linux',
  arch: 'x64',
  systemBinary: ''
}
2022-10-28T18:37:35.283Z MongoMS:DryMongoBinary getBinaryName
2022-10-28T18:37:35.285Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.285Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.285Z MongoMS:DryMongoBinary generatePaths: resolveConfigValue is not empty
2022-10-28T18:37:35.286Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.286Z MongoMS:DryMongoBinary combineBinaryName
2022-10-28T18:37:35.286Z MongoMS:DryMongoBinary generateDownloadPath: Paths: {
  legacyHomeCache: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
  modulesCache: '/usr/share/backend-server/node_modules/.cache/mongodb-memory-server/mongod-x64-debian-5.0.8',
  relative: '/usr/share/backend-server/mongodb-binaries/mongod-x64-debian-5.0.8',
  resolveConfig: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8'
} 
2022-10-28T18:37:35.295Z MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
2022-10-28T18:37:35.299Z MongoMS:DryMongoBinary locateBinary: found binary at "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
2022-10-28T18:37:35.299Z MongoMS:MongoBinary getPath: Mongod binary path: "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
2022-10-28T18:37:35.302Z MongoMS:MongoInstance Mongo[38667]: start: Starting Processes
2022-10-28T18:37:35.303Z MongoMS:MongoInstance Mongo[38667]: _launchMongod: Launching Mongod Process
2022-10-28T18:37:35.306Z MongoMS:MongoInstance Mongo[38667]: prepareCommandArgs
2022-10-28T18:37:35.309Z MongoMS:MongoInstance Mongo[38667]: prepareCommandArgs: final argument array:["--port","38667","--dbpath","/tmp/mongo-mem--45284-6BRbSp5aBXK6","--storageEngine","ephemeralForTest","--bind_ip","127.0.0.1","--noauth"]
2022-10-28T18:37:35.379Z MongoMS:MongoInstance Mongo[38667]: _launchKiller: Launching Killer Process (parent: 45284, child: 50692)

@hasezoey
Copy link
Member

After piping the output to a file I am getting the same results with the logs ending after Launching Killer Process

very weird, but because i dont have enough information to go on (or be able to reproduce the issue), i cannot really help with it

the only thing that may be helpful is if you add console.log(childProcess) in lib/util/MongoInstance.js#L247 (see unpkg example of where)

@AustinMutschler
Copy link
Author

I pulled the childProcess. I will keep digging around this area in my debugger.

Attempted to log "childProcess1 <ref *1> ChildProcess {
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _closesNeeded: 3,
      _closesGot: 0,
      connected: false,
      signalCode: null,
      exitCode: null,
      killed: false,
      spawnfile: '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
      _handle: Process {
        onexit: [Function (anonymous)],
        pid: 37213,
        [Symbol(owner_symbol)]: [Circular *1]
      },
      spawnargs: [
        '/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8',
        '--port',
        '39543',
        '--dbpath',
        '/tmp/mongo-mem--90422-E4QtiEv7DndD',
        '--storageEngine',
        'ephemeralForTest',
        '--bind_ip',
        '127.0.0.1',
        '--noauth'
      ],
      pid: 37213,
      stdin: <ref *2> Socket {
        connecting: false,
        _hadError: false,
        _parent: null,
        _host: null,
        _readableState: ReadableState {
          objectMode: false,
          highWaterMark: 16384,
          buffer: BufferList { head: null, tail: null, length: 0 },
          length: 0,
          pipes: [],
          flowing: null,
          ended: false,
          endEmitted: false,
          reading: false,
          sync: true,
          needReadable: false,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          destroyed: false,
          errored: null,
          closed: false,
          closeEmitted: false,
          defaultEncoding: 'utf8',
          awaitDrainWriters: null,
          multiAwaitDrain: false,
          readingMore: false,
          dataEmitted: false,
          decoder: null,
          encoding: null,
          readable: false,
          [Symbol(kPaused)]: null
        },
        _events: [Object: null prototype] { end: [Function: onReadableStreamEnd] },
        _eventsCount: 1,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: false,
          ending: false,
          ended: false,
          finished: false,
          destroyed: false,
          decodeStrings: false,
          defaultEncoding: 'utf8',
          length: 0,
          writing: false,
          corked: 0,
          sync: true,
          bufferProcessing: false,
          onwrite: [Function: bound onwrite],
          writecb: null,
          writelen: 0,
          afterWriteTickInfo: null,
          buffered: [],
          bufferedIndex: 0,
          allBuffers: true,
          allNoop: true,
          pendingcb: 0,
          prefinished: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          errored: null,
          closed: false,
          closeEmitted: false
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        [Symbol(async_id_symbol)]: 888,
        [Symbol(kHandle)]: Pipe { [Symbol(owner_symbol)]: [Circular *2] },
        [Symbol(kSetNoDelay)]: false,
        [Symbol(lastWriteQueueSize)]: 0,
        [Symbol(timeout)]: null,
        [Symbol(kBuffer)]: null,
        [Symbol(kBufferCb)]: null,
        [Symbol(kBufferGen)]: null,
        [Symbol(kCapture)]: false,
        [Symbol(kBytesRead)]: 0,
        [Symbol(kBytesWritten)]: 0
      },
      stdout: <ref *3> Socket {
        connecting: false,
        _hadError: false,
        _parent: null,
        _host: null,
        _readableState: ReadableState {
          objectMode: false,
          highWaterMark: 16384,
          buffer: BufferList { head: null, tail: null, length: 0 },
          length: 0,
          pipes: [],
          flowing: null,
          ended: false,
          endEmitted: false,
          reading: true,
          sync: false,
          needReadable: true,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          destroyed: false,
          errored: null,
          closed: false,
          closeEmitted: false,
          defaultEncoding: 'utf8',
          awaitDrainWriters: null,
          multiAwaitDrain: false,
          readingMore: false,
          dataEmitted: false,
          decoder: null,
          encoding: null,
          [Symbol(kPaused)]: null
        },
        _events: [Object: null prototype] {
          end: [Function: onReadableStreamEnd],
          close: [Function (anonymous)]
        },
        _eventsCount: 2,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: false,
          ending: false,
          ended: false,
          finished: false,
          destroyed: false,
          decodeStrings: false,
          defaultEncoding: 'utf8',
          length: 0,
          writing: false,
          corked: 0,
          sync: true,
          bufferProcessing: false,
          onwrite: [Function: bound onwrite],
          writecb: null,
          writelen: 0,
          afterWriteTickInfo: null,
          buffered: [],
          bufferedIndex: 0,
          allBuffers: true,
          allNoop: true,
          pendingcb: 0,
          prefinished: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          errored: null,
          closed: false,
          writable: false,
          closeEmitted: false
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        [Symbol(async_id_symbol)]: 889,
        [Symbol(kHandle)]: Pipe { reading: true, [Symbol(owner_symbol)]: [Circular *3] },
        [Symbol(kSetNoDelay)]: false,
        [Symbol(lastWriteQueueSize)]: 0,
        [Symbol(timeout)]: null,
        [Symbol(kBuffer)]: null,
        [Symbol(kBufferCb)]: null,
        [Symbol(kBufferGen)]: null,
        [Symbol(kCapture)]: false,
        [Symbol(kBytesRead)]: 0,
        [Symbol(kBytesWritten)]: 0
      },
      stderr: <ref *4> Socket {
        connecting: false,
        _hadError: false,
        _parent: null,
        _host: null,
        _readableState: ReadableState {
          objectMode: false,
          highWaterMark: 16384,
          buffer: BufferList { head: null, tail: null, length: 0 },
          length: 0,
          pipes: [],
          flowing: null,
          ended: false,
          endEmitted: false,
          reading: true,
          sync: false,
          needReadable: true,
          emittedReadable: false,
          readableListening: false,
          resumeScheduled: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          destroyed: false,
          errored: null,
          closed: false,
          closeEmitted: false,
          defaultEncoding: 'utf8',
          awaitDrainWriters: null,
          multiAwaitDrain: false,
          readingMore: false,
          dataEmitted: false,
          decoder: null,
          encoding: null,
          [Symbol(kPaused)]: null
        },
        _events: [Object: null prototype] {
          end: [Function: onReadableStreamEnd],
          close: [Function (anonymous)]
        },
        _eventsCount: 2,
        _maxListeners: undefined,
        _writableState: WritableState {
          objectMode: false,
          highWaterMark: 16384,
          finalCalled: false,
          needDrain: false,
          ending: false,
          ended: false,
          finished: false,
          destroyed: false,
          decodeStrings: false,
          defaultEncoding: 'utf8',
          length: 0,
          writing: false,
          corked: 0,
          sync: true,
          bufferProcessing: false,
          onwrite: [Function: bound onwrite],
          writecb: null,
          writelen: 0,
          afterWriteTickInfo: null,
          buffered: [],
          bufferedIndex: 0,
          allBuffers: true,
          allNoop: true,
          pendingcb: 0,
          prefinished: false,
          errorEmitted: false,
          emitClose: false,
          autoDestroy: false,
          errored: null,
          closed: false,
          writable: false,
          closeEmitted: false
        },
        allowHalfOpen: false,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        [Symbol(async_id_symbol)]: 890,
        [Symbol(kHandle)]: Pipe { reading: true, [Symbol(owner_symbol)]: [Circular *4] },
        [Symbol(kSetNoDelay)]: false,
        [Symbol(lastWriteQueueSize)]: 0,
        [Symbol(timeout)]: null,
        [Symbol(kBuffer)]: null,
        [Symbol(kBufferCb)]: null,
        [Symbol(kBufferGen)]: null,
        [Symbol(kCapture)]: false,
        [Symbol(kBytesRead)]: 0,
        [Symbol(kBytesWritten)]: 0
      },
      stdio: [
        <ref *2> Socket {
          connecting: false,
          _hadError: false,
          _parent: null,
          _host: null,
          _readableState: [ReadableState],
          _events: [Object: null prototype],
          _eventsCount: 1,
          _maxListeners: undefined,
          _writableState: [WritableState],
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          [Symbol(async_id_symbol)]: 888,
          [Symbol(kHandle)]: [Pipe],
          [Symbol(kSetNoDelay)]: false,
          [Symbol(lastWriteQueueSize)]: 0,
          [Symbol(timeout)]: null,
          [Symbol(kBuffer)]: null,
          [Symbol(kBufferCb)]: null,
          [Symbol(kBufferGen)]: null,
          [Symbol(kCapture)]: false,
          [Symbol(kBytesRead)]: 0,
          [Symbol(kBytesWritten)]: 0
        },
        <ref *3> Socket {
          connecting: false,
          _hadError: false,
          _parent: null,
          _host: null,
          _readableState: [ReadableState],
          _events: [Object: null prototype],
          _eventsCount: 2,
          _maxListeners: undefined,
          _writableState: [WritableState],
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          [Symbol(async_id_symbol)]: 889,
          [Symbol(kHandle)]: [Pipe],
          [Symbol(kSetNoDelay)]: false,
          [Symbol(lastWriteQueueSize)]: 0,
          [Symbol(timeout)]: null,
          [Symbol(kBuffer)]: null,
          [Symbol(kBufferCb)]: null,
          [Symbol(kBufferGen)]: null,
          [Symbol(kCapture)]: false,
          [Symbol(kBytesRead)]: 0,
          [Symbol(kBytesWritten)]: 0
        },
        <ref *4> Socket {
          connecting: false,
          _hadError: false,
          _parent: null,
          _host: null,
          _readableState: [ReadableState],
          _events: [Object: null prototype],
          _eventsCount: 2,
          _maxListeners: undefined,
          _writableState: [WritableState],
          allowHalfOpen: false,
          _sockname: null,
          _pendingData: null,
          _pendingEncoding: '',
          server: null,
          _server: null,
          [Symbol(async_id_symbol)]: 890,
          [Symbol(kHandle)]: [Pipe],
          [Symbol(kSetNoDelay)]: false,
          [Symbol(lastWriteQueueSize)]: 0,
          [Symbol(timeout)]: null,
          [Symbol(kBuffer)]: null,
          [Symbol(kBufferCb)]: null,
          [Symbol(kBufferGen)]: null,
          [Symbol(kCapture)]: false,
          [Symbol(kBytesRead)]: 0,
          [Symbol(kBytesWritten)]: 0
        }
      ],
      [Symbol(kCapture)]: false
    }".

@AustinMutschler
Copy link
Author

I have found the exact code where it stalls but I have no idea why.

yield launch line is hit but then it will not proceed to the next line to emit.

this.killerProcess = this._launchKiller(process.pid, this.mongodProcess.pid);
yield launch; // <---- This line
this.emit(MongoInstanceEvents.instanceStarted);

@hasezoey
Copy link
Member

hasezoey commented Oct 28, 2022

I pulled the childProcess.

from what i can tell it looks correctly started

I have found the exact code where it stalls but I have no idea why.

from what i can tell now, is that the child-process gets correctly spawned and does not exit BUT does not output any stdout (or stderr for that matter), which MMS requires to fetch from to get when the database is correctly started, or has a error, see the following code:

https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/util/MongoInstance.ts#L348-L370

https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/util/MongoInstance.ts#L477-L480

https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/util/MongoInstance.ts#L577-L579

in case of a error or close, it should fire the closeHandler or errorHandler (as seen in the code above), which looks like:

https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/util/MongoInstance.ts#L524-L547

but as can be seen from the logs, no stdout, stderr or events were fired, and thats the reason on why i cant really help debug further without being able to reproduce it

just to be sure, you are running nodejs and not something like deno, correct?

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 28, 2022

Correct. I am using CommonJS. Specifically: Docker Image node:14.20.1-bullseye-slim with the following additional software installed for other purposes:

NODE_ENV=development

apt-get install nano git bash openssl musl curl libaio1 wget unzip libcurl4

I know some of these are packages are in Debian. We recently transitioned from Alpine.

I am going to setup a small repo that demonstrates the issue to see if it can be recreated.

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 28, 2022

@hasezoey I have create a sample repo that recreates the issue along with instructions on my specific Docker setup and workflow in the Readme.

https://github.com/AustinMutschler/debug-mms

I was able to run this demo repo on an Intel Macbook using Docker (same steps as the README) and it works as intended but not on my M1 Macbook. This seems to be an issue with an M1 Macbook running a Docker container with platform linux/amd64.

Docker Engine 20.10.17
Compose: 2.10.2

My setup:
Macbook Pro M1 Max -> Docker platform: linux/amd64 with image built from node:18.12.0-bullseye-slim.

@hasezoey
Copy link
Member

tired your repository locally and in docker, but i cannot reproduce this issue, for me it "just works" (Linux Manjaro x86_64, i dont have a Mac device to test on)

because you are running on M1, is rosetta installed and working correctly? (i dont more to help with that)

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 29, 2022

tired your repository locally and in docker, but i cannot reproduce this issue, for me it "just works" (Linux Manjaro x86_64, i dont have a Mac device to test on)

because you are running on M1, is rosetta installed and working correctly? (i dont more to help with that)

Rosetta is working fine. I have a feeling it has something to do with how Docker ARM running a linux/amd64 container uses STDOUT

@hasezoey
Copy link
Member

hasezoey commented Oct 29, 2022

what you could also try is to:

# term 1
docker-compose up --build
# wait for it to start
# term 2
docker ps
docker exec -it containerIdHere /bin/bash
# now in the container in term 2
mkdir /tmp/some-db-path
/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 --port 43471 --dbpath /tmp/some-db-path --storageEngine ephemeralForTest --bind_ip 127.0.0.1 --noauth
# and see if it actually outputs something

(Note: with term N i mean different terminals, because the first one blocks when the container is running, you could also use -d to detach; in docker ps you have to take the containerID of the started container and add it in the next command)

@theonetheycallneo
Copy link

Same is happening for us but we are not using docker just using M1/arm64 with a self-hosted runner:

mongod = await MongoMemoryServer.create()

hangs with no status or state update:

Screen Shot 2022-10-30 at 10 32 52 AM

@hasezoey
Copy link
Member

but we are not using docker just using M1/arm64 with a self-hosted runner:

if i understand correctly, github runners are also running in docker (or at least very similar to it), and gitlab runners do too

sad to hear that it is affects multiple users, but i will not be able to debug this because i dont have a apple device (M1) to test on.
so any help in debugging this would be appreciated.


for example, the following questions would need to be answered:

  • does the downloaded mongod binary work by itself (started manually)?
    if it does not start by itself, then MMS will not be able to do anything about it
  • if the binary does start by itself, then some investigation on why the ChildProcess is not outputting any STDOUT (or STDERR) would be required

the place where the binary has been downloaded to can be found by starting your script (with MMS) in debug log mode and looking for a line similar to MongoMS:DryMongoBinary generateDownloadPath: Found binary in resolveConfig (DOWNLOAD_DIR): "/root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8"
and then start to start the binary in the container, the dbpath would need to be created first before starting the binary (a full run is required just to be sure the binary starts fully correctly):

mkdir /tmp/some-db-path
/path/to/binary/mongod-x64-debian-5.0.8 --port 43471 --dbpath /tmp/some-db-path --storageEngine ephemeralForTest --bind_ip 127.0.0.1

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 31, 2022

@hasezoey according to Docker, to emulate amd64 on ARM machines they use a QEMU virtual machine. The good news for Mac users is they want to which to using Rosetta but have not begun development on that yet.

https://docs.docker.com/build/building/multi-platform/

I am not sure if it is re-creatable in there. I will do some digging into the questions you asked above and get back to you.

@jpilgrim
Copy link

jpilgrim commented Oct 31, 2022

I'm not quite sure whether my problem is similar, but it is at least related: I'm trying to run in a docker image on macos with an M1 machine. I have prepared an amazonlinux image with node to be able to use mongodb-linux-aarch64-amazon2-4.4.6. (I'm using 4.4.6 since I also run that on an Gitlab instance with old CPUs...).

The file is correctly computed from os and arch, but unfortunately the download takes more than 10 seconds. Unfortunately the 10 seconds timeout cannot be changed, can it?

It is set here:
https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/util/MongoInstance.ts#L356-L359

When creating an instance via MongoMemoryServer.create one can add instance options, e.g.

const mongod = await MongoMemoryServer.create( { instance: { launchTimeout: 60000 } });

However, this configuration is not passed to MongoInstance later on due to these lines:
https://github.com/nodkz/mongodb-memory-server/blob/85f7e5e59974b8f2ff809d13ec6124782da6321b/packages/mongodb-memory-server-core/src/MongoMemoryServer.ts#L414-L418

That is, instOpts is the object with the settings passed in create, but its values are ignored except for args (and some others used before these lines of course).

I'm using a workaround by simply downloading the file manually, extract bin/mongod from the file and rename it accordingly (at ~/.cache/mongodb-binaries). But this is not an ideal solution.

@kevincennis
Copy link

@jpilgrim you can also set MONGOMS_VERSION=4.4.6 during your npm install step. That gets read as the postinstall hook for mongodb-memory-server runs, and will just pull the correct binary at install time.

Also has the benefit (if you're on Docker) of better caching, since it happens at an earlier layer.

@jpilgrim
Copy link

jpilgrim commented Oct 31, 2022

@kevincennis, I already have configured that (actually, I set the version in package.json via config/mongodbMemoryServer/version. This (the version of the mondod binary) is not the issue here.

The problem is that downloading the binaries (via your aforementioned hook) has a (more or less) hard coded timeout. This is why I thought that my issue is related to this thread here.

Oh, maybe I should add that the timeout also hinders the binary to be downloaded correctly (or, let's say, completely) during npm install. That brings me to another question: Is it possible to configure the timeout used in npm install?

@hasezoey
Copy link
Member

However, this configuration is not passed to MongoInstance later on due to these lines:

thanks for pointing this out, will fix it in a patch version soon (and will probably refactor that thing for the next major)

The file is correctly computed from os and arch, but unfortunately the download takes more than 10 seconds. Unfortunately the 10 seconds timeout cannot be changed, can it?

the timeout is for launching the binary not downloading the binary

@jpilgrim
Copy link

@hasezoey Thanks! So with "patch" you mean: Add a setting for timeout for downloading the binary ?

@hasezoey
Copy link
Member

Thanks! So with "patch" you mean: Add a setting for timeout for downloading the binary ?

no, with thanks for pointing this out, will fix it in a patch version soon (and will probably refactor that thing for the next major) i mean that i will fix passing through launchTimeout from MongoMemoryServer to MongoInstance

the actual download has no timeout (that i know of)

@jpilgrim
Copy link

@hasezoey Thanks for the fast fix! I'm happy to helping improve mms... even though I apparently have a different problem. Very weird, seems to be related to how I start docker... As a matter of fact during npm install the download is cancelled after 10 seconds. But I have no idea -- and this is not a docker forum anyway :-)

@hasezoey
Copy link
Member

As a matter of fact during npm install the download is cancelled after 10 seconds. But I have no idea -- and this is not a docker forum anyway :-)

weird, from what i know docker does not have timeout things, so maybe your package-manager somehow has a timeout for postinstall scripts? (though from what i know yarn and npm dont have such a thing)

@AustinMutschler
Copy link
Author

  • does the downloaded mongod binary work by itself (started manually)?

After creating the /tmp/some-db-path path, I ran the following commands to test the binary

root@0a2a03a5dbe0:/usr/share/backend-server# /root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 --help

and

root@0a2a03a5dbe0:/usr/share/backend-server# /root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 --port 43471 --dbpath /tmp/some-db-path --storageEngine ephemeralForTest --bind_ip 127.0.0.1

Both commands hang until cancelled.

@hasezoey
Copy link
Member

Both commands hang until cancelled.

thanks for that information, this would mean it is a mongodb's issues, nothing MMS could do about (that i know), a issue would have to be opened at https://jira.mongodb.org/browse/ (and for discoverability, i would request to have the url of the opened issue posted in this thread to)

@AustinMutschler
Copy link
Author

AustinMutschler commented Oct 31, 2022

@hasezoey Update

I replaced the mongod file from /root/.cache/mongodb-binaries/mongod-x64-debian-5.0.8 with a custom downloaded 4.4.17 mongod binary (Debian 10) and it worked. I know that I am running Debian 11 but Mongo doesn't seem to have a binary for Deb 11 v4.4.17.

I then manually replaced the mongod binary with a Debian 11 5.0.13 binary and it failed with the hanging issue.

Root problem

I was reading a post in a MongoDB forum and they said that QEMU does not work with >= v5 binaries because of issues with "AVX Instructions".

Future Solution

The good news is, last week QEMU committed a change for AVX instructions which is said to potentially fix the issue. Hopefully Docker will update QEMU when it releases and eventually support newer versions of Mongo.

For now, it looks like ARM processors debugging in Docker using AMD64 will not be able to use MMS for v5 or v6 MongoDB.

I know this is probably a rare instance because usually I would run the container on ARM natively and all would be well; however, there is another application in the container (Oracle Instantclient) that requires amd64 because it has little support for ARM (plus we have devs with both types of machines).

Workaround

If it is acceptable to use Mongo 4.4 for testing you just need to change the version MMS uses by specifying it in an ENV variable or in the create configuration.

  const mongod = await MongoMemoryServer.create(
    {
      binary: {
        version: '4.4.17'
      }
    }
  );

@hasezoey
Copy link
Member

I was reading a post in a MongoDB forum and they said that QEMU does not work with >= v5 binaries because of issues with "AVX Instructions".

thanks for finding this, i initially excluded the AVX problem, because normally mongodb (at least on windows and linux from what i can tell) print a failing message / error and are not left hanging, like a exit signal of SIGILL

@github-actions
Copy link

github-actions bot commented Dec 1, 2022

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

@github-actions github-actions bot added the stale This Issue is outdated and will likely be closed if no further comments are given label Dec 1, 2022
@github-actions
Copy link

github-actions bot commented Dec 9, 2022

Closing Issue because it is marked as stale

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Dec 9, 2022
@hasezoey
Copy link
Member

Update:
Qemu 7.2 has been released with AVX and AVX2 handling, but no docker update has been issued yet
for those that want to follow for a docker update: docker/for-mac#6620

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug stale This Issue is outdated and will likely be closed if no further comments are given
Projects
None yet
Development

No branches or pull requests

5 participants