Repository: wix/Detox
Pull request #3804 (2023-01-03 16:20:51)

fix(logger): complete events in sandbox
## Description

Consider this code in userbase:

```js
detox.log.trace.complete('Navigating to Sanity', async () => {
  detox.log.trace('Reloading app');
  await device.reloadReactNative();
  detox.log.trace('Tap on Sanity');
  await element(by.text('Sanity')).tap();
  detox.log.trace('I am on Sanity screen');
});
```

### Expected result

Begin event, instant event x 3, End event
```
|B-- Navigating to Sanity --E|
|---i----------i---------i---|
```

### Actual result

```
|B-- E-----------------------|
|---i----------i---------i---|
```

### Analysis

The **sandboxed** `Promise` constructor fails the previously implemented `isPromise` check:

```
obj = [Promise*]
Promise.resolve(obj) !== obj
```

### Chosen solution

It is fair enough to expect any Promise-like object in such logger calls, so I switched the implementation to `isPromiseLike` with a duck typing check: if it has `.then` function, then probably it is a promise.

### Confirmation

| Before      | After |
| ----------- | ----------- |
| ![](https://user-images.githubusercontent.com/1962469/210393875-13f36d49-7f1b-4798-b4f0-f1503b238108.png) | ![](https://user-images.githubusercontent.com/1962469/210393912-539e13de-2aed-447e-8bd9-2bdaabc7e66a.png) |

### Test strategy

#### Integration tests 

I added this case to the timeline snapshot test at the moment. For example, a regression would look like this:

<img width="708" alt="image" src="https://user-images.githubusercontent.com/1962469/210394851-b8fde583-6313-4937-9cad-594167312e5a.png">

#### Unit tests

1. Added tests for `isPromiseLike`.
2. Added an extra test for `DetoxLogger` which verifies it treats promise-like objects identically to the promises:

```js
const promiseLike = { then: jest.fn() };
const promiseLikeResult = l.fatal.complete('Fatal (pending)', promiseLike);
expect(promiseLikeResult).toBe(promiseLike);
// ...
expect.objectContaining({ msg: 'Fatal (pending)', ph: 'B', time, tid, level: 60 }),
```






Patch:
diff --git a/detox/src/logger/DetoxLogger.js b/detox/src/logger/DetoxLogger.js
index 512a51bf9..042343461 100644
--- a/detox/src/logger/DetoxLogger.js
+++ b/detox/src/logger/DetoxLogger.js
@@ -4,7 +4,7 @@ const _ = require('lodash');
 
 const { DetoxInternalError, DetoxError } = require('../errors');
 const { shortFormat } = require('../utils/dateUtils');
-const isPromise = require('../utils/isPromise');
+const { isPromiseLike } = require('../utils/isPromise');
 
 const BunyanLogger = require('./utils/BunyanLogger');
 const CategoryThreadDispatcher = require('./utils/CategoryThreadDispatcher');
@@ -263,7 +263,7 @@ class DetoxLogger {
         ? action()
         : action;
 
-      if (!isPromise(result)) {
+      if (!isPromiseLike(result)) {
         end({ success: true });
       } else {
         result.then(
diff --git a/detox/src/utils/isPromise.js b/detox/src/utils/isPromise.js
index 711b95e69..f52ee33b6 100644
--- a/detox/src/utils/isPromise.js
+++ b/detox/src/utils/isPromise.js
@@ -2,4 +2,11 @@ function isPromise(value) {
   return Promise.resolve(value) === value;
 }
 
-module.exports = isPromise;
\ No newline at end of file
+function isPromiseLike(value) {
+  return value ? typeof value.then === 'function' : false;
+}
+
+module.exports = {
+  isPromise,
+  isPromiseLike,
+};


Test patch:
diff --git a/detox/src/logger/DetoxLogger.test.js b/detox/src/logger/DetoxLogger.test.js
index 539d288a1..ad1d6fc68 100644
--- a/detox/src/logger/DetoxLogger.test.js
+++ b/detox/src/logger/DetoxLogger.test.js
@@ -203,6 +203,10 @@ describe('DetoxLogger', () => {
       expect(asyncResult).toBeInstanceOf(Promise);
       expect(await asyncResult).toBe(168);
 
+      const promiseLike = { then: jest.fn() };
+      const promiseLikeResult = l.fatal.complete('Fatal (pending)', promiseLike);
+      expect(promiseLikeResult).toBe(promiseLike);
+
       try {
         l.error.complete('Error duration (sync)', () => { throw anError('Oops (sync)!'); });
       } catch (e) {}
@@ -224,6 +228,7 @@ describe('DetoxLogger', () => {
         expect.objectContaining({ ph: 'E', time, tid, level: 20, success: true }),
         expect.objectContaining({ msg: 'Trace duration', ph: 'B', time, tid, level: 10 }),
         expect.objectContaining({ ph: 'E', time, tid, level: 10, success: true }),
+        expect.objectContaining({ msg: 'Fatal (pending)', ph: 'B', time, tid, level: 60 }),
         expect.objectContaining({ msg: 'Error duration (sync)', ph: 'B', time, tid, level: 50 }),
         expect.objectContaining({ ph: 'E', time, tid, level: 50, success: false, error: expect.any(String) }),
         expect.objectContaining({ msg: 'Error duration (async)', ph: 'B', time, tid, level: 50 }),
diff --git a/detox/src/logger/__snapshots__/DetoxLogger.test.js.snap b/detox/src/logger/__snapshots__/DetoxLogger.test.js.snap
index 3b261c639..fd1ce5ff3 100644
--- a/detox/src/logger/__snapshots__/DetoxLogger.test.js.snap
+++ b/detox/src/logger/__snapshots__/DetoxLogger.test.js.snap
@@ -96,6 +96,7 @@ exports[`DetoxLogger - main functionality - should log complete duration events
 00:00:00.000 detox[PID] E  Debug duration
 00:00:00.000 detox[PID] B  Trace duration
 00:00:00.000 detox[PID] E  Trace duration
+00:00:00.000 detox[PID] B  Fatal (pending)
 00:00:00.000 detox[PID] B  Error duration (sync)
 00:00:00.000 detox[PID] E  Error duration (sync)
   error: Error: Oops (sync)!
diff --git a/detox/src/utils/isPromise.test.js b/detox/src/utils/isPromise.test.js
index 9ee807467..ab7aa4a6c 100644
--- a/detox/src/utils/isPromise.test.js
+++ b/detox/src/utils/isPromise.test.js
@@ -1,4 +1,4 @@
-const isPromise = require('./isPromise');
+const { isPromise, isPromiseLike } = require('./isPromise');
 
 describe('isPromise', () => {
   it.each([
@@ -11,3 +11,15 @@ describe('isPromise', () => {
     expect(isPromise(arg)).toBe(expected);
   });
 });
+
+describe('isPromiseLike', () => {
+  it.each([
+    [true, 'a new promise', new Promise(() => {})],
+    [true, 'a resolved promise', Promise.resolve()],
+    [true, 'a promise-like object', { then: () => {}, catch: () => {}, finally: () => {} }],
+    [false, 'a function', () => {}],
+    [false, 'undefined', undefined],
+  ])('should return %j for %s', (expected, _comment, arg) => {
+    expect(isPromiseLike(arg)).toBe(expected);
+  });
+});
diff --git a/detox/test/integration/__snapshots__/timeline-artifact.test.js.snap b/detox/test/integration/__snapshots__/timeline-artifact.test.js.snap
index bacd3353f..022d76c75 100644
--- a/detox/test/integration/__snapshots__/timeline-artifact.test.js.snap
+++ b/detox/test/integration/__snapshots__/timeline-artifact.test.js.snap
@@ -189,8 +189,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
   {
     "args": {
       "functionCode": "async () => {
-    await device.reloadReactNative();
-    await detox.traceCall('Navigate to sanity', element(by.text('Sanity')).tap());
+    await log.trace.complete('Navigate to sanity', navigateToSanity);
   }",
       "level": 10,
       "v": 0,
@@ -202,6 +201,66 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "tid": 1,
     "ts": 13,
   },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Navigate to sanity",
+    "ph": "B",
+    "pid": 1,
+    "tid": 2,
+    "ts": 14,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Reloading app",
+    "ph": "i",
+    "pid": 1,
+    "tid": 2,
+    "ts": 15,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Tap on Sanity",
+    "ph": "i",
+    "pid": 1,
+    "tid": 2,
+    "ts": 16,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "I am on Sanity screen",
+    "ph": "i",
+    "pid": 1,
+    "tid": 2,
+    "ts": 17,
+  },
+  {
+    "args": {
+      "level": 10,
+      "success": true,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "ph": "E",
+    "pid": 1,
+    "tid": 2,
+    "ts": 18,
+  },
   {
     "args": {
       "level": 10,
@@ -212,16 +271,18 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 14,
+    "ts": 19,
   },
   {
     "args": {
       "functionCode": "async () => {
     try {
       detox.trace.startSection('Asserting various texts');
-      await expect(element(by.text('Welcome'))).toBeVisible();
-      await expect(element(by.text('Say Hello'))).toBeVisible();
-      await expect(element(by.text('Say World'))).toBeVisible();
+      await detox.traceCall('by.text()', async () => {
+        await expect(element(by.text('Welcome'))).toBeVisible();
+        await expect(element(by.text('Say Hello'))).toBeVisible();
+        await expect(element(by.text('Say World'))).toBeVisible();
+      });
     } finally {
       detox.trace.endSection('Asserting various texts');
     }
@@ -237,7 +298,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "B",
     "pid": 1,
     "tid": 1,
-    "ts": 15,
+    "ts": 20,
   },
   {
     "args": {
@@ -250,7 +311,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 16,
+    "ts": 21,
   },
   {
     "args": {
@@ -263,7 +324,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 17,
+    "ts": 22,
   },
   {
     "args": {
@@ -275,7 +336,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "i",
     "pid": 1,
     "tid": 1,
-    "ts": 18,
+    "ts": 23,
   },
   {
     "args": {
@@ -286,7 +347,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 19,
+    "ts": 24,
   },
   {
     "args": {
@@ -297,7 +358,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 20,
+    "ts": 25,
   },
   {
     "args": {
@@ -309,7 +370,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "B",
     "pid": 1,
     "tid": 1,
-    "ts": 21,
+    "ts": 26,
   },
   {
     "args": {
@@ -320,7 +381,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 22,
+    "ts": 27,
   },
   {
     "args": {
@@ -332,7 +393,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 1,
     "tid": 1,
-    "ts": 23,
+    "ts": 28,
   },
   {
     "args": {
@@ -346,7 +407,7 @@ exports[`Timeline integration test should deterministically produce a timeline a
     "ph": "E",
     "pid": 0,
     "tid": 0,
-    "ts": 24,
+    "ts": 29,
   },
   {
     "args": {
@@ -362,7 +423,7 @@ Detox CLI is going to restart the test runner with those files...
     "ph": "i",
     "pid": 0,
     "tid": 0,
-    "ts": 25,
+    "ts": 30,
   },
   {
     "args": {
@@ -375,7 +436,7 @@ Detox CLI is going to restart the test runner with those files...
     "ph": "B",
     "pid": 0,
     "tid": 0,
-    "ts": 26,
+    "ts": 31,
   },
   {
     "args": {
@@ -386,8 +447,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "integration/e2e/flaky.test.js",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 27,
+    "tid": 3,
+    "ts": 32,
   },
   {
     "args": {
@@ -398,8 +459,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "set up environment",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 28,
+    "tid": 3,
+    "ts": 33,
   },
   {
     "args": {
@@ -410,8 +471,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 29,
+    "tid": 3,
+    "ts": 34,
   },
   {
     "args": {
@@ -422,8 +483,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "flaky.test.js is assigned to Stub #StubDevice#1",
     "ph": "i",
     "pid": 2,
-    "tid": 2,
-    "ts": 30,
+    "tid": 3,
+    "ts": 35,
   },
   {
     "args": {
@@ -434,8 +495,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "run the tests",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 31,
+    "tid": 3,
+    "ts": 36,
   },
   {
     "args": {
@@ -446,8 +507,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "Flaky",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 32,
+    "tid": 3,
+    "ts": 37,
   },
   {
     "args": {
@@ -462,8 +523,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "should have welcome screen",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 33,
+    "tid": 3,
+    "ts": 38,
   },
   {
     "args": {
@@ -474,8 +535,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "Flaky: should have welcome screen",
     "ph": "i",
     "pid": 2,
-    "tid": 2,
-    "ts": 34,
+    "tid": 3,
+    "ts": 39,
   },
   {
     "args": {
@@ -507,8 +568,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "beforeEach",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 35,
+    "tid": 3,
+    "ts": 40,
   },
   {
     "args": {
@@ -519,14 +580,13 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 36,
+    "tid": 3,
+    "ts": 41,
   },
   {
     "args": {
       "functionCode": "async () => {
-    await device.reloadReactNative();
-    await detox.traceCall('Navigate to sanity', element(by.text('Sanity')).tap());
+    await log.trace.complete('Navigate to sanity', navigateToSanity);
   }",
       "level": 10,
       "v": 0,
@@ -535,8 +595,68 @@ Detox CLI is going to restart the test runner with those files...
     "name": "beforeEach",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 37,
+    "tid": 3,
+    "ts": 42,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Navigate to sanity",
+    "ph": "B",
+    "pid": 2,
+    "tid": 4,
+    "ts": 43,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Reloading app",
+    "ph": "i",
+    "pid": 2,
+    "tid": 4,
+    "ts": 44,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "Tap on Sanity",
+    "ph": "i",
+    "pid": 2,
+    "tid": 4,
+    "ts": 45,
+  },
+  {
+    "args": {
+      "level": 10,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "name": "I am on Sanity screen",
+    "ph": "i",
+    "pid": 2,
+    "tid": 4,
+    "ts": 46,
+  },
+  {
+    "args": {
+      "level": 10,
+      "success": true,
+      "v": 0,
+    },
+    "cat": "user,lifecycle",
+    "ph": "E",
+    "pid": 2,
+    "tid": 4,
+    "ts": 47,
   },
   {
     "args": {
@@ -547,17 +667,19 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 38,
+    "tid": 3,
+    "ts": 48,
   },
   {
     "args": {
       "functionCode": "async () => {
     try {
       detox.trace.startSection('Asserting various texts');
-      await expect(element(by.text('Welcome'))).toBeVisible();
-      await expect(element(by.text('Say Hello'))).toBeVisible();
-      await expect(element(by.text('Say World'))).toBeVisible();
+      await detox.traceCall('by.text()', async () => {
+        await expect(element(by.text('Welcome'))).toBeVisible();
+        await expect(element(by.text('Say Hello'))).toBeVisible();
+        await expect(element(by.text('Say World'))).toBeVisible();
+      });
     } finally {
       detox.trace.endSection('Asserting various texts');
     }
@@ -572,8 +694,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "test_fn",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 39,
+    "tid": 3,
+    "ts": 49,
   },
   {
     "args": {
@@ -584,8 +706,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 40,
+    "tid": 3,
+    "ts": 50,
   },
   {
     "args": {
@@ -596,8 +718,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 41,
+    "tid": 3,
+    "ts": 51,
   },
   {
     "args": {
@@ -608,8 +730,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "Flaky: should have welcome screen [OK]",
     "ph": "i",
     "pid": 2,
-    "tid": 2,
-    "ts": 42,
+    "tid": 3,
+    "ts": 52,
   },
   {
     "args": {
@@ -619,8 +741,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 43,
+    "tid": 3,
+    "ts": 53,
   },
   {
     "args": {
@@ -630,8 +752,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 44,
+    "tid": 3,
+    "ts": 54,
   },
   {
     "args": {
@@ -642,8 +764,8 @@ Detox CLI is going to restart the test runner with those files...
     "name": "tear down environment",
     "ph": "B",
     "pid": 2,
-    "tid": 2,
-    "ts": 45,
+    "tid": 3,
+    "ts": 55,
   },
   {
     "args": {
@@ -653,8 +775,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 46,
+    "tid": 3,
+    "ts": 56,
   },
   {
     "args": {
@@ -665,8 +787,8 @@ Detox CLI is going to restart the test runner with those files...
     "cat": "lifecycle,jest-environment",
     "ph": "E",
     "pid": 2,
-    "tid": 2,
-    "ts": 47,
+    "tid": 3,
+    "ts": 57,
   },
   {
     "args": {
@@ -678,7 +800,7 @@ Detox CLI is going to restart the test runner with those files...
     "ph": "E",
     "pid": 0,
     "tid": 0,
-    "ts": 48,
+    "ts": 58,
   },
   {
     "args": {
@@ -689,7 +811,7 @@ Detox CLI is going to restart the test runner with those files...
     "ph": "E",
     "pid": 0,
     "tid": 0,
-    "ts": 49,
+    "ts": 59,
   },
 ]
 `;
diff --git a/detox/test/integration/e2e/flaky.test.js b/detox/test/integration/e2e/flaky.test.js
index efb336684..90bec721d 100644
--- a/detox/test/integration/e2e/flaky.test.js
+++ b/detox/test/integration/e2e/flaky.test.js
@@ -1,17 +1,19 @@
 const { session } = require('detox/internals');
+const log = detox.log.child({ cat: 'lifecycle' });
 
 describe('Flaky', () => {
   beforeEach(async () => {
-    await device.reloadReactNative();
-    await detox.traceCall('Navigate to sanity', element(by.text('Sanity')).tap());
+    await log.trace.complete('Navigate to sanity', navigateToSanity);
   });
 
   it('should have welcome screen', async () => {
     try {
       detox.trace.startSection('Asserting various texts');
-      await expect(element(by.text('Welcome'))).toBeVisible();
-      await expect(element(by.text('Say Hello'))).toBeVisible();
-      await expect(element(by.text('Say World'))).toBeVisible();
+      await detox.traceCall('by.text()', async () => {
+        await expect(element(by.text('Welcome'))).toBeVisible();
+        await expect(element(by.text('Say Hello'))).toBeVisible();
+        await expect(element(by.text('Say World'))).toBeVisible();
+      });
     } finally {
       detox.trace.endSection('Asserting various texts');
     }
@@ -21,4 +23,11 @@ describe('Flaky', () => {
     }
   });
 
+  async function navigateToSanity() {
+    log.trace('Reloading app');
+    await device.reloadReactNative();
+    log.trace('Tap on Sanity');
+    await element(by.text('Sanity')).tap();
+    log.trace('I am on Sanity screen');
+  }
 });