Remove overly verbose data from custom formatter #8353

cravend · 2023-05-18T05:53:09Z

This PR modifies the LogFormatter to filter overly verbose items out of the custom object logged with each entry. Currently, the following items are filtered:

const ignoredCustomData = [
  'time',
  'pid',
  'hostname',
  'msg',
  'res',
  'req',
  'reqId',
  'responseTime',
]

These items are used elsewhere in the log formatter, and including them in the custom object is redundant.

It also adds tests to ensure that these keys are removed.

After:

api | 10:35:43 🌲 incoming request GET xxx /auth?method=getToken
api | 10:35:43 🌲 Starting a postgresql pool with 1 connections.
api | 🗒 Custom
api | {
api |   "prisma": {
api |     "clientVersion": "4.14.0"
api |   },
api |   "target": "quaint::pooled",
api | }
api | 10:35:43 🌲 request completed 66ms
api | 10:35:43 🌲 incoming request POST xxx /graphql
api | 10:35:43 🐛 Parsing request to extract GraphQL parameters
api | 10:35:43 🐛 Processing GraphQL Parameters
api | 10:35:43 🐛 graphql-server GraphQL execution started: __REDWOOD__AUTH_GET_CURRENT_USER
api | 10:35:43 🌲 request completed 21ms
api | 10:35:43 🐛 graphql-server GraphQL execution completed: __REDWOOD__AUTH_GET_CURRENT_USER
api | 10:35:43 🐛 Processing GraphQL Parameters done.

Before:

api | 10:35:43 🌲 incoming request GET xxx /auth?method=getToken
api | 🗒 Custom
api | {
api |   "time": 1684074943416,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "reqId": "req-1",
api |   "req": {
api |     "method": "GET",
api |     "url": "/auth?method=getToken",
api |     "hostname": "localhost:8910",
api |     "remoteAddress": "::1",
api |     "remotePort": 54521
api |   },
api |   "msg": "incoming request"
api | }
api | 10:35:43 🌲 Starting a postgresql pool with 1 connections.
api | 🗒 Custom
api | {
api |   "time": 1684074943437,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "prisma": {
api |     "clientVersion": "4.14.0"
api |   },
api |   "timestamp": "2023-05-14T14:35:43.437Z",
api |   "target": "quaint::pooled",
api |   "msg": "Starting a postgresql pool with 1 connections."
api | }
api | 10:35:43 🌲 request completed 66ms
api | 🗒 Custom
api | {
api |   "time": 1684074943482,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "reqId": "req-1",
api |   "res": {
api |     "statusCode": 200
api |   },
api |   "msg": "request completed"
api | }
api | 10:35:43 🌲 incoming request POST xxx /graphql
api | 🗒 Custom
api | {
api |   "time": 1684074943545,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "reqId": "req-2",
api |   "req": {
api |     "method": "POST",
api |     "url": "/graphql",
api |     "hostname": "localhost:8910",
api |     "remoteAddress": "::1",
api |     "remotePort": 54524
api |   },
api |   "msg": "incoming request"
api | }
api | 10:35:43 🐛 Parsing request to extract GraphQL parameters
api | 🗒 Custom
api | {
api |   "time": 1684074943549,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "msg": "Parsing request to extract GraphQL parameters"
api | }
api | 10:35:43 🐛 Processing GraphQL Parameters
api | 🗒 Custom
api | {
api |   "time": 1684074943549,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "msg": "Processing GraphQL Parameters"
api | }
api | 10:35:43 🐛 graphql-server GraphQL execution started: __REDWOOD__AUTH_GET_CURRENT_USER
api | 🗒 Custom
api | {
api |   "time": 1684074943564,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "msg": "GraphQL execution started: __REDWOOD__AUTH_GET_CURRENT_USER"
api | }
api | 10:35:43 🌲 request completed 21ms
api | 🗒 Custom
api | {
api |   "time": 1684074943567,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "reqId": "req-2",
api |   "res": {
api |     "statusCode": 200
api |   },
api |   "msg": "request completed"
api | }
api | 10:35:43 🐛 graphql-server GraphQL execution completed: __REDWOOD__AUTH_GET_CURRENT_USER
api | 🗒 Custom
api | {
api |   "time": 1684074943565,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "msg": "GraphQL execution completed: __REDWOOD__AUTH_GET_CURRENT_USER"
api | }
api | 10:35:43 🐛 Processing GraphQL Parameters done.
api | 🗒 Custom
api | {
api |   "time": 1684074943565,
api |   "pid": 30701,
api |   "hostname": "Daltons-Air",
api |   "msg": "Processing GraphQL Parameters done."
api | }

Closes #8318

replay-io · 2023-05-18T06:04:14Z

18 replays were recorded for 18ad691.

0 Failed

18 Passed

useAuth hook, auth redirects checks

locator.waitFor: Target closed
=========================== logs ===========================
waiting for locator('text=Username `testuser@bazinga.com` already in use') to be visible
============================================================

Check that a specific blog post is prerendered
Check that about is prerendered
Check that homepage is prerendered
Check that meta-tags are rendering the correct dynamic data
Check that rehydration works for page not wrapped in Set
Check that rehydration works for page with Cell in Set
Check that rehydration works for page with code split chunks
Check that you can navigate from home page to specific blog post
Waterfall prerendering (nested cells)
RBAC: Admin user should be able to delete contacts

RBAC: Should not be able to delete contact as non-admin user

