Closed Bug 1437193 Opened 6 years ago Closed 4 years ago

ensure that res.status is not called multiple times

Categories

(Taskcluster :: Services, defect)

Product:
Taskcluster
Component:
Services
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: dustin, Unassigned, Mentored)

Details

(Keywords: good-first-bug)

Attachments

(1 file)

two other tests
1.62 KB, text/plain
Details 
Simple errors like a forgotten await can end up with an API method calling `res.send` twice with different results.  This should raise alarm bells that would cause tests to fail and tracebacks to go to sentry.
This fix would be in the taskcluster-lib-api library.
Mentor: dustin
Hey, Can I work on this bug ? Some guidance on how to approach it would be appreciated. 
Thanks !
Sure!

Have a look at https://github.com/taskcluster/taskcluster-lib-api.  You'll want to get familiar with Express.js too.

A good way to start would be to add a test case to taskcluster-lib-api that calls res.status(200) twice in the same request.  We want the second time to be an error, but right now it's not.

The next step will be to figure out if Express can be configured to detect this and throw an exception.  If not, then we'll need to figure out how to throw that exception ourselves.
Summary: ensure that res.send is not called multiple times → ensure that res.status is not called multiple times
Thank you for the guidance Dustin!
I will start working on it.
Hello Dustin,

Checking the value of res.headerSent can be used to determine whether res.send is being called the second time. Have I understood it correctly ?
Yes, that sounds about right.  It is probably worth looking at the Express source code to see if res.send checks res.headerSent.  It seems like it does not!
We can throw an exception when res.send is called the 2nd time, as -

`if (res.headersSent) throw new Error('Multiple responses from same request');`

Is this correct ?
That sounds good, yes :)
I assume the test cases can be added in test/auth_test.js file. How do I run the tests ? I am new to Express.js, So a little help on how to test whether my changes are working would be appreciated.
Thanks!
It's probably best to add a new test file for this, patterned after auth_test.js.

The test files have this format:

suite(
  // declare an API
  // setup
  // teardown
  // tests
)

So I think you could start by declaring an API with one method that calls res.status(200) twice.  Then add a test that calls the API method and checks that it returns a 500 status, not 200 :)

...actually, that won't work.  The first call to res.status(200) will succeed and send the 200 response before the second call happens.  Ugh.

Brian, do you have an idea how to test this, based on your recent work with req.authorize?

Akshatha, please make a pull request with your changes, that passes all of the existing tests.  We can do some review on that while we figure out how to write the tests :)
Flags: needinfo?(bstack)
Before we write a test for this, we should either land or reject something I just put up for review [0]. It is just a change to test/auth_test.js in an attempt to clean it up and make it easier to understand.

Once we decide the status of that, we can add a test that uses side-effects to test. We pass a mock lib-monitor instance into api methods and then assert certain things about the mock are true afterward in a few other places [1]. You can see the mock implementation in [2]. This may be a good place to assert that reportError was called on lib-monitor in the tests rather than asserting return codes. I will be doing a similar thing to check for regressions in authorize().


[0] https://github.com/taskcluster/taskcluster-lib-api/pull/78
[1] https://github.com/taskcluster/taskcluster-lib-api/blob/d4aadf0405a0051db523390468184f7e4e3c30d4/test/responsetimer_test.js#L69-L78
[2] https://github.com/taskcluster/taskcluster-lib-monitor/blob/master/src/mockmonitor.js#L16
Flags: needinfo?(bstack)
I am getting the following error when I try to run the tests -

