fix: allow to config timeout timer buffer (#138)

lumigo-io · Jul 15, 2020 · 949e554 · 949e554
1 parent 9154e98
commit 949e554
Show file tree

Hide file tree

Showing 4 changed files with 94 additions and 5 deletions.
diff --git a/src/tracer.js b/src/tracer.js
@@ -11,6 +11,8 @@ import {
   STEP_FUNCTION_UID_KEY,
   getContextInfo,
   isTimeoutTimerEnabled,
+  getTimeoutTimerBuffer,
+  getTimeoutMinDuration,
 } from './utils';
 import {
   getFunctionSpan,
@@ -29,19 +31,20 @@ export const ASYNC_HANDLER_REJECTED = 'async_handler_rejected';
 export const NON_ASYNC_HANDLER_ERRORED = 'non_async_errored';
 export const LEAK_MESSAGE =
   'Execution leak detected. More information is available in: https://docs.lumigo.io/docs/execution-leak-detected';
-const TIMEOUT_BUFFER_MS = 250;
 
 const setupTimeoutTimer = () => {
   logger.debug('Timeout timer set-up started');
   const { context } = TracerGlobals.getHandlerInputs();
   const { remainingTimeInMillis } = getContextInfo(context);
-  if (TIMEOUT_BUFFER_MS < remainingTimeInMillis) {
+  const timeoutBuffer = getTimeoutTimerBuffer();
+  const minDuration = getTimeoutMinDuration();
+  if (timeoutBuffer < remainingTimeInMillis && remainingTimeInMillis >= minDuration) {
     GlobalTimer.setGlobalTimeout(async () => {
       logger.debug('Invocation is about to timeout, sending trace data.');
       const spans = SpansContainer.getSpans();
       SpansContainer.clearSpans();
       await sendSpans(spans);
-    }, remainingTimeInMillis - TIMEOUT_BUFFER_MS);
+    }, remainingTimeInMillis - timeoutBuffer);
   }
 };
 

diff --git a/src/tracer.test.js b/src/tracer.test.js
@@ -90,7 +90,7 @@ describe('tracer', () => {
   });
 
   test('startTrace - timeout timer - simple flow', async done => {
-    const timeout = 1000;
+    const timeout = 2000;
     const testBuffer = 50;
 
     new EnvironmentBuilder().awsEnvironment().applyEnv();
@@ -108,8 +108,27 @@ describe('tracer', () => {
     }, timeout + testBuffer);
   });
 
+  test('startTrace - timeout timer - too short timeout', async done => {
+    const timeout = 500;
+    const testBuffer = 50;
+
+    new EnvironmentBuilder().awsEnvironment().applyEnv();
+    const handlerInputs = new HandlerInputesBuilder().withTimeout(timeout).build();
+    TracerGlobals.setHandlerInputs(handlerInputs);
+
+    await tracer.startTrace();
+    SpansContainer.addSpan({ id: 'SomeRandomHttpSpan' });
+
+    setTimeout(() => {
+      const requests = AxiosMocker.getRequests();
+      //1 for start span
+      expect(requests.length).toEqual(1);
+      done();
+    }, timeout + testBuffer);
+  });
+
   test('startTrace - timeout timer - called twice', async done => {
-    const timeout = 1000;
+    const timeout = 2000;
     const testBuffer = 50;
 
     new EnvironmentBuilder().awsEnvironment().applyEnv();

diff --git a/src/utils.js b/src/utils.js
@@ -28,6 +28,7 @@ export const GET_KEY_DEPTH_ENV_KEY = 'LUMIGO_KEY_DEPTH';
 export const DEFAULT_GET_KEY_DEPTH = 3;
 export const EXECUTION_TAGS_KEY = 'lumigo_execution_tags_no_scrub';
 export const SKIP_SCRUBBING_KEYS = [EXECUTION_TAGS_KEY];
+export const DEFAULT_TIMEOUT_MIN_DURATION = 2000;
 
 export const getContextInfo = context => {
   const remainingTimeInMillis = context.getRemainingTimeInMillis();
@@ -135,6 +136,9 @@ const VERBOSE_FLAG = 'LUMIGO_VERBOSE';
 const SEND_ONLY_IF_ERROR_FLAG = 'SEND_ONLY_IF_ERROR';
 const PRUNE_TRACE_OFF_FLAG = 'LUMIGO_PRUNE_TRACE_OFF';
 const STORE_LOGS_FLAG = 'LUMIGO_STORE_LOGS';
+const TIMEOUT_BUFFER_FLAG = 'LUMIGO_TIMEOUT_BUFFER';
+const TIMEOUT_MIN_DURATION = 'LUMIGO_TIMEOUT_MIN_DURATION';
+const TIMEOUT_BUFFER_FLAG_MS = 'LUMIGO_TIMEOUT_BUFFER_MS';
 
 const validateEnvVar = (envVar, value = 'TRUE') =>
   !!(process.env[envVar] && process.env[envVar].toUpperCase() === value.toUpperCase());
@@ -150,6 +154,19 @@ export const getEnvVarAsList = (key, def) => {
 
 export const isTimeoutTimerEnabled = () => !validateEnvVar(TIMEOUT_ENABLE_FLAG, 'FALSE');
 
+export const getTimeoutTimerBuffer = () => {
+  if (process.env[TIMEOUT_BUFFER_FLAG_MS]) return parseFloat(process.env[TIMEOUT_BUFFER_FLAG_MS]);
+  if (process.env[TIMEOUT_BUFFER_FLAG]) return parseFloat(process.env[TIMEOUT_BUFFER_FLAG]) * 1000;
+  const { context } = TracerGlobals.getHandlerInputs();
+  const { remainingTimeInMillis } = getContextInfo(context);
+  return Math.max(500, Math.min(remainingTimeInMillis / 10, 3000));
+};
+
+export const getTimeoutMinDuration = () => {
+  if (process.env[TIMEOUT_MIN_DURATION]) return parseFloat(process.env[TIMEOUT_MIN_DURATION]);
+  return DEFAULT_TIMEOUT_MIN_DURATION;
+};
+
 export const isVerboseMode = () => validateEnvVar(VERBOSE_FLAG);
 
 export const isWarm = () => validateEnvVar(WARM_FLAG);

diff --git a/src/utils.test.js b/src/utils.test.js
@@ -20,6 +20,7 @@ import { isDebug } from './logger';
 import { GET_KEY_DEPTH_ENV_KEY } from './utils';
 import { ConsoleWritesForTesting } from '../testUtils/consoleMocker';
 import { getEnvVarAsList, isEncodingType, isEmptyString, runOneTimeWrapper } from './utils';
+import { DEFAULT_TIMEOUT_MIN_DURATION } from './utils';
 
 describe('utils', () => {
   const spies = {};
@@ -323,6 +324,55 @@ describe('utils', () => {
     process.env['LUMIGO_VALID_ALIASES'] = undefined;
   });
 
+  test('getTimeoutMinDuration -> ENV_VAR', () => {
+    process.env['LUMIGO_TIMEOUT_MIN_DURATION'] = '500';
+    expect(utils.getTimeoutMinDuration()).toEqual(500);
+  });
+
+  test('getTimeoutMinDuration -> default', () => {
+    expect(utils.getTimeoutMinDuration()).toEqual(DEFAULT_TIMEOUT_MIN_DURATION);
+  });
+
+  test('getTimeoutTimerBuffer -> ENV_VAR', () => {
+    process.env['LUMIGO_TIMEOUT_BUFFER'] = '0.35';
+    expect(utils.getTimeoutTimerBuffer()).toEqual(350);
+  });
+
+  test('getTimeoutTimerBuffer -> ENV_VAR ms', () => {
+    process.env['LUMIGO_TIMEOUT_BUFFER_MS'] = '350';
+    expect(utils.getTimeoutTimerBuffer()).toEqual(350);
+  });
+
+  test('getTimeoutTimerBuffer -> Min value', () => {
+    expect(utils.isValidAlias()).toEqual(true);
+    TracerGlobals.setHandlerInputs({
+      context: {
+        getRemainingTimeInMillis: () => 1000,
+      },
+    });
+    expect(utils.getTimeoutTimerBuffer()).toEqual(500);
+  });
+
+  test('getTimeoutTimerBuffer -> Max value', () => {
+    expect(utils.isValidAlias()).toEqual(true);
+    TracerGlobals.setHandlerInputs({
+      context: {
+        getRemainingTimeInMillis: () => 60000,
+      },
+    });
+    expect(utils.getTimeoutTimerBuffer()).toEqual(3000);
+  });
+
+  test('getTimeoutTimerBuffer -> 10% of the run time', () => {
+    expect(utils.isValidAlias()).toEqual(true);
+    TracerGlobals.setHandlerInputs({
+      context: {
+        getRemainingTimeInMillis: () => 20000,
+      },
+    });
+    expect(utils.getTimeoutTimerBuffer()).toEqual(2000);
+  });
+
   test('setSwitchOff', () => {
     expect(utils.isSwitchedOff()).toBe(false);
     utils.setSwitchOff();