Error when running tests in Docker / CI

[rjhilgefort]

Things work great when I'm running on my local machine, but I'm seeing problems getting things to run in my CI pipeline, which is running tests in a Docker containers.

The symptom is that my global.__MONGOD__ appears to be undefined by the time my mongo-environment.js is loaded by the test.

TypeError: Cannot read property 'getConnectionString' of undefined

Here's what my setup.js and my mongo-environment.js files look like:

// setup.js
const MongodbMemoryServer = require('mongodb-memory-server');

const MONGO_DB_NAME = 'jest';

const mongod = new MongodbMemoryServer.default({
  instance: {
    dbName: MONGO_DB_NAME,
  },
  binary: {
    version: '3.4.6',
  },
});

module.exports = () => {
  global.__MONGOD__ = mongod;
  global.__MONGO_DB_NAME__ = MONGO_DB_NAME;
};

// mongo-environment.js
const NodeEnvironment = require('jest-environment-node');

class MongoEnvironment extends NodeEnvironment {
  async setup() {
    // 👇 This line is throwing the error I mentioned above
    this.global.__MONGO_URI__ = await global.__MONGOD__.getConnectionString();
    this.global.__MONGO_DB_NAME__ = global.__MONGO_DB_NAME__;

    await super.setup();
  }

  async teardown() {
    await super.teardown();
  }

  runScript(script) {
    return super.runScript(script);
  }
}

module.exports = MongoEnvironment;

It looks like mongo doesn't get downloaded all the way before the code tries to run and reference the connection string? As I'm watching it run, I see this line about downloading Mongo and it starts showing percentages, but then tests start running and failing. (Note, the percent is gone in the screen grab).

[nodkz]

Try two things

1. increase timeouts for jest jasmine.DEFAULT_TIMEOUT_INTERVAL = 160000; it's required to download mongod first time. PS do not forget to add to a CI cache a dowloaded binaries (for further fast starts).

2. if it doesnot help, try to set debug: true optionand provides its output here.

[rjhilgefort]

increase timeouts for jest jasmine.DEFAULT_TIMEOUT_INTERVAL = 160000; it's required to download mongod first time. PS do not forget to add to a CI cache a dowloaded binaries (for further fast starts).

I'm either having trouble figuring out how to update the timeout, or it's not alleviating the issue. I've tried to update the timeout using the suggested setup on this issue. To try to see if it's running, I've put a console log in my testSetupFile, but I'm not seeing that log in my test output. Any suggestions on how to increase the global timeout? Sorry for the probably trivial question.

if it doesnot help, try to set debug: true optionand provides its output here.

$ yarn jest --runInBand --coverage "StateMachine"
config-api_1  | Determining test suites to run...Autostarting MongoDB instance...
  Mongo[34551] Starting MongoDB instance with following options: {"port":34551,"dbName":"jest","uri":"mongodb://localhost:34551/jest","storageEngine":"ephemeralForTest","dbPath":"/tmp/mongo-mem-296twsZEMl2k6I"} +0ms
Downloading: https://fastdl.mongodb.org/linux/mongodb-linux-x86_64-debian81-3.4.6.tgz
 FAIL  tests/models/Experiment/index.test.js96mb)
  ● Test suite failed to run