akshatha@akshatha-HP-15-Notebook-PC:~/taskcluster-lib-api/test$ mocha auth_test.js
/home/akshatha/taskcluster-lib-api/test/auth_test.js:1
(function (exports, require, module, __filename, __dirname) { suite('api/auth', function() {
                                                              ^
ReferenceError: suite is not defined
    at Object.<anonymous> (/home/akshatha/taskcluster-lib-api/test/auth_test.js:1:63)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Module.require (module.js:604:17)
    at require (internal/module.js:11:18)
    at /usr/local/lib/node_modules/mocha/lib/mocha.js:231:27
    at Array.forEach (<anonymous>)
    at Mocha.loadFiles (/usr/local/lib/node_modules/mocha/lib/mocha.js:228:14)
    at Mocha.run (/usr/local/lib/node_modules/mocha/lib/mocha.js:536:10)
    at Object.<anonymous> (/usr/local/lib/node_modules/mocha/bin/_mocha:582:18)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:190:16)
    at bootstrap_node.js:662:3

Initially I was getting this error when trying to run `node auth_test.js`
Some links on the Internet suggested mocha needs to be installed and added to dependencies. But even after running the tests with mocha, it still doesn't seem to solve the issue. Please help and let me know if I am doing something wrong. Thanks !
If you run `yarn` and then `yarn test` does that still happen? We use https://yarnpkg.com/ to manage dependencies.
Thanks Brian. That fixed the issue.

I have made a pull request with the changes I discussed in comment 7.
https://github.com/taskcluster/taskcluster-lib-api/pull/80

Please review. 
Thanks!
Assignee: nobody → akshanayaki
Akshatha appears to have stopped working on this..
Assignee: akshanayaki → nobody
Hi Dustin. Can I take this task up ?
Assignee: nobody → tuhinatwyla
Please do!
Assignee: tuhinatwyla → nobody
Keywords: good-first-bug
Hey! Can I take up this bug? I am new so I would like to do this as my good first bug and I would also appreciate any help offered.
Sure!  Hopefully there's enough context above to get started?
Assignee: nobody → rishabh.budhiraja
Yes there is! I'll not hesitate to ask if I get stuck anywhere!
Hey Dustin! I could write a test case which would check if res.sent() is being sent twice or not. I wanted to ask you, that out of the 49 tests that were before I added mine, 38 were passing, 1 is pending and 10 were failing. Was it like that or did I mess something up or am I missing something here?
Regarding the test cases, the one pending makes sense.  However, the rest should all pass.  What errors are you seeing?

And just to make sure we're thinking of the same thing: what we need to do is make sure that any code *using* this library fails if it calls res.send() twice.  So just adding something under tests/ in taskcluster-lib-api won't be enough (since that code isn't run by users of the library).
Rishabh, how is this going?
Flags: needinfo?(rishabh.budhiraja)
Assignee: rishabh.budhiraja → nobody
Component: Platform Libraries → Services
Flags: needinfo?(rishabh.budhiraja)

Hi Dustin!
Can I work on this bug?

Sure! You can find res.reply defined at
https://github.com/taskcluster/taskcluster/blob/73730cd7bf12b86df82d3dd17a46d2186b4cac9f/libraries/api/src/middleware/schema.js#L66
and you'll want to look at the README in
https://github.com/taskcluster/taskcluster/blob/73730cd7bf12b86df82d3dd17a46d2186b4cac9f/libraries/api
to understand what the api library does.

A good place to start is to write a test case for the api library where the test case defines an API method that calls res.reply twice, and see what happens. Once that's done, we can work in improving it.

Assignee: nobody → himanshusahu31

Thank you for the references, Dustin!

So I did as you suggested. I tested the following scenarios:

  1. Call res.reply twice, both without parameters. like res.reply() --> No errors

  2. Call res.reply twice, both with parameters. like res.reply({a: 1}) --> Errors at console

  3. Call res.reply twice, with(1st call) and without(2nd call) parameters. --> Errors at console

  4. Call res.reply twice, without(1st call) and with(2nd call) parameters. --> Errors at console

  5. Call res.reply twice, with empty json(1st call - like res.reply({});) and without(2nd call) parameters. --> Errors at console

  6. Call res.reply twice, without(1st call) parameters and with empty json(2nd call - like res.reply({});). --> Errors at console

There are errors in the console for the second res.reply. Below is the error:
Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client
at ServerResponse.setHeader (_http_outgoing.js:470:11)
at ServerResponse.header (/home/himanshu/open-source-projects/taskcluster/node_modules/express/lib/response.js:767:10)
at ServerResponse.send (/home/himanshu/open-source-projects/taskcluster/node_modules/express/lib/response.js:170:12)
at ServerResponse.json (/home/himanshu/open-source-projects/taskcluster/node_modules/express/lib/response.js:267:15)
at /home/himanshu/open-source-projects/taskcluster/libraries/api/src/middleware/express-error.js:99:41
at Layer.handle_error (/home/himanshu/open-source-projects/taskcluster/node_modules/express/lib/router/layer.js:71:5)
at next (/home/himanshu/open-source-projects/taskcluster/node_modules/express/lib/router/route.js:135:13)
at Promise.resolve.then.then.catch (/home/himanshu/open-source-projects/taskcluster/libraries/api/src/middleware/handle.js:28:14)
at process._tickCallback (internal/process/next_tick.js:68:7)

I've also tried to test res.send calling them twice for a simple API. The behavior for res.send is also similar for the above scenarios except for scenario 5 where there were no errors.

Kindly, let me know the next steps.

It looks like express is giving an error for most of those situations. However, #1 concerns me -- that should be an error too!

When you tested these things, did you write tests to do so, or were you doing the testing by hand? I'd like to have unit tests that check all six situations.

I had written the test cases as specified in Comment 10.

Regarding case #1, I found an interesting thing. The errors also appear for #1, but it's failing intermittently. Tracing the error, I found that express is not throwing the error, instead nodejs is throwing the error.
When the second res.reply is passed empty, null or undefined as parameter:
https://github.com/nodejs/node/blob/master/lib/_http_outgoing.js#L541
When the second res.reply is passed a valid object:
https://github.com/nodejs/node/blob/master/lib/_http_outgoing.js#L483

When express tries to set/remove header for the second res.reply, it is rejected by node since the header has already been set.
https://github.com/expressjs/express/blob/master/lib/response.js#L767
https://github.com/expressjs/express/blob/master/lib/response.js#L210

Analyzing further, since the two res.reply are async, if the second res.reply reaches the setHeader/removeHeader in nodejs before the header has been set for first res.reply, this may behave unexpectedly.

Thus, for all the test cases, the error may or may not be thrown. Until now I've not encoured this but it's a possibility.

Please let me know how to proceed on this.

Hm, good research, I'm impressed!

I think that we could probably make this all a lot more explicit by including our own only-once logic in res.reply, to catch the issue before express and Node's http implementation get a chance to do so. That should allow us to catch case #1 reliably, as well as all of the other cases. What do you think?

Thank you! :)

Sounds good to me. I think we can keep track of whether 'res.reply' has been called before or not by using a local boolean variable 'executed'. This can be achieved by closures. So, 'res.reply' if called for the first time will invert the variable and all subsequent calls to it will enter the if condition when 'executed' is true. Then, we can handle this the way we want. What do you suggest?

Another question, do we plan to throw an error when encountered with multiple calls to res.reply or silent ignore them with a 'return;'?

A boolean sounds good. And definitely throw an error -- calling res.reply twice is a sign of a serious programming error in the api method implementation, and hiding that would not be good.

So can I implement a solution for this as well as add the tests and raise a PR?

Also, should I add the tests in someplace existing or create a new test file for this?

Yep, a PR sounds good.

https://github.com/taskcluster/taskcluster/blob/master/libraries/api/test/validate_test.js might be a good place for the new tests. Feel free to add a new sub-suite to that file if that makes sense to you.

I have implemented the solution to throw an error. But writing the tests are tricky since the response from the first res.reply() is sent successfully to the client(in our case the test). The error is thrown for second res.reply() and appears in the console.

I have looked up the express project for references and found out they have not written tests for such a scenario.

Errors should be handled by calling monitor.reportError. There is a "mock" mode for the monitor that allows you to make assertions on what it was called with. "Reporting an error" is really just a special form of log message. You can see some assertions about log messages here. Hopefully that helps!

Himanshu: are you still working on this?

Flags: needinfo?(himanshusahu31)
Assignee: himanshusahu31 → nobody
Flags: needinfo?(himanshusahu31)

Hello Dustin, Can outreachy applicant take up issues from Bugzilla too. If yes, I can try working on it.

Sure thing! There's a lot of context in the above comments, so have a careful look there.

Assignee: nobody → vishakhanihore.10

Great, I will take a look and ensure a PR :+1
:

(In reply to Vishakha Nihore from comment #39)

Great, I will take a look and ensure a PR :+1

Vishakha: are you still working on this?

Flags: needinfo?(vishakhanihore.10)
Assignee: vishakhanihore.10 → nobody
Flags: needinfo?(vishakhanihore.10)

Hi,

I think I have implemented the tests for this but they seem to contradict this comment
https://github.com/taskcluster/taskcluster-lib-api/pull/80#issuecomment-367839970

here is the test for the first test case that, according to the comment doesn't trigger an error:

    const builder = new APIBuilder({
      title: 'Test Api',
      description: 'Another test api',
      serviceName: 'test',
      apiVersion: 'v1',
    });

    builder.declare({
      method: 'get',
      route: '/test-double-json-send',
      name: 'testDoubleSend',
      output: 'test-schema.yml',
      category: 'API Library',
      title: 'Test End-Point',
      description: 'place to call to trigger a double send',
    }, function(req, res) {
      res.status(400).json({error: 'yep'});
      res.status(200).send('OK');
    });
    const url = u('/test-double-json-send');
    return request.get(url).then((res) => {
      assert(false, 'Error didn\'t trigger');
    }).catch(() => {
      assert(true, 'Error was triggered');
    });

And this test passes.

I think I'm missing something but after re-reading the comments I can't seem to find it.

Any help would be appreciated.

Attached file two other tests — 
I should clarify,

I also tested the other 3 scenarios with the following code
```

I should clarify,

I also tested the other 3 scenarios with the code in 'two other tests'

Ah, I think there's some confusion over two uses of "error". All three of those test cases should both

  1. return a 400 status to the request.get call
  2. log a JS error via the monitor

Here's how that breaks down:

      res.status(400).json({error: 'yep'});

this sends an HTTP response to the caller with the 400 status (1).

But the real bug we want to prevent here is subsequently calling

      res.status(200).send('OK');

By the time that call occurs, we've already sent the HTTP response, so it's too late to change it. The best we can do is call monitor.reportError, which will end up logging an error to the service's logs. We have systems in place to pick up those errors and email us about them in production. And in tests for services, tc-lib-testing will cause the test to fail if such an error is logged -- exactly what we want.

So in addition to the tests you've written so far, you'll want to add some assertions that an error is logged. You can see some examples of testing for logging here. Note that if you run the tests with DEBUG=*, you can also see the logging in the output (with lots of other stuff). I'd also suggest using -b to bail out when the first test fails, and --grep to run only one test:

DEBUG=* mocha test/auth_test.js -b --grep 'calling send twice with status json'

(assuming your new test cases are in auth_test.js - otherwise change the filename in the above).

I see.

I'll add the code, modify the tests and come back with a PR.

Thank you for your help.

I'm currently preparing my PR and there doesn't seem to be an issue associated with this bug.
Would you prefer it if I added one or should I not add a changelog entry?

You can reference this bug in the changelog entry with yarn changelog --bug 1437193 --patch

Louis: are you still working on this? It's the final blocker for bug 1436000.

Flags: needinfo?(louiscontant)

Hi, Yes I'm still on this. I'm trying to capture res.send to trigger the error if it's called after another function that uses it, but have not been able to do it so far.

Flags: needinfo?(louiscontant)

THanks @louiscontant!

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: