Analyze Trace Logs (#282)

metlo-labs · Jan 13, 2023 · 87c82ec · 87c82ec
1 parent cbd4f87
commit 87c82ec
Show file tree

Hide file tree

Showing 3 changed files with 32 additions and 6 deletions.
diff --git a/backend/src/analyze-traces.ts b/backend/src/analyze-traces.ts
@@ -116,13 +116,17 @@ const analyze = async (
   queryRunner: QueryRunner,
   newEndpoint?: boolean,
 ) => {
+  const traceUUID = uuidv4()
+  mlog.debug(`Analyzing Trace: ${traceUUID}`)
   const prevRiskScore = apiEndpoint.riskScore
   const prevLastActive = apiEndpoint.lastActive
   endpointUpdateDates(trace.createdAt, apiEndpoint)
+  mlog.debug(`Analyzing Trace - Updated Dates: ${traceUUID}`)
 
   const start1 = performance.now()
   const dataFields = await findDataFieldsToSave(ctx, trace, apiEndpoint)
   mlog.time("analyzer.find_data_fields", performance.now() - start1)
+  mlog.debug(`Analyzing Trace - Found Datafields: ${traceUUID}`)
 
   const start2 = performance.now()
   let alerts = await SpecService.findOpenApiSpecDiff(
@@ -132,6 +136,7 @@ const analyze = async (
     queryRunner,
   )
   mlog.time("analyzer.find_openapi_spec_diff", performance.now() - start2)
+  mlog.debug(`Analyzing Trace - Found OpenAPI Spec Diffs: ${traceUUID}`)
 
   const start3 = performance.now()
   const sensitiveDataAlerts = await AlertService.createDataFieldAlerts(
@@ -144,6 +149,7 @@ const analyze = async (
   )
   alerts = alerts?.concat(sensitiveDataAlerts)
   mlog.time("analyzer.create_data_field_alerts", performance.now() - start3)
+  mlog.debug(`Analyzing Trace - Created Data Field Alerts: ${traceUUID}`)
 
   if (newEndpoint) {
     const newEndpointAlert = await AlertService.createAlert(
@@ -176,6 +182,7 @@ const analyze = async (
     5,
   )
   mlog.time("analyzer.insert_api_trace_query", performance.now() - start4)
+  mlog.debug(`Analyzing Trace - Inserted API Trace: ${traceUUID}`)
 
   const start5 = performance.now()
   await retryTypeormTransaction(
@@ -186,6 +193,7 @@ const analyze = async (
     5,
   )
   mlog.time("analyzer.insert_data_fields_query", performance.now() - start5)
+  mlog.debug(`Analyzing Trace - Inserted Data Fields: ${traceUUID}`)
 
   const start6 = performance.now()
   await retryTypeormTransaction(
@@ -195,14 +203,19 @@ const analyze = async (
       ),
     5,
   )
+  mlog.time("analyzer.update_data_fields_query", performance.now() - start6)
+  mlog.debug(`Analyzing Trace - Updated Data Fields: ${traceUUID}`)
+
+  const start7 = performance.now()
   await retryTypeormTransaction(
     () =>
       insertValuesBuilder(ctx, queryRunner, Alert, alerts).orIgnore().execute(),
     5,
   )
-  mlog.time("analyzer.insert_alerts_query", performance.now() - start6)
+  mlog.time("analyzer.insert_alerts_query", performance.now() - start7)
+  mlog.debug(`Analyzing Trace - Inserted Alerts: ${traceUUID}`)
 
-  const start7 = performance.now()
+  const start8 = performance.now()
   if (shouldUpdateEndpoint(prevRiskScore, prevLastActive, apiEndpoint)) {
     await retryTypeormTransaction(
       () =>
@@ -218,14 +231,19 @@ const analyze = async (
       5,
     )
   }
-  mlog.time("analyzer.update_api_endpoint_query", performance.now() - start7)
+  mlog.time("analyzer.update_api_endpoint_query", performance.now() - start8)
+  mlog.debug(`Analyzing Trace - Updated API Endpoint: ${traceUUID}`)
 
-  const start8 = performance.now()
+  const start9 = performance.now()
   await updateIPs(ctx, trace, apiEndpoint, queryRunner)
-  mlog.time("analyzer.update_ips", performance.now() - start8)
+  mlog.time("analyzer.update_ips", performance.now() - start9)
+  mlog.debug(`Analyzing Trace - Updated IPs: ${traceUUID}`)
   await queryRunner.commitTransaction()
 
+  const start10 = performance.now()
   await sendWebhookRequests(ctx, alerts, apiEndpoint)
+  mlog.time("analyzer.sent_webhook_requests", performance.now() - start10)
+  mlog.debug(`Analyzing Trace - Sent Webhook Requests: ${traceUUID}`)
 }
 
 const generateEndpoint = async (

diff --git a/backend/src/api/collector/log-request/index.ts b/backend/src/api/collector/log-request/index.ts
@@ -1,3 +1,4 @@
+import mlog from "logger"
 import { Response } from "express"
 import { LogRequestService } from "services/log-request"
 import { TraceParams } from "@common/types"
@@ -8,6 +9,7 @@ export const logRequestSingleHandler = async (
   req: MetloRequest,
   res: Response,
 ): Promise<void> => {
+  mlog.debug("Called Log Request Single Handler")
   const traceParams: TraceParams = req.body
   try {
     await LogRequestService.logRequest(req.ctx, traceParams)
@@ -21,6 +23,7 @@ export const logRequestBatchHandler = async (
   req: MetloRequest,
   res: Response,
 ): Promise<void> => {
+  mlog.debug("Called Log Request Batch Handler")
   const traceParamsBatch: TraceParams[] = req.body
   try {
     await LogRequestService.logRequestBatch(req.ctx, traceParamsBatch)

diff --git a/backend/src/services/log-request/index.ts b/backend/src/services/log-request/index.ts
@@ -14,20 +14,25 @@ export class LogRequestService {
     ctx: MetloContext,
     traceParams: TraceParams,
   ): Promise<void> {
+    mlog.debug("Called Log Request Service Func")
     const unsafeRedisClient = RedisClient.getInstance()
     try {
       /** Log Request in ApiTrace table **/
       let queueLength = 0
       try {
         queueLength = await unsafeRedisClient.llen(TRACES_QUEUE)
-      } catch {}
+      } catch (err) {
+        mlog.withErr(err).debug(`Error checking queue length`)
+      }
+      mlog.debug(`Trace queue length ${queueLength}`)
       if (queueLength > 1000) {
         mlog.debug("Trace queue overloaded")
         return
       }
 
       const validPath = getValidPath(traceParams?.request?.url?.path)
       if (!validPath.isValid) {
+        mlog.debug(`Invalid Path: ${traceParams?.request?.url?.path}`)
         throw new Error400BadRequest(
           `Invalid path ${traceParams?.request?.url?.path}: ${validPath.errMsg}`,
         )