Repository: wix/Detox
Pull request #1453 (2019-06-16 12:37:12)

Increase log-level for result of 'adb devices' command
- [x] This is a small change 
- [x] This change has been discussed in issue #1427 and the solution has been agreed upon with maintainers.

---

**Description:**

Since we don't know what the root cause is for the sporadic failures of #1427, for now we'll have to settle on getting more info. With this PR, we'll `debug`-log the result of each `adb devices` instead of just `trace`-ing it. This will give us high visibility the next time this happens.


Patch:
diff --git a/detox/src/devices/android/ADB.js b/detox/src/devices/android/ADB.js
index 0e9393cf6..1f0b6cd17 100644
--- a/detox/src/devices/android/ADB.js
+++ b/detox/src/devices/android/ADB.js
@@ -13,7 +13,7 @@ class ADB {
   }
 
   async devices() {
-    const output = (await this.adbCmd('', 'devices')).stdout;
+    const output = (await this.adbCmd('', 'devices', { verbosity: 'high' })).stdout;
     return this.parseAdbDevicesConsoleOutput(output);
   }
 
diff --git a/detox/src/devices/ios/AppleSimUtils.js b/detox/src/devices/ios/AppleSimUtils.js
index 765de74b3..bbd757f7d 100644
--- a/detox/src/devices/ios/AppleSimUtils.js
+++ b/detox/src/devices/ios/AppleSimUtils.js
@@ -219,7 +219,8 @@ class AppleSimUtils {
   }
 
   async _execSimctl({ cmd, statusLogs = {}, retries = 1, silent = false }) {
-    return await exec.execWithRetriesAndLogs(`/usr/bin/xcrun simctl ${cmd}`, { silent }, statusLogs, retries);
+    const verbosity = silent ? 'low' : 'normal';
+    return await exec.execWithRetriesAndLogs(`/usr/bin/xcrun simctl ${cmd}`, { verbosity }, statusLogs, retries);
   }
 
   _parseResponseFromAppleSimUtils(response) {
diff --git a/detox/src/utils/exec.js b/detox/src/utils/exec.js
index 1d23333e2..47581a3db 100644
--- a/detox/src/utils/exec.js
+++ b/detox/src/utils/exec.js
@@ -12,6 +12,7 @@ async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 10, in
   const cmd = _composeCommand(bin, options);
   const execTimeout = _.get(options, 'timeout', 0);
   const log = execLogger.child({ fn: 'execWithRetriesAndLogs', cmd, trackingId });
+  const verbosity = _.get(options, 'verbosity', 'normal');
   log.debug({ event: 'EXEC_CMD' }, `${cmd}`);
 
   let result;
@@ -28,8 +29,7 @@ async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 10, in
       ? `timeout = ${execTimeout}ms`
       : `code = ${err.code}`;
 
-    const silent = _.get(options, 'silent', false);
-    const level = silent ? 'debug' : 'error';
+    const level = (verbosity === 'low' ? 'debug' : 'error');
 
     log[level]({ event: 'EXEC_FAIL' }, `"${cmd}" failed with ${_failReason}, stdout and stderr:\n`);
     log[level]({ event: 'EXEC_FAIL', stdout: true }, err.stdout);
@@ -43,7 +43,7 @@ async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 10, in
     throw new DetoxRuntimeError(`command ${cmd} returned undefined`);
   }
 
-  _logExecOutput(log, result);
+  _logExecOutput(log, result, verbosity === 'high' ? 'debug' : 'trace');
 
   if (statusLogs && statusLogs.successful) {
     log.debug({ event: 'EXEC_SUCCESS' }, statusLogs.successful);
@@ -66,7 +66,7 @@ async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 10, in
 }
 
 /* istanbul ignore next */
