Feature/51974 ps report logging (#2162)

* start building out components * build out message generator * implement log generator * implement writer * use existing blob service and enhance it * renames * create orchestrator * fixes after testing * add cleanup for queue messages * implement log levels * log levels as string union instead of enum * implement into list schools function * working version * inject ps report logger into all ps functions * changes needed to write in batches and append due to volume constraints * working version with blob append * opt for receive and delete mode due to performance considerations * remove comment * rename method * set schedule * docs * info Co-authored-by: Mohsen Qureshi <[email protected]>
DFEAGILEDEVOPS · Apr 6, 2022 · 4e5de6d · 4e5de6d
1 parent c15ce57
commit 4e5de6d
Show file tree

Hide file tree

Showing 38 changed files with 758 additions and 42 deletions.
diff --git a/deploy/service-bus/deploy.config.js b/deploy/service-bus/deploy.config.js
@@ -91,6 +91,10 @@ const config = {
     {
       name: 'sync-results-to-db-complete',
       maxSizeInMegabytes: {}.hasOwnProperty.call(process.env, 'SERVICE_BUS_QUEUE_MAX_SIZE_MEGABYTES_SYNC_RESULTS_COMPLETE') ? parseInt(process.env.SERVICE_BUS_QUEUE_MAX_SIZE_MEGABYTES_SYNC_RESULTS_COMPLETE, 10) : twentyGigabytes
+    },
+    {
+      name: 'ps-report-log',
+      maxSizeInMegabytes: {}.hasOwnProperty.call(process.env, 'SERVICE_BUS_QUEUE_MAX_SIZE_MEGABYTES_PS_REPORT_LOG') ? parseInt(process.env.SERVICE_BUS_QUEUE_MAX_SIZE_MEGABYTES_PS_REPORT_LOG, 10) : twentyGigabytes
     }
   ]
 }

diff --git a/docs/support-utils/util-gen-ps-report-logs.md b/docs/support-utils/util-gen-ps-report-logs.md
@@ -0,0 +1,13 @@
+# util-gen-ps-report-logs
+
+generates fake log messages onto the `ps-report-log` service bus queue for the purpose of testing the log writer function (ps-report-log-writer).
+
+You can override the default message count by providing the following request body in `JSON`...
+
+```
+{
+  messageCount: 100000
+}
+```
+
+Execute a `HTTP GET` at http://localhost:7071/api/util-gen-ps-report-logs to invoke the util function.
diff --git a/func-consumption/util-gen-ps-report-logs/function.json b/func-consumption/util-gen-ps-report-logs/function.json
@@ -0,0 +1,21 @@
+{
+  "bindings": [
+    {
+      "authLevel": "function",
+      "type": "httpTrigger",
+      "direction": "in",
+      "name": "req",
+      "methods": [
+        "get"
+      ]
+    },
+    {
+      "direction": "out",
+      "type": "serviceBus",
+      "name": "psReportLogQueue",
+      "queueName": "ps-report-log",
+      "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
+    }
+  ],
+  "scriptFile": "../dist/functions/util-gen-ps-report-logs/index.js"
+}
diff --git a/func-ps-report/ps-report-1-list-schools/function.json b/func-ps-report/ps-report-1-list-schools/function.json
@@ -16,6 +16,13 @@
       "name": "schoolMessages",
       "queueName": "ps-report-schools",
       "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
+    },
+    {
+      "direction": "out",
+      "type": "serviceBus",
+      "name": "logs",
+      "queueName": "ps-report-log",
+      "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
     }
   ],
   "scriptFile": "../dist/functions-ps-report/ps-report-1-list-schools/index.js"

diff --git a/func-ps-report/ps-report-2-pupil-data/function.json b/func-ps-report/ps-report-2-pupil-data/function.json
@@ -13,6 +13,13 @@
       "direction": "out",
       "queueName": "ps-report-staging",
       "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
+    },
+    {
+      "direction": "out",
+      "type": "serviceBus",
+      "name": "logs",
+      "queueName": "ps-report-log",
+      "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
     }
   ],
   "scriptFile": "../dist/functions-ps-report/ps-report-2-pupil-data/index.js"

diff --git a/func-ps-report/ps-report-3-transformer/function.json b/func-ps-report/ps-report-3-transformer/function.json
@@ -13,6 +13,13 @@
       "name": "outputData",
       "queueName": "ps-report-export",
       "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
+    },
+    {
+      "direction": "out",
+      "type": "serviceBus",
+      "name": "logs",
+      "queueName": "ps-report-log",
+      "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
     }
   ],
   "scriptFile": "../dist/functions-ps-report/ps-report-3-transformer/index.js"

