Use log service for console messages (#221)

* Use logService for console messages

* Implement a base ConsoleLog service

Use this class as a default for other services that would like to output
to console. This service is overriden in CLI and Desktop to use CLI's
consoleLogService and electronLogService, respectively.

* Use browser-process-hrtime for timing

* test LogService implementations

* Ignore default import of hrtime

* Clean up imports. Require ConsoleLog injection

Co-authored-by: Matt Gibson <mdgibson@Matts-MBP.lan>

package.json

@@ -57,6 +57,7 @@
     "karma-typescript": "^4.0.0",
     "nodemon": "^1.17.3",
     "rimraf": "^2.6.2",
+    "ts-node": "^9.1.0",
     "tslint": "^6.1.3",
     "typemoq": "^2.1.0",
     "typescript": "3.8.3"
@@ -75,6 +76,7 @@
     "@microsoft/signalr-protocol-msgpack": "3.1.0",
     "@nodert-win10-rs4/windows.security.credentials.ui": "^0.4.4",
     "big-integer": "1.6.36",
+    "browser-process-hrtime": "1.0.0",
     "chalk": "2.4.1",
     "commander": "2.18.0",
     "core-js": "2.6.2",

spec/common/services/consoleLog.service.spec.ts

@@ -0,0 +1,95 @@
+import { ConsoleLogService } from '../../../src/services/consoleLog.service';
+
+const originalConsole = console;
+let caughtMessage: any;
+
+declare var console: any;
+
+export function interceptConsole(interceptions: any): object {
+    console = {
+        // tslint:disable-next-line
+        log: function () {
+            interceptions.log = arguments;
+        },
+        // tslint:disable-next-line
+        warn: function () {
+            interceptions.warn = arguments;
+        },
+        // tslint:disable-next-line
+        error: function () {
+            interceptions.error = arguments;
+        }
+    };
+    return interceptions;
+}
+
+export function restoreConsole() {
+    console = originalConsole;
+}
+
+describe('ConsoleLogService', () => {
+    let logService: ConsoleLogService;
+    beforeEach(() => {
+        caughtMessage = {};
+        interceptConsole(caughtMessage);
+        logService = new ConsoleLogService(true);
+    });
+
+    afterAll(() => {
+        restoreConsole();
+    });
+
+    it('filters messages below the set threshold', () => {
+        logService = new ConsoleLogService(true, (level) => true);
+        logService.debug('debug');
+        logService.info('info');
+        logService.warning('warning');
+        logService.error('error');
+
+        expect(caughtMessage).toEqual({});
+    });
+    it('only writes debug messages in dev mode', () => {
+        logService = new ConsoleLogService(false);
+
+        logService.debug('debug message');
+        expect(caughtMessage.log).toBeUndefined();
+    });
+
+
+    it('writes debug/info messages to console.log', () => {
+        logService.debug('this is a debug message');
+        expect(caughtMessage).toEqual({ log: jasmine.arrayWithExactContents(['this is a debug message']) });
+
+        logService.info('this is an info message');
+        expect(caughtMessage).toEqual({ log: jasmine.arrayWithExactContents(['this is an info message']) });
+    });
+    it('writes warning messages to console.warn', () => {
+        logService.warning('this is a warning message');
+        expect(caughtMessage).toEqual({ warn: jasmine.arrayWithExactContents(['this is a warning message']) });
+    });
+    it('writes error messages to console.error', () => {
+        logService.error('this is an error message');
+        expect(caughtMessage).toEqual({ error: jasmine.arrayWithExactContents(['this is an error message']) });
+    });
+
+    it('times with output to info', async () => {
+        logService.time();
+        await new Promise(r => setTimeout(r, 250));
+        const duration = logService.timeEnd();
+        expect(duration[0]).toBe(0);
+        expect(duration[1]).toBeGreaterThan(0);
+        expect(duration[1]).toBeLessThan(500 * 10e6);
+
+        expect(caughtMessage).toEqual(jasmine.arrayContaining([]));
+        expect(caughtMessage.log.length).toBe(1);
+        expect(caughtMessage.log[0]).toEqual(jasmine.stringMatching(/^default: \d+\.?\d*ms$/));
+    });
+
+    it('filters time output', async () => {
+        logService = new ConsoleLogService(true, (level) => true);
+        logService.time();
+        logService.timeEnd();
+
+        expect(caughtMessage).toEqual({});
+    });
+});

spec/electron/services/electronLog.service.spec.ts

@@ -0,0 +1,9 @@
+import { ElectronLogService } from '../../../src/electron/services/electronLog.service';
+
+describe('ElectronLogService', () => {
+    it('sets dev based on electron method', () => {
+        process.env.ELECTRON_IS_DEV = '1';
+        const logService = new ElectronLogService();
+        expect(logService).toEqual(jasmine.objectContaining({ isDev: true }) as any);
+    });
+});

spec/node/cli/consoleLog.service.spec.ts

@@ -0,0 +1,41 @@
+import { ConsoleLogService } from '../../../src/cli/services/consoleLog.service';
+import { interceptConsole, restoreConsole } from '../../common/services/consoleLog.service.spec';
+
+const originalConsole = console;
+let caughtMessage: any = {};
+
+describe('CLI Console log service', () => {
+    let logService: ConsoleLogService;
+    beforeEach(() => {
+        caughtMessage = {};
+        interceptConsole(caughtMessage);
+        logService = new ConsoleLogService(true);
+    });
+
+    afterAll(() => {
+        restoreConsole();
+    });
+
+    it('should redirect all console to error if BW_RESPONSE env is true', () => {
+        process.env.BW_RESPONSE = 'true';
+
+        logService.debug('this is a debug message');
+        expect(caughtMessage).toEqual({ error: jasmine.arrayWithExactContents(['this is a debug message']) });
+    });
+
+    it('should not redirect console to error if BW_RESPONSE != true', () => {
+        process.env.BW_RESPONSE = 'false';
+
+        logService.debug('debug');
+        logService.info('info');
+        logService.warning('warning');
+        logService.error('error');
+
+        expect(caughtMessage).toEqual({
+            log: jasmine.arrayWithExactContents(['info']),
+            warn: jasmine.arrayWithExactContents(['warning']),
+            error: jasmine.arrayWithExactContents(['error']),
+        });
+
+    });
+});

spec/support/jasmine.json

@@ -2,7 +2,8 @@
   "spec_dir": "dist/spec",
   "spec_files": [
     "common/**/*[sS]pec.js",
-    "node/**/*[sS]pec.js"
+    "node/**/*[sS]pec.js",
+    "electron/**/*[sS]pec.js"
   ],
   "helpers": [
     "helpers.js"

src/abstractions/log.service.ts

@@ -6,4 +6,6 @@ export abstract class LogService {
     warning: (message: string) => void;
     error: (message: string) => void;
     write: (level: LogLevelType, message: string) => void;
+    time: (label: string) => void;
+    timeEnd: (label: string) => [number, number];
 }

src/cli/baseProgram.ts

@@ -18,7 +18,7 @@ export abstract class BaseProgram {
         if (!response.success) {
             if (process.env.BW_QUIET !== 'true') {
                 if (process.env.BW_RESPONSE === 'true') {
-                    this.writeLn(this.getJson(response), true, true);
+                    this.writeLn(this.getJson(response), true, false);
                 } else {
                     this.writeLn(chalk.redBright(response.message), true, true);
                 }

src/cli/services/consoleLog.service.ts

@@ -1,53 +1,23 @@
 import { LogLevelType } from '../../enums/logLevelType';
 
-import { LogService as LogServiceAbstraction } from '../../abstractions/log.service';
+import { ConsoleLogService as BaseConsoleLogService } from '../../services/consoleLog.service';
 
-export class ConsoleLogService implements LogServiceAbstraction {
-    constructor(private isDev: boolean, private filter: (level: LogLevelType) => boolean = null) { }
-
-    debug(message: string) {
-        if (!this.isDev) {
-            return;
-        }
-        this.write(LogLevelType.Debug, message);
-    }
-
-    info(message: string) {
-        this.write(LogLevelType.Info, message);
-    }
-
-    warning(message: string) {
-        this.write(LogLevelType.Warning, message);
-    }
-
-    error(message: string) {
-        this.write(LogLevelType.Error, message);
+export class ConsoleLogService extends BaseConsoleLogService {
+    constructor(isDev: boolean, filter: (level: LogLevelType) => boolean = null) {
+        super(isDev, filter);
     }
 
     write(level: LogLevelType, message: string) {
         if (this.filter != null && this.filter(level)) {
             return;
         }
 
-        switch (level) {
-            case LogLevelType.Debug:
-                // tslint:disable-next-line
-                console.log(message);
-                break;
-            case LogLevelType.Info:
-                // tslint:disable-next-line
-                console.log(message);
-                break;
-            case LogLevelType.Warning:
-                // tslint:disable-next-line
-                console.warn(message);
-                break;
-            case LogLevelType.Error:
-                // tslint:disable-next-line
-                console.error(message);
-                break;
-            default:
-                break;
+        if (process.env.BW_RESPONSE === 'true') {
+            // tslint:disable-next-line
+            console.error(message);
+            return;
         }
+
+        super.write(level, message);
     }
 }

src/electron/services/electronLog.service.ts

@@ -5,10 +5,12 @@ import { isDev } from '../utils';
 
 import { LogLevelType } from '../../enums/logLevelType';
 
-import { LogService as LogServiceAbstraction } from '../../abstractions/log.service';
+import { ConsoleLogService as BaseLogService } from '../../services/consoleLog.service';
 
-export class ElectronLogService implements LogServiceAbstraction {
-    constructor(private filter: (level: LogLevelType) => boolean = null, logDir: string = null) {
+export class ElectronLogService extends BaseLogService {
+
+    constructor(protected filter: (level: LogLevelType) => boolean = null, logDir: string = null) {
+        super(isDev(), filter);
         if (log.transports == null) {
             return;
         }
@@ -19,26 +21,6 @@ export class ElectronLogService implements LogServiceAbstraction {
         }
     }
 
-    debug(message: string) {
-        if (!isDev()) {
-            return;
-        }
-
-        this.write(LogLevelType.Debug, message);
-    }
-
-    info(message: string) {
-        this.write(LogLevelType.Info, message);
-    }
-
-    warning(message: string) {
-        this.write(LogLevelType.Warning, message);
-    }
-
-    error(message: string) {
-        this.write(LogLevelType.Error, message);
-    }
-
     write(level: LogLevelType, message: string) {
         if (this.filter != null && this.filter(level)) {
             return;

src/importers/baseImporter.ts

@@ -1,5 +1,7 @@
 import * as papa from 'papaparse';
 
+import { LogService } from '../abstractions/log.service';
+
 import { ImportResult } from '../models/domain/importResult';
 
 import { CipherView } from '../models/view/cipherView';
@@ -17,9 +19,13 @@ import { CipherType } from '../enums/cipherType';
 import { FieldType } from '../enums/fieldType';
 import { SecureNoteType } from '../enums/secureNoteType';
 
+import { ConsoleLogService } from '../services/consoleLog.service';
+
 export abstract class BaseImporter {
     organizationId: string = null;
 
+    protected logService: LogService = new ConsoleLogService(false);
+
     protected newLineRegex = /(?:\r\n|\r|\n)/;
 
     protected passwordFieldNames = [
@@ -88,7 +94,7 @@ export abstract class BaseImporter {
             result.errors.forEach((e) => {
                 if (e.row != null) {
                     // tslint:disable-next-line
-                    console.warn('Error parsing row ' + e.row + ': ' + e.message);
+                    this.logService.warning('Error parsing row ' + e.row + ': ' + e.message);
                 }
             });
         }

src/services/auth.service.ts

@@ -17,6 +17,7 @@ import { AppIdService } from '../abstractions/appId.service';
 import { AuthService as AuthServiceAbstraction } from '../abstractions/auth.service';
 import { CryptoService } from '../abstractions/crypto.service';
 import { I18nService } from '../abstractions/i18n.service';
+import { LogService } from '../abstractions/log.service';
 import { MessagingService } from '../abstractions/messaging.service';
 import { PlatformUtilsService } from '../abstractions/platformUtils.service';
 import { TokenService } from '../abstractions/token.service';
@@ -91,7 +92,9 @@ export class AuthService implements AuthServiceAbstraction {
         private userService: UserService, private tokenService: TokenService,
         private appIdService: AppIdService, private i18nService: I18nService,
         private platformUtilsService: PlatformUtilsService, private messagingService: MessagingService,
-        private vaultTimeoutService: VaultTimeoutService, private setCryptoKeys = true) { }
+        private vaultTimeoutService: VaultTimeoutService, private logService: LogService,
+        private setCryptoKeys = true) {
+    }
 
     init() {
         TwoFactorProviders[TwoFactorProviderType.Email].name = this.i18nService.t('emailTitle');
@@ -351,7 +354,7 @@ export class AuthService implements AuthServiceAbstraction {
                         tokenResponse.privateKey = keyPair[1].encryptedString;
                     } catch (e) {
                         // tslint:disable-next-line
-                        console.error(e);
+                        this.logService.error(e);
                     }
                 }