diff --git a/functions/accept.js b/functions/accept.js index 0dc610e..172f3b1 100644 --- a/functions/accept.js +++ b/functions/accept.js @@ -20,7 +20,6 @@ module.exports.post = async function(event, context) { event, context, }); - log.info("summary"); const { UPSTREAM_SERVICE_URL, @@ -65,7 +64,7 @@ module.exports.post = async function(event, context) { log.commonFields.uid = authArtifacts.id; } catch (err) { Raven.captureException(err); - log.error("authInvalid", { authorization }); + log.error("authInvalid", { authorization, error: err.message }); return response( 401, { error: err.message }, @@ -168,7 +167,7 @@ module.exports.post = async function(event, context) { positive_uri, positive_email, }; - log.info("response", responseData); + log.info("summary", responseData); return response(201, responseData); }; diff --git a/functions/periodicMetrics.js b/functions/periodicMetrics.js index 66699de..ead6a75 100644 --- a/functions/periodicMetrics.js +++ b/functions/periodicMetrics.js @@ -12,7 +12,6 @@ module.exports.handler = async function(event = {}, context = {}) { event, context, }); - log.info("summary"); const Raven = Sentry(); @@ -40,6 +39,7 @@ module.exports.handler = async function(event = {}, context = {}) { await wait(pingPeriod); } log.verbose("exit", { pingCount }); + log.info("summary"); }; const sendHeartbeatMetrics = async ( diff --git a/functions/processQueueItem.js b/functions/processQueueItem.js index 1e607d3..4a0bf53 100644 --- a/functions/processQueueItem.js +++ b/functions/processQueueItem.js @@ -17,7 +17,6 @@ exports.handler = async function(event = {}, context = {}) { event, context, }); - log.info("summary", { recordCount: Records.length }); const results = []; for (let idx = 0; idx < Records.length; idx++) { @@ -26,6 +25,7 @@ exports.handler = async function(event = {}, context = {}) { } log.debug("done", { resultCount: results.length }); + log.info("summary", { recordCount: Records.length }); return results; }; diff --git a/lib/logging.js b/lib/logging.js index 8398d70..0ca1be5 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -1,22 +1,25 @@ // Configure logging and wrap mozlog methods in decorators that automatically // include function context and event information -module.exports = ({ name, event, context, isRequest = false }) => { - const { - LOG_LEVEL = "info", - LOG_FORMAT = "heka", - LOG_DEBUG = "0", - GIT_COMMIT = "", - } = process.env; +const { + LOG_LEVEL = "info", + LOG_FORMAT = "heka", + LOG_DEBUG = "0", + GIT_COMMIT = "", +} = process.env; - const mozlog = require("mozlog")({ - app: "watchdog-proxy", - level: LOG_LEVEL, - fmt: LOG_FORMAT, - debug: LOG_DEBUG === "1", - }); +const mozlog = require("mozlog")({ + app: "watchdog-proxy", + level: LOG_LEVEL, + fmt: LOG_FORMAT, + debug: LOG_DEBUG === "1", +}); + +module.exports = ({ name, event, context, isRequest = false }) => { + const startTime = Date.now(); + + const selector = isRequest ? selectRequest : selectBase; const log = mozlog(name); - const selector = isRequest ? selectRequest : selectBase; const out = {}; out.commonFields = { @@ -27,7 +30,13 @@ module.exports = ({ name, event, context, isRequest = false }) => { (out[level] = (op, fields = {}) => log[level]( op, - selector({ event, context, fields, commonFields: out.commonFields }) + selector({ + startTime, + event, + context, + fields, + commonFields: out.commonFields, + }) )) ); return out; @@ -43,12 +52,21 @@ const LOG_LEVELS = [ "critical", ]; -const selectRequest = ({ event, context, fields = {}, commonFields = {} }) => - Object.assign(selectRequestEvent(event), selectBase({ context, fields })); - -const selectBase = ({ context, fields = {}, commonFields = {} }) => +const selectRequest = ({ + startTime, + event, + context, + fields = {}, + commonFields = {}, +}) => Object.assign( - { timestamp: Date.now() }, + selectRequestEvent(event), + selectBase({ startTime, context, fields }) + ); + +const selectBase = ({ startTime, context, fields = {}, commonFields = {} }) => + Object.assign( + { timestamp: Date.now(), t: Date.now() - startTime }, selectContext(context), commonFields, fields @@ -58,22 +76,27 @@ const selectBase = ({ context, fields = {}, commonFields = {} }) => const selectRequestEvent = ({ path, httpMethod: method, - headers: { Host: hostname, "User-Agent": agent }, + headers: { + Host: hostname, + "User-Agent": agent, + "X-Forwarded-For": remoteAddressChain, + }, }) => ({ path, method, + remoteAddressChain, agent, hostname, }); // https://docs.aws.amazon.com/lambda/latest/dg/nodejs-prog-model-context.html const selectContext = ({ - awsRequestId, + awsRequestId: rid, functionName, functionVersion, memoryLimitInMB, }) => ({ - awsRequestId, + rid, functionName, functionVersion, memoryLimitInMB,