Hi maintainers, love your library - thank you so much. We've been using it for over 2 years at our startup and it's great.

I know that the behavior surrounding error.cause is intentional, as discussed mainly in #110 (the discussion there is now locked)
This issue is meant to express a personal experience and opinion.
If discussions issues are not welcome here, I apologize. Please let me know if there's a different communication channel for constructive discussion regarding pino serializers (or maybe none at all).

If that's the case, I'll close this issue and happily use the suggested configurations to fix my issue.

Current design advantages
I completely agree that just printing the full error + causes serialized object causes duplication in the stack trace. However, I believe the solution is less useful than doing nothing (explained below), and I also think that there is a "win win" solution here, detailed below.

Current design cons
Currently, by default, error.causes are entirely omitted from the log output. In their stead, the original error's message and stack traces are concatenated as a string. I believe this behavior is surprising and detrimental. I'm not going to do a deep dive in to the reasons since they were very well explained by @hypesystem in this comment. In short:

• Concatenating message and stackTrace is unexpected and weird since serialization usually does not change string values
• Parsing messages and stack traces becomes really hard and error prone since they're no longer structured
• Extremely important debug information is not printed

Rebuttal to design decision
optimizing for usefulness per size (message and stack are concatenated but causes are not serialized in full) (link):

I think the usefulness of the error stack trace is reduced dramatically, so the goal of the design choice is not achieved. The common use case of error.cause is wrapping an infrastructure library (like Apollo, TypeORM, express etc.) with a userland error. In these cases, the userland error explains the context of the error creation (e.g "error while trying to create user"), and the "cause" error explains the technical reasons for the error (e.g "duplicate primary key"). If the "cause" error includes extra fields, they're usually extremely helpful. Examples:

• AxiosError includes the URL of the request. Without the "cause" fields, you just know you got a 403, but not which site you were making a request to
• TypeORM errors include the query and parameters that caused the error. Without this, you might not easily know which row in the DB has bad data or otherwise requires intervention
• Many, many libraries have stacktraces that do not contain their async context (even after async stack traces were added to node natively), and their "cause" fields really help to understand what caused the error

I think that for 90% of the use cases a summary of the cause chain is good enough. (link):
I disagree with this, but this is anecdotal. I don't think either of us has numbers to justify their opinion, so this is merely opinion. When it comes to matters of opinion, yours matters more than mine since you're the maintainers of this library, but I hope you're open to others' opinions.

Proposed solution
I think we can implement a solution that:

• cuts down the stack trace duplication
• still prints the "cause" error additional fields

My solution is to fully serialize the error.cause object (even if nested), but to remove all "caused by" rows from the stack traces, such that each error's stack trace only includes their own lines, and there's zero duplication.

I believe this is a win-win solution that caters to everybody's wants, and I'm happy to implement it if the maintainers agree that this is an acceptable solution.

I don't even believe this is a breaking change since is only adds fields to the response. It does removes parts of the "stackTrace" and "message" fields, but these were strings and I wouldn't expect anybody to rely on their parsing. To be safe, this can be added in the next major version.

This is a long post. I tried to make it as clear as possible. I hope the maintainers take a moment to read this. It was aimed to be positive and constructive. If this is not welcome, I'll simply use a custom serializer as suggested, but I'd rather have a professional discussion surrounding this issue.

Thank you!

because the readme said "id defaults to an empty string" I made it default to empty string

