Unable to log query nor params for request serializers

[samholmes]

app.use(
    pinoMiddleware({
      logger,
      customLogLevel: res => {
        return res.statusCode >= 500 ? 'warn' : 'info'
      },
      serializers: {
        req: numbRequest,
        res: numbResponse
      }
    })
  )

export const numbRequest = (req: any) => {
  const { url, repoId } = numbEndpoint(req.url)
  const { params, query } = req

  const out = {
    id: req.id,
    method: req.method,
    url,
    params,
    query,
    foo: 'hi',
    remoteAddress: req.remoteAddress,
    remotePort: req.remotePort,
    repoId
  }

  console.log('query', query)
  console.log('JSON.stringify(query)', JSON.stringify(query))
  console.log('params', params)
  console.log('JSON.stringify(params)', JSON.stringify(params))
  console.log('out', out)

  return out
}

The query and params console.log output is showing in the terminal, however the fields are not showing up in the final log output. The field foo is showing, so this means that params and query are treated in a special way that is not documented.

[mcollina]

Could you please provide a complete example to reproduce your problem?

[samholmes]

Could you please provide a complete example to reproduce your problem?

It turns out my problem was a misunderstanding of the API. The serializer functions always expect the value being logged as the first parameter. I was expecting the express request object as it is from a route handler, but instead I got a the “context object” (this) of the event handlers for the finish/error events on the request object. In order to access the request object details such as query or params I would need to go through req.raw.

Figuring this out took longer than it would have if there was stronger typing for the serializers for pino-http. I understand how the typing of serializer functions could be challenging due to their dynamic nature. So this leads me to an alternative API idea: what if the library just gave you the request, response and error objects in a callback, and then you decide everything that should be logged from that callback?

[mcollina]

how would that API look like?

[samholmes]

how would that API look like?

pinoMiddleware({
  logger,
  onResFinished: (req, res, err) => {
	return { ... } // Return whatever you want from the req, res, or err objects.
  }
})

The object returned from the onResFinished callback would be included in the log which could then be serialized further. The signature of the callback is identical to that of a route handler (very familiar). The name could be even one of onResponseFinished, onRequestFinished, onFinished, or event logHandler.

[samholmes]

This could be done by changing:

function onResFinished (err) {
    this.removeListener('error', onResFinished)
    this.removeListener('finish', onResFinished)

    var log = this.log
    var responseTime = Date.now() - this[startTime]
    var level = customLogLevel ? customLogLevel(this, err) : useLevel

    if (err || this.err || this.statusCode >= 500) {
      var error = err || this.err || new Error('failed with status code ' + this.statusCode)

      log[level]({
        [resKey]: this,
        [errKey]: error,
        [responseTimeKey]: responseTime
      }, errorMessage(error, this))
      return
    }

    log[level]({
      [resKey]: this,
      [responseTimeKey]: responseTime
    }, successMessage(this))
  }

Into:

function onResFinished (err) {
    this.removeListener('error', onResFinished)
    this.removeListener('finish', onResFinished)

    var log = this.log
    var responseTime = Date.now() - this[startTime]
    var level = customLogLevel ? customLogLevel(this, err) : useLevel
    var logOut = {
      [resKey]: this,
      [responseTimeKey]: responseTime,
    }

    if (err || this.err || this.statusCode >= 500) {
      var error = err || this.err || new Error('failed with status code ' + this.statusCode)
      logOut[errKey] = error
      logOut.msg = errorMessage(error, this),
    }
    else {
      logOut.msg = successMessage(this),
    }

    log[level]({
      ...logOut
      ...logHandler(req, res, err)
    })
  }

Here we're going with the name logHandler as the field name for the options argument. We'll need to make onResFinished close over the loggerMiddleware scope so it has access to req, res, and err.

[mcollina]

I don't think we have req available at that point.

[samholmes]

I don't think we have req available at that point.

loggerMiddleware has req.

[mcollina]

Indeed. The code is written so that we avoid allocating a new closure for each request.

[samholmes]

If memory footprint is a concern, then we could leak the abstraction: Pass a ctx object to the log logHandler(ctx) and then allow for a field for making the context object.

[mcollina]

That would still add something somewhere :/.

I'm not sure what @jsumners thinks, but I'm kind of ok to how this module works now.

[samholmes]

@mcollina I see; so you want to avoid creating any closure whatsoever per request. I'm assuming this is because closures have significant performance implications. Regardless, use of a closure is only an implementation detail. You could get a bit more hacky and just add the req, res, and err objects from the middleware to the event emitter and access these pieces of data from this within the onResFinished. The field could be something like this._pinoHttpCtx even. The point is that you just provide a reference to those objects to a handler like logHandler to generate the log. This way you have full control over what gets logged at the end of a request.

[jsumners]

That would still add something somewhere :/.

I'm not sure what @jsumners thinks, but I'm kind of ok to how this module works now.

Honestly, I've never actually used this module. And I haven't really followed the code in this thread. I get the impression there is a misunderstanding of what the module is and how it works, but, again, I haven't really been paying much attention here.

[mcollina]

@samholmes I think your view of what you would like to achieve with this module is quite different from the current scope of it.

I have not used this in a while as well and I would prefer not to significantly change this.

[samholmes]

Fair enough. My only suggestion then is somehow addressing the slight lack of clarity for using the API through documentation. One thing that wasn’t clear at first was that pino-http logged a specific object that could then be changed either through serializer functions or some other handlers. Documenting what exactly this object is would be helpful. 🙂

[UderMoreiraDeAssis]

This issue still persists as of April 2024. Indeed, when making a request using parameters, it resolves to a URL rather than to params. Even when using custom serializers, the information that reaches the serializer about the request is already resolved to a URL, even though in the request (for example in Express.js), it belongs to the params attribute.

Log in Express.js:

params: { userId: '123' },
query: {},

Log in Pino:

  "url": "/user/123",
  "query": {},
  "params": {},

[askmrsinh]

@UderMoreiraDeAssis Seems like this is expected behavior. Express middleware doesn't inherently know the structure of route parameters across different routes unless you explicitly define it. If you register the pino-http logger middleware without explicitly providing any routes, params won't be parsed because the middleware is not aware about them. More details here.

@samholmes In your example code, you could try registering the middleware as:

app.use('/*',
    pinoMiddleware({
        logger,
        customLogLevel: res => {
            return res.statusCode >= 500 ? 'warn' : 'info'
        },
        serializers: {
            req: numbRequest,
            res: numbResponse
        }
    })
)

Of course, it's not perfect as you would have to duplicate the exact route param names to get the correct object.