feat: add log tracing + major log refactoring

* redaction of sensitive information

docs/docs/reference/enum-types.mdx

@@ -51,8 +51,19 @@ Levels of log messages used for marking and filtering.
 | `debug` | Log level for debugging messages. |
 | `error` | Log level for error messages. |
 | `info` | Log level for info messages. |
+| `trace` | Log level for execution tracing |
 | `warn` | Log level for warning messages. |
 
+## LogRedactionMode
+
+Specifies how sensitive data should be redacted for logging.
+
+| Value | Description |
+|-------|-------------|
+| `all` | Redact all possibly sensitive data |
+| `auto` | Automatically detect sensitive data to be redacted |
+| `none` | Do not redact sensitive data at all. |
+
 ## MarkProcessedMethod
 
 The method to mark processed threads/messages/attachments.

src/lib/actions/GlobalActions.spec.ts

@@ -33,7 +33,7 @@ afterEach(() => {
 it("should log with default level to console", () => {
   spy = jest.spyOn(console, "log").mockImplementation()
   GlobalActions.log(mocks.processingContext, { message: "Log message" })
-  expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] INFO: Log message/)
+  expect(spy.mock.calls[0][0]).toMatch(/^[^ ]+ INFO Log message/)
 })
 
 it("should with a certain log level to console", () => {
@@ -42,15 +42,19 @@ it("should with a certain log level to console", () => {
     level: LogLevel.WARN,
     message: "Log message",
   })
-  expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] WARN: Log message/)
+  expect(spy.mock.calls[0][0]).toMatch(/^[^ ]+ WARN Log message/)
 })
 
 it("should log with default level (info) to a logSheet", () => {
-  GlobalActions.sheetLog(mocks.attachmentContext, { message: "Log message" })
+  GlobalActions.sheetLog(mocks.attachmentContext, {
+    location: "GlobalAction.spec",
+    message: "Log message",
+  })
   // TODO: Test should not depend on the action implementation
   expect(mocks.logSheet.appendRow.mock.calls[0][0]).toEqual([
     `${fakedSystemDateTimeString}.000`,
     LogLevel.INFO,
+    "GlobalAction.spec",
     "Log message",
     "aa0b8cc192a5d8d5b5d8ecda24fd0961b10ae283",
     "2019-05-02 07:15:28",

src/lib/actions/GlobalActions.ts

@@ -14,6 +14,10 @@ export type GlobalActionLoggingBase = {
    * The level of the log message (default: `info`).
    */
   level?: LogLevel
+  /**
+   * The location of the log message
+   */
+  location?: string
   /**
    * The message to be logged.
    */
@@ -24,26 +28,26 @@ export class GlobalActions implements ActionProvider<ProcessingContext> {
   [key: string]: ActionFunction<ProcessingContext>
 
   /** Do nothing (no operation). Used for testing. */
-  public static noop(context: ProcessingContext) {
-    context.log.info("NOOP: Do nothing.")
+  public static noop(ctx: ProcessingContext) {
+    ctx.log.info("NOOP: Do nothing.")
   }
 
   /** Terminate processing due to an error. */
   public static panic(
-    context: ProcessingContext,
+    ctx: ProcessingContext,
     args: GlobalActionLoggingBase,
   ): ActionReturnType {
-    const msg = PatternUtil.substitute(context, args.message)
-    context.log.error(msg)
+    const msg = PatternUtil.substitute(ctx, args.message)
+    ctx.log.error(msg)
     throw new Error(msg)
   }
 
   /** Create a log entry. */
   public static log(
-    context: ProcessingContext,
+    ctx: ProcessingContext,
     args: GlobalActionLoggingBase,
   ): ActionReturnType {
-    context.log.log(PatternUtil.substitute(context, args.message), args.level)
+    ctx.log.log(PatternUtil.substitute(ctx, args.message), args.level)
     return {
       ok: true,
     }
@@ -52,14 +56,13 @@ export class GlobalActions implements ActionProvider<ProcessingContext> {
   /** Create a log entry in the log spreadsheet. */
   @writingAction<ProcessingContext>()
   public static sheetLog(
-    context: ProcessingContext,
+    ctx: ProcessingContext,
     args: GlobalActionLoggingBase,
   ): ActionReturnType {
-    context.proc.spreadsheetAdapter.log(
-      context,
-      PatternUtil.substitute(context, args.message),
-      args.level,
-    )
+    ctx.proc.spreadsheetAdapter.log(ctx, {
+      ...args,
+      message: PatternUtil.substitute(ctx, args.message),
+    })
     return {
       ok: true,
     }

src/lib/adapter/LogAdapter.spec.ts

@@ -26,6 +26,7 @@ beforeEach(() => {
       logFields: [
         "log.timestamp",
         "log.level",
+        "log.location",
         "log.message",
         "field.1",
         "field.2",
@@ -38,13 +39,14 @@ beforeEach(() => {
 })
 
 it("should create a field config compliant log array", () => {
-  const actual = richLogAdapter.getLogValues(
-    mocks.processingContext,
-    "Log message",
-  )
+  const actual = richLogAdapter.getLogValues(mocks.processingContext, {
+    location: "LogAdapter.spec",
+    message: "Log message",
+  })
   expect(actual).toEqual([
     `${fakedSystemDateTimeString}.000`,
     LogLevel.INFO,
+    "LogAdapter.spec",
     "Log message",
     "static value",
     mocks.processingContext.type,
@@ -53,10 +55,14 @@ it("should create a field config compliant log array", () => {
 })
 
 it("should create a field config compliant JSON log object", () => {
-  const actual = richLogAdapter.logJSON(mocks.processingContext, "Log message")
+  const actual = richLogAdapter.logJSON(mocks.processingContext, {
+    location: "LogAdapter.spec",
+    message: "Log message",
+  })
   expect(actual).toEqual({
     "log.timestamp": `${fakedSystemDateTimeString}.000`,
     "log.level": LogLevel.INFO,
+    "log.location": "LogAdapter.spec",
     "log.message": "Log message",
     "field.1": "static value",
     "field.2": mocks.processingContext.type,

src/lib/adapter/LogAdapter.ts

@@ -6,8 +6,10 @@ import {
   ProcessingContext,
   ThreadContext,
 } from "../Context"
+import { GlobalActionLoggingBase } from "../actions/GlobalActions"
 import {
   LOG_LEVEL_NAME,
+  LOG_LOCATION_NAME,
   LOG_MESSAGE_NAME,
   LogFieldConfig,
   SettingsConfig,
@@ -72,14 +74,15 @@ export class LogAdapter extends BaseAdapter {
   public getLogFieldValue(
     ctx: Context,
     field: LogFieldConfig,
-    message: string,
-    level: LogLevel = LogLevel.INFO,
+    args: GlobalActionLoggingBase,
   ): string {
     let value = ""
     if (field.name === LOG_MESSAGE_NAME) {
-      value = message
+      value = args.message
     } else if (field.name === LOG_LEVEL_NAME) {
-      value = level
+      value = args.level ?? LogLevel.INFO
+    } else if (field.name === LOG_LOCATION_NAME) {
+      value = args.location ?? ""
     } else if (field?.ctxValues?.[ctx.type]) {
       value = field.ctxValues[ctx.type] as string
     } else if (field.value !== undefined) {
@@ -90,33 +93,27 @@ export class LogAdapter extends BaseAdapter {
 
   public getLogObject(
     ctx: Context,
-    message: string,
-    level: LogLevel = LogLevel.INFO,
+    args: GlobalActionLoggingBase,
   ): Record<string, string> {
     const data: Record<string, string> = {}
     this.getLogFields(ctx).map(
-      (f) => (data[f.name] = this.getLogFieldValue(ctx, f, message, level)),
+      (f) => (data[f.name] = this.getLogFieldValue(ctx, f, args)),
     )
     return data
   }
 
-  public getLogValues(
-    ctx: Context,
-    message: string,
-    level: LogLevel = LogLevel.INFO,
-  ): string[] {
+  public getLogValues(ctx: Context, args: GlobalActionLoggingBase): string[] {
     return this.getLogFields(ctx).map((f) =>
-      this.getLogFieldValue(ctx, f, message, level),
+      this.getLogFieldValue(ctx, f, args),
     )
   }
 
   public logJSON(
     ctx: ProcessingContext | ThreadContext | MessageContext | AttachmentContext,
-    message: string,
-    level: LogLevel = LogLevel.INFO,
+    args: GlobalActionLoggingBase,
   ): Record<string, string> {
-    const logObject = this.getLogObject(ctx, message, level)
-    ctx.log.log(`JSON: ${JSON.stringify(logObject)}`, level)
+    const logObject = this.getLogObject(ctx, args)
+    ctx.log.log(`JSON: ${JSON.stringify(logObject)}`, args.level)
     return logObject
   }
 }

src/lib/adapter/SpreadsheetAdapter.spec.ts

@@ -33,7 +33,10 @@ it("should initialize a new logsheet", () => {
 it("should log to an existing logsheet", () => {
   mocks.spreadsheetApp.create.mockReset()
   mocks.logSheet.appendRow.mockReset()
-  spreadsheetAdapter.log(mocks.attachmentContext, "some log message")
+  spreadsheetAdapter.log(mocks.attachmentContext, {
+    location: "SpreadsheetAdapter.spec",
+    message: "some log message",
+  })
   expect(mocks.spreadsheetApp.create).not.toHaveBeenCalled()
   expect(mocks.logSheet.appendRow).toHaveBeenCalled()
 })

src/lib/adapter/SpreadsheetAdapter.ts

@@ -5,8 +5,8 @@ import {
   ProcessingContext,
   ThreadContext,
 } from "../Context"
+import { GlobalActionLoggingBase } from "../actions/GlobalActions"
 import { SettingsConfig } from "../config/SettingsConfig"
-import { LogLevel } from "../utils/Logger"
 import { PatternUtil } from "../utils/PatternUtil"
 import { BaseAdapter } from "./BaseAdapter"
 import { DriveUtils } from "./GDriveAdapter"
@@ -107,15 +107,16 @@ export class SpreadsheetAdapter extends BaseAdapter {
 
   public log(
     ctx: ProcessingContext | ThreadContext | MessageContext | AttachmentContext,
-    message: string,
-    level: LogLevel = LogLevel.INFO,
+    args: GlobalActionLoggingBase,
   ) {
     if (!this.logSheetEnabled()) {
-      this.ctx.log.warn(`Skipping Logsheet: ${message}`, level)
+      this.ctx.log.log(
+        `Skipping logsheet log: [${args.location}] ${args.message}`,
+        args.level,
+      )
       return
     }
-    ctx.log.log(`Logsheet: ${message}`, level)
-    const logValues = this.logAdapter.getLogValues(ctx, message, level)
+    const logValues = this.logAdapter.getLogValues(ctx, args)
     this.appendToLogSheet(...logValues)
   }
 }

src/lib/config/SettingsConfig.ts

@@ -1,6 +1,7 @@
 import { Expose, Type, plainToInstance } from "class-transformer"
 import "reflect-metadata"
 import { essentialObject } from "../utils/ConfigUtils"
+import { LogLevel } from "../utils/Logger"
 import { RequiredDeep } from "../utils/UtilityTypes"
 
 // TODO: Use these constants in SettingsConfig below, when typescript-json-schema bug is resolved.
@@ -11,6 +12,7 @@ export const DEFAULT_SETTING_MAX_RUNTIME = 280
 export const DEFAULT_SETTING_SLEEP_TIME_THREADS = 100
 export const LOG_MESSAGE_NAME = "log.message"
 export const LOG_LEVEL_NAME = "log.level"
+export const LOG_LOCATION_NAME = "log.location"
 
 /**
  * The method to mark processed threads/messages/attachments.
@@ -88,6 +90,18 @@ export class LogFieldConfig {
   ctxValues?: LogFieldContextConfig = {}
 }
 
+/**
+ * Specifies how sensitive data should be redacted for logging.
+ */
+export enum LogRedactionMode {
+  /** Do not redact sensitive data at all. */
+  NONE = "none",
+  /** Automatically detect sensitive data to be redacted */
+  AUTO = "auto",
+  /** Redact all possibly sensitive data */
+  ALL = "all",
+}
+
 /**
  * Represents a settings config that affect the way GmailProcessor works.
  */
@@ -115,6 +129,7 @@ export class SettingsConfig {
   logFields?: string[] = [
     "log.timestamp",
     "log.level",
+    "log.location",
     "log.message",
     "object.id",
     "object.date",
@@ -229,6 +244,19 @@ export class SettingsConfig {
       },
     },
   ]
+  /**
+   * Filter logs to given level or higher.
+   */
+  logLevel? = LogLevel.INFO
+  /**
+   * Specifies how sensitive information should be redacted for logging.
+   */
+  logSensitiveRedactionMode? = LogRedactionMode.AUTO
+  /**
+   * Enables trace logging into the logsheet.
+   * This automatically loggs useful information for debugging without placing `global.sheetLog`
+   */
+  logSheetTracing?: boolean = false
   /**
    * The maximum batch size of threads to process in a single run to respect Google processing limits
    */