search

artsy / positron

Positron is Artsy Writer or the editorial tool and API for Artsy.
MIT License
85 stars 42 forks source link

POC - Node - standard logging format #3102

Closed ovasdi closed 1 year ago

ovasdi commented 1 year ago

https://artsyproduct.atlassian.net/browse/PLATFORM-4903

This PR introduces a new logger Pino (replacing artsy-morgan) for the purposes of proving out a POC which is about standardizing our logging posture across Artsy applications and specifically as it pertains to web apps.

Word on artsy-morgan: it appears this package is only used in Positron. artsy-morgan is just morgan, an HTTP logger for express.js apps, with minimal tweaks for colorized output and format. Seeing as morgan is specifically designed for use with express and for HTTP logging, Pino may be a better recommendation as an all-purpose highly performant logging solution across Node apps at Artsy.

Few reasons for choosing pino over the other alternatives (eg: winston) are:

Note that this PR uses pino v7.11.0 and pino-http v7.1.0 seeing as Positron is currently on Node12 and pino[-http] v8 (latest) does not have LTS support for Node12, according to this schedule table.

The implementation in this PR replaced only the middleware logging. In case of Positron, the app has a number of lines being logged using console.log. Those have not been touched for this POC.

I did not spend a lot of time configuring log output. As agreed upon during the last velocity mob session, this PR is mostly using defaults that come out of the box when using Pino library.

If this was to get merged as is, as far viewing logs in papertrail, I believe we would see something similar to kube-api logs but for Positron requests.

Some questions for PR discussion:

NOTE: sensitive information has been removed from the logs (via logger configuration), namely: x-access-token and cookie, which are logged by default with the whole request object. The timestamp has been formatted to be more human-readable.

Below is an example request for the purposes of demonstration and discussion:

request path: /

