Repository: wix/Detox
Pull request #1944 (2020-03-05 13:43:48)

Introduce unified custom logger to log user events using bunyan
- [ ] This is a small change 
- [ ] This change has been discussed in issue #<?> and the solution has been agreed upon with maintainers.

---

**Description:**
Introduce a unified logging solution that overrides `console` functions implementation. Goal here is twofold:

1. Wire user logs onto bunyan, such that (in addition to its nice optional features) the log would be associated with the `pid` -- as in parallel-exec envs all user logs are currently scarce without it.
2. Pave way for thus bundling user logs into the timeline trace artefact.

#### Implementation
Initially, the plan was to simply grab the logs as-is and just rewire through bunyan. This turned out to be a bit of a dirty but mostly an imperfect solution - especially in Jest (which already provide a custom logger), which logs the log-origin (which gets broken in this approach) and also log in multiple lines and thus ident to start (which by default overrides the bunyan pid prefix).

Hence, eventually, solution was to introduce a fully blown custom logger. The ends result is pretty nice.


Patch:
diff --git a/detox/src/utils/callsites.js b/detox/src/utils/callsites.js
new file mode 100644
index 000000000..de1fc43e3
--- /dev/null
+++ b/detox/src/utils/callsites.js
@@ -0,0 +1,19 @@
+const path = require('path');
+const cwd = process.cwd() + path.sep;
+
+// Taken from https://github.com/sindresorhus/callsites
+module.exports = () => {
+  const _prepareStackTrace = Error.prepareStackTrace;
+  Error.prepareStackTrace = (_, stack) => stack;
+  const stack = new Error().stack.slice(1);
+  Error.prepareStackTrace = _prepareStackTrace;
+  return stack;
+};
+
+module.exports.stackdump = (endFrame = 0) => {
+  return new Error().stack
+    .split('\n')
+    .slice(2 + endFrame) // 2 = 1 for 'Error:' prefix and 1 for this function's frame
+    .join('\n')
+    .replace(new RegExp(cwd, 'g'), '');
+};
diff --git a/detox/src/utils/customConsoleLogger.js b/detox/src/utils/customConsoleLogger.js
new file mode 100644
index 000000000..a7be782bb
--- /dev/null
+++ b/detox/src/utils/customConsoleLogger.js
@@ -0,0 +1,54 @@
+const util = require('util');
+const path = require('path');
+const callsites = require('./callsites');
+
+const USER_STACK_FRAME_INDEX = 2;
+const CONSOLE_ASSERT_USER_ARGS_INDEX = 1;
+
+function getStackDump() {
+  return callsites.stackdump(USER_STACK_FRAME_INDEX);
+}
+
+function getOrigin() {
+  const userCallsite = callsites()[USER_STACK_FRAME_INDEX];
+  const filename = path.relative(process.cwd(), userCallsite.getFileName());
+  return `at ${filename}:${userCallsite.getLineNumber() || '?'}:${userCallsite.getColumnNumber() || '?'}`;
+}
+
+function override(consoleLevel, bunyanFn) {
+  console[consoleLevel] = (...args) => {
+    bunyanFn({ event: 'USER_LOG' }, getOrigin(), '\n', util.format(...args));
+  };
+}
+
+function overrideTrace(consoleLevel, bunyanFn) {
+  console[consoleLevel] = (...args) => {
+    bunyanFn({ event: 'USER_LOG' }, getOrigin(), '\n  Trace:', util.format(...args), '\n\r' + getStackDump());
+  };
+}
+
+function overrideAssertion(consoleLevel, bunyanFn) {
+  console[consoleLevel] = (...args) => {
+    const [condition] = args;
+    if (!condition) {
+      bunyanFn({ event: 'USER_LOG' }, getOrigin(), '\n  AssertionError:', util.format(...args.slice(CONSOLE_ASSERT_USER_ARGS_INDEX)));
+    }
+  };
+}
+
+function overrideAllLevels(bunyanLogger) {
+  const log = bunyanLogger;
+  override('debug', log.debug.bind(log));
+  override('log', log.info.bind(log));
+  override('warn', log.warn.bind(log));
+  override('error', log.error.bind(log));
+  overrideTrace('trace', log.info.bind(log));
+  overrideAssertion('assert', log.error.bind(log));
+}
+
+module.exports = {
+  override,
+  overrideTrace,
+  overrideAssertion,
+  overrideAllLevels,
+};
diff --git a/detox/src/utils/logger.js b/detox/src/utils/logger.js
index 7929d1807..95cbad4e1 100644
--- a/detox/src/utils/logger.js
+++ b/detox/src/utils/logger.js
@@ -4,6 +4,7 @@ const bunyan = require('bunyan');
 const bunyanDebugStream = require('bunyan-debug-stream');
 const argparse = require('./argparse');
 const temporaryPath = require('../artifacts/utils/temporaryPath');
