feat: log error causes (without breaking things this time) (#438)

vladfrangu · web-flow · commit ea3cb572c9d8 · 2024-01-25T09:38:40.000+02:00
This is the proper reimplementation of #428 & revert of #434 ![image](https://github.com/apify/apify-shared-js/assets/17960496/0a664bed-8775-4ec6-860b-679538e77646) ```ts import log from '@apify/log'; const err = new Error('Some error'); const errWithCause = new Error('Some error with cause', { cause: err }); const errWithNestedCause = new Error('Some error with nested cause', { cause: errWithCause }); log.exception(errWithNestedCause); ```
diff --git a/packages/log/src/log.ts b/packages/log/src/log.ts
@@ -170,7 +170,7 @@ export class Log {
         if (level > this.options.level) return;
 
         data = { ...this.options.data, ...data };
-        data = Object.keys(data).length > 0 ? this._limitDepth(data) : undefined;
+        data = Reflect.ownKeys(data).length > 0 ? this._limitDepth(data) : undefined;
         exception = this._limitDepth(exception);
 
         this.options.logger.log(level, message, data, exception, {
diff --git a/packages/log/src/log_consts.ts b/packages/log/src/log_consts.ts
@@ -23,3 +23,9 @@ export const LEVELS = LogLevel;
 
 // Inverse of LOG_LEVELS = maps log level to string.
 export const LEVEL_TO_STRING = Object.keys(LogLevel).filter((x) => Number.isNaN(+x));
+
+/**
+ * A symbol used to mark a limited depth object as having come from an error
+ * @internal
+ */
+export const IS_APIFY_LOGGER_EXCEPTION = Symbol('apify.processed_error');
diff --git a/packages/log/src/log_helpers.ts b/packages/log/src/log_helpers.ts
@@ -1,5 +1,5 @@
 import { APIFY_ENV_VARS } from '@apify/consts';
-import { LogLevel, LogFormat } from './log_consts';
+import { LogLevel, LogFormat, IS_APIFY_LOGGER_EXCEPTION } from './log_consts';
 
 /**
  * Ensures a string is shorter than a specified number of character, and truncates it if not, appending a specific suffix to it.
@@ -64,15 +64,15 @@ export function limitDepth<T>(record: T, depth: number, maxStringLength?: number
         return maxStringLength && record.length > maxStringLength ? truncate(record, maxStringLength) as unknown as T : record;
     }
 
-    if (['number', 'boolean'].includes(typeof record) || record == null || record instanceof Date) {
+    if (['number', 'boolean', 'symbol', 'bigint'].includes(typeof record) || record == null || record instanceof Date) {
         return record;
     }
 
     // WORKAROUND: Error's properties are not iterable, convert it to a simple object and preserve custom properties
     // NOTE: _.isError() doesn't work on Match.Error
     if (record instanceof Error) {
-        const { name, message, stack, ...rest } = record;
-        record = { name, message, stack, ...rest } as unknown as T;
+        const { name, message, stack, cause, ...rest } = record;
+        record = { name, message, stack, cause, ...rest, [IS_APIFY_LOGGER_EXCEPTION]: true } as unknown as T;
     }
 
     const nextCall = (rec: T) => limitDepth(rec, depth - 1, maxStringLength);
@@ -84,7 +84,7 @@ export function limitDepth<T>(record: T, depth: number, maxStringLength?: number
     if (typeof record === 'object' && record !== null) {
         const mapObject = <U extends Record<PropertyKey, any>> (obj: U) => {
             const res = {} as U;
-            Object.keys(obj).forEach((key: keyof U) => {
+            Reflect.ownKeys(obj).forEach((key: keyof U) => {
                 res[key as keyof U] = nextCall(obj[key]) as U[keyof U];
             });
             return res;
@@ -104,3 +104,19 @@ export function limitDepth<T>(record: T, depth: number, maxStringLength?: number
 
     return undefined;
 }
+
+// Like an error class, but turned into an object
+export interface LimitedError {
+    // used to identify this object as an error
+    [IS_APIFY_LOGGER_EXCEPTION]: true;
+    name: string;
+    message: string;
+    stack?: string;
+    cause?: unknown;
+
+    // Custom properties
+    type?: string;
+    details?: Record<string, unknown>;
+    reason?: string;
+    [key: string]: unknown;
+}
diff --git a/packages/log/src/logger.ts b/packages/log/src/logger.ts
@@ -1,7 +1,6 @@
 /* eslint-disable no-console */
 import { EventEmitter } from 'events';
 import { LogLevel } from './log_consts';
-import { Exception } from './logger_text';
 
 /**
  * This is an abstract class that should
@@ -39,7 +38,7 @@ export class Logger extends EventEmitter {
     }
 
     // eslint-disable-next-line @typescript-eslint/no-unused-vars
-    _log(level: LogLevel, message: string, data?: any, exception?: Exception, opts: Record<string, any> = {}) {
+    _log(level: LogLevel, message: string, data?: any, exception?: unknown, opts: Record<string, any> = {}) {
         throw new Error('log() method must be implemented!');
     }
 
diff --git a/packages/log/src/logger_json.ts b/packages/log/src/logger_json.ts
@@ -1,6 +1,5 @@
 import { PREFIX_DELIMITER, LogLevel } from './log_consts';
 import { Logger } from './logger';
-import { Exception } from './logger_text';
 
 const DEFAULT_OPTIONS = {
     skipLevelInfo: false,
@@ -12,7 +11,7 @@ export class LoggerJson extends Logger {
         super({ ...DEFAULT_OPTIONS, ...options });
     }
 
-    _log(level: LogLevel, message: string, data?: any, exception?: Exception, opts: Record<string, any> = {}) {
+    _log(level: LogLevel, message: string, data?: any, exception?: unknown, opts: Record<string, any> = {}) {
         const { prefix, suffix } = opts;
 
         if (exception) data = { ...data, exception };
diff --git a/packages/log/src/logger_text.ts b/packages/log/src/logger_text.ts
@@ -1,6 +1,8 @@
 import c from 'ansi-colors';
 import { Logger } from './logger';
-import { LEVEL_TO_STRING, LogLevel, PREFIX_DELIMITER } from './log_consts';
+import { IS_APIFY_LOGGER_EXCEPTION, LEVEL_TO_STRING, LogLevel, PREFIX_DELIMITER } from './log_consts';
+import { LimitedError } from './log_helpers';
+import { getStackFrames } from './node_internals';
 
 const SHORTEN_LEVELS = {
     SOFT_FAIL: 'SFAIL',
@@ -31,18 +33,12 @@ const DEFAULT_OPTIONS = {
     skipTime: true,
 };
 
-export interface Exception extends Error {
-    type?: string;
-    details?: Record<string, any>;
-    reason?: string;
-}
-
 export class LoggerText extends Logger {
     constructor(options = {}) {
         super({ ...DEFAULT_OPTIONS, ...options });
     }
 
-    _log(level: LogLevel, message: string, data?: any, exception?: Exception, opts: Record<string, any> = {}) {
+    _log(level: LogLevel, message: string, data?: any, exception?: unknown, opts: Record<string, any> = {}) {
         let { prefix, suffix } = opts;
 
         let maybeDate = '';
@@ -65,35 +61,67 @@ export class LoggerText extends Logger {
         return line;
     }
 
-    _parseException(exception: Exception) {
-        let errStack = '';
+    protected _parseException(exception: unknown, indentLevel = 1) {
+        if (['string', 'boolean', 'number', 'undefined', 'bigint'].includes(typeof exception)) {
+            return `\n${exception}`;
+        }
+
+        if (exception === null) {
+            return '\nnull';
+        }
+
+        // We need to manually call toString on symbols
+        if (typeof exception === 'symbol') {
+            return `\n${exception.toString()}`;
+        }
+
+        if (typeof exception === 'object' && IS_APIFY_LOGGER_EXCEPTION in exception) {
+            return this._parseLoggerException(exception as LimitedError, indentLevel);
+        }
+
+        // Anything else we just stringify
+        return `\n${JSON.stringify(exception, null, 2)}`;
+    }
 
-        // Parse error.type and error.details from ApifyClientError.
+    private _parseLoggerException(exception: LimitedError, indentLevel = 1) {
         const errDetails = [];
-        if (exception.type) errDetails.push(`type=${exception.type}`);
+
+        if (exception.type) {
+            errDetails.push(`type=${exception.type}`);
+        }
+
         if (exception.details) {
             Object.entries(exception.details).map(([key, val]) => errDetails.push(`${key}=${val}`));
         }
 
-        // Parse error stack lines.
-        // NOTE: Reason is here to support Meteor.js like errors.
-        const errorString = exception.stack || exception.reason || exception.toString();
-        const errorLines = errorString.split('\n');
-        // const causeString = exception.cause
-        //     ? inspect(exception.cause, { colors: true, maxArrayLength: 20 }) : null;
+        // Parse the stack lines
+        const errorString = exception.stack || exception.reason || exception.message;
+        const isStack = errorString === exception.stack;
+        const errorLines = getStackFrames(exception, errorString);
+
+        if (isStack) {
+            // Remove the useless `Error` prefix from stack traces
+            errorLines[0] = exception.message || errorLines[0];
+        }
+
+        // Add details to the first line.
+        if (errDetails.length) {
+            errorLines[0] += c.gray(`(details: ${errDetails.join(', ')})`);
+        }
 
-        // Add details to a first line.
-        if (errDetails.length) errorLines[0] += c.gray(`(details: ${errDetails.join(', ')})`);
+        // Make stack lines gray
+        for (let i = 1; i < errorLines.length; i++) {
+            errorLines[i] = c.gray(errorLines[i]);
+        }
 
-        // if (causeString) {
-        //     const causeLines = causeString.split('\n');
-        //     errorLines.push(c.gray(`Cause: ${causeLines[0]}`), ...causeLines.slice(1).map((line) => `  ${line}`));
-        // }
+        // Recursively parse the cause.
+        if (exception.cause) {
+            const causeString = this._parseException(exception.cause, indentLevel + 1);
+            const causeLines = causeString.trim().split('\n');
 
-        // Compose it back.
-        errStack = errorLines.map((line) => `  ${line}`).join('\n');
-        errStack = `\n${errStack}`;
+            errorLines.push(c.red(`  CAUSE: ${c.reset(causeLines[0])}`), ...causeLines.slice(1));
+        }
 
-        return errStack;
+        return `\n${errorLines.map((line) => `${' '.repeat(indentLevel * 2)}${line}`).join('\n')}`;
     }
 }
diff --git a/packages/log/src/node_internals.ts b/packages/log/src/node_internals.ts
@@ -0,0 +1,81 @@
+/*
+THE FOLLOWING CODE IS LICENSED UNDER THE FOLLOWING LICENSE:
+
+Copyright Joyent, Inc. and other Node contributors. All rights reserved.
+Permission is hereby granted, free of charge, to any person obtaining a copy
+of this software and associated documentation files (the "Software"), to
+deal in the Software without restriction, including without limitation the
+rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
+sell copies of the Software, and to permit persons to whom the Software is
+furnished to do so, subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in
+all copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+IN THE SOFTWARE.
+*/
+
+// We've adapted the following code to work with our "error" representations (which are just nested simple objects)
+
+import c from 'ansi-colors';
+import { IS_APIFY_LOGGER_EXCEPTION } from './log_consts';
+
+function identicalSequenceRange(a: any[], b: any[]) {
+    for (let i = 0; i < a.length - 3; i++) {
+        // Find the first entry of b that matches the current entry of a.
+        const pos = b.indexOf(a[i]);
+        if (pos !== -1) {
+            const rest = b.length - pos;
+            if (rest > 3) {
+                let len = 1;
+                const maxLen = Math.min(a.length - i, rest);
+                // Count the number of consecutive entries.
+                while (maxLen > len && a[i + len] === b[pos + len]) {
+                    len++;
+                }
+                if (len > 3) {
+                    return { len, offset: i };
+                }
+            }
+        }
+    }
+
+    return { len: 0, offset: 0 };
+}
+
+function getStackString(error: any) {
+    return error.stack ? String(error.stack) : Error.prototype.toString.call(error);
+}
+
+export function getStackFrames(err: Error, stack: string) {
+    const frames = stack.split('\n');
+
+    let cause;
+    try {
+        ({ cause } = err);
+    } catch {
+    // If 'cause' is a getter that throws, ignore it.
+    }
+
+    // Remove stack frames identical to frames in cause.
+    if (cause != null && typeof cause === 'object' && IS_APIFY_LOGGER_EXCEPTION in (cause as any)) {
+        const causeStack = getStackString(cause);
+        const causeStackStart = causeStack.indexOf('\n    at');
+        if (causeStackStart !== -1) {
+            const causeFrames = causeStack.slice(causeStackStart + 1).split('\n');
+            const { len, offset } = identicalSequenceRange(frames, causeFrames);
+            if (len > 0) {
+                const skipped = len - 2;
+                const msg = `    ... ${skipped} lines matching cause stack trace ...`;
+                frames.splice(offset + 1, skipped, c.grey(msg));
+            }
+        }
+    }
+    return frames;
+}
diff --git a/packages/utilities/src/exponential_backoff.ts b/packages/utilities/src/exponential_backoff.ts
@@ -1,17 +1,17 @@
-import log, { Exception } from '@apify/log';
+import log from '@apify/log';
 import { delayPromise } from './utilities';
 
 export class RetryableError extends Error {
-    readonly error: Exception;
+    readonly error: Error;
 
-    constructor(error: Error | Exception, ...args: unknown[]) {
+    constructor(error: Error, ...args: unknown[]) {
         super(...args as [string]);
-        this.error = error as Exception;
+        this.error = error;
     }
 }
 
 // extend the error with added properties
-export interface RetryableError extends Exception {}
+export interface RetryableError extends Error {}
 
 export async function retryWithExpBackoff<T>(
     params: { func?: (...args: unknown[]) => T, expBackoffMillis?: number, expBackoffMaxRepeats?: number } = {},
@@ -54,7 +54,7 @@ export async function retryWithExpBackoff<T>(
         if (i === Math.round(expBackoffMaxRepeats / 2)) {
             log.warning(`Retry failed ${i} times and will be repeated in ${randomizedWaitMillis}ms`, {
                 originalError: error.error.message,
-                errorDetails: error.error.details,
+                errorDetails: Reflect.get(error.error, 'details'),
             });
         }
 
diff --git a/test/exponential_backoff.test.ts b/test/exponential_backoff.test.ts
@@ -1,4 +1,4 @@
-import log, { Exception } from '@apify/log';
+import log from '@apify/log';
 import { retryWithExpBackoff, RetryableError } from '@apify/utilities';
 
 describe('exponential_backoff', () => {
@@ -103,19 +103,19 @@ describe('exponential_backoff', () => {
     it('should display correct message after 1/2 of retries', async () => {
         const logWarningSpy = jest.spyOn(log, 'warning');
 
-        let error!: Exception;
+        let error!: Error & { details?: Record<string, any> };
         try {
             await retryWithExpBackoff({
                 func: async () => {
-                    const err = new Error('Failed because of XXX') as Exception;
+                    const err = new Error('Failed because of XXX') as Error & { details?: Record<string, any> };
                     err.details = { foo: 'bar' };
                     throw new RetryableError(err);
                 },
                 expBackoffMaxRepeats: 6,
                 expBackoffMillis: 10,
             });
         } catch (e) {
-            error = e as Exception;
+            error = e as Error & { details?: Record<string, any> };
         }
         expect(error.message).toBe('Failed because of XXX');
         expect(error.details).toEqual({ foo: 'bar' });
diff --git a/test/log.test.ts b/test/log.test.ts
diff --git a/test/log_helpers.test.ts b/test/log_helpers.test.ts
diff --git a/test/logger_text.test.ts b/test/logger_text.test.ts

Original file line number	Diff line number	Diff line change
`@@ -1,7 +1,6 @@`
`1`	`1`	`/* eslint-disable no-console */`
`2`	`2`	`import { EventEmitter } from 'events';`
`3`	`3`	`import { LogLevel } from './log_consts';`
`4`		`-import { Exception } from './logger_text';`
`5`	`4`
`6`	`5`	`/**`
`7`	`6`	`* This is an abstract class that should`
`@@ -39,7 +38,7 @@ export class Logger extends EventEmitter {`
`39`	`38`	`}`
`40`	`39`
`41`	`40`	`// eslint-disable-next-line @typescript-eslint/no-unused-vars`
`42`		`- _log(level: LogLevel, message: string, data?: any, exception?: Exception, opts: Record<string, any> = {}) {`
	`41`	`+ _log(level: LogLevel, message: string, data?: any, exception?: unknown, opts: Record<string, any> = {}) {`
`43`	`42`	`throw new Error('log() method must be implemented!');`
`44`	`43`	`}`
`45`	`44`