feat(aws-lambda): added optional timeout detection (#1181)

refs https://jsw.ibm.com/browse/INSTA-7063

- customers need that issue for debugging purposes
- env variable INSTANA_ENABLE_LAMBDA_TIMEOUT_DETECTION

Author: kirrg001

packages/aws-lambda/package.json

@@ -28,7 +28,7 @@
     "audit": "npm audit --omit=dev",
     "node_modules:exists": "mkdir -p node_modules",
     "test": "mocha --config=test/.mocharc.js --sort $(find test -iname '*test.js')",
-    "test:debug": "WITH_STDOUT=true npm run test",
+    "test:debug": "WITH_STDOUT=true INSTANA_DEBUG=true npm run test",
     "test:ci": "mocha --config=test/.mocharc.js --reporter mocha-multi-reporters --reporter-options configFile=reporter-config.json 'test/**/*test.js'",
     "lint": "eslint src test lambdas",
     "verify": "npm run lint && npm test",

packages/aws-lambda/src/wrapper.js

@@ -175,6 +175,19 @@ function shimmedHandler(originalHandler, originalThis, originalArgs, _config) {
       });
     };
 
+    /**
+     * We offer the customer to enable the timeout detection
+     * But its not recommended to use it on production, only for debugging purposes.
+     * See https://github.com/instana/nodejs/pull/668.
+     */
+    if (
+      process.env.INSTANA_ENABLE_LAMBDA_TIMEOUT_DETECTION &&
+      process.env.INSTANA_ENABLE_LAMBDA_TIMEOUT_DETECTION === 'true'
+    ) {
+      logger.debug('Heuristical timeout detection enabled. Please only use for debugging purposes.');
+      registerTimeoutDetection(context, entrySpan);
+    }
+
     let handlerPromise;
     try {
       handlerPromise = originalHandler.apply(originalThis, originalArgs);
@@ -258,6 +271,50 @@ function init(event, arnInfo, _config) {
   tracing.activate();
 }
 
+function registerTimeoutDetection(context, entrySpan) {
+  // We register the timeout detection directly at the start so getRemainingTimeInMillis basically gives us the
+  // configured timeout for this Lambda function, minus roughly 50 - 100 ms that is spent in bootstrapping.
+  const initialRemainingMillis = getRemainingTimeInMillis(context);
+  if (typeof initialRemainingMillis !== 'number') {
+    return;
+  }
+  if (initialRemainingMillis <= 2500) {
+    logger.debug(
+      'Heuristical timeout detection will be disabled for Lambda functions with a short timeout ' +
+        '(2 seconds and smaller).'
+    );
+    return;
+  }
+
+  let triggerTimeoutHandlingAfter;
+  if (initialRemainingMillis <= 4000) {
+    // For Lambdas configured with a timeout of 3 or 4 seconds we heuristically assume a timeout when only
+    // 10% of time is remaining.
+    triggerTimeoutHandlingAfter = initialRemainingMillis * 0.9;
+  } else {
+    // For Lambdas configured with a timeout of  5 seconds or more we heuristically assume a timeout when only 400 ms of
+    // time are remaining.
+    triggerTimeoutHandlingAfter = initialRemainingMillis - 400;
+  }
+
+  logger.debug(
+    `Registering heuristical timeout detection to be triggered in ${triggerTimeoutHandlingAfter} milliseconds.`
+  );
+
+  setTimeout(() => {
+    postHandlerForTimeout(entrySpan, getRemainingTimeInMillis(context));
+  }, triggerTimeoutHandlingAfter).unref();
+}
+
+function getRemainingTimeInMillis(context) {
+  if (context && typeof context.getRemainingTimeInMillis === 'function') {
+    return context.getRemainingTimeInMillis();
+  } else {
+    logger.warn('context.getRemainingTimeInMillis() is not available, timeout detection will be disabled.');
+    return null;
+  }
+}
+
 function shouldUseLambdaExtension() {
   if (process.env.INSTANA_DISABLE_LAMBDA_EXTENSION) {
     logger.info('INSTANA_DISABLE_LAMBDA_EXTENSION is set, not using the Lambda extension.');
@@ -390,6 +447,48 @@ function postHandler(entrySpan, error, result, callback) {
   });
 }
 
+/**
+ * When the timeout heuristic detects an imminent timeout, we finish the entry span prematurely and send it to the
+ * back end.
+ */
+function postHandlerForTimeout(entrySpan, remainingMillis) {
+  /**
+   * context.getRemainingTimeInMillis(context) can return negative values
+   * That just means that the lambda was already closed.
+   * `setTimeout` is not 100% reliable
+   */
+  if (remainingMillis < 200) {
+    logger.debug('Skipping heuristical timeout detection because lambda timeout exceeded already.');
+    return;
+  }
+
+  if (entrySpan) {
+    // CASE: Timeout not needed, we already send the data to the backend successfully
+    if (entrySpan.transmitted) {
+      logger.debug('Skipping heuristical timeout detection because BE data was sent already.');
+      return;
+    }
+
+    entrySpan.ec = 1;
+    entrySpan.data.lambda.msleft = remainingMillis;
+    entrySpan.data.lambda.error = `Possible Lambda timeout with only ${remainingMillis} ms left.`;
+    entrySpan.d = Date.now() - entrySpan.ts;
+    entrySpan.transmit();
+  }
+
+  logger.debug(`Heuristical timeout detection was triggered with ${remainingMillis} milliseconds left.`);
+
+  // deliberately not gathering metrics but only sending spans.
+  const spans = spanBuffer.getAndResetSpans();
+
+  sendToBackend({
+    spans,
+    metricsPayload: {},
+    finalLambdaRequest: true,
+    callback: () => {}
+  });
+}
+
 exports.currentSpan = function getHandleForCurrentSpan() {
   return tracing.getHandleForCurrentSpan();
 };

packages/aws-lambda/test/Control.js

@@ -45,6 +45,7 @@ Control.prototype.reset = function reset() {
 };
 
 Control.prototype.startMonitoredProcess = function startMonitoredProcess() {
+  const self = this;
   const envs = {
     HANDLER_DEFINITION_PATH: this.opts.handlerDefinitionPath,
     DOWNSTREAM_DUMMY_URL: this.downstreamDummyUrl,
@@ -79,6 +80,8 @@ Control.prototype.startMonitoredProcess = function startMonitoredProcess() {
       }
     } else if (message.type === 'lambda-context') {
       this.clientContext = message.context.clientContext;
+    } else if (message.type === 'lambda-timeout') {
+      self.faasRuntime.kill();
     } else {
       this.messagesFromFaasRuntime.push(message);
     }

packages/aws-lambda/test/runtime_mock/index.js

@@ -129,6 +129,22 @@ function runHandler(handler, error, { context, event, eventOpts } = {}) {
   context = context || createContext(callback);
   addDirectInvokeTracingCorrelationToContext(context, trigger);
 
+  if (
+    process.env.INSTANA_ENABLE_RUNTIME_TIMEOUT_DETECTION &&
+    process.env.INSTANA_ENABLE_RUNTIME_TIMEOUT_DETECTION === 'true'
+  ) {
+    setTimeout(() => {
+      log('Lambda timed out.');
+
+      sendToParent('runtime: terminating');
+
+      sendToParent({
+        type: 'lambda-timeout',
+        error: true
+      });
+    }, context.getRemainingTimeInMillis());
+  }
+
   const promise = handler(event, context, callback);
 
   if (promise && typeof promise.then === 'function') {
@@ -188,6 +204,9 @@ function createContext(callback) {
 
   const configuredTimeout = process.env.LAMBDA_TIMEOUT ? parseInt(process.env.LAMBDA_TIMEOUT, 10) : 3000;
 
+  // eslint-disable-next-line no-console
+  console.log(`Lambda timeout is set to ${configuredTimeout} ms.`);
+
   const done = (err, result) => {
     callback(err, result);
   };

packages/aws-lambda/test/timeout/lambda.js

@@ -0,0 +1,28 @@
+/*
+ * (c) Copyright IBM Corp. 2021
+ * (c) Copyright Instana Inc. and contributors 2020
+ */
+
+/* eslint-disable no-console */
+
+'use strict';
+
+const instana = require('../..');
+
+const delay = require('../../../core/test/test_util/delay');
+
+if (!process.env.DELAY) {
+  throw new Error('This Lambda requires the environment variable DELAY to be set.');
+}
+
+exports.handler = instana.wrap(async () => {
+  console.log(`Lambda handler started, now waiting ${process.env.DELAY} milliseconds.`);
+  await delay(process.env.DELAY);
+  console.log('Lambda handler finished');
+
+  return {
+    body: {
+      message: 'Stan says hi!'
+    }
+  };
+});