config-api_1  |
config-api_1  |     TypeError: Cannot read property 'getConnectionString' of undefined
config-api_1  |
config-api_1  |       11 |     // https://github.com/facebook/jest/issues/5731
config-api_1  |       12 |
config-api_1  |     > 13 |     this.global.__MONGO_URI__ = await global.__MONGOD__.getConnectionString();
config-api_1  |          |                                                        ^
config-api_1  |       14 |     this.global.__MONGO_DB_NAME__ = global.__MONGO_DB_NAME__;
config-api_1  |       15 |
config-api_1  |       16 |     await super.setup();
config-api_1  |
config-api_1  |       at MongoEnvironment.setup (tests/_lib/mongo-environment.js:13:56)
config-api_1  |
config-api_1  | Test Suites: 24 failed, 24 total
config-api_1  | Tests:       0 total
config-api_1  | Snapshots:   0 total
config-api_1  | Time:        6.325s
config-api_1  | Ran all test suites.
config-api_1  |   Mongo[34551] MongoBinary: Mongod binary path: /root/.mongodb-binaries/3.4.6/mongod +4s
config-api_1  |   Mongo[34551] MongoBinary: Download lock removed +42ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] MongoDB starting : pid=81 port=34551 dbpath=/tmp/mongo-mem-296twsZEMl2k6I 64-bit host=9f2dc97c4877
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] db version v3.4.6
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] git version: c55eb86ef46ee7aede3b1e2a5d184a7df4bfb5b5
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1t  3 May 2016
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] allocator: tcmalloc
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] modules: none
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] build environment:
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten]     distmod: debian81
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten]     distarch: x86_64
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten]     target_arch: x86_64
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.271+0000 I CONTROL  [initandlisten] options: { net: { port: 34551 }, security: { authorization: "disabled" }, storage: { dbPath: "/tmp/mongo-mem-296twsZEMl2k6I", engine: "ephemeralForTest" } }
config-api_1  |   Mongo[34551]  +1ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.289+0000 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.289+0000 I CONTROL  [initandlisten]
config-api_1  |   Mongo[34551]  +8ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.290+0000 I CONTROL  [initandlisten]
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.290+0000 I CONTROL  [initandlisten] ** NOTE: The ephemeralForTest storage engine is for testing only.
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.290+0000 I CONTROL  [initandlisten] **       Do not use in production.
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.290+0000 I CONTROL  [initandlisten]
config-api_1  |   Mongo[34551]  +2ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.297+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/tmp/mongo-mem-296twsZEMl2k6I/diagnostic.data'
config-api_1  |   Mongo[34551]  +7ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.298+0000 I INDEX    [initandlisten] build index on: admin.system.version properties: { v: 2, key: { version: 1 }, name: "incompatible_with_version_32", ns: "admin.system.version" }
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.298+0000 I INDEX    [initandlisten]   building index using bulk method; build may temporarily use up to 500 megabytes of RAM
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.298+0000 I INDEX    [initandlisten] build index done.  scanned 0 total records. 0 secs
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.298+0000 I COMMAND  [initandlisten] setting featureCompatibilityVersion to 3.4
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.298+0000 I NETWORK  [thread1] waiting for connections on port 34551
config-api_1  |   Mongo[34551]  +1ms
config-api_1  |   Mongo[34551] MongodbInstance: is ready! +0ms
config-api_1  |   Mongo[34551] Shutdown MongoDB server on port 34551 with pid 81 +1ms
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I NETWORK  [signalProcessingThread] closing listening socket: 6
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I NETWORK  [signalProcessingThread] closing listening socket: 7
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I NETWORK  [signalProcessingThread] removing socket file: /tmp/mongodb-34551.sock
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I NETWORK  [signalProcessingThread] shutdown: going to flush diaglog...
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I FTDC     [signalProcessingThread] Shutting down full-time diagnostic data capture
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I STORAGE  [signalProcessingThread] shutdown: removing fs lock...
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I CONTROL  [signalProcessingThread] now exiting
config-api_1  |   Mongo[34551] 2018-08-31T18:23:56.302+0000 I CONTROL  [signalProcessingThread] shutting down with code:0
config-api_1  |   Mongo[34551]  +4ms
config-api_1  |   Mongo[34551] MongodbInstance: is failed: Mongod shutting down +0ms
config-api_1  |   Mongo[34551] Removing tmpDir /tmp/mongo-mem-296twsZEMl2k6I +27ms
config-api_1  |   Mongo[34551] CLOSE: 0 +4ms
error Command failed with exit code 1.
error Command failed with exit code 1.
distillery-experiment-config-api_config-api_1 exited with code 1

[rjhilgefort]

Based on when the mongo logs indicate that it's starting up, I think you're right that it's likely just the timeout issue. I just can't seem to get jest to respect that setting.

I'm also not sure how to control caching that download in my CI pipeline. It's likely slightly different for every setup, but in general, can you expand on what you mean?

Thanks for the help with this!

[nodkz]

By provided logs, there are no problems with jest timeout or environment. Mongod downloaded succesfully, launched without problems, and after tests was killed by internal killer. It's ok to free resources when tests ended.

It looks like the problem somewhere in your tests.

But to be sure, please run a simple test https://github.com/nodkz/mongodb-memory-server#simple-jest-test-example with your CI setup. It should work. If so, then needs to inspect the problem with your tests setup.

I think that you something miss, cause global.__MONGOD__ is undefined by your logs.

[rjhilgefort]

By provided logs, there are no problems with jest timeout or environment. Mongod downloaded succesfully, launched without problems, and after tests was killed by internal killer. It's ok to free resources when tests ended.

Based on how the logs play out, it really does seem like Mongo is still being downloaded by the time the individual tests start. That seems even more to be the case based on when I see the logs for Mongo saying that it's starting and then running- which occur after the tests failed.

It looks like the problem somewhere in your tests.

But to be sure, please run a simple test https://github.com/nodkz/mongodb-memory-server#simple-jest-test-example with your CI setup. It should work. If so, then needs to inspect the problem with your tests setup.

The tests run fine outside of Docker and/or my CI pipeline. I'm not sure what aspect of running in Docker is the problem, but that's definitely the difference.

I'm a bit stumped on what else to try. Is there any way you can think of to eliminate the variable of the Mongo download up front? If I had the Docker image download it and bake it into a place where in-memory-mongo is looking?

