fix: sync device logs

Author: noomorph

package-e2e/test.ts

@@ -28,6 +28,11 @@ assertType<DetoxAllure2AdapterDeviceLogsOptions>({
   android: () => true,
   override: true,
   saveAll: true,
+  syncDelay: 0,
+});
+
+assertType<DetoxAllure2AdapterDeviceLogsOptions>({
+  syncDelay: { ios: 0, android: 1000 },
 });
 
 assertType<DetoxAllure2AdapterDeviceScreenshotOptions>({

src/listener.ts

@@ -79,20 +79,16 @@ export const listener: EnvironmentListenerFn = (
       logs?.attachBefore(allure);
     })
     .on('hook_failure', async () => {
-      await screenshots?.attachFailure(allure);
-      logs?.attachAfterFailure(allure);
+      await Promise.all([logs?.attachAfterFailure(allure), screenshots?.attachFailure(allure)]);
     })
     .on('hook_success', async () => {
-      await screenshots?.attachSuccess(allure);
-      logs?.attachAfterSuccess(allure);
+      await Promise.all([logs?.attachAfterSuccess(allure), screenshots?.attachSuccess(allure)]);
     })
     .on('test_fn_failure', async () => {
-      await screenshots?.attachFailure(allure);
-      logs?.attachAfterFailure(allure);
+      await Promise.all([logs?.attachAfterFailure(allure), screenshots?.attachFailure(allure)]);
     })
     .on('test_fn_success', async () => {
-      await screenshots?.attachSuccess(allure);
-      logs?.attachAfterSuccess(allure);
+      await Promise.all([logs?.attachAfterSuccess(allure), screenshots?.attachSuccess(allure)]);
     })
     .on('test_done', async () => {
       $test = undefined;

src/logs/log-buffer.ts

@@ -5,6 +5,7 @@ import type { Emitter, AndroidEntry, IosEntry } from 'logkitten';
 import { Level, logkitten } from 'logkitten';
 import type { DetoxAllure2AdapterDeviceLogsOptions } from '../types';
 import type { DeviceWrapper } from '../utils';
+import { Deferred } from '../utils';
 
 import { PIDEntryCollection } from './pid-entry-collection';
 
@@ -18,26 +19,30 @@ export interface LogBufferOptions {
 
 export interface StepLogRecorder {
   attachBefore(allure: AllureRuntime): void;
-  attachAfter(allure: AllureRuntime, failed: boolean): void;
-  attachAfterSuccess(allure: AllureRuntime): void;
-  attachAfterFailure(allure: AllureRuntime): void;
+  attachAfter(allure: AllureRuntime, failed: boolean): Promise<void>;
+  attachAfterSuccess(allure: AllureRuntime): Promise<void>;
+  attachAfterFailure(allure: AllureRuntime): Promise<void>;
   setPid(pid: number): void;
   close(): Promise<void>;
 }
 
 const noop = () => {};
+const DEFAULT_SYNC_DELAY = 500;
 
 export class LogBuffer implements StepLogRecorder {
   private readonly _emitter: Emitter;
   private readonly _appEntries = new PIDEntryCollection();
   private readonly _detoxEntries = new PIDEntryCollection();
-  private _options: DetoxAllure2AdapterDeviceLogsOptions;
+  private readonly _options: DetoxAllure2AdapterDeviceLogsOptions;
+  private readonly _deferreds = new Set<Deferred<number>>();
+  private readonly _syncDelay: number;
 
   constructor(readonly _config: LogBufferOptions) {
     const deviceId = this._config.device.id;
     const platform = this._config.device.platform;
 
     this._options = typeof this._config.options === 'boolean' ? {} : this._config.options;
+    this._syncDelay = this._inferSyncDelay(platform, this._config.options);
     this._emitter =
       platform === 'android'
         ? logkitten({
@@ -70,18 +75,37 @@ export class LogBuffer implements StepLogRecorder {
     return this._attachLogs(allure, false, false);
   }
 
-  public attachAfter(allure: AllureRuntime, failed: boolean) {
+  public async attachAfter(allure: AllureRuntime, failed: boolean) {
+    await this._synchronize();
     return this._attachLogs(allure, failed, true);
   }
 
-  public attachAfterSuccess(allure: AllureRuntime) {
+  public async attachAfterSuccess(allure: AllureRuntime) {
+    await this._synchronize();
     return this._attachLogs(allure, false, true);
   }
 
-  public attachAfterFailure(allure: AllureRuntime) {
+  public async attachAfterFailure(allure: AllureRuntime) {
+    await this._synchronize();
     return this._attachLogs(allure, true, true);
   }
 
+  private _synchronize(reference = Date.now()): Promise<void> {
+    if (this._syncDelay < 1) {
+      return Promise.resolve();
+    }
+
+    const deferred = new Deferred<number>({
+      timeoutMs: this._syncDelay,
+      predicate: (ts) => ts > reference,
+      cleanup: () => {
+        this._deferreds.delete(deferred);
+      },
+    });
+    this._deferreds.add(deferred);
+    return deferred.promise.then(() => {}); // resolve to void
+  }
+
   private readonly _attachLogs = (allure: AllureRuntime, failed: boolean, after: boolean) => {
     // Check if we should save logs based on failure status
     const saveAll = this._options.saveAll ?? false;
@@ -102,11 +126,19 @@ export class LogBuffer implements StepLogRecorder {
     }
   };
 
+  private _updateDeferreds(ts: number) {
+    for (const deferred of this._deferreds) {
+      deferred.update(ts);
+    }
+  }
+
   private readonly _onEntry = (entry: AnyEntry) => {
     this._appEntries.push(entry);
   };
 
   private _iosFilter(entry: IosEntry): boolean {
+    this._updateDeferreds(entry.ts);
+
     if (entry.subsystem === 'com.wix.Detox') {
       this._detoxEntries.push(entry);
 
@@ -126,6 +158,8 @@ export class LogBuffer implements StepLogRecorder {
   }
 
   private _androidFilter(entry: AndroidEntry): boolean {
+    this._updateDeferreds(entry.ts);
+
     if (entry.tag && entry.tag.startsWith('Detox')) {
       this._detoxEntries.push(entry);
 
@@ -177,4 +211,23 @@ export class LogBuffer implements StepLogRecorder {
 
     return false;
   };
+
+  /**
+   * Infers the sync delay (ms) for the given platform and options.
+   */
+  private _inferSyncDelay(
+    platform: string,
+    options: DetoxAllure2AdapterDeviceLogsOptions | boolean,
+  ): number {
+    if (typeof options !== 'boolean') {
+      const syncDelay = options.syncDelay;
+      if (typeof syncDelay === 'number') {
+        return syncDelay;
+      } else if (typeof syncDelay === 'object' && syncDelay !== null) {
+        return syncDelay[platform as keyof typeof syncDelay] ?? DEFAULT_SYNC_DELAY;
+      }
+    }
+
+    return DEFAULT_SYNC_DELAY;
+  }
 }

src/screenshots/helpers.ts

@@ -50,7 +50,14 @@ export class ScreenshotHelper {
     }
   }
 
-  async extractFromResult(allure: AllureRuntime, result: unknown) {
+  async attachFromResultOrFailure(allure: AllureRuntime, result: unknown) {
+    const attached = await this.attachFromResult(allure, result);
+    if (!attached) {
+      await this.attachFailure(allure);
+    }
+  }
+
+  async attachFromResult(allure: AllureRuntime, result: unknown) {
     if (!result) {
       return false;
     }

src/steps/wrapWithSteps.ts

@@ -38,18 +38,18 @@ export function wrapWithSteps(options: WrapWithStepsOptions) {
     const ws = worker._client._asyncWebSocket;
     const send = ws.send.bind(ws) as (...args: any[]) => Promise<{ type?: string }>;
     const onActionSuccess = async () => {
-      logs?.attachAfterSuccess(allure);
+      await logs?.attachAfterSuccess(allure);
     };
+
     const onActionFailure = async (shouldSetStatus: boolean, result?: unknown) => {
       if (shouldSetStatus) {
         allure.status('failed');
       }
 
-      const attached = await screenshots?.extractFromResult(allure, result);
-      if (!attached) {
-        await screenshots?.attachFailure(allure);
-      }
-      logs?.attachAfterFailure(allure);
+      await Promise.all([
+        logs?.attachAfterFailure(allure),
+        screenshots?.attachFromResultOrFailure(allure, result),
+      ]);
     };
     ws.send = async (...args: any[]) => {
       const desc = descriptionMaker(args[0]);
@@ -97,13 +97,11 @@ function wrapDeviceMethod(
       try {
         logs?.attachBefore(allure);
         const result = await originalMethod.apply(device, args);
-        await screenshots?.attach(allure, false);
-        logs?.attachAfterSuccess(allure);
+        await Promise.all([logs?.attachAfterSuccess(allure), screenshots?.attach(allure, false)]);
 
         return result;
       } catch (error) {
-        await screenshots?.attachFailure(allure);
-        logs?.attachAfterFailure(allure);
+        await Promise.all([logs?.attachAfterFailure(allure), screenshots?.attachFailure(allure)]);
 
         throw error; // Re-throw the error
       }

src/types.ts

@@ -25,6 +25,11 @@ export interface DetoxAllure2AdapterDeviceLogsOptions {
   android?: (entry: AndroidEntry) => boolean;
   override?: boolean;
   saveAll?: boolean;
+  /**
+   * Synchronization delay (ms) for log collection. 0 disables, number for both, or { ios, android } for per-platform.
+   * @default 500
+   */
+  syncDelay?: number | { ios?: number; android?: number };
 }
 
 export interface DetoxAllure2AdapterDeviceScreenshotOptions {

src/utils/deferred.test.ts

@@ -0,0 +1,69 @@
+import { Deferred } from './deferred';
+
+describe('Deferred', () => {
+  const timeoutMs = 100;
+  const cleanup = jest.fn();
+
+  afterEach(() => {
+    jest.clearAllTimers();
+    jest.useRealTimers();
+    cleanup.mockClear();
+  });
+
+  it('resolves when predicate is satisfied', async () => {
+    jest.useFakeTimers();
+    const deferred = new Deferred<number>({
+      timeoutMs,
+      predicate: (v) => v > 5,
+      cleanup,
+    });
+    let resolved = false;
+    deferred.promise.then(() => {
+      resolved = true;
+    });
+    deferred.update(3);
+    expect(resolved).toBe(false);
+    deferred.update(7);
+    jest.runAllTimers();
+    await Promise.resolve();
+    expect(resolved).toBe(true);
+    expect(cleanup).toHaveBeenCalled();
+  });
+
+  it('resolves on timeout if predicate is never satisfied', async () => {
+    jest.useFakeTimers();
+    const deferred = new Deferred<number>({
+      timeoutMs,
+      predicate: () => false,
+      cleanup,
+    });
+    let resolved = false;
+    deferred.promise.then(() => {
+      resolved = true;
+    });
+    deferred.update(1);
+    deferred.update(2);
+    jest.advanceTimersByTime(timeoutMs + 1);
+    await Promise.resolve();
+    expect(resolved).toBe(true);
+    expect(cleanup).toHaveBeenCalled();
+  });
+
+  it('does not resolve more than once and cleanup is called once', async () => {
+    jest.useFakeTimers();
+    const deferred = new Deferred<number>({
+      timeoutMs,
+      predicate: (v) => v === 1,
+      cleanup,
+    });
+    const onResolve = jest.fn();
+    deferred.promise.then(onResolve);
+    deferred.update(1);
+    deferred.update(2);
+    deferred.update(1);
+    jest.runAllTimers();
+    await Promise.resolve();
+    expect(onResolve).toHaveBeenCalledTimes(1);
+    expect(cleanup).toHaveBeenCalledTimes(1);
+  });
+});

src/utils/deferred.ts

@@ -0,0 +1,41 @@
+export class Deferred<T> {
+  public promise: Promise<void>;
+  private _resolve!: () => void;
+  private _settled = false;
+  private _timeout: NodeJS.Timeout;
+  private _cleanup: () => void;
+  private _predicate: (value: T) => boolean;
+
+  constructor({
+    timeoutMs,
+    predicate,
+    cleanup,
+  }: {
+    timeoutMs: number;
+    predicate: (value: T) => boolean;
+    cleanup: () => void;
+  }) {
+    this._predicate = predicate;
+    this._cleanup = cleanup;
+    this.promise = new Promise<void>((resolve) => {
+      this._resolve = () => {
+        if (!this._settled) {
+          this._settled = true;
+          clearTimeout(this._timeout);
+          this._cleanup();
+          resolve();
+        }
+      };
+    });
+    this._timeout = setTimeout(() => {
+      this._resolve();
+    }, timeoutMs);
+  }
+
+  update(value: T) {
+    if (this._settled) return;
+    if (this._predicate(value)) {
+      this._resolve();
+    }
+  }
+}

src/utils/index.ts

@@ -1,2 +1,3 @@
+export * from './deferred';
 export * from './device-wrapper';
 export * from './worker-wrapper';