diff --git a/packages/logger/src/logger.js b/packages/logger/src/logger.js index 54c212455..63b884b2b 100644 --- a/packages/logger/src/logger.js +++ b/packages/logger/src/logger.js @@ -1,6 +1,6 @@ import { colors } from './utils.js'; -const URL_REGEXP = /\bhttps?:\/\/[^\s/$.?#].[^\s]*\b/i; +const URL_REGEXP = /https?:\/\/[-a-zA-Z0-9@:%._+~#=]{2,256}\.[a-z]{2,4}\b([-a-zA-Z0-9@:;%_+.~#?&//=[\]]*)/i; const LOG_LEVELS = { debug: 0, info: 1, warn: 2, error: 3 }; // A PercyLogger instance retains logs in-memory for quick lookups while also writing log @@ -95,6 +95,7 @@ export class PercyLogger { // Formats messages before they are logged to stdio format(debug, level, message, elapsed) { + let color = (n, m) => this.isTTY ? colors[n](m) : m; let label = 'percy'; let suffix = ''; @@ -112,37 +113,43 @@ export class PercyLogger { // include elapsed time since last log if (elapsed != null) { - suffix = ' ' + colors.grey(`(${elapsed}ms)`); + suffix = ' ' + color('grey', `(${elapsed}ms)`); } } - label = colors.magenta(label); + // add colors + label = color('magenta', label); if (level === 'error') { // red errors - message = colors.red(message); + message = color('red', message); } else if (level === 'warn') { // yellow warnings - message = colors.yellow(message); + message = color('yellow', message); } else if (level === 'info' || level === 'debug') { // blue info and debug URLs - message = message.replace(URL_REGEXP, colors.blue('$&')); + message = message.replace(URL_REGEXP, color('blue', '$&')); } return `[${label}] ${message}${suffix}`; } + // True if stdout is a TTY interface + get isTTY() { + return !!this.constructor.stdout.isTTY; + } + // Replaces the current line with a log message progress(debug, message, persist) { if (!this.shouldLog(debug, 'info')) return; let { stdout } = this.constructor; - if (stdout.isTTY || !this._progress) { + if (this.isTTY || !this._progress) { message &&= this.format(debug, message); - if (stdout.isTTY) stdout.cursorTo(0); + if (this.isTTY) stdout.cursorTo(0); else message &&= message + '\n'; if (message) stdout.write(message); - if (stdout.isTTY) stdout.clearLine(1); + if (this.isTTY) stdout.clearLine(1); } this._progress = !!message && { message, persist }; @@ -174,29 +181,32 @@ export class PercyLogger { // save log entries let timestamp = Date.now(); message = err ? (message.stack || err) : message.toString(); - let entry = { debug, level, message, meta, timestamp }; + let entry = { debug, level, message, meta, timestamp, error: !!err }; this.messages.add(entry); // maybe write the message to stdio if (this.shouldLog(debug, level)) { + // unless the loglevel is debug, write shorter error messages if (err && this.level !== 'debug') message = err; - let elapsed = timestamp - (this.lastlog || timestamp); - this.write(level, this.format(debug, err ? 'error' : level, message, elapsed)); + this.write({ ...entry, message }); this.lastlog = timestamp; } } - // Writes a message to stdio based on the loglevel - write(level, message) { + // Writes a log entry to stdio based on the loglevel + write({ debug, level, message, timestamp, error }) { + let elapsed = timestamp - (this.lastlog || timestamp); + let msg = this.format(debug, error ? 'error' : level, message, elapsed); + let progress = this.isTTY && this._progress; let { stdout, stderr } = this.constructor; - let progress = stdout.isTTY && this._progress; + // clear any logged progress if (progress) { stdout.cursorTo(0); stdout.clearLine(0); } - (level === 'info' ? stdout : stderr).write(message + '\n'); + (level === 'info' ? stdout : stderr).write(msg + '\n'); if (!this._progress?.persist) delete this._progress; else if (progress) stdout.write(progress.message); } diff --git a/packages/logger/test/logger.test.js b/packages/logger/test/logger.test.js index 34240fd1a..50c504f8b 100644 --- a/packages/logger/test/logger.test.js +++ b/packages/logger/test/logger.test.js @@ -6,7 +6,7 @@ describe('logger', () => { let log, inst; beforeEach(async () => { - await helpers.mock({ ansi: true }); + await helpers.mock({ ansi: true, isTTY: true }); inst = logger.instance; log = logger('test'); }); @@ -40,6 +40,7 @@ describe('logger', () => { let entry = (level, message, meta) => ({ timestamp: jasmine.any(Number), debug: 'test', + error: false, level, message, meta @@ -75,10 +76,11 @@ describe('logger', () => { }); it('highlights info URLs blue', () => { - log.info('URL: https://percy.io'); + let url = 'https://percy.io/?foo[bar]=baz&qux=quux:xyzzy;'; + log.info(`URL: ${url}`); expect(helpers.stdout).toEqual([ - `[${colors.magenta('percy')}] URL: ${colors.blue('https://percy.io')}` + `[${colors.magenta('percy')}] URL: ${colors.blue(url)}` ]); }); @@ -91,6 +93,7 @@ describe('logger', () => { level: 'error', message: error.stack, timestamp: jasmine.any(Number), + error: true, meta: {} }); @@ -129,7 +132,8 @@ describe('logger', () => { level: 'info', message: 'Yes me', timestamp: jasmine.any(Number), - meta: { match: true } + meta: { match: true }, + error: false }]); }); @@ -171,6 +175,32 @@ describe('logger', () => { expect(logger.stderr).toBe(logger.constructor.stderr); }); + it('can define a custom instance write method', () => { + let write = logger.instance.write = jasmine.createSpy('write'); + + log.info('Info log'); + log.warn('Warn log'); + log.error('Error log'); + log.debug('Debug log'); + + expect(write).toHaveBeenCalledWith(jasmine.objectContaining( + { debug: 'test', level: 'info', message: 'Info log' })); + expect(write).toHaveBeenCalledWith(jasmine.objectContaining( + { debug: 'test', level: 'warn', message: 'Warn log' })); + expect(write).toHaveBeenCalledWith(jasmine.objectContaining( + { debug: 'test', level: 'error', message: 'Error log' })); + + // write is not called when a log should not be written + expect(write).not.toHaveBeenCalledWith(jasmine.objectContaining( + { debug: 'test', level: 'debug', message: 'Debug log' })); + + log.loglevel('debug'); + log.debug('Debug log'); + + expect(write).toHaveBeenCalledWith(jasmine.objectContaining( + { debug: 'test', level: 'debug', message: 'Debug log' })); + }); + describe('levels', () => { it('can be initially set by defining PERCY_LOGLEVEL', () => { helpers.reset(); @@ -280,7 +310,7 @@ describe('logger', () => { it('enables debug logging when PERCY_DEBUG is defined', async () => { process.env.PERCY_DEBUG = '*'; - await helpers.mock({ ansi: true }); + await helpers.mock({ ansi: true, isTTY: true }); logger('test').debug('Debug log'); @@ -300,9 +330,9 @@ describe('logger', () => { logger('test:3').debug('Debug test 3'); expect(helpers.stderr).toEqual([ - `[${colors.magenta('percy:test')}] Debug test`, - `[${colors.magenta('percy:test:1')}] Debug test 1`, - `[${colors.magenta('percy:test:3')}] Debug test 3` + '[percy:test] Debug test', + '[percy:test:1] Debug test 1', + '[percy:test:3] Debug test 3' ]); }); @@ -330,7 +360,6 @@ describe('logger', () => { spyOn(logger.stdout, 'cursorTo').and.callThrough(); spyOn(logger.stdout, 'clearLine').and.callThrough(); spyOn(logger.stdout, 'write').and.callThrough(); - logger.stdout.isTTY = true; ({ stdout } = logger); }); @@ -401,7 +430,7 @@ describe('logger', () => { log.progress('baz'); expect(stdout.cursorTo).not.toHaveBeenCalled(); - expect(stdout.write).toHaveBeenCalledWith(`[${colors.magenta('percy')}] foo\n`); + expect(stdout.write).toHaveBeenCalledWith('[percy] foo\n'); expect(stdout.clearLine).not.toHaveBeenCalled(); }); @@ -413,7 +442,7 @@ describe('logger', () => { expect(stdout.cursorTo).not.toHaveBeenCalled(); expect(stdout.clearLine).not.toHaveBeenCalled(); - expect(stdout.write).toHaveBeenCalledWith(`[${colors.magenta('percy')}] bar\n`); + expect(stdout.write).toHaveBeenCalledWith('[percy] bar\n'); }); it('ignores consecutive persistant logs after the first', () => { @@ -424,10 +453,10 @@ describe('logger', () => { expect(stdout.cursorTo).not.toHaveBeenCalled(); expect(stdout.write).toHaveBeenCalledTimes(3); - expect(stdout.write).toHaveBeenCalledWith(`[${colors.magenta('percy')}] foo\n`); - expect(stdout.write).toHaveBeenCalledWith(`[${colors.magenta('percy')}] bar\n`); - expect(stdout.write).not.toHaveBeenCalledWith(`[${colors.magenta('percy')}] baz\n`); - expect(stdout.write).toHaveBeenCalledWith(`[${colors.magenta('percy')}] qux\n`); + expect(stdout.write).toHaveBeenCalledWith('[percy] foo\n'); + expect(stdout.write).toHaveBeenCalledWith('[percy] bar\n'); + expect(stdout.write).not.toHaveBeenCalledWith('[percy] baz\n'); + expect(stdout.write).toHaveBeenCalledWith('[percy] qux\n'); expect(stdout.clearLine).not.toHaveBeenCalled(); }); });