Express: Debugging ERR_HTTP_HEADERS_SENT errors in res.render

[jstarmx]

I work on a large Express app with a lot of async code. Occasionally due to a bug we are calling res.render twice, the second of which causes a ERR_HTTP_HEADERS_SENT: Cannot set headers after they are sent to the client error which crashes the app 🤯

I think that due to the nature of render using an async callback, the stack trace is meaningless in terms of identifying where this errant render call was made. E.g.

Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client
    at ServerResponse.setHeader (_http_outgoing.js:467:11)
    at ServerResponse.header (/usr/src/app/node_modules/express/lib/response.js:771:10)
    at ServerResponse.send (/usr/src/app/node_modules/express/lib/response.js:170:12)
    at done (/usr/src/app/node_modules/express/lib/response.js:1008:10)
    at render_file (/usr/src/app/node_modules/hbs/lib/hbs.js:49:14)
    at ReadFileContext.callback (/usr/src/app/node_modules/hbs/lib/hbs.js:168:16)
    at FSReqCallback.readFileAfterOpen [as oncomplete] (fs.js:232:13)

🤷‍♂️

I have managed to debug it by monkey-patching res.render and res.send:

app.use((req, res, next) => {
    const render = res.render;
    const send = res.send;
    res.render = function renderWrapper(...args) {
        Error.captureStackTrace(this);
        return render.apply(this, args);
    };
    res.send = function sendWrapper(...args) {
        try {
            send.apply(this, args);
        } catch (err) {
            console.error(`Error in res.send | ${err.code} | ${err.message} | ${res.stack}`);
        }
    };
    next();
});

Which prevents the crash and changes the logs to:

Error in res.send | ERR_HTTP_HEADERS_SENT | Cannot set headers after they are sent to the client | Error
     at ServerResponse.renderWrapper [as render] (/usr/src/app/app/server.js:289:15)
     at index (/usr/src/app/app/controllers/home-controller.js:88:21)
     at processTicksAndRejections (internal/process/task_queues.js:89:5)

The second last line is the exact place the second render call occurred 🎉

Question is, is this a terrible approach? Is there a better way? Or is there potential to make this kind of debugging easier in Express?

[wesleytodd]

So there is not a great way to debug this better than what you are doing. The typical cause of this error is calling next but then not return'ing in an error condition, for example:

app.use(async (req, res, next) => {
  try {
    await someAsyncThing()
  } catch (e) {
    next(e) // <- see no return
  }

  res.send(200)
})

So when I hit this issue that is the pattern I look for. In this case, we might be able to improve the stack trace, but I am not sure it would help you because it would be the stack trace for only the second time send is called, but your issue is most likely with the first time not return'ing.

[jstarmx]

Thanks very much for your reply @wesleytodd. Yeah I have seen this pattern as a regular cause of this error.

I think what I'm getting at is slightly different as it's specifically regarding the render function. Let's say we have this extremely simplistic example:

// index.js

app.get('/', (req, res) => {
  try {
    throw new Error();
  } catch (err) {
    res.render('error');
  }

  res.render('home');
});

Hitting this route will result in the ERR_HTTP_HEADERS_SENT error. And yes the fix would be the same i.e. returning the first call to res.render.

The issue here is that the stack trace for this situation does not even reference index.js at all (only modules and internals), which makes pinning down the root of it extremely difficult if this is one of many routes in a large application.

Error [ERR_HTTP_HEADERS_SENT]: /home/runner/views/home.hbs: Cannot set headers after they are sent to the client
    at ServerResponse.setHeader (_http_outgoing.js:470:11)
    at ServerResponse.header (/home/runner/node_modules/express/lib/response.js:771:10)
    at ServerResponse.contentType (/home/runner/node_modules/express/lib/response.js:599:15)
    at ServerResponse.send (/home/runner/node_modules/express/lib/response.js:145:14)
    at done (/home/runner/node_modules/express/lib/response.js:1008:10)
    at /home/runner/node_modules/hbs/lib/hbs.js:69:11
    at Object.done (/home/runner/node_modules/hbs/lib/async.js:74:20)
    at /home/runner/node_modules/hbs/lib/hbs.js:64:20
    at FSReqWrap.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:53:3)

[dougwilson]

I'm not sure there is really a way for Express to solve this, as it is the class Node.js async stack trace problem that happens in Node.js. There are several module that will (at the cost of runtime performance) "fix" the stack traces to go though async operations like the file read. I'm on my phone so don't know them off-hand.

[jstarmx]

Thanks @dougwilson. Yeah that's what I suspected. I've seen some add-ons to provide longer stack traces but I it's not worth the impact on performance.

[krzkaczor]

@jstarmx have you tried using node's 12 async stack trace feature? It's enabled by default.

[davidmashe]

Ambiguity as to whether this is an express problem, no activity for some time. Closing issue.