From aa982ba39bbad4ee92d36b30e9bd332565992949 Mon Sep 17 00:00:00 2001 From: Ryan Ahearn Date: Thu, 21 Jan 2021 16:59:52 -0500 Subject: [PATCH 1/2] Add an audit logger label for AU-2 required messages --- src/app.js | 9 ++-- src/index.js | 4 +- src/lib/apiErrorHandler.js | 2 +- src/lib/updateGrantsGrantees.js | 6 +-- src/logger.js | 49 ++++++++++++++----- src/middleware/authMiddleware.js | 2 + src/middleware/userAdminAccessMiddleware.js | 7 ++- .../userAdminAccessMiddleware.test.js | 24 ++++++--- src/routes/admin/user.js | 4 ++ src/routes/apiDirectory.js | 3 ++ src/services/accessValidation.js | 37 ++++++-------- src/services/accessValidation.test.js | 25 ++++------ src/tools/bootstrapAdmin.js | 4 +- src/tools/bootstrapAdminCLI.js | 4 +- 14 files changed, 110 insertions(+), 70 deletions(-) diff --git a/src/app.js b/src/app.js index 5835bf97e8..acc92b0c87 100644 --- a/src/app.js +++ b/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}`); } }; diff --git a/src/index.js b/src/index.js index 876bc38914..955970674c 100644 --- a/src/index.js +++ b/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; diff --git a/src/lib/apiErrorHandler.js b/src/lib/apiErrorHandler.js index 7eb9aa8cc1..f9e20a78f5 100644 --- a/src/lib/apiErrorHandler.js +++ b/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 diff --git a/src/lib/updateGrantsGrantees.js b/src/lib/updateGrantsGrantees.js index 41eaa1aa39..321f910757 100644 --- a/src/lib/updateGrantsGrantees.js +++ b/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); } } diff --git a/src/logger.js b/src/logger.js index 0e90da15c5..db26ff7baf 100644 --- a/src/logger.js +++ b/src/logger.js @@ -1,5 +1,5 @@ import {} from 'dotenv/config'; -import winston from 'winston'; +import { format, transports, createLogger } from 'winston'; import expressWinston from 'express-winston'; import env from './env'; @@ -7,33 +7,56 @@ 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; diff --git a/src/middleware/authMiddleware.js b/src/middleware/authMiddleware.js index ea6627f4e8..8204f19f2b 100644 --- a/src/middleware/authMiddleware.js +++ b/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) { diff --git a/src/middleware/userAdminAccessMiddleware.js b/src/middleware/userAdminAccessMiddleware.js index 967668c877..261fd7a877 100644 --- a/src/middleware/userAdminAccessMiddleware.js +++ b/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); } diff --git a/src/middleware/userAdminAccessMiddleware.test.js b/src/middleware/userAdminAccessMiddleware.test.js index 102f14a772..93b46022ac 100644 --- a/src/middleware/userAdminAccessMiddleware.test.js +++ b/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,37 @@ const mockResponse = { end: jest.fn(), })), }; +let user; describe('userAdminAccessMiddleware', () => { afterEach(() => { jest.clearAllMocks(); }); - afterAll(() => { + beforeEach(async () => { + user = (await User.findOrCreate({ + where: { + email: "admin@acf.hhs.gov", + }, + }))[0]; + + 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); diff --git a/src/routes/admin/user.js b/src/routes/admin/user.js index 7df2297319..79014eee31 100644 --- a/src/routes/admin/user.js +++ b/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); diff --git a/src/routes/apiDirectory.js b/src/routes/apiDirectory.js index 9a600eaceb..26ae51f550 100644 --- a/src/routes/apiDirectory.js +++ b/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); }); diff --git a/src/services/accessValidation.js b/src/services/accessValidation.js index 866be62380..dc9f169a75 100644 --- a/src/services/accessValidation.js +++ b/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; } diff --git a/src/services/accessValidation.test.js b/src/services/accessValidation.test.js index fc3789a736..d914f896d7 100644 --- a/src/services/accessValidation.test.js +++ b/src/services/accessValidation.test.js @@ -1,11 +1,5 @@ import db, { User, Permission, sequelize } from '../models'; import findOrCreateUser, { validateUserAuthForAdmin } from './accessValidation'; -import logger from '../logger'; - -jest.mock('../logger', () => ( - { - error: jest.fn(), - })); const mockUser = { id: 47, @@ -112,15 +106,16 @@ describe('accessValidation', () => { await expect(() => findOrCreateUser(undefined)).rejects.toBeInstanceOf(Error); }); - it('Logs an error message on error', async () => { - const user = { - hsesUserId: '33', - email: 'invalid', - 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'); - }); + // I cannot figure out how to mock out a named import properly. + // it('Logs an error message on error', async () => { + // const user = { + // hsesUserId: '33', + // email: 'invalid', + // homeRegionId: 3, + // }; + // await expect(findOrCreateUser(user)).rejects.toThrow(); + // expect(mockLogger.error).toHaveBeenCalledWith('SERVICE:ACCESS_VALIDATION - Error finding or creating user in database - SequelizeValidationError: Validation error: Validation isEmail on email failed'); + // }); }); describe('validateUserAuthForAdmin', () => { it('returns true if a user has admin priviledges', async () => { diff --git a/src/tools/bootstrapAdmin.js b/src/tools/bootstrapAdmin.js index a6676445a0..cdd15e7c17 100644 --- a/src/tools/bootstrapAdmin.js +++ b/src/tools/bootstrapAdmin.js @@ -1,5 +1,5 @@ import { User, Permission } from '../models'; -import logger from '../logger'; +import { auditLogger } from '../logger'; import SCOPES from '../middleware/scopeConstants'; const { ADMIN } = SCOPES; @@ -20,7 +20,7 @@ const bootstrapAdmin = async () => { }, }); if (created) { - logger.warn(`SECURITY ALERT: Setting ${ADMIN_EMAIL} as an ADMIN`); + auditLogger.warn(`Setting ${ADMIN_EMAIL} as an ADMIN`); } return permission; }; diff --git a/src/tools/bootstrapAdminCLI.js b/src/tools/bootstrapAdminCLI.js index 080395fcfe..9f9dde254f 100644 --- a/src/tools/bootstrapAdminCLI.js +++ b/src/tools/bootstrapAdminCLI.js @@ -1,4 +1,5 @@ import bootstrapAdmin from './bootstrapAdmin'; +import { auditLogger } from '../logger'; /** * bootstrapAdminCLI is responsible for setting the first ADMIN for TTA Smart Hub. @@ -10,7 +11,6 @@ import bootstrapAdmin from './bootstrapAdmin'; * Open a new issue and PR to update the ADMIN_EMAIL constant within bootstrapAdmin.js */ bootstrapAdmin().catch((e) => { - // eslint-disable-next-line no-console - console.log(e); + auditLogger.error(e); return process.exit(1); }); From 876e5fc77cc8e61b71fd031cb183fef25ef99865 Mon Sep 17 00:00:00 2001 From: Ryan Ahearn Date: Fri, 22 Jan 2021 09:10:03 -0500 Subject: [PATCH 2/2] Fix the accessValidation audit log test --- .../userAdminAccessMiddleware.test.js | 14 ++++++---- src/services/accessValidation.test.js | 27 ++++++++++++------- 2 files changed, 26 insertions(+), 15 deletions(-) diff --git a/src/middleware/userAdminAccessMiddleware.test.js b/src/middleware/userAdminAccessMiddleware.test.js index 93b46022ac..8e9913d83f 100644 --- a/src/middleware/userAdminAccessMiddleware.test.js +++ b/src/middleware/userAdminAccessMiddleware.test.js @@ -28,21 +28,25 @@ describe('userAdminAccessMiddleware', () => { jest.clearAllMocks(); }); beforeEach(async () => { - user = (await User.findOrCreate({ + [user] = await User.findOrCreate({ where: { - email: "admin@acf.hhs.gov", + email: 'admin@acf.hhs.gov', }, - }))[0]; + }); mockSession.userId = user.id; }); afterAll(async () => { - await User.destroy({ where: {id: user.id} }); + await User.destroy({ where: { id: user.id } }); db.sequelize.close(); }); it('should allow access if an user has an admin role', async () => { - const admin = await Permission.create({scopeId: ADMIN, userId: user.id, regionId: 14}); + const admin = await Permission.create({ + scopeId: ADMIN, + userId: user.id, + regionId: 14, + }); await userAdminAccessMiddleware(mockRequest, mockResponse, mockNext); diff --git a/src/services/accessValidation.test.js b/src/services/accessValidation.test.js index d914f896d7..25d1f404ca 100644 --- a/src/services/accessValidation.test.js +++ b/src/services/accessValidation.test.js @@ -1,5 +1,13 @@ import db, { User, Permission, sequelize } from '../models'; import findOrCreateUser, { validateUserAuthForAdmin } from './accessValidation'; +import { auditLogger } from '../logger'; + +jest.mock('../logger', () => ({ + auditLogger: { + error: jest.fn(), + info: jest.fn(), + }, +})); const mockUser = { id: 47, @@ -106,16 +114,15 @@ describe('accessValidation', () => { await expect(() => findOrCreateUser(undefined)).rejects.toBeInstanceOf(Error); }); - // I cannot figure out how to mock out a named import properly. - // it('Logs an error message on error', async () => { - // const user = { - // hsesUserId: '33', - // email: 'invalid', - // homeRegionId: 3, - // }; - // await expect(findOrCreateUser(user)).rejects.toThrow(); - // expect(mockLogger.error).toHaveBeenCalledWith('SERVICE:ACCESS_VALIDATION - Error finding or creating user in database - SequelizeValidationError: Validation error: Validation isEmail on email failed'); - // }); + it('Logs an error message on error', async () => { + const user = { + hsesUserId: '33', + email: 'invalid', + homeRegionId: 3, + }; + await expect(findOrCreateUser(user)).rejects.toThrow(); + expect(auditLogger.error).toHaveBeenCalledWith('SERVICE:ACCESS_VALIDATION - Error finding or creating user in database - SequelizeValidationError: Validation error: Validation isEmail on email failed'); + }); }); describe('validateUserAuthForAdmin', () => { it('returns true if a user has admin priviledges', async () => {