[nodkz]

I think that async setup() in mongo-environment.js does not work properly under Docker. Maybe some bug inside Jest.

So you need to try another way to define mongo in your tests.
Please, try such code and provide its output:

import mongoose from 'mongoose';
import MongodbMemoryServer from 'mongodb-memory-server';

let mongoServer;
beforeAll(async () => {
  mongoServer = new MongodbMemoryServer();
  const mongoUri = await mongoServer.getConnectionString();
  await mongoose.connect(
    mongoUri,
    { useNewUrlParser: true }
  );
  mongoose.set('debug', true);
});

afterAll(() => {
  mongoose.disconnect();
  mongoServer.stop();
});

// May require additional time for downloading MongoDB binaries
jasmine.DEFAULT_TIMEOUT_INTERVAL = 120000;

describe('some test', () => {
  const RecordSchema = new mongoose.Schema({ id: String, title: String });
  const Record = mongoose.model('Record', RecordSchema);

  beforeAll(async () => {
    for (let i = 1; i <= 9; i++) {
      await Record.create({ _id: `10000000000000000000000${i}`, title: `${i}` });
    }
  });

  it('check count', async () => {
    const cnt = await Record.count();
    expect(cnt).toBe(9);
  });
});

[rjhilgefort]

Thanks for the suggestion! I think you may be right about this being an issue with how Jest runs inside Docker- possibly something with the async keyword.

I didn't use your code exactly, but I leveraged the strategy you were proposing and adapted it to my tests. When doing so, I was able to see my tests pass outside and inside of Docker. While this works, it obviously starts up mongo and stops it for every test file.

I'm going to run with this for now and I think it's likely not a problem here and should probably be put against Jest, correct? Let me know your thoughts and I'll go from there. Thank you so much for your help with this issue!

// mongo-env.js
import MongodbMemoryServer from 'mongodb-memory-server';
import { MongoClient } from 'mongodb';

const MONGO_DB_NAME = 'jest';

export const setupMongoEnv = async () => {
  const mongod = new MongodbMemoryServer({
    instance: {
      dbName: MONGO_DB_NAME,
    },
    binary: {
      version: '3.4.6',
    },
    debug: true,
  });

  const mongoUri = await mongod.getConnectionString();
  const connection = await MongoClient.connect(mongoUri);
  const db = await connection.db(MONGO_DB_NAME);

  return { connection, db, mongod };
};

export const teardownMongoEnv = async ({ connection, db, mongod }) => {
  await connection.close();
  await db.close();
  await mongod.stop();
};

// some-test.js
import { setupMongoEnv, teardownMongoEnv } from './mongo-env';
import newExperiment from './experiment-mock';

describe('updateRoles', () => {
  let mongoEnv;

  beforeAll(async () => {
    jest.setTimeout(30 * 1000);
    mongoEnv = await setupMongoEnv();
  });

  afterAll(async () => {
    await teardownMongoEnv(mongoEnv);
  });

  describe('missing data', () => {
    let model;

    beforeEach(async () => {
      model = newExperiment(mongoEnv.db);
    });

    afterEach(async () => {
      await model.clear();
    });

    it('should throw an error for missing experiment', async () => {
      await expect(
        model.updateRoles({
          uuid: 'whatever',
          role: 'TECH_POC',
          userIds: ['pUpdate1'],
        }),
      ).rejects.toThrow('Experiment not found');
    });

  });
});

[nodkz]

Yep, I think that the problem somewhere in Jest, or maybe in incorrect configs in mongo-environment.js. It's very difficult to understand exactly what works wrongly.

[nodkz]

I'm glad that you found working solution.
And thank you very much for provided working example. It helps to further googlers with same problem.

[rjhilgefort]

Thanks for your help!

[sgarcia-dev]

Hey everyone! Thank you so much for documenting this. We are having the same problems on our side while trying to run Puppeteer in some Jest tests, and we are also having problems with Jest not respecting our setTimeout in some environments like Windows. I will be trying to remove the async keyword in test setups, but in the mean time, why was this issue closed? It doesn't seem like it was resolved, and searching for "jest setTimeout" yields 0 documentation links supporting any of this, or that you should be using jasmine. DEFAULT_TIMEOUT_INTERVAL to set test timeouts, and if so, where.

It's just I'm seriously loving Jest, but these timeout issues are seriously causing some regret on picking it for long running automation tasks.

[rjhilgefort]

@sgarcia-dev I closed it because I agreed with @nodkz that the issue wasn't with this project, but rather with jest. I have a TODO item to create a proper issue against jest, but I have not gotten around to it yet. It would be fantastic if you had the bandwidth to do so!

I still haven't resolved the issue and relegated myself to the workaround I described above.