From 5837794ce130aea2452ce3c2fd804da8ad219727 Mon Sep 17 00:00:00 2001
From: Mark Vayngrib <mark@tradle.io>
Date: Wed, 18 Jul 2018 21:53:20 -0400
Subject: [PATCH] fix: log-parsing

---
 src/in-house-bot/log-processor.ts           | 31 +++++++++++++++------
 src/test/in-house-bot/log-processor.test.ts |  7 ++++-
 2 files changed, 28 insertions(+), 10 deletions(-)

diff --git a/src/in-house-bot/log-processor.ts b/src/in-house-bot/log-processor.ts
index 80055d6a0..b9ed15cc2 100644
--- a/src/in-house-bot/log-processor.ts
+++ b/src/in-house-bot/log-processor.ts
@@ -41,6 +41,13 @@ const createDummySendAlert = (logger: Logger) => async (events, idx) => {
   logger.debug('TODO: send alert for sub-event', events[idx])
 }
 
+const REQUEST_LIFECYCLE_PROP = '__'
+const LIFECYCLE = {
+  START: 'START',
+  END: 'END',
+  REPORT: 'REPORT',
+}
+
 export class LogProcessor {
   private ignoreGroups: string[]
   private sendAlert: SendAlert
@@ -68,7 +75,7 @@ export class LogProcessor {
         })
       }
     })
-    .filter(notNull)
+    .filter(entry => entry && entry[REQUEST_LIFECYCLE_PROP] !== LIFECYCLE.END)
     .filter(shouldSave)
 
     const bad = logEvents.filter(shouldRaiseAlert)
@@ -109,7 +116,8 @@ export const fromLambda = (lambda: IPBLambda) => {
 }
 
 export const parseLogEntry = (entry: CloudWatchLogsSubEvent):ParsedEntry => {
-  const { requestId, body } = parseLogEntryMessage(entry.message)
+  const parsed = parseLogEntryMessage(entry.message)
+  const { requestId, body } = parsed
   return {
     id: entry.id,
     timestamp: entry.timestamp,
@@ -119,26 +127,30 @@ export const parseLogEntry = (entry: CloudWatchLogsSubEvent):ParsedEntry => {
 }
 
 const REGEX = {
-  START: /^START RequestId:\s*([^\s]+)\s*Version:\s*(.*)$/i,
-  END: /^END RequestId:\s*([^\s]+)$/i,
-  REPORT: /^REPORT RequestId:\s*([^\s]+)\s*Duration:\s*([^\s]*)\s*ms\s*Billed Duration:\s*([^\s]*)\s*ms\s*Memory Size:\s*(\d+)\s*([a-zA-Z])+\s*Max Memory Used:\s*(\d+)\s*([a-zA-Z])+$/i,
+  START: /^START RequestId:\s*([^\s]+)\s*Version:\s*(.*)\s*$/i,
+  END: /^END RequestId:\s*([^\s]+)\s*$/i,
+  REPORT: /^REPORT RequestId:\s*([^\s]+)\s*Duration:\s*([^\s]*)\s*ms\s*Billed Duration:\s*([^\s]*)\s*ms\s*Memory Size:\s*(\d+)\s*([a-zA-Z])+\s*Max Memory Used:\s*(\d+)\s*([a-zA-Z])+\s*$/i,
 }
 
 export const parseLogEntryMessage = (message: string) => {
   // "2018-07-18T16:26:47.716Z\t5b382e36-8aa7-11e8-9d6a-9343f875c9b4\t[JSON]
-  if (message.startsWith('START')) {
+  if (message.startsWith(LIFECYCLE.START)) {
     const [requestId, version] = REGEX.START.exec(message).slice(1)
     return {
+      [REQUEST_LIFECYCLE_PROP]: LIFECYCLE.START,
       requestId,
       version
     }
   }
 
-  if (message.startsWith('END')) {
-    return null
+  if (message.startsWith(LIFECYCLE.END)) {
+    return {
+      [REQUEST_LIFECYCLE_PROP]: LIFECYCLE.END,
+      requestId: REGEX.END.exec(message)[1]
+    }
   }
 
-  if (message.startsWith('REPORT')) {
+  if (message.startsWith(LIFECYCLE.REPORT)) {
     const [
       requestId,
       duration,
@@ -148,6 +160,7 @@ export const parseLogEntryMessage = (message: string) => {
     ] = REGEX.REPORT.exec(message).slice(1)
 
     return {
+      [REQUEST_LIFECYCLE_PROP]: LIFECYCLE.REPORT,
       requestId,
       duration,
       billedDuration,
diff --git a/src/test/in-house-bot/log-processor.test.ts b/src/test/in-house-bot/log-processor.test.ts
index 27d33063c..d8f191c77 100644
--- a/src/test/in-house-bot/log-processor.test.ts
+++ b/src/test/in-house-bot/log-processor.test.ts
@@ -24,6 +24,7 @@ REPORT RequestId: fe9e83ca-8af2-11e8-a5e2-b9d7a9e128fc\tDuration: 107.52 ms Bill
 
 const expectedParsed = [
   {
+    "__": "START",
     "requestId": "fe9e83ca-8af2-11e8-a5e2-b9d7a9e128fc",
     "version": "$LATEST"
   },
@@ -107,8 +108,12 @@ const expectedParsed = [
       "level": "SILLY"
     }
   },
-  null,
   {
+    "__": "END",
+    "requestId": "fe9e83ca-8af2-11e8-a5e2-b9d7a9e128fc"
+  },
+  {
+    "__": "REPORT",
     "requestId": "fe9e83ca-8af2-11e8-a5e2-b9d7a9e128fc",
     "duration": "107.52",
     "billedDuration": "200",