Logging Refactor

backend/config/registry.conf

@@ -26,9 +26,4 @@ http:
   addr: :5000
   relativeurls: true
   headers:
-    X-Content-Type-Options: [nosniff]
-health:
-  storagedriver:
-    enabled: true
-    interval: 10s
-    threshold: 3
+    X-Content-Type-Options: [nosniff]

backend/package.json

@@ -55,6 +55,7 @@
     "nanoid": "^5.0.6",
     "node-fetch": "^3.3.2",
     "nodemailer": "^6.9.13",
+    "pretty-bytes": "^6.1.1",
     "qs": "^6.12.1",
     "semver": "^7.6.0",
     "shelljs": "^0.8.5",

backend/src/clients/s3.ts

@@ -11,6 +11,7 @@ import {
 } from '@aws-sdk/client-s3'
 import { Upload } from '@aws-sdk/lib-storage'
 import { NodeHttpHandler } from '@smithy/node-http-handler'
+import prettyBytes from 'pretty-bytes'
 import { PassThrough, Readable } from 'stream'
 
 import { getHttpsAgent } from '../services/http.js'
@@ -45,14 +46,21 @@ export async function putObjectStream(
 
   let fileSize = 0
   upload.on('httpUploadProgress', (progress) => {
-    log.debug('Object upload is in progress', progress)
+    log.debug(
+      {
+        ...progress,
+        ...(progress.loaded && { loaded: prettyBytes(progress.loaded) }),
+        ...(progress.total && { total: prettyBytes(progress.total) }),
+      },
+      'Object upload is in progress',
+    )
     if (progress.loaded) {
       fileSize = progress.loaded
     }
   })
 
   const s3Response = await upload.done()
-  log.debug('Object upload complete', s3Response)
+  log.debug(s3Response, 'Object upload complete')
 
   return {
     fileSize,

backend/src/connectors/audit/Base.ts

@@ -36,6 +36,7 @@ export const AuditInfo = {
   UpdateModelCard: { typeId: 'UpdateModelCard', description: 'Model Card Updated', auditKind: AuditKind.Update },
 
   CreateFile: { typeId: 'CreateFile', description: 'File Information Created', auditKind: AuditKind.Create },
+  ViewFile: { typeId: 'ViewFile', description: 'File Downloaded', auditKind: AuditKind.View },
   ViewFiles: { typeId: 'ViewFiles', description: 'File Information Viewed', auditKind: AuditKind.View },
   DeleteFile: { typeId: 'DeleteFile', description: 'File Information Deleted', auditKind: AuditKind.Delete },
 
@@ -111,6 +112,7 @@ export abstract class BaseAuditConnector {
   abstract onViewModelCardRevisions(req: Request, modelId: string, modelCards: ModelCardInterface[])
 
   abstract onCreateFile(req: Request, file: FileInterfaceDoc)
+  abstract onViewFile(req: Request, file: FileInterfaceDoc)
   abstract onViewFiles(req: Request, modelId: string, files: FileInterface[])
   abstract onDeleteFile(req: Request, modelId: string, fileId: string)
 

backend/src/connectors/audit/silly.ts

@@ -27,6 +27,7 @@ export class SillyAuditConnector extends BaseAuditConnector {
   onUpdateModelCard(_req: Request, _modelId: string, _modelCard: ModelCardInterface) {}
   onViewModelCardRevisions(_req: Request, _modelId: string, _modelCards: ModelCardInterface[]) {}
   onCreateFile(_req: Request, _file: FileInterfaceDoc) {}
+  onViewFile(_req: Request, _file: FileInterfaceDoc) {}
   onViewFiles(_req: Request, _modelId: string, _files: FileInterface[]) {}
   onDeleteFile(_req: Request, _modelId: string, _fileId: string) {}
   onCreateRelease(_req: Request, _release: ReleaseDoc) {}

backend/src/connectors/audit/stdout.ts

@@ -81,9 +81,15 @@ export class StdoutAuditConnector extends BaseAuditConnector {
     req.log.info(event, req.audit.description)
   }
 
+  onViewFile(req: Request, file: FileInterfaceDoc) {
+    this.checkEventType(AuditInfo.ViewFile, req)
+    const event = this.generateEvent(req, { id: file._id.toString(), modelId: file.modelId })
+    req.log.info(event, req.audit.description)
+  }
+
   onViewFiles(req: Request, modelId: string, files: FileInterface[]) {
     this.checkEventType(AuditInfo.ViewFiles, req)
-    const event = this.generateEvent(req, { modelId, results: files.map((file) => file.name) })
+    const event = this.generateEvent(req, { modelId, results: files.map((file) => file._id) })
     req.log.info(event, req.audit.description)
   }
 

backend/src/index.ts

@@ -37,5 +37,6 @@ const { server } = await import('./routes.js')
 const httpServer = server.listen(config.api.port, () => {
   log.info('Listening on port', config.api.port)
 })
+httpServer.headersTimeout = 1200000
 
 registerSigTerminate(httpServer)

backend/src/models/File.ts

@@ -1,10 +1,11 @@
-import { Document, model, Schema } from 'mongoose'
+import { Document, model, ObjectId, Schema } from 'mongoose'
 import MongooseDelete from 'mongoose-delete'
 
 // This interface stores information about the properties on the base object.
 // It should be used for plain object representations, e.g. for sending to the
 // client.
 export interface FileInterface {
+  _id: ObjectId
   modelId: string
 
   name: string

backend/src/routes/middleware/defaultAuthentication.ts

@@ -27,8 +27,11 @@ export function checkAuthentication(req, res, next) {
   if (!req.user) {
     throw Unauthorized('No valid authentication provided.')
   }
-  req.log.debug('User successfully authorized.', {
-    user: req.user,
-  })
+  req.log.debug(
+    {
+      user: req.user,
+    },
+    'User successfully authorized.',
+  )
   return next()
 }

backend/src/routes/v2/model/file/getDownloadFile.ts

@@ -4,6 +4,8 @@ import { Request, Response } from 'express'
 import stream from 'stream'
 import { z } from 'zod'
 
+import { AuditInfo } from '../../../../connectors/audit/Base.js'
+import audit from '../../../../connectors/audit/index.js'
 import { FileInterface, FileInterfaceDoc } from '../../../../models/File.js'
 import { TokenActions } from '../../../../models/Token.js'
 import { downloadFile, getFileById } from '../../../../services/file.js'
@@ -90,6 +92,7 @@ interface GetDownloadFileResponse {
 export const getDownloadFile = [
   bodyParser.json(),
   async (req: Request, res: Response<GetDownloadFileResponse>) => {
+    req.audit = AuditInfo.ViewFile
     const { params } = parse(req, getDownloadFileSchema)
     let file: FileInterfaceDoc
     if ('semver' in params) {
@@ -117,6 +120,8 @@ export const getDownloadFile = [
       throw InternalError('We were not able to retrieve the body of this file', { fileId: file._id })
     }
 
+    await audit.onViewFile(req, file)
+
     // required to support utf-8 file names
     res.set('Content-Disposition', contentDisposition(file.name, { type: 'attachment' }))
     res.set('Content-Type', file.mime)

backend/src/services/accessRequest.ts

@@ -59,7 +59,7 @@ export async function createAccessRequest(
     await createAccessRequestReviews(model, accessRequest)
   } catch (error) {
     // Transactions here would solve this issue.
-    log.warn('Error when creating Release Review Requests. Approval cannot be given to this Access Request', error)
+    log.warn(error, 'Error when creating Release Review Requests. Approval cannot be given to this Access Request')
   }
 
   sendWebhooks(

backend/src/services/file.ts

@@ -46,29 +46,29 @@ export async function uploadFile(
       try {
         av = await new NodeClam().init({ clamdscan: config.avScanning.clamdscan })
       } catch (error) {
-        log.error('Unable to connect to ClamAV.', error)
+        log.error(error, 'Unable to connect to ClamAV.')
         return file
       }
     }
     const avStream = av.passthrough()
     const s3Stream = (await getObjectStream(file.bucket, file.path)).Body as Readable
     s3Stream.pipe(avStream)
-    log.info('Scan started.', { modelId, fileId: file._id, name })
+    log.info({ modelId, fileId: file._id, name }, 'Scan started.')
 
     avStream.on('scan-complete', async (result) => {
-      log.info('Scan complete.', { result, modelId, fileId: file._id, name })
+      log.info({ result, modelId, fileId: file._id, name }, 'Scan complete.')
       await file.update({
         avScan: { state: ScanState.Complete, isInfected: result.isInfected, viruses: result.viruses },
       })
     })
     avStream.on('error', async (error) => {
-      log.error('Scan errored.', { error, modelId, fileId: file._id, name })
+      log.error({ error, modelId, fileId: file._id, name }, 'Scan errored.')
       await file.update({
         avScan: { state: ScanState.Error },
       })
     })
     avStream.on('timeout', async (error) => {
-      log.error('Scan timed out.', { error, modelId, fileId: file._id, name })
+      log.error({ error, modelId, fileId: file._id, name }, 'Scan timed out.')
       await file.update({
         avScan: { state: ScanState.Error },
       })