page.waitForNavigation: Navigation failed because page was closed!
=========================== logs ===========================
waiting for navigation to "**/" until "load"
============================================================

Smoke test with dev server
Smoke test with rw serve
Loads Cell mocks when Cell is nested in another story
Loads Cell Stories
Loads MDX Stories
Mocks current user, and updates UI while dev server is running

View test run on Replay ↗︎

dac09 · 2023-05-18T08:17:31Z

Thanks for this also @cravend - would you mind updating the description with a couple of screenshots / small description on what this achieves? (hard to tell from the code)

It also helpful for users to see exactly what got merged without diving into the code :)

cravend · 2023-05-18T16:12:15Z

Thanks for this also @cravend - would you mind updating the description with a couple of screenshots / small description on what this achieves? (hard to tell from the code)

It also helpful for users to see exactly what got merged without diving into the code :)

Done @dac09 :-)

dthyresson · 2023-05-18T20:34:42Z

Thanks @cravend I'll review soon. I had initially thought of a different implementation rather than ignoring those attributes -- but I have to remember what it was (and it may not have worked). Let me try to recall what that was so I can review better.

Thanks so much for taking this on!

dthyresson

Thanks @cravend ! Approved!

Sorry this got off my review list for so long. This definitely makes logs cleaner and easier to read.

I might decide to add in the req url and /or id on the main message line at some point if we find that having the request url in a more serverful log is helpful.

Thanks again and I'll merge when CI completes.

Thanks again!

cravend · 2023-05-24T22:06:33Z

Thanks @cravend ! Approved!

Sorry this got off my review list for so long. This definitely makes logs cleaner and easier to read.

I might decide to add in the req url and /or id on the main message line at some point if we find that having the request url in a more serverful log is helpful.

Thanks again and I'll merge when CI completes.

Thanks again!

Sounds good! Thanks :-)

Just so you know, the req url is in the main message already (but ID and hostname are not).

dthyresson · 2023-05-24T22:47:23Z

Thanks @cravend ! Approved!
Sorry this got off my review list for so long. This definitely makes logs cleaner and easier to read.
I might decide to add in the req url and /or id on the main message line at some point if we find that having the request url in a more serverful log is helpful.
Thanks again and I'll merge when CI completes.
Thanks again!

Sounds good! Thanks :-)

Just so you know, the req url is in the main message already (but ID and hostname are not).

Oh you’re right. Perfect! Thanks again!

* refactor: remove overly verbose data from custom formatter * test: add tests for LogFormatter custom filter --------- Co-authored-by: David Thyresson <dthyresson@gmail.com>

jtoar · 2023-05-31T23:48:05Z

Talked with @thedavidprice, we're not sure if this is breaking or not strictly but since we're taking away information that people could be relying in some edge case in production, we just don't feel comfortable releasing it in a minor. v6 is on the horizon, or at least not too far away, so we'll get this out then. Thanks @cravend!

This reverts commit 9d443ef.

cravend added 2 commits May 18, 2023 02:06

refactor: remove overly verbose data from custom formatter

8fd896b

test: add tests for LogFormatter custom filter

8ec6657

cravend force-pushed the djc-simplify-server-logs branch from 0df81e5 to 8ec6657 Compare May 18, 2023 06:08

dac09 added the release:fix This PR is a fix label May 18, 2023

dac09 self-assigned this May 18, 2023

dthyresson self-requested a review May 18, 2023 20:31

dthyresson assigned dthyresson and unassigned dac09 May 18, 2023

dthyresson requested a review from Tobbe May 18, 2023 20:32

Merge branch 'main' into djc-simplify-server-logs

18ad691

dthyresson approved these changes May 24, 2023

View reviewed changes

dthyresson enabled auto-merge (squash) May 24, 2023 21:03

dthyresson merged commit b627156 into redwoodjs:main May 24, 2023
25 checks passed

redwoodjs-bot bot added this to the next-release milestone May 24, 2023

cravend deleted the djc-simplify-server-logs branch May 24, 2023 22:07

jtoar added release:breaking This PR is a breaking change and removed release:fix This PR is a fix labels May 31, 2023

jtoar modified the milestones: next-release, v6.0.0 Jun 1, 2023

jtoar added a commit that referenced this pull request Jun 2, 2023

Revert "Remove overly verbose data from custom formatter (#8353)"

a8610b8

This reverts commit 9d443ef.

jtoar mentioned this pull request Jun 12, 2023

Move fastify.logger.infos to fastify.logger.traces #8590

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove overly verbose data from custom formatter #8353

Remove overly verbose data from custom formatter #8353

cravend commented May 18, 2023 •

edited

replay-io bot commented May 18, 2023 •

edited

dac09 commented May 18, 2023

cravend commented May 18, 2023

dthyresson commented May 18, 2023

dthyresson left a comment

cravend commented May 24, 2023

dthyresson commented May 24, 2023

jtoar commented May 31, 2023

Remove overly verbose data from custom formatter #8353

Remove overly verbose data from custom formatter #8353

Conversation

cravend commented May 18, 2023 • edited

After:

Before:

replay-io bot commented May 18, 2023 • edited

dac09 commented May 18, 2023

cravend commented May 18, 2023

dthyresson commented May 18, 2023

dthyresson left a comment

Choose a reason for hiding this comment

cravend commented May 24, 2023

dthyresson commented May 24, 2023

jtoar commented May 31, 2023

cravend commented May 18, 2023 •

edited

replay-io bot commented May 18, 2023 •

edited