diff --git a/bun.lockb b/bun.lockb index 5ca2f05..12921d9 100755 Binary files a/bun.lockb and b/bun.lockb differ diff --git a/packages/doorman-api/package.json b/packages/doorman-api/package.json index 7707587..6382487 100644 --- a/packages/doorman-api/package.json +++ b/packages/doorman-api/package.json @@ -12,10 +12,11 @@ }, "dependencies": { "@aws-sdk/client-dynamodb": "^3.609.0", - "@twilio-labs/serverless-runtime-types": "^3.0.0", + "@twilio-labs/serverless-runtime-types": "^4.0.1", "@twilio/runtime-handler": "1.3.0", "discord.js": "^14.16.3", "prom-client": "^15.1.3", + "promise.timeout": "^1.2.0", "twilio": "^3.56", "winston": "^3.17.0", "winston-loki": "^6.1.3" diff --git a/packages/doorman-api/src/common/DoormanHandler.ts b/packages/doorman-api/src/common/DoormanHandler.ts index e02fa62..764ad68 100644 --- a/packages/doorman-api/src/common/DoormanHandler.ts +++ b/packages/doorman-api/src/common/DoormanHandler.ts @@ -4,19 +4,27 @@ import { DoormanLambdaContext } from "./DoormanHandlerContext"; import { shouldBlockRequest } from "../utils/blockUserAgent"; import { RequestOptions } from "https"; import { FastHttpPushgateway } from "../metrics/FastHttpPromGateway"; +import '@twilio-labs/serverless-runtime-types'; +import VoiceResponse from 'twilio/lib/twiml/VoiceResponse'; import { createLogger, format, Logger, transports } from "winston"; import LokiTransport from "winston-loki"; +import pTimeout, { TimeoutError } from "promise.timeout"; export type BaseEvent = { request: { cookies: {}; headers: {}; }; } +export type CallbackResult = Parameters; +export type FailFastCallback = () => CallbackResult; + export type DoormanLambda = ( context: Parameters>[0], event: Parameters>[1], callback: Parameters>[2], metricsRegistry: Registry, logger: Logger, -) => void; + // this is optional, but if called this method should provide an alternative callback provider that can fail fast + failFastCallback: (fn: FailFastCallback) => void, +) => Promise; export enum CommonMetrics { RUNTIME = "FunctionRuntime", @@ -25,6 +33,9 @@ export enum CommonMetrics { LOKI_ERROR = "LokiError", LOKI_LOG_AFTER_CLOSE = "LokiLogAfterClose", TWILIO_ISOLATION_BUSTED = "TwilioIsolationBusted", + INNER_HANDLER_TIMEOUT = "InnerHandlerTimeout", + INNER_HANDLER_MISSING_FAIL_FAST = "InnerHandlerMissingFailFast", + RETURN_FALLBACK_RESPONSE = "ReturnFallbackResponse", }; export function getMetricFromRegistry(metricsRegistry: Registry, metric: string): T { @@ -42,8 +53,15 @@ export function gracefullyEndLogger(logger: Logger): Promise { }); } +// TODO: make this response a voice message? +const REJECT_RESPONSE = new VoiceResponse(); +REJECT_RESPONSE.reject(); + +const FALLBACK_CALLBACK: CallbackResult = [null, REJECT_RESPONSE]; + const MINIMUM_MS_TO_SEND_RESPONSE: number = 250; const FUNCTION_MAXIMUM_DURATION_MS: number = 10_000; +const INNER_HANDLER_MAXIMUM_DURATION_MS: number = 8_500; /** * A decorator for twilio handlers. It provides a metrics registry and @@ -100,6 +118,21 @@ export function withMetrics help: "Twilio invocation lasted longer than 10s", })); + metricsRegistry.registerMetric(new Counter({ + name: CommonMetrics.INNER_HANDLER_MISSING_FAIL_FAST, + help: "Inner handler was timed out and we did not have any fallback response", + })); + + metricsRegistry.registerMetric(new Counter({ + name: CommonMetrics.INNER_HANDLER_TIMEOUT, + help: "Inner handler was timed out", + })); + + metricsRegistry.registerMetric(new Counter({ + name: CommonMetrics.RETURN_FALLBACK_RESPONSE, + help: "Common handler returned a fallback response", + })); + // Create a Winston logger const logger = createLogger({ level: 'info', @@ -136,6 +169,7 @@ export function withMetrics // Override the base console log with winston console.log = function (...args) { if (logger.writable) { + // @ts-ignore return logger.info.apply(logger, [...args]); } getMetricFromRegistry(metricsRegistry, CommonMetrics.LOKI_LOG_AFTER_CLOSE).inc(1); @@ -143,6 +177,7 @@ export function withMetrics }; console.error = function (...args) { if (logger.writable) { + // @ts-ignore return logger.error.apply(logger, [...args]); } getMetricFromRegistry(metricsRegistry, CommonMetrics.LOKI_LOG_AFTER_CLOSE).inc(1); @@ -150,6 +185,7 @@ export function withMetrics }; console.warn = function (...args) { if (logger.writable) { + // @ts-ignore return logger.warn.apply(logger, [...args]); } getMetricFromRegistry(metricsRegistry, CommonMetrics.LOKI_LOG_AFTER_CLOSE).inc(1); @@ -157,6 +193,7 @@ export function withMetrics }; console.info = function (...args) { if (logger.writable) { + // @ts-ignore return logger.info.apply(logger, [...args]); } getMetricFromRegistry(metricsRegistry, CommonMetrics.LOKI_LOG_AFTER_CLOSE).inc(1); @@ -175,6 +212,12 @@ export function withMetrics callbackResult = [err, payload]; } + // intercept the fail fast callback method, if it is provided + let failFastCallbackMethod: FailFastCallback | undefined; + const failFastCallbackProvider: (fn: FailFastCallback) => void = (fn) => { + failFastCallbackMethod = fn; + } + // block requests before we even call the handler if (shouldBlockRequest(event)) { getMetricFromRegistry(metricsRegistry, CommonMetrics.BLOCKED_REQUEST).inc(1); @@ -182,14 +225,34 @@ export function withMetrics response.setStatusCode(200); callbackResult = [null, response]; } else { - await handler(context, event, tempCallback, metricsRegistry, logger); + // wait for response for up to x ms, otherwise we call the failFastCallbackMethod + try { + await pTimeout( + () => handler(context, event, tempCallback, metricsRegistry, logger, failFastCallbackProvider), + INNER_HANDLER_MAXIMUM_DURATION_MS + )(); + } catch (e) { + console.log(e); + if (e instanceof TimeoutError) { + getMetricFromRegistry(metricsRegistry, CommonMetrics.INNER_HANDLER_TIMEOUT).inc(1); + + if (!failFastCallbackMethod) { + getMetricFromRegistry(metricsRegistry, CommonMetrics.INNER_HANDLER_MISSING_FAIL_FAST).inc(1); + reject("Timeout, but no failfast result was given"); + return; + } + + callbackResult = failFastCallbackMethod(); + } + } } if (!callbackResult) { reject("No callback was given"); + return; } - let statusCode: number | undefined = (callbackResult?.[1] as any)?.statusCode; + let statusCode: number | undefined = (callbackResult[1] as any)?.statusCode; if (statusCode && statusCode >= 400) { getMetricFromRegistry(metricsRegistry, CommonMetrics.HTTP_CLIENT_ERROR).inc({ @@ -197,12 +260,16 @@ export function withMetrics }, 1); } - resolve(callbackResult as Parameters); + resolve(callbackResult); }); console.time("[CommonHandler] nested handler time"); - const result = await handlerResponsePromise; + const result = await handlerResponsePromise.catch((err) => { + console.error("[CommonHandler] inner handler promise was rejected with reason: " + err); + getMetricFromRegistry(metricsRegistry, CommonMetrics.RETURN_FALLBACK_RESPONSE).inc(1); + return FALLBACK_CALLBACK; + }); console.timeEnd("[CommonHandler] nested handler time"); @@ -214,7 +281,7 @@ export function withMetrics getMetricFromRegistry(metricsRegistry, CommonMetrics.TWILIO_ISOLATION_BUSTED).inc(1); } - // abandoning metrics, since there isn't enough time + // abandoning metrics/logs, 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); diff --git a/packages/doorman-client/package.json b/packages/doorman-client/package.json index 6e4f891..c90d1b9 100644 --- a/packages/doorman-client/package.json +++ b/packages/doorman-client/package.json @@ -11,11 +11,12 @@ "deploy": "twilio-run deploy --load-system-env --env .env.example --service-name buzzer --environment=prod --override-existing-project" }, "dependencies": { - "@twilio-labs/serverless-runtime-types": "^3.0.0", + "@twilio-labs/serverless-runtime-types": "^4.0.1", "@twilio/runtime-handler": "1.3.0", "node-fetch": "^2.7.0", "prom-client": "^15.1.3", "prometheus-remote-write": "^0.5.0", + "promise.timeout": "^1.2.0", "twilio": "^3.84.1", "winston": "^3.17.0", "winston-loki": "^6.1.3" diff --git a/packages/doorman-client/src/functions/buzzer-activated.ts b/packages/doorman-client/src/functions/buzzer-activated.ts index 1ccf3d7..70fe6a9 100644 --- a/packages/doorman-client/src/functions/buzzer-activated.ts +++ b/packages/doorman-client/src/functions/buzzer-activated.ts @@ -19,7 +19,7 @@ import { getMetricFromRegistry, withMetrics } from '../../../doorman-api/src/com import { Counter, Summary } from 'prom-client'; import { BuzzerActivatedMetrics, registerMetrics } from '../metrics/BuzzerActivatedMetrics'; -export const handler: ServerlessFunctionSignature = withMetrics('buzzer-activated', async function(context, event, callback, metricsRegistry) { +export const handler: ServerlessFunctionSignature = withMetrics('buzzer-activated', async function(context, event, callback, metricsRegistry, logger, failFastCallback) { // metrics registerMetrics(metricsRegistry); @@ -58,7 +58,7 @@ export const handler: ServerlessFunctionSignature ""), metricsRegistry); - let discordLock = false; + let responseLock = false; let intervals: Timer[] = []; let timeouts: Timer[] = []; @@ -79,8 +79,8 @@ export const handler: ServerlessFunctionSignature { const twiml = dialFallbackTwiml(config); - if (!discordLock) { - discordLock = true; + if (!responseLock) { + responseLock = true; getMetricFromRegistry(metricsRegistry, BuzzerActivatedMetrics.DIAL_THROUGH) .inc({ door: config.door }, 1); @@ -120,15 +120,18 @@ export const handler: ServerlessFunctionSignature((resolve, reject) => { - timeouts.push(setTimeout(async () => { - getMetricFromRegistry(metricsRegistry, BuzzerActivatedMetrics.RESULT_NOTIFICATION_FATE_UNKNOWN) + // provide a method to the decorator to use as a fast fallback that shouldn't have any await + failFastCallback(() => { + // prevent other responses + responseLock = true; + + getMetricFromRegistry(metricsRegistry, BuzzerActivatedMetrics.RESULT_NOTIFICATION_FATE_UNKNOWN) .inc({ door: config.door }, 1); getMetricFromRegistry(metricsRegistry, BuzzerActivatedMetrics.DIAL_THROUGH) @@ -136,13 +139,12 @@ export const handler: ServerlessFunctionSignature clearTimeout(timeout)); intervals.forEach(interval => clearInterval(interval));