fix: remove console output from tests

See #935
loopbackio · Jan 31, 2018 · ff4a320 · ff4a320
1 parent 54f3ea7
commit ff4a320
Show file tree

Hide file tree

Showing 10 changed files with 67 additions and 60 deletions.
diff --git a/packages/context/test/acceptance/method-level-bindings.feature.md b/packages/context/test/acceptance/method-level-bindings.feature.md
@@ -20,19 +20,19 @@
 
    static say(@inject('user') user: string):string {
      const msg = `Hello ${user}`;
-     console.log(msg);
+     debug(msg);
      return msg;
    }
 
    hello(@inject('user') user: string):string {
      const msg = `Hello ${user}`;
-     console.log(msg);
+     debug(msg);
      return msg;
    }
 
    greet(prefix: string, @inject('user') user: string):string {
      const msg = `[${prefix}] Hello ${user}`;
-     console.log(msg);
+     debug(msg);
      return msg;
    }
  }

diff --git a/packages/context/test/acceptance/method-level-bindings.ts b/packages/context/test/acceptance/method-level-bindings.ts
@@ -5,23 +5,25 @@
 
 import {expect} from '@loopback/testlab';
 import {Context, inject, invokeMethod} from '../..';
+import * as debugModule from 'debug';
+const debug = debugModule('loopback:context:test');
 
 class InfoController {
   static sayHello(@inject('user') user: string): string {
     const msg = `Hello ${user}`;
-    console.log(msg);
+    debug(msg);
     return msg;
   }
 
   hello(@inject('user') user: string): string {
     const msg = `Hello ${user}`;
-    console.log(msg);
+    debug(msg);
     return msg;
   }
 
   greet(prefix: string, @inject('user') user: string): string {
     const msg = `[${prefix}] Hello ${user}`;
-    console.log(msg);
+    debug(msg);
     return msg;
   }
 }

diff --git a/packages/example-log-extension/package.json b/packages/example-log-extension/package.json
@@ -24,7 +24,7 @@
     "tslint:fix": "npm run tslint -- --fix",
     "prepublishOnly": "npm run build",
     "pretest": "npm run clean && npm run build:current",
-    "test": "lb-dist mocha \"DIST/test/unit/**/*.js\" \"DIST/test/acceptance/**/*.js\"",
+    "test": "lb-mocha \"DIST/test/unit/**/*.js\" \"DIST/test/acceptance/**/*.js\"",
     "posttest": "npm run lint",
     "verify": "npm pack && tar xf *example-log-extension*.tgz && tree package && npm run clean"
   },
@@ -44,13 +44,15 @@
   "devDependencies": {
     "@loopback/build": "^4.0.0-alpha.12",
     "@loopback/testlab": "^4.0.0-alpha.22",
+    "@types/debug": "0.0.30",
     "mocha": "^4.0.0",
     "source-map-support": "^0.5.2"
   },
   "dependencies": {
     "@loopback/context": "^4.0.0-alpha.29",
     "@loopback/core": "^4.0.0-alpha.31",
     "@loopback/rest": "^4.0.0-alpha.23",
-    "chalk": "^2.3.0"
+    "chalk": "^2.3.0",
+    "debug": "^3.1.0"
   }
 }
diff --git a/packages/example-log-extension/src/providers/log-action.provider.ts b/packages/example-log-extension/src/providers/log-action.provider.ts
@@ -10,6 +10,8 @@ import {getLogMetadata} from '../decorators/log.decorator';
 import {EXAMPLE_LOG_BINDINGS, LOG_LEVEL} from '../keys';
 import {LogFn, TimerFn, HighResTime, LevelMetadata} from '../types';
 import chalk from 'chalk';
