Skip to content

Commit

Permalink
✨ Improve logger functionality (#1012)
Browse files Browse the repository at this point in the history 
* 🐛 Better match URLs to colorize when logged

* 🐛 Only log colors for TTY streams

* ✨ Refactor write method to allow overriding
  • Loading branch information
@wwilsman
wwilsman authored Jul 28, 2022
1 parent 6bb4944 commit de161ba
Show file tree
Hide file tree
Showing 2 changed files with 70 additions and 31 deletions.
42 changes: 26 additions & 16 deletions packages/logger/src/logger.js
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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 = '';

Expand All @@ -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 };
Expand Down Expand Up @@ -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);
}
Expand Down
59 changes: 44 additions & 15 deletions packages/logger/test/logger.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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');
});
Expand Down Expand Up @@ -40,6 +40,7 @@ describe('logger', () => {
let entry = (level, message, meta) => ({
timestamp: jasmine.any(Number),
debug: 'test',
error: false,
level,
message,
meta
Expand Down Expand Up @@ -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)}`
]);
});

Expand All @@ -91,6 +93,7 @@ describe('logger', () => {
level: 'error',
message: error.stack,
timestamp: jasmine.any(Number),
error: true,
meta: {}
});

Expand Down Expand Up @@ -129,7 +132,8 @@ describe('logger', () => {
level: 'info',
message: 'Yes me',
timestamp: jasmine.any(Number),
meta: { match: true }
meta: { match: true },
error: false
}]);
});

Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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');

Expand All @@ -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'
]);
});

Expand Down Expand Up @@ -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);
});

Expand Down Expand Up @@ -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();
});

Expand All @@ -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', () => {
Expand All @@ -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();
});
});
Expand Down

0 comments on commit de161ba

Please sign in to comment.