Error Object Serialisation issue with nestedKey options

[dhruvppatel]

Error object information is not serialized/included when nestedKey option is provided

Code

const pino = require('pino');

const logger = pino({
  prettyPrint: true,
  base: null,
});

const loggerWithNested = pino({
  prettyPrint: true,
  nestedKey: 'data',
  base: null,
});

console.log('----- Without nestedKey -------');
logger.error(new Error('an error'));
console.log('\n----- With nestedKey -------');
loggerWithNested.error(new Error('an error'));

Output

----- Without nestedKey -------
[1581516926814] ERROR: an error
    Error: an error
        at Object.<anonymous> (/opt/hotstar/applications/cricinfo/cric-info-api/src/sample.js:15:14)
        at Module._compile (internal/modules/cjs/loader.js:945:30)
        at Object.Module._extensions..js (internal/modules/cjs/loader.js:962:10)
        at Module.load (internal/modules/cjs/loader.js:798:32)
        at Function.Module._load (internal/modules/cjs/loader.js:711:12)
        at Function.Module.runMain (internal/modules/cjs/loader.js:1014:10)
        at internal/main/run_main_module.js:17:11

----- With nestedKey -------
[1581516926816] ERROR:
    data: {}

[jsumners]

I think you'll need to add a serializer for the data property. You can use pino-std-serializers to bootstrap your custom serializer.

[obchap]

I am running into a similar issue with API responses.

When I upgrade to pino@5.16.0 and use the nestedKey option, the entire res and req properties are logged regardless of what serializers I have set which causes too much data to be logged.

If I remove the nestedKey option with pino@5.16.0, everything logs as expected.

const logger = require('pino')(
  {
    base: {
      appContext: {
        ip: ip.address(),
        name,
        version
      }
    },
    nestedKey: 'payload',
    level: LOG_LEVEL,
    prettyPrint: !ELASTICSEARCH_URL
  },
  elasticTransport
);

await server.register([
  {
    plugin: h2o2
  },
  {
    plugin: hapiPino,
    options: {
      prettyPrint: !config.ELASTICSEARCH_URL,
      ignorePaths: '/up',
      instance: logger,
      serializers: {
        err: err => ({
          type: err.type
        }),
        req: req => ({
          headers: req.headers
        }),
        res: res => ({
          headers: res.headers
        })
      }
    }
  }
]);

Here is what the req and res properties look like

req: {
  "headers": {
    "content-type": "application/json",
    "user-agent": "PostmanRuntime/7.21.0",
    "accept": "*/*",
    "cache-control": "no-cache",
    "postman-token": "8910c018-6280-47d2-b4ab-97bc590de718",
    "host": "localhost:21871",
    "accept-encoding": "gzip, deflate",
    "content-length": "671925",
    "connection": "keep-alive"
  }
}
res: {
  "headers": {
    "content-type": "application/json; charset=utf-8",
    "cache-control": "no-cache",
    "content-length": 62
  }
}

Here are the libraries that I am using

"hapi": "17.8.5",
"pino": "5.16.0",
"pino-pretty": "3.5.0",

[obchap]

@jsumners

I was able to identify where the issue is.

The code checks if the nestedKey property exists. If it does, it wraps all objects under the specified nestedKey property. So it will nest the req, res and err properties under the nestedKey property on response logging.

https://github.com/pinojs/pino/blob/master/lib/tools.js#L37

The problem is that when the code tries to run the serializers against the object, the req, res and err properties are nested and can't be found.

https://github.com/pinojs/pino/blob/master/lib/tools.js#L94

I'm looking into a possible fix now

[jsumners]

Yes, that was the point of #759

By enabling the nestedKey option you are opting-in to every property that isn't a core Pino property, those which are essentially metadata about the log, being added to the specified "nest key". Thus, with nestedKey enabled doing log.info({ req }) will result in the { req } object being a child of the specified nesting key. Whereas without the nestedKey option enabled, the properties of { req } will simply be added to the root log object.

Serializers work by inspecting the root level of the log object, e.g. the msg property. In normal operation that means the req serializer will look for log.req and serialize that property. But the nestedKey option makes that log object look like log.nestKey.req so the serializer cannot find it.

Thus my response that you will need to define a new serializer to accommodate whatever key you specified as the nesting key.

[obchap]

Thanks for the quick response and being so thorough in the explanation! It makes complete sense now.

I was able to get the desired output by using the following options with the default pino serializers.

nestedKey: 'payload',
serializers: {
  payload: data => {
    if (data.req) {
      data.req = pino.stdSerializers.req(data.req);
    }

    if (data.res) {
      data.res = pino.stdSerializers.res(data.res);
    }

    if (data.err) {
      data.err = pino.stdSerializers.err(data.err);
    }

    return data;
  }
}

As for my part of this issue, I feel that the issue is resolved.

Do you think that that adding to the documentation about the use of nestedKey and serializers would be too verbose? If not, I can try to draft something up.

[jsumners]

Better documentation is always welcome.

[jsumners]

I'm closing this as I believe it has been sufficiently answered.

[fiznool]

Thanks @VtoCorleone your code snippet helped me to workaround this.

For reference, I also added a conditional to support directly logging out an error object, i.e. logger.error(err):

nestedKey: 'payload',
serializers: {
  payload: data => {
    if(data instanceof Error) {
      return pino.stdSerializers.err(data.err);
    }

    if (data.req) {
      data.req = pino.stdSerializers.req(data.req);
    }

    if (data.res) {
      data.res = pino.stdSerializers.res(data.res);
    }

    if (data.err) {
      data.err = pino.stdSerializers.err(data.err);
    }

    return data;
  }
}

[mfrye]

Thanks @VtoCorleone your code snippet helped me to workaround this.

For reference, I also added a conditional to support directly logging out an error object, i.e. logger.error(err):

nestedKey: 'payload',
serializers: {
  payload: data => {
    if(data instanceof Error) {
      return pino.stdSerializers.err(data.err);
    }

    if (data.req) {
      data.req = pino.stdSerializers.req(data.req);
    }

    if (data.res) {
      data.res = pino.stdSerializers.res(data.res);
    }

    if (data.err) {
      data.err = pino.stdSerializers.err(data.err);
    }

    return data;
  }
}

A helpful note for whoever finds this, note that the first check for an error here should just pass the error instead of data.err.

if (data instanceof Error) {
   return pino.stdSerializers.err(data);
}

[Repraance]

There's still problem. By adding serializers for nestedKey, the error object is well printed. But the msg which should be the message of the error is still missing.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.