Repository: wix/Detox
Pull request #1273 (2019-04-11 08:50:41)

fix: stabilize simulator log plugin
The pull request has two improvements to the simulator log plugin:

## 1. Tail glitch workaround

Finally, I've found the reason for the weird `tail` + `SimulatorLogPlugin` integration errors we were experiencing for the last year:

https://github.com/lucagrulla/node-tail/blob/3791355a0ddcc5de72e1ad64ea2f0d6e78e2c9c5/src/tail.coffee#L102

So, we have a race condition here. At times, when the `SimulatorLogPlugin` tells its `stdout` and `stderr` tails to `unwatch()`, there is a delayed `setTimeout(() => this.watch(), 1000)` inside `tail`'s very own implementation which leads to unexpected issues:

1. It keeps emitting `line` events even after we unwatch the log and close the writeable stream.
2. It leaves CI hanging due to untracked `fs.watch` handle which is created by the library itself.

So, before we `tail.unwatch()`, it is a safety measure to wipe `tail.watch = _.noop` to make sure it does not restart itself without us knowing.

## 2. Listen to more relevant events

I've noticed that there a lot of log plugin errors in `e2e/06.device.test.js` and it appeared that instead of listening to `onBeforeShutdownDevice` and `onBeforeLaunchApp` events in order to know that it is high time to unwatch log files and close the writable stream, it makes more sense to listen to:

* onBeforeShutdownDevice
* onBeforeUninstallApp
* onBeforeTerminateApp

I had to add `onBeforeUninstallApp` to the artifacts lifecycle to make this PR possible. That constitutes the majority of changes in the files of the artifact subsystem.


Patch:
diff --git a/detox/package.json b/detox/package.json
index 205ba1594..1e950b8b1 100644
--- a/detox/package.json
+++ b/detox/package.json
@@ -33,7 +33,8 @@
     "jest": "23.x.x",
     "mockdate": "^2.0.1",
     "prettier": "1.7.0",
