ROC-1105: Request tracing (#22)

.travis.yml

@@ -4,10 +4,6 @@ script:
 - yarn --version
 - yarn check --integrity
 - yarn test
-before_install:
-- yarn global add greenkeeper-lockfile@1
-before_script: greenkeeper-lockfile-update
-after_script: greenkeeper-lockfile-upload
 deploy:
   provider: npm
   email: [email protected]

README.md

@@ -1,53 +1,62 @@
-## Logging
+# Node.js Logging
 
 [![Greenkeeper badge](https://badges.greenkeeper.io/hmcts/nodejs-logging.svg)](https://greenkeeper.io/)
 
-* There are 8 log levels: ALL, TRACE, DEBUG, INFO, WARN, ERROR, FATAL and OFF.
-* A level can be set via an environment variable LOG_LEVEL, the default is**info**.
-* There are 2 types of logging output which is set via an environment variable LOG_OUTPUT, the default is**single**.
-  1. Production - a single line output - LOG_OUTPUT=single.
-  2. Development - a multi line output - LOG_OUTPUT=multi.
-* By default logging is turned off when running these unit tests.
+A logging component used by Reform's Node.js applications. Some background info:
+* there are 8 log levels: `ALL`, `TRACE`, `DEBUG`, `INFO`, `WARN`, `ERROR`, `FATAL` and `OFF`.
+* a level can be set via an environment variable `LOG_LEVEL`, the default is `INFO`.
+* there are 3 types of logging output which is set via an environment variable `LOG_OUTPUT`, the default is `human`:
+  - `human` - single line of a human readable output
+  - `single` - a single line of JSON output
+  - `multi` - a multiline formatted JSON output
+* by default logging is turned off when running the unit tests.
 
-#### Use
+## Usage
 
-```
+Add it as your project's dependency:
+
+```bash
 yarn add @hmcts/nodejs-logging
 ```
 
-```
-// Require it
-const logging = require('nodejs-logging');
-```
+Require it:
 
+```javascript
+const { Logger } = require('@hmcts/nodejs-logging')
 ```
-// Set this config only once
-logging.config({ 
+
+Set the logging configuration. Should be done once at application startup:
+
+```javascript
+Logger.config({ 
     microservice: 'your-service-name', 
-    team: 'YOURTEAM'
+    team: 'your-team',
     environment: 'some-environemnt'
-});
+})
 ```
 
-```
-// Get your logger
-logger = logging.getLogger('app.js');
-```
+Then you can create a logger instance and use it to log information:
 
-```
-// Get logging
-  logger.info({
-    message: 'Yay, logging!'
-  });
+```javascript
+const logger = Logger.getLogger('app.js') // app.js is just an example, can be anything that's meaningful to you
+
+logger.info({
+  message: 'Yay, logging!'
+})
 ```
 
-Optionally you can use the built in express.js access logger.
+### Access logging for Express applications 
 
+Optionally you can use the built-in Express access logger:
+
+```javascript
+const { Express } = require('@hmcts/nodejs-logging')
+
+app.use(Express.accessLogger())
 ```
-app.use(logging.express.accessLogger());
-```
 
-A typical HTTP 404 log error when encountering an error would look like the following.
+It will log all requests made against your application. For example, a typical HTTP 404 log error when encountering an error would look like the following:
+
 ```
 {
   responseCode: 404,
@@ -61,14 +70,45 @@ A typical HTTP 404 log error when encountering an error would look like the foll
   originRequestId: '',
   type: 'nodejs',
   microservice: 'your-service-name',
-  team: 'YOURTEAM',
+  team: 'your-team',
   timestamp: '2017-01-27T11:27:23+00:00'
 }
 ```
 
-#### Units Tests
+### Request tracing for Express applications
+
+An Express middleware is provided which automatically populates request headers with request tracing IDs. Sample usage:
+
+```javascript
+const { RequestTracing } = require('@hmcts/nodejs-logging')
+
+app.use(RequestTracing.middleware)
+```
+
+Assuming your Express application servers as the system's entry point which serves user UI, this middleware will intercept user requests and set `Root-Request-Id` and `Request-Id` headers on it. If the incoming request comes from a different service which already populated those values, they will be forwarded.
+
+Apart from populating the headers, access to request tracing information is available at any point during request processing, e.g.:
+
+```javascript
+const id = RequestTracing.getCurrentRequestId()
+```
+
+We can also access the original request:
+
+```javascript
+const request = RequestTracing.retrieveInitialRequest()
+```
+
+These features are enabled by [continuation-local-storage module](https://github.com/othiym23/node-continuation-local-storage).
+
+## Units Tests
+
+Just do
 
 ```
 yarn test
 ```
 
+## License
+
+This project is licensed under the MIT License - see the [LICENSE](LICENSE.md) file for details.

index.js

@@ -1,6 +1,9 @@
 'use strict'
 
-let Logger = require('./log/Logger');
-Logger.express = require('./log/express');
-
-module.exports = Logger;
+module.exports = {
+  Logger: require('./log/Logger'),
+  LoggingConfig: require('./log/config'),
+  RequestTracing: require('./log/tracing/requestTracing'),
+  RequestTracingHeaders: require('./log/tracing/headers'),
+  Express: require('./log/express')
+}

log/Logger.js

@@ -1,6 +1,6 @@
 const merge = require('lodash.merge');
 const moment = require('moment');
-const {logging, outputTypes} = require('./config');
+const { logging, outputTypes } = require('./config');
 const levels = logging.log4js.levels;
 
 let userConfig = {};
@@ -101,8 +101,4 @@ class Logger {
 
 }
 
-class Config {
-
-}
-
 module.exports = Logger;

log/express.js

@@ -1,15 +1,17 @@
 'use strict'
 
 const onFinished = require('on-finished');
+const Logger = require('./Logger')
+const { REQUEST_ID_HEADER, ORIGIN_REQUEST_ID_HEADER, ROOT_REQUEST_ID_HEADER } = require('./tracing/headers')
 
 class AccessLogger {
-  constructor(config={}) {
-    this.logger = config.logger || require('./Logger').getLogger('express.access');
-    this.formatter = config.formatter || this.defaultFormatter;
-    this.userLevel = config.level || function() {};
+  constructor(config = { }) {
+    this.logger = config.logger || Logger.getLogger('express.access');
+    this.formatter = config.formatter || AccessLogger.defaultFormatter;
+    this.userLevel = config.level || AccessLogger.defaultLevel;
   }
 
-  static middleware(config={}) {
+  static middleware(config = { }) {
     const accessLogger = new AccessLogger(config);
 
     return (req, res, next) => {
@@ -25,33 +27,35 @@ class AccessLogger {
     const level = this.level(req, res);
     level.call(this.logger, {
       responseCode: res.statusCode,
-      message: this.formatter(req, res)
+      message: this.formatter(req, res),
+      requestId: req.headers[REQUEST_ID_HEADER],
+      originRequestId: req.headers[ORIGIN_REQUEST_ID_HEADER],
+      rootRequestId: req.headers[ROOT_REQUEST_ID_HEADER]
     });
   }
 
   level(req, res) {
-    return this.userLevel(this.logger, req, res) || this.defaultLevel(req, res);
+    return this.userLevel(this.logger, req, res);
   }
 
-  defaultLevel(req, res) {
-    if (res.statusCode < 400 || res.statusCode == 404) {
-      return this.logger.info;
+  static defaultLevel(logger, req, res) {
+    if (res.statusCode < 400 || res.statusCode === 404) {
+      return logger.info;
     } else if (res.statusCode >= 500) {
-      return this.logger.error;
+      return logger.error;
     } else {
-      return this.logger.warn;
+      return logger.warn;
     }
   }
 
-  defaultFormatter(req, res) {
+  static defaultFormatter(req, res) {
     return '"' + req.method + ' ' + (req.originalUrl || req.url) +
       ' HTTP/' + req.httpVersionMajor + '.' + req.httpVersionMinor + '" ' +
       res.statusCode;
   }
 }
 
-
-
 module.exports = {
+  AccessLoggingHandler: AccessLogger,
   accessLogger: AccessLogger.middleware,
 };

log/tracing/headers.js

@@ -0,0 +1,5 @@
+module.exports = {
+  REQUEST_ID_HEADER: 'Request-Id',
+  ORIGIN_REQUEST_ID_HEADER: 'Origin-Request-Id',
+  ROOT_REQUEST_ID_HEADER: 'Root-Request-Id'
+}

log/tracing/localStorage.js

@@ -0,0 +1,24 @@
+'use strict'
+
+const { createNamespace } = require('continuation-local-storage')
+
+const INITIAL_REQUEST = 'initialRequest'
+
+const clsNamespace = createNamespace('uk.gov.hmcts.reform.tracing.localStorage')
+
+class LocalStorage {
+  static proceedWithinLocalStorageContext (req, res, next) {
+    clsNamespace.run(() => {
+      clsNamespace.bindEmitter(req)
+      clsNamespace.bindEmitter(res)
+      clsNamespace.set(INITIAL_REQUEST, req)
+      next()
+    })
+  }
+
+  static retrieveInitialRequest () {
+    return clsNamespace.get(INITIAL_REQUEST)
+  }
+}
+
+module.exports = LocalStorage

log/tracing/requestTracing.js

@@ -0,0 +1,51 @@
+'use strict'
+
+const uuid = require('uuid')
+
+const LocalStorage = require('./localStorage')
+const { REQUEST_ID_HEADER, ROOT_REQUEST_ID_HEADER, ORIGIN_REQUEST_ID_HEADER } = require('./headers')
+
+function setInitialRequestTracingHeaders (req) {
+  const id = uuid()
+  req.headers[REQUEST_ID_HEADER] = id
+  req.headers[ROOT_REQUEST_ID_HEADER] = id
+  req.headers[ORIGIN_REQUEST_ID_HEADER] = undefined
+}
+
+function tracingHeadersNotPresentOrInvalid (req) {
+  return notUUID(req.headers[REQUEST_ID_HEADER])
+    || notUUID(req.headers[ROOT_REQUEST_ID_HEADER])
+    || notUUID(req.headers[ORIGIN_REQUEST_ID_HEADER])
+}
+
+function notUUID (uuidString) {
+  const UUID_REGEX = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/
+  return !UUID_REGEX.test(uuidString)
+}
+
+class RequestTracing {
+  static middleware (req, res, next) {
+    if (tracingHeadersNotPresentOrInvalid(req)) {
+      setInitialRequestTracingHeaders(req)
+    }
+    LocalStorage.proceedWithinLocalStorageContext(req, res, next)
+  }
+
+  static getInitialRequest () {
+    return LocalStorage.retrieveInitialRequest()
+  }
+
+  static getRootRequestId () {
+    return RequestTracing.getInitialRequest().headers[ROOT_REQUEST_ID_HEADER]
+  }
+
+  static getCurrentRequestId () {
+    return RequestTracing.getInitialRequest().headers[REQUEST_ID_HEADER]
+  }
+
+  static createNextRequestId () {
+    return uuid()
+  }
+}
+
+module.exports = RequestTracing

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@hmcts/nodejs-logging",
-  "version": "1.4.3",
+  "version": "2.0.0",
   "description": "",
   "main": "Logger.js",
   "scripts": {
@@ -13,10 +13,12 @@
   "author": "HMCTS",
   "license": "MIT",
   "dependencies": {
+    "continuation-local-storage": "^3.2.1",
     "lodash.merge": "^4.6.0",
     "log4js": "^2.3.5",
     "moment": "^2.19.3",
-    "on-finished": "^2.3.0"
+    "on-finished": "^2.3.0",
+    "uuid": "^3.1.0"
   },
   "devDependencies": {
     "chai": "^4.1.2",

test/unit/accessLogger.js

@@ -0,0 +1,23 @@
+/* global describe, it */
+
+const expect = require('chai').expect;
+
+const AccessLogger = require('../../log/express').AccessLoggingHandler;
+const Logger = require('../../log/Logger')
+
+describe('AccessLogger', () => {
+  it('should have a default logger', () => {
+    const accessLogger = new AccessLogger()
+    expect(accessLogger.logger).to.be.instanceOf(Logger)
+  })
+
+  it('should have a default formatter', () => {
+    const accessLogger = new AccessLogger()
+    expect(accessLogger.formatter).to.be.instanceOf(Function)
+  })
+
+  it('should have a default level function', () => {
+    const accessLogger = new AccessLogger()
+    expect(accessLogger.level).to.be.instanceOf(Function)
+  })
+})