#2180 - Additional log improvement (#2326)

### Log improvements
- The date and time are now prepended in the job logger.
- Added a visual hierarchy to identify better the child logs.
- Changed the hierarchy organization to allow child process to be
chronologically added, as seen in the image below (before the green
ones, for instance, would be displayed altogether).

Created a new method to inspect the summary message to indicate if there
is something that needs attention in the logs.

Scheduler Enqueuer Query Change

The query was not filtering by application status and I thought that it
would be better to ensure that only `Submitted` and `Completed`
applications would be considered to have a workflow queued.

Refactor

Adjusted the logs for the `assessment-workflow-enqueuer` and
`start-application-assessment` to exclusively use the new
`ProcessSummary` class instead of the `QueueProcessSummary`. The
suggestion is intended to be a POC to have the `QueueProcessSummary`
marked as deprecated.

Author: andrewsignori-aot

sources/packages/backend/apps/queue-consumers/src/processors/assessment/_tests_/start-application-assessment.processor.e2e-spec.ts

@@ -9,6 +9,7 @@ import {
   createTestingAppModule,
   describeProcessorRootTest,
 } from "../../../../test/helpers";
+import { LogLevels, ProcessSummary } from "@sims/utilities/logger";
 
 describe(
   describeProcessorRootTest(QueueNames.StartApplicationAssessment),
@@ -29,7 +30,7 @@ describe(
       jest.resetAllMocks();
     });
 
