/** * Copyright © 2016-2020 Threema GmbH (https://threema.ch/). * * This file is part of Threema Web. * * Threema Web is free software: you can redistribute it and/or modify it * under the terms of the GNU Affero General Public License as published by * the Free Software Foundation, either version 3 of the License, or (at * your option) any later version. * * This program is distributed in the hope that it will be useful, but * WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Affero * General Public License for more details. * * You should have received a copy of the GNU Affero General Public License * along with Threema Web. If not, see . */ // tslint:disable:no-reference /// import {Logger} from 'ts-log'; import {BaseConfidential} from '../../src/helpers/confidential'; import {ConsoleLogger, LevelLogger, MemoryLogger, TagLogger, TeeLogger, UnveilLogger} from '../../src/helpers/logger'; import LogLevel = threema.LogLevel; import LogType = threema.LogType; interface EnsureLoggedArgs { level: LogLevel, logger: TestLogger | TestLogger[], tag?: string | string[], } type LogRecord = [LogType, any?, ...any[]]; type LogFunction = (message?: any, ...args: any[]) => void; // Supported log (level) types const LOG_TYPES: LogType[] = ['debug', 'trace', 'info', 'warn', 'error']; /** * Stores all log records in memory for evaluation. */ class TestLogger implements Logger { public readonly records: LogRecord[] = []; public readonly debug: LogFunction; public readonly trace: LogFunction; public readonly info: LogFunction; public readonly warn: LogFunction; public readonly error: LogFunction; constructor() { // Bind log level type methods for (const type of LOG_TYPES) { this[type] = this.append.bind(this, type); } } private append(type: LogType, message?: any, ...args: any[]): void { this.records.push([type, message, ...args]) } } /** * A confidential log record for testing purposes. */ class TestConfidential extends BaseConfidential { public readonly uncensored: string = 'uncensored'; public censored(): string { return 'censored'; } } /** * Log a record of each type. */ function logEachType(...loggers: Logger[]): void { for (const logger of loggers) { for (const type of LOG_TYPES) { logger[type](type); } } } /** * Format a log record. This splices a tag into the expected place. */ function formatLogRecord(record: LogRecord, tag?: string[]): LogRecord { if (tag === undefined) { return record; } // Splice tag into message const [type, ...args] = record; return [type, ...tag.concat(args)]; } /** * Ensure a log record of a level equal to or above has been logged. */ function expectLogged(args: EnsureLoggedArgs): void { // Prepare arguments if (!(args.logger instanceof Array)) { args.logger = [args.logger]; } let tag: string[]; if (args.tag !== undefined) { tag = args.tag instanceof Array ? args.tag : [args.tag]; } // Check for log records to be present, depending on the level for (const logger of args.logger) { // noinspection FallThroughInSwitchStatementJS switch (args.level) { case 'debug': expect(logger.records).toContain(formatLogRecord(['debug', 'debug'], tag)); expect(logger.records).toContain(formatLogRecord(['trace', 'trace'], tag)); case 'info': expect(logger.records).toContain(formatLogRecord(['info', 'info'], tag)); case 'warn': expect(logger.records).toContain(formatLogRecord(['warn', 'warn'], tag)); case 'error': expect(logger.records).toContain(formatLogRecord(['error', 'error'], tag)); default: break; } } } describe('Logger Helpers', () => { describe('TestLogger', () => { it('stores log records', () => { const logger = new TestLogger(); // Ensure a record of each type is being logged logEachType(logger); expectLogged({ level: 'debug', logger: logger }); }); }); describe('TeeLogger', () => { it('forwards log records to each underlying logger', () => { const loggers: TestLogger[] = [ new TestLogger(), new TestLogger(), new TestLogger(), ]; const root = new TeeLogger(loggers); // Ensure a record of each type is being logged logEachType(root); expectLogged({ level: 'debug', logger: loggers }); }); }); describe('LevelLogger', () => { it("'none' level discards everything", () => { const logger = new TestLogger(); const root = new LevelLogger(logger, 'none'); // Ensure a record of each expected type is being logged logEachType(root); expect(logger.records.length).toBe(0); }); it("'debug' level discards nothing", () => { const logger = new TestLogger(); const root = new LevelLogger(logger, 'debug'); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'debug', logger: logger }); }); it("'info' level discards 'debug' and 'trace'", () => { const logger = new TestLogger(); const root = new LevelLogger(logger, 'info'); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'info', logger: logger }); }); it("'warn' level discards 'debug', 'trace' and 'info'", () => { const logger = new TestLogger(); const root = new LevelLogger(logger, 'warn'); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'warn', logger: logger }); }); it("'error' level discards 'debug', 'trace', 'info' and 'warn'", () => { const logger = new TestLogger(); const root = new LevelLogger(logger, 'error'); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'error', logger: logger }); }); }); describe('TagLogger', () => { it('applies a tag', () => { const logger = new TestLogger(); const root = new TagLogger(logger, 'tag'); // Ensure a record of each type is being logged with the expected tag logEachType(root); expectLogged({ level: 'debug', tag: 'tag', logger: logger }); }); it('applies multiple tags', () => { const logger = new TestLogger(); const root = new TagLogger(logger, 'tag1', 'tag2'); // Ensure a record of each type is being logged with the expected tag logEachType(root); expectLogged({ level: 'debug', tag: ['tag1', 'tag2'], logger: logger }); }); }); describe('UnveilLogger', () => { it('leaves normal log records untouched', () => { const logger = new TestLogger(); const root = new UnveilLogger(logger); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'debug', logger: logger }); }); it('unveils confidential log record', () => { const logger = new TestLogger(); const root = new UnveilLogger(logger); // Ensure a confidential record is being unveiled root.debug(new TestConfidential()); expect(logger.records).toContain(['debug', 'uncensored']); }); }); describe('ConsoleLogger', () => { let backup: Logger = {} as Logger; let logger: TestLogger; beforeEach(() => { logger = new TestLogger(); // Store each log level type method of console that we will override for (const type of LOG_TYPES) { backup[type] = console[type]; } // Overwrite each log level type method of console for (const type of LOG_TYPES) { console[type] = logger[type]; } }); afterEach(() => { // Restore each log level type method of console that we have // previously overridden. for (const type of LOG_TYPES) { console[type] = backup[type]; } }); it('forwards log records to the console', () => { const root = new ConsoleLogger(); // Ensure a record of each expected type is being logged logEachType(root); expectLogged({ level: 'debug', logger: logger }); }); it('leaves confidential log record untouched', () => { const root = new ConsoleLogger(); // Ensure a confidential record is being left untouched const message = new TestConfidential(); root.debug(message); expect(logger.records).toContain(['debug', message]); }); }); describe('MemoryLogger', () => { it('serialises each log record with a timestamp', () => { const start = Date.now(); const logger = new MemoryLogger(); // Ensure each log record has a timestamp. for (let i = 0; i < 10; ++i) { logger.debug(i); } const end = Date.now(); const timestamps = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry[0]); expect(timestamps.length).toBe(10); for (const timestamp of timestamps) { expect(timestamp).toBeGreaterThanOrEqual(start); expect(timestamp).toBeLessThanOrEqual(end); } }); it('stores all arguments of the log record', () => { const logger = new MemoryLogger(); // Ensure all arguments of the log record are being kept. // Note: All of these values need to serialised loss-less. const record = [ 'debug', null, true, 1, 'a', [2, 3], { b: 4 }, ]; logger.debug(...record.slice(1)); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(record); }); it("trims the first log record's message (tag)", () => { const logger = new MemoryLogger(); // Ensure %c CSS style formatting placeholder remains but the tag // is being trimmed. const args = [ null, true, 1, 'a', [2, 3], { b: 4 }, ]; logger.debug(' te%cst ', 'color: #fff', ...args); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual((['debug', 'te%cst', 'color: #fff'] as any[]).concat(args)); }); it("ignores style formatting beyond the log record's message (args)", () => { const logger = new MemoryLogger(); // Ensure %c CSS style formatting placeholder and the following // argument are not being touched. const record = [ 'debug', 'test', ' me%cow ', 'color: #fff', null, true, ' ra%cwr ', 'color: #ffa500', 1, 'a', [2, 3], { b: 4 }, ]; logger.debug(...record.slice(1)); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(record); }); it('serialises standard types', () => { const logger = new MemoryLogger(); // Ensure 'null', 'boolean', 'number' and 'string' are being // represented loss-less. const record = [ 'debug', null, false, 1337, 'meow?', ]; logger.debug(...record.slice(1)); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(record); }); it('serialises confidential types sanitised, if requested', () => { const logger = new MemoryLogger(); // Ensure 'Confidential' messages are being sanitised. const confidential = new TestConfidential(); logger.debug(confidential, confidential, confidential); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['debug', 'censored', 'censored', 'censored']); }); it('serialises confidential types as is, if requested', () => { const logger = new MemoryLogger(); // Ensure 'Confidential' messages are being sanitised. const confidential = new TestConfidential(); logger.debug(confidential, confidential, confidential); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(false))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['debug', 'uncensored', 'uncensored', 'uncensored']); }); it('serialises exceptions', () => { const logger = new MemoryLogger(); // Ensure exceptions are being represented (in their lossy string form). const error = new Error('WTF!'); logger.error(error); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['error', error.toString()]); }); it('serialises unrepresentable binary types', () => { const logger = new MemoryLogger(); // Ensure 'ArrayBuffer', 'Uint8Array' and 'Blob' are being // represented with metadata only. const buffer = new ArrayBuffer(10); const array = new Uint8Array(buffer, 2, 6); const blob = new Blob([JSON.stringify({ a: 10 })], { type: 'application/json'} ); logger.debug(buffer, array, blob); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual([ 'debug', '[ArrayBuffer: length=10]', '[Uint8Array: length=6, offset=2]', `[Blob: length=${blob.size}, type=application/json]`, ]); }); it('serialises class instances', () => { const logger = new MemoryLogger(); // Ensure instances are being represented with their name. logger.debug(logger); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['debug', '[MemoryLogger]']); }); it('serialises objects recursively', () => { const logger = new MemoryLogger(); // Ensure an object's properties are being serialised recursively. const object = { bool: true, inner: { number: 4, }, array: ['a', 'b'], }; logger.debug(object); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['debug', object]); }); it('serialises arrays recursively', () => { const logger = new MemoryLogger(); // Ensure each item of an array is being serialised recursively. const array = [ false, { null: null }, ['a', 'b'], ]; logger.debug(array); const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records.length).toBe(1); expect(records[0]).toEqual(['debug', array]); }); it('respects the supplied log record limit', () => { const logger = new MemoryLogger(2); // Ensure only the last two log records are being kept for (let i = 0; i < 10; ++i) { logger.debug(i); } const records = JSON .parse(JSON.stringify(logger.getRecords(), logger.getReplacer(true))) .map((entry) => entry.slice(1)); expect(records).toEqual([ ['debug', 8], ['debug', 9], ]); }); }); });