-function _logExecOutput(log, process) {
+function _logExecOutput(log, process, level) {
   let stdout = process.stdout || '';
   let stderr = process.stderr || '';
 
@@ -76,15 +76,15 @@ function _logExecOutput(log, process) {
   }
 
   if (stdout) {
-    log.trace({ event: 'EXEC_SUCCESS', stdout: true }, stdout);
+    log[level]({ event: 'EXEC_SUCCESS', stdout: true }, stdout);
   }
 
   if (stderr) {
-    log.trace({ event: 'EXEC_SUCCESS', stderr: true }, stderr);
+    log[level]({ event: 'EXEC_SUCCESS', stderr: true }, stderr);
   }
 
   if (!stdout && !stderr) {
-    log.trace({ event: 'EXEC_SUCCESS' }, '');
+    log[level]({ event: 'EXEC_SUCCESS' }, '');
   }
 }
 


Test patch:
diff --git a/detox/src/devices/android/ADB.test.js b/detox/src/devices/android/ADB.test.js
index 964244c6f..4759e7987 100644
--- a/detox/src/devices/android/ADB.test.js
+++ b/detox/src/devices/android/ADB.test.js
@@ -1,4 +1,6 @@
 describe('ADB', () => {
+  const mockAndroidSDKPath = '/Android/sdk-mock';
+
   let ADB;
   let adb;
   let EmulatorTelnet;
@@ -7,7 +9,7 @@ describe('ADB', () => {
   beforeEach(() => {
     jest.mock('../../utils/logger');
     jest.mock('../../utils/environment', () => ({
-      getAndroidSDKPath: () => '/dev/null',
+      getAndroidSDKPath: () => mockAndroidSDKPath,
     }));
 
     jest.mock('./EmulatorTelnet');
@@ -27,6 +29,7 @@ describe('ADB', () => {
 
   it(`devices`, async () => {
     await adb.devices();
+    expect(exec).toHaveBeenCalledWith(`${mockAndroidSDKPath}/platform-tools/adb  devices`, { verbosity: 'high' }, undefined, 1);
     expect(exec).toHaveBeenCalledTimes(1);
   });
 
diff --git a/detox/src/utils/__snapshots__/exec.test.js.snap b/detox/src/utils/__snapshots__/exec.test.js.snap
index ca0c275f5..e984f8f46 100644
--- a/detox/src/utils/__snapshots__/exec.test.js.snap
+++ b/detox/src/utils/__snapshots__/exec.test.js.snap
@@ -26,13 +26,19 @@ Array [
 ]
 `;
 
-exports[`exec exec command and fail with timeout 1`] = `
+exports[`exec exec command and fail with error code, report only to debug log if verbosity is low 1`] = `
 Array [
+  Array [
+    Object {
+      "event": "EXEC_CMD",
+    },
+    "bin",
+  ],
   Array [
     Object {
       "event": "EXEC_FAIL",
     },
-    "\\"bin\\" failed with timeout = 1ms, stdout and stderr:
+    "\\"bin\\" failed with code = undefined, stdout and stderr:
 ",
   ],
   Array [
@@ -52,19 +58,13 @@ Array [
 ]
 `;
 
-exports[`exec exec command and silently fail with error code, report only to debug log 1`] = `
+exports[`exec exec command and fail with timeout 1`] = `
 Array [
-  Array [
-    Object {
-      "event": "EXEC_CMD",
-    },
-    "bin",
-  ],
   Array [
     Object {
       "event": "EXEC_FAIL",
     },
-    "\\"bin\\" failed with code = undefined, stdout and stderr:
+    "\\"bin\\" failed with timeout = 1ms, stdout and stderr:
 ",
   ],
   Array [
diff --git a/detox/src/utils/exec.test.js b/detox/src/utils/exec.test.js
index ff277a1be..190f8609b 100644
--- a/detox/src/utils/exec.test.js
+++ b/detox/src/utils/exec.test.js
@@ -61,6 +61,37 @@ describe('exec', () => {
     expect(cpp.exec).toHaveBeenCalledWith(`bin --argument 123`, { timeout: 0 });
   });
 
+  it(`exec command should output success and err logs`, async () => {
+    mockCppSuccessful(cpp);
+    await exec.execWithRetriesAndLogs('bin');
+
+    expect(logger.trace).toHaveBeenCalledWith({ event: 'EXEC_SUCCESS', stdout: true }, '"successful result"');
+    expect(logger.trace).toHaveBeenCalledWith({ event: 'EXEC_SUCCESS', stderr: true }, 'err');
+  });
+
+  it(`exec command should output a plain success if no output was made`, async () => {
+    const cppResult = {
+      childProcess: {
+        exitCode: 0
+      }
+    };
+    cpp.exec.mockReturnValueOnce(Promise.resolve(cppResult));
+
+    await exec.execWithRetriesAndLogs('bin');
+
+    expect(logger.trace).toHaveBeenCalledWith({ event: 'EXEC_SUCCESS' }, '');
+    expect(logger.trace).toHaveBeenCalledTimes(1);
+  });
+
+  it(`exec command should output success with high severity if verbosity set to high`, async () => {
+    mockCppSuccessful(cpp);
+    await exec.execWithRetriesAndLogs('bin', { verbosity: 'high' });
+
+    expect(logger.debug).toHaveBeenCalledWith({ event: 'EXEC_SUCCESS', stdout: true }, '"successful result"');
+    expect(logger.debug).toHaveBeenCalledWith({ event: 'EXEC_SUCCESS', stderr: true }, 'err');
+    expect(logger.trace).not.toHaveBeenCalledWith(expect.objectContaining({event: 'EXEC_SUCCESS'}), expect.anything());
+  });
+
   it(`exec command with undefined return should throw`, async () => {
     cpp.exec.mockReturnValueOnce(undefined);
     try {
@@ -85,13 +116,13 @@ describe('exec', () => {
     }
   });
 
-  it(`exec command and silently fail with error code, report only to debug log`, async () => {
+  it(`exec command and fail with error code, report only to debug log if verbosity is low`, async () => {
     const errorResult = returnErrorWithValue('error result');
     const rejectedPromise = Promise.reject(errorResult);
     cpp.exec.mockReturnValueOnce(rejectedPromise);
 
     try {
-      await exec.execWithRetriesAndLogs('bin', { silent: true }, '', 1, 1);
+      await exec.execWithRetriesAndLogs('bin', { verbosity: 'low' }, '', 1, 1);
       fail('expected execWithRetriesAndLogs() to throw');
     } catch (object) {
       expect(cpp.exec).toHaveBeenCalledWith(`bin`, { timeout: 0 });