+import * as debugModule from 'debug';
+const debug = debugModule('loopback:example:extension:log');
 
 export class LogActionProvider implements Provider<LogFn> {
   constructor(
@@ -60,33 +62,37 @@ export class LogActionProvider implements Provider<LogFn> {
       level !== LOG_LEVEL.OFF
     ) {
       if (!args) args = [];
-      let log = `${req.url} :: ${controllerClass.name}.`;
-      log += `${methodName}(${args.join(', ')}) => `;
+      let msg = `${req.url} :: ${controllerClass.name}.`;
+      msg += `${methodName}(${args.join(', ')}) => `;
 
-      if (typeof result === 'object') log += JSON.stringify(result);
-      else log += result;
+      if (typeof result === 'object') msg += JSON.stringify(result);
+      else msg += result;
 
       if (start) {
         const timeDiff: HighResTime = this.timer(start);
         const time: number =
           timeDiff[0] * 1000 + Math.round(timeDiff[1] * 1e-4) / 100;
-        log = `${time}ms: ${log}`;
+        msg = `${time}ms: ${msg}`;
       }
 
       switch (level) {
         case LOG_LEVEL.DEBUG:
-          console.log(chalk.white(`DEBUG: ${log}`));
+          this.log(chalk.white(`DEBUG: ${msg}`));
           break;
         case LOG_LEVEL.INFO:
-          console.log(chalk.green(`INFO: ${log}`));
+          this.log(chalk.green(`INFO: ${msg}`));
           break;
         case LOG_LEVEL.WARN:
-          console.log(chalk.yellow(`WARN: ${log}`));
+          this.log(chalk.yellow(`WARN: ${msg}`));
           break;
         case LOG_LEVEL.ERROR:
-          console.log(chalk.red(`ERROR: ${log}`));
+          this.log(chalk.red(`ERROR: ${msg}`));
           break;
       }
     }
   }
+
+  log(msg: string) {
+    debug(msg);
+  }
 }
diff --git a/packages/example-log-extension/src/providers/log-level.provider.ts b/packages/example-log-extension/src/providers/log-level.provider.ts
@@ -10,6 +10,8 @@ export class LogLevelProvider implements Provider<number> {
   constructor() {}
 
   value(): number {
+    const level = Number(process.env.LOG_LEVEL);
+    if (!isNaN(level) && typeof level === 'number') return level;
     return LOG_LEVEL.WARN;
   }
 }
