diff --git a/docs/docs/reference/enum-types.mdx b/docs/docs/reference/enum-types.mdx index e65f92f6..99bef6b7 100644 --- a/docs/docs/reference/enum-types.mdx +++ b/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. diff --git a/src/lib/actions/GlobalActions.spec.ts b/src/lib/actions/GlobalActions.spec.ts index 0eef1010..4901cc3d 100644 --- a/src/lib/actions/GlobalActions.spec.ts +++ b/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", diff --git a/src/lib/actions/GlobalActions.ts b/src/lib/actions/GlobalActions.ts index 622004c8..3554d8e6 100644 --- a/src/lib/actions/GlobalActions.ts +++ b/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 { [key: string]: ActionFunction /** 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 { /** Create a log entry in the log spreadsheet. */ @writingAction() 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, } diff --git a/src/lib/adapter/LogAdapter.spec.ts b/src/lib/adapter/LogAdapter.spec.ts index c82fb0e0..4116d84b 100644 --- a/src/lib/adapter/LogAdapter.spec.ts +++ b/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, diff --git a/src/lib/adapter/LogAdapter.ts b/src/lib/adapter/LogAdapter.ts index 45517cb1..94034819 100644 --- a/src/lib/adapter/LogAdapter.ts +++ b/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 { const data: Record = {} 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 { - 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 } } diff --git a/src/lib/adapter/SpreadsheetAdapter.spec.ts b/src/lib/adapter/SpreadsheetAdapter.spec.ts index fb946dd3..e40efe5c 100644 --- a/src/lib/adapter/SpreadsheetAdapter.spec.ts +++ b/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() }) diff --git a/src/lib/adapter/SpreadsheetAdapter.ts b/src/lib/adapter/SpreadsheetAdapter.ts index 67d314f8..ca585054 100644 --- a/src/lib/adapter/SpreadsheetAdapter.ts +++ b/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) } } diff --git a/src/lib/config/SettingsConfig.ts b/src/lib/config/SettingsConfig.ts index 5b51841b..8d506fe4 100644 --- a/src/lib/config/SettingsConfig.ts +++ b/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 */ diff --git a/src/lib/config/config-schema-v2.json b/src/lib/config/config-schema-v2.json index 38f8c3c2..4a5c12a9 100644 --- a/src/lib/config/config-schema-v2.json +++ b/src/lib/config/config-schema-v2.json @@ -81,11 +81,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -135,11 +141,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -189,11 +201,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -1580,11 +1598,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -1634,11 +1658,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -1688,11 +1718,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -2750,6 +2786,7 @@ "default": [ "log.timestamp", "log.level", + "log.location", "log.message", "object.id", "object.date", @@ -2770,12 +2807,40 @@ "title": "logFields", "type": "array" }, + "logLevel": { + "description": "Filter logs to given level or higher.", + "enum": [ + "debug", + "error", + "info", + "trace", + "warn" + ], + "title": "logLevel", + "type": "string" + }, + "logSensitiveRedactionMode": { + "description": "Specifies how sensitive information should be redacted for logging.", + "enum": [ + "all", + "auto", + "none" + ], + "title": "logSensitiveRedactionMode", + "type": "string" + }, "logSheetLocation": { "default": "", "description": "Location of the spreadsheet log file. Enables logging to a spreadsheet if not empty.\nExample: `GmailProcessor/logsheet-${date.now:date::yyyy-MM}`", "title": "logSheetLocation", "type": "string" }, + "logSheetTracing": { + "default": false, + "description": "Enables trace logging into the logsheet.\nThis automatically loggs useful information for debugging without placing `global.sheetLog`", + "title": "logSheetTracing", + "type": "boolean" + }, "markProcessedLabel": { "default": "", "description": "The label to be added to processed GMail threads (only for markProcessedMode=\"label\").", @@ -3031,11 +3096,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -3085,11 +3156,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", @@ -3139,11 +3216,17 @@ "debug", "error", "info", + "trace", "warn" ], "title": "level", "type": "string" }, + "location": { + "description": "The location of the log message", + "title": "location", + "type": "string" + }, "message": { "description": "The message to be logged.", "title": "message", diff --git a/src/lib/processors/AttachmentProcessor.ts b/src/lib/processors/AttachmentProcessor.ts index f74a3eef..450aa1d7 100644 --- a/src/lib/processors/AttachmentProcessor.ts +++ b/src/lib/processors/AttachmentProcessor.ts @@ -207,40 +207,66 @@ export class AttachmentProcessor extends BaseProcessor { configs: RequiredAttachmentConfig[], result: ProcessingResult = newProcessingResult(), ): ProcessingResult { + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processConfigs()", + message: "Processing attachment configs started ...", + }) for (let configIndex = 0; configIndex < configs.length; configIndex++) { - const config = configs[configIndex] - ctx.log.info( - `Processing of attachment config '${config.name}' started ...`, - ) - const matchConfig = this.buildMatchConfig( + result = this.processConfig( ctx, - ctx.proc.config.global.attachment.match, - config.match, + configs[configIndex], + configIndex, + result, ) - const opts: GoogleAppsScript.Gmail.GmailAttachmentOptions = { - includeAttachments: matchConfig.includeAttachments, - includeInlineImages: matchConfig.includeInlineImages, - } - const attachments = ctx.message.object.getAttachments(opts) - for (let index = 0; index < attachments.length; index++) { - const attachment = attachments[index] - if (!this.matches(ctx, matchConfig, attachment)) { - ctx.log.debug( - `Skipping non-matching attachment hash '${attachment.getHash()}' (name:'${attachment.getName()}', type:${attachment.getContentType()}, size:${attachment.getSize()}) started ...`, - ) - continue - } - const attachmentContext = this.buildContext(ctx, { - config: config, - configIndex: configIndex, - index: index, - object: attachment, - }) - result = this.processEntity(attachmentContext, result) + } + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processConfigs()", + message: "Processing attachment configs finished.", + }) + return result + } + + public static processConfig( + ctx: MessageContext, + config: RequiredAttachmentConfig, + configIndex: number, + result: ProcessingResult, + ): ProcessingResult { + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processConfig()", + message: `Processing attachment config '${configIndex}' started ...`, + }) + const matchConfig = this.buildMatchConfig( + ctx, + ctx.proc.config.global.attachment.match, + config.match, + ) + const opts: GoogleAppsScript.Gmail.GmailAttachmentOptions = { + includeAttachments: matchConfig.includeAttachments, + includeInlineImages: matchConfig.includeInlineImages, + } + const attachments = ctx.message.object.getAttachments(opts) + for (let index = 0; index < attachments.length; index++) { + const attachment = attachments[index] + if (!this.matches(ctx, matchConfig, attachment)) { + ctx.log.info( + `Skipping non-matching attachment hash '${ctx.log.redact(ctx, attachment.getHash())}' (name:'${ctx.log.redact(ctx, attachment.getName())}', type:${attachment.getContentType()}, size:${attachment.getSize()}) started ...`, + ) + continue } - result.processedAttachmentConfigs += 1 - ctx.log.info(`Processing of attachment config '${config.name}' finished.`) + const attachmentContext = this.buildContext(ctx, { + config: config, + configIndex: configIndex, + index: index, + object: attachment, + }) + result = this.processEntity(attachmentContext, result) } + result.processedAttachmentConfigs += 1 + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processConfig()", + message: `Processing attachment config '${configIndex}' finished.`, + }) return result } @@ -249,9 +275,10 @@ export class AttachmentProcessor extends BaseProcessor { result: ProcessingResult = newProcessingResult(), ): ProcessingResult { const attachment = ctx.attachment.object - ctx.log.info( - `Processing of attachment hash '${attachment.getHash()}' (name:'${attachment.getName()}', type:${attachment.getContentType()}, size:${attachment.getSize()}) started ...`, - ) + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processEntity()", + message: `Processing attachment hash '${ctx.log.redact(ctx, attachment.getHash())}' (name:'${ctx.log.redact(ctx, attachment.getName())}', type:${attachment.getContentType()}, size:${attachment.getSize()}) started ...`, + }) // Execute pre-main actions: result = this.executeActions( ctx, @@ -279,9 +306,10 @@ export class AttachmentProcessor extends BaseProcessor { ctx.proc.config.global.attachment.actions, ) result.processedAttachments += 1 - ctx.log.info( - `Processing of attachment hash '${attachment.getHash()}' finished.`, - ) + ctx.log.trace(ctx, { + location: "AttachmentProcessor.processEntity()", + message: `Processing attachment hash '${ctx.log.redact(ctx, attachment.getHash())}' finished.`, + }) return result } } diff --git a/src/lib/processors/GmailProcessor.spec.ts b/src/lib/processors/GmailProcessor.spec.ts index 22623904..86a7ad74 100644 --- a/src/lib/processors/GmailProcessor.spec.ts +++ b/src/lib/processors/GmailProcessor.spec.ts @@ -49,6 +49,7 @@ describe("run", () => { name: "global.panic", args: { level: LogLevel.INFO, + location: "GmailProcessor.spec", message: "Intended failing", }, description: "Failing action", diff --git a/src/lib/processors/GmailProcessor.ts b/src/lib/processors/GmailProcessor.ts index 8d290eb3..df5a5470 100644 --- a/src/lib/processors/GmailProcessor.ts +++ b/src/lib/processors/GmailProcessor.ts @@ -91,9 +91,7 @@ export class GmailProcessor extends BaseProcessor { return actionRegistry } - public static run(config: RequiredConfig, ctx: EnvContext): ProcessingResult { - ctx.log.info("Processing of GmailProcessor config started ...") - + private static checkTimezone(ctx: EnvContext, config: RequiredConfig) { if ( config.settings.timezone && config.settings.timezone != "default" && @@ -106,27 +104,17 @@ export class GmailProcessor extends BaseProcessor { `Setting it in the config settings is deprecated. Make sure to have it set correctly in the Google Apps Script project settings or in 'appsscript.json'!`, ) } - const actionRegistry = GmailProcessor.setupActionRegistry(ctx) - const logAdapter = new LogAdapter(ctx, config.settings) - const processingContext = GmailProcessor.buildContext(ctx, { - actionRegistry: actionRegistry, - config: config, - gdriveAdapter: new GDriveAdapter(ctx, config.settings), - gmailAdapter: new GmailAdapter(ctx, config.settings), - logAdapter, - spreadsheetAdapter: new SpreadsheetAdapter( - ctx, - config.settings, - logAdapter, - ), - timer: new Timer(config.settings.maxRuntime), - }) - ctx.log.logProcessingContext(processingContext) - const result = ThreadProcessor.processConfigs( - processingContext, - config.threads, - newProcessingResult(), - ) + } + + private static reportResults( + ctx: EnvContext, + result: ProcessingResult, + reportFormat: string, + ) { + if (reportFormat == "json") { + ctx.log.info(JSON.stringify(result, null, 2)) + return + } if (result.status !== ProcessingStatus.OK) { ctx.log.error(`There have been errors during processing:`) ctx.log.error( @@ -134,7 +122,7 @@ export class GmailProcessor extends BaseProcessor { ) ctx.log.error(` - Error: ${JSON.stringify(result.error ?? "-")}`) } - ctx.log.info("Processing of GmailProcessor config finished.") + ctx.log.info("Processing GmailProcessor config finished.") ctx.log.info(`Processing summary:`) ctx.log.info( ` - Processed thread configs: ${result.processedThreadConfigs}`, @@ -150,6 +138,44 @@ export class GmailProcessor extends BaseProcessor { ctx.log.info(` - Processed attachments: ${result.processedAttachments}`) ctx.log.info(` - Executed actions: ${result.executedActions.length}`) ctx.log.info(` - Result status: ${result.status}`) + } + + public static run( + config: RequiredConfig, + ctx: EnvContext, + reportFormat = "text", + ): ProcessingResult { + ctx.log.info("Processing GmailProcessor config started ...") + this.checkTimezone(ctx, config) + const actionRegistry = GmailProcessor.setupActionRegistry(ctx) + const logAdapter = new LogAdapter(ctx, config.settings) + const processingContext = GmailProcessor.buildContext(ctx, { + actionRegistry: actionRegistry, + config: config, + gdriveAdapter: new GDriveAdapter(ctx, config.settings), + gmailAdapter: new GmailAdapter(ctx, config.settings), + logAdapter, + spreadsheetAdapter: new SpreadsheetAdapter( + ctx, + config.settings, + logAdapter, + ), + timer: new Timer(config.settings.maxRuntime), + }) + ctx.log.trace(processingContext, { + location: "GmailProcessor.run()", + message: "GmailProcessor started ...", + }) + const result = ThreadProcessor.processConfigs( + processingContext, + config.threads, + newProcessingResult(), + ) + this.reportResults(ctx, result, reportFormat) + ctx.log.trace(processingContext, { + location: "GmailProcessor.run()", + message: "GmailProcessor finished.", + }) return result } diff --git a/src/lib/processors/MessageProcessor.ts b/src/lib/processors/MessageProcessor.ts index ade5c11f..5ac701bb 100644 --- a/src/lib/processors/MessageProcessor.ts +++ b/src/lib/processors/MessageProcessor.ts @@ -370,47 +370,76 @@ export class MessageProcessor extends BaseProcessor { return m } + public static processConfig( + ctx: ThreadContext, + config: RequiredMessageConfig, + configIndex: number, + result: ProcessingResult, + ): ProcessingResult { + ctx.log.trace(ctx, { + location: "MessageProcessor.processConfig()", + message: `Processing message config '${configIndex}' started ...`, + }) + const messages = ctx.thread.object.getMessages() + const matchConfig = this.buildMatchConfig( + ctx, + ctx.proc.config.global.message.match, + config.match, + ) + for (let index = 0; index < messages.length; index++) { + if ( + ctx.proc.config.settings.markProcessedMethod === + MarkProcessedMethod.MARK_MESSAGE_READ + ) { + ctx.proc.timer.checkMaxRuntimeReached() + } + // TODO: Move everything from here on into processEntity() + const message = messages[index] + if (!this.matches(ctx, matchConfig, message)) { + ctx.log.info( + `Skipping non-matching message id '${ctx.log.redact(ctx, message.getId())}' (date:'${message + .getDate() + .toISOString()}', subject:'${ctx.log.redact(ctx, message.getSubject())}', from:${ctx.log.redact(ctx, message.getFrom())}).`, + ) + continue + } + const messageContext = this.buildContext(ctx, { + object: message, + config: config, + configIndex: configIndex, + index: index, + }) + result = this.processEntity(messageContext, result) + } + result.processedMessageConfigs += 1 + ctx.log.trace(ctx, { + location: "MessageProcessor.processConfig()", + message: `Processing message config '${configIndex}' finished.`, + }) + return result + } + public static processConfigs( ctx: ThreadContext, configs: RequiredMessageConfig[], result: ProcessingResult = newProcessingResult(), ): ProcessingResult { + ctx.log.trace(ctx, { + location: "MessageProcessor.processConfigs()", + message: "Processing message configs started ...", + }) for (let configIndex = 0; configIndex < configs.length; configIndex++) { - const config = configs[configIndex] - ctx.log.info(`Processing of message config '${config.name}' started ...`) - const messages = ctx.thread.object.getMessages() - const matchConfig = this.buildMatchConfig( + result = this.processConfig( ctx, - ctx.proc.config.global.message.match, - config.match, + configs[configIndex], + configIndex, + result, ) - for (let index = 0; index < messages.length; index++) { - if ( - ctx.proc.config.settings.markProcessedMethod === - MarkProcessedMethod.MARK_MESSAGE_READ - ) { - ctx.proc.timer.checkMaxRuntimeReached() - } - const message = messages[index] - if (!this.matches(ctx, matchConfig, message)) { - ctx.log.debug( - `Skipping non-matching message id ${message.getId()} (date:'${message - .getDate() - .toISOString()}', subject:'${message.getSubject()}', from:${message.getFrom()}).`, - ) - continue - } - const messageContext = this.buildContext(ctx, { - object: message, - config: config, - configIndex: configIndex, - index: index, - }) - result = this.processEntity(messageContext, result) - } - result.processedMessageConfigs += 1 - ctx.log.info(`Processing of message config '${config.name}' finished.`) } + ctx.log.trace(ctx, { + location: "MessageProcessor.processConfigs()", + message: "Processing message configs finished.", + }) return result } @@ -426,11 +455,12 @@ export class MessageProcessor extends BaseProcessor { ): ProcessingResult { const config = ctx.message.config const message = ctx.message.object - ctx.log.info( - `Processing of message id ${message.getId()} (date:'${message + ctx.log.trace(ctx, { + location: "MessageProcessor.processEntity()", + message: `Processing message id '${ctx.log.redact(ctx, message.getId())}' (date:'${message .getDate() - .toISOString()}', subject:'${message.getSubject()}', from:${message.getFrom()}) started ...`, - ) + .toISOString()}', subject:'${ctx.log.redact(ctx, message.getSubject())}', from:${ctx.log.redact(ctx, message.getFrom())}) started ...`, + }) // Execute pre-main actions: result = this.executeActions( ctx, @@ -459,7 +489,10 @@ export class MessageProcessor extends BaseProcessor { ctx.proc.config.global.message.actions, ) result.processedMessages += 1 - ctx.log.info(`Processing of message id ${message.getId()} finished.`) + ctx.log.trace(ctx, { + location: "MessageProcessor.processEntity()", + message: `Processing message id '${ctx.log.redact(ctx, message.getId())}' finished.`, + }) return result } } diff --git a/src/lib/processors/ThreadProcessor.spec.ts b/src/lib/processors/ThreadProcessor.spec.ts index 00fe33cc..9edd672a 100644 --- a/src/lib/processors/ThreadProcessor.spec.ts +++ b/src/lib/processors/ThreadProcessor.spec.ts @@ -1,7 +1,7 @@ import { ConfigMocks } from "../../test/mocks/ConfigMocks" import { ContextMocks } from "../../test/mocks/ContextMocks" import { MockFactory, Mocks } from "../../test/mocks/MockFactory" -import { ProcessingStatus, RunMode } from "../Context" +import { ProcessingStatus } from "../Context" import { newConfig } from "../config/Config" import { MarkProcessedMethod } from "../config/SettingsConfig" import { newThreadConfig } from "../config/ThreadConfig" @@ -42,7 +42,7 @@ it("should construct a GMail search query with globals (query, newerThan) and pr ctx.proc.config.global.thread.match, threadConfig.match, ) - const actualQuery = ThreadProcessor.buildQuery(ctx, matchConfig) + const actualQuery = ThreadProcessor.buildQuery(matchConfig) expect(actualQuery).toEqual( "some-global-query newer_than:3m -label:some-label some-thread-specific-query newer_than:2m", ) @@ -61,11 +61,7 @@ it("should construct a GMail search query without globals and no processedLabel" }, ], }) - const customMocks = MockFactory.newMocks(config, RunMode.DANGEROUS) - const actualQuery = ThreadProcessor.buildQuery( - customMocks.processingContext, - config.threads[0].match, - ) + const actualQuery = ThreadProcessor.buildQuery(config.threads[0].match) expect(actualQuery).toEqual("some-thread-specific-query") }) diff --git a/src/lib/processors/ThreadProcessor.ts b/src/lib/processors/ThreadProcessor.ts index aa0bae6f..d7445254 100644 --- a/src/lib/processors/ThreadProcessor.ts +++ b/src/lib/processors/ThreadProcessor.ts @@ -37,13 +37,9 @@ export class ThreadProcessor extends BaseProcessor { return threadContext } - public static buildQuery( - ctx: ProcessingContext, - threadMatchConfig: RequiredThreadMatchConfig, - ) { + public static buildQuery(threadMatchConfig: RequiredThreadMatchConfig) { let query = this.getStr(threadMatchConfig.query) query = query.trim().replace(/ +/g, " ") - ctx.log.debug(`Built GMail search query: ${query}`) return query } @@ -335,51 +331,73 @@ export class ThreadProcessor extends BaseProcessor { configs: RequiredThreadConfig[], result: ProcessingResult = newProcessingResult(), ): ProcessingResult { + ctx.log.trace(ctx, { + location: "ThreadProcessor.processConfigs()", + message: "Processing thread configs started ...", + }) for (let configIndex = 0; configIndex < configs.length; configIndex++) { - const config = configs[configIndex] - ctx.log.info( - `Processing of thread config index '${configIndex}' started ...`, - ) - const matchConfig = this.buildMatchConfig( + result = this.processConfig( ctx, - ctx.proc.config.global.thread.match, - config.match, - ) - const query = PatternUtil.substitute( - ctx, - this.buildQuery(ctx, matchConfig), - ) - ctx.log.info(`GMail search query: ${query}`) - // Process all threads matching the search expression: - const threads = ctx.proc.gmailAdapter.search( - query, - ctx.proc.config.settings.maxBatchSize, + configs[configIndex], + configIndex, + result, ) - ctx.log.info(`-> got ${threads.length} threads`) - for (let threadIndex = 0; threadIndex < threads.length; threadIndex++) { - const thread = threads[threadIndex] - if (!this.matches(ctx, matchConfig, thread)) { - ctx.log.debug( - `Skipping non-matching thread id ${thread.getId()} (date:'${thread - .getLastMessageDate() - .toISOString()}', firstMessageSubject:'${thread.getFirstMessageSubject()}').`, - ) - continue - } - ctx.proc.timer.checkMaxRuntimeReached() - const threadContext = this.buildContext(ctx, { - object: thread, - config: config, - configIndex: configIndex, - index: threadIndex, - }) - result = this.processEntity(threadContext, result) + } + ctx.log.trace(ctx, { + location: "ThreadProcessor.processConfigs()", + message: "Processing thread configs finished.", + }) + return result + } + + public static processConfig( + ctx: ProcessingContext, + config: RequiredThreadConfig, + configIndex: number, + result: ProcessingResult, + ): ProcessingResult { + ctx.log.trace(ctx, { + location: "ThreadProcessor.processConfig()", + message: `Processing thread config '${configIndex}' started ...`, + }) + const matchConfig = this.buildMatchConfig( + ctx, + ctx.proc.config.global.thread.match, + config.match, + ) + const query = PatternUtil.substitute(ctx, this.buildQuery(matchConfig)) + ctx.log.info(`GMail search query: ${query}`) + // Process all threads matching the search expression: + const threads = ctx.proc.gmailAdapter.search( + query, + ctx.proc.config.settings.maxBatchSize, + ) + ctx.log.info(`-> got ${threads.length} threads`) + for (let threadIndex = 0; threadIndex < threads.length; threadIndex++) { + ctx.proc.timer.checkMaxRuntimeReached() + // TODO: Move everything from here on into processEntity() + const thread = threads[threadIndex] + if (!this.matches(ctx, matchConfig, thread)) { + ctx.log.info( + `Skipping non-matching thread id '${ctx.log.redact(ctx, thread.getId())}' (date:'${thread + .getLastMessageDate() + .toISOString()}', firstMessageSubject:'${ctx.log.redact(ctx, thread.getFirstMessageSubject())}').`, + ) + continue } - result.processedThreadConfigs += 1 - ctx.log.info( - `Processing of thread config index '${configIndex}' finished.`, - ) + const threadContext = this.buildContext(ctx, { + object: thread, + config: config, + configIndex: configIndex, + index: threadIndex, + }) + result = this.processEntity(threadContext, result) } + result.processedThreadConfigs += 1 + ctx.log.trace(ctx, { + location: "ThreadProcessor.processConfig()", + message: `Processing thread config '${configIndex}' finished.`, + }) return result } @@ -389,9 +407,10 @@ export class ThreadProcessor extends BaseProcessor { ): ProcessingResult { const thread: GoogleAppsScript.Gmail.GmailThread = ctx.thread.object const config: RequiredThreadConfig = ctx.thread.config - ctx.log.info( - `Processing of thread id ${thread.getId()} (subject:'${thread.getFirstMessageSubject()}') started ...`, - ) + ctx.log.trace(ctx, { + location: "ThreadProcessor.processEntity()", + message: `Processing thread id '${ctx.log.redact(ctx, thread.getId())}' (subject:'${ctx.log.redact(ctx, thread.getFirstMessageSubject())}') started ...`, + }) // Execute pre-main actions: result = this.executeActions( ctx, @@ -415,7 +434,10 @@ export class ThreadProcessor extends BaseProcessor { ctx.proc.config.global.thread.actions, ) result.processedThreads += 1 - ctx.log.info(`Processing of thread id ${thread.getId()} finished.`) + ctx.log.trace(ctx, { + location: "ThreadProcessor.processEntity()", + message: `Processing thread id '${ctx.log.redact(ctx, thread.getId())}' finished.`, + }) return result } } diff --git a/src/lib/utils/Logger.spec.ts b/src/lib/utils/Logger.spec.ts index a700a248..8fa76839 100644 --- a/src/lib/utils/Logger.spec.ts +++ b/src/lib/utils/Logger.spec.ts @@ -1,4 +1,5 @@ import { MockFactory, Mocks } from "../../test/mocks/MockFactory" +import { ConfigMocks } from "./../../test/mocks/ConfigMocks" import { LogLevel, Logger } from "./Logger" let logger: Logger @@ -10,77 +11,95 @@ beforeEach(() => { mocks = MockFactory.newMocks() }) afterEach(() => { - spy.mockReset() + spy?.mockReset() +}) + +it("should log a trace message", () => { + spy = jest.spyOn(console, "log").mockImplementation() + spy.mockClear() + logger.trace(mocks.processingContext, { + location: "Logger.spec", + message: "Log message", + }) + expect(spy.mock.calls?.[0]?.[0]).toMatch( + /^[^ ]+ TRACE \[Logger\.spec\] Log message$/, + ) }) it("should log a debug message", () => { spy = jest.spyOn(console, "log").mockImplementation() spy.mockClear() logger.debug("Log message") - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] DEBUG: Log message$/) + expect(spy.mock.calls[0][0]).toMatch(/^[^ ]+ DEBUG Log message$/) }) it("should log an info message", () => { spy = jest.spyOn(console, "log").mockImplementation() spy.mockClear() logger.info("Log message") - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] INFO: Log message$/) + expect(spy.mock.calls[0][0]).toMatch(/^[^ ]+ INFO Log message$/) }) it("should log a warning message", () => { const spy = jest.spyOn(console, "error").mockImplementation() spy.mockClear() logger.warn("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 an error message", () => { const spy = jest.spyOn(console, "error").mockImplementation() spy.mockClear() logger.error("Log message") - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] ERROR: Log message$/) + expect(spy.mock.calls[0][0]).toMatch(/^[^ ]+ ERROR Log message$/) }) -it("should log an EnvContext", () => { - const spy = jest.spyOn(console, "log").mockImplementation() - const ctx = mocks.envContext - spy.mockClear() - logger.logEnvContext(ctx, LogLevel.WARN) - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] DEBUG: EnvContext: .+/) +it("should filter log levels", () => { + logger = new Logger(LogLevel.WARN) + const spyLog = jest.spyOn(console, "log") + const spyError = jest.spyOn(console, "error") + spyLog.mockClear() + logger.debug("Log message") + expect(spyLog).not.toHaveBeenCalled() + spyLog.mockClear() + logger.info("Log message") + expect(spyLog).not.toHaveBeenCalled() + spyError.mockClear() + logger.warn("Log message") + expect(spyError).toHaveBeenCalled() + spyError.mockClear() + logger.error("Log message") + expect(spyError).toHaveBeenCalled() }) -it("should log an ProcessingContext", () => { - const spy = jest.spyOn(console, "log").mockImplementation() +it("should trace to console and not logsheet", () => { + const config = ConfigMocks.newDefaultConfig() + config.settings.logSheetTracing = false + mocks = MockFactory.newMocks(config) const ctx = mocks.processingContext - spy.mockClear() - logger.logProcessingContext(ctx, LogLevel.DEBUG) - expect(spy.mock.calls[0][0]).toMatch( - /^\[[^\]]+\] DEBUG: ProcessingContext: .+/, + const logSpy = jest.spyOn(console, "log") + const sheetSpy = jest.spyOn(ctx.proc.spreadsheetAdapter, "log") + logSpy.mockClear() + sheetSpy.mockClear() + logger.trace(ctx, { location: "Logger.logTrace()", message: "Trace message" }) + expect(logSpy.mock.calls[0][0]).toMatch( + /^[^ ]+ TRACE \[Logger\.logTrace\(\)\] Trace message/, ) + expect(sheetSpy).not.toHaveBeenCalled() }) -it("should log an ThreadContext", () => { - const spy = jest.spyOn(console, "log").mockImplementation() - const ctx = mocks.threadContext - spy.mockClear() - logger.logThreadContext(ctx, LogLevel.ERROR) - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] DEBUG: ThreadContext: .+/) -}) - -it("should log an MessageContext", () => { - const spy = jest.spyOn(console, "log").mockImplementation() - const ctx = mocks.messageContext - spy.mockClear() - logger.logMessageContext(ctx, LogLevel.INFO) - expect(spy.mock.calls[0][0]).toMatch(/^\[[^\]]+\] DEBUG: MessageContext: .+/) -}) - -it("should log an AttachmentContext", () => { - const spy = jest.spyOn(console, "log").mockImplementation() - const ctx = mocks.attachmentContext - spy.mockClear() - logger.logAttachmentContext(ctx) - expect(spy.mock.calls[0][0]).toMatch( - /^\[[^\]]+\] DEBUG: AttachmentContext: .+/, +it("should trace to console and logsheet", () => { + const config = ConfigMocks.newDefaultConfig() + config.settings.logSheetTracing = true + mocks = MockFactory.newMocks(config) + const ctx = mocks.processingContext + const logSpy = jest.spyOn(console, "log") + const sheetSpy = jest.spyOn(ctx.proc.spreadsheetAdapter, "log") + logSpy.mockClear() + sheetSpy.mockClear() + logger.trace(ctx, { location: "Logger.logTrace()", message: "Trace message" }) + expect(logSpy.mock.calls[0][0]).toMatch( + /^[^ ]+ TRACE \[Logger\.logTrace\(\)\] Trace message/, ) + expect(sheetSpy).toHaveBeenCalled() }) diff --git a/src/lib/utils/Logger.ts b/src/lib/utils/Logger.ts index 7b700fdb..15883a48 100644 --- a/src/lib/utils/Logger.ts +++ b/src/lib/utils/Logger.ts @@ -1,14 +1,12 @@ /* eslint-disable @typescript-eslint/no-explicit-any */ -import { - AttachmentContext, - EnvContext, - MessageContext, - ProcessingContext, - ThreadContext, -} from "../Context" +import { ProcessingContext } from "../Context" +import { GlobalActionLoggingBase } from "../actions/GlobalActions" +import { LogRedactionMode } from "../config/SettingsConfig" /** Levels of log messages used for marking and filtering. */ export enum LogLevel { + /** Log level for execution tracing */ + TRACE = "trace", /** Log level for debugging messages. */ DEBUG = "debug", /** Log level for info messages. */ @@ -18,16 +16,29 @@ export enum LogLevel { /** Log level for error messages. */ ERROR = "error", } +const levels = Object.values(LogLevel) + +function levelIndex(level: LogLevel): number { + return levels.indexOf(level) +} export class Logger { + logLevelIndex: number + constructor(public logLevel: LogLevel = LogLevel.TRACE) { + this.logLevelIndex = levelIndex(logLevel) + } + shouldLog(level: LogLevel): boolean { + return this.logLevelIndex <= levelIndex(level) + } getMessage(message?: unknown, level: LogLevel = LogLevel.INFO) { - return `[${new Date().toISOString()}] ${level.toUpperCase()}: ${message}` + return `${new Date().toISOString()} ${level.toUpperCase()} ${message}` } log( message?: unknown, level: LogLevel = LogLevel.INFO, ...optionalParams: unknown[] ) { + if (!this.shouldLog(level)) return if ([LogLevel.WARN, LogLevel.ERROR].includes(level)) { console.error(this.getMessage(message, level), ...optionalParams) } else { @@ -46,86 +57,26 @@ export class Logger { error(message?: unknown, ...optionalParams: unknown[]) { this.log(message, LogLevel.ERROR, ...optionalParams) } - logEnvContext(ctx: EnvContext, level: LogLevel = LogLevel.DEBUG) { - const logObj = { - runMode: ctx.env.runMode, - timezone: ctx.env.timezone, - } - this.debug(`EnvContext: ${JSON.stringify(logObj, null, 2)}`, level) - } - logProcessingContext( - ctx: ProcessingContext, - level: LogLevel = LogLevel.DEBUG, - ) { - const logObj = { - config: ctx.proc.config, - } - this.debug(`ProcessingContext: ${JSON.stringify(logObj, null, 2)}`, level) - } - logThreadContext(ctx: ThreadContext, level: LogLevel = LogLevel.DEBUG) { - const logObj = { - config: ctx.thread.config, - object: { - id: ctx.thread.object.getId(), - firstMessageSubject: ctx.thread.object.getFirstMessageSubject(), - }, - } - this.debug(`ThreadContext: ${JSON.stringify(logObj, null, 2)}`, level) - } - logMessageContext(ctx: MessageContext, level: LogLevel = LogLevel.DEBUG) { - const logObj = { - config: ctx.message.config, - object: { - from: ctx.message.object.getFrom(), - id: ctx.message.object.getId(), - subject: ctx.message.object.getSubject(), - to: ctx.message.object.getTo(), - }, - } - this.debug(`MessageContext: ${JSON.stringify(logObj, null, 2)}`, level) - } - logAttachmentContext( - ctx: AttachmentContext, - level: LogLevel = LogLevel.DEBUG, - ) { - const logObj = { - config: ctx.attachment.config, - object: { - contentType: ctx.attachment.object.getContentType(), - name: ctx.attachment.object.getName(), - size: ctx.attachment.object.getSize(), - }, + trace(ctx: ProcessingContext, args: GlobalActionLoggingBase) { + const { logSheetTracing, logSheetLocation } = ctx.proc.config.settings + ctx.log.log(`[${args.location}] ${args.message}`, LogLevel.TRACE) + if (logSheetTracing === true && logSheetLocation) { + ctx.proc.spreadsheetAdapter.log(ctx, args) } - this.debug(`AttachmentContext: ${JSON.stringify(logObj, null, 2)}`, level) } - toValues(arg: T, fields: string[] = []): unknown { - let val: unknown - if (typeof arg === "function") { - arg = arg() - } - if (Array.isArray(arg)) { - val = arg.map((e) => this.toValues(e, fields)) - } else if (typeof arg === "object") { - val = {} - Object.keys(arg as object).forEach((key) => { - const directFields: string[] = [] - const nestedFields: string[] = [] - fields - .filter((f) => f.length > 0) - .map((f) => { - const fieldParts = f.split(".") - directFields.push(fieldParts[0]) - if (fieldParts.length > 1) { - nestedFields.push(fieldParts.splice(1).join(".")) - } - }) - if (directFields.includes(key)) { - ;(val as any)[key] = this.toValues((arg as any)[key], nestedFields) + redact(ctx: ProcessingContext, value: string): string { + switch (ctx.proc.config.settings.logSensitiveRedactionMode) { + case LogRedactionMode.ALL: + value = "(redacted)" + break + case LogRedactionMode.AUTO: + if (value.length < 8) { + value = "(redacted)" + } else { + value = `${value.slice(0, 3)}...${value.slice(-3)}` } - }) - } else { - val = arg + break } - return val + return value } }