pino-http icon indicating copy to clipboard operation
pino-http copied to clipboard

Missing log on client timeout

Open dalexanco opened this issue 3 years ago • 0 comments

I have an issue : when my client cut the connection (generally because of a timeout), then pino-http does not log anything.

The default behavior of express is to continue the request processing, even if the client has gone, so it could be interesting to have these logs.

A small example :

const express = require('express')
const pinoLogger = require('pino-http')
const pino = require('pino')

const app = express()
const pinoInstance = pino({
  prettyPrint: true,
})
app.use(pinoLogger({ logger: pinoInstance }))

app.get('/foo', (req, res) => {
  pinoInstance.info('Received request')
  setTimeout(() => {
    res.sendStatus(200)
    pinoInstance.info('Response sent')
  }, 10000)
})

app.use((err, req, res, next) => {
  pinoInstance.error('Error : ', err)
})

app.listen(3000, () => {
  pinoInstance.info('Server ready')
})

Case 1 : a simple request, no timeout

[1604486775436] INFO     (15596 on CM000091.local): Server ready
[1604486778910] INFO     (15596 on CM000091.local): Received request
[1604486788921] INFO     (15596 on CM000091.local): Response sent
[1604486788922] INFO     (15596 on CM000091.local): request completed
    res: {
      "statusCode": 200,
      "headers": {
        "x-powered-by": "Express",
        "content-type": "text/plain; charset=utf-8",
        "content-length": "2",
        "etag": "W/\"2-nOO9QiTIwXgNtWtBJezz8kv3SLc\""
      }
    }
    responseTime: 10012
    req: {
      "id": 1,
      "method": "GET",
      "url": "/foo",
      "headers": {
        "accept": "application/json, text/plain, */*",
        "user-agent": "axios/0.21.0",
        "host": "localhost:3000",
        "connection": "close"
      },
      "remoteAddress": "::ffff:127.0.0.1",
      "remotePort": 59200
    }

Case 2 : a request with a timeout set (3sec)

[1604487109825] INFO     (15694 on CM000091.local): Server ready
[1604487111452] INFO     (15694 on CM000091.local): Received request
[1604487121458] INFO     (15694 on CM000091.local): Response sent

No pino-http log "request completed".

Is it a normal behavior ?

dalexanco avatar Nov 04 '20 10:11 dalexanco