but this now causes failing tests when integrating with pino (it's not expecting an ID to there)

I don't think we should include an id with empty string in output

can we change the readme to id defaults to undefined, make id undefined, then release a major
(because technically prior pub was a patch, now this is api breaking, so major)

The current error serializer only walks enumerable properties using a for..in loop. The downside to this is that vanilla errors with their cause property set are not enumerable by default. I don't know if it's spec related or just specific to V8's implementation, but it's a bit wonky/unexpected nonetheless.

This means if you have the following code, the cause property won't actually be logged/printed. It will only log the very first/top-level error.

fastify.get('/throw', async (req, res) => {
  throw new Error('first cool error', {
    cause: new Error('second boring error', {
      cause: new Error('third awesome error'),
    }),
  });
});

Here's what node's inspector prints:

Uncaught [Error: first cool error] {
  [cause]: Error: second boring error
      at REPL5:2:12
      at Script.runInThisContext (node:vm:129:12)
      ... 7 lines matching cause stack trace ...
      at REPLServer.[_line] [as _line] (node:internal/readline/interface:879:18) {
    [cause]: Error: third awesome error
        at REPL5:3:14
        at Script.runInThisContext (node:vm:129:12)
        at REPLServer.defaultEval (node:repl:566:29)
        at bound (node:domain:421:15)
        at REPLServer.runBound [as eval] (node:domain:432:12)
        at REPLServer.onLine (node:repl:893:10)
        at REPLServer.emit (node:events:539:35)
        at REPLServer.emit (node:domain:475:12)
        at REPLServer.[_onLine] [as _onLine] (node:internal/readline/interface:418:12)
        at REPLServer.[_line] [as _line] (node:internal/readline/interface:879:18)
  }
}

Would people be open to a PR that explicitly checks for a cause key alongside the existing for..in check? Are there other ways to achieve this? It seems like this would be an expected/sane default, but perhaps there are downsides to doing this or was previously not done intentionally?

Thanks.

Hi there!

Seems that switching to this module leads to bugs in hapi v17.
So does request.connection not exist, it's now request.info because multiple connection support was removed.

Unfortunately no time to fire a PR with tests etc.
Hope someone can tackle it :)

Thanks

Hi,

How do I use this module? I can't make much sense from the doc. This is my logger setup. Right now, I only can see the error message in the console. But stack trace is not there.

const applyServiceStyles = (log: LogDescriptor, messageKey: string) => {
  let style;
  switch (log.service) {
    case SERVICES.KIOSK_APP_CLIENT:
      style = bgLightBlue;
      break;
    case SERVICES.KIOSK_APP_SERVER:
      style = bgYellow;
      break;
    case SERVICES.AWS_IOT_SERVER:
      style = bgLightGreen;
      break;
    case SERVICES.AWS_IOT:
      style = bgLightMagenta;
      break;
    default:
      style = bgLightCyan;
      break;
  }
  return `${black(style(`[${log.service}]`))} ${log[messageKey]}`;
};

const logger = pino({
  prettyPrint: {
    colorize: true,
    errorLikeObjectKeys: ["err", "error", "details"],
    levelFirst: true,
    translateTime: "SYS:hh:MM:ss TT dd-mm-yyyy",
    ignore: "pid,hostname,service",
    messageFormat: (log, messageKey, levelLabel) => {
      return applyServiceStyles(log, messageKey);
    },
  },
  level: process.env.LOG_LEVEL || "debug",
  serializers: {
    error: pino.stdSerializers.err,
  },
});

I'm trying to log an error object, that has some extra context. The error serializer ignores anything but type, message and stack. Would you consider extending the error serializer to make it hydrate the resulting _err object with the extra fields it may have? Or should I rather use the pino-std-serializers directly, serialize my error object directly, then hydrate it and then pass it to pino?

Example:

const logger = pino();

const err = new Error('Boom!');
err.foo = 'bar';

// Expecting to see `foo: bar` logged here, but it's not
logger.error(err);

Here's the interim solution I have:

const stdSerializers = require('pino-std-serializers');
const logger = pino();

// Assuming this error is created in a separate file, and passed into this file as an argument
const err = new Error('Boom!');
err.foo = 'bar';

const serializedErr = stdSerializers.err(err);
serializedErr.foo = err.foo;

pino.error(serializedErr);

I'm mostly using express these days, and i notice req.url contains the qs (because req.originalUrl does), not sure what behaviour is with fastify or other libs.

that said, would a PR be accepted to add a req.path prop (at least for express, so this would be done in the "if originalUrl is truthy" branch) that with something like req.originalUrl.split("?").shift() ?

My use case is wanting to add the value of these as a tag/label in log based metrics and it should have a low cardinality, though I think it might make sense to have this in the standard req serializer.

hey, folks, first of all, thank you for your great work! 💪🏽

I used code copied from res.js to create a performance test to compare creating new instances of resSerializer using the current syntax, based on Object.create(myProto), to using new MyClass. According to this test, speed of Object.create(myProto) is about 37% slower than new MyClass.

As pino-std-serializers is used in http-pino (and its variants), I think this improvement on logs could be positive to many HTTP services.

Would you be interested into a PR to refactor these constructor calls? As this should not change behaviour, the existing tests should guarantee compatibility ... on a long shot, maybe you'd also be interested into porting this codebase to TypeScript?

Performance tests are here: https://jsperf.app/wajexuw/2

Trying out pino these days, and it works like a charm 👍

