Upgrading 5.10.4 to 5.10.5 cause test run to hang

[josephstgh]

Do you want to request a feature or report a bug?

Might be a bug

What is the current behavior?

Update:

I think I managed to drill down a little but still not quite sure. I isolated to a few more specific test case suite. Will update here once I have more findings. Update: Sorry, wasn't able to find anything conclusive yet..

---

When using 5.10.4, when I ran my test (ts-mocha), it run smoothly as usual without any issue but once I upgrade to 5.10.5, there seem to have some weird issue like "hanging" on the test case. I don't have any error, or anything. Based on the changelog, the only thing it seem to possibly affect is the upgrade of mongodb driver to 3.6.2 but I am not sure where to begin checking.

I'm not sure if it has anything to do with #9203 ? Just a wild guess.

I am still able to run my application without issue, it seem to be affecting the test run now

All test case seem to hit the timeout limit of 10s

I understand this is little to go with, but do let me know what I can do to provide more information

What is the expected behavior?

Test to run as per usual to what it does in 5.10.4 or before

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version.

Working

node: v12.18.4
mongoose: 5.10.4
mongodb: 4.2.0

Not working

node: v12.18.4
mongoose: 5.10.5
mongodb: 4.2.0

[rvillane]

just by chance does your unit test runs any aggregation pipeline ? if so, then you hit the same issue I reported as #9431 a couple of days ago

[vkarpov15]

It may be related. Do you use async iterators in your tests @josephstgh ? Any code samples you can provide would be helpful.

[josephstgh]

@rvillane I don't have any aggregation pipeline in my test

@vkarpov15 I do have some for await usage in my test but doesn't seem to be affected. I haven't have time to go through in more details. I will try to pin down as much as I can to try to repo.

Update back again shortly

[paglias]

I'm trying to create an easily reproducible script but we got a similar problem, a piece of our code and tests started to hand at doc.save()

[paglias]

Ok, in our case it seems that using sinonjs' fake timers to simulate a different date and time is causing doc.save() to hang

[josephstgh]

Ah yes, I'm also using fake timers in some of my test, and it does seem to be hanging there too. I'll verify and update here too

[josephstgh]

Possibly related to #9417

[josephstgh]

I have verified, and I think it is indeed related to fake timers, and I have also tried to used workaround mentioned sinon.useFakeTimers({ toFake: ['setTimeout', 'setInterval'] })

It does seem to work for some of the test but not all. For example, some test case continue to fail even with the workaround. Still trying to figure out why..

[vkarpov15]

Glad to hear this doesn't have anything to do with our aggregation cursor changes. You are right that useFakeTimers causes an issue between v5.10.4 and v5.10.5.

This issue is due to a fix in the MongoDB node driver that allows for better concurrency but relies on setImmediate(): mongodb/node-mongodb-native#2537 (comment) , because setImmediate() is the only reliable way to defer work to the next macrotask of the event loop.

Can you please provide an example of a test that fails even with sinon.useFakeTimers({ toFake: ['setTimeout', 'setInterval'] })? That should be enough to prevent sinon from stubbing out setImmediate() and blocking the MongoDB driver.

[josephstgh]

Apologies, haven't had the time to do so yet. Will try to get an example of that soon. Appreciate your help!

[josephstgh]

Hi @vkarpov15, I am unable to provide an repo as of right now, because of the test setup. I'm still trying to break it down, but this is roughly it..

I am testing kind of a refresh-token mechanism so the flow is something like this

// perform a app login
await usernamePwLogin(); // jwt token will be stored in storage
const token1 = getTokenFromStorage();

// my logic is if it the token is used before some expiry and after certain timing, the token will sort of refreshed
const clock = sinon.useFakeTimers({ now: token1.oat * 1000, toFake: ['setTimeout', 'setInterval']});
clock.tick(someDelay);

// perform an login with existing token should return new set of token
await jwtLogin(token1);
const token2 = getTokenFromStorage();

assert.notStrictEqual(token2, token1); // this should not be the same

so when using 5.10.4, and not using useFakeTimers, the token indeed is different. But after I switched to 5.10.5, and changed to use useFakeTimers, the token is the same. So it kinda seem like the clock hasn't ticked? Note that I have another test case, where it test for before the token refreshes, it compares for same token string and it uses useFakeTimers and the test pass.

---

So I went to look at the API of useFakeTimers and tried to use shouldAdvanceTime: true and this is what I observe. Without using shouldAdvanceTime, my test will "hang" but if I do use it, the test will not "hang" but my test still fails because the token did not change. Am I still missing something?
When I console.log(clock.now) before and after clock.tick(someDelay), the value does seem to be different

If you are able to spot anything from this would be much much appreciated. Thanks!

[vkarpov15]

What does jwtLogin() look like?

[josephstgh]

As I'm using feathersjs framework, it also comes with feathers-client to perform the authentication which eventually triggers this jwtLoginStrategy