+const customConsoleLogger = require('./customConsoleLogger');
 
 function adaptLogLevelName(level) {
   switch (level) {
@@ -23,6 +24,11 @@ function adaptLogLevelName(level) {
   }
 }
 
+function overrideConsoleLogger(logger) {
+  const log = logger.child({component: 'USER_LOG'});
+  customConsoleLogger.overrideAllLevels(log);
+}
+
 function createPlainBunyanStream({ logPath, level }) {
   const options = {
     showDate: false,
@@ -97,6 +103,10 @@ function init() {
     logger.plainFileStreamPath = plainFileStreamPath;
   }
 
+  if (argparse.getArgValue('use-custom-logger') === 'true') {
+    overrideConsoleLogger(logger);
+  }
+
   return logger;
 }
 
diff --git a/docs/APIRef.DetoxCLI.md b/docs/APIRef.DetoxCLI.md
index 2c097b531..aba0bebbe 100644
--- a/docs/APIRef.DetoxCLI.md
+++ b/docs/APIRef.DetoxCLI.md
@@ -83,6 +83,7 @@ Initiating your test suite. <sup>[[1]](#notice-passthrough)</sup>
 | --gpu                                         | [Android Only] Launch Emulator with the specific -gpu [gpu mode] parameter. |
 | --device-launch-args | A list of passthrough-arguments to use when (if) devices (Android emulator / iOS simulator) are launched by Detox.<br />**Note: the value must be specified after an equal size (`=`) and inside quotes.** Usage example:<br />`--device-launch-args="-http-proxy http://1.1.1.1:8000 -no-snapshot-load"` |
 | --no-color                                    | Disable colors in log output |
+| --use-custom-logger | Use Detox' custom console-logging implementation, for logging Detox (non-device) logs. Disabling will fallback to node.js / test-runner's implementation (e.g. Jest / Mocha).<br />*Default: true* |
 | --help                                        | Show help |
 
 ##### Notices


Test patch:
diff --git a/detox/local-cli/test.js b/detox/local-cli/test.js
index bba624145..bf19c83a2 100644
--- a/detox/local-cli/test.js
+++ b/detox/local-cli/test.js
@@ -125,7 +125,13 @@ module.exports.builder = {
   'device-launch-args': {
     group: 'Execution:',
     describe: 'Custom arguments to pass (through) onto the device (emulator/simulator) binary when launched.'
-  }
+  },
+  'use-custom-logger': {
+    boolean: true,
+    default: true,
+    group: 'Execution:',
+    describe: `Use Detox' custom console-logging implementation, for logging Detox (non-device) logs. Disabling will fallback to node.js / test-runner's implementation (e.g. Jest / Mocha).`,
+  },
 };
 
 const collectExtraArgs = require('./utils/collectExtraArgs')(module.exports.builder);
@@ -224,6 +230,7 @@ module.exports.handler = async function test(program) {
         (hasCustomValue('record-performance') ? `--record-performance ${program.recordPerformance}` : ''),
         (program.artifactsLocation ? `--artifacts-location "${program.artifactsLocation}"` : ''),
         (program.deviceName ? `--device-name "${program.deviceName}"` : ''),
+        (program.useCustomLogger ? `--use-custom-logger "${program.useCustomLogger}"` : ''),
       ]),
       ...getPassthroughArguments(),
     ]).join(' ');
