give more time to push metrics before exiting

packages/doorman-api/src/common/DoormanHandler.ts

@@ -24,6 +24,7 @@ export enum CommonMetrics {
   HTTP_CLIENT_ERROR = "HttpClientError",
   LOKI_ERROR = "LokiError",
   LOKI_LOG_AFTER_CLOSE = "LokiLogAfterClose",
+  TWILIO_ISOLATION_BUSTED = "TwilioIsolationBusted",
 };
 
 export function getMetricFromRegistry<T>(metricsRegistry: Registry, metric: string): T {
@@ -33,7 +34,6 @@ export function getMetricFromRegistry<T>(metricsRegistry: Registry, metric: stri
 export function gracefullyEndLogger(logger: Logger): Promise<void> {
   return new Promise((fulfill, reject) => {
     // Add logic for other transports here ...
-  
     logger.on('finish', () => {
       fulfill();
     });
@@ -42,6 +42,9 @@ export function gracefullyEndLogger(logger: Logger): Promise<void> {
   });
 }
 
+const MINIMUM_MS_TO_SEND_RESPONSE: number = 250;
+const FUNCTION_MAXIMUM_DURATION_MS: number = 10_000;
+
 /**
  * A decorator for twilio handlers. It provides a metrics registry and 
  * should implement timeout and cleanup jobs based on lambda timeout
@@ -92,6 +95,11 @@ export function withMetrics<T extends DoormanLambdaContext, U extends BaseEvent>
       help: "Tried to write logs after log stream closed",
     }));
 
+    metricsRegistry.registerMetric(new Counter({
+      name: CommonMetrics.TWILIO_ISOLATION_BUSTED,
+      help: "Twilio invocation lasted longer than 10s",
+    }));
+
     // Create a Winston logger
     const logger = createLogger({
       level: 'info',
@@ -199,13 +207,25 @@ export function withMetrics<T extends DoormanLambdaContext, U extends BaseEvent>
     console.timeEnd("[CommonHandler] nested handler time");
 
     const endTime = Date.now();
-    const remainingTime = 10000 - (endTime - startTime);
+    const remainingTime = FUNCTION_MAXIMUM_DURATION_MS - (endTime - startTime);
+
+    if (remainingTime < 0) {
+      console.error("[CommonHandler] remaining time is negative for some reason...");
+      getMetricFromRegistry<Counter>(metricsRegistry, CommonMetrics.TWILIO_ISOLATION_BUSTED).inc(1);
+    }
+
+    // abandoning metrics, since there isn't enough time
+    if (remainingTime <= MINIMUM_MS_TO_SEND_RESPONSE) {
+      console.error("[CommonHandler] there is no time to send metrics / logs abandoning them");
+      callback(...result);
+      return;
+    }
 
     console.log(`[CommonHandler] there is ${remainingTime} ms left to send metrics`);
 
     let metricsTimeout = setTimeout(() => {
       callback(...result);
-    }, remainingTime - 250);
+    }, remainingTime - MINIMUM_MS_TO_SEND_RESPONSE);
 
     summaryTimer();
     console.log("[CommonHandler] attempting to push metrics...");

packages/doorman-client/src/functions/buzzer-activated.ts

@@ -26,7 +26,7 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
   let invokeId = `[${randomUUID()}]`;
   let configString = event.config;
   let config: InfoResponseClient | undefined;
-  console.log(invokeId, "starting execution");
+  console.log(invokeId + " starting execution");
 
   // get by api or parse it out from query
   if (!configString) {
@@ -82,7 +82,7 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
             if (!discordLock) {
               discordLock = true;
               console.log(
-                invokeId, "UnlockPromise: I was the fastest, so I will attempt to notify discord users before resolving with unlock"
+                invokeId + " UnlockPromise: I was the fastest, so I will attempt to notify discord users before resolving with unlock"
               );
               getMetricFromRegistry<Counter>(metricsRegistry, BuzzerActivatedMetrics.API_UNLOCK)
                 .inc({ door: config.door }, 1);
@@ -91,11 +91,11 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
               resolve(twiml);
             } else {
               console.log(
-                invokeId, "UnlockPromise: dropping out of the race, graceful fallback is already notifiying discord users"
+                invokeId + " UnlockPromise: dropping out of the race, graceful fallback is already notifiying discord users"
               );
             }
           }
-        }).catch(err => console.log(invokeId, err));
+        }).catch(err => console.log(invokeId + err));
     }, 1250));
   });
 
@@ -109,7 +109,7 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
           .inc({ door: config.door }, 1);
 
         console.log(
-          invokeId, "GracefulFallbackPromise: I was the fastest, so I will attempt to notify discord users before resolving with a call"
+          invokeId + " GracefulFallbackPromise: I was the fastest, so I will attempt to notify discord users before resolving with a call"
         );
         await notifyAllDiscord(
           context, 
@@ -120,10 +120,10 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
         resolve(twiml);
       } else {
         console.log(
-          invokeId, "GracefulFallbackPromise: dropping out of the race, unlock is already notifying discord users"
+          invokeId + " GracefulFallbackPromise: dropping out of the race, unlock is already notifying discord users"
         );
       }
-    }, 8000));
+    }, 7500));
   });
 
   const ungracefulFallbackPromise = new Promise<VoiceResponse>((resolve, reject) => {
@@ -136,14 +136,14 @@ export const handler: ServerlessFunctionSignature<TwilioContext, BuzzerDialEvent
 
       const twiml = dialFallbackTwiml(config);
       console.log(
-        invokeId, "UngracefulFallbackPromise: Cutting it too close to timeout! Skipping notifying users and calling fallback"
+        invokeId + " UngracefulFallbackPromise: Cutting it too close to timeout! Skipping notifying users and calling fallback"
       );
       resolve(twiml);
-    }, 9000));
+    }, 8500));
   });
 
   const twiml = await Promise.race([unlockPromise, gracefulFallbackPromise, ungracefulFallbackPromise]);
-  console.log(invokeId, "Race ended, clearing residual timers");
+  console.log(invokeId + " Race ended, clearing residual timers");
   timeouts.forEach(timeout => clearTimeout(timeout));
   intervals.forEach(interval => clearInterval(interval));
   callback(null, twiml);