I believe triggers this code

https://github.com/feathersjs/feathers/blob/6369f0b93fb2e1b3b20e6f11aa69d862a8d6f5c6/packages/authentication/src/jwt.ts#L117

Sorry, I don't mean to dump the codes/library to you, but I'm not exactly sure what you looking out for. Do let me know if more info is required, or I'm missing your question/point

[paglias]

@vkarpov15 I was going to fix my tests by making sure Sinon didn't overwrite setImmediate but it looks like faking only the Date object causes mongoose to hang as well:

fakeClock = sinon.useFakeTimers(mayMysteryItemTimeframe, { toFake: ['Date'] });

[vkarpov15]

@paglias do you know exactly what code hangs? Is it a query, a save(), something else?

[paglias]

@vkarpov15 so I was writing a test and noticed that I had messed up sinon's syntax. With the correct one nothing hangs as long as only Date is faked. Thanks

[vkarpov15]

@paglias can you please provide the code of the test you wrote?

[vkarpov15]

The below script works fine for me with Mongoose v5.10.9, please modify the below script to demonstrate your issue @paglias @josephstgh 👍

'use strict';
  
const mongoose = require('mongoose');
const sinon = require('sinon');

sinon.useFakeTimers({ toFake: ['Date'] });

mongoose.set('useFindAndModify', false);

const { Schema } = mongoose;

run().catch(err => console.log(err));

async function run() {
  await mongoose.connect('mongodb://localhost:27017/test', {
    useNewUrlParser: true,
    useUnifiedTopology: true
  });

  await mongoose.connection.dropDatabase();

  const Model = mongoose.model('Test', Schema({ name: String }));
  await Model.create({ name: 'test' });

  console.log('Done', await Model.findOne(), new Date());
}

[paglias]

@vkarpov15 with my previous comment I meant that sinon.useFakeTimers({ toFake: ['Date'] }); is working fine for me, it wasn't before because I was using the wrong syntax for SinonJS. So for me the issue is resolved

[josephstgh]

Hi, will be testing out again in next couple days.

[josephstgh]

Hi @vkarpov15, setting toFake: ['Date'] or toFake: ['Date', 'setTimeout'] seem to have solved it for most of my failing test with exception of a couple more.

Those that continues to fail, is not caused by the "hang" issue but my assertion based on sinon.spy. For example, I'm spying on notification - create (I have a notification service), the count does not match what I'm expected. It seem like those failing ones are those that if I'm using both fakeTimers and spy as I have other test cases that uses spy on the same service - notification - create but did not fail. I need to dig a little deeper to figure out what exactly is causing it

I will try to see if I can pinpoint more clearly so I can try to do up a repo so that it can be more easily diagnose. However before I am able to, do you have any suggestion?

Thank you!

[vkarpov15]

It seems very strange that adding 'setTimeout' to toFake would fix tests, I unfortunately don't see how that would help. If you can set up a repo, we should be able to fix this issue, just hard to guess what the issue might be without being able to see it in action.

[josephstgh]

Hi @vkarpov15, I will try to replicate it with a new repo as soon as possible. Thanks for helping!

[josephstgh]

Hi @vkarpov15, I managed to replicate it here

Let me know if there's anything else I can provide with

Thanks!

[vkarpov15]

@josephstgh the issue is that node-schedule uses setTimeout() under the hood to schedule jobs, so you would need to do const clock = sinon.useFakeTimers({now, toFake: ['Date', 'setTimeout']});. If you remove setTimeout from the list of timers to fake, your clock.tick() call won't cause the node-schedule job to fire, because it is using the real setTimeout().

[josephstgh]

So if I were to understand correctly, based on what failing test I have now, I need to understand what sort of timer the libraries use under the hood? And based on that, I would fake it accordingly in order to get the correct behavior?

So it would be one of these based on the docs setTimeout, clearTimeout, setInterval, clearInterval, setImmediate, clearImmediate, process.hrtime, performance.now and Date

[vkarpov15]

@josephstgh that's correct. Which is why we strongly recommend not using useFakeTimers(). When you choose to break your JavaScript environment for testing purposes, you need to be careful that you don't break the libraries you use.

[josephstgh]

In that case, may I know what's the correct way to test when I want to time-jump forward (basically clock.tick) if not using useFakeTimers(). Appreciate if you could point me to the right direction. Thanks!

[vkarpov15]

Stub node-scheduler's schedule() function and assert that it gets called with the correct parameters.

[josephstgh]

This would only assert that it's being called with the correct params but not able to verify the result of the job that is being scheduled isn't it, without ticking the time forward.

Imagine I scheduled a job to run an hour later, and that it will call an update to a doc, or create new doc. Without ticking the time, I am not able verify if the item is updated / created, yes?

I understand this is a little out of scope, but would appreciate if you could help me understand the right approach. Thank you very much.