-    it("Should throw an error when the workflow createProcessInstance method throws an error.", async () => {
+    it("Should log an error when the workflow createProcessInstance method throws an unexpected error.", async () => {
       // Arrange
       const dummyException = new Error("Dummy error");
       const job = createMock<Job<StartAssessmentQueueInDTO>>({
@@ -41,9 +42,32 @@ describe(
       zbClientMock.createProcessInstance = jest.fn().mockImplementation(() => {
         throw dummyException;
       });
+      // Capture the processSummary for later assertion.
+      let processSummary: ProcessSummary;
+      processor.logger.logProcessSummary = jest.fn((providedProcessSummary) => {
+        processSummary = providedProcessSummary;
+      });
+
+      // Act
+      const result = await processor.startAssessment(job);
 
-      // Act and Assert.
-      await expect(processor.startAssessment(job)).rejects.toBe(dummyException);
+      // Assert.
+
+      // Assert process summary was provided.
+      expect(processSummary).toBeDefined();
+      // Assert expected result message.
+      expect(result).toBe(
+        "Unexpected error while executing the job, check logs for further details.",
+      );
+      // Assert error message was added to the logs.
+      const hasExpectedLogErrorMessage = processSummary
+        .flattenLogs()
+        .some(
+          (log) =>
+            log.level === LogLevels.Error &&
+            log.message.includes("Dummy error"),
+        );
+      expect(hasExpectedLogErrorMessage).toBeTruthy();
     });
 
     it("Should invoke the workflow create instance method with the received job parameters.", async () => {

sources/packages/backend/apps/queue-consumers/src/processors/assessment/start-application-assessment.processor.ts

@@ -4,6 +4,12 @@ import { StartAssessmentQueueInDTO } from "@sims/services/queue";
 import { WorkflowClientService } from "@sims/services";
 import { QueueNames } from "@sims/utilities";
 import { StudentAssessmentService } from "../../services";
+import {
+  InjectLogger,
+  LoggerService,
+  ProcessSummary,
+} from "@sims/utilities/logger";
+import { logProcessSummaryToJobLogger } from "../../utilities";
 
 /**
  * Process messages sent to start assessment queue.
@@ -15,20 +21,43 @@ export class StartApplicationAssessmentProcessor {
     private readonly studentAssessmentService: StudentAssessmentService,
   ) {}
 
+  /**
+   * Call Camunda to start the workflow.
+   * @param job job details with assessment if and optional workflow name.
+   * @returns process summary.
+   */
   @Process()
-  async startAssessment(job: Job<StartAssessmentQueueInDTO>) {
-    let workflowName = job.data.workflowName;
-    if (!workflowName) {
-      const applicationData =
-        await this.studentAssessmentService.getApplicationDynamicData(
-          job.data.assessmentId,
-        );
-      workflowName = applicationData.workflowName;
+  async startAssessment(job: Job<StartAssessmentQueueInDTO>): Promise<string> {
+    const processSummary = new ProcessSummary();
+    try {
+      processSummary.info("Processing the start assessment job.");
+      let workflowName = job.data.workflowName;
+      if (!workflowName) {
+        const applicationData =
+          await this.studentAssessmentService.getApplicationDynamicData(
+            job.data.assessmentId,
+          );
+        workflowName = applicationData.workflowName;
+      }
+      processSummary.info(
+        `Starting assessment id ${job.data.assessmentId} using workflow ${workflowName}.`,
+      );
+      await this.workflowClientService.startApplicationAssessment(
+        workflowName,
+        job.data.assessmentId,
+      );
+      const successMessage = "Workflow call executed with success.";
+      return successMessage;
+    } catch (error) {
+      processSummary.error("Unexpected error while executing the job.", error);
+      return "Unexpected error while executing the job, check logs for further details.";
+    } finally {
+      this.logger.logProcessSummary(processSummary);
+      await logProcessSummaryToJobLogger(processSummary, job);
+      // Todo: add queue history cleaning logic as in schedulers.
     }
-    await this.workflowClientService.startApplicationAssessment(
-      workflowName,
-      job.data.assessmentId,
-    );
-    // Todo: add queue history cleaning logic as in schedulers.
   }
+
+  @InjectLogger()
+  logger: LoggerService;
 }

sources/packages/backend/apps/queue-consumers/src/processors/models/processors.models.ts

@@ -1,5 +1,4 @@
 import { LoggerService } from "@nestjs/common";
-import { ProcessSummary } from "@sims/utilities/logger";
 
 export interface QueueProcessSummaryResult {
   /**
@@ -19,6 +18,7 @@ export interface QueueProcessSummaryResult {
 /**
  * Allow the logs aggregation for a process summary and optionally
  * allow the same logs to be saved to different outputs.
+ * @deprecated please use ProcessSummary from sims/utilities/logger.
  */
 export class QueueProcessSummary {
   private summary: string[] = [];
@@ -82,27 +82,6 @@ export class QueueProcessSummary {
       errors: this.errors.length ? this.errors : undefined,
     };
   }
-
-  /**
-   * Writes all the log entries.
-   * @param processSummary process summary logs.
-   * @param logger optionally provides a job logger
-   * in case one is not present.
-   */
-  async logProcessSummaryToJobLogger(
-    processSummary: ProcessSummary,
-    logger?: JobLogger,
-  ): Promise<void> {
-    const jobLogger = logger ?? this.loggers?.jobLogger;
-    if (!jobLogger) {
-      throw new Error("No job logger was provided.");
-    }
-    for (const logEntry of processSummary.flattenLogs()) {
-      await jobLogger.log(
-        `${logEntry.level.toUpperCase()}: ${logEntry.message}`,
-      );
-    }
-  }
 }
 
 /**

sources/packages/backend/apps/queue-consumers/src/processors/schedulers/workflow/assessment-workflow-enqueuer.scheduler.ts

@@ -1,18 +1,18 @@
 import { InjectQueue, Process, Processor } from "@nestjs/bull";
 import { Job, Queue } from "bull";
 import { BaseScheduler } from "../base-scheduler";
-import { QueueNames, parseJSONError } from "@sims/utilities";
+import { QueueNames } from "@sims/utilities";
 import { QueueService } from "@sims/services/queue";
-import {
-  QueueProcessSummary,
-  QueueProcessSummaryResult,
-} from "../../models/processors.models";
 import { WorkflowEnqueuerService } from "../../../services";
 import {
   InjectLogger,
   LoggerService,
   ProcessSummary,
 } from "@sims/utilities/logger";
+import {
+  getSuccessMessageWithAttentionCheck,
+  logProcessSummaryToJobLogger,
+} from "../../../utilities";
 
 /**
  * Search for assessments that have some pending operation, for instance,
@@ -35,39 +35,33 @@ export class AssessmentWorkflowEnqueuerScheduler extends BaseScheduler<void> {
    * @returns processing result.
    */
   @Process()
-  async enqueueAssessmentOperations(
-    job: Job<void>,
-  ): Promise<QueueProcessSummaryResult> {
-    const summary = new QueueProcessSummary({
-      appLogger: this.logger,
-      jobLogger: job,
-    });
-    await summary.info(
-      "Checking application assessments to be queued for start.",
-    );
-    // Process summary to be populated by the enqueueStartAssessmentWorkflows.
-    // In case an unexpected error happen the finally block will still be able to
-    // output the partial information captured by the processSummary.
+  async enqueueAssessmentOperations(job: Job<void>): Promise<string[]> {
     const processSummary = new ProcessSummary();
     try {
+      processSummary.info(
+        "Checking application assessments to be queued for start.",
+      );
+      // Process summary to be populated by the enqueueStartAssessmentWorkflows.
+      // In case an unexpected error happen the finally block will still be able to
+      // output the partial information captured by the processSummary.
+      const serviceProcessSummary = new ProcessSummary();
+      processSummary.children(serviceProcessSummary);
       await this.workflowEnqueuerService.enqueueStartAssessmentWorkflows(
-        processSummary,
+        serviceProcessSummary,
       );
-      await summary.info(
-        "All application assessments queued with success, check logs for further details.",
+      return getSuccessMessageWithAttentionCheck(
+        "Process finalized with success.",
+        processSummary,
       );
     } catch (error: unknown) {
-      await summary.error(
-        `Unexpected error while executing the job check logs for further details. ${parseJSONError(
-          error,
-        )}`,
-      );
+      const errorMessage = "Unexpected error while executing the job.";
+      processSummary.error(errorMessage, error);
+      return [errorMessage];
     } finally {
       this.logger.logProcessSummary(processSummary);
-      await summary.logProcessSummaryToJobLogger(processSummary);
+      await logProcessSummaryToJobLogger(processSummary, job);
+      await this.cleanSchedulerQueueHistory();
     }
-    await this.cleanSchedulerQueueHistory();
-    return summary.getSummary();
   }
 
   @InjectLogger()

sources/packages/backend/apps/queue-consumers/src/services/application/application.service.ts

@@ -94,6 +94,9 @@ export class ApplicationService {
             );
           }),
         )
+        .andWhere("application.applicationStatus IN (:...status)", {
+          status: [ApplicationStatus.Submitted, ApplicationStatus.Completed],
+        })
         .andWhere(
           "studentAssessment.studentAssessmentStatus = :submittedStatus",
           {

sources/packages/backend/apps/queue-consumers/src/services/workflow/workflow-enqueuer.service.ts

@@ -10,7 +10,7 @@ import {
   StudentAssessmentStatus,
 } from "@sims/sims-db";
 import { DataSource } from "typeorm";
-import { LogScopes, ProcessSummary } from "@sims/utilities/logger";
+import { ProcessSummary } from "@sims/utilities/logger";
 
 /**
  * Manages the operations to search assessments that requires some
@@ -37,27 +37,23 @@ export class WorkflowEnqueuerService {
     try {
       summary.info(
         "Checking database for applications with assessments waiting to be triggered.",
-        LogScopes.Summary,
       );
       const applications =
         await this.applicationService.getApplicationsToStartAssessments();
-      summary.info(
-        `Found ${applications.length} applications.`,
-        LogScopes.Summary,
-      );
+      summary.info(`Found ${applications.length} applications.`);
       if (!applications.length) {
         return;
       }
-      summary.children = await processInParallel(
+      const children = await processInParallel(
         (application: Application) => this.queueNextAssessment(application),
         applications,
       );
-      summary.info("All assessments were processed.", LogScopes.Summary);
+      summary.children(...children);
+      summary.info("All assessments were processed.");
     } catch (error: unknown) {
       summary.error(
         "Error while enqueueing assessment workflows to be processed.",
         error,
-        LogScopes.Summary,
       );
     }
   }

sources/packages/backend/apps/queue-consumers/src/utilities/index.ts

@@ -0,0 +1 @@
+export * from "./log-utils";

sources/packages/backend/apps/queue-consumers/src/utilities/log-utils.ts

@@ -0,0 +1,63 @@
+import { ProcessSummary } from "@sims/utilities/logger";
+import * as dayjs from "dayjs";
+
+/**
+ * Used for log indentation to create a hierarchy
+ * for log children at different levels.
+ */
+const LOG_INDENTATION = "--";
+
+/**
+ * Log capability provided by a queue job.
+ */
+export interface JobLogger {
+  log(message: string): Promise<void>;
+}
+
+/**
+ * Writes all the log entries to job logger.
+ * @param processSummary process summary logs.
+ * @param logger optionally provides a job logger 3r
+ * in case one is not present.
+ */
+export async function logProcessSummaryToJobLogger(
+  processSummary: ProcessSummary,
+  logger: JobLogger,
+): Promise<void> {
+  for (const logEntry of processSummary.flattenLogs()) {
+    const logIndentation = LOG_INDENTATION.repeat(logEntry.indentationLevel);
+    const dateTimeEntry = dayjs(logEntry.date).format("YYYY-MM-DD HH:mm:ss");
+    await logger.log(
+      `[${dateTimeEntry}]${logIndentation}${logEntry.level.toUpperCase()}: ${
+        logEntry.message
+      }`,
+    );
+  }
+}
+
+/**
+ * Takes a regular success messages and append possible
+ * attention messages if there are errors or warnings.
+ * @param successMessage generic success message.
+ * @param processSummary processSummary to check if an
+ * attention message is required.
+ * @returns generic success message or success message with
+ * attention messages appended.
+ */
+export function getSuccessMessageWithAttentionCheck(
+  successMessage: string,
+  processSummary: ProcessSummary,
+): string[] {
+  const message: string[] = [];
+  message.push(successMessage);
+  const logsSum = processSummary.getLogLevelSum();
+  if (logsSum.error || logsSum.warn) {
+    message.push(
+      "Attention, process finalized with success but some errors and/or warnings messages may require some attention.",
+    );
+    message.push(
+      `Error(s): ${logsSum.error}, Warning(s): ${logsSum.warn}, Info: ${logsSum.info}`,
+    );
+  }
+  return message;
+}