Merge pull request #262 from adhocteam/main

Add extra audit logging messages

src/app.js

@@ -12,7 +12,7 @@ import updateGrantsGrantees from './lib/updateGrantsGrantees';
 
 import findOrCreateUser from './services/accessValidation';
 
-import logger, { requestLogger } from './logger';
+import logger, { auditLogger, requestLogger } from './logger';
 
 const app = express();
 
@@ -58,11 +58,12 @@ app.get(oauth2CallbackPath, async (req, res) => {
     });
 
     req.session.userId = dbUser.id;
+    auditLogger.info(`User ${dbUser.id} logged in`);
 
-    logger.info(`role: ${req.session.userId} ${req.session.referrerPath}`);
+    logger.debug(`referrer path: ${req.session.referrerPath}`);
     res.redirect(join(process.env.TTA_SMART_HUB_URI, req.session.referrerPath));
   } catch (error) {
-    logger.error(`Error logging in: ${error}`);
+    auditLogger.error(`Error logging in: ${error}`);
     res.status(INTERNAL_SERVER_ERROR).end();
   }
 });
@@ -82,7 +83,7 @@ const runJob = () => {
   try {
     updateGrantsGrantees();
   } catch (error) {
-    logger.error(`Error processing HSES file: ${error}`);
+    auditLogger.error(`Error processing HSES file: ${error}`);
   }
 };
 

src/index.js

@@ -2,12 +2,12 @@ require('newrelic');
 
 /* eslint-disable import/first */
 import app from './app';
-import logger from './logger';
+import { auditLogger } from './logger';
 /* eslint-enable import/first */
 
 const port = process.env.PORT || 8080;
 const server = app.listen(port, () => {
-  logger.info(`Listening on port ${port}`);
+  auditLogger.info(`Listening on port ${port}`);
 });
 
 module.exports = server;

src/lib/apiErrorHandler.js

@@ -1,7 +1,7 @@
 import { INTERNAL_SERVER_ERROR } from 'http-codes';
 import Sequelize from 'sequelize';
 import createRequestError from '../services/requestErrors';
