Feature/Issue #33 log messages marked as aietes (#40)

* Add Aietes identifier as a prefix for each log trace:

- new module to provide 'info', 'warn' and 'error' functions

* Issue #33 added Aietes prefix to access logs, use central log methods consistently throughout, clean up old logging module

* Issue #33 added unit test for logging

Co-authored-by: benjaiser <devjaiser@gmail.com>

lib/errorHandler.js

@@ -1,5 +1,7 @@
+const { log } = require('./logging');
+
 const _handleUnconfiguredRoutes = (req, res) => {
-  console.warn(`Unconfigured route called: ${req.path}, method: ${req.method}`);
+  log.warn(`Unconfigured route called: ${req.path}, method: ${req.method}`);
   res.status(404);
   res.json({
     error: {

lib/logging.js

@@ -0,0 +1,24 @@
+const morgan = require('morgan');
+
+const LOGGING_PREFIX = '[Aietes]';
+
+const info = data => {
+  if (!process.env.NO_OUTPUT) {
+    console.log(`${LOGGING_PREFIX} ${data}`);
+  }
+};
+
+const warn = data => {
+  if (!process.env.NO_OUTPUT) {
+    console.warn(`${LOGGING_PREFIX} ${data}`);
+  }
+};
+
+const error = data => {
+  console.error(`${LOGGING_PREFIX} ${data}`);
+};
+
+module.exports = {
+  log: { info, warn, error },
+  accessLog: morgan(`${LOGGING_PREFIX} :method :url :status :response-time[1] ms - :res[content-length] b`)
+};

lib/metaData.js

@@ -1,3 +1,5 @@
+const { log } = require('./logging');
+
 class MetaData {
   constructor() {
     this.responsesMetaData = {};
@@ -22,11 +24,11 @@ class MetaData {
   nextResponseIndex(path, method, maxValue) {
     const metaData = this.responsesMetaData[path][method];
     if (!metaData) {
-      console.warn(`No meta data for ${method} to ${path}.`);
+      log.warn(`No meta data for ${method} to ${path}.`);
       throw new Error('MetaData not initialized.');
     }
     const currentValue = metaData.currentResIndex;
-    console.log(`calling callback for ${path} and ${method}`);
+    log.info(`calling callback for ${path} and ${method}`);
     metaData.currentResIndex = (metaData.currentResIndex + 1) % maxValue;
     return currentValue;
   }

mock-server.js

@@ -1,10 +1,9 @@
 const express = require('express');
 const _ = require('lodash');
 const enableDestroy = require('server-destroy');
-const morgan = require('morgan');
-const log = require('./lib/log');
 const unconfiguredRoutesHandler = require('./lib/errorHandler');
 const MetaData = require('./lib/metaData');
+const { log, accessLog } = require('./lib/logging');
 
 const SUPPORTED_METHODS = ['get', 'post', 'put', 'delete'];
 
@@ -22,23 +21,23 @@ class AietesServer {
   start() {
     try {
       this._listen(() => {
-        log(`Aietes server running at http://localhost:${this.serverPort}/`);
+        log.info(`Aietes server running at http://localhost:${this.serverPort}/`);
         return true;
       });
     } catch (e) {
-      log('Could not start Aietes server.');
-      console.error(e);
+      log.error('Could not start Aietes server.');
+      log.error(e);
       process.exit(1);
     }
   }
 
   update(responses) {
-    log('Updating responses');
+    log.info('Updating responses');
     Object.assign(this.responses, responses);
   }
 
   reset(responses) {
-    log('Restarting Aietes server');
+    log.info('Restarting Aietes server');
     this._end();
     this.responses = Object.assign({}, responses);
     this.responsesMetaData.clear();
@@ -47,7 +46,7 @@ class AietesServer {
   }
 
   stop() {
-    log('Exiting Aietes server');
+    log.info('Exiting Aietes server');
     this._end();
   }
 
@@ -57,7 +56,7 @@ class AietesServer {
 
   _setup() {
     this.app = express();
-    this.app.use(morgan('tiny'));
+    this.app.use(accessLog);
     this.app.locals = {
       _: _
     };
@@ -84,7 +83,7 @@ class AietesServer {
           this.responsesMetaData.initMetaDataForHandler(path, method);
           this.app[methodForExpress](path, this._createHandler(path, method));
         } else {
-          console.warn(`Method ${method} is not supported. Path '${path}'-${method} will be skipped.`);
+          log.warn(`Method ${method} is not supported. Path '${path}'-${method} will be skipped.`);
         }
       });
     });
@@ -118,7 +117,7 @@ const logParameters = req => {
   }
   if (logMessage) {
     logMessage = `Request to ${req.path}\n` + logMessage;
-    log(logMessage);
+    log.info(logMessage);
   }
 };
 
@@ -134,15 +133,15 @@ const createSendResponseCallback = (handlerResponse, responseData, delayMs) => {
   return async() => {
     const returnStatus = responseData['status'] || 200;
     if (delayMs) {
-      log(`Delaying response for ${delayMs}ms`);
+      log.info(`Delaying response for ${delayMs}ms`);
       await setTimeout(() => {
         handlerResponse
           .status(returnStatus)
           .set(responseData['headers'])
           .jsonp(responseData['data']);
       }, delayMs);
     } else {
-      log('Returning immediate response');
+      log.info('Returning immediate response');
       handlerResponse
         .status(returnStatus)
         .set(responseData['headers'])

standalone/index.js

@@ -1,12 +1,12 @@
 const getPort = require('get-port');
 const argv = require('yargs').argv;
 const fs = require('fs');
-const log = require('../lib/log');
+const { log } = require('../lib/logging');
 
 const AietesServer = require('../mock-server');
 
 const standalone = async() => {
-  log('Starting Aietes standalone');
+  log.info('Starting Aietes standalone');
 
   const port = argv.port || await getPort();
 
@@ -16,8 +16,8 @@ const standalone = async() => {
     try {
       jsonResponse = JSON.parse(fs.readFileSync(responseFileName, 'utf8'));
     } catch (err) {
-      console.error(err.message);
-      console.error(`Reading response definition file '${responseFileName}' failed. Aietes exiting.`);
+      log.error(err.message);
+      log.error(`Reading response definition file '${responseFileName}' failed. Aietes exiting.`);
       process.exit(1);
     }
   }

test/logging.test.js

@@ -0,0 +1,59 @@
+const { log } = require('../lib/logging');
+
+describe('logging facade', () => {
+  it('should pass info to the console.log and prepend with Aietes', () => {
+    const infoMock = jest.fn();
+    console.log = infoMock;
+
+    log.info('message');
+
+    expect(infoMock).toHaveBeenCalled();
+    expect(infoMock).toHaveBeenCalledWith('[Aietes] message');
+  });
+
+  it('should pass warn to the console.warn and prepend with Aietes', () => {
+    const warnMock = jest.fn();
+    console.warn = warnMock;
+
+    log.warn('message');
+
+    expect(warnMock).toHaveBeenCalled();
+    expect(warnMock).toHaveBeenCalledWith('[Aietes] message');
+  });
+
+  it('should pass calls to info to the console and prepend with Aietes', () => {
+    const errorMock = jest.fn();
+    console.error = errorMock;
+
+    log.error('message');
+
+    expect(errorMock).toHaveBeenCalled();
+    expect(errorMock).toHaveBeenCalledWith('[Aietes] message');
+  });
+
+  it('should skip console calls for info and warn if environment variable is set', () => {
+    const OLD_ENV = process.env;
+    jest.resetModules(); // this is important - it clears the cache
+    process.env = { ...OLD_ENV };
+    delete process.env.NODE_ENV;
+
+    process.env.NO_OUTPUT = true;
+
+    const infoMock = jest.fn();
+    console.log = infoMock;
+    const warnMock = jest.fn();
+    console.warn = warnMock;
+    const errorMock = jest.fn();
+    console.error = errorMock;
+
+    log.info('info');
+    log.warn('warn');
+    log.error('error');
+
+    expect(infoMock).toHaveBeenCalledTimes(0);
+    expect(warnMock).toHaveBeenCalledTimes(0);
+    expect(errorMock).toHaveBeenCalledTimes(1);
+
+    process.env = OLD_ENV;
+  });
+});