@@ -284,6 +291,7 @@ module.exports.handler = async function test(program) {
         'reportSpecs',
         'readOnlyEmu',
         'deviceLaunchArgs',
+        'useCustomLogger'
       ]),
       DETOX_START_TIMESTAMP: Date.now(),
     };
diff --git a/detox/src/utils/callsites.test.js b/detox/src/utils/callsites.test.js
new file mode 100644
index 000000000..a96454356
--- /dev/null
+++ b/detox/src/utils/callsites.test.js
@@ -0,0 +1,42 @@
+describe('callsites', () => {
+
+  let callsites;
+  beforeEach(() => {
+    callsites = require('./callsites');
+  });
+
+  describe('call-sites query', () => {
+    const callFromWrapperFn = () => callsites();
+
+    it('should return a query-able callsites array', () => {
+      const [callsite0, callsite1] = callFromWrapperFn();
+
+      expect(callsite0.getFileName()).toEqual(expect.stringContaining('src/utils/callsites.test.js'));
+      expect(callsite0.getFunctionName()).toEqual('callFromWrapperFn');
+      expect(callsite0.isToplevel()).toEqual(true);
+      expect(callsite1.getFunctionName()).toEqual('it');
+      expect(callsite1.isToplevel()).toEqual(false);
+    });
+  });
+
+  describe('stack-dump', () => {
+    const callStackDumpFromWrapperFn = (endFrame) => callsites.stackdump(endFrame);
+    const callStackDumpFromTwoWrapperFn = (endFrame) => callStackDumpFromWrapperFn(endFrame);
+
+    const expectedTopFrameRegExp = /^ {4}at callStackDumpFromWrapperFn \(src\/utils\/callsites\.test\.js:[0-9][0-9]?:[0-9][0-9]?\)/;
+    const expected2ndLineRegExp = /^ {4}at callStackDumpFromTwoWrapperFn \(src\/utils\/callsites\.test\.js:[0-9][0-9]?:[0-9][0-9]?\)/;
+
+    it('should return a valid, multi-line, stack-dump string', () => {
+      const stackdump = callStackDumpFromTwoWrapperFn();
+
+      expect(stackdump).toEqual(expect.stringMatching(expectedTopFrameRegExp));
+      expect(stackdump).toEqual(expect.stringMatching(new RegExp(expected2ndLineRegExp, 'm')));
+    });
+
+    it('should slice according to end-frame arg', () => {
+      const _expectedTopLineRegExp = expected2ndLineRegExp;
+      const stackdump = callStackDumpFromTwoWrapperFn(1);
+      expect(stackdump).toEqual(expect.stringMatching(_expectedTopLineRegExp));
+    });
+  });
+});
diff --git a/detox/src/utils/customConsoleLogger.test.js b/detox/src/utils/customConsoleLogger.test.js
new file mode 100644
index 000000000..d12aa5e64
--- /dev/null
+++ b/detox/src/utils/customConsoleLogger.test.js
@@ -0,0 +1,148 @@
+const ignored = expect.anything;
+
+describe('customConsoleLogger', () => {
+  let bunyanLogger;
+
+  beforeEach(() => {
+    jest.unmock('./callsites');
+
+    bunyanLogger = {
+      mock: jest.fn(),
+    };
+  });
+
+  afterEach(() => {
+    delete console.__log;
+  });
+
+  it('should log an event as the prefix', () => {
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log();
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith({ event: 'USER_LOG' }, ignored(), ignored(), ignored());
+  });
+
+  it('should log multiple args', () => {
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log('Testing123');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), ignored(), ignored(), 'Testing123');
+  });
+
+  it('should support string formatting', () => {
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log('Tada! this %s', 'worx');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), ignored(), ignored(), 'Tada! this worx');
+  });
+
+  it('should include log origin', () => {
+    mockCallsites({file: 'mockfilename', line: 'mocklinenumber', col: 'mockcolnumber'});
+
+    const expectedOrigin = 'mockfilename:mocklinenumber:mockcolnumber';
+
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log('');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), expect.stringContaining(expectedOrigin), ignored(), ignored());
+  });
+
+  it('should use relative file-name rather than absolute in origin', () => {
+    const expectedOrigin = 'at src/utils/customConsoleLogger.test.js:';
+
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log('');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), expect.stringContaining(expectedOrigin), ignored(), ignored());
+  });
+
+  it('should handle missing file line/column in origin', () => {
+    mockCallsites({file: 'mockfilename', line: undefined, col: undefined});
+
+    const logger = require('./customConsoleLogger');
+    logger.override('__log', bunyanLogger.mock);
+    console.__log('');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), expect.stringContaining('mockfilename:?:?'), ignored(), ignored());
+  });
+
+  it('should support assertion logging', () => {
+    const logger = require('./customConsoleLogger');
+    logger.overrideAssertion('__log', bunyanLogger.mock);
+    console.__log(false, 'Testing456');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith({ event: 'USER_LOG' }, ignored(), ignored(), 'Testing456');
+  });
+
+  it('should limit assertion logging to false-conditions', () => {
+    const logger = require('./customConsoleLogger');
+    logger.overrideAssertion('__log', bunyanLogger.mock);
+    console.__log(true, 'Testing456');
+
+    expect(bunyanLogger.mock).not.toHaveBeenCalled();
+  });
+
+  it('should support trace-logging', () => {
+    const logger = require('./customConsoleLogger');
+    logger.overrideTrace('__log', bunyanLogger.mock);
+    console.__log('Testing789');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith({ event: 'USER_LOG' }, ignored(), ignored(), 'Testing789', ignored());
+  });
+
+  it('should log stack-trace dump when trace-logging', () => {
+    mockCallsites();
+    const callsites = require('./callsites');
+    callsites.stackdump = jest.fn().mockReturnValue('mockstack\ntrace');
+
+    const logger = require('./customConsoleLogger');
+    logger.overrideTrace('__log', bunyanLogger.mock);
+    console.__log('');
+
+    expect(bunyanLogger.mock).toHaveBeenCalledWith(ignored(), ignored(), ignored(), ignored(), '\n\rmockstack\ntrace');
+  });
+
+  it('should override all levels', () => {
+    const bunyanLogger = {
+      debug: jest.fn(),
+      info: jest.fn(),
+      warn: jest.fn(),
+      error: jest.fn(),
+    };
+
+    const _console = console;
+
+    try {
+      global.console = {};
+
+      const logger = require('./customConsoleLogger');
+      logger.overrideAllLevels(bunyanLogger);
+
+      expect(console.debug).toEqual(expect.any(Function));
+      expect(console.log).toEqual(expect.any(Function));
+      expect(console.warn).toEqual(expect.any(Function));
+      expect(console.error).toEqual(expect.any(Function));
+      expect(console.trace).toEqual(expect.any(Function));
+      expect(console.assert).toEqual(expect.any(Function));
+    } finally {
+      global.console = _console;
+    }
+  });
+
+  const mockCallsites = (callsite) => {
+    const mockCallsite = mockACallsite(callsite);
+    jest.mock('./callsites', () => jest.fn().mockReturnValue([{}, {}, mockCallsite]));
+  };
+
+  const mockACallsite = ({func, file, line, col} = {}) => ({
+    getFunctionName: jest.fn().mockReturnValue(func || ''),
+    getFileName: jest.fn().mockReturnValue(file || ''),
+    getLineNumber: jest.fn().mockReturnValue(line),
+    getColumnNumber: jest.fn().mockReturnValue(col),
+  });
+});