diff --git a/app-routes.js b/app-routes.js index 8ff3f0b..e4c46fe 100644 --- a/app-routes.js +++ b/app-routes.js @@ -6,12 +6,39 @@ const _ = require("lodash"); const config = require("config"); const HttpStatus = require("http-status-codes"); const { v4: uuid } = require('uuid'); +const util = require("util"); const helper = require("./src/common/helper"); const errors = require("./src/common/errors"); const logger = require("./src/common/logger"); const routes = require("./src/routes"); const authenticator = require("tc-core-library-js").middleware.jwtAuthenticator; +const sanitizeForLog = (value) => { + const seen = new WeakSet(); + try { + return JSON.parse( + JSON.stringify(value, (key, val) => { + if (typeof val === "object" && val !== null) { + if (seen.has(val)) return ""; + seen.add(val); + } + if (Buffer.isBuffer(val)) return ``; + if (val && typeof val === "object" && val.type === "Buffer" && Array.isArray(val.data)) { + return ``; + } + if (Array.isArray(val) && val.length > 30) return `Array(${val.length})`; + if (typeof val === "string" && val.length > 500) return `${val.slice(0, 500)}...`; + return val; + }) + ); + } catch (err) { + return ``; + } +}; + +const safeInspect = (payload) => util.inspect(sanitizeForLog(payload), { breakLength: Infinity }); +const getSignature = (req) => req.signature || req._reqLogId || "no-signature"; + /** * Configure all routes for express app * @param app the express app @@ -31,7 +58,11 @@ module.exports = (app) => { if (def.method !== "checkHealth") { req._id = uuid(); req.signature = `${req._id}-${def.controller}#${def.method}`; - logger.info(`Started request handling, ${req.signature}`); + logger.info( + `Started request handling, ${req.signature} ${req.method} ${req.originalUrl} controller=${def.controller}.${def.method} query=${safeInspect( + req.query + )} params=${safeInspect(req.params)} body=${safeInspect(req.body)}` + ); } next(); }); @@ -39,6 +70,7 @@ module.exports = (app) => { actions.push((req, res, next) => { if (_.get(req, "query.token")) { _.set(req, "headers.authorization", `Bearer ${_.trim(req.query.token)}`); + logger.info(`[${getSignature(req)}] Promoted query.token to Authorization header`); } next(); }); @@ -53,6 +85,11 @@ module.exports = (app) => { if (req.authUser.isMachine) { // M2M if (!req.authUser.scopes || !helper.checkIfExists(def.scopes, req.authUser.scopes)) { + logger.warn( + `[${getSignature(req)}] Machine token scope mismatch. required=${safeInspect( + def.scopes + )} provided=${safeInspect(req.authUser.scopes)}` + ); next(new errors.ForbiddenError(`You are not allowed to perform this action, because the scopes are incorrect. \ Required scopes: ${JSON.stringify(def.scopes)} \ Provided scopes: ${JSON.stringify(req.authUser.scopes)}`)); @@ -60,6 +97,11 @@ module.exports = (app) => { req.authUser.handle = config.M2M_AUDIT_HANDLE; req.authUser.userId = config.M2M_AUDIT_USERID; req.userToken = req.headers.authorization.split(" ")[1]; + logger.info( + `[${getSignature(req)}] Authenticated M2M token scopes=${safeInspect( + req.authUser.scopes + )}` + ); next(); } } else { @@ -73,15 +115,26 @@ module.exports = (app) => { _.map(req.authUser.roles, (r) => r.toLowerCase()) ) ) { + logger.warn( + `[${getSignature(req)}] User role mismatch required=${safeInspect( + def.access + )} provided=${safeInspect(req.authUser.roles)}` + ); next(new errors.ForbiddenError(`You are not allowed to perform this action, because the roles are incorrect. \ Required roles: ${JSON.stringify(def.access)} \ Provided roles: ${JSON.stringify(req.authUser.roles)}`)); } else { // user token is used in create/update challenge to ensure user can create/update challenge under specific project req.userToken = req.headers.authorization.split(" ")[1]; + logger.info( + `[${getSignature(req)}] Authenticated user=${req.authUser.userId} roles=${safeInspect( + req.authUser.roles + )}` + ); next(); } } else { + logger.warn(`[${getSignature(req)}] Authenticated user missing roles`); next(new errors.ForbiddenError("You are not authorized to perform this action, \ because no roles were provided")); } @@ -90,15 +143,40 @@ module.exports = (app) => { } else { // public API, but still try to authenticate token if provided, but allow missing/invalid token actions.push((req, res, next) => { + const hasToken = + !!req.headers.authorization || !!_.get(req, "query.token") || !!req.authUser; + if (!hasToken) { + return next(); + } const interceptRes = {}; interceptRes.status = () => interceptRes; interceptRes.json = () => interceptRes; - interceptRes.send = () => next(); - authenticator(_.pick(config, ["AUTH_SECRET", "VALID_ISSUERS"]))(req, interceptRes, next); + interceptRes.send = (payload) => { + logger.info( + `[${getSignature(req)}] Public route: authenticator send called payload=${safeInspect( + payload + )}` + ); + return next(); + }; + const authMw = authenticator(_.pick(config, ["AUTH_SECRET", "VALID_ISSUERS"])); + let finished = false; + const bailoutTimer = setTimeout(() => { + if (finished) return; + finished = true; + next(); + }, 8000); + authMw(req, interceptRes, (...args) => { + if (finished) return; + finished = true; + clearTimeout(bailoutTimer); + next(...args); + }); }); actions.push((req, res, next) => { if (!req.authUser) { + logger.info(`[${getSignature(req)}] Public route: no authUser context`); next(); } else if (req.authUser.isMachine) { if ( @@ -106,16 +184,44 @@ module.exports = (app) => { !req.authUser.scopes || !helper.checkIfExists(def.scopes, req.authUser.scopes) ) { + logger.info( + `[${getSignature(req)}] Public route: dropping machine token due to scope mismatch` + ); req.authUser = undefined; + } else { + logger.info(`[${getSignature(req)}] Public route: valid machine token attached`); } next(); } else { req.authUser.userId = String(req.authUser.userId); + logger.info( + `[${getSignature(req)}] Public route: user present userId=${req.authUser.userId}` + ); next(); } }); } - actions.push(method); + + actions.push(async (req, res, next) => { + logger.info(`[${getSignature(req)}] Invoking ${def.controller}.${def.method}`); + try { + const resultPromise = method(req, res, next); + if (resultPromise && typeof resultPromise.then === "function") { + await resultPromise; + } + logger.info( + `[${getSignature(req)}] Completed ${def.controller}.${def.method} headersSent=${res.headersSent} status=${res.statusCode}` + ); + } catch (err) { + logger.error( + `[${getSignature(req)}] ${def.controller}.${def.method} threw error: ${ + err.message || "unknown error" + }` + ); + throw err; + } + }); + app[verb](`/${config.API_VERSION}${path}`, helper.autoWrapExpress(actions)); }); }); @@ -123,10 +229,12 @@ module.exports = (app) => { // Check if the route is not found or HTTP method is not supported app.use((req, res) => { if (routes[req.baseUrl]) { + logger.warn(`Unsupported method ${req.method} for ${req.originalUrl}`); res.status(HttpStatus.METHOD_NOT_ALLOWED).json({ message: "The requested HTTP method is not supported.", }); } else { + logger.warn(`Route not found for ${req.method} ${req.originalUrl}`); res.status(HttpStatus.NOT_FOUND).json({ message: "The requested resource cannot be found.", }); diff --git a/app.js b/app.js index 62c1ef7..4ac3927 100644 --- a/app.js +++ b/app.js @@ -50,6 +50,9 @@ const { getClient } = require("./src/common/prisma"); // setup express app const app = express(); +// Use extended query parsing so bracket syntax like types[]=F2F is handled as arrays +app.set("query parser", "extended"); + // Disable POST, PUT, PATCH, DELETE operations if READONLY is set to true app.use((req, res, next) => { if (config.READONLY === true && ["POST", "PUT", "PATCH", "DELETE"].includes(req.method)) { diff --git a/package.json b/package.json index b198e8e..46d62de 100644 --- a/package.json +++ b/package.json @@ -61,7 +61,7 @@ "moment": "^2.30.1", "node-cache": "^5.1.2", "swagger-ui-express": "^5.0.1", - "tc-core-library-js": "github:appirio-tech/tc-core-library-js#v2.6.4", + "tc-core-library-js": "github:appirio-tech/tc-core-library-js#security", "topcoder-bus-api-wrapper": "github:topcoder-platform/tc-bus-api-wrapper", "uuid": "^11.0.3", "winston": "^3.18.3",