Merge pull request #1394 from gchq/bug/better-logging

Improve developer logging of requests
gchq · Oct 30, 2024 · a48ba87 · a48ba87
2 parents 8307deb + 0cbe95d
commit a48ba87
Show file tree

Hide file tree

Showing 6 changed files with 39 additions and 11 deletions.
diff --git a/backend/src/routes/middleware/defaultAuthentication.ts b/backend/src/routes/middleware/defaultAuthentication.ts
@@ -22,7 +22,7 @@ export function checkAuthentication(req, res, next) {
   if (!req.user) {
     throw Unauthorized('No valid authentication provided.')
   }
-  req.log.debug(
+  req.log.trace(
     {
       user: req.user,
     },

diff --git a/backend/src/routes/middleware/expressLogger.ts b/backend/src/routes/middleware/expressLogger.ts
@@ -17,7 +17,7 @@ const morganLog = promisify(
         requestId: req.reqId,
         ...(tokens.res(req, res, 'content-length') && { 'content-length': tokens.res(req, res, 'content-length') }),
       }
-      req.log.trace(info, `Request completed.`)
+      req.log.debug(info, 'Request completed')
 
       return ''
     },

diff --git a/backend/src/services/log.ts b/backend/src/services/log.ts
@@ -15,6 +15,14 @@ interface BunyanLog {
   src: { file: string; line: number }
   msg: string
 }
+
+interface RequestCompletedLog extends BunyanLog {
+  method: string
+  url: string
+  status: number
+  'response-time': number
+}
+
 export function isBunyanLogGuard(data: unknown): data is BunyanLog {
   if (typeof data !== 'object' || data === null) {
     return false
@@ -63,7 +71,7 @@ export class Writer extends WritableStream {
   }
 
   getSrc(src: { file: string; line: any }) {
-    const line = src.file.replace(this.basepath, '')
+    const line = src.file.replace(this.basepath, '').replace('file://', '')
 
     if (line.startsWith('routes/middleware/expressLogger.ts')) {
       return 'express'
@@ -76,6 +84,19 @@ export class Writer extends WritableStream {
     return typeof value === 'object' ? util.inspect(value) : String(value)
   }
 
+  static isRequestCompleted(data: unknown): data is RequestCompletedLog {
+    if (typeof data !== 'object' || data === null) {
+      return false
+    }
+
+    if (!('msg' in data) || typeof data.msg !== 'string') {
+      return false
+    }
+
+    const keys = Object.keys(data)
+    return ['requestId', 'url', 'method'].every((k) => keys.includes(k)) && data.msg === 'Request completed'
+  }
+
   static getAttributes(data: any) {
     let attributes = omit(data, [
       'name',
@@ -92,9 +113,9 @@ export class Writer extends WritableStream {
     ])
     let keys = Object.keys(attributes)
 
-    if (['id', 'url', 'method', 'response-time', 'status'].every((k) => keys.includes(k))) {
+    if (Writer.isRequestCompleted(data)) {
       // this is probably a req object.
-      attributes = omit(attributes, ['id', 'url', 'method', 'response-time', 'status'])
+      attributes = omit(attributes, ['requestId', 'agent'])
       keys = Object.keys(attributes)
     }
 
@@ -121,9 +142,14 @@ export class Writer extends WritableStream {
     const level = Writer.getLevel(data.level)
     const src = data.src ? this.getSrc(data.src) : undefined
     const attributes = Writer.getAttributes(data)
-    const formattedAttributes = attributes.length ? ` (${attributes})` : ''
+    const formattedAttributes = attributes.length ? `${data.msg ? ' ' : ''}(${attributes})` : ''
 
-    const message = `${level} - (${src}): ${data.msg}${formattedAttributes}`
+    let message
+    if (Writer.isRequestCompleted(data)) {
+      message = `${level} - ${data.status} ${data.method} ${data.url} ${data['response-time']}ms`
+    } else {
+      message = `${level} - (${src}): ${data.msg}${formattedAttributes}`
+    }
 
     const pipe = data.level >= 40 ? 'stderr' : 'stdout'
     process[pipe].write(`${message}\n`)
@@ -145,7 +171,7 @@ if (process.env.NODE_ENV !== 'production') {
   const currentDirectory = getDirectory(import.meta.url)
 
   streams.push({
-    level: 'trace',
+    level: config.log.level,
     type: 'raw',
     stream: new Writer({
       basepath: join(currentDirectory, '..', '..'),

diff --git a/backend/test/routes/middleware/defaultAuthentication.spec.ts b/backend/test/routes/middleware/defaultAuthentication.spec.ts
@@ -40,7 +40,7 @@ describe('middleware > defaultAuthentication', () => {
     const request = {
       user: 'test',
       log: {
-        debug: vi.fn(),
+        trace: vi.fn(),
       },
     } as Request
     const next = vi.fn()

diff --git a/backend/test/services/log.spec.ts b/backend/test/services/log.spec.ts
@@ -62,7 +62,9 @@ describe('services > log', () => {
   test('Writer > getAttributes', () => {
     expect(Writer.getAttributes({ name: 'ignore', user: 'ignore' })).toBe('')
     expect(Writer.getAttributes({ name: 'ignore', user: 'ignore', example: 'hello' })).toBe('example=hello')
-    expect(Writer.getAttributes({ id: true, url: true, method: true, 'response-time': true, status: true })).toBe('')
+    expect(Writer.getAttributes({ id: true, url: true, method: true, 'response-time': true, status: true })).toBe(
+      'id=true url=true method=true response-time=true status=true',
+    )
     expect(Writer.getAttributes({ id: longId() })).toBe('')
   })
 

diff --git a/lib/python/README.md b/lib/python/README.md
@@ -55,7 +55,7 @@ yolo = Model.create(
     team_id="Uncategorised"
 )
 
-yolo.card_from_schema("minimal-general-v10-beta")
+yolo.card_from_schema("minimal-general-v10")
 
 # Create a new release
 my_release = yolo.create_release(version="0.1.0",