"Cannot set headers..." error happening only on one specific kind of request

[getify]

I'm using Node 10.1.0, and node-static v0.7.2. The error stack in my logs:

Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client
    at ServerResponse.setHeader (_http_outgoing.js:471:11)
    at ServerResponse.writeHead (_http_server.js:231:21)
    at Server.finish (/tmp/site/node_modules/node-static/lib/node-static.js:125:17)
    at finish (/tmp/site/node_modules/node-static/lib/node-static.js:170:14)
    at /tmp/site/node_modules/node-static/lib/node-static.js:337:13
    at streamFile (/tmp/site/node_modules/node-static/lib/node-static.js:382:13)
    at ReadStream.<anonymous> (/tmp/site/node_modules/node-static/lib/node-static.js:375:17)
    at ReadStream.emit (events.js:182:13)
    at fs.close (fs.js:2161:14)
    at FSReqWrap.oncomplete (fs.js:152:20)

I'm experiencing this persistent error every single time a specific kind of request comes in -- but only for that, all other requests are fine -- which appears to be a request from a Slackbot. Here are the request headers from the specific request:

{"x-forwarded-host":"my.domain.tld","x-forwarded-proto":"https","x-forwarded-port":"443","x-forwarded-for":"::ffff:52.71.192.87","if-modified-since":"Mon, 17 Oct 2016 23:58:19 GMT","accept-encoding":"gzip,deflate","accept":"*/*","user-agent":"Slackbot 1.0 (+https://api.slack.com/robots)","host":"my.domain.tld","connection":"close"}

Here's my code:

"use strict";

var path = require("path");
var http = require("http");
var httpServer = http.createServer(handleRequest);
var nodeStatic = require("node-static");
var staticServer = new nodeStatic.Server(path.join(__dirname,"static"),{
        serverInfo: "my-server",
        cache: 86400,
        gzip: true,
});

const HSTS = `max-age=${1E9}; includeSubdomains`;

httpServer.listen(8003);

// *********************

function handleRequest(req,res) {
        // unconditional, permanent HTTPS redirect
        if (req.headers["x-forwarded-proto"] !== "https") {
                res.writeHead(301,{
                        "Strict-Transport-Security": HSTS,
                        "Cache-Control": "public, max-age=31536000",
                        Expires: new Date(Date.now() + 31536000000).toUTCString(),
                        Location: `https://${req.headers["host"]}${req.url}`
                });
                res.end();
        }
        else if (["GET","HEAD"].includes(req.method)) {
                req.addListener("end",function requestEnd(){
                        req.removeListener("end",requestEnd);
                        res.setHeader("Strict-Transport-Security",HSTS);
                        staticServer.serve(req,res);
                }).resume();
        }
        else {
                res.writeHead(404,{ "Strict-Transport-Security": HSTS });
                res.end();
        }
}

As you can see, my server is running on localhost:8003 -- I have a public server on 80/443 that proxies the requests after doing SSL certificate handling, etc.

In my debugging, I have narrowed down that the error happens inside of the staticServer.serve(..) call itself, not in this code shown.

And the res.setHeader(..) call that I make before serve(..) seems to cause the error, though I don't understand why. If I comment that line of code out, the error stops.

But my understanding is that me calling setHeader(..) only queues up a header to be sent. It's not supposed to flush headers or anything, only prepare a header for later sending. I don't have any other calls in that code path to res.writeHead(..) or anything, so I can't figure out how the error is getting triggered.

I am aware that I could set this response header in the new nodeStatic.Server(..) constructor call. But I don't want to do it there, because I actually need to be able to set specific headers on a per-request basis under certain conditions, and that approach sets headers for all static-file responses.

Can you help me figure out why, in only this one specific Slackbot request case, my call to setHeader(..) is triggering logic in node-static that causes this error? I'm really perplexed.

[1ns3cur3]