artsy-morgan ``` GET / 302 3.278 ms - 62 POST /api/graphql 200 1816.408 ms - - GET /api/sessions 200 106.931 ms - 2 GET /articles 304 2315.606 ms - - GET /assets/main.css 304 51.697 ms - - GET /icons/search.svg 304 6.397 ms - - [socket] onArticlesRequested, channel id: [REDACTED] GET /images/favicon.ico 304 146.969 ms - - GET /api/sessions 200 145.264 ms - 2 GET /api/channels?user_id=[REDACTED]&limit=50 304 457.635 ms - - ```
pino ```JSON { "level": "info", "time": "2023-01-27T18:00:35.205Z", "req": { "id": 51, "method": "GET", "url": "/", "query": {}, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "sec-ch-ua-mobile": "?0", "sec-ch-ua-platform": "\"macOS\"", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "sec-fetch-site": "same-origin", "sec-fetch-mode": "navigate", "sec-fetch-user": "?1", "sec-fetch-dest": "document", "referer": "http://localhost:3005/settings", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9" }, "remoteAddress": "::1", "remotePort": 56443 }, "res": { "statusCode": 302, "headers": { "x-powered-by": "Express", "x-frame-options": "SAMEORIGIN", "location": "/articles", "vary": "Accept, Accept-Encoding", "content-type": "text/html; charset=utf-8", "content-length": "62" } }, "responseTime": 4, "msg": "request completed" }, { "level": "info", "time": "2023-01-27T18:00:35.760Z", "req": { "id": 53, "method": "POST", "url": "/api/graphql", "query": {}, "params": {}, "headers": { "accept": "application/json", "content-type": "application/json", "accept-encoding": "gzip,deflate", "user-agent": "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)", "connection": "close", "content-length": "348", "x-datadog-trace-id": "[REDACTED]", "x-datadog-parent-id": "[REDACTED]", "x-datadog-sampling-priority": "1", "host": "localhost:3005" }, "remoteAddress": "::ffff:127.0.0.1", "remotePort": 56444 }, "res": { "statusCode": 200, "headers": { "x-powered-by": "Express", "access-control-allow-origin": "*", "content-type": "application/json; charset=utf-8", "vary": "Accept-Encoding", "content-encoding": "gzip" } }, "responseTime": 516, "msg": "request errored" }, { "level": "info", "time": "2023-01-27T18:00:35.865Z", "req": { "id": 54, "method": "GET", "url": "/api/sessions", "query": {}, "params": {}, "headers": { "x-datadog-trace-id": "[REDACTED]", "x-datadog-parent-id": "[REDACTED]", "x-datadog-sampling-priority": "1", "host": "localhost:3005", "accept-encoding": "gzip, deflate", "connection": "close" }, "remoteAddress": "::ffff:127.0.0.1", "remotePort": 56445 }, "res": { "statusCode": 200, "headers": { "x-powered-by": "Express", "access-control-allow-origin": "*", "content-type": "application/json; charset=utf-8", "content-length": "2", "etag": "W/\"2-l9Fw4VUO7kr8CvBlt4zaMCqXZ0w\"", "vary": "Accept-Encoding" } }, "responseTime": 97, "msg": "request errored" }, { "level": "info", "time": "2023-01-27T18:00:35.920Z", "req": { "id": 52, "method": "GET", "url": "/articles", "query": {}, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "sec-fetch-site": "same-origin", "sec-fetch-mode": "navigate", "sec-fetch-user": "?1", "sec-fetch-dest": "document", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "sec-ch-ua-mobile": "?0", "sec-ch-ua-platform": "\"macOS\"", "referer": "http://localhost:3005/settings", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9", "if-none-match": "W/\"3999-bNG7tLn35AyW0ot1tLksYgZfGX4\"" }, "remoteAddress": "::1", "remotePort": 56443 }, "res": { "statusCode": 304, "headers": { "x-powered-by": "Express", "x-frame-options": "SAMEORIGIN", "etag": "W/\"3999-bNG7tLn35AyW0ot1tLksYgZfGX4\"" } }, "responseTime": 688, "msg": "request completed" }, { "level": "info", "time": "2023-01-27T18:00:36.012Z", "req": { "id": 55, "method": "GET", "url": "/assets/main.css", "query": {}, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "if-none-match": "W/\"19b18-185f4279dbb\"", "if-modified-since": "Fri, 27 Jan 2023 16:55:15 GMT", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"macOS\"", "accept": "text/css,*/*;q=0.1", "sec-fetch-site": "same-origin", "sec-fetch-mode": "no-cors", "sec-fetch-dest": "style", "referer": "http://localhost:3005/articles", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9" }, "remoteAddress": "::1", "remotePort": 56443 }, "res": { "statusCode": 304, "headers": { "x-powered-by": "Express", "x-frame-options": "SAMEORIGIN", "accept-ranges": "bytes", "cache-control": "public, max-age=0", "last-modified": "Fri, 27 Jan 2023 16:55:15 GMT", "etag": "W/\"19b18-185f4279dbb\"" } }, "responseTime": 63, "msg": "request completed" }, { "level": "info", "time": "2023-01-27T18:00:36.871Z", "req": { "id": 56, "method": "GET", "url": "/icons/search.svg", "query": {}, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "if-none-match": "W/\"3f7-180858b48a7\"", "if-modified-since": "Mon, 02 May 2022 16:12:19 GMT", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"macOS\"", "accept": "image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8", "sec-fetch-site": "same-origin", "sec-fetch-mode": "no-cors", "sec-fetch-dest": "image", "referer": "http://localhost:3005/assets/main.css", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9" }, "remoteAddress": "::1", "remotePort": 56446 }, "res": { "statusCode": 304, "headers": { "x-powered-by": "Express", "x-frame-options": "SAMEORIGIN", "accept-ranges": "bytes", "cache-control": "public, max-age=0", "last-modified": "Mon, 02 May 2022 16:12:19 GMT", "etag": "W/\"3f7-180858b48a7\"" } }, "responseTime": 8, "msg": "request completed" }, [socket] onArticlesRequested, channel id: [REDACTED] { "level": "info", "time": "2023-01-27T18:00:37.152Z", "req": { "id": 57, "method": "GET", "url": "/api/sessions", "query": {}, "params": {}, "headers": { "x-datadog-trace-id": "[REDACTED]", "x-datadog-parent-id": "[REDACTED]", "x-datadog-sampling-priority": "1", "host": "localhost:3005", "accept-encoding": "gzip, deflate", "connection": "close" }, "remoteAddress": "::ffff:127.0.0.1", "remotePort": 56450 }, "res": { "statusCode": 200, "headers": { "x-powered-by": "Express", "access-control-allow-origin": "*", "content-type": "application/json; charset=utf-8", "content-length": "2", "etag": "W/\"2-l9Fw4VUO7kr8CvBlt4zaMCqXZ0w\"", "vary": "Accept-Encoding" } }, "responseTime": 71, "msg": "request errored" }, { "level": "info", "time": "2023-01-27T18:00:37.325Z", "req": { "id": 59, "method": "GET", "url": "/images/favicon.ico", "query": {}, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"macOS\"", "accept": "image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8", "sec-fetch-site": "same-origin", "sec-fetch-mode": "no-cors", "sec-fetch-dest": "image", "referer": "http://localhost:3005/articles", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9", "if-none-match": "W/\"76cc-Oj2M/jF5AiF2s5NrMFAiMgN13kY\"" }, "remoteAddress": "::1", "remotePort": 56452 }, "res": { "statusCode": 304, "headers": { "x-powered-by": "Express", "x-frame-options": "SAMEORIGIN", "etag": "W/\"76cc-Oj2M/jF5AiF2s5NrMFAiMgN13kY\"" } }, "responseTime": 176, "msg": "request completed" }, { "level": "info", "time": "2023-01-27T18:00:37.777Z", "req": { "id": 58, "method": "GET", "url": "/api/channels?user_id=[REDACTED]&limit=50", "query": { "user_id": "[REDACTED]", "limit": "50" }, "params": {}, "headers": { "host": "localhost:3005", "connection": "keep-alive", "sec-ch-ua": "\"Not_A Brand\";v=\"99\", \"Google Chrome\";v=\"109\", \"Chromium\";v=\"109\"", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"macOS\"", "accept": "*/*", "sec-fetch-site": "same-origin", "sec-fetch-mode": "cors", "sec-fetch-dest": "empty", "referer": "http://localhost:3005/articles", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9", "if-none-match": "W/\"568-ZFbZfVT8b6crZwt3rqLB38sA2wE\"" }, "remoteAddress": "::1", "remotePort": 56451 }, "res": { "statusCode": 304, "headers": { "x-powered-by": "Express", "access-control-allow-origin": "*", "etag": "W/\"568-ZFbZfVT8b6crZwt3rqLB38sA2wE\"" } }, "responseTime": 636, "msg": "request errored" } ```
codecov[bot] commented 1 year ago

