Response status code is inaccurate on aborted requests

[jonathansamines]

access-logs-aborted-requests

See reproduction repository

Problem

When the client aborts a request before the server is able to respond, then the response status code is always captured as 200.

How to reproduce?

A reproduction code is included for both express and hapi.js. The server.js and hapi-server.js scripts create a simple server with two endpoints:

1. GET /immediate - responds back immediately
2. GET /delayed - responds back after a delay of 100ms

Express server

node server.js

Hapi server

node hapi-server.js

Test cases

The client.js script performs two requests to the server:

1. A request to GET /immediate
2. A request to GET /delayed. This request is aborted after 10ms, long before the server responds back

node client.js

Results

pino-http

Completed request

Log is correct

{"level":30,"time":1652973706067,"pid":4030,"hostname":"codespaces-0f9e76","req":{"id":2,"method":"GET","url":"/immediate","query":{},"params":{},"headers":{"host":"127.0.0.1:4000","connection":"close"},"remoteAddress":"::ffff:127.0.0.1","remotePort":43018},"res":{"statusCode":500,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"18","etag":"W/\"12-+eLe/Is4e/DsYM51R9etEfeL+TE\""}},"err":{"type":"Error","message":"failed with status code 500","stack":"Error: failed with status code 500\n    at ServerResponse.onResFinished (/workspaces/access-logs-aborted-requests/node_modules/pino-http/logger.js:107:40)\n    at ServerResponse.emit (node:events:538:35)\n    at onFinish (node:_http_outgoing:830:10)\n    at callback (node:internal/streams/writable:552:21)\n    at afterWrite (node:internal/streams/writable:497:5)\n    at afterWriteTick (node:internal/streams/writable:484:10)\n    at processTicksAndRejections (node:internal/process/task_queues:82:21)"},"responseTime":4,"msg":"request errored"}

Aborted request

Log is not created. There is an open pull request to fix it.

-

Hapi server

node hapi-server.js

hapi-pino

Completed request

Log is correct

{"level":30,"time":1652973536836,"pid":2728,"hostname":"codespaces-0f9e76","req":{"id":"1652973536834:codespaces-0f9e76:2728:l3d5qt36:10003","method":"get","url":"/immediate","headers":{"host":"127.0.0.1:4000","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":42740},"res":{"statusCode":500,"headers":{"content-type":"application/json; charset=utf-8","cache-control":"no-cache","content-length":18}},"responseTime":2,"msg":"[response] get /immediate 500 (2ms)"}

Aborted request

Log is incorrect. Status code is included as 200 in both msg and res.statusCode, even when the request was aborted.

{"level":30,"time":1652973536840,"pid":2728,"hostname":"codespaces-0f9e76","req":{"id":"1652973536834:codespaces-0f9e76:2728:l3d5qt36:10002","method":"get","url":"/delayed","headers":{"host":"127.0.0.1:4000","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":42738},"res":{"statusCode":200,"headers":{}},"responseTime":6,"msg":"[response] get /delayed 200 (6ms)"}

Suggested fix

Other existing access logs libraries (e.g morgan), just capture the response status code when headers have been flushed. I'd suggest we do the same

[jsumners]

How is the pino-std-serializers module implicated in this?

[jonathansamines]

@jsumners Framework-specific libraries that are build on top of pino would usually pass a reference to the res object when logging the response details as part of their access logs implementation:

• pino-http
• hapi-pino

pino-std-serializers will then take the response object and serialize it by copying the res.statusCode reference from the response object:

• pino-std-serializers

This is the reason why I think pino-std-serializers is the best place to update how the res.statusCode is included in the final logs. The current implementation is:

https://github.com/pinojs/pino-std-serializers/blob/202ee4741c4f7c2ae511cbca4aad58cc398f57aa/lib/res.js#L37

I'd suggest moving to:

  _res.statusCode = res.headersSent ? res.statusCode : null

[mcollina]

Would you like to send a Pull Request to address this issue? Remember to add unit tests.

[jonathansamines]

@mcollina Sure thing, I just created #103