Requesting /favicon.ico URL invokes function, ignores its response, logs error to console

[kkm000]

Unexpected behavior

invoker.ts handles the URLs '/favicon.ico' and '/robots.txt' specially, by sending back a 404 response. I assume that, by design, this was all what these two URLs were supposed to do, so that the behavior I am seeing is really a bug.

Reproduction

Everything goes as expected...

1. Follow the HelloWorld function tutorial. Confirm the response from curl localhost:8080 at the last step.
2. Add a code line to the function to print a debug message to console as early as possible (the code should look as below), and run the server with npm start again.

exports.helloWorld = (req, res) => {
  console.log('helloWorld is invoked');  /* Print a line every time the function is invoked */
  res.send('Hello, World');
};

3. Execute curl -s http://localhost:8080. Observe that, in addition to the reply being returned, a line helloWorld is invoked is printed to the server console.
4. Execute curl -sv http://localhost:8080/favicon.ico. Quite as expected, the command returns a 404 Not Found response¹.
   ____________
   ¹ And, somewhat less expected, courtesy of Express and on its conscience, also a text/plain body with the text "Not Found" which is not required, provides no extra information and thus unneeded, goes without the terminating \r\n as text/plain is supposed to be. But this is what Express does by default.

...until it does not

But much less than expected, the server console now shows:

helloWorld is invoked
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 (node_modules\express\lib\response.js:771:10)
    at ServerResponse.send (node_modules\express\lib\response.js:170:12)
    at ServerResponse.json (node_modules\express\lib\response.js:267:15)
    at ServerResponse.send (node_modules\express\lib\response.js:158:21)
    at helloWorld (index.js:3:9)
    at process.nextTick (node_modules\@google-cloud\functions-framework\build\src\invoker.js:100:17)
    at process._tickCallback (internal/process/next_tick.js:61:11)

This is rather bad. The function is actually invoked, with all its possible side effects. But whatever it returns is not seen by the caller: the framework has already sent a complete response to the HTTP trigger:

< HTTP/1.1 404 Not Found
< X-Powered-By: Express
< Content-Type: text/plain; charset=utf-8
< Content-Length: 9
< ETag: W/"9-0gXL1ngzMqISxa6S1zx3F4wtLyg"
< Date: Sat, 08 Aug 2020 18:43:58 GMT
< Connection: keep-alive
<
* Connection #0 to host localhost left intact
Not Found

and, sure enough, Express gets very angry when the function calls res.send('Hello, World'): it has already sent a complete response even before the function was entered.

---

I noticed the problem while trying the function using a Web browser. Every time I did a full refresh (i.e. discarding cache, C+S+r in Chrome), I surprisingly saw 2 invocation log messages from the function to console, and this stack trace.

I found the root cause, will open a PR today. It's quite an obvious bug with a one-line fix, easy to verify by tweaking the framework code under node_modules. Also, the bug certainly slips through tests in test/invoker.ts, but I have no idea how to also verify that /favicons.ico (and /robots.txt) do not cause the function invocation. The test should also verify that the function mock was not in fact called with these two special URLs, and that exceeds my knowledge of the test framework. In fact, I only learned a bit of node.js and JS yesterday morning (really, no kidding, but it's a very simple language, and TypeScript strong-ish typing with VS Intellisense help a lot).

Workaround in production GCP deployment

Compare the req.path property to one of the two special URLs (/favicons.ico and /robots.txt) and return without attempting to send a response, for example,

  if (['/favicon.ico', '/robots.txt'].indexOf(req.path) >= 0) return;

the first thing in function code. This is especially important if function is designed to accept calls from Web browsers.

[grant]

We should not invoke on those paths, yes.

I think this is due to an issue with our routing.

https://github.com/GoogleCloudPlatform/functions-framework-nodejs/blob/master/src/invoker.ts#L256

We shouldn't call next() here I believe, as it will call the next middleware router, which will invoke the function.

Obviously this an edge case as Functions aren't ideal for rendering web apps.

[kkm000]

Exactly, the next() is the culprit!

I'm using Functions to run CI/CD with a Bitbucket repo, and one invocation is an OAuth2 callback from the browser. So it has only a very little bit of a Web application.

I'll send a PR, fixing the Express' 404 nonsense at the same time if you do not mind.

[grant]

A PR with a test or two sounds good. Will look Monday.

[kkm000]

Uh, the test is a hard part, considering that my experience with JS/TS is limited to only few hours. But I'll try to figure it out. :)

[grant]

No worries. Will be able to help out later if needed, thanks for the issue.

[hdp617]

Thanks for finding and fixing this issue. It was my change that caused this.