feat(appium): Improve context logging (#20250)

packages/appium/lib/logsink.js

@@ -142,7 +142,7 @@ function createConsoleTransport(args, logLvl) {
     format: format.combine(
       formatTimestamp(args),
       isLogColorEnabled(args) ? colorizeFormat : stripColorFormat,
-      format.printf(formatLogLine(args, true))
+      formatLog(args, true),
     ),
   });
 }
@@ -166,7 +166,7 @@ function createFileTransport(args, logLvl) {
     format: format.combine(
       stripColorFormat,
       formatTimestamp(args),
-      format.printf(formatLogLine(args, false))
+      formatLog(args, false),
     ),
   });
 }
@@ -199,7 +199,7 @@ function createHttpTransport(args, logLvl) {
     level: logLvl,
     format: format.combine(
       stripColorFormat,
-      format.printf(formatLogLine(args, false))
+      formatLog(args, false),
     ),
   });
 }
@@ -288,22 +288,35 @@ function colorizePrefix(text) {
 /**
  * @param {ParsedArgs} args
  * @param {boolean} targetConsole
- * @returns {(info: import('logform').TransformableInfo) => string}
+ * @returns {import('logform').Format}
  */
-function formatLogLine(args, targetConsole) {
-  return (info) => {
-    if (['json', 'pretty_json'].includes(args.logFormat)) {
-      let infoCopy = {...info};
-      if (targetConsole && !args.logTimestamp) {
-        delete infoCopy.timestamp;
-      }
-      return JSON.stringify(infoCopy, null, args.logFormat === 'pretty_json' ? 2 : undefined);
-    }
+function formatLog(args, targetConsole) {
+  if (['json', 'pretty_json'].includes(args.logFormat)) {
+    return format.combine(
+      format((info) => {
+        const infoCopy = {...info};
+        const contextInfo = globalLog.asyncStorage.getStore() ?? {};
+
+        if (targetConsole && !args.logTimestamp) {
+          delete infoCopy.timestamp;
+        }
+
+        if (!_.isEmpty(contextInfo)) {
+          infoCopy.context = {...contextInfo};
+        }
+
+        return infoCopy;
+      })(),
+      format.json({space: args.logFormat === 'pretty_json' ? 2 : undefined}),
+    );
+  }
+
+  return format.printf((info) => {
     if (targetConsole) {
       return `${args.logTimestamp ? `${info.timestamp} - ` : ''}${info.message}`;
     }
     return `${info.timestamp} ${info.message}`;
-  };
+  });
 }
 
 /**

packages/base-driver/lib/basedriver/driver.ts

@@ -20,6 +20,7 @@ import {
 import B from 'bluebird';
 import _ from 'lodash';
 import {fixCaps, isW3cCaps} from '../helpers/capabilities';
+import {calcSignature} from '../helpers/session';
 import {DELETE_SESSION_COMMAND, determineProtocol, errors} from '../protocol';
 import {processCapabilities, validateCaps} from './capabilities';
 import {DriverCore} from './core';
@@ -309,6 +310,11 @@ export class BaseDriver<
 
     this._log.prefix = helpers.generateDriverLogPrefix(this);
 
+    this.log.updateAsyncContext({
+      sessionId: this.sessionId,
+      sessionSignature: calcSignature(this.sessionId),
+    });
+
     this.log.info(`Session created with session id: ${this.sessionId}`);
 
     return [this.sessionId, caps] as CreateResult;

packages/base-driver/lib/express/idempotency.js

@@ -144,6 +144,9 @@ async function handleIdempotency(req, res, next) {
   }
 
   const key = _.isArray(keyOrArr) ? keyOrArr[0] : keyOrArr;
+
+  log.updateAsyncContext({idempotencyKey: key});
+
   if (!MONITORED_METHODS.includes(req.method)) {
     // GET, DELETE, etc. requests are idempotent by default
     // there is no need to cache them

packages/base-driver/lib/express/middleware.js

@@ -3,6 +3,8 @@ import log from './logger';
 import {errors} from '../protocol';
 export {handleIdempotency} from './idempotency';
 import {pathToRegexp} from 'path-to-regexp';
+import {util} from '@appium/support';
+import {calcSignature} from '../helpers/session';
 
 /**
  *
@@ -76,15 +78,13 @@ export function fixPythonContentType(basePath) {
  * @returns {any}
  */
 export function handleLogContext(req, res, next) {
-  const contextStorage = global._global_npmlog?.asyncStorage;
-  if (!contextStorage) {
-    return next();
-  }
+  const requestId = util.uuidV4();
+
+  const sessionId = SESSION_ID_PATTERN.exec(req.url)?.[1];
+  const sessionInfo = sessionId ? {sessionId, sessionSignature: calcSignature(sessionId)} : {};
+
+  log.updateAsyncContext({requestId, ...sessionInfo}, true);
 
-  const sessionIdMatch = SESSION_ID_PATTERN.exec(req.url);
-  contextStorage.enterWith(
-    sessionIdMatch ? {sessionSignature: sessionIdMatch[1].substring(0, 8)} : {}
-  );
   return next();
 }
 

packages/base-driver/lib/helpers/session.ts

@@ -0,0 +1,8 @@
+/**
+ * Extract the first 8 characters of session ID to prefix the log.
+ *
+ * @param sessionId session identifier
+ */
+export function calcSignature(sessionId: string): string {
+  return sessionId.substring(0, 8);
+}

packages/logger/lib/log.ts

@@ -88,6 +88,19 @@ export class Log extends EventEmitter implements Logger {
     return this._asyncStorage;
   }
 
+  updateAsyncStorage(contextInfo: Record<string, any>, replace: boolean): void {
+    if (!_.isPlainObject(contextInfo)) {
+      return;
+    }
+    if (replace) {
+      this._asyncStorage.enterWith({...contextInfo});
+    } else {
+      const store = this._asyncStorage.getStore() ?? {};
+      Object.assign(store, contextInfo);
+      this._asyncStorage.enterWith(store);
+    }
+  }
+
   enableColor(): void {
     this._colorEnabled = true;
   }

packages/logger/lib/types.ts

@@ -54,6 +54,8 @@ export interface Logger extends EventEmitter {
 
   addLevel(level: string, n: number, style?: StyleObject, disp?: string): void;
 
+  updateAsyncStorage(contextInfo: Record<string, any>, replace: boolean): void;
+
   get asyncStorage(): AsyncLocalStorage<Record<string, any>>;
 
   // Allows for custom log levels

packages/support/lib/logging.js

@@ -35,26 +35,20 @@ export function getLogger(prefix = null) {
     unwrap: () => logger,
     levels: LEVELS,
     prefix,
-    /**
-     * Logs given arguments at the error level and returns
-     * the error object.
-     *
-     * @param  {...any} args
-     * @returns {Error}
-     */
     errorWithException (/** @type {any[]} */ ...args) {
       this.error(...args);
       // make sure we have an `Error` object. Wrap if necessary
       return _.isError(args[0]) ? args[0] : new Error(args.join('\n'));
     },
-    /**
-     * @deprecated Use {@link errorWithException} instead
-     * @param {...any} args
-     * @throws {Error}
-     */
     errorAndThrow (/** @type {any[]} */ ...args) {
       throw this.errorWithException(args);
     },
+    updateAsyncContext(
+      /** @type {import('@appium/types').AppiumLoggerContext} */ contextInfo,
+      replace = false,
+    ) {
+      this.unwrap().updateAsyncStorage(contextInfo, replace);
+    },
   };
   // allow access to the level of the underlying logger
   Object.defineProperty(wrappedLogger, 'level', {

packages/types/lib/logger.ts

@@ -12,6 +12,20 @@ export type AppiumLoggerPrefix = string | (() => string);
  */
 export type AppiumLoggerLevel = 'silly' | 'verbose' | 'debug' | 'info' | 'http' | 'warn' | 'error';
 
+
+/**
+ * Async Context information to be stored in AsyncLocalStorage.
+ * Only the sessionSignature value is used as the prefix of the log message,
+ * and the remaining values are recorded only in JSON format logs.
+ */
+export type AppiumLoggerContext = {
+  idempotencyKey?: string;
+  requestId?: string;
+  sessionId?: string;
+  sessionSignature?: string;
+  [key: string]: any
+}
+
 /**
  * Describes the internal logger.
  */
@@ -36,7 +50,23 @@ export interface AppiumLogger {
   http(...args: any[]): void;
   /**
    * @deprecated Use {@link errorWithException} instead
+   * @param {...any} args
+   * @throws {Error}
    */
   errorAndThrow(...args: any[]): never;
+  /**
+   * Logs given arguments at the error level and returns
+   * the error object.
+   *
+   * @param  {...any} args
+   * @returns {Error}
+   */
   errorWithException(...args: any[]): Error;
+  /**
+   * Assign context values to be used in the entire current asynchronous context for logging.
+   *
+   * @param {AppiumLoggerContext} contextInfo key-value pairs to be added to the context
+   * @param {boolean} [replace=false] if true, replace the existing context info object(default: false)
+   */
+  updateAsyncContext(contextInfo: AppiumLoggerContext, replace?: boolean): void;
 }