-    "react-native": "0.56.0"
+    "react-native": "0.56.0",
+    "wtfnode": "^0.8.0"
   },
   "dependencies": {
     "bunyan": "^1.8.12",
diff --git a/detox/src/artifacts/ArtifactsManager.js b/detox/src/artifacts/ArtifactsManager.js
index 7eceed56e..25d39c331 100644
--- a/detox/src/artifacts/ArtifactsManager.js
+++ b/detox/src/artifacts/ArtifactsManager.js
@@ -82,6 +82,7 @@ class ArtifactsManager {
     deviceEmitter.on('beforeLaunchApp', this.onBeforeLaunchApp.bind(this));
     deviceEmitter.on('launchApp', this.onLaunchApp.bind(this));
     deviceEmitter.on('beforeTerminateApp', this.onBeforeTerminateApp.bind(this));
+    deviceEmitter.on('beforeUninstallApp', this.onBeforeUninstallApp.bind(this));
   }
 
   async onBootDevice(deviceInfo) {
@@ -92,6 +93,10 @@ class ArtifactsManager {
     await this._callPlugins('onBeforeTerminateApp', appInfo);
   }
 
+  async onBeforeUninstallApp(appInfo) {
+    await this._callPlugins('onBeforeUninstallApp', appInfo);
+  }
+
   async onBeforeShutdownDevice(deviceInfo) {
     await this._callPlugins('onBeforeShutdownDevice', deviceInfo);
   }
diff --git a/detox/src/artifacts/log/ios/SimulatorLogPlugin.js b/detox/src/artifacts/log/ios/SimulatorLogPlugin.js
index eeb05545a..36757504e 100644
--- a/detox/src/artifacts/log/ios/SimulatorLogPlugin.js
+++ b/detox/src/artifacts/log/ios/SimulatorLogPlugin.js
@@ -14,8 +14,13 @@ class SimulatorLogPlugin extends LogArtifactPlugin {
     await this._tryStopCurrentRecording();
   }
 
-  async onBeforeLaunchApp(event) {
-    await super.onBeforeLaunchApp(event);
+  async onBeforeUninstallApp(event) {
+    await super.onBeforeUninstallApp(event);
+    await this._tryStopCurrentRecording();
+  }
+
+  async onBeforeTerminateApp(event) {
+    await super.onBeforeTerminateApp(event);
     await this._tryStopCurrentRecording();
   }
 
diff --git a/detox/src/artifacts/log/ios/SimulatorLogRecording.js b/detox/src/artifacts/log/ios/SimulatorLogRecording.js
index 6ca3cf9b5..dbf549e80 100644
--- a/detox/src/artifacts/log/ios/SimulatorLogRecording.js
+++ b/detox/src/artifacts/log/ios/SimulatorLogRecording.js
@@ -22,9 +22,6 @@ class SimulatorLogRecording extends Artifact {
     this._logStream = null;
     this._stdoutTail = null;
     this._stderrTail = null;
-
-    this._beforeUnwatch = null;
-    this._afterUnwatch = null;
   }
 
   async doStart({ readFromBeginning } = {}) {
@@ -33,16 +30,12 @@ class SimulatorLogRecording extends Artifact {
     }
 
     this._logStream = this._logStream || this._openWriteableStream();
-
-    await this._afterUnwatch;
     this._stdoutTail = await this._createTail(this._stdoutPath, 'stdout');
     this._stderrTail = await this._createTail(this._stderrPath, 'stderr');
-    this._beforeUnwatch = sleep(200); // HACK: experimental value that ensures saving all lines from tail
   }
 
   async doStop() {
     await this._unwatch();
-    this._afterUnwatch = sleep(100); // HACK: works around the Tail bug - it emits lines even after unwatch
   }
 
   async doSave(artifactPath) {
@@ -61,7 +54,6 @@ class SimulatorLogRecording extends Artifact {
   }
 
   async _unwatch() {
-    await this._beforeUnwatch;
     await Promise.all([this._unwatchTail('stdout'), this._unwatchTail('stderr')]);
   }
 
@@ -72,6 +64,7 @@ class SimulatorLogRecording extends Artifact {
 
     if (tail) {
       log.trace({ event: 'TAIL_UNWATCH' }, `unwatching ${stdxxx} log: ${logPath}`);
+      tail.watch = _.noop; // HACK: suppress race condition: https://github.com/lucagrulla/node-tail/blob/3791355a0ddcc5de72e1ad64ea2f0d6e78e2c9c5/src/tail.coffee#L102
       tail.unwatch();
       await new Promise((resolve) => setImmediate(resolve));
     }
@@ -84,7 +77,6 @@ class SimulatorLogRecording extends Artifact {
 
     const stream = this._logStream;
     this._logStream = null;
-    await this._afterUnwatch;
     await new Promise(resolve => stream.end(resolve));
   }
 
@@ -105,10 +97,7 @@ class SimulatorLogRecording extends Artifact {
 
   _appendLine(prefix, line) {
     if (this._logStream) {
-      this._logStream.write(prefix);
-      this._logStream.write(': ');
-      this._logStream.write(line);
-      this._logStream.write('\n');
+      this._logStream.write(`${prefix}: ${line}\n`);
     } else {
       log.warn({ event: 'LOG_WRITE_ERROR' }, 'failed to add line to log:\n' + line);
     }
diff --git a/detox/src/artifacts/templates/plugin/ArtifactPlugin.js b/detox/src/artifacts/templates/plugin/ArtifactPlugin.js
index 0e9d6fdca..3cb8e778b 100644
--- a/detox/src/artifacts/templates/plugin/ArtifactPlugin.js
+++ b/detox/src/artifacts/templates/plugin/ArtifactPlugin.js
@@ -98,7 +98,7 @@ class ArtifactPlugin {
    *
    * @protected
    * @async
-   * @param {Object} event - Device shutdown event object
+   * @param {Object} event - App termination event object
    * @param {string} event.deviceId - Current deviceId
    * @param {string} event.bundleId - Current bundleId
    * @return {Promise<void>} - when done
@@ -110,6 +110,23 @@ class ArtifactPlugin {
     });
   }
 
+  /**
+   * Hook that is supposed to be called before app is uninstalled
+   *
+   * @protected
+   * @async
+   * @param {Object} event - App uninstall event object
+   * @param {string} event.deviceId - Current deviceId
+   * @param {string} event.bundleId - Current bundleId
+   * @return {Promise<void>} - when done
+   */
+  async onBeforeUninstallApp(event) {
+    Object.assign(this.context, {
+      deviceId: event.deviceId,
+      bundleId: event.bundleId,
+    });
+  }
+
   /**
    * Hook that is supposed to be called before device.shutdown() happens
    *
diff --git a/detox/src/devices/drivers/AndroidDriver.js b/detox/src/devices/drivers/AndroidDriver.js
index b962d6372..29320c7b0 100644
--- a/detox/src/devices/drivers/AndroidDriver.js
+++ b/detox/src/devices/drivers/AndroidDriver.js
@@ -76,6 +76,8 @@ class AndroidDriver extends DeviceDriverBase {
   }
 
   async uninstallApp(deviceId, bundleId) {
+    await this.emitter.emit('beforeUninstallApp', { deviceId, bundleId });
+
     if (await this.adb.isPackageInstalled(deviceId, bundleId)) {
       await this.adb.uninstall(deviceId, bundleId);
     }
diff --git a/detox/src/devices/drivers/DeviceDriverBase.js b/detox/src/devices/drivers/DeviceDriverBase.js
index 381c3f8e0..34ba02888 100644
--- a/detox/src/devices/drivers/DeviceDriverBase.js
+++ b/detox/src/devices/drivers/DeviceDriverBase.js
@@ -14,6 +14,7 @@ class DeviceDriverBase {
         'beforeShutdownDevice',
         'shutdownDevice',
         'beforeTerminateApp',
+        'beforeUninstallApp',
         'beforeLaunchApp',
         'launchApp',
       ],
diff --git a/detox/src/devices/drivers/SimulatorDriver.js b/detox/src/devices/drivers/SimulatorDriver.js
index bcc2d1088..701ef1db8 100644
--- a/detox/src/devices/drivers/SimulatorDriver.js
+++ b/detox/src/devices/drivers/SimulatorDriver.js
@@ -81,6 +81,7 @@ class SimulatorDriver extends IosDriver {
   }
 
   async uninstallApp(deviceId, bundleId) {
+    await this.emitter.emit('beforeUninstallApp', { deviceId, bundleId });
     await this._applesimutils.uninstall(deviceId, bundleId);
   }
 


Test patch:
diff --git a/detox/src/artifacts/ArtifactsManager.test.js b/detox/src/artifacts/ArtifactsManager.test.js
index c64783a80..e13e50fd9 100644
--- a/detox/src/artifacts/ArtifactsManager.test.js
+++ b/detox/src/artifacts/ArtifactsManager.test.js
@@ -90,6 +90,7 @@ describe('ArtifactsManager', () => {
           onBootDevice: jest.fn(),
           onBeforeShutdownDevice: jest.fn(),
           onShutdownDevice: jest.fn(),
+          onBeforeUninstallApp: jest.fn(),
           onBeforeLaunchApp: jest.fn(),
           onLaunchApp: jest.fn(),
           onBeforeTerminateApp: jest.fn(),
@@ -274,6 +275,11 @@ describe('ArtifactsManager', () => {
           bundleId: 'testBundleId',
           deviceId: 'testDeviceId',
         }));
+
+        itShouldCatchErrorsOnPhase('onBeforeUninstallApp', () => ({
+          bundleId: 'testBundleId',
+          deviceId: 'testDeviceId',
+        }));
       });
 
       describe('onBeforeAll', () => {
@@ -346,6 +352,19 @@ describe('ArtifactsManager', () => {
         });
       });
 
+      describe('onBeforeUninstallApp', () => {
+        it('should call onBeforeUninstallApp in plugins', async () => {
+          const uninstallInfo = {
+            deviceId: 'testDeviceId',
+            bundleId: 'testBundleId',
+          };
+
+          expect(testPlugin.onBeforeUninstallApp).not.toHaveBeenCalled();
+          await artifactsManager.onBeforeUninstallApp(uninstallInfo);
+          expect(testPlugin.onBeforeUninstallApp).toHaveBeenCalledWith(uninstallInfo);
+        });
+      });
+
       describe('onBeforeShutdownDevice', () => {
         it('should call onBeforeShutdownDevice in plugins', async () => {
           const shutdownInfo = {
diff --git a/detox/src/artifacts/__snapshots__/ArtifactsManager.test.js.snap b/detox/src/artifacts/__snapshots__/ArtifactsManager.test.js.snap
index 22d5c32ce..dd9f1ac1e 100644
--- a/detox/src/artifacts/__snapshots__/ArtifactsManager.test.js.snap
+++ b/detox/src/artifacts/__snapshots__/ArtifactsManager.test.js.snap
@@ -100,6 +100,20 @@ Array [
 ]
 `;
 
+exports[`ArtifactsManager .artifactsApi hooks error handling should catch .onBeforeUninstallApp errors 1`] = `
+Array [
+  Array [
+    Object {
+      "err": [Error: test onBeforeUninstallApp error],
+      "event": "SUPPRESS_PLUGIN_ERROR",
+      "methodName": "onBeforeUninstallApp",
+      "plugin": "testPlugin",
+    },
+    "Suppressed error inside function call: testPlugin.onBeforeUninstallApp({ bundleId: 'testBundleId', deviceId: 'testDeviceId' })",
+  ],
+]
+`;
+
 exports[`ArtifactsManager .artifactsApi hooks error handling should catch .onBootDevice errors 1`] = `
 Array [
   Array [
diff --git a/detox/src/artifacts/log/ios/SimulatorLogPlugin.test.js b/detox/src/artifacts/log/ios/SimulatorLogPlugin.test.js
index 17f940756..68e59fa08 100644
--- a/detox/src/artifacts/log/ios/SimulatorLogPlugin.test.js
+++ b/detox/src/artifacts/log/ios/SimulatorLogPlugin.test.js
@@ -121,7 +121,7 @@ describe('SimulatorLogPlugin', () => {
   }
 
   it('should work consistently in a stressed environment, through-out boots, launches and relaunches', async () => {
-    const results = await Promise.all(_.times(3, majorWorkflow));
+    const results = await Promise.all(_.times(100, majorWorkflow));
 
     for (const [snapshotName, value] of Object.entries(results[0])) {
       expect(value).toMatchSnapshot(snapshotName);
diff --git a/detox/src/artifacts/templates/plugin/ArtifactPlugin.test.js b/detox/src/artifacts/templates/plugin/ArtifactPlugin.test.js
index 94d42c709..dcf04b7d2 100644
--- a/detox/src/artifacts/templates/plugin/ArtifactPlugin.test.js
+++ b/detox/src/artifacts/templates/plugin/ArtifactPlugin.test.js
@@ -97,6 +97,15 @@ describe(ArtifactPlugin, () => {
       expect(plugin.context).toMatchSnapshot();
     });
 
+    it('should update context on .onBeforeUninstallApp', async () => {
+      await expect(plugin.onBeforeUninstallApp({
+        deviceId: 'testDeviceId',
+        bundleId: 'testBundleId',
+      }));
+
+      expect(plugin.context).toMatchSnapshot();
+    });
+
     it('should update context on .onBeforeTerminateApp', async () => {
       await expect(plugin.onBeforeTerminateApp({
         deviceId: 'testDeviceId',
diff --git a/detox/src/artifacts/templates/plugin/__snapshots__/ArtifactPlugin.test.js.snap b/detox/src/artifacts/templates/plugin/__snapshots__/ArtifactPlugin.test.js.snap
index 5fd69855a..6ae160e72 100644
--- a/detox/src/artifacts/templates/plugin/__snapshots__/ArtifactPlugin.test.js.snap
+++ b/detox/src/artifacts/templates/plugin/__snapshots__/ArtifactPlugin.test.js.snap
@@ -65,6 +65,14 @@ Object {
 }
 `;
 
+exports[`ArtifactPlugin lifecycle hooks should update context on .onBeforeUninstallApp 1`] = `
+Object {
+  "bundleId": "testBundleId",
+  "deviceId": "testDeviceId",
+  "shouldNotBeDeletedFromContext": "extraProperty",
+}
+`;
+
 exports[`ArtifactPlugin when enabled if it is disabled with a reason should log warning to log with that reason 1`] = `
 Array [
   Array [