refactor(@embark/core): refactor logger to provide correct origins

Also make a few more revisions:

Revise the "write logs" testing strategy such that it's not necessary for the
logger functions to take an optional callback.

Drop unused `tmp` package from `packages/core/logger` since it's not used in
the tests.

Strip colors before writing to the log file, use a two-space delimiter between
sections of each logged line in the log file, and collapse whitespace in the
message section of each line. These changes make the log file more amenable to
being processed with cli tools such as awk, cut, etc. It's also possible in a
text editor to replace `'  '` with `\t` and then load the file in a spreadsheet,
with each line-section in its own column.

Rearrange the sections of each logged line so that it's easier to read, and
only include the origin if the loglevel is debug or trace.

packages/core/logger/package.json

@@ -49,7 +49,8 @@
     "@babel/runtime-corejs3": "7.8.3",
     "colors": "1.4.0",
     "core-js": "3.6.4",
-    "date-and-time": "0.12.0"
+    "date-and-time": "0.12.0",
+    "fs-extra": "8.1.0"
   },
   "devDependencies": {
     "@babel/core": "7.7.7",
@@ -59,8 +60,7 @@
     "eslint": "6.8.0",
     "jest": "24.9.0",
     "npm-run-all": "4.1.5",
-    "rimraf": "3.0.0",
+    "rimraf": "3.0.0"
-    "tmp": "0.1.0"
   },
   "engines": {
     "node": ">=10.17.0",

packages/core/logger/src/index.js

@@ -1,11 +1,12 @@
 const async = require('async');
 require('colors');
-const fs = require('fs');
+const fs = require('fs-extra');
 const date = require('date-and-time');
 const { escapeHtml } = require('./utils');
 const util = require('util');
 
 const DATE_FORMAT = 'YYYY-MM-DD HH:mm:ss:SSS';
+const DELIM = '  ';
 
 export const LogLevels = {
   error: 'error',
@@ -21,28 +22,45 @@ export class Logger {
     this.logLevel = options.logLevel || 'info';
     this._logFunction = options.logFunction || console.log;
     this.fs = options.fs || fs;
-    this.logFunction = function(...args) {
-      const color = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-      this._logFunction(...args.filter(arg => arg ?? false).map(arg => {
-        if (color) {
-          return typeof arg === 'object' ? util.inspect(arg, 2)[color] : arg[color];
-        }
-        return typeof arg === 'object' ? util.inspect(arg, 2) : arg;
-      }));
-    };
-    this.logFile = options.logFile;
 
-    this.writeToFile = async.cargo((tasks, callback) => {
+    this.logFunction = function(args, color) {
+      args  = Array.isArray(args) ? args : [args];
+      this._logFunction(...(args.filter(arg => arg ?? false).map(arg => {
+        if (typeof arg === 'object') arg = util.inspect(arg, 2);
+        return color ? arg[color] : arg;
+      })));
+    };
+
+    this.logFile = options.logFile;
+    if (this.logFile) {
+      this.fs.ensureFileSync(this.logFile);
+    }
+
+    const isDebugOrTrace = ['debug', 'trace'].includes(this.logLevel);
+    this.isDebugOrTrace = isDebugOrTrace;
+
+    const noop = () => {};
+    this.writeToFile = async.cargo((tasks, callback = noop) => {
       if (!this.logFile) {
         return callback();
       }
       let logs = '';
-      let origin = "[" + ((new Error().stack).split("at ")[3]).trim() + "]";
       tasks.forEach(task => {
-        logs += `[${date.format(new Date(), DATE_FORMAT)}] ${task.prefix} ${task.args}\n`;
+        let message = [].concat(task.args).join(' ').trim();
+        if (!message) return;
+        const dts = `[${date.format(new Date(), DATE_FORMAT)}]`;
+        message = message.replace(/\s+/g, ' ');
+        let origin = '';
+        if (isDebugOrTrace) origin = `${DELIM}${task.origin.match(/^at\s+.*(\(.*\))/)[1] || '(unknown)'}`;
+        const prefix = task.prefix;
+        logs += `${dts}${DELIM}${prefix}${DELIM}${message}${origin}\n`;
       });
-      this.fs.appendFile(this.logFile, `\n${origin} ${logs}`, err => {
+
+      if (!logs) {
+        callback();
+      }
+
+      this.fs.appendFile(this.logFile, logs.stripColors, err => {
         if (err) {
           this.logFunction(`There was an error writing to the log file: ${err}`, 'red');
           return callback(err);
@@ -71,15 +89,18 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
-
     this.events.emit("log", "error", args);
-    this.logFunction(...args, 'red');
+    this.logFunction(args, 'red');
-    this.writeToFile.push({ prefix: "[error]: ", args }, callback);
+
+    let origin;
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[error]" });
   }
 
   warn(...args) {
@@ -87,15 +108,18 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
-
     this.events.emit("log", "warn", args);
-    this.logFunction(...args, 'yellow');
+    this.logFunction(args, 'yellow');
-    this.writeToFile.push({ prefix: "[warning]: ", args }, callback);
+
+    let origin;
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[warn]" });
   }
 
   info(...args) {
@@ -103,15 +127,18 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
-
     this.events.emit("log", "info", args);
-    this.logFunction(...args, 'green');
+    this.logFunction(args, 'green');
-    this.writeToFile.push({ prefix: "[info]: ", args }, callback);
+
+    let origin;
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[info]" });
   }
 
   consoleOnly(...args) {
@@ -119,14 +146,17 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
+    this.logFunction(args, 'green');
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
 
-    this.logFunction(...args, 'green');
+    let origin;
-    this.writeToFile.push({prefix: "[consoleOnly]: ", args }, callback);
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[consoleOnly]" });
   }
 
   debug(...args) {
@@ -134,15 +164,18 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
-
     this.events.emit("log", "debug", args);
-    this.logFunction(...args, null);
+    this.logFunction(args, null);
-    this.writeToFile.push({ prefix: "[debug]: ", args }, callback);
+
+    let origin;
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[debug]" });
   }
 
   trace(...args) {
@@ -150,32 +183,37 @@ export class Logger {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
-
     this.events.emit("log", "trace", args);
-    this.logFunction(...args, null);
+    this.logFunction(args, null);
-    this.writeToFile.push({ prefix: "[trace]: ", args }, callback);
+
+    let origin;
+    if (this.isDebugOrTrace) {
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile.push({ args, origin, prefix: "[trace]" });
   }
 
-  dir(...args) {
+  dir(obj) {
-    const txt = args[0];
+    if (!obj || !(this.shouldLog('info'))) {
-    if (!txt || !(this.shouldLog('info'))) {
       return;
     }
 
-    let callback = () => {};
+    this.events.emit("log", "dir", obj);
-    if (typeof args[args.length - 1] === 'function') {
+    this.logFunction(obj, null);
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
 
-    this.events.emit("log", "dir", txt);
+    let origin;
-    this.logFunction(txt, null);
+    if (this.isDebugOrTrace) {
-    this.writeToFile({ prefix: "[dir]: ", args }, callback);
+      try {
+        const stack = new Error().stack;
+        origin = stack.split('\n')[2].trim();
+      // eslint-disable-next-line no-empty
+      } catch (e) {}
+    }
+    this.writeToFile({ args: obj, origin, prefix: "[dir]" });
   }
 
   shouldLog(level) {
@@ -183,4 +221,3 @@ export class Logger {
     return (logLevels.indexOf(level) <= logLevels.indexOf(this.logLevel));
   }
 }
-

packages/core/logger/test/logger.spec.js

@@ -2,35 +2,49 @@ import assert from 'assert';
 import sinon from 'sinon';
 import * as fs from 'fs';
 import { fakeEmbark } from 'embark-testing';
-import { Logger } from '../src/';
-import tmp from 'tmp';
 
 describe('core/logger', () => {
 
   const { embark, plugins } = fakeEmbark();
 
-  let logger, testLogFn, logFile;
+  let logger, testLogFn, resolve;
+  const logFile = 'embark.log';
 
   const fsMock = {
     logs: {},
     appendFile: (file, content, callback) => {
+      fsMock.logs[file].push(content);
+      if (resolve) resolve();
+      callback();
+    },
+    ensureFileSync: (file) => {
       if (!fsMock.logs[file]) {
         fsMock.logs[file] = [];
       }
-      fsMock.logs[file].push(content);
-      callback();
     }
   };
 
-  beforeEach(() => {
+  let Logger;
-    logFile = tmp.fileSync();
+  beforeAll(() => {
-    fsMock[logFile.name] = [];
+    process.env.FORCE_COLOR = '1';
+    // load the module only after the environment variable is set, otherwise
+    // the colors package will already have been loaded and in CI the result
+    // will be that colors are disabled and tests below will fail
+    ({Logger} = require('../src'));
+  });
 
+  afterAll(() => {
+    delete process.env.FORCE_COLOR;
+  });
+
+  beforeEach(() => {
+    fsMock.logs[logFile] = [];
+    resolve = null;
     testLogFn = sinon.fake();
     logger = new Logger({
       events: embark.events,
+      logFile,
       logFunction: testLogFn,
-      logFile: logFile.name,
       fs: fsMock
     });
   });
@@ -40,37 +54,40 @@ describe('core/logger', () => {
     sinon.restore();
   });
 
-  test('it should use custom log function for logging', () => {
+  test('it should use custom log function for logging', async () => {
+    const promise = new Promise(res => { resolve = res; });
     logger.info('Hello world');
     assert(testLogFn.calledOnce);
+    await promise;
   });
 
-  test('it should inject color encoding based on log method', () => {
+  test('it should inject color encoding based on log method', async () => {
     logger.info('Hello world');
     assert(testLogFn.calledWith('\u001b[32mHello world\u001b[39m'));
     logger.warn('Hello world');
     assert(testLogFn.calledWith('\u001b[33mHello world\u001b[39m'));
+    const promise = new Promise(res => { resolve = res; });
     logger.error('Hello world');
     assert(testLogFn.calledWith('\u001b[31mHello world\u001b[39m'));
+    await promise;
   });
 
-  test('it should write logs to log file', (done) => {
+  test('it should write logs to log file', async () => {
-    const stats = fs.statSync(logFile.name);
+    const promise = new Promise(res => { resolve = res; });
-    logger.info('Some test log', () => {
+    logger.info('Some test log');
-      fsMock.logs[logFile.name].forEach(entry => {
+    await promise;
-        if (entry.indexOf('[info]:  Some test log') > -1) {
+    assert(fsMock.logs[logFile].some(
-          assert.ok(true);
+      entry => entry.includes('[info]  Some test log')
-        }
+    ));
-      });
-      done();
-    });
   });
 
-  test('it should not log if log method level is higher than configured log level', () => {
+  test('it should not log if log method level is higher than configured log level', async () => {
     logger.trace('Hello world');
     // default log level is `info` which is lower than `trace`
     assert.ok(!testLogFn.calledOnce);
+    const promise = new Promise(res => { resolve = res; });
     logger.warn('Test');
     assert.ok(testLogFn.calledOnce);
+    await promise;
   });
 });

yarn.lock

@@ -22286,7 +22286,7 @@ tmp@0.0.33, tmp@^0.0.33:
   dependencies:
     os-tmpdir "~1.0.2"
 
-tmp@0.1.0, tmp@^0.1.0:
+tmp@^0.1.0:
   version "0.1.0"
   resolved "https://registry.yarnpkg.com/tmp/-/tmp-0.1.0.tgz#ee434a4e22543082e294ba6201dcc6eafefa2877"
   integrity sha512-J7Z2K08jbGcdA1kkQpJSqLF6T0tdQqpR2pnSUXsIchbPdTI9v3e85cLW0d6WDhwuAleOV71j2xWs8qMPfK7nKw==