Merge pull request #203 from lmorchard/202-duplicate-log-events

De-dupe and tweak log events

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);
 };
 

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 (

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;
 };
 

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,