sainsburys-tech / next-logger

JSON logging patcher for Next.js
MIT License
144 stars 14 forks source link

jsdoc-based typescript rewrite #15

Closed devinrhode2 closed 6 months ago

devinrhode2 commented 2 years ago

See commit log

devinrhode2 commented 2 years ago

Adding typescript on it's own isn't super useful Neither are my prettier preferences This is all foundational bits for major refactoring I am doing

I can keep pushing commits to this PR (easiest) Or, I can stack PRs (not much harder, I'm pretty experienced with it)

atkinchris commented 2 years ago

Thank you for the work that's been put into this; there's a lot of change here and I'm thankful for your interest in developing the library. To make contributions easier to review and accept, they should be broken down into on a per-change basis, so they can be reviewed individually.

Additionally, there's a few changes that I wouldn't be able to bring into the library at this stage, without further discussion.

This is all foundational bits for major refactoring I am doing

What is the major refactor you're planning? If there's a fundamental change you'd like to make, please raise a GitHub Issue so we can discuss it in threads, and make PRs like this easier to review.

I'm a great fan of TypeScript. However, if it was to be introduced into the library, given users mostly interact with it without writing code (i.e. NODE_OPTIONS='-r next-logger' next start), the specific change would need to be isolated to typing - and preserve the implementation like-for-like.

devinrhode2 commented 2 years ago

Prepare scripts actually should be dev-only, but it'd be interesting to test

Indeed, these changes are not broken up for improved readability

devinrhode2 commented 2 years ago

I am actually done making functional changes

So the final code wouldn't change much from what is here now

Prettier settings can be changed

Nvmrc, I think it should be ok to add data for Volta users

devinrhode2 commented 2 years ago

Here’s a few things I would highlight

  1. Type check everything on strict mode.
  2. Avoid ambiguous decisions in code, generate warnings and errors instead
  3. Avoid relying on pino logMethod hook (poor/no ts interface)
  4. Through strict typing approach, I ended up generating these simple config objects which map next and console methods to pino methods.

I think the commit log could use a LOT of cleanup. Given some major cleanup it will probably serve as a pretty useful mechanism to view and understand the changes. (After which, I can try to break things up into separate PRs). I usually try to produce extremely clean commit logs, but was under pressure at work, and wanted to try skimping in this area. (I didn’t enjoy it)

I may have updated a few unit tests very early on, but pretty quickly stopped updating them.

I didn’t rush though refactoring this as quickly as possible, but did cut a few small corners along the way, which should probably be addressed before merging here. For example, I filter out logs starting with “ApplicationInsights:”,

devinrhode2 commented 2 years ago

I don’t expect you @atkinchris to review this as-is, but I’d like to leave this open for discoverability. It likely contains fixes and changes others would like to cherry pick into smaller PRs :)

devinrhode2 commented 2 years ago

I didn't know this when I started refactoring, but it turns out there were no major bugs that this refactoring fixed. The bugs were evidently inside of pino-applicationinsights.

The huge improvement that has been made to next-logger, however, is that:

Here's a diff of cli output before+after my changes (yes I'm logging the final objects I pass to pino-applicationinsights, but the diff still reflects the underlying changes coming from my next-logger fork)

-SNAPSHOT with next-logger@3.0.1 + pino-applicationinsights #v3-beta 
+SNAPSHOT with next-logger #major-ts-based-refactoring + pino-applicationinsights #v3-beta 
+  [next-logger] defined global{This}.originalConsole.{debug,log,warn,error}
   called applicationinsights.start()