Any thoughts on excluding certain HTTP headers from the request? I would really like to avoid dumping end-user's authorization header w/JWT into our logs.

Previously I've been using bunyan-middleware's obscureHeader option to accomplish this with bunyan. At first glance it doesn't look like there's something similar in these pino serialisers.

Have you accomplished something like this before or is it a plausible new feature of the standard request serialiser?

as titled

Cut new version from the next branch.

Relied upon by:

• pino-http

As explained in the Express docs, req.url gets rewritten in certain scenarios (notably when using app.use()) for internal routing purposes, the original request URL being saved in req.originalUrl.

req.originalUrl

This property is much like req.url; however, it retains the original request URL, allowing you to rewrite req.url freely for internal routing purposes. For example, the “mounting” feature of app.use() will rewrite req.url to strip the mount point.

This results into pino logging the wrong request url, although this can be worked around with a custom serializer:

  serializers: {
    req: (serializedRequest: any) => ({
      ...serializedRequest,
      url: serializedRequest.raw.originalUrl,
    }),
  },

As titled.

@davidmarkclements and @mcollina

This function causes fastify/light-my-request to emit warnings for deprecation whenever request.connection is accessed.

Refs:
https://github.com/fastify/light-my-request/blob/c677df30b7b5fa931422ba39c91ed25757390458/lib/request.js#L87
https://github.com/fastify/fastify/blob/5e0e674823642d851fefb73d78fc590325c880b2/lib/request.js#L134

Can I create a PR so that it will take from request.socket before request.connection?

What

As the Error Cause tc39 proposal has reached stage 4 and is accepted + part of Node.js since version 16.9.0 I think it would be great if these serializers started to use them.

Historical context

Also: For a long while before this proposal there was Joyent's VError module, which eg. was recommended in this Joyent article from +7 years ago and which was adopted by eg. Netflix who forked it as NError. VError also uses .cause but in their case it points to a method that returns the cause rather than the cause itself.

Related approaches

I myself created a module, pony-cause, which apart from providing a polyfill for Error Causes (ErrorWithCause) also provides a couple of helpers which supports official Error Causes as well as VError/NError causes, two which would be helpful here:

• messageWithCauses – resolves the messages from all causes into a single message, using the style of VError which is: To join them together using the equivalent of .join(': ')

• stackWithCauses – provides causes for the full chain, also similar to how VError does:

  Error: something really bad happened here
      at Object.<anonymous> (/examples/fullStack.js:5:12)
      at Module._compile (module.js:409:26)
      at Object.Module._extensions..js (module.js:416:10)
      at Module.load (module.js:343:32)
      at Function.Module._load (module.js:300:12)
      at Function.Module.runMain (module.js:441:10)
      at startup (node.js:139:18)
      at node.js:968:3
  caused by: Error: something bad happened
      at Object.<anonymous> (/examples/fullStack.js:3:12)
      at Module._compile (module.js:409:26)
      at Object.Module._extensions..js (module.js:416:10)
      at Module.load (module.js:343:32)
      at Function.Module._load (module.js:300:12)
      at Function.Module.runMain (module.js:441:10)
      at startup (node.js:139:18)
      at node.js:968:3
  

This approach follows the prior art of VError/NError and extends it to support the new Error Causes, making it a neat approach.

This also aligns with the support for VError style errors which bunyan has, but with the addition of supporting that format for new Error Causes as well.

Suggested approach

Either implement the functionality of my pony-cause module directly in this module or pull in my pony-cause module to:

• Use messageWithCauses to set the message property.
• Use stackWithCauses to set the cause property.

Related discussions

• This @mcollina response to a tweet of mine: https://twitter.com/matteocollina/status/1446048309903306753

Will/can I submit a PR?

Yes 👍

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

There appears to be a new version of @types/pino-std-serializers (version 4.0.0) published to npm 16 days ago which is missing a type definition file and thus has broken our use of typescript. Not having the type definition file results in a TS2688 error being thrown by the typescript compiler.

Npm reference:
https://www.npmjs.com/package/@types/pino-std-serializers

Part of the problem is the package @types/[email protected] has a wildcard version reference to the @types/pino-std-serializers package

"@types/pino-std-serializers": "*"

To fix dependency chains broken by this, at a minimum, a new 4.0.1 version of @types/pino-std-serializers with a valid index.d.ts should be published.

I'd like to propose a new feature.

AggregateErrors get serialised as regular errors, displaying only information from the aggregated error.