Codecov Report

Merging #3102 (cd72896) into main (9d19fbf) will increase coverage by 0.0%. The diff coverage is 100.0%.

@@          Coverage Diff          @@
##            main   #3102   +/-   ##
=====================================
  Coverage   83.0%   83.0%           
=====================================
  Files        197     198    +1     
  Lines       5416    5420    +4     
  Branches     989     989           
=====================================
+ Hits        4500    4504    +4     
  Misses       663     663           
  Partials     253     253
ovasdi commented 1 year ago

RE: the question, do we want to change the structure of the log output? If so, how?

I think the default format looks OK, for the most part, but it does feel quite busy and IMO there are some fields that we could eliminate or rename, to make them more clear:

The following fields seem not very useful:

req.id: remove req.headers.connection: remove req.headers.sec-ch-ua*: remove req.headers.upgrade-insecure-requests: remove req.headers.sec-fetch*: remove (though sec-fetch-site may be useful to keep?)

On that note, I liked the example that is listed in the OWASP logging cheat sheet. I wonder if it would be worth following that example more closely. This would necessitate some heavy formating customization tho.

ovasdi commented 1 year ago

Another question I am contemplating is regarding log format when running in development vs production mode. How different do we the format to be between environments? I would think we would want only what is most useful. Hence why I like the OWASP example. It seems quite lean compared to the Pino default. I also like that it's not nested.

joeyAghion commented 1 year ago

This is a lot more data than we currently log! On the one hand, I could see that being useful (e.g., Cloudflare headers available in logs), on the other, we're already trending toward exhausting our quota regularly, and a lot of the headers are noise. I would consider removing all the request and response headers, or maybe all but a few interesting ones (User-agent, Accept...).

Curious what others think.

mc-jones commented 1 year ago

I agree with cutting down the defaults here that we don't anticipate providing much value, though I do think that one of the nice things about the new JSON format gives us the ability to log more without it generating too much more visual noise since we can collapse or expand the JSON string in papertrail. In other words, I would vote to cut down the current output form peno outputs, but think we should feel free to leverage the more readable JSON format where it makes sense for this or other repos.

I think using the OWASP format you linked to @ovasdi is a reasonable start. It would also be good to see how much work it takes to customize the output in peno.

ovasdi commented 1 year ago

I started to customize the httpLogger and quickly learned that a bug in pino-http causes cutomProps, logger option for adding custom properties, to get logged twice... Looking if similar customization can be achieved using the formatters.log API otherwise will need some workaround.

ovasdi commented 1 year ago

I was not able to come up with a working and clean workaround to fully customize the httpLogger. My plan was to remove all of req and res from the httpLogger and build a one level object, similar to the example mentioned earlier, with only the properties that we would want to see. I ended up expanding the redact.paths list to remove the various properties we don't care about. This isn't ideal and not super portable.

