Requests body is not logged in POST request

[lowmemory]

🐛 Bug Report

Hello,
I cannot see the request body in my logs when I do POST requests to my test server.

To Reproduce

'use strict'

// Read the .env file.
require('dotenv').config()

// Require the framework
const Fastify = require('fastify')

// Instantiate Fastify with some config
// const app = Fastify({
//   logger: true,
//   pluginTimeout: 10000
// })

const app = Fastify({
  logger: {
    prettyPrint: true,
    serializers: {
      res (res) {
        // the default
        return {
          statusCode: res.statusCode
        }
      },
      req (req) {
        return {
          method: req.method,
          url: req.url,
          path: req.path,
          // parameters: req.parameters,
          // Including the body and headers in the log could be in violation 
          // of privacy laws, e.g. GDPR. You should use the "redact" option to
          // remove sensitive fields. It could also leak authentication data in
          // the logs.
          body: req.body,
          headers: req.headers
        }
      }
    }
  }
})

// Register your application as a normal plugin.
app.register(require('./app.js'))

// Start listening.
app.listen(process.env.PORT || 5123, (err) => {
  if (err) {
    app.log.error(err)
    process.exit(1)
  }
})

Expected behavior

The request body in the logs:

{
    "gender": [
        "f",
        "m"
    ],
    "country": "ITA",
    "isTeam": false,
    "isSearch": true,
    "name": "xxxx",
    "fetchPage": 1
}

What I get

[1559408233939] INFO  (15868 on sauron): Server listening at http://127.0.0.1:5123
[1559408239792] INFO  (15868 on sauron): incoming request
    reqId: 1
    req: {
      "method": "POST",
      "url": "/athletes/search",
      "headers": {
        "content-type": "application/json",
        "user-agent": "PostmanRuntime/7.13.0",
        "accept": "*/*",
        "cache-control": "no-cache",
        "postman-token": "f4002054-80c5-4b01-8fa0-0a173f12e73b",
        "host": "localhost:5123",
        "accept-encoding": "gzip, deflate",
        "content-length": "98",
        "connection": "keep-alive"
      }
    }

Your Environment

• node version: 11
• fastify version: = 2.4.1
• os: Windows

[mcollina]

This happens because the request is serialized when we create the child logger. At that time, the body is not parsed yet. So, the approach described in https://www.fastify.io/docs/latest/Logging/ is wrong.

In order to log the body, you would have to log it manually with:

app.addHook('preHandler', function (req, reply, next) {
  if (req.body) {
    req.log.info({ body: req.body }, 'parsed body')
  }
  next()
})

I'm tagging updating this issue as a "good first issue", updating the docs for this should be easy enough.

[lowmemory]

Ok.
Thanks @mcollina !

[RafaelGSS]

Hello @mcollina, this issue is just to update docs ? or change the order of parser body...

If I remember, the child logger is instantiated in the creation of fastify.build... It may not make sense a approach for it. I believe it's just the documentation.

[mcollina]

Yes!

[yunfan]

i had a related issue oon this
i found i cant got a way to record the responsed body
because in my code i dont use reply.send but return the object directly(i am developing a json api service)

when customizing the serializer in logger, i found reply.body is not available

[climba03003]

i had a related issue oon this i found i cant got a way to record the responsed body because in my code i dont use reply.send but return the object directly(i am developing a json api service)

when customizing the serializer in logger, i found reply.body is not available

@yunfan Please open your own issue with reproducible example.