chore: Streamline logging helpers

lib/commands/log.js

@@ -47,27 +47,18 @@ const SUPPORTED_LOG_TYPES = {
   server: {
     description: 'Appium server logs',
     /**
-     * @returns {AppiumServerLogEntry[]}
+     * @returns {import('./types').LogEntry[]}
      */
     getter: (self) => {
       self.assertFeatureEnabled(GET_SERVER_LOGS_FEATURE);
-      return log.unwrap().record.map((x) => ({
-        timestamp: /** @type {any} */ (x).timestamp ?? Date.now(),
-        level: 'ALL',
-        message: _.isEmpty(x.prefix) ? x.message : `[${x.prefix}] ${x.message}`,
-      }));
+      return log.unwrap().record.map((x) => toLogEntry(
+        _.isEmpty(x.prefix) ? x.message : `[${x.prefix}] ${x.message}`,
+        /** @type {any} */ (x).timestamp ?? Date.now()
+      ));
     },
   },
 };
 
-/**
- * Log entry in the array returned by `getLogs('server')`
- * @typedef AppiumServerLogEntry
- * @property {number} timestamp
- * @property {'ALL'} level
- * @property {string} message
- */
-
 export default {
   supportedLogTypes: SUPPORTED_LOG_TYPES,
   /**
@@ -235,6 +226,20 @@ export default {
   },
 };
 
+/**
+ *
+ * @param {string} message
+ * @param {number} timestamp
+ * @returns {import('./types').LogEntry}
+ */
+export function toLogEntry(message, timestamp) {
+  return {
+    timestamp,
+    level: 'ALL',
+    message,
+  };
+}
+
 /**
  * @typedef {import('../driver').XCUITestDriver} XCUITestDriver
  */

lib/commands/types.ts

@@ -566,3 +566,9 @@ export interface KeyboardKey {
    */
   modifierFlags?: number;
 }
+
+export interface LogEntry {
+  timestamp: number;
+  level: string,
+  message: string;
+}

lib/device-log/ios-crash-log.js

@@ -11,13 +11,6 @@ const MAGIC_SEP = '/';
 // The file format has been changed from '.crash' to '.ips' since Monterey.
 const CRASH_REPORTS_GLOB_PATTERN = '**/*.@(crash|ips)';
 
-/**
- * @typedef {Object} LogRecord
- * @property {number} timestamp
- * @property {string} level
- * @property {string} message
- */
-
 class IOSCrashLog {
   constructor(opts = {}) {
     this.udid = opts.udid;
@@ -103,7 +96,7 @@ class IOSCrashLog {
   }
 
   /**
-   * @returns {Promise<LogRecord[]>}
+   * @returns {Promise<import('../commands/types').LogEntry[]>}
    */
   async getLogs() {
     let crashFiles = await this.getCrashes();
@@ -113,7 +106,7 @@ class IOSCrashLog {
   }
 
   /**
-   * @returns {Promise<LogRecord[]>}
+   * @returns {Promise<import('../commands/types').LogEntry[]>}
    */
   async getAllLogs() {
     let crashFiles = await this.getCrashes();
@@ -123,12 +116,12 @@ class IOSCrashLog {
 
   /**
    * @param {string[]} paths
-   * @returns {Promise<LogRecord[]>}
+   * @returns {Promise<import('../commands/types').LogEntry[]>}
    */
   async filesToJSON(paths) {
     const tmpRoot = await tempDir.openDir();
     try {
-      return /** @type {LogRecord[]} */ ((
+      return /** @type {import('../commands/types').LogEntry[]} */ ((
         await B.map(paths, async (fullPath) => {
           if (_.includes(fullPath, REAL_DEVICE_MAGIC)) {
             const fileName = /** @type {string} */ (_.last(fullPath.split(MAGIC_SEP)));

lib/device-log/ios-device-log.js

@@ -22,6 +22,9 @@ class IOSDeviceLog extends IOSLog {
     this.service.start(this.onLog.bind(this));
   }
 
+  /**
+   * @param {string} logLine
+   */
   onLog(logLine) {
     this.broadcast(logLine);
     if (this.showLogs) {

lib/device-log/ios-log.js

@@ -1,14 +1,22 @@
 import {EventEmitter} from 'events';
+import { LRUCache } from 'lru-cache';
+import { toLogEntry } from '../commands/log';
 
 // We keep only the most recent log entries to avoid out of memory error
 const MAX_LOG_ENTRIES_COUNT = 10000;
 
+// TODO: Rewrite this class to typescript for better generic typing
+
 class IOSLog extends EventEmitter {
-  constructor() {
+  constructor(maxBufferSize = MAX_LOG_ENTRIES_COUNT) {
     super();
-    this.logs = [];
-    this.logIdxSinceLastRequest = -1;
-    this.maxBufferSize = MAX_LOG_ENTRIES_COUNT;
+    this.maxBufferSize = maxBufferSize;
+    /** @type {LRUCache<bigint, any>} */
+    this.logs = new LRUCache({
+      max: this.maxBufferSize,
+    });
+    /** @type {bigint?} */
+    this.logHrTimeSinceLastRequest = null;
   }
 
   /** @returns {Promise<void>} */
@@ -28,36 +36,80 @@ class IOSLog extends EventEmitter {
     throw new Error(`Sub-classes need to implement a 'isCapturing' function`);
   }
 
-  broadcast(logLine) {
-    const logObj = {
-      timestamp: Date.now(),
-      level: 'ALL',
-      message: logLine,
-    };
-    this.logs.push(logObj);
-    this.emit('output', logObj);
-    if (this.logs.length > this.maxBufferSize) {
-      this.logs.shift();
-      if (this.logIdxSinceLastRequest > 0) {
-        --this.logIdxSinceLastRequest;
-      }
+  /**
+   *
+   * @param {any} entry
+   * @returns {void}
+   */
+  broadcast(entry) {
+    const hrTime = process.hrtime.bigint();
+    const serializedEntry = this._serializeEntry(entry);
+    this.logs.set(hrTime, serializedEntry);
+    if (this.listenerCount('output')) {
+      this.emit('output', this._deserializeEntry(serializedEntry));
     }
   }
 
+  /**
+   *
+   * @returns {import('../commands/types').LogEntry[]}
+   */
   getLogs() {
-    if (this.logs.length && this.logIdxSinceLastRequest < this.logs.length) {
-      let result = this.logs;
-      if (this.logIdxSinceLastRequest > 0) {
-        result = result.slice(this.logIdxSinceLastRequest);
+    if (!this.logs.size) {
+      return [];
+    }
+
+    /** @type {import('../commands/types').LogEntry[]} */
+    const result = [];
+    /** @type {bigint?} */
+    let recentLogHrTime = null;
+    for (const [hrTime, value] of this.logs.entries()) {
+      if (this.logHrTimeSinceLastRequest && hrTime > this.logHrTimeSinceLastRequest
+          || !this.logHrTimeSinceLastRequest) {
+        recentLogHrTime = hrTime;
+        result.push(this._deserializeEntry(value));
       }
-      this.logIdxSinceLastRequest = this.logs.length;
-      return result;
     }
-    return [];
+    if (recentLogHrTime) {
+      this.logHrTimeSinceLastRequest = recentLogHrTime;
+    }
+    return result;
   }
 
+  /**
+   *
+   * @returns {import('../commands/types').LogEntry[]}
+   */
   getAllLogs() {
-    return this.logs;
+    /** @type {import('../commands/types').LogEntry[]} */
+    const result = [];
+    for (const value of this.logs.values()) {
+      result.push(this._deserializeEntry(value));
+    }
+    return result;
+  }
+
+  /**
+   *
+   * @param {any} value
+   * @returns {any}
+   */
+  _serializeEntry(value) {
+    return [value, Date.now()];
+  }
+
+  /**
+   *
+   * @param {any} value
+   * @returns {any}
+   */
+  _deserializeEntry(value) {
+    const [message, timestamp] = value;
+    return toLogEntry(message, timestamp);
+  }
+
+  _clearEntries() {
+    this.logs.clear();
   }
 }
 

lib/device-log/ios-performance-log.js

@@ -1,55 +1,67 @@
 import {logger} from 'appium/support';
 import _ from 'lodash';
+import IOSLog from './ios-log';
 
 const log = logger.getLogger('IOSPerformanceLog');
 const MAX_EVENTS = 5000;
 
-class IOSPerformanceLog {
+class IOSPerformanceLog extends IOSLog {
   constructor(remoteDebugger, maxEvents = MAX_EVENTS) {
+    super(maxEvents);
     this.remoteDebugger = remoteDebugger;
     this.maxEvents = parseInt(String(maxEvents), 10);
-
-    this.timelineEvents = [];
+    this._started = false;
   }
 
+  /**
+   * @override
+   */
   async startCapture() {
     log.debug('Starting performance (Timeline) log capture');
-    this.timelineEvents = [];
-    return await this.remoteDebugger.startTimeline(this.onTimelineEvent.bind(this));
+    this._clearEntries();
+    const result = await this.remoteDebugger.startTimeline(this.onTimelineEvent.bind(this));
+    this._started = true;
+    return result;
   }
 
+  /**
+   * @override
+   */
   async stopCapture() {
     log.debug('Stopping performance (Timeline) log capture');
-    return await this.remoteDebugger.stopTimeline();
+    const result = await this.remoteDebugger.stopTimeline();
+    this._started = false;
+    return result;
   }
 
-  onTimelineEvent(event) {
-    log.debug(`Received Timeline event: ${_.truncate(JSON.stringify(event))}`);
-    this.timelineEvents.push(event);
-
-    // if we have too many, get rid of the oldest log line
-    if (this.timelineEvents.length > this.maxEvents) {
-      let removedEvent = this.timelineEvents.shift();
-      log.warn(
-        `Too many Timeline events, removing earliest: ${_.truncate(JSON.stringify(removedEvent))}`,
-      );
-    }
+  /**
+   * @override
+   */
+  get isCapturing() {
+    return this._started;
   }
 
-  // eslint-disable-next-line require-await
-  async getLogs() {
-    let events = this.timelineEvents;
-
-    // flush events
-    log.debug('Flushing Timeline events');
-    this.timelineEvents = [];
+  /**
+   * @override
+   */
+  _serializeEntry(value) {
+    return value;
+  }
 
-    return events;
+  /**
+   * @override
+   */
+  _deserializeEntry(value) {
+    return value;
   }
 
-  // eslint-disable-next-line require-await
-  async getAllLogs() {
-    return this.getLogs();
+  /**
+   *
+   * @param {import('../commands/types').LogEntry} event
+   */
+  onTimelineEvent(event) {
+    log.debug(`Received Timeline event: ${_.truncate(JSON.stringify(event))}`);
+    this.broadcast(event);
   }
 }