I am happy to work out a better solution if this approach isn't sufficient.

ovasdi commented 1 year ago

I am just realizing I dismissed this workaround thinking WeakSet is only supported in Node v14+ but it seems it may be supported in earlier versions as well. Will give this a try tomorrow.

ovasdi commented 1 year ago

The latest changes in b1165f1 refactors the logger to include a custom serializer which operates on req and res objects specifying which properties to keep. This eliminates the need for using the redact API to remove sensitive values from logs.

I also added a custom message for received requests to make it easier to identify incoming requests.

There are a number of requests that contain the message 'request errored'. These do complete successfully, with status code 200 or 304. Unclear why the logger is including the 'errored' message but appears to mostly affect: /api/sessions, /api/graphql, /api/channels.

Log sample ``` { "level": "info", "time": "2023-02-01T16:08:38.921Z", "req": { "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sourceIP": "::1", "hostname": "localhost:3005", "requestURI": "/", "requestMethod": "GET", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9" }, "msg": "request received" }, { "level": "info", "time": "2023-02-01T16:08:38.926Z", "req": { "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sourceIP": "::1", "hostname": "localhost:3005", "requestURI": "/", "requestMethod": "GET", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9" }, "res": { "statusCode": 302 }, "responseTime": 5, "msg": "request completed" }, { "level": "info", "time": "2023-02-01T16:08:38.930Z", "req": { "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "sourceIP": "::1", "hostname": "localhost:3005", "requestURI": "/articles", "requestMethod": "GET", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9" }, "msg": "request received" }, { "level": "info", "time": "2023-02-01T16:08:38.935Z", "req": { "useragent": "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)", "sourceIP": "::ffff:127.0.0.1", "hostname": "localhost:3005", "requestURI": "/api/graphql", "requestMethod": "POST", "accept": "application/json" }, "msg": "request received" }, { "level": "info", "time": "2023-02-01T16:08:39.397Z", "req": { "useragent": "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)", "sourceIP": "::ffff:127.0.0.1", "hostname": "localhost:3005", "requestURI": "/api/graphql", "requestMethod": "POST", "accept": "application/json" }, "res": { "statusCode": 200 }, "responseTime": 462, "msg": "request errored" } ```
ovasdi commented 1 year ago

I don't follow the need for the custom "request received" lines. It's pretty standard to log upon request completion, which I think is already achieved by default (even if the request fails).

I removed this. I was looking at an outdated copy of logs and didn't realize that adding this option actually enables additional logs to be output for 'received requests'. Thanks for pointing this out.

Can you explain those other customizations around pid, timestamp, and level?

Updated log sample ``` { "level": "info", "time": "2023-02-01T17:31:50.103Z", "req": { "method": "GET", "url": "/", "hostname": "localhost:3005", "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "remoteAddress": "::1", "port": 58368 }, "res": { "statusCode": 302 }, "responseTime": 3, "msg": "request completed" }, { "level": "info", "time": "2023-02-01T17:31:50.522Z", "req": { "method": "POST", "url": "/api/graphql", "hostname": "localhost:3005", "useragent": "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)", "accept": "application/json", "remoteAddress": "::ffff:127.0.0.1", "port": 58369 }, "res": { "statusCode": 200 }, "responseTime": 409, "msg": "request errored" }, { "level": "info", "time": "2023-02-01T17:31:50.608Z", "req": { "method": "GET", "url": "/api/sessions", "hostname": "localhost:3005", "remoteAddress": "::ffff:127.0.0.1", "port": 58370 }, "res": { "statusCode": 200 }, "responseTime": 82, "msg": "request errored" }, { "level": "info", "time": "2023-02-01T17:31:50.650Z", "req": { "method": "GET", "url": "/articles", "hostname": "localhost:3005", "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "remoteAddress": "::1", "port": 58368 }, "res": { "statusCode": 304 }, "responseTime": 543, "msg": "request completed" }, { "level": "info", "time": "2023-02-01T17:31:50.737Z", "req": { "method": "GET", "url": "/assets/main.css", "hostname": "localhost:3005", "useragent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36", "accept": "text/css,*/*;q=0.1", "remoteAddress": "::1", "port": 58368 }, "res": { "statusCode": 304 }, "responseTime": 63, "msg": "request completed" }, ```
ovasdi commented 1 year ago

After discussing with @joeyAghion all options but one were removed. The only option remaining is the custom serializer which lists the properties of req and res we want to see in the logged output. Everything else is the default.

Find additional context in this slack thread