[WIP] Provide queryable console logs in Detox (wix#835)

* deps: switched from npmlog to bunyan, bunyan-debug-stream * feat: detox writes plain text and json logs to artifacts folder if recording logs is enabled * fix: missing parts of logging messages in Jest log * npm: merging detox-server and detox-common into detox package * ci: force exit e2e test if failed on beforeAll * ci: added Android artifacts integrity check on Jenkins * cli: added no-color flag * cli: adding deprecated warning for the old log level names * docs: updated detox server mentions
metinkiperr · Jul 25, 2018 · 78575f0 · 78575f0
1 parent dff3082
commit 78575f0
Show file tree

Hide file tree

Showing 72 changed files with 1,132 additions and 507 deletions.
diff --git a/.gitignore b/.gitignore
@@ -212,7 +212,6 @@ detox/ios/DetoxBuild
 Detox.framework.tbz
 Detox-ios-src.tbz
 
-detox-server/lib
 demo-native-ios/Build
 detox/DetoxBuild
 examples/demo-native-ios/Build

diff --git a/detox-server/.gitignore b/detox-server/.gitignore
diff --git a/detox-server/README.md b/detox-server/README.md
diff --git a/detox-server/package.json b/detox-server/package.json
diff --git a/detox-server/src/cli.js b/detox-server/src/cli.js
diff --git a/detox-server/src/index.js b/detox-server/src/index.js
diff --git a/detox/local-cli/detox-init.js b/detox/local-cli/detox-init.js
@@ -1,10 +1,10 @@
 const _ = require("lodash");
-const log = require("npmlog");
 const fs = require("fs");
 const path = require("path");
 const program = require("commander");
 const mochaTemplates = require("./templates/mocha");
 const jestTemplates = require("./templates/jest");
+const log = require("../src/utils/logger");
 
 const PREFIX = "detox-init";
 

diff --git a/detox/local-cli/detox-run-server.js b/detox/local-cli/detox-run-server.js
@@ -1,12 +1,31 @@
 #!/usr/bin/env node
 
 const program = require('commander');
-const cp = require('child_process');
-const path = require('path');
+const DetoxServer = require('../src/server/DetoxServer');
+const logger = require('../src/utils/logger');
 
-program.parse(process.argv);
+program
+  .name('detox run-server')
+  .description('Start a standalone Detox server')
+  .option(
+    '-p, --port [port]',
+    'Port number',
+    '8099'
+  )
+  .option('-l, --loglevel [value]',
+    'Log level: fatal, error, warn, info, debug, trace', 'info')
+  .option(
+    '--no-color',
+    'Disable colorful logs',
+    false
+  )
+  .parse(process.argv);
 
-const serverPackagePath = require.resolve('detox-server/package.json');
-const cli = require(serverPackagePath).bin['detox-server'];
-const binPath = path.join(path.dirname(serverPackagePath), cli);
-cp.execFileSync('node', [binPath], {stdio: 'inherit'});
+if (program.port < 1 || program.port > 65535) {
+  program.help();
+}
+
+const detoxServer = new DetoxServer({
+  port: +program.port,
+  log: logger,
+});
diff --git a/detox/local-cli/detox-test.js b/detox/local-cli/detox-test.js
@@ -16,7 +16,9 @@ program
   .option('-s, --specs [relativePath]',
     `Root of test folder`)
   .option('-l, --loglevel [value]',
-    'info, debug, verbose, silly, wss')
+    'Log level: fatal, error, warn, info, debug, trace')
+  .option('--no-color',
+    'Disable colors in log output')
   .option('-c, --configuration [device configuration]',
     'Select a device configuration from your defined configurations, if not supplied, and there\'s only one configuration, detox will default to it', getDefaultConfiguration())
   .option('-r, --reuse',
@@ -112,11 +114,12 @@ function runMocha() {
   const screenshots = program.takeScreenshots ? `--take-screenshots ${program.takeScreenshots}` : '';
   const videos = program.recordVideos ? `--record-videos ${program.recordVideos}` : '';
   const headless = program.headless ? `--headless` : '';
+  const color = program.color ? '' : '--no-colors';
 
   const debugSynchronization = program.debugSynchronization ? `--debug-synchronization ${program.debugSynchronization}` : '';
   const binPath = path.join('node_modules', '.bin', 'mocha');
-  const command = `${binPath} ${testFolder} ${configFile} ${configuration} ${loglevel} ${cleanup} ` +
-    `${reuse} ${debugSynchronization} ${platformString} ${headless} ` +
+  const command = `${binPath} ${testFolder} ${configFile} ${configuration} ${loglevel} ${color} ` +
+    `${cleanup} ${reuse} ${debugSynchronization} ${platformString} ${headless} ` +
     `${logs} ${screenshots} ${videos} ${artifactsLocation}`;
 
   console.log(command);
@@ -128,7 +131,8 @@ function runJest() {
 
   const platformString = platform ? shellQuote(`--testNamePattern=^((?!${getPlatformSpecificString(platform)}).)*$`) : '';
   const binPath = path.join('node_modules', '.bin', 'jest');
-  const command = `${binPath} ${testFolder} ${configFile} --maxWorkers=${program.workers} ${platformString}`;
+  const color = program.color ? '' : ' --no-color';
+  const command = `${binPath} ${testFolder} ${configFile}${color} --maxWorkers=${program.workers} ${platformString}`;
   const detoxEnvironmentVariables = {
     configuration: program.configuration,
     loglevel: program.loglevel,

diff --git a/detox/package.json b/detox/package.json
@@ -38,15 +38,15 @@
     "prettier": "1.7.0"
   },
   "dependencies": {
+    "bunyan": "^1.8.12",
+    "bunyan-debug-stream": "^1.1.0",
     "child-process-promise": "^2.2.0",
     "commander": "^2.15.1",
-    "detox-server": "^7.0.0",
     "fs-extra": "^4.0.2",
     "get-port": "^2.1.0",
     "ini": "^1.3.4",
     "lodash": "^4.17.5",
     "minimist": "^1.2.0",
-    "npmlog": "^4.0.2",
     "proper-lockfile": "^3.0.2",
     "shell-utils": "^1.0.9",
     "tail": "^1.2.3",
@@ -67,12 +67,14 @@
       "src/artifacts/log",
       "src/artifacts/screenshot",
       "src/artifacts/video",
+      "src/server/DetoxServer.js",
       ".*Driver.js",
       "EmulatorTelnet.js",
       "Emulator.js",
       "DeviceDriverBase.js",
       "GREYConfiguration.js",
       "src/utils/environment.js",
+      "src/utils/logger.js",
       "src/utils/onTerminate.js",
       "src/utils/sleep.js",
       "AAPT.js",

diff --git a/detox/src/Detox.js b/detox/src/Detox.js
@@ -1,4 +1,6 @@
-const log = require('npmlog');
+const _ = require('lodash');
+const logger = require('./utils/logger');
+const log = require('./utils/logger').child({ __filename });
 const Device = require('./devices/Device');
 const IosDriver = require('./devices/IosDriver');
 const SimulatorDriver = require('./devices/SimulatorDriver');
@@ -8,15 +10,10 @@ const DetoxRuntimeError = require('./errors/DetoxRuntimeError');
 const argparse = require('./utils/argparse');
 const configuration = require('./configuration');
 const Client = require('./client/Client');
-const DetoxServer = require('detox-server');
+const DetoxServer = require('./server/DetoxServer');
 const URL = require('url').URL;
-const _ = require('lodash');
 const ArtifactsManager = require('./artifacts/ArtifactsManager');
 
-log.level = argparse.getArgValue('loglevel') || 'info';
-log.addLevel('wss', 999, {fg: 'blue', bg: 'black'}, 'wss');
-log.heading = 'detox';
-
 const DEVICE_CLASSES = {
   'ios.simulator': SimulatorDriver,
   'ios.none': IosDriver,
@@ -35,11 +32,17 @@ class Detox {
 
   async init(userParams) {
     const sessionConfig = await this._getSessionConfig();
-    const defaultParams = {launchApp: true, initGlobals: true};
-    const params = Object.assign(defaultParams, userParams || {});
+    const params = {
+      launchApp: true,
+      initGlobals: true,
+      ...userParams,
+    };
 
     if (!this.userSession) {
-      this.server = new DetoxServer(new URL(sessionConfig.server).port);
+      this.server = new DetoxServer({
+        log: logger,
+        port: new URL(sessionConfig.server).port,
+      });
     }
 
     this.client = new Client(sessionConfig);
@@ -94,16 +97,22 @@ class Detox {
 
   async beforeEach(testSummary) {
     this._validateTestSummary(testSummary);
+    this._logTestRunCheckpoint('DETOX_BEFORE_EACH', testSummary);
     await this._handleAppCrashIfAny(testSummary.fullName);
     await this.artifactsManager.onBeforeEach(testSummary);
   }
 
   async afterEach(testSummary) {
     this._validateTestSummary(testSummary);
+    this._logTestRunCheckpoint('DETOX_AFTER_EACH', testSummary);
     await this.artifactsManager.onAfterEach(testSummary);
     await this._handleAppCrashIfAny(testSummary.fullName);
   }
 
+  _logTestRunCheckpoint(event, { status, fullName }) {
+    log.trace({ event, status }, `${status} test: ${JSON.stringify(fullName)}`);
+  }
+
   _validateTestSummary(testSummary) {
     if (!_.isPlainObject(testSummary)) {
       throw new DetoxRuntimeError({
@@ -134,7 +143,7 @@ class Detox {
     const pendingAppCrash = this.client.getPendingCrashAndReset();
 
     if (pendingAppCrash) {
-      log.error('', `App crashed in test '${testName}', here's the native stack trace: \n${pendingAppCrash}`);
+      log.error({ event: 'APP_CRASH' }, `App crashed in test '${testName}', here's the native stack trace: \n${pendingAppCrash}`);
       await this.device.launchApp({ newInstance: true });
     }
   }

diff --git a/detox/src/Detox.test.js b/detox/src/Detox.test.js
@@ -42,7 +42,7 @@ describe('Detox', () => {
       jest.setMock(modulePath, FinalMock);
     }
 
-    jest.mock('npmlog');
+    jest.mock('./utils/logger');
     jest.mock('fs');
     jest.mock('fs-extra');
     fs = require('fs');
@@ -57,7 +57,7 @@ describe('Detox', () => {
     jest.mock('./devices/IosDriver');
     jest.mock('./devices/SimulatorDriver');
     jest.mock('./devices/Device');
-    jest.mock('detox-server');
+    jest.mock('./server/DetoxServer');
     jest.mock('./client/Client');
   });
 

diff --git a/detox/src/artifacts/ArtifactsManager.js b/detox/src/artifacts/ArtifactsManager.js
@@ -1,9 +1,8 @@
 const _ = require('lodash');
 const fs = require('fs-extra');
 const path = require('path');
-const log = require('npmlog');
+const log = require('../utils/logger').child({ __filename });
 const argparse = require('../utils/argparse');
-const logError = require('../utils/logError');
 const DetoxRuntimeError = require('../errors/DetoxRuntimeError');
 const ArtifactPathBuilder = require('./utils/ArtifactPathBuilder');
 
@@ -117,18 +116,20 @@ class ArtifactsManager {
     device.off('launchApp', this.onLaunchApp);
   }
 
-  async onBeforeLaunchApp({ deviceId, bundleId }) {
+  async onBeforeLaunchApp(launchInfo) {
+    const { deviceId, bundleId } = launchInfo;
     const isFirstTime = !this._deviceId;
 
     this._deviceId = deviceId;
     this._bundleId = bundleId;
 
     return isFirstTime
-      ? this._onBeforeLaunchAppFirstTime()
-      : this._onBeforeRelaunchApp({ deviceId, bundleId });
+      ? this._onBeforeLaunchAppFirstTime(launchInfo)
+      : this._onBeforeRelaunchApp();
   }
 
-  async _onBeforeLaunchAppFirstTime() {
+  async _onBeforeLaunchAppFirstTime(launchInfo) {
+    log.trace({ event: 'LIFECYCLE', fn: 'onBeforeLaunchApp' }, 'onBeforeLaunchApp', launchInfo);
     this._artifactPlugins = this._instantiateArtifactPlugins();
   }
 
@@ -145,9 +146,13 @@ class ArtifactsManager {
     }]);
   }
 
-  async onLaunchApp({ deviceId, bundleId, pid }) {
+  async onLaunchApp(launchInfo) {
     const isFirstTime = isNaN(this._pid);
+    if (isFirstTime) {
+      log.trace({ event: 'LIFECYCLE', fn: 'onLaunchApp' }, 'onLaunchApp', launchInfo);
+    }
 
+    const { deviceId, bundleId, pid } = launchInfo;
     this._deviceId = deviceId;
     this._bundleId = bundleId;
     this._pid = pid;
@@ -180,26 +185,29 @@ class ArtifactsManager {
   async onAfterAll() {
     await this._emit('onAfterAll', []);
     await this._idlePromise;
-    log.verbose('ArtifactsManager', 'finalized artifacts successfully');
   }
 
   async onTerminate() {
     if (this._artifactPlugins.length === 0) {
       return;
     }
 
-    log.info('ArtifactsManager', 'finalizing all artifacts, this can take some time');
+    log.info({ event: 'TERMINATE_START' }, 'finalizing the recorded artifacts, this can take some time...');
+
     await this._emit('onTerminate', []);
     await Promise.all(this._onIdleCallbacks.splice(0).map(this._executeIdleCallback));
     await this._idlePromise;
 
     await Promise.all(this._activeArtifacts.map(artifact => artifact.discard()));
     await this._idlePromise;
     this._artifactPlugins.splice(0);
-    log.info('ArtifactsManager', 'finalized all artifacts');
+
+    log.info({ event: 'TERMINATE_SUCCESS' }, 'done.');
   }
 
   async _emit(methodName, args) {
+    log.trace(Object.assign({ event: 'LIFECYCLE', fn: methodName }, ...args), `${methodName}`);
+
     await Promise.all(this._artifactPlugins.map(async (plugin) => {
       try {
         await plugin[methodName](...args);
@@ -209,9 +217,9 @@ class ArtifactsManager {
     }));
   }
 
-  _errorHandler(e, { plugin, methodName }) {
-    log.error('ArtifactsManager', 'Caught exception inside plugin (%s) at phase %s', plugin.name || 'unknown', methodName);
-    logError(e, 'ArtifactsManager');
+  _errorHandler(err, { plugin, methodName }) {
+    const eventObject = { event: 'PLUGIN_ERROR', plugin: plugin.name || 'unknown', methodName, err };
+    log.error(eventObject, `Caught exception inside plugin (${eventObject.plugin}) at phase ${methodName}`);
   }
 
   _idleCallbackErrorHandle(e, callback) {