-  ERROR [1650210589069] (console/26510 on MacBook-Air): (node:26510) Warning: Using insecure HTTP parsing
+  [next-logger] patching next methods: wait, error, warn, ready, info, event, trace
+  [next-logger] patching console methods: error, warn, log, info, dirxml, table, trace
+  ERROR [1650210907293] (next-logger-patched-console/27059 on MacBook-Air): (node:27059) Warning: Using insecure HTTP parsing
   (Use `node --trace-warnings ...` to show where the warning was created)
   applicationinsights trackTrace {
-    message: '(node:26510) Warning: Using insecure HTTP parsing\n' +
+    message: '(node:27059) Warning: Using insecure HTTP parsing\n' +
       '(Use `node --trace-warnings ...` to show where the warning was created)',
     severity: 3,
     properties: {
-      time: 1650210589069,
-      pid: 26510,
+      time: 1650210907293,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }
   applicationinsights trackException {
-    exception: Error: (node:26510) Warning: Using insecure HTTP parsing
+    exception: Error: (node:27059) Warning: Using insecure HTTP parsing
     (Use `node --trace-warnings ...` to show where the warning was created)
         at insertException (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:85:12)
         at /Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:212:7
         at Array.forEach (<anonymous>)
         at insert (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:135:9)
         at Writable.writeStream._write (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:234:7)
         at writeOrBuffer (node:internal/streams/writable:389:12)
         at _write (node:internal/streams/writable:330:10)
         at Writable.write (node:internal/streams/writable:334:10)
         at Transform.ondata (/Users/devinrhode2/repos/company-project/pino-applicationinsights/node_modules/readable-stream/lib/_stream_readable.js:681:20)
         at Transform.emit (node:events:526:28),
     severity: 3,
     properties: {
-      time: 1650210589069,
-      pid: 26510,
+      time: 1650210907293,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }
-  INFO [1650210589074] (next.js/26510 on MacBook-Air): started server on 0.0.0.0:3000, url: http://localhost:3000
+  INFO [1650210907299] (next-logger-nextjs-patch/27059 on MacBook-Air): next.ready: started server on 0.0.0.0:3000, url: http://localhost:3000
   applicationinsights trackTrace {
-    message: 'started server on 0.0.0.0:3000, url: http://localhost:3000',
+    message: 'next.ready: started server on 0.0.0.0:3000, url: http://localhost:3000',
     severity: 1,
     properties: {
-      time: 1650210589074,
-      pid: 26510,
+      time: 1650210907299,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'next.js',
+      name: 'next-logger-nextjs-patch',
       prefix: 'ready'
     }
   }
-  INFO [1650210589076] (next.js/26510 on MacBook-Air): Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.production.local
+  INFO [1650210907302] (next-logger-nextjs-patch/27059 on MacBook-Air): next.info: Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.production.local
   applicationinsights trackTrace {
-    message: 'Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.production.local',
+    message: 'next.info: Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.production.local',
     severity: 1,
     properties: {
-      time: 1650210589076,
-      pid: 26510,
+      time: 1650210907302,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'next.js',
+      name: 'next-logger-nextjs-patch',
       prefix: 'info'
     }
   }
-  INFO [1650210589077] (next.js/26510 on MacBook-Air): Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.local
+  INFO [1650210907304] (next-logger-nextjs-patch/27059 on MacBook-Air): next.info: Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.local
   applicationinsights trackTrace {
-    message: 'Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.local',
+    message: 'next.info: Loaded env from /Users/devinrhode2/repos/company-project/demo-app/.env.local',
     severity: 1,
     properties: {
-      time: 1650210589077,
-      pid: 26510,
+      time: 1650210907304,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'next.js',
+      name: 'next-logger-nextjs-patch',
       prefix: 'info'
     }
   }
-  INFO [1650210589623] (console/26510 on MacBook-Air): next.config.js loaded
+  INFO [1650210907885] (next-logger-patched-console/27059 on MacBook-Air): next.config.js loaded
   applicationinsights trackTrace {
     message: 'next.config.js loaded',
     severity: 1,
     properties: {
-      time: 1650210589623,
-      pid: 26510,
+      time: 1650210907885,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'log'
     }
   }
-  ERROR [1650210620171] (console/26510 on MacBook-Air): intentionally crash
+  ERROR [1650210913512] (next-logger-patched-console/27059 on MacBook-Air): intentionally crash
       err: {
         "type": "Error",
         "message": "intentionally crash",
         "stack":
             Error: intentionally crash
                 at apiHandler (/Users/devinrhode2/repos/company-project/demo-app/.next/server/pages/api/throw.js:16:9)
                 at Object.apiResolver (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/api-utils.js:102:15)
                 at processTicksAndRejections (node:internal/process/task_queues:96:5)
                 at async NextNodeServer.handleApiRequest (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:1076:9)
                 at async Object.fn (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:963:37)
                 at async Router.execute (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/router.js:222:32)
                 at async NextNodeServer.run (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:1103:29)
                 at async NextNodeServer.handleRequest (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:319:20)
       }
   applicationinsights trackTrace {
     message: 'intentionally crash',
     severity: 3,
     properties: {
-      time: 1650210620171,
-      pid: 26510,
+      time: 1650210913512,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }
   applicationinsights trackException {
     exception: Error: intentionally crash
         at apiHandler (/Users/devinrhode2/repos/company-project/demo-app/.next/server/pages/api/throw.js:16:9)
         at Object.apiResolver (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/api-utils.js:102:15)
         at processTicksAndRejections (node:internal/process/task_queues:96:5)
         at async NextNodeServer.handleApiRequest (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:1076:9)
         at async Object.fn (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:963:37)
         at async Router.execute (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/router.js:222:32)
         at async NextNodeServer.run (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:1103:29)
         at async NextNodeServer.handleRequest (/Users/devinrhode2/repos/company-project/demo-app/node_modules/next/dist/server/base-server.js:319:20),
     severity: 3,
     properties: {
-      time: 1650210620171,
-      pid: 26510,
+      time: 1650210913512,
+      pid: 27059,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }

 DUPLICATE SERVER BOOT
+  [next-logger] defined global{This}.originalConsole.{debug,log,warn,error}
   called applicationinsights.start()
-  ERROR [1650210666062] (console/26762 on MacBook-Air): (node:26762) Warning: Using insecure HTTP parsing
+  [next-logger] patching next methods: wait, error, warn, ready, info, event, trace
+  [next-logger] patching console methods: error, warn, log, info, dirxml, table, trace
+  ERROR [1650210952657] (next-logger-patched-console/27101 on MacBook-Air): (node:27101) Warning: Using insecure HTTP parsing
   (Use `node --trace-warnings ...` to show where the warning was created)
   applicationinsights trackTrace {
-    message: '(node:26762) Warning: Using insecure HTTP parsing\n' +
+    message: '(node:27101) Warning: Using insecure HTTP parsing\n' +
       '(Use `node --trace-warnings ...` to show where the warning was created)',
     severity: 3,
     properties: {
-      time: 1650210666062,
-      pid: 26762,
+      time: 1650210952657,
+      pid: 27101,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }
   applicationinsights trackException {
-    exception: Error: (node:26762) Warning: Using insecure HTTP parsing
+    exception: Error: (node:27101) Warning: Using insecure HTTP parsing
     (Use `node --trace-warnings ...` to show where the warning was created)
         at insertException (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:85:12)
         at /Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:212:7
         at Array.forEach (<anonymous>)
         at insert (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:135:9)
         at Writable.writeStream._write (/Users/devinrhode2/repos/company-project/pino-applicationinsights/src/appinsights-client.js:234:7)
         at writeOrBuffer (node:internal/streams/writable:389:12)
         at _write (node:internal/streams/writable:330:10)
         at Writable.write (node:internal/streams/writable:334:10)
         at Transform.ondata (/Users/devinrhode2/repos/company-project/pino-applicationinsights/node_modules/readable-stream/lib/_stream_readable.js:681:20)
         at Transform.emit (node:events:526:28),
     severity: 3,
     properties: {
-      time: 1650210666062,
-      pid: 26762,
+      time: 1650210952657,
+      pid: 27101,
       hostname: 'MacBook-Air',
-      name: 'console'
+      name: 'next-logger-patched-console',
+      prefix: 'error'
     }
   }
-  ERROR [1650210666067] (console/26762 on MacBook-Air): listen EADDRINUSE: address already in use 0.0.0.0:3000
+  ERROR [1650210952662] (next-logger-patched-console/27101 on MacBook-Air): listen EADDRINUSE: address already in use 0.0.0.0:3000
       err: {
         "type": "Error",
         "message": "listen EADDRINUSE: address already in use 0.0.0.0:3000",
         "stack":
             Error: listen EADDRINUSE: address already in use 0.0.0.0:3000
                 at Server.setupListenHandle [as _listen2] (node:net:1330:16)
                 at listenInCluster (node:net:1378:12)
                 at doListen (node:net:1516:7)
                 at processTicksAndRejections (node:internal/process/task_queues:84:21)
         "code": "EADDRINUSE",
         "errno": -48,
         "syscall": "listen",
         "address": "0.0.0.0",
         "port": 3000
       }
   applicationinsights trackTrace {
     message: 'listen EADDRINUSE: address already in use 0.0.0.0:3000',
     severity: 3,
     properties: {
-      time: 1650210666067,
-      pid: 26762,
+      time: 1650210952662,
+      pid: 27101,
       hostname: 'MacBook-Air',
-      name: 'console',
+      name: 'next-logger-patched-console',
+      prefix: 'error',
       pinoAI_errData: {
         code: 'EADDRINUSE',
         errno: -48,
         syscall: 'listen',
         address: '0.0.0.0',
         port: 3000
       }
     }
   }
   applicationinsights trackException {
     exception: Error: listen EADDRINUSE: address already in use 0.0.0.0:3000
         at Server.setupListenHandle [as _listen2] (node:net:1330:16)
         at listenInCluster (node:net:1378:12)
         at doListen (node:net:1516:7)
         at processTicksAndRejections (node:internal/process/task_queues:84:21),
     severity: 3,
     properties: {
-      time: 1650210666067,
-      pid: 26762,
+      time: 1650210952662,
+      pid: 27101,
       hostname: 'MacBook-Air',
-      name: 'console',
+      name: 'next-logger-patched-console',
+      prefix: 'error',
       pinoAI_errData: {
         code: 'EADDRINUSE',
         errno: -48,
         syscall: 'listen',
         address: '0.0.0.0',
         port: 3000
       }
     }
   }
devinrhode2 commented 2 years ago

I think a pretty fundamental aspect to this re-write is creating this object:

/**
 * @type {Record<
 *   keyof typeof nextLogger.prefixes,
 *   keyof Omit<import('pino').BaseLogger, 'level'>
 * >}
 */
const nextLoggerToPinoLoggerMethodMap = {
  error: 'error',
  warn: 'warn',
  trace: 'trace',
  info: 'info',

  // rest:
  wait: 'info',
  ready: 'info',
  event: 'info',
}

We get a type-error if there's a new nextLogger method (trace) or if we type one incorrectly tracee, or if a method is removed one day.

I think it makes the code much more readable too, and it makes it easy to change this mapping.

However, we need to iterate over either nextLogger.prefixes or nextLoggerToPinoLoggerMethodMap, and do away with the switch statement.

I find it's often the case that js with ts added on after the fact is much different style of code that js/ts written with TS in mind from the beginning. Are you open to using something like nextLoggerToPinoLoggerMethodMap? Otherwise it probably just makes sense to leave my branch as a ts-based fork

devinrhode2 commented 2 years ago

I forgot you already did change to start using Object.keys(nextLogger.prefixes), so that's great :)

devinrhode2 commented 2 years ago

Added WIP to PR title as I don't think this should be merged as-is.

Should be broken into smaller PRs, each with passing tests....

Might not need to unpack args array up to 2 times only at all, or maybe we only need do this once.

I was really confused/lost until properly spread+type check pinoArgs

Also the issue with yarn link was really confusing

That said, if you don't strongly believe in unit tests but DO believe in a strongly typed approach, you'll likely want to use/contribute to this branch/fork

If you don't like typescript, you won't want to contribute to this fork

devinrhode2 commented 2 years ago

Was thinking of trying out graphite for this... what do you think @atkinchris ?

CleanShot 2022-05-19 at 00 36 21

devinrhode2 commented 2 years ago

erm..

Graphite is designed to be used at work - unfortunately we don't yet support submitting PRs to open-source repos as an external contributor (i.e. without write access) due to limitations of GitHub. https://www.npmjs.com/package/@withgraphite/graphite-cli https://graphite.dev/

devinrhode2 commented 2 years ago

maybe we could use graphite if you add me as a contributor/with write access? At this point I'm just interested in trying out graphite.dev :)

atkinchris commented 2 years ago

I'm concerned that connecting tools like Graphite to this repository would risk changes being published to a library that is used in production.

PRs can be stacked through GitHub's interface, by changing the base branch that the changes are applied to, while editing the PR.

atkinchris commented 6 months ago

You've done an enormous amount of work here; thank you for that. However, it makes significant changes in addition to adding TypeScript, as outlined in comments on this PR.

After nearly two years, we're not able to reconcile those changes, so I'm closing this to make it clear that this isn't a change users should expect to see merged in this state.