express 4.10.2 issue with sinon fake timers

[Rovack]

When calling Sinon.JS's useFakeTimers with the most recent version of Express, requests sent to the app aren't answered.

This is caused by the commit titled "Correctly invoke async router callback asynchronously", which changed line 186 of lib/router/index.js from return done(layerError) to setImmediate(done, layerError).

When using fake timers, functions run using setImmediate don't execute until one explicitly ticks forward the clock.

It could be argued this isn't really a problem with Express, and rather the solution is to be sure to tick whenever one issues a request to the app. However, it's not entirely clear to me how this could be done, since one would have to know when Express got to that setImmediate call and only then tick. Further, even if it is possible, it's doubtful many existing tests do this, meaning this breaks a lot of existing code.

Presumably this is also a problem with any other framework that manipulates setImmediate, not just Sinon.

[dougwilson]

I'm not similar with what Sinon.JS even is, but if that is the comment that broke it, it's 100% not a bug in Express. Express simply stopped releasing Zalgo in that comment, i.e. we fixed the behavior of our async callback to be always async instead of sometimes async.

[Rovack]

Sorry, I suppose I should have been clearer.

Sinon.JS is (by far) the most popular stubbing framework for Node.JS (https://nodejsmodules.org/tags/stubs). One of the features it offers is "fake timers", which make it possible to manipulate time as needed - rather important functionality for any tests that deal with time-sensitive logic.
To do this, Sinon has to override several global functions, such as setTimeout, setInterval, and, as it happens, setImmediate.

Now, sadly I'm not sufficiently familiar with the internals of Express, so I'm not sure what you mean by it previously being "sometimes async". However, I would guess that for tests, where the app is wrapped by something like supertest, it generally is synchronous.

I could definitely be wrong about that, but what I can say for certain is that before this commit, the following code would work, and now it doesn't:

var request = require('supertest');
var sinon = require('sinon');
var clock = sinon.useFakeTimers();
var app = require('../app');
return request(app).get('/some/url').end(function() {
  console.log('Success!');
});

Either way, I think it would be wise to have someone who's more familiar with testing look this over. They may be able to provide insights into how this scenario can be handled with the current Express version, or suggest fixes if it can't. Wouldn't you agree?

P.S. In our specific project it turned out we didn't really need to override setImmediate specifically (it was setTimeout, setInterval and Date that mattered to us), so the solution was just to re-override setImmediate with its original value after calling useFakeTimers. There's a few nuances to getting this right, and obviously it isn't a very elegant solution, but in our case it proved sufficient.

[dougwilson]

Either way, I think it would be wise to have someone who's more familiar with testing look this over.

I am the authority on Express; there is no one else who will look this over, but if someone who actually knew how Sinon.JS worked could determine if it's a Sinon bug or not would be great. Please point them here :)

Now, sadly I'm not sufficiently familiar with the internals of Express, so I'm not sure what you mean by it previously being "sometimes async".

Literally if this change broke Sinon.JS it's a bug in Sinon or how you were using it. There is zero chance it is a bug in Express. You even said youself it should be async from your view, so just adding a setImmediate call would not make it look any different to how you're using it, but without it, it caused very real-world bugs and server crashes. The change you highlighted will never be reverted, but just because that change may have affected Sinon doesn't mean that it was specific the setImmediate call; the sometimes async behavior (which is very bad behavior) may have been masking a bug in Sinon.

Perhaps this bug applies to you? sinonjs/sinon#603 if so, then it's a mocha bug: mochajs/mocha#1435 which has literally just been fixed and nothing yet published. Our new use of setImmediate probably brought that mocha bug into the light. Please try npm install mochajs/mocha to get the very latest mocha to test it out.

[Rovack]

Thank you for your detailed answer.

It's definitely possible that I'm using Sinon wrong, or that Sinon doesn't work well when requests are handled asynchronously. The reason I bring it up as an issue with Express is that code which used to work (deterministically) in previous versions doesn't work with Express 4.10.2, so I figured you'd want to be notified.

I actually didn't say that it should be asynchronous from my view, I said it should be synchronous (because of supertest etc), but maybe I really can't assume that.

I also didn't say the change should be reverted, but rather had hoped someone might have a fix that would avoid these real-world problems while also making it possible to test Express apps with standard testing tools.

Better yet, it would be great if someone could point out what I'm doing wrong and what the proper way to use Express/Sinon in these scenarios is, if there is one.

However, I should clarify that I definitely was not asking what the "bug" was; there's no question that the problem was created when that line changed, simply because changing it back to return done(layerError) makes the code work again. :)

There's also no question about the reason the change caused this problem: when fake timers are in effect, setImmediate don't execute until a "tick" function is explicitly called, as I mentioned in my original comment.

So, this isn't related to the mocha bug, but thank you anyway for the suggestion and for providing those links.

At any rate, I already have a workaround that works for my use-case. I fear other projects, that actually do need Sinon's setImmediate override, may not find it so easy to work with Express 4.10.2, but if you think there's nothing that can be done to solve this, that's up to you.

[dougwilson]

The reason I bring it up as an issue with Express is that code which used to work (deterministically) in previous versions doesn't work with Express 4.10.2, so I figured you'd want to be notified.

I'm sorry, but the code was because Express < 4.10.2 was not deterministic. That line made it deterministic.

Take for example this:

var express = require('express');
var request = require('supertest');
var sinon = require('sinon');
var clock = sinon.useFakeTimers();
var app = express();
app.get('/', function (req, res) {
  res.end();
});
return request(app).get('/some/url').end(function() {
  console.log('Success!');
});

vs

var express = require('express');
var request = require('supertest');
var sinon = require('sinon');
var clock = sinon.useFakeTimers();
var app = express();
app.get('/some/url', function (req, res, next) {
  setTimeout(function(){
    // nevermind, after a db lookup, i don't want to handle this route
    next();
  })
})
return request(app).get('/some/url').end(function() {
  console.log('Success!');
});

The first app used to fall into the 404 handling code (which is outside of Express code) sync, while the second app would fall into it async. This was not deterministic from the view point of the external 404-handling code (which people can point anywhere). As of 4.10.2 it is not always async.

I also didn't say the change should be reverted, but rather had hoped someone might have a fix that would avoid these real-world problems while also making it possible to test Express apps with standard testing tools.

I would like to understand what is going wrong, but I don't have any available time to understand what Sinon.JS is doing or even what it is. If someone who is knowledgeable can put together some code and explain what the cause of the error is (not the symptom is), and if it's something that can be fixed here or in Sinon.JS, then awesome! If there is a bug in Express, the fix is not removing the setImmediate, but something else. If someone can determine what that fix is, please make a PR or explain it and we can fix it.

there's no question that the problem was created when that line changed, simply because changing it back to "return done(layerError)" makes the code work again. :)

Once again, this did not create a bug, but only revealed a bug that already existed because some behavior changed that should not have matter to Sinon.JS. There is a difference.

There's also no question about the reason the change caused this problem: when fake timers are in effect, setImmediate don't execute until a "tick" function is explicitly called, as I mentioned in my original comment.

Interesting. So, I would like to understand what that means, but it almost seems like it's using some terms that are Sinon.JS-related, right? I think my non-understanding of what Sinon.JS even is is blocking me from fully groking that sentence :(

I fear other projects, that actually do need Sinon's setImmediate override, may not find it so easy to work with Express 4.10.2, but if you think there's nothing that can be done to solve this, that's up to you.

We are using a feature of the Node.js platform. The sentence to me reads: "Sinon.JS does not handle setImmediate well, can you just not use it?". I'm not sure if that's very fair to ask Node.js library to reduce their use of Node.js features to assist with third-party libraries trying to patch globals. Our view on patching globals like setImmediate, Date, etc. is that you have to make them fully compliant with the existing functionality of Node.js core.

If you can provide me with a test case that does not use Sinon.JS that fails, I can 100% add it to the test suite and fix Express to work.

[blakeembrey]

@dougwilson Figure I'll try to help out briefly. What Sinon.js does is patch global date/timer related functions for testing. The timed functions won't run unless you trigger a tick in Sinon.js. The issue that now occurs now would be that setImmediate has been patched and you would need to trigger a tick for it to respond. A potential patch may be to keep a reference to the global setImmediate locally, but it won't fix when it's patched before Express runs and it's a little jank.

@Rovack Does that just about sum the issue up?

[dougwilson]

The issue that now occurs now would be that setImmediate has been patched and you would need to trigger a tick for it to respond.

Ohhhh, I fully understand now. Would using process.nextTick work? The reason I choose to use setImmediate instead of process.nextTick, though, is that unfortunately if I use process.nextTick, certain Node.js applications would then start printing out the following:

(node) warning: Recursive process.nextTick detected. This will break in the next version of node. Please use setImmediate for recursive deferral.

[blakeembrey]

I think nextTick would work, it's not patched IIRC. Still, aliasing locally seems like a better fix var immediate = setImmediate.

[dougwilson]

I think nextTick would work, it's not patched IIRC

Yes, but it produces those warnings I listed above.

Still, aliasing locally seems like a better fix var immediate = setImmediate.

If that works, I can definitely do it, but people are going to have problems with many of our dependencies which use setImmediate for deferrals, on the recommendation of Node.js core itself. My main reservation to this is change this one piece is only trying to fix the symptom, not the problem. Next thing you know, you're going to have to start asking all libraries on npm to bend over backwards and keep local copies of setImmediate so they do not interfere with Sinon.JS.

[dougwilson]

In general, I don't think it's ever possible to fully understand when you should be calling this Sinon.JS's tick function when you get lots of dependencies involved; everything you are doing this, you are being the intricate implementation details of what you are testing into your test code. When you are testing more than just your own code, changes in those dependencies that have no effect on tests that do not rely on implementation details will only cause your tests to fail if you are relying on those details. This is basically going into unit testing theory and is another topic.

But, Express stands by mocking is absolutely not supported in any way for testing. Overriding setImmediate in such a way that you have to now control it's invocation manually is akin to mocking.

I'm glad I now understand what the issue is, but I'm sorry to say we disagree on who's issue it is. In my opinion, as soon as you're asking to manually control all setImmediate invocations, then it is now your responsibility to follow through on that and call them. You should treat upgrading a dependency the same as your own code changing. Just like if you added a new setImmediate call in your code that doesn't change the output in any way would require you to add another tick increment in your test code, upgrading a dependency that does the same brings the same responsibility.

If benign changes in dependencies break your tests, you have just discovered you have been including internal implementation testing of your dependencies in your tests! senchalabs/connect#1059 is a recent example in connect and now connect does absolutely no mocking and no longer relies on internal implementation details of it's dependencies.

[rlidwka]

Next thing you know, you're going to have to start asking all libraries on npm to bend over backwards and keep local copies of setImmediate so they do not interfere with Sinon.JS.

It's already started.

[dougwilson]

The other thing is that if you need to control what Date.now() is returning, you are not using good dependency injection, which is why your tests are so hard to write. If you have to write a mock, then the code that requires a mock is not written well. Code written well will allow dependency injection, like for example if you are testing a library that uses timers, the use of timers should be completely extracted into a specific class and you can use dependency injection to inject a different implementation of that class for all testing except for the testing on that class itself.

[Rovack]

That's exactly right - "except for the testing on that class itself", which is a problem.
Well, that and any end-to-end "acceptance" test in which you want to include your entire system, for a story that involves time. But I don't know how you feel about that kind of test.

Either way, I can't agree that if any test requires time manipulation then it's a problem with the code.
There is a reason people use Sinon's fake timers: when you want to test a module that's inherently time-related, you need to "inject" a different implementation of time.

You have, however, convinced me that this isn't a problem with Express alone.
A proper solution will have to come in the form of a pattern suitable for these tests, or some new feature in Sinon.

Nevertheless, I would think the fact that the new version breaks any test code that uses fake timers, even if it's entirely out of your control, should be documented somewhere.
Even if we disagree on whether using fake timers is bad practice or not, the fact remains it is an existing practice, and you don't want people having to struggle themselves to figure out why their tests suddenly stopped working when they updated Express.

[dougwilson]

or some new feature in Sinon.

Sinon could add a feature that only injected the fake timers into specific files, so maybe that's a possibility? I'm not familiar enough with your workflow to understand if restricting the injection to specific files (or even directories) is useful, but if it is, Sinon could easily implement it by injecting globally like it does now, but inspecting the call stack to determine if it should fake or not.

should be documented somewhere.

I can probably do that. Where was the first place you looked to find documentation when you ran into the issue/where do you think I should put it? Do you have any suggestions for the wording that does not mention Sinon.JS specifically (since it's a general issue)?

[Rovack]

The first place I looked was History.md, though having looked at it, it doesn't seem like that's the sort of information it usually contains.
Not sure where else documentation regarding known issues could go, though.

As for phrasing, I think you could just say that Express now uses setImmediate before sending responses, so if setImmediate is overridden in a project, namely for testing with fake timers, these tests may become stuck.

[dougwilson]

now uses setImmediate before sending responses

So, it only uses setImmeidate before a 404 or error response, and even then, it depends on if you've added your own 404 or error handlers. And then, it depends on how many routers you used in your project, which ones they happened to traverse, etc. The number of times setImmediate is called is strictly tied to your app's code.

[dougwilson]

res.sendFile and res.sendfile also use setImmediate internally, and when they call it depends on what the client did, so you don't have a way to control it's timing from your code (on-finished internally calls setImmediate depending on the conditions of the reqest).

When the default error handler is calling, the finalhandler dependency internally calls setImmediate to invoke the logging function as well.

Not sure where else documentation regarding known issues could go, though.

Currently there are no known issues with Express, otherwise they would be fixed. As for known issue when a user combines two different libraries together, I'm not sure where that would go. Perhaps on the expressjs.com website (issues for that at https://github.com/strongloop/expressjs.com)?

What it sounds like you're asking for is a through document of all possible times Express and all of it's dependencies may call setImmediate or setTimeout so you'll know when you tick fake timers to match, correct? The problem is, no reasonable project would document this, because it's not a public API and would be on the same lines of documenting just every single call and when a library calls something in Nore.js core, since they all have the potential to be overwritten.

[Rovack]

Oh, I don't think it's necessary to go into all the possible times the call may happen, and I agree it doesn't sound at all realistic.
I was thinking about more of a general comment, simply stating that in version 4.10.2 a setImmediate call was added that now makes tests with fake timers get stuck. This wouldn't let people know when to tick fake timers, it'd just make them aware that there might be a problem and to what it's related.

Though, going by what you're saying here, it sounds like there are many cases where this problem would've already appeared in previous versions.
The question is, was the setImmediate call in those cases necessary for getting a response from the app? I'm pretty sure the new call actually stopped me from getting one when the app was going to return a plain old 200, so are you sure it should only affect 404/error responses?

[dougwilson]

so are you sure it should only affect 404/error responses?

The answer depends on your app. See #2447 (comment) for a better explanation. If your app consists only of app and app[VERB] and stuff, then only 404/error. If you use external middleware, then it depends on if that middleware internally uses a router. Also depends on if you are using multiple routers, etc.

[dougwilson]

So if you post a full app and what method and path you are making a call with, I'd be happy to tell you where the setImmediate is getting called. Here are a few examples:

var express = require('express')
var request = require('supertest')
var app = express()

// This invokes setImmediate since it's a default 404
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.get('/', function (req, res) {
  throw new Error()
})

// This invokes setImmediate since it's a default error
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.get('/', function (req, res) {
  res.send('hello, world')
})

// This never invokes setImmediate
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.use(express.Router())
app.get('/', function (req, res) {
  throw new Error()
})

// This invokes setImmediate since it passes through a router that doesn't handle the request
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.use('/api', express.Router())
app.get('/', function (req, res) {
  throw new Error()
})

// This never invokes setImmediate, since the URL does not invoke the second router
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.get('/', function (req, res) {
  res.send('hello, world')
})
app.use(express.Router())

// This never invokes setImmediate because the second router isn't reached since GET / is handled before it
request(app)
.get('/')
.end(function(){process.exit()})

var express = require('express')
var request = require('supertest')
var app = express()

app.get('/', function (req, res) {
  throw new Error()
})

app.use(function (err, req, res, next){
  res.send('error!')
})

// This never invokes setImmediate because there was an error handler that responded
request(app)
.get('/')
.end(function(){process.exit()})

There are many more examples I can put, but I hope that helps understand when and when not the setImmediate gets invoked by some examples. My offer to tell you when setImmediate still stands if you post the full, complete app code.

[dougwilson]

In the end, we are not going to add a note about this anywhere. I would rather revert the change instead and bring back the critical errors that could have occurred (like errors being reported multiple times, etc.). @bajtos can weigh in, as I believe he had the biggest need for this change and maybe he/StrongLoop can wait until Express 5.0.

[dougwilson]

@Rovack I see you have a little project at https://github.com/Rovack/deploy-test . Can you tell me a method + path to call that would cause a 200 to call setImmediate? Doing GET / on your app returns Hello World. without invoking setImmediate, but that's because it never crosses a router-exit-boundary, which is when the setImmediate is called.

[Rovack]

Naturally that's not the project to which I was referring. The one I was talking about is in a private company repo, and I'd have to get approval to share it.
Anyway, I don't think that's necessary, as the multiple routers/middleware explanation makes sense.

[bajtos]

In the end, we are not going to add a note about this anywhere. I would rather revert the change instead and bring back the critical errors that could have occurred (like errors being reported multiple times, etc.). @bajtos can weigh in, as I believe he had the biggest need for this change and maybe he/StrongLoop can wait until Express 5.0.

Here is the discussion capturing my needs: expressjs/expressjs.com#270

In essence, if the callback function passed to app.handle throws an error (e.g. via assert in unit-tests), the express invokes the callback again with the new error:

var assert = require('assert');
var app = require('express')();
app.use(function(req, res, next) { next(); });

function callback(err) {
  console.log('done', err && err.name + ' ' + err.message || 'ok');
  // simulate a failing test
  if (!err) assert(false);
}

var server = http.createServer(function(req, res) {
    app.handle(req, res, callback);
});
request(server)
  .get(urlPath)
  .end(function(err) {
    if (err) return callback(err);
  });

// output:
//   done ok
//   done AssertionError false == true

Honestly, I don't mind whether the callback is called sync or async, as long as it is called only once. I am sure there is a way how to prevent double invocation while preserving the old sync behaviour?

However, if the fix in 4.x would be too difficult to implement and the double invocation problem is already fixed in 5.0 in a more clean way, then I can live with the old behaviour and fix my unit-tests to use setImmediate before invoking the callback.

[Fishrock123]

In essence, if the callback function passed to app.handle throws an error (e.g. via assert in unit-tests), the express invokes the callback again with the new error:

Oh god no. superagent was bugged up for me doing this and it was terrible.

err should only ever be an error upstream of the call, erroring and re-calling is surprising and inconsistent.

[Fishrock123]

EDIT: Oh ok, I thought the functionality was being changed to do that. It was fixed, all is good.

Honestly, I don't mind whether the callback is called sync or async, as long as it is called only once. I am sure there is a way how to prevent double invocation while preserving the old sync behaviour?

Yeah this. (unless async has some benefits that I am unaware of.)

[dougwilson]

Async is the only possible solution, otherwise either the error is lost into oblivion and never thrown, since the call stack will have dozens of trys. Invoking the callback async (as is the node.js promise anyways and does not release zalgo) is the best solution to not double-invoking and not losing the error into oblivion.

Really, before this was fixed, I could only image the production hair-pulling multiple error invocation would have caused, especially when it used to also loose errors in some cases.

[Fishrock123]

Really, before this was fixed, I could only image the production hair-pulling multiple error invocation would have caused, especially when it used to also loose errors in some cases

Yes. This is definitely no going to warrant reverting that fix.