Mongodb-memory-server: MongoMemoryReplSet taking time to stop

[elieteyssedou]

Versions

• NodeJS: 12.16.3
• mongodb-memory-server-*: 6.6.1
• mongodb: 3.5.4
• mongoose: 5.4.12
• system: MacOS

What is your question?

Hi,

Along with Mocha, I was using mongodb-memory-server in my test suite. after (like the Mocha's after) all my tests, I was shutting down my MongoMemoryServer instance (an await server.stop was doing the job).
I had to switch to MongoMemoryReplSet in order to be able to use mongodb transactions. The thing is that, now, doing the same exact stop on my MongoMemoryReplSet stop method, I have a 10s delay before my test suite shutdown.

How can I avoid that 10s delay ?

Here is some log of what mongodb-memory-server is doing :

 MongoMS:MongoInstance Mongo[58861]: STDOUT: 2020-07-25T17:42:28.787+0200 I STORAGE  [signalProcessingThread] Failed to stepDown in non-command initiated shutdown path ExceededTimeLimit: No electable secondaries caught up as of 2020-07-25T17:42:28.786+0200Please use the replSetStepDown command with the argument {force: true} to force node to step down.
  MongoMS:MongoInstance  +10s
  MongoMS:MongoInstance Mongo[58861]: STDOUT: 2020-07-25T17:42:28.787+0200 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...

We can see +10s. in the logs.

[hasezoey]

in the code there isnt any delay for the mentioned output (MongoMS:MongoInstance), so this would mean this is directly from mongod's output

[elieteyssedou]

Then how can I stop properly my replSet ? When I follow the mongo-memory-server's documentation, it leads to the 10sec delay. What do I have to do to avoid this ?

[hasezoey]

i never used replset's, so i can not tell how to properly do it - but judging from the code, this +10s message comes directly from an mongod instance

PS: the only thing that is somehow missing is the Mongo[PID] so i can not tell from which process it comes

[nodkz]

From MongoDB docs:

Starting in MongoDB 4.0.8 (and 3.6.15), if a replica set primary receives a SIGTERM, the primary attempts to step down before shutting down.

• If the step down succeeds, the instance does not vote in the ensuing election of the new primary, and continues its shutdown.
• If the step down fails, the instance continues its shutdown.

@elieteyssedou try to manually shutdown ReplicaSet https://docs.mongodb.com/manual/tutorial/manage-mongodb-processes/#force-replica-set-shutdown

And if it helps please drop a line here with your solution. Probably we can add your founded solution inside the lib. Thanks.

[NathanHazout]

I'm having the same issue. I'm not sure how to manually shutdown from code ...

[njtnestor]

Some solution?

[elieteyssedou]

I didn't find any solution. I don't manage to manually / force stop the replica set (as @nodkz suggested).

Apart from that, MongoMemoryReplSet seems to be super slow (~3 or 4s) to start.

@nodkz, is there any way to not use MongoMemoryReplSet and be able to use mongodb transactions ?

[hasezoey]

@elieteyssedou the mongodb documentation mention that transactions are only available in an replset

[njtnestor]

To avoid this error in jest: Timeout - Async callback was not invoked within the 5000 ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000 ms timeout specified by jest.setTimeout.

I did this in the first lane of afterAll method:
jest.setTimeout(15000);

[hasezoey]

sorry for the late resolution, this +10s you see, is from debug, somewhere in the code there is an empty console log, which happens 10ms after the previous log

closing because original issue is resolved with this

[elieteyssedou]

Thanks !! 🎉

[ChrisLahaye]

Is there anything we can do such that we don't have to wait 10 seconds?

  MongoMS:MongoInstance Mongo[41011]: STDOUT: 2020-11-19T15:26:43.624+0100 I CONTROL  [signalProcessingThread] got signal 2 (Interrupt), will terminate after current cmd ends
  MongoMS:MongoInstance  +1ms
Jest did not exit one second after the test run has completed.

This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.
  MongoMS:MongoInstance Mongo[41011]: STDOUT: 2020-11-19T15:26:53.624+0100 I STORAGE  [signalProcessingThread] Failed to stepDown in non-command initiated shutdown path ExceededTimeLimit: No electable secondaries caught up as of 2020-11-19T15:26:53.624+0100Please use the replSetStepDown command with the argument {force: true} to force node to step down.

[hasezoey]

@ChrisLahaye i dont know what version you are using, but in the latest (non beta) it should run SIGKILL after 10 seconds when the server.stop() is awaited, and in 7.0.0 (beta) it is properly shutdown (with an command instead of signal)

from what i can see and assume latest version being used, you dont seem to await the server.stop

[theseyi]

sorry for the late resolution, this +10s you see, is from debug, somewhere in the code there is an empty console log, which happens 10ms after the previous log

closing because original issue is resolved with this

@hasezoey I'm not quite clear on what the resolution you're referring to is here? Are you saying this will not be present in non debug mode?

I see this in debug mode:

  MongoMS:MongoInstance  +1ms
  MongoMS:MongoInstance Mongo[51849]: kill_internal timeout triggered, trying SIGKILL +10s
  MongoMS:MongoInstance Mongo[51849]: - childProcess: got exit signal, Code: null, Signal: SIGKILL +29ms
  MongoMS:MongoInstance Mongo[51849]: - killerProcess: send "SIGINT" +1ms
  MongoMS:MongoInstance Mongo[51849]: Mongod instance closed with an non-0 code! +1ms
  MongoMS:MongoInstance Mongo[51849]: CLOSE: null +0ms
  MongoMS:MongoInstance Mongo[51849]: MongodbInstance: Instance has failed: Mongod instance closed with code "null" +0ms
  MongoMS:MongoInstance Mongo[51849]: [MongoKiller]: exit - [null,"SIGTERM"] +4ms
  MongoMS:MongoInstance Mongo[51849]: - killerProcess: got exit signal, Code: null, Signal: SIGTERM +0ms
  MongoMS:MongoInstance Mongo[51849]: Instance Finished Shutdown +0ms
  MongoMS:MongoMemoryServer Removing tmpDir /var/folders/ss/dmmpqn_j0236yb9418hzkp8h0000gn/T/mongo-mem--32014-O7eEa7otrVoY +10s

and without

  console.warn
    An Process didnt exit with signal "SIGINT" within 10 seconds, using "SIGKILL"!
    Enable debug logs for more information

      at ../node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:162:21
      at Timeout.task [as _onTimeout] (../node_modules/jsdom/lib/jsdom/browser/Window.js:391:19)

I have

const replSet = new MongoMemoryReplSet({
  replSet: { storageEngine: 'wiredTiger' },
});
await replSet.waitUntilRunning();
const uri = await replSet.getUri();
await timer(2000);

const conn = await MongoClient.connect(uri, {
  useNewUrlParser: true,
  useUnifiedTopology: true,
});

// ...tests happen

// ...then later
replSet.stop();
conn.close();

mongodb-memory-server version = 6.9.6

[hasezoey]

@theseyi from the original question, it was about this line:

  MongoMS:MongoInstance  +10s

which was an result of not removing the \n (new line) from some lines that the mongod process had output
and because its from the package debug, the time that is shown is the difference from when the last log-line from "that module" is logged

---

Your question / problem is not related to this issue (your problem is #411) (which got "hotfixed" (the timeout with this message))
The solution to your problem is to use the beta of this package (currently at v7.0.0-beta.38, the full change (to not have to use SIGKILL) couldnt be backported, because it would break stuff)

[theseyi]

The solution to your problem is to use the beta of this package (currently at v7.0.0-beta.38, the full change (to not have to use SIGKILL) couldnt be backported, because it would break stuff)

Thanks @hasezoey I'll try out the beta version asap. Curious, is there an ETA for when the beta will graduate to a major release?

[hasezoey]

@theseyi

Thanks @hasezoey I'll try out the beta version asap. Curious, is there an ETA for when the beta will graduate to a major release?

not really, it is still in beta, because i couldnt do much "live" testing (on other projects using it), so i am kinda waiting for some feedback, and still want to extend / finish up the migration guide and documentation (at https://nodkz.github.io/mongodb-memory-server/ )