diff --git a/func-ps-report/ps-report-4-writer/function.json b/func-ps-report/ps-report-4-writer/function.json
@@ -6,6 +6,13 @@
       "direction": "in",
       "queueName": "ps-report-export",
       "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
+    },
+    {
+      "direction": "out",
+      "type": "serviceBus",
+      "name": "logs",
+      "queueName": "ps-report-log",
+      "connection": "AZURE_SERVICE_BUS_CONNECTION_STRING"
     }
   ],
   "scriptFile": "../dist/functions-ps-report/ps-report-4-writer/index.js"

diff --git a/func-ps-report/ps-report-5-log-writer/function.json b/func-ps-report/ps-report-5-log-writer/function.json
@@ -0,0 +1,15 @@
+{
+  "bindings": [
+    {
+      "name": "psReport5LogWriter",
+      "type": "timerTrigger",
+      "direction": "in",
+      "timerDescription": "{second} {minute} {hour} {day} {month} {day-of-week}",
+      "dev-schedule": "0 */5 * * * *",
+      "prod-schedule": "0 0 7 * * 3",
+      "prod-description": "Every Wednesday at 7am",
+      "schedule": "0 0 7 * * 3"
+    }
+  ],
+  "scriptFile": "../dist/functions-ps-report/ps-report-5-log-writer/index.js"
+}
diff --git a/tslib/src/azure/blob-service.ts b/tslib/src/azure/blob-service.ts
@@ -3,9 +3,27 @@ import config from '../config'
 
 export interface IBlobService {
   deleteBlob (blobName: string, containerName: string): Promise<void>
+  createBlob (data: Buffer, blobName: string, containerName: string): Promise<void>
+  appendBlob (data: Buffer, blobName: string, containerName: string): Promise<void>
 }
 
 export class BlobService implements IBlobService {
+  async appendBlob (data: Buffer, blobName: string, containerName: string): Promise<void> {
+    const client = await this.getContainerClient(containerName)
+    await client.createIfNotExists()
+    const blobClient = client.getAppendBlobClient(blobName)
+    await blobClient.createIfNotExists()
+    await blobClient.appendBlock(data, data.length)
+  }
+
+  async createBlob (data: Buffer, blobName: string, containerName: string): Promise<void> {
+    const client = await this.getContainerClient(containerName)
+    await client.createIfNotExists()
+    const blobClient = client.getBlobClient(blobName)
+    const blockClient = await blobClient.getBlockBlobClient()
+    await blockClient.uploadData(data)
+  }
+
   private async getContainerClient (containerName: string): Promise<ContainerClient> {
     const bsc = BlobServiceClient.fromConnectionString(config.AzureStorage.ConnectionString)
     return bsc.getContainerClient(containerName)

diff --git a/tslib/src/common/ContextLike.ts b/tslib/src/common/ContextLike.ts
@@ -0,0 +1,17 @@
+import { ILogger } from './logger'
+
+/**
+ * @description same signature as Azure Function ContextBindings
+ */
+export interface IContextBindingsLike {
+  [name: string]: any
+}
+
+/**
+ * @description Azure Function Context Like object that supports members required
+ * by the Ps Report Logger
+ */
+export interface IContextLike {
+  bindings: IContextBindingsLike
+  log: ILogger
+}
diff --git a/tslib/src/config.ts b/tslib/src/config.ts
@@ -135,5 +135,8 @@ export default {
   SyncResultsInit: {
     MaxParallelTasks: parseInt(parser.valueOrSubstitute(process.env.SYNC_RESULTS_INIT_MAX_PARALLEL_TASKS, 5), 10)
   },
-  LiveFormQuestionCount: getLinesPerCheck()
+  LiveFormQuestionCount: getLinesPerCheck(),
+  PsReportLogWriter: {
+    MessagesPerBatch: parseInt(parser.valueOrSubstitute(process.env.PS_REPORT_LOG_WRITER_MESSAGE_BATCH_SIZE, 100), 10)
+  }
 }
diff --git a/tslib/src/functions-ps-report/common/ps-report-log-entry.ts b/tslib/src/functions-ps-report/common/ps-report-log-entry.ts
@@ -0,0 +1,17 @@
+import moment from 'moment'
+
+export interface IPsReportLogEntry {
+  message: string
+  level: PsReportLogLevel
+  source: PsReportSource
+  generatedAt: moment.Moment
+}
+
+export enum PsReportSource {
+  SchoolGenerator = 'ps-report-1-list-schools',
+  PupilGenerator = 'ps-report-2-pupil-data',
+  Transformer = 'ps-report-3-transformer',
+  Writer = 'ps-report-4-writer'
+}
+
+export type PsReportLogLevel = 'info' | 'warning' | 'verbose' | 'error'
diff --git a/tslib/src/functions-ps-report/common/ps-report-logger.ts b/tslib/src/functions-ps-report/common/ps-report-logger.ts
@@ -0,0 +1,51 @@
+import moment from 'moment'
+import { IContextLike } from '../../common/ContextLike'
+import { ILogger } from '../../common/logger'
+import { PsLogEntryFormatter } from '../ps-report-5-log-writer/log-entry-formatter'
+import { IPsReportLogEntry, PsReportLogLevel, PsReportSource } from './ps-report-log-entry'
+
+const formatter = new PsLogEntryFormatter()
+
+export class PsReportLogger implements ILogger {
+  private readonly context: IContextLike
+  private readonly source: PsReportSource
+
+  constructor (context: IContextLike, sourceFunction: PsReportSource) {
+    this.context = context
+    this.source = sourceFunction
+  }
+
+  private log (message: string, level: PsReportLogLevel): string {
+    const entry: IPsReportLogEntry = {
+      generatedAt: moment(),
+      message: message,
+      source: this.source,
+      level: level
+    }
+    if (this.context.bindings.logs === undefined) {
+      this.context.bindings.logs = []
+    }
+    this.context.bindings.logs.push(entry)
+    return formatter.formatEntry(entry)
+  }
+
+  info (message: string): void {
+    const formatted = this.log(message, 'info')
+    this.context.log.info(formatted)
+  }
+
+  verbose (message: string): void {
+    const formatted = this.log(message, 'verbose')
+    this.context.log.verbose(formatted)
+  }
+
+  warn (message: string): void {
+    const formatted = this.log(message, 'warning')
+    this.context.log.warn(formatted)
+  }
+
+  error (message: string): void {
+    const formatted = this.log(message, 'error')
+    this.context.log.error(formatted)
+  }
+}
diff --git a/tslib/src/functions-ps-report/ps-report-1-list-schools/index.ts b/tslib/src/functions-ps-report/ps-report-1-list-schools/index.ts
@@ -2,6 +2,8 @@ import { AzureFunction, Context } from '@azure/functions'
 import { performance } from 'perf_hooks'
 import { ListSchoolsService } from './list-schools-service'
 import { IFunctionTimer } from '../../azure/functions'
+import { PsReportLogger } from '../common/ps-report-logger'
+import { PsReportSource } from '../common/ps-report-log-entry'
 
 const functionName = 'ps-report-1-list-schools'
 
@@ -11,21 +13,21 @@ const timerTrigger: AzureFunction = async function (context: Context, timer: IFu
     context.log(`${functionName}: timer is past due, exiting.`)
     return
   }
+  const logger = new PsReportLogger(context, PsReportSource.SchoolGenerator)
   const start = performance.now()
   const meta = { processCount: 0, errorCount: 0 }
   try {
-    const schoolListService = new ListSchoolsService(context.log)
+    const schoolListService = new ListSchoolsService(logger)
     const messages = await schoolListService.getSchoolMessages()
     context.bindings.schoolMessages = messages
     meta.processCount = messages.length
   } catch (error) {
-    context.log.error(`${functionName}: ERROR: ${error.message}`)
+    logger.error(error.message)
     throw error
   }
   const end = performance.now()
   const durationInMilliseconds = end - start
-  const timeStamp = new Date().toISOString()
-  context.log(`${functionName}: ${timeStamp} processed ${meta.processCount} records, run took ${durationInMilliseconds} ms`)
+  logger.info(`processed ${meta.processCount} records, run took ${durationInMilliseconds} ms`)
 }
 
 export default timerTrigger
diff --git a/tslib/src/functions-ps-report/ps-report-1-list-schools/list-schools-service.spec.ts b/tslib/src/functions-ps-report/ps-report-1-list-schools/list-schools-service.spec.ts
@@ -1,6 +1,6 @@
 import { ListSchoolsService } from './list-schools-service'
-import { MockLogger, ILogger } from '../../common/logger'
 import { ISqlService } from '../../sql/sql.service'
+import { ILogger, MockLogger } from '../../common/logger'
 
 describe('ListSchoolsService', () => {
   let sut: ListSchoolsService

diff --git a/tslib/src/functions-ps-report/ps-report-1-list-schools/list-schools-service.ts b/tslib/src/functions-ps-report/ps-report-1-list-schools/list-schools-service.ts
@@ -1,8 +1,6 @@
-import { ConsoleLogger, ILogger } from '../../common/logger'
+import { ILogger } from '../../common/logger'
 import { ISqlService, SqlService } from '../../sql/sql.service'
 
-const functionName = 'ps-report-1-list-schools'
-
 export interface School {
   id: number
   uuid: string
@@ -22,8 +20,8 @@ export class ListSchoolsService implements IListSchoolsService {
   private readonly logger: ILogger
   private readonly sqlService: ISqlService
 
-  constructor (logger?: ILogger, sqlService?: ISqlService) {
-    this.logger = logger ?? new ConsoleLogger()
+  constructor (logger: ILogger, sqlService?: ISqlService) {
+    this.logger = logger
     this.sqlService = sqlService ?? new SqlService()
   }
 
@@ -33,15 +31,15 @@ export class ListSchoolsService implements IListSchoolsService {
   }
 
   public async getSchoolMessages (): Promise<SchoolMessage[]> {
-    this.logger.verbose(`${functionName}: ListSchoolsService called - retrieving all schools`)
+    this.logger.verbose('ListSchoolsService called - retrieving all schools')
     const schools = await this.getSchools()
     const schoolMessages: SchoolMessage[] = schools.map(school => {
       return {
         uuid: school.uuid,
         name: school.name
       }
     })
-    this.logger.info(`${functionName}: getSchoolMessages() retrieved ${schoolMessages.length} schools`)
+    this.logger.info(`getSchoolMessages() retrieved ${schoolMessages.length} schools`)
     return schoolMessages
   }
 }
diff --git a/tslib/src/functions-ps-report/ps-report-2-pupil-data/index.ts b/tslib/src/functions-ps-report/ps-report-2-pupil-data/index.ts
@@ -2,8 +2,8 @@ import { AzureFunction, Context } from '@azure/functions'
 import { performance } from 'perf_hooks'
 import { PsReportService } from './ps-report.service'
 import { PupilResult } from './models'
-
-const functionName = 'ps-report-2-pupil-data'
+import { PsReportLogger } from '../common/ps-report-logger'
+import { PsReportSource } from '../common/ps-report-log-entry'
 
 /**
  * Incoming message is just the name and UUID of the school to process
@@ -17,15 +17,15 @@ interface IncomingMessage {
 
 const serviceBusQueueTrigger: AzureFunction = async function (context: Context, incomingMessage: IncomingMessage): Promise<void> {
   const start = performance.now()
-  context.log.verbose(`${functionName}: called for school ${incomingMessage.name}`)
+  const logger = new PsReportLogger(context, PsReportSource.PupilGenerator)
+  logger.verbose(`called for school ${incomingMessage.name}`)
   const outputBinding: PupilResult[] = []
   context.bindings.psReportPupilMessage = outputBinding
-  const psReportService = new PsReportService(outputBinding, context.log)
+  const psReportService = new PsReportService(outputBinding, logger)
   await psReportService.process(incomingMessage.uuid)
   const end = performance.now()
   const durationInMilliseconds = end - start
-  const timeStamp = new Date().toISOString()
-  context.log.info(`${functionName}: ${timeStamp} processed ${outputBinding.length} pupils, run took ${durationInMilliseconds} ms`)
+  logger.info(`processed ${outputBinding.length} pupils, run took ${durationInMilliseconds} ms`)
 }
 
 export default serviceBusQueueTrigger
diff --git a/tslib/src/functions-ps-report/ps-report-2-pupil-data/ps-report.data.service.ts b/tslib/src/functions-ps-report/ps-report-2-pupil-data/ps-report.data.service.ts
@@ -1,5 +1,4 @@
 import { ISqlService, SqlService } from '../../sql/sql.service'
-import { ConsoleLogger, ILogger } from '../../common/logger'
 import { TYPES } from 'mssql'
 import {
   Answer,
@@ -22,6 +21,7 @@ import {
 } from './models'
 import * as R from 'ramda'
 import moment from 'moment'
+import { ILogger } from '../../common/logger'
 
 const functionName = 'ps-report-2-pupil-data'
 
@@ -34,12 +34,12 @@ export interface IPsReportDataService {
 }
 
 export class PsReportDataService {
-  private readonly logger: ILogger
   private readonly sqlService: ISqlService
+  private readonly logger: ILogger
   private readonly checkFormCache: Map<number, CheckForm> = new Map()
 
-  constructor (logger?: ILogger, sqlService?: ISqlService) {
-    this.logger = logger ?? new ConsoleLogger()
+  constructor (logger: ILogger, sqlService?: ISqlService) {
+    this.logger = logger
     this.sqlService = sqlService ?? new SqlService(this.logger)
   }