-import logger from '../logger';
+import { auditLogger as logger } from '../logger';
 
 /**
  * Handles sequelize errors

src/lib/updateGrantsGrantees.js

@@ -5,7 +5,7 @@ import axios from 'axios';
 import {
   Grantee, Grant,
 } from '../models';
-import logger from '../logger';
+import { auditLogger } from '../logger';
 
 const fs = require('mz/fs');
 /**
@@ -85,7 +85,7 @@ export async function processFiles() {
         updateOnDuplicate: ['number', 'regionId', 'granteeId', 'status', 'startDate', 'endDate', 'updatedAt'],
       });
   } catch (error) {
-    logger.error(`Error reading or updating database on HSES data import: ${error.message}`);
+    auditLogger.error(`Error reading or updating database on HSES data import: ${error.message}`);
     throw error;
   }
 }
@@ -119,6 +119,6 @@ export default async function updateGrantsGrantees() {
 
     await processFiles();
   } catch (error) {
-    logger.error(error);
+    auditLogger.error(error);
   }
 }

src/logger.js

@@ -1,39 +1,62 @@
 import {} from 'dotenv/config';
-import winston from 'winston';
+import { format, transports, createLogger } from 'winston';
 import expressWinston from 'express-winston';
 import env from './env';
 
 const formatFunc = ({
   level, message, label, timestamp, meta = {},
 }) => `${timestamp} ${label || '-'} ${level}: ${message} ${JSON.stringify(meta)}`;
 
-const stringFormatter = winston.format.combine(
-  winston.format.timestamp(),
-  winston.format.colorize(),
-  winston.format.align(),
-  winston.format.printf(formatFunc),
+const stringFormatter = format.combine(
+  format.timestamp(),
+  format.colorize(),
+  format.align(),
+  format.printf(formatFunc),
 );
 
-const jsonFormatter = winston.format.combine(
-  winston.format.timestamp(),
-  winston.format.json(),
+const jsonFormatter = format.combine(
+  format.timestamp(),
+  format.json(),
 );
 
 const formatter = env.bool('LOG_JSON_FORMAT') ? jsonFormatter : stringFormatter;
 
-const logger = winston.createLogger({
+const logger = createLogger({
   level: process.env.LOG_LEVEL,
   format: formatter,
   transports: [
-    new winston.transports.Console(),
+    new transports.Console(),
+  ],
+});
+
+export const auditLogger = createLogger({
+  level: 'info',
+  format: format.combine(
+    format.label({ label: 'AUDIT' }),
+    formatter,
+  ),
+  transports: [
+    new transports.Console(),
   ],
 });
 
 export const requestLogger = expressWinston.logger({
   transports: [
-    new winston.transports.Console(),
+    new transports.Console(),
   ],
-  format: formatter,
+  format: format.combine(
+    format.label({ label: 'REQUEST' }),
+    formatter,
+  ),
+  dynamicMeta: (req) => {
+    if (req && req.session) {
+      const { userId } = req.session;
+      return {
+        userId,
+      };
+    }
+    return {};
+  },
 });
 
 export default logger;

src/middleware/authMiddleware.js

@@ -1,5 +1,6 @@
 import {} from 'dotenv/config';
 import ClientOAuth2 from 'client-oauth2';
+import { auditLogger } from '../logger';
 
 export const hsesAuth = new ClientOAuth2({
   clientId: process.env.AUTH_CLIENT_ID,
@@ -41,6 +42,7 @@ export function login(req, res) {
 export default async function authMiddleware(req, res, next) {
   // bypass authorization, used for cucumber UAT and axe accessibility testing
   if (process.env.NODE_ENV !== 'production' && process.env.BYPASS_AUTH === 'true') {
+    auditLogger.warn(`Bypassing authentication in authMiddleware - using User ${process.env.CURRENT_USER_ID}`);
     req.session.userId = process.env.CURRENT_USER_ID;
   }
   if (!req.session.userId) {

src/middleware/userAdminAccessMiddleware.js

@@ -1,5 +1,6 @@
 import httpCodes from 'http-codes';
 import { validateUserAuthForAdmin } from '../services/accessValidation';
+import { auditLogger } from '../logger';
 import handleErrors from '../lib/apiErrorHandler';
 
 /**
@@ -14,7 +15,11 @@ import handleErrors from '../lib/apiErrorHandler';
  */
 export default async function userAdminAccessMiddleware(req, res, next) {
   try {
-    if (!(await validateUserAuthForAdmin(req))) {
+    const { userId } = req.session;
+    if ((await validateUserAuthForAdmin(req))) {
+      auditLogger.info(`User ${userId} successfully checked ADMIN access`);
+    } else {
+      auditLogger.error(`User ${userId} attempted to access an ADMIN route without permission`);
       // consider sending a 404 rather than a 403 (Forbidden) to avoid confirming route
       return res.sendStatus(httpCodes.FORBIDDEN);
     }

src/middleware/userAdminAccessMiddleware.test.js

@@ -1,13 +1,15 @@
 import {} from 'dotenv/config';
-import db from '../models';
+import db, { User, Permission } from '../models';
 import userAdminAccessMiddleware from './userAdminAccessMiddleware';
 import handleErrors from '../lib/apiErrorHandler';
+import SCOPES from './scopeConstants';
+
+const { ADMIN } = SCOPES;
 
 jest.mock('../lib/apiErrorHandler', () => jest.fn().mockReturnValue(() => Promise.resolve()));
 
 const mockNext = jest.fn();
 const mockSession = jest.fn();
-mockSession.userId = 2;
 const mockRequest = {
   path: '/api/endpoint',
   session: mockSession,
@@ -19,27 +21,41 @@ const mockResponse = {
     end: jest.fn(),
   })),
 };
+let user;
 
 describe('userAdminAccessMiddleware', () => {
   afterEach(() => {
     jest.clearAllMocks();
   });
-  afterAll(() => {
+  beforeEach(async () => {
+    [user] = await User.findOrCreate({
+      where: {
+        email: '[email protected]',
+      },
+    });
+
+    mockSession.userId = user.id;
+  });
+  afterAll(async () => {
+    await User.destroy({ where: { id: user.id } });
     db.sequelize.close();
   });
 
   it('should allow access if an user has an admin role', async () => {
-    mockSession.role = 'admin';
+    const admin = await Permission.create({
+      scopeId: ADMIN,
+      userId: user.id,
+      regionId: 14,
+    });
 
     await userAdminAccessMiddleware(mockRequest, mockResponse, mockNext);
 
     expect(mockResponse.sendStatus).not.toHaveBeenCalled();
     expect(mockNext).toHaveBeenCalled();
+    await admin.destroy();
   });
 
   it('should return 403 if an user does not have an admin permission', async () => {
-    mockSession.role = undefined;
-
     await userAdminAccessMiddleware(mockRequest, mockResponse, mockNext);
 
     expect(mockResponse.sendStatus).toHaveBeenCalledWith(403);

src/routes/admin/user.js

@@ -3,6 +3,7 @@ import {
 } from '../../models';
 import { userById } from '../../services/users';
 import handleErrors from '../../lib/apiErrorHandler';
+import { auditLogger } from '../../logger';
 
 const namespace = 'SERVICE:USER';
 
@@ -62,6 +63,7 @@ export async function createUser(req, res) {
           include: [{ model: Permission, as: 'permissions', attributes: ['userId', 'scopeId', 'regionId'] }],
         }, transaction);
     });
+    auditLogger.info(`User ${req.session.userId} created new User: ${user.id}`);
     res.json(user);
   } catch (error) {
     await handleErrors(req, res, error, logContext);
@@ -91,6 +93,7 @@ export async function updateUser(req, res) {
       await Permission.bulkCreate(requestUser.permissions,
         { transaction: t });
     });
+    auditLogger.warn(`User ${req.session.userId} updated User: ${userId} and set permissions: ${JSON.stringify(requestUser.permissions)}`);
     const user = await userById(userId);
     res.json(user);
   } catch (error) {
@@ -106,6 +109,7 @@ export async function updateUser(req, res) {
  */
 export async function deleteUser(req, res) {
   const { userId } = req.params;
+  auditLogger.info(`User ${req.session.userId} deleting User: ${userId}`);
   try {
     const result = await User.destroy({ where: { id: userId } });
     res.json(result);

src/routes/apiDirectory.js

@@ -7,6 +7,7 @@ import handleErrors from '../lib/apiErrorHandler';
 import adminRouter from './user';
 import activityReportsRouter from './activityReports';
 import { userById } from '../services/users';
+import { auditLogger } from '../logger';
 
 export const loginPath = '/login';
 
@@ -34,6 +35,8 @@ router.get('/user', async (req, res) => {
 });
 
 router.get('/logout', (req, res) => {
+  const { userId } = req.session;
+  auditLogger.info(`User ${userId} logged out`);
   req.session = null;
   res.sendStatus(204);
 });

src/services/accessValidation.js

@@ -1,5 +1,5 @@
 import { User, Permission, sequelize } from '../models';
-import logger from '../logger';
+import { auditLogger as logger } from '../logger';
 import SCOPES from '../middleware/scopeConstants';
 
 const { ADMIN } = SCOPES;
@@ -24,33 +24,28 @@ export default function findOrCreateUser(data) {
       ...data,
     },
     transaction,
-  }) // findOrCreate API returns 2 values (instance, created). We only need to return the first.
-    .then((result) => result[0])
-    .catch((error) => {
-      const msg = `Error finding or creating user in database - ${error}`;
-      logger.error(`${namespace} - ${msg}`);
-      throw new Error(msg);
-    }));
+  }).then(([user, created]) => {
+    if (created) {
+      logger.info(`Created user ${user.id} with no access permissions`);
+    }
+    return user;
+  }).catch((error) => {
+    const msg = `Error finding or creating user in database - ${error}`;
+    logger.error(`${namespace} - ${msg}`);
+    throw new Error(msg);
+  }));
 }
 
 export async function validateUserAuthForAdmin(req) {
-  let result = false;
   const { userId } = req.session;
-  const { role } = req.session;
-  let userPermissions;
   try {
-    if (role && role === 'admin') {
-      result = true;
-    } else {
-      userPermissions = await Permission.findAll({
-        attributes: ['scopeId'],
-        where: { userId },
-      });
-      result = userPermissions.some((permission) => (permission.scopeId === ADMIN));
-    }
+    const userPermissions = await Permission.findAll({
+      attributes: ['scopeId'],
+      where: { userId },
+    });
+    return userPermissions.some((permission) => (permission.scopeId === ADMIN));
   } catch (error) {
     logger.error(`${JSON.stringify({ ...logContext })} - Access error - ${error}`);
     throw error;
   }
-  return result;
 }

src/services/accessValidation.test.js

@@ -1,11 +1,13 @@
 import db, { User, Permission, sequelize } from '../models';
 import findOrCreateUser, { validateUserAuthForAdmin } from './accessValidation';
-import logger from '../logger';
+import { auditLogger } from '../logger';
 
-jest.mock('../logger', () => (
-  {
+jest.mock('../logger', () => ({
+  auditLogger: {
     error: jest.fn(),
-  }));
+    info: jest.fn(),
+  },
+}));
 
 const mockUser = {
   id: 47,
@@ -119,7 +121,7 @@ describe('accessValidation', () => {
         homeRegionId: 3,
       };
       await expect(findOrCreateUser(user)).rejects.toThrow();
-      expect(logger.error).toHaveBeenCalledWith('SERVICE:ACCESS_VALIDATION - Error finding or creating user in database - SequelizeValidationError: Validation error: Validation isEmail on email failed');
+      expect(auditLogger.error).toHaveBeenCalledWith('SERVICE:ACCESS_VALIDATION - Error finding or creating user in database - SequelizeValidationError: Validation error: Validation isEmail on email failed');
     });
   });
   describe('validateUserAuthForAdmin', () => {