Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

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

wants to merge 1 commit into from

Conversation

jstewmon
Copy link

@jstewmon jstewmon commented Apr 3, 2019

  • 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
Copy link
Author

jstewmon commented Apr 3, 2019 •
edited
Loading

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
Copy link
Author

jstewmon commented Apr 4, 2019

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
Copy link
Author

jstewmon commented Apr 4, 2019

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
Copy link

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

@clayreimann
Copy link

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

@Fdawgs
Copy link
Member

Fdawgs commented Dec 24, 2021 •
edited
Loading

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

@jstewmon jstewmon changed the title update pino-http to ^4.1.0 interop with pino-http by setting res.err instead of calling log.error Dec 24, 2021
@jstewmon
Copy link
Author

@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. 🤞

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@Fdawgs Fdawgs Fdawgs approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

using ctx.throw results in both request errored and request completed being logged
4 participants
@jstewmon @amckibben @clayreimann @Fdawgs