From 697260ad7f1100b9a4d4de5a3d352b73cc7667ca Mon Sep 17 00:00:00 2001 From: Tobias Bocanegra Date: Wed, 24 Jul 2019 12:00:15 +0900 Subject: [PATCH] fix(logger): export Logger again to keep module backward compatible (#138) --- package.json | 2 +- src/HelixConfig.js | 10 ++ src/Logger.js | 185 ++++++++++++++++++++ src/index.js | 2 + src/log.js | 4 +- test/config.test.js | 45 ++++- test/log.test.js | 23 ++- test/logger.test.js | 208 +++++++++++++++++++++++ test/specs/configs/full-canonical.yaml | 224 +++++++++++++++++++++++++ 9 files changed, 698 insertions(+), 5 deletions(-) create mode 100644 src/Logger.js create mode 100644 test/logger.test.js create mode 100644 test/specs/configs/full-canonical.yaml diff --git a/package.json b/package.json index c9fa1ac5..7e9bc458 100644 --- a/package.json +++ b/package.json @@ -6,7 +6,7 @@ "scripts": { "semantic-release": "semantic-release", "docs": "npx jsonschema2md -d src/schemas -o docs && npx jsdoc2md -c .jsdoc.json --files src/*.js > docs/API.md", - "test": "nyc --reporter=text --reporter=lcov --check-coverage --branches 96 --statements 97 --lines 97 mocha", + "test": "nyc --reporter=text --reporter=lcov --check-coverage --branches 95 --statements 98 --lines 99 mocha", "lint": "./node_modules/.bin/eslint .", "junit": "mocha --exit -R mocha-junit-reporter", "snyk-protect": "snyk protect", diff --git a/src/HelixConfig.js b/src/HelixConfig.js index 334b5bdb..407c2e7f 100644 --- a/src/HelixConfig.js +++ b/src/HelixConfig.js @@ -38,6 +38,7 @@ class HelixConfig { this._source = ''; this._cfg = null; this._document = null; + this._logger = console; this._version = ''; this._strains = new Strains(); } @@ -57,6 +58,11 @@ class HelixConfig { return this; } + withLogger(logger) { + this._logger = logger; + return this; + } + withDirectory(cwd) { this._cwd = cwd; return this; @@ -120,6 +126,10 @@ class HelixConfig { return this._strains; } + get log() { + return this._logger; + } + async hasFile() { return isFile(this.configPath); } diff --git a/src/Logger.js b/src/Logger.js new file mode 100644 index 00000000..51756d62 --- /dev/null +++ b/src/Logger.js @@ -0,0 +1,185 @@ +/* + * Copyright 2018 Adobe. All rights reserved. + * This file is licensed to you under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. You may obtain a copy + * of the License at http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software distributed under + * the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS + * OF ANY KIND, either express or implied. See the License for the specific language + * governing permissions and limitations under the License. + */ + +'use strict'; + +const path = require('path'); +const stream = require('stream'); +const uuidv4 = require('uuid/v4'); +const winston = require('winston'); +const fs = require('fs-extra'); +const { MESSAGE, LEVEL } = require('triple-beam'); + +const ANSI_REGEXP = RegExp([ + '[\\u001B\\u009B][[\\]()#;?]*(?:(?:(?:[a-zA-Z\\d]*(?:;[a-zA-Z\\d]*)*)?\\u0007)', + '(?:(?:\\d{1,4}(?:;\\d{0,4})*)?[\\dA-PRZcf-ntqry=><~]))', +].join('|'), 'g'); + + +const MY_LEVELS = { + levels: { + error: 0, + warn: 1, + info: 2, + verbose: 3, + debug: 4, + silly: 5, + }, + colors: { + // use default colors + }, +}; + +/** + * Winston format that suppresses messages when the `info.progress` is `true` and console._stdout + * is a TTY. This is used to log steps during a progress meter. + */ +const progressFormat = winston.format((info) => { + // eslint-disable-next-line no-underscore-dangle,no-console + if (info.progress && console._stdout.isTTY) { + return false; + } + return info; +}); + +/** + * Winston format that is used for a command line application where `info` messages are rendered + * without level. + */ +const commandLineFormat = winston.format((info) => { + if (info[LEVEL] === 'info') { + // eslint-disable-next-line no-param-reassign + info[MESSAGE] = `${info.message}`; + } else { + // eslint-disable-next-line no-param-reassign + info[MESSAGE] = `${info.level}: ${info.message}`; + } + return info; +}); + + +function getLogger(config) { + let categ; + if (typeof config === 'string') { + categ = config; + } else { + categ = (config && config.category) || 'hlx'; + } + + if (winston.loggers.has(categ)) { + return winston.loggers.get(categ); + } + + const level = (config && config.level) || (this && this.level) || 'info'; + const logsDir = path.normalize((config && config.logsDir) || 'logs'); + + const logFiles = config && Array.isArray(config.logFile) + ? config.logFile + : ['-', (config && config.logFile) || path.join(logsDir, `${categ}-server.log`)]; + + const transports = []; + logFiles.forEach((logFile) => { + if (logFile === '-') { + const formats = []; + if (categ === 'cli') { + formats.push(progressFormat()); + formats.push(winston.format.colorize()); + formats.push(commandLineFormat()); + } else { + formats.push(winston.format.colorize()); + formats.push(winston.format.printf(info => `[${categ}] ${info.level}: ${info.message}`)); + } + transports.push(new winston.transports.Console({ + level, + format: winston.format.combine(...formats), + })); + } else { + fs.ensureDirSync(path.dirname(logFile)); + + const formats = [winston.format.timestamp()]; + if (/\.json/.test(logFile)) { + formats.push(winston.format.logstash()); + } else { + formats.push(winston.format.printf(info => `${info.timestamp} ${info.level}: ${info.message}`)); + } + + transports.push(new winston.transports.File({ + level: 'debug', + filename: logFile, + format: winston.format.combine(...formats), + })); + } + }); + + const logger = winston.loggers.add(categ, { + level, + levels: MY_LEVELS.levels, + transports, + }); + logger.getLogger = getLogger.bind(logger); + winston.addColors(MY_LEVELS.colors); + return logger; +} + +/** + * Creates a test logger that logs to the console but also to an internal buffer. The contents of + * the buffer can be retrieved with {@code Logger#getOutput()} which will flush also close the + * logger. Each test logger will be registered with a unique category, so that there is no risk of + * reusing a logger in between tests. + * @returns {winston.Logger} + */ +function getTestLogger(config = {}) { + class StringStream extends stream.Writable { + constructor() { + super(); + this.data = ''; + } + + _write(chunk, enc, next) { + // add chunk but strip ansi control characters + this.data += chunk.toString().replace(ANSI_REGEXP, ''); + next(); + } + } + + // discard category + const cfg = typeof config === 'string' ? {} : config; + cfg.category = uuidv4(); + if (!cfg.logFile) { + cfg.logFile = ['-']; + } + const logger = getLogger(cfg); + const s = new StringStream(); + + logger.add(new winston.transports.Stream({ + stream: s, + format: winston.format.simple(), + })); + + const finishPromise = new Promise((resolve) => { + logger.on('finish', () => { + resolve(s.data); + }); + }); + + logger.getOutput = async () => { + logger.end(); + return finishPromise; + }; + return logger; +} + +// configure with defaults +module.exports = { + getLogger, + getTestLogger, +}; diff --git a/src/index.js b/src/index.js index a8fe536c..d02bf680 100644 --- a/src/index.js +++ b/src/index.js @@ -16,6 +16,7 @@ const utils = require('./utils.js'); const string = require('./string.js'); const dom = require('./dom.js'); const log = require('./log.js'); +const Logger = require('./Logger.js'); const async_ = require('./async.js'); module.exports = { @@ -26,5 +27,6 @@ module.exports = { dom, utils, log, + Logger, async: async_, }; diff --git a/src/log.js b/src/log.js index a05cb1d0..b167e48d 100644 --- a/src/log.js +++ b/src/log.js @@ -313,7 +313,7 @@ class StreamLogger { } log(msg, opts = {}) { - const { level = 'info' } = opts || {}; + const { level = 'info' } = opts; if (numericLogLevel(level) > numericLogLevel(this.level)) { return; } @@ -376,7 +376,7 @@ class MemLogger { } log(msg, opts = {}) { - const { level = 'info' } = opts || {}; + const { level = 'info' } = opts; if (numericLogLevel(level) <= numericLogLevel(this.level)) { this.buf.push(`[${level.toUpperCase()}] ${serializeMessage(msg, this.serializeOpts)}`); } diff --git a/test/config.test.js b/test/config.test.js index 200dad76..a41f8b68 100644 --- a/test/config.test.js +++ b/test/config.test.js @@ -15,7 +15,8 @@ const assert = require('assert'); const fs = require('fs-extra'); const path = require('path'); -const { HelixConfig } = require('../src/index.js'); +const { HelixConfig, Logger } = require('../src/index.js'); + const Strain = require('../src/Strain.js'); const GitUrl = require('../src/GitUrl.js'); @@ -140,6 +141,36 @@ describe('Helix Config Loading', () => { .init(); assert.deepEqual(cfg1.toJSON(), cfg2.toJSON()); }); + + it('sets logger', async () => { + const logger = Logger.getTestLogger(); + const cfg = await new HelixConfig() + .withLogger(logger) + .withConfigPath(path.resolve(SPEC_ROOT, 'minimal.yaml')) + .init(); + cfg.log.info('Hello, world.'); + assert.ok((await logger.getOutput()).indexOf('Hello, world.') > 0); + }); + + it('sets directory', async () => { + const source = await fs.readFile(path.resolve(SPEC_ROOT, 'full.yaml'), 'utf-8'); + const cfg = await new HelixConfig() + .withDirectory(SPEC_ROOT) + .withSource(source) + .init(); + assert.equal(cfg.directory, SPEC_ROOT); + }); + + it('fails with corrupt file path', async () => { + try { + await new HelixConfig() + .withConfigPath('no-such-file.yaml') + .init(); + assert.fail('should fail.'); + } catch (e) { + assert.equal(e.toString(), 'Error: Invalid configuration:\n\n\nA list of strains and a strain with the name "default" is required.'); + } + }); }); describe('Helix Config Merging', () => { @@ -186,6 +217,18 @@ describe('Helix Config Serializing', () => { assert.equal(actual, source); }); + it('can serialize to canonical form with missing document', async () => { + const source = await fs.readFile(path.resolve(SPEC_ROOT, 'full.yaml'), 'utf-8'); + const cfg = await new HelixConfig() + .withSource(source) + .init(); + delete cfg._document; + + const actual = cfg.toYAML(); + const expected = await fs.readFile(path.resolve(SPEC_ROOT, 'full-canonical.yaml'), 'utf-8'); + assert.equal(actual, expected); + }); + it('can save config', async () => { const testDir = path.resolve(__dirname, 'tmp', `test${Math.random()}`); await fs.ensureDir(testDir); diff --git a/test/log.test.js b/test/log.test.js index 6628fbbf..a4e5b897 100644 --- a/test/log.test.js +++ b/test/log.test.js @@ -171,6 +171,14 @@ const logOutputDebug = multiline(` [DEBUG] Nooo\n `); +const logOutputInfo = multiline(` + [ERROR] { foo: 23 } + [FATAL] + [ERROR] 42 + [WARN] Hello 42 World + [INFO] { foo: 42 }\n +`); + const logOutputWarn = multiline(` [ERROR] { foo: 23 } [FATAL] @@ -207,6 +215,9 @@ it('ConsoleLogger', async () => { it('StreamLogger', () => { const ss = new StringStream(); + testLogger(new StreamLogger(ss)); + assert.strictEqual(ss.extract(), logOutputInfo); + testLogger(new StreamLogger(ss, { level: 'debug' })); assert.strictEqual(ss.extract(), logOutputDebug); @@ -237,13 +248,23 @@ it('FileLogger', async () => { testLogger(logger); await endStreamAndSync(logger.stream); assert.strictEqual(await readFile(tmpfile, { encoding: 'utf-8' }), `${logOutputDebug}${logOutputWarn}`); + + // Tests that append mode is properly used + logger = new FileLogger(tmpfile); + testLogger(logger); + await endStreamAndSync(logger.stream); + assert.strictEqual(await readFile(tmpfile, { encoding: 'utf-8' }), `${logOutputDebug}${logOutputWarn}${logOutputInfo}`); } finally { await unlink(tmpfile); } }); it('MemLogger', () => { - let logger = new MemLogger({ level: 'debug' }); + let logger = new MemLogger(); + testLogger(logger); + assert.strictEqual(`${join(logger.buf, '\n')}\n`, logOutputInfo); + + logger = new MemLogger({ level: 'debug' }); testLogger(logger); assert.strictEqual(`${join(logger.buf, '\n')}\n`, logOutputDebug); diff --git a/test/logger.test.js b/test/logger.test.js new file mode 100644 index 00000000..41a6411f --- /dev/null +++ b/test/logger.test.js @@ -0,0 +1,208 @@ +/* + * Copyright 2018 Adobe. All rights reserved. + * This file is licensed to you under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. You may obtain a copy + * of the License at http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software distributed under + * the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS + * OF ANY KIND, either express or implied. See the License for the specific language + * governing permissions and limitations under the License. + */ + +/* eslint-env mocha */ +/* eslint-disable no-underscore-dangle,no-console */ + +const fs = require('fs-extra'); +const path = require('path'); +const assert = require('assert'); +const stream = require('stream'); +const winston = require('winston'); +const { Logger } = require('../src/index.js'); + +const LOG_DIR = path.resolve(__dirname, 'tmp', 'logs'); + +describe('Logger tests', () => { + const consoleLogs = []; + let consoleStdout; + + const tty = new stream.Writable(); + tty._write = (chunk, encoding, done) => { + consoleLogs.push(chunk.toString('utf-8')); + done(); + }; + tty.isTTY = true; + + const notty = new stream.Writable(); + notty._write = (chunk, encoding, done) => { + consoleLogs.push(chunk.toString('utf-8')); + done(); + }; + notty.isTTY = false; + + beforeEach(async () => { + await fs.remove(LOG_DIR); + winston.loggers.loggers.clear(); + consoleStdout = console._stdout; + console._stdout = tty; + consoleLogs.length = 0; + }); + + afterEach(() => { + console._stdout = consoleStdout; + }); + + it('returns a default logger', () => { + const log = Logger.getLogger(); + assert.ok(log); + }); + + it('returns the same logger twice', () => { + const log1 = Logger.getLogger('foo'); + const log2 = Logger.getLogger('foo'); + assert.strictEqual(log1, log2); + }); + + it('can set a log files', async () => { + const file1 = path.resolve(LOG_DIR, 'f1.log'); + const file2 = path.resolve(LOG_DIR, 'f2.log'); + const file3 = path.resolve(LOG_DIR, 'f3.json'); + const log = Logger.getLogger({ + logFile: [file1, file2, file3], + }); + + log.info('hello, world'); + log.error('gnu not unix'); + log.end(); + + // maybe not the best condition to wait for the streams to close + await new Promise(r => setTimeout(r, 100)); + const f1 = await fs.readFile(file1, 'utf-8'); + const f2 = await fs.readFile(file2, 'utf-8'); + const f3 = await fs.readFile(file3, 'utf-8'); + assert.ok(/.*hello, world.*/.test(f1)); + assert.ok(/.*hello, world.*/.test(f2)); + const r1 = JSON.parse(f3.split('\n')[0]); + delete r1['@timestamp']; + assert.deepEqual(r1, { + '@fields': { + level: 'info', + }, + '@message': 'hello, world', + }); + + const r2 = JSON.parse(f3.split('\n')[1]); + delete r2['@timestamp']; + assert.deepEqual(r2, { + '@fields': { + level: 'error', + }, + '@message': 'gnu not unix', + }); + }); + + it('suppressed logs for tty', async () => { + const file1 = path.resolve(LOG_DIR, 'f1.log'); + const log = Logger.getLogger({ + category: 'cli', + logFile: ['-', file1], + }); + log.info('normal info'); + log.error('normal error'); + log.info({ + progress: true, + level: 'info', + message: 'progress info', + }); + log.close(); + + // maybe not the best condition to wait for the streams to close + await new Promise(r => setTimeout(r, 100)); + const f1 = await fs.readFile(file1, 'utf-8'); + assert.ok(/.*progress info.*/.test(f1)); + + // also test tty output + assert.deepEqual(consoleLogs, [ + 'normal info\n', + '\u001b[31merror\u001b[39m: normal error\n', + ]); + }); + + it('all logs for no tty', async () => { + const file1 = path.resolve(LOG_DIR, 'f1.log'); + const log = Logger.getLogger({ + category: 'cli', + logFile: ['-', file1], + }); + console._stdout = notty; + log.info('normal info'); + log.info({ + progress: true, + level: 'info', + message: 'progress info', + }); + log.close(); + + // maybe not the best condition to wait for the streams to close + await new Promise(r => setTimeout(r, 100)); + const f1 = await fs.readFile(file1, 'utf-8'); + assert.ok(/.*progress info.*/.test(f1)); + + // also test tty output + assert.deepEqual(consoleLogs, [ + 'normal info\n', + 'progress info\n', + ]); + }); + + it('all logs for no cli categ', async () => { + const file1 = path.resolve(LOG_DIR, 'f1.log'); + const log = Logger.getLogger({ + category: 'hlx', + logFile: ['-', file1], + }); + console._stdout = notty; + log.info('normal info'); + log.info({ + progress: true, + level: 'info', + message: 'progress info', + }); + log.close(); + + // maybe not the best condition to wait for the streams to close + await new Promise(r => setTimeout(r, 100)); + const f1 = await fs.readFile(file1, 'utf-8'); + assert.ok(/.*progress info.*/.test(f1)); + + // also test tty output + assert.deepEqual(consoleLogs, [ + '[hlx] \u001b[32minfo\u001b[39m: normal info\n', + '[hlx] \u001b[32minfo\u001b[39m: progress info\n', + ]); + }); + + it('test logger works', async () => { + const log = Logger.getTestLogger(); + log.debug('hello, world'); + log.info('hello, world'); + log.warn('hello, world'); + const output = await log.getOutput(); + assert.equal(output, 'info: hello, world\nwarn: hello, world\n'); + }); + + it('test logger can set log level', async () => { + const log = Logger.getTestLogger({ level: 'debug' }); + log.debug('hello, world'); + log.info('hello, world'); + log.warn('hello, world'); + const output = await log.getOutput(); + assert.equal(output, 'debug: hello, world\ninfo: hello, world\nwarn: hello, world\n'); + }); + + it('test loggers are not recycled', async () => { + const log1 = Logger.getTestLogger(); + const log2 = Logger.getTestLogger(); + assert.notStrictEqual(log1, log2); + }); +}); diff --git a/test/specs/configs/full-canonical.yaml b/test/specs/configs/full-canonical.yaml new file mode 100644 index 00000000..d8cc0cad --- /dev/null +++ b/test/specs/configs/full-canonical.yaml @@ -0,0 +1,224 @@ +version: 1 +strains: + - code: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + content: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + static: + magic: false + allow: [] + deny: [] + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: /htdocs + directoryIndex: index.html + package: "" + name: default + sticky: false + condition: "" + perf: + device: "" + location: "" + connection: "" + urls: [] + - code: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + content: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + static: + magic: false + allow: [] + deny: [] + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: /htdocs + directoryIndex: index.html + package: 75f29aa936bfc2b84bde5ac0ee4afbf824b1391e-dirty + name: adhoc + sticky: false + condition: "" + perf: + device: "" + location: London + connection: "" + onload: 1000 + urls: [] + - code: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + content: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: helix-cli + ref: master + path: "" + static: + magic: false + allow: [] + deny: [] + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: /htdocs + directoryIndex: readme.html + package: "" + name: client + sticky: false + condition: req.http.host == "client.project-helix.io" + perf: + device: "" + location: "" + connection: "" + urls: [] + - code: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: "" + content: + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: hypermedia-pipeline + ref: master + path: "" + static: + magic: false + allow: [] + deny: [] + protocol: https + host: github.com + port: "" + hostname: github.com + owner: adobe + repo: project-helix.io + ref: master + path: /www + directoryIndex: index.html + package: "" + name: pipeline + sticky: true + condition: req.http.host == "pipeline.project-helix.io" + perf: + device: "" + location: "" + connection: "" + urls: [] + params: + - search + - lang + redirects: + - from: (.*)\.php + to: $1.html + - from: \/content\/dam\/(.*)$ + to: /htdocs/$1 + - origin: + hostname: www.adobe.io + error_threshold: 0 + first_byte_timeout: 15000 + weight: 100 + address: www.adobe.io + connect_timeout: 1000 + name: Proxywwwadobeio3a0a + port: 443 + between_bytes_timeout: 10000 + shield: iad-va-us + ssl_cert_hostname: www.adobe.io + max_conn: 200 + use_ssl: true + path: / + name: proxy + sticky: true + condition: req.http.host == "proxy.project-helix.io" + perf: + device: "" + location: "" + connection: "" + urls: [] + params: + - search + - api* + - origin: + hostname: 192.168.0.1 + error_threshold: 0 + first_byte_timeout: 0 + weight: 100 + address: 192.168.0.1 + connect_timeout: 1000 + name: publish + port: 80 + between_bytes_timeout: 10000 + shield: iad-va-us + ssl_cert_hostname: 192.168.0.1 + max_conn: 200 + use_ssl: false + override_host: www.adobe.io + path: /stuff + name: proxy-detailed + sticky: false + condition: "" + perf: + device: "" + location: "" + connection: "" + urls: [] + redirects: + - from: \/old + to: /new