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 the 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.

Author: michaelsbradleyjr

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",
-    "tmp": "0.1.0"
+    "rimraf": "3.0.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.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);
+    }
 
-    this.writeToFile = async.cargo((tasks, callback) => {
+    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,116 +89,135 @@ 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.writeToFile.push({ prefix: "[error]: ", args }, callback);
+    this.logFunction(args, 'red');
+
+    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) {
     if (!args.length || !(this.shouldLog('warn'))) {
       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.writeToFile.push({ prefix: "[warning]: ", args }, callback);
+    this.logFunction(args, 'yellow');
+
+    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) {
     if (!args.length || !(this.shouldLog('info'))) {
       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.writeToFile.push({ prefix: "[info]: ", args }, callback);
+    this.logFunction(args, 'green');
+
+    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) {
     if (!args.length || !(this.shouldLog('info'))) {
       return;
     }
 
-    let callback = () => {};
-    if (typeof args[args.length - 1] === 'function') {
-      callback = args[args.length - 1];
-      args.splice(args.length - 1, 1);
-    }
+    this.logFunction(args, 'green');
 
-    this.logFunction(...args, 'green');
-    this.writeToFile.push({prefix: "[consoleOnly]: ", 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: "[consoleOnly]" });
   }
 
   debug(...args) {
     if (!args.length || !(this.shouldLog('debug'))) {
       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.writeToFile.push({ prefix: "[debug]: ", args }, callback);
+    this.logFunction(args, null);
+
+    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) {
     if (!args.length || !(this.shouldLog('trace'))) {
       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.writeToFile.push({ prefix: "[trace]: ", args }, callback);
+    this.logFunction(args, null);
+
+    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) {
-    const txt = args[0];
-    if (!txt || !(this.shouldLog('info'))) {
+  dir(obj) {
+    if (!obj || !(this.shouldLog('info'))) {
       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", "dir", obj);
+    this.logFunction(obj, null);
 
-    this.events.emit("log", "dir", txt);
-    this.logFunction(txt, null);
-    this.writeToFile({ prefix: "[dir]: ", 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({ args: obj, origin, prefix: "[dir]" });
   }
 
   shouldLog(level) {
     const logLevels = Object.keys(LogLevels);
     return (logLevels.indexOf(level) <= logLevels.indexOf(this.logLevel));
   }
 }
-