Including message and stack from the underlying errors, in a similar vain to what has been on #78 could be beneficial and provide a better picture.

Example

const log = require('pino')()
const inner = new Error('inner')
const aggregate = new AggregatedError([inner], 'aggregated')
log.error(aggregate)

Current serialisation

{
    "level": 50,
    "time": 1640082406574,
    "pid": 45285,
    "hostname": "hostname1",
    "stack": "AggregateError: aggregated\n    at REPL18:1:7\n    at Script.runInThisContext (node:vm:129:12)\n    at REPLServer.defaultEval (node:repl:562:29)\n    at bound (node:domain:421:15)\n    at REPLServer.runBound [as eval] (node:domain:432:12)\n    at REPLServer.onLine (node:repl:889:10)\n    at REPLServer.emit (node:events:402:35)\n    at REPLServer.emit (node:domain:475:12)\n    at REPLServer.Interface._onLine (node:readline:487:10)\n    at REPLServer.Interface._line (node:readline:864:8)",
    "type": "Error",
    "msg": "aggregated"
}

Possible improvement

{
    "level": 50,
    "time": 1640082406574,
    "pid": 45285,
    "hostname": "hostname1",
    "stack": "AggregateError: aggregated\n    at REPL18:1:7\n    at Script.runInThisContext (node:vm:129:12)\n    at REPLServer.defaultEval (node:repl:562:29)\n    at bound (node:domain:421:15)\n    at REPLServer.runBound [as eval] (node:domain:432:12)\n    at REPLServer.onLine (node:repl:889:10)\n    at REPLServer.emit (node:events:402:35)\n    at REPLServer.emit (node:domain:475:12)\n    at REPLServer.Interface._onLine (node:readline:487:10)\n    at REPLServer.Interface._line (node:readline:864:8)",
    "type": "Error",
    "msg": "aggregated",
    "aggregateErrors": [{
        "msg": "inner",
        "stack": "Error: inner\n    at REPL18:1:7\n    at Script.runInThisContext (node:vm:129:12)\n    at REPLServer.defaultEval (node:repl:562:29)\n    at bound (node:domain:421:15)\n    at REPLServer.runBound [as eval] (node:domain:432:12)\n    at REPLServer.onLine (node:repl:889:10)\n    at REPLServer.emit (node:events:402:35)\n    at REPLServer.emit (node:domain:475:12)\n    at REPLServer.Interface._onLine (node:readline:487:10)\n    at REPLServer.Interface._line (node:readline:864:8)"
    }]
} 

On every project I've used pino on (2 :-) ), we end up using our own err serializer that just does:

function errSerializer(err: Error): unknown {
  return {
    type: err.constructor.name,
    message: err.message,
    stack: err.stack,
  };
}

Because the for key in err behavior of the current serializer invariably ends up walking an Error that points to a connection pool or an HTTP request or an ORM metadata field or a Buffer that was not intended to put JSON.stringified and we get huge/nonsensical/corrupt output in our logs.

(The latest instance actually caused our app to crash b/c of an infinite loop in the fast-safe-stringify library: davidmarkclements/fast-safe-stringify#46 (comment))

So, admittedly based on my N=2, I think the err serializer should be changed to either:

1. This above verison that just does type, message, stack, or
2. Make the for key in err smarter and have it only copy over values that are one of:
   • a) primitives,
   • b) have a toJSON property, or
   • c) a is-plain-object (using that npm package) and then apply this same criteria to each value in that object (either as deep as it needs to go or for a fixed number of levels)

