PP-5324: supplement production logs with request info

* add user id, toolbox id and services correlation id
* only expose information if it exists
* update dev logs to include user id

src/lib/logger.ts

@@ -17,6 +17,10 @@ import * as config from '../config'
 
 const { combine, timestamp, printf } = format
 
+const TOOLBOX_ID_KEY = 'toolbox_id'
+const CORRELATION_ID_KEY = 'correlation_id'
+const AUTHENTICATED_USER_ID_KEY = 'authenticated_user_id'
+
 const logger = createLogger()
 const session = createNamespace('govuk-pay-logging')
 
@@ -25,22 +29,40 @@ const loggerMiddleware = function loggerMiddleware(
   res: Response,
   next: NextFunction
 ): void {
-  session.run(() => {
-    session.set('toolboxid', crypto.randomBytes(4).toString('hex'))
+  session.run((): void => {
+    const correlationHeader = 'x-request-id'
+    session.set(TOOLBOX_ID_KEY, crypto.randomBytes(4).toString('hex'))
+    session.set(CORRELATION_ID_KEY, req.headers[correlationHeader])
+    session.set(AUTHENTICATED_USER_ID_KEY, req.user && req.user.user)
     next()
   })
 }
 
+const supplementProductionInfo = format((info) => {
+  const productionContext = {
+    toolboxId: session.get(TOOLBOX_ID_KEY),
+    correlationId: session.get(CORRELATION_ID_KEY),
+    userId: session.get(AUTHENTICATED_USER_ID_KEY)
+  }
+  return Object.assign(info, productionContext)
+})
+
 if (!config.common.development) {
   const productionTransport = new transports.Console({
+    format: combine(
+      supplementProductionInfo(),
+      timestamp({ format: 'HH:mm:ss' }),
+      format.json()
+    ),
     level: 'info'
   })
   logger.add(productionTransport)
 }
 
 const payLogsFormatter = printf((log) => {
-  const id = session.get('toolboxid')
-  return `${log.timestamp} [${id || '(none)'}] ${log.level}: ${log.message}`
+  const id = session.get('toolbox_id')
+  const user = session.get('authenticated_user_id')
+  return `${log.timestamp} [${id || '(none)'}] [${user || '(no_user)'}] ${log.level}: ${log.message}`
 })
 
 // coloursise and timestamp developer logs as these will probably be viewed

src/web/server.js

@@ -38,8 +38,6 @@ const configureSecureHeaders = function configureSecureHeaders(instance) {
 }
 
 const configureRequestParsing = function configureRequestParsing(instance) {
-  const httpRequestLoggingFormat = common.production ? 'short' : 'dev'
-
   if (!common.development) {
     // service is behind a front-facing proxy - set req IP values accordinglyi
     instance.enable('trust proxy')
@@ -48,11 +46,6 @@ const configureRequestParsing = function configureRequestParsing(instance) {
   instance.use(bodyParser.urlencoded({ extended: false }))
   instance.use(bodyParser.json({ strict: true, limit: '15kb' }))
   instance.use(flash())
-
-  // logger middleware included after flash and body parsing middleware as they
-  // alter the call stack (it should ideally be placed just before routes)
-  instance.use(logger.middleware)
-  instance.use(morgan(httpRequestLoggingFormat, { stream: logger.stream }))
 }
 
 const configureServingPublicStaticFiles = function configureServingPublicStaticFiles(instance) {
@@ -96,7 +89,16 @@ const configureTemplateRendering = function configureTemplateRendering(instance)
   instance.set('view engine', 'njk')
 }
 
+// @TODO(sfount) double check that errors thrown by CSRF prevention etc. have enough information to log
+// -- putting this so late in the stack might mean those logs fail
 const configureRouting = function configureRouting(instance) {
+  const httpRequestLoggingFormat = common.development ? 'dev' : 'common'
+
+  // logger middleware included after flash and body parsing middleware as they
+  // alter the call stack (it should ideally be placed just before routes)
+  instance.use(logger.middleware)
+  instance.use(morgan(httpRequestLoggingFormat, { stream: logger.stream }))
+
   instance.use('/', router)
   instance.use(errors.handleNotFound)
 }