From 5b988ead7a9d3bad426b9026de3c744deae0ad61 Mon Sep 17 00:00:00 2001 From: "Michael Bradley, Jr" Date: Tue, 28 Jan 2020 19:00:23 -0600 Subject: [PATCH] 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 | 6 +- packages/core/logger/src/index.js | 187 ++++++++++++++--------- packages/core/logger/test/logger.spec.js | 61 +++++--- yarn.lock | 2 +- 4 files changed, 155 insertions(+), 101 deletions(-) diff --git a/packages/core/logger/package.json b/packages/core/logger/package.json index 452adc457..6885c16db 100644 --- a/packages/core/logger/package.json +++ b/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", diff --git a/packages/core/logger/src/index.js b/packages/core/logger/src/index.js index 211989330..e49d5e218 100644 --- a/packages/core/logger/src/index.js +++ b/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.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) { @@ -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.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) { @@ -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.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) { @@ -119,14 +146,17 @@ 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.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) { @@ -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.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) { @@ -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.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) { @@ -183,4 +221,3 @@ export class Logger { return (logLevels.indexOf(level) <= logLevels.indexOf(this.logLevel)); } } - diff --git a/packages/core/logger/test/logger.spec.js b/packages/core/logger/test/logger.spec.js index 8aa645b72..11ee3bee3 100644 --- a/packages/core/logger/test/logger.spec.js +++ b/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(() => { - logFile = tmp.fileSync(); - fsMock[logFile.name] = []; + let Logger; + beforeAll(() => { + 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) => { - const stats = fs.statSync(logFile.name); - logger.info('Some test log', () => { - fsMock.logs[logFile.name].forEach(entry => { - if (entry.indexOf('[info]: Some test log') > -1) { - assert.ok(true); - } - }); - done(); - }); + test('it should write logs to log file', async () => { + const promise = new Promise(res => { resolve = res; }); + logger.info('Some test log'); + await promise; + assert(fsMock.logs[logFile].some( + entry => entry.includes('[info] Some test log') + )); }); - 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; }); }); diff --git a/yarn.lock b/yarn.lock index 191011c5d..6c2a13978 100644 --- a/yarn.lock +++ b/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==