diff --git a/packages/example-log-extension/test/acceptance/log.extension.acceptance.ts b/packages/example-log-extension/test/acceptance/log.extension.acceptance.ts
@@ -21,6 +21,7 @@ import {
 } from '@loopback/rest';
 import {
   LogComponent,
+  LogActionProvider,
   LogLevelMixin,
   LOG_LEVEL,
   log,
@@ -66,9 +67,9 @@ describe('log extension acceptance test', () => {
   beforeEach(createApp);
   beforeEach(createController);
   beforeEach(createSequence);
-  beforeEach(createConsoleSpy);
+  beforeEach(createLogSpy);
 
-  afterEach(restoreConsoleSpy);
+  afterEach(restoreLogSpy);
 
   it('logs information at DEBUG or higher', async () => {
     setAppLogToDebug();
@@ -317,11 +318,11 @@ describe('log extension acceptance test', () => {
     return [2, 2];
   }
 
-  function createConsoleSpy() {
-    spy = sinon.spy(console, 'log');
+  function createLogSpy() {
+    spy = sinon.spy(LogActionProvider.prototype, 'log');
   }
 
-  function restoreConsoleSpy() {
+  function restoreLogSpy() {
     spy.restore();
   }
 });
diff --git a/packages/example-log-extension/test/unit/providers/log-action.provider.unit.ts b/packages/example-log-extension/test/unit/providers/log-action.provider.unit.ts
@@ -22,10 +22,10 @@ describe('LogActionProvider (unit)', () => {
   let logger: LogFn;
   const req = <ParsedRequest>{url: '/test'};
 
-  beforeEach(createConsoleSpy);
+  beforeEach(createLogSpy);
   beforeEach(getLogger);
 
-  afterEach(restoreConsoleSpy);
+  afterEach(restoreLogSpy);
 
   it('logs a value without a start time', async () => {
     const match = chalk.red('ERROR: /test :: TestClass.test() => test message');
@@ -68,11 +68,11 @@ describe('LogActionProvider (unit)', () => {
     logger = await context.get(EXAMPLE_LOG_BINDINGS.LOG_ACTION);
   }
 
-  function createConsoleSpy() {
-    spy = sinon.spy(console, 'log');
+  function createLogSpy() {
+    spy = sinon.spy(LogActionProvider.prototype, 'log');
   }
 
-  function restoreConsoleSpy() {
+  function restoreLogSpy() {
     spy.restore();
   }
 

diff --git a/packages/rest/package.json b/packages/rest/package.json
@@ -42,6 +42,7 @@
     "@loopback/openapi-spec-builder": "^4.0.0-alpha.20",
     "@loopback/repository": "^4.0.0-alpha.27",
     "@loopback/testlab": "^4.0.0-alpha.22",
+    "@types/debug": "0.0.30",
     "@types/js-yaml": "^3.9.1",
     "@types/lodash": "^4.14.96"
   },

diff --git a/packages/rest/src/providers/log-error-provider.ts b/packages/rest/src/providers/log-error-provider.ts
@@ -6,18 +6,20 @@
 import {Provider} from '@loopback/context';
 import {ServerRequest} from 'http';
 import {LogError} from '../internal-types';
+import * as debugModule from 'debug';
+const debug = debugModule('loopback:rest:error');
 
 export class LogErrorProvider implements Provider<LogError> {
   value(): LogError {
     return (err, statusCode, req) => this.action(err, statusCode, req);
   }
 
   action(err: Error, statusCode: number, req: ServerRequest) {
-    if (statusCode < 500) {
+    if (statusCode < 400) {
       return;
     }
 
-    console.error(
+    debug(
       'Unhandled error in %s %s: %s %s',
       req.method,
       req.url,

diff --git a/packages/rest/test/integration/http-handler.integration.ts b/packages/rest/test/integration/http-handler.integration.ts
@@ -10,19 +10,19 @@ import {
   writeResultToResponse,
   parseOperationArgs,
   RestBindings,
+  FindRouteProvider,
+  InvokeMethodProvider,
+  RejectProvider,
 } from '../..';
 import {ControllerSpec, get} from '@loopback/openapi-v2';
 import {Context} from '@loopback/context';
 import {Client, createClientForHandler} from '@loopback/testlab';
 import * as HttpErrors from 'http-errors';
+import * as debugModule from 'debug';
 import {ParameterObject} from '@loopback/openapi-spec';
 import {anOpenApiSpec, anOperationSpec} from '@loopback/openapi-spec-builder';
-import {
-  FindRouteProvider,
-  InvokeMethodProvider,
-  RejectProvider,
-} from '../../src/providers';
 
+const debug = debugModule('loopback:rest:test');
 const SequenceActions = RestBindings.SequenceActions;
 
 describe('HttpHandler', () => {
@@ -496,20 +496,26 @@ describe('HttpHandler', () => {
 
     rootContext.bind(RestBindings.SEQUENCE).toClass(DefaultSequence);
 
-    function logger(err: Error, statusCode: number, req: ServerRequest) {
-      console.error(
-        'Unhandled error in %s %s: %s %s',
-        req.method,
-        req.url,
-        statusCode,
-        err.stack || err,
-      );
-    }
-
     handler = new HttpHandler(rootContext);
     rootContext.bind(RestBindings.HANDLER).to(handler);
   }
 
+  let skipStatusCode = 200;
+  function logger(err: Error, statusCode: number, req: ServerRequest) {
+    if (statusCode === skipStatusCode) return;
+    debug(
+      'Unhandled error in %s %s: %s %s',
+      req.method,
+      req.url,
+      statusCode,
+      err.stack || err,
+    );
+  }
+
+  function logErrorsExcept(ignoreStatusCode: number) {
+    skipStatusCode = ignoreStatusCode;
+  }
+
   function givenControllerClass(
     // tslint:disable-next-line:no-any
     ctor: new (...args: any[]) => Object,
@@ -521,26 +527,11 @@ describe('HttpHandler', () => {
   function givenClient() {
     client = createClientForHandler((req, res) => {
       handler.handleRequest(req, res).catch(err => {
-        console.error('Request failed.', err.stack);
+        debug('Request failed.', err.stack);
         if (res.headersSent) return;
         res.statusCode = 500;
         res.end();
       });
     });
   }
-
-  function logErrorsExcept(ignoreStatusCode: number) {
-    const oldLogger: Function = rootContext.getSync(SequenceActions.LOG_ERROR);
-    rootContext.bind(SequenceActions.LOG_ERROR).to(conditionalLogger);
-
-    function conditionalLogger(
-      err: Error,
-      statusCode: number,
-      req: ServerRequest,
-    ) {
-      if (statusCode === ignoreStatusCode) return;
-      // tslint:disable-next-line:no-invalid-this
-      oldLogger.apply(this, arguments);
-    }
-  }
 });