interop with pino-http by setting res.err instead of calling log.error

[jstewmon]

• remove explicit log statement in favor of providing res.err and
  err.status as recognized by pino-http
• added pino ^5.12.0 as a devDependency to support extreme mode
  benchmark

fixes #19

[jstewmon]

Benchmarks

(master) benchmarks/pino-error-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬───────┬───────┬───────┬───────┬──────────┬─────────┬───────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max       │
├─────────┼───────┼───────┼───────┼───────┼──────────┼─────────┼───────────┤
│ Latency │ 16 ms │ 22 ms │ 40 ms │ 57 ms │ 23.75 ms │ 8.47 ms │ 154.97 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬────────┬────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼────────┼────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 2547   │ 2547   │ 4091   │ 5475   │ 4104.11 │ 766.47 │ 2546   │
├───────────┼────────┼────────┼────────┼────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 461 kB │ 461 kB │ 741 kB │ 991 kB │ 743 kB  │ 139 kB │ 461 kB │
└───────────┴────────┴────────┴────────┴────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

0 2xx responses, 41035 non 2xx responses
41k requests in 10.07s, 7.43 MB read

(PR) benchmarks/pino-error-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬───────┬───────┬───────┬───────┬──────────┬─────────┬───────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max       │
├─────────┼───────┼───────┼───────┼───────┼──────────┼─────────┼───────────┤
│ Latency │ 12 ms │ 14 ms │ 26 ms │ 32 ms │ 14.98 ms │ 4.74 ms │ 147.03 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬─────────┬────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%  │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼─────────┼────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 3713   │ 3713   │ 6819    │ 7187   │ 6462.28 │ 927.55 │ 3712   │
├───────────┼────────┼────────┼─────────┼────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 672 kB │ 672 kB │ 1.23 MB │ 1.3 MB │ 1.17 MB │ 168 kB │ 672 kB │
└───────────┴────────┴────────┴─────────┴────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

0 2xx responses, 71080 non 2xx responses
71k requests in 11.04s, 12.9 MB read

(master) benchmarks/pino-extreme-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼──────────┤
│ Latency │ 5 ms │ 6 ms │ 10 ms │ 16 ms │ 6.58 ms │ 2.36 ms │ 84.98 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴──────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 8679    │ 8679    │ 14679   │ 16007   │ 14084.8 │ 1921.04 │ 8676    │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 1.32 MB │ 1.32 MB │ 2.23 MB │ 2.43 MB │ 2.14 MB │ 292 kB  │ 1.32 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

141k requests in 10.04s, 21.4 MB read

(PR) benchmarks/pino-extreme-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬───────┬───────┬───────┬───────┬──────────┬─────────┬───────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max       │
├─────────┼───────┼───────┼───────┼───────┼──────────┼─────────┼───────────┤
│ Latency │ 17 ms │ 20 ms │ 41 ms │ 83 ms │ 23.09 ms │ 13.6 ms │ 208.25 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬────────┬────────┬─────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg     │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼─────────┼─────────┼────────┤
│ Req/Sec   │ 2819   │ 2819   │ 4335   │ 4747   │ 4239.91 │ 544.17  │ 2818   │
├───────────┼────────┼────────┼────────┼────────┼─────────┼─────────┼────────┤
│ Bytes/Sec │ 429 kB │ 429 kB │ 659 kB │ 722 kB │ 644 kB  │ 82.8 kB │ 428 kB │
└───────────┴────────┴────────┴────────┴────────┴─────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

47k requests in 11.04s, 7.09 MB read

(master) benchmarks/pino-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼──────────┤
│ Latency │ 5 ms │ 6 ms │ 17 ms │ 24 ms │ 7.42 ms │ 3.85 ms │ 90.94 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴──────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 8335    │ 8335    │ 13127   │ 15407   │ 12618.55 │ 2057.06 │ 8334    │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 1.27 MB │ 1.27 MB │ 1.99 MB │ 2.34 MB │ 1.92 MB  │ 313 kB  │ 1.27 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

139k requests in 11.05s, 21.1 MB read

(PR) benchmarks/pino-server.js

Running 10s test @ http://localhost:3000
100 connections

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼──────────┤
│ Latency │ 5 ms │ 5 ms │ 8 ms  │ 12 ms │ 5.74 ms │ 2.45 ms │ 110.9 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴──────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 9703    │ 9703    │ 16543   │ 17327   │ 15898.91 │ 2019.28 │ 9700    │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 1.47 MB │ 1.47 MB │ 2.51 MB │ 2.63 MB │ 2.42 MB  │ 307 kB  │ 1.47 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

175k requests in 11.04s, 26.6 MB read

[jstewmon]

Leaving a note for myself that I didn’t confirm a test case exists for ensuring the status is correctly captured when using ctx.throw

[jstewmon]

As it turns out, we only needed to assign ctx.res.err.

The Error instances created by http-errors assigns both status and statusCode as enumerable props, so the value is logged under two keys, which I don't love. But, the only way I can think to address it here would be to either delete one of them or redefine one of them as non-enumerable, which of course could violate someone's expectations elsewhere.

Is it possible to customize the err serializer to pick statusCode and omit status from the keys that are added to the JSON? Seems like that should be possible, but it's been a while since I worked with a custom serializer.

[amckibben]

Yeah ... this being so outdated is (I think) causing the pino redact option not to work / be available which is a bummer.

[clayreimann]

@davidmarkclements Is this likely to get merged any time soon?

[Fdawgs]

This has been resolved partially by #27 and #30.
@jstewmon would you be happy to rebase and review conflicts please?

[jstewmon]

@Fdawgs it has been a very long time, since I opened this, and I'm not actively using the package, but I did the rebase, so that this PR now just addresses the issue of thrown errors being logged in duplicate. 🤞