I realize both of these are breaking changes, but basically I think err serializer (and really everything in pino that leads to objects getting JSON.stringify'd) should not stringify classes unless it explicitly has a toJSON method on it because its not known whether the class really intended to have its potentially-large/circular 'private' data put on the wire.

(Basically only primitives, object literals, i.e. is-plain-object, and classes with toJSON, are fine to make this assumption.)

As an alternative given the breaking change, maybe having some sort of flag like doNotStringifyClasses (bad name, but you get the idea) on the top-level pino config that switched to different err and formatter behavior and recommend that in the docs as a better default going forward.

In http2 compat _header is just a boolean. Not quite what we expect?

Hi, apologies,

In #29, req.path was made preferred to req.url, for finding the url. In restify however req.path is a fucntion (this link is to current master branch). This causes the url not to be logged for restify systems.

Hello,

Both the req and res serializers have a const keyword in them, which is not ES5 compatible - could these be changed to var?

req.js - const _req = Object.create(pinoReqProto)
res.js - const _res = Object.create(pinoResProto)

Thanks

When running npm test or npm run test-ci I get the following error (running on Windows with npm in git bash/MinGW):

$ npm run test

> [email protected] test
> tap --no-cov 'test/**/*.test.js'

​ FAIL ​ 'test/**/*.test.js'
 ✖ ENOENT: no such file or directory, stat ''test/**/*.test.js''

  test: "'test/**/*.test.js'"
  stack: |
    Object.j.main (node_modules/jackspeak/index.js:483:5)
    execute (node_modules/jackspeak/index.js:224:7)
    jack (node_modules/jackspeak/index.js:163:31)
  at:
    line: 1536
    column: 3
    file: node:fs
    function: Object.statSync
  errno: -4058
  syscall: stat
  code: ENOENT
  path: "'test/**/*.test.js'"

​ FAIL ​ 'test/**/*.test.js' 1 failed of 1 128.292ms
 ✖ ENOENT: no such file or directory, stat ''test/**/*.test.js''




  🌈 SUMMARY RESULTS 🌈  

​ FAIL ​ 'test/**/*.test.js' 1 failed of 1 128.292ms
 ✖ ENOENT: no such file or directory, stat ''test/**/*.test.js''


Suites:   ​1 failed​, ​1 of 1 completed​
Asserts:  ​​​1 failed​, ​of 1​
​Time:​   ​498.155ms​

Recently encountered a weird error, here is the stack trace (node 12.18.1):

TypeError: Cannot read property 'name' of undefined
    at Object.errSerializer [as err] (/src/node_modules/pino-std-serializers/lib/err.js:45:31)
    at Pino.asJson (/src/node_modules/pino/lib/tools.js:118:50)
    at Pino.write (/src/node_modules/pino/lib/proto.js:160:28)
    at Pino.LOG [as info] (/src/node_modules/pino/lib/tools.js:55:21)
    at Server.audit (/src/lib/plugins/audit.js:158:15)
    at Server.emit (events.js:315:20)

https://github.com/pinojs/pino-std-serializers/blob/master/lib/err.js#L45

  _err.type = err.constructor.name

Incoming object is from restify after event:
Relevant piece of code where the log is triggered:

  function audit(req, res, route, err) {
    let latency = res.get('Response-Time');

    if (typeof latency !== 'number') {
      latency = Date.now() - req._time;
    }

    const obj = {
      remoteAddress: req.connection.remoteAddress,
      remotePort: req.connection.remotePort,
      user: req.user && req.user.id,
      req_id: req.getId(),
      req,
      res,
      err,
      latency,
      secure: req.secure,
      _audit: true,
      event: opts.event
    };

    if (printLog) {
      switch (opts.event) {
        case 'after':
          log.info(obj, 'handled: %d', res.statusCode); // <---------- error was triggered here
          break;

        case 'pre':
          log.info(obj, 'pre');
          break;

        case 'routed':
          log.info(obj, 'routed');
          break;

        default:
          throw new Error(`Unexpected audit event: ${opts.event}`);
      }
    }

    if (server !== undefined) {
      server.emit('audit', obj);
    }

    return true;
  }

  return audit;
}

I'm not exactly sure how it is possible for err.constructor to be undefined and still be an instanceof Error, but the error did happen.

Should I create a PR that introduces a check on the constructor property? I'm not sure how detailed the check should be as to not affect the performance too much

ie (truthy/instanceof) or smth else? or is the reason for error entirely in my domain and I should dig deeper to understand the reason for missing constructor?

Hi, I would like to migrate the tests from tap to node:test

Any chance to get this changed, since it is deprecated...
Thanks
Ognian

I'm building a custom serializer to sanitize some headers before logging and I had the impression that the parameter provider to the custom serializer was a deep serialized copy of the request, as the README reads: "the newly serialized request object".

However, on line 63 of lib/req.js _req.headers is given a reference to the request headers object.

I'm not sure if you want to make a copy of the headers object, but maybe you want to update the README.

For context, I can't use redact feature from pino because we let users provide their own pino logger instance and AFAIK child logger can't set redact...

We recently had a problem with pino in hapi, because hapi is unable to create the request.url object when the URL is invalid, see this gist

Our logger ends up falling apart here as the object being serialized is null. Although this can be fixed at source but it should be possible to pass a null object. The serializer should handle the null object gracefully.