I tried this via Postman (don't know how accurate my approach is) but on node v10.0.0, I am consistently getting 404. Doesn't matter which source path I take (forcefully) in Server.prototype.finish.

Let me try with node 10.1.0

Even with 10.1.0, I am not getting that error thrown. Even with node-static v0.7.1 and v0.7.2 I am not getting error thrown.

What am I missing?

1. Copied your code and ran
2. Made a GET request from Postman by copying request headers you mentioned.

No error

[getify]

I know, I've tried the same kind of thing and I'm not able to reproduce with those headers either. Super frustrating. I figure it must be:

• something about how that Slackbot is making the request. Unfortunately, I don't control Slackbot so I don't have any idea what they're doing.

• some weird state created when the request has been proxy forwarded and when HTTPS and HSTS is involved, etc.

Is there some way to turn on some kind of verbose logging of everything that happens when a connect/request comes in? I have no idea how to track this down other than what I've already tried.

[getify]

I am consistently getting 404

As implied by the code I pasted, I assume you are using a ./static/ directory with some index.html file in it, for your testing, right? Otherwise, you'd expect to get a 404 I think.

Also, it may help to forcibly set req.url to "/index.html" in the request handler, to ensure all inbound requests serve that one index.html file, instead of 404s.

[1ns3cur3]

I think I read something about chunked in request header and node closing connection forcing write on response.

A valid 404 from all possible code path means that code is not throwing error.

Regrading verbose logging, I sprinkled console.log in node-static. Other than that, verbose logging should be supported by modules, which node-static doesn't; at least not in installed version. May be dev version has more logging. MAY BE.

Viel Glück!

[getify]

A valid 404 from all possible code path means that code is not throwing error.

That's true, but it's also possible those kinds of requests/responses are going through different code paths inside node-static than regular found resources, since ostensibly it needs to add headers like content-type, etc... if it's processing on a different path, it could just be accidentally avoiding (but not actually un-susceptible to) the error in question.

[getify]

BTW, another reason I can't just only set headers in the headers config of the constructor: certain headers have timestamps in them, and those would be calculated at the time the node server starts up, and never be re-calculated. But they actually should be relative to (recalculated at) each request. Otherwise, the longer the server stays alive without a restart, the more inaccurate that header's timestamp would be. :(

My only viable option here is to be able to call setHeader(..) upon each request. That's why I need this problem fixed.

[getify]

UPDATE:

This post seems to have identified the culprit, or at least pointed at where the probable problem lies.

The problem seems to be that a HEAD request comes into my code as shown above, and the HSTS header is set, and then serve(..) is called, and that seems to trigger incorrect behavior where a response body is sent when it shouldn't.

I'm not fully versed on this, but here are a few assumptions/observations that I'd think of initially:

• I would expect to be able to call serve(..) even on HEAD requests, since it seems important that node-static properly respond with content-type/length/etc response headers, even if it won't send the whole file body.

  Does node-static properly handle HEAD requests?

• I would also expect to be able to, and probably should, set HSTS headers even on responses to HEAD requests. It seems like it's important to protect all inbound requests with HTTPS, and HSTS is how we notify senders that they must always use HTTPS, even on HEAD requests.

  Is there something I'm missing where HSTS should not be sent out for HEAD requests?

• It seems that me setting the header with setHeader(..) triggers this bug, but if I set the same header via the node-static constructor, no such bug crops up. At a minimum, this seems like a bug in node-static.

  Am I correct in observing this difference in behavior based on how a header is queued up as "buggy", or is there some other reason that's expected or intended?

• I haven't figured out yet if there's anything about this bug related specifically to the HSTS header -- IOW, if I tried setHeader(..) with some other header, does the bug still happen? Also, I am not sure if this bug only relates to me running my server behind the proxy forwarding, such that the request headers have "proxy-forwarded-*" like headers included in them?

+@1ns3cur3

[getify]

Further analysis from that thread:

The root of the problem I think is that the node-static tries to send headers twice, and node-request (i.e. request module of Node.js) checks that headers were already sent only in setHeader method. That is, the error is thrown only when setHeader method was called. If setHeader method was not called, the error is not thrown even if writeHead method is called again.

From my reading, that sounds like both a bug in node-static and also in Node itself. Thoughts?

[1ns3cur3]

@getify Nope, calling writeHead twice is erroneous; Node says that. Earlier I didn't debug HEAD, let me check that once quickly.

[1ns3cur3]

After adding a static/index.html, for a GET call I am getting this error:

issue/node_modules/node-static/lib/node-static.js:290
                      mime.lookup(files[0]) ||
                           ^

TypeError: mime.lookup is not a function
    at Server.respond (issue/node_modules/node-static/lib/node-static.js:290:28)
    at issue/node_modules/node-static/lib/node-static.js:144:22
    at FSReqWrap.oncomplete (fs.js:166:5)

Here's the input data:

    pathname: null,
    status: 200,
    _headers: {},
    files: issue/static/index.html,
    stat: <...mostly useless stats...>,
    Object.keys(mime): _types,_extensions

[getify]

@1ns3cur3 that's strange, i'm definitely not seeing that.

[1ns3cur3]

So far, HEAD shouldn't send headers which GET wouldn't; which I guess you aren't.

Other than that, yes, you can call writeHead as many times as you want, if you don't call setHeaders().