feat(auth): add logs to routes #2697

njlie · 2024-05-02T17:57:19Z

Changes proposed in this pull request

Adds logging to route handlers on the auth server
- Includes request method, path, and a unique request id in each log
- Includes a breakdown of the request body, params, and headers (that are applicable) in each log
- If applicable, any other relevant objects that were created/retrieved in the route business logic (e.g. a grant or an interaction)

Context

Closes #2577.

Checklist

netlify · 2024-05-02T17:57:35Z

✅ Deploy Preview for brilliant-pasca-3e80ec canceled.

Name	Link
🔨 Latest commit	`b7d2663`
🔍 Latest deploy log	https://app.netlify.com/sites/brilliant-pasca-3e80ec/deploys/664caf937930dc00089deddf

mkurapov

Should we create an openPaymentsServerErrorMiddleware like we do in backend to catch all of the GNAPErrors to have a single place for a standardized log for each error? (Since most of the logs are added right before the throw).

mkurapov · 2024-05-03T09:47:56Z

packages/auth/src/shared/utils.ts

+  requestBody: typeof ctx.request.body
+} {
+  return {
+    requestId: v4(),


This would show a different uuid for each log, right?
I was looking into a way to have a common request/traceId as a property on a child pino logger, but it is a bit difficult to do that with how we've set up dependency injection with adonis fold library. I'll take another attempt at addressing this in my upcoming changes.

I figured it would be workable for now as the routes log once per request, but I admit it's wishful thinking

mkurapov · 2024-05-03T09:48:58Z

packages/auth/src/accessToken/routes.ts

+  deps.logger.debug(
+    {
+      ...generateRouteLogs(ctx),
+      accessToken


should we be logging out tokens such as accessToken?

Probably not

Does it make any difference that its a debug log? I guess we can say these can but shouldnt be logged in production. Had the same thought about grant.continueToken elsewhere.

BlairCurrey · 2024-05-06T17:04:09Z

packages/auth/src/shared/utils.ts

+export function generateRouteLogs(ctx: AppContext): {
+  route: typeof ctx.path
+  method: typeof ctx.method
+  params: typeof ctx.params
+  headers: typeof ctx.headers
+  requestBody: typeof ctx.request.body
+} {
+  return {
+    method: ctx.method,
+    route: ctx.path,
+    headers: ctx.headers,
+    params: ctx.params,
+    requestBody: ctx.request.body
+  }
+}


I imagine there is probably some sensitive info in here somewhere.

for example from a POST continue/{{continueId}}:

requestBody.continue.access_token.value

requestBody.access_token.value

And is everything in headers OK to log or should any of it be redacted?

"headers": { "accept": "application/json", "content-type": "application/json", "content-digest": "sha-512=:wJHRy2GvqCYWZhLTIAdtBaDT9MRO69ldMWgdld0GO8cYVu8uop7pmilYh1xmlVDiiT8d2P1CSdyYgnbCsJIrNA==:", "content-length": "174", "signature": "sig1=:M5wb//IFQa43pZ6DfUrxcx7RCf3aQWXApk28TmhqgiUrzBbhlu0hs2/zVzXuiB7kEa1LZuq3taQT1XT5wuBDDg==:", "signature-input": "sig1=(\"@method\" \"@target-uri\" \"content-digest\" \"content-length\" \"content-type\");keyid=\"keyid-97a3a431-8ee1-48fc-ac85-70e2f5eba8e5\";created=1715013373", "user-agent": "axios/1.6.8", "accept-encoding": "gzip, compress, deflate, br", "host": "happy-life-bank-test-auth:4106", "connection": "keep-alive" },

If we need to configure pino to redact I imagine it might make sense to do it where we initialize the logger for some things, like the headers (if required).

This seems like a good pattern btw though. Also wondering if you think it would make sense to destructure this where we init the pino logger so we dont have to do ...generateRouteLogs(ctx) everywhere? Or if we dont want to always log context do a new loggerWithCtx or something?

mkurapov · 2024-05-08T10:27:21Z

What do you think about original PR review comment?

Should we create an openPaymentsServerErrorMiddleware like we do in backend to catch all of the GNAPErrors to have a single place for a standardized log for each error? (Since most of the logs are added right before the throw).

Might be nice to match the behaviour in backend

njlie · 2024-05-14T17:22:12Z

What do you think about original PR review comment?

Should we create an openPaymentsServerErrorMiddleware like we do in backend to catch all of the GNAPErrors to have a single place for a standardized log for each error? (Since most of the logs are added right before the throw).

Might be nice to match the behaviour in backend

I think it's possible to have this PR also match that pattern. It'll be slightly different since it's supposed to also return GNAP error codes, but will be mostly similar.

mkurapov

Looks good, just a few minor comments

mkurapov · 2024-05-15T09:17:45Z

packages/auth/src/signature/middleware.ts

      'invalid access token'
    )
  }

  if (!accessToken.grant) {
-    const logger = await ctx.container.use('logger')
-    logger.error(
-      `access token with management id ${ctx.params['id']} has no grant associated with it.`
-    )


is this log worth keeping still?

Probably...in hindsight that's a pretty severe case that shouldn't happen - we should know about if it does for some reason

mkurapov · 2024-05-15T09:25:21Z

packages/auth/src/logger/service.ts

@@ -3,7 +3,14 @@ import createLogger, { Logger as PinoLogger } from 'pino'
 import { Config } from '../config/app'

 function initLogger(): PinoLogger {
-  const logger = createLogger()
+  const logger = createLogger({


do we need to use this when instantiating the logger singleton in index.ts?

mkurapov · 2024-05-15T09:32:34Z

packages/auth/src/shared/gnapErrors.ts

+  }
+}
+
+export async function gnapServerErrorMiddleware(


We should also check for OpenAPIValidatorMiddlewareError here as well, similar to backend, so we get a nicely formatted error when getting validation errors as well. This means we need to update @interledger/openapi to 2.0.1

mkurapov

just one comment

mkurapov · 2024-05-16T08:42:45Z

packages/auth/src/shared/gnapErrors.test.ts

+    ctx.container = deps
+  })
+
+  test('handles GNAPServerRouteError error', async (): Promise<void> => {


we should add a test for the validator middleware error

…middleware

njlie requested review from BlairCurrey, mkurapov and sabineschaller May 2, 2024 17:57

github-actions bot added type: source Changes business logic pkg: auth Changes in the GNAP auth package. labels May 2, 2024

mkurapov reviewed May 3, 2024

View reviewed changes

BlairCurrey reviewed May 6, 2024

View reviewed changes

github-actions bot added the type: tests Testing related label May 14, 2024

mkurapov reviewed May 15, 2024

View reviewed changes

njlie force-pushed the nl/2577/auth-routes-logs branch from 85a7724 to 82c7135 Compare May 15, 2024 18:05

njlie requested review from BlairCurrey and mkurapov May 16, 2024 21:45

BlairCurrey previously approved these changes May 20, 2024

View reviewed changes

mkurapov reviewed May 21, 2024

View reviewed changes

njlie dismissed BlairCurrey’s stale review via c7af5bf May 21, 2024 14:23

njlie requested review from mkurapov and BlairCurrey May 21, 2024 14:24

njlie added 8 commits May 21, 2024 07:28

feat(auth): add logs to routes

40244cb

fix: improve access token log a little bit

fcd8467

fix: remove requestId

afff13c

fix: remove access token from logs, and some redundant fields

9a5958d

fix: logger redactions

ee3b529

feat: log gnap route errors with middleware

7e3f6c4

feat: update interledger/openapi, handle openapi validator errors in …

c67c3b5

…middleware

feat: test openapi validation error

b7d2663

njlie force-pushed the nl/2577/auth-routes-logs branch from c7af5bf to b7d2663 Compare May 21, 2024 14:28

mkurapov approved these changes May 21, 2024

View reviewed changes

njlie merged commit 8aaf505 into main May 21, 2024
42 checks passed

njlie deleted the nl/2577/auth-routes-logs branch May 21, 2024 16:38

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(auth): add logs to routes #2697

feat(auth): add logs to routes #2697

njlie commented May 2, 2024 •

edited

netlify bot commented May 2, 2024 •

edited

mkurapov left a comment

mkurapov May 3, 2024

njlie May 3, 2024

mkurapov May 3, 2024

njlie May 6, 2024

BlairCurrey May 6, 2024

BlairCurrey May 6, 2024 •

edited

BlairCurrey May 6, 2024 •

edited

mkurapov commented May 8, 2024

njlie commented May 14, 2024

mkurapov left a comment

mkurapov May 15, 2024

njlie May 15, 2024

mkurapov May 15, 2024

mkurapov May 15, 2024

mkurapov left a comment

mkurapov May 16, 2024

feat(auth): add logs to routes #2697

feat(auth): add logs to routes #2697

Conversation

njlie commented May 2, 2024 • edited

Changes proposed in this pull request

Context

Checklist

netlify bot commented May 2, 2024 • edited

✅ Deploy Preview for brilliant-pasca-3e80ec canceled.

mkurapov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BlairCurrey May 6, 2024 • edited

Choose a reason for hiding this comment

BlairCurrey May 6, 2024 • edited

Choose a reason for hiding this comment

mkurapov commented May 8, 2024

njlie commented May 14, 2024

mkurapov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mkurapov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

njlie commented May 2, 2024 •

edited

netlify bot commented May 2, 2024 •

edited

BlairCurrey May 6, 2024 •

edited

BlairCurrey May 6, 2024 •

edited