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,27 +1,10 @@
 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 {
+export class ConsoleLogService extends BaseConsoleLogService {
-    constructor(private isDev: boolean, private filter: (level: LogLevelType) => boolean = null) { }
+    constructor(isDev: boolean, filter: (level: LogLevelType) => boolean = null) {
-
+        super(isDev, filter);
-    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);
     }
 
     write(level: LogLevelType, message: string) {
@@ -29,25 +12,12 @@ export class ConsoleLogService implements LogServiceAbstraction {
             return;
         }
 
-        switch (level) {
+        if (process.env.BW_RESPONSE === 'true') {
-            case LogLevelType.Debug:
+            // tslint:disable-next-line
-                // tslint:disable-next-line
+            console.error(message);
-                console.log(message);
+            return;
-                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;
         }
+
+        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 {
+export class ElectronLogService extends BaseLogService {
-    constructor(private filter: (level: LogLevelType) => boolean = null, logDir: string = null) {
+
+    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);
                     }
                 }
 

src/services/consoleLog.service.ts

@@ -0,0 +1,71 @@
+import { LogLevelType } from '../enums/logLevelType';
+
+import { LogService as LogServiceAbstraction } from '../abstractions/log.service';
+
+// @ts-ignore: import * as ns from "mod" error, need to do it this way
+import hrtime = require('browser-process-hrtime');
+
+export class ConsoleLogService implements LogServiceAbstraction {
+    protected timersMap: Map<string, [number, number]> = new Map();
+
+    constructor(protected isDev: boolean, protected 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);
+    }
+
+    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;
+        }
+    }
+
+    time(label: string = 'default') {
+        if (!this.timersMap.has(label)) {
+            this.timersMap.set(label, hrtime());
+        }
+    }
+
+    timeEnd(label: string = 'default'): [number, number] {
+        const elapsed = hrtime(this.timersMap.get(label));
+        this.timersMap.delete(label);
+        this.write(LogLevelType.Info, `${label}: ${elapsed[0] * 1000 + elapsed[1] / 10e6}ms`);
+        return elapsed;
+    }
+}

src/services/crypto.service.ts

@@ -10,6 +10,7 @@ import { ProfileOrganizationResponse } from '../models/response/profileOrganizat
 
 import { CryptoService as CryptoServiceAbstraction } from '../abstractions/crypto.service';
 import { CryptoFunctionService } from '../abstractions/cryptoFunction.service';
+import { LogService } from '../abstractions/log.service';
 import { PlatformUtilsService } from '../abstractions/platformUtils.service';
 import { StorageService } from '../abstractions/storage.service';
 
@@ -37,7 +38,9 @@ export class CryptoService implements CryptoServiceAbstraction {
     private orgKeys: Map<string, SymmetricCryptoKey>;
 
     constructor(private storageService: StorageService, private secureStorageService: StorageService,
-        private cryptoFunctionService: CryptoFunctionService, private platformUtilService: PlatformUtilsService) { }
+        private cryptoFunctionService: CryptoFunctionService, private platformUtilService: PlatformUtilsService,
+        private logService: LogService) {
+    }
 
     async setKey(key: SymmetricCryptoKey): Promise<any> {
         this.key = key;
@@ -546,14 +549,12 @@ export class CryptoService implements CryptoServiceAbstraction {
         const theKey = this.resolveLegacyKey(encType, keyForEnc);
 
         if (theKey.macKey != null && mac == null) {
-            // tslint:disable-next-line
+            this.logService.error('mac required.');
-            console.error('mac required.');
             return null;
         }
 
         if (theKey.encType !== encType) {
-            // tslint:disable-next-line
+            this.logService.error('encType unavailable.');
-            console.error('encType unavailable.');
             return null;
         }
 
@@ -563,8 +564,7 @@ export class CryptoService implements CryptoServiceAbstraction {
                 fastParams.macKey, 'sha256');
             const macsEqual = await this.cryptoFunctionService.compareFast(fastParams.mac, computedMac);
             if (!macsEqual) {
-                // tslint:disable-next-line
+                this.logService.error('mac failed.');
-                console.error('mac failed.');
                 return null;
             }
         }
@@ -596,8 +596,7 @@ export class CryptoService implements CryptoServiceAbstraction {
 
             const macsMatch = await this.cryptoFunctionService.compare(mac, computedMac);
             if (!macsMatch) {
-                // tslint:disable-next-line
+                this.logService.error('mac failed.');
-                console.error('mac failed.');
                 return null;
             }
         }

src/services/notifications.service.ts

@@ -6,6 +6,7 @@ import { NotificationType } from '../enums/notificationType';
 import { ApiService } from '../abstractions/api.service';
 import { AppIdService } from '../abstractions/appId.service';
 import { EnvironmentService } from '../abstractions/environment.service';
+import { LogService } from '../abstractions/log.service';
 import { NotificationsService as NotificationsServiceAbstraction } from '../abstractions/notifications.service';
 import { SyncService } from '../abstractions/sync.service';
 import { UserService } from '../abstractions/user.service';
@@ -27,7 +28,9 @@ export class NotificationsService implements NotificationsServiceAbstraction {
 
     constructor(private userService: UserService, private syncService: SyncService,
         private appIdService: AppIdService, private apiService: ApiService,
-        private vaultTimeoutService: VaultTimeoutService, private logoutCallback: () => Promise<void>) { }
+        private vaultTimeoutService: VaultTimeoutService,
+        private logoutCallback: () => Promise<void>, private logService: LogService) {
+    }
 
     async init(environmentService: EnvironmentService): Promise<void> {
         this.inited = false;
@@ -87,8 +90,7 @@ export class NotificationsService implements NotificationsServiceAbstraction {
                 await this.signalrConnection.stop();
             }
         } catch (e) {
-            // tslint:disable-next-line
+            this.logService.error(e.toString());
-            console.error(e.toString());
         }
     }
 

src/services/search.service.ts

@@ -3,6 +3,7 @@ import * as lunr from 'lunr';
 import { CipherView } from '../models/view/cipherView';
 
 import { CipherService } from '../abstractions/cipher.service';
+import { LogService } from '../abstractions/log.service';
 import { SearchService as SearchServiceAbstraction } from '../abstractions/search.service';
 
 import { CipherType } from '../enums/cipherType';
@@ -13,7 +14,7 @@ export class SearchService implements SearchServiceAbstraction {
     private indexing = false;
     private index: lunr.Index = null;
 
-    constructor(private cipherService: CipherService) {
+    constructor(private cipherService: CipherService, private logService: LogService) {
     }
 
     clearIndex(): void {
@@ -30,8 +31,8 @@ export class SearchService implements SearchServiceAbstraction {
         if (this.indexing) {
             return;
         }
-        // tslint:disable-next-line
+
-        console.time('search indexing');
+        this.logService.time('search indexing');
         this.indexing = true;
         this.index = null;
         const builder = new lunr.Builder();
@@ -62,8 +63,8 @@ export class SearchService implements SearchServiceAbstraction {
         ciphers.forEach((c) => builder.add(c));
         this.index = builder.build();
         this.indexing = false;
-        // tslint:disable-next-line
+
-        console.timeEnd('search indexing');
+        this.logService.timeEnd('search indexing');
     }
 
     async searchCiphers(query: string,