fix: size and time limitations on large invocations (#490)

* fix: rewrite the max latency reached log * fix: better debug log for splitting spans into zip bulks * fix: log when spans are skipped due to large total spans size * feat: env var for max spans size stored * test: getStoredSpansMaxSize using value from env var if present
lumigo-io · Jul 14, 2024 · b6d3153 · b6d3153
1 parent 16ecb28
commit b6d3153
Show file tree

Hide file tree

Showing 9 changed files with 90 additions and 20 deletions.
diff --git a/src/globals.test.js b/src/globals.test.js
@@ -3,6 +3,7 @@ import * as globals from './globals';
 import {
   DEFAULT_MAX_SIZE_FOR_REQUEST,
   DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR,
+  DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
   MAX_TRACER_ADDED_DURATION_ALLOWED,
 } from './globals';
 import { getMaxRequestSize } from './utils';
@@ -64,7 +65,7 @@ describe('globals', () => {
     expect(spans).toEqual([span1]);
   });
 
-  test('SpansContainer - cleanning the request size limiter', () => {
+  test('SpansContainer - cleaning the request size limiter', () => {
     const span1 = { a: 'b', c: 'd', id: '1' };
     for (let i = 0; i < getMaxRequestSize(); i++) {
       globals.SpansContainer.addSpan(span1);
@@ -238,6 +239,7 @@ describe('globals', () => {
     const isStepFunction = false;
     const maxSizeForRequest = 1234;
     const maxSizeForRequestOnError = 12345;
+    const maxSizeForStoredSpansInMemory = 1234567;
     globals.TracerGlobals.setTracerInputs({
       token,
       debug,
@@ -246,6 +248,7 @@ describe('globals', () => {
       isStepFunction,
       maxSizeForRequest,
       maxSizeForRequestOnError,
+      maxSizeForStoredSpansInMemory,
     });
     expect(globals.TracerGlobals.getTracerInputs()).toEqual({
       token,
@@ -256,6 +259,7 @@ describe('globals', () => {
       lambdaTimeout: MAX_TRACER_ADDED_DURATION_ALLOWED,
       maxSizeForRequest,
       maxSizeForRequestOnError,
+      maxSizeForStoredSpansInMemory,
     });
     globals.TracerGlobals.clearTracerInputs();
     expect(globals.TracerGlobals.getTracerInputs()).toEqual({
@@ -267,6 +271,7 @@ describe('globals', () => {
       isStepFunction: false,
       maxSizeForRequest: DEFAULT_MAX_SIZE_FOR_REQUEST,
       maxSizeForRequestOnError: DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR,
+      maxSizeForStoredSpansInMemory: DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
     });
   });
 
@@ -310,6 +315,7 @@ describe('globals', () => {
       lambdaTimeout: MAX_TRACER_ADDED_DURATION_ALLOWED,
       maxSizeForRequest: DEFAULT_MAX_SIZE_FOR_REQUEST,
       maxSizeForRequestOnError: DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR,
+      maxSizeForStoredSpansInMemory: DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
     });
   });
 

diff --git a/src/globals.ts b/src/globals.ts
@@ -5,23 +5,31 @@ import { BasicSpan } from './types/spans/basicSpan';
 import {
   getAutoTagKeys,
   getJSONBase64Size,
-  getMaxRequestSize,
-  getMaxRequestSizeOnError,
+  getMaxSizeForStoredSpansInMemory,
   isLambdaTraced,
   spanHasErrors,
 } from './utils';
 import { GlobalDurationTimer } from './utils/globalDurationTimer';
 import { isString } from '@lumigo/node-core/lib/common';
+import { runOneTimeWrapper } from './utils/functionUtils';
 
 const MAX_TAGS = 50;
 const MAX_TAG_KEY_LEN = 50;
 const MAX_TAG_VALUE_LEN = 70;
 const ADD_TAG_ERROR_MSG_PREFIX = 'Skipping addExecutionTag: Unable to add tag';
 export const DEFAULT_MAX_SIZE_FOR_REQUEST = 1024 * 500;
 export const DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR = 1024 * 990;
+export const DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY =
+  DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR * 10;
 export const MAX_TRACER_ADDED_DURATION_ALLOWED = 750;
 export const MIN_TRACER_ADDED_DURATION_ALLOWED = 200;
 
+const warnSpansSizeOnce = runOneTimeWrapper((threshold: number, currentSize: number) => {
+  logger.info(
+    `Lumigo tracer is no longer collecting data on the invocation - maximum size of total spans collected (${threshold} bytes allowed, current size is ${currentSize} bytes)`
+  );
+}, {});
+
 export class SpansContainer {
   private static spans: { [id: string]: BasicSpan } = {};
   private static currentSpansSize: number = 0;
@@ -33,12 +41,19 @@ export class SpansContainer {
       this.totalSpans += 1;
     }
     // Memory optimization, take up to 10x maxSize because of smart span selection logic
-    if (spanHasErrors(span) || getMaxRequestSizeOnError() * 10 > this.currentSpansSize) {
+    const maxSpansSize = getMaxSizeForStoredSpansInMemory();
+    if (spanHasErrors(span) || this.currentSpansSize <= maxSpansSize) {
       this.spans[span.id] = span;
       this.currentSpansSize += getJSONBase64Size(span);
       logger.debug('Span created', span);
       return true;
     }
+
+    logger.debug('Span was not added due to size limitations', {
+      currentSpansSize: this.currentSpansSize,
+      maxSpansSize,
+    });
+    warnSpansSizeOnce(maxSpansSize, this.currentSpansSize);
     return false;
   }
 
@@ -213,6 +228,7 @@ export const TracerGlobals = (() => {
     isStepFunction: false,
     maxSizeForRequest: DEFAULT_MAX_SIZE_FOR_REQUEST,
     maxSizeForRequestOnError: DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR,
+    maxSizeForStoredSpansInMemory: DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
     lambdaTimeout: MAX_TRACER_ADDED_DURATION_ALLOWED,
   };
 
@@ -241,7 +257,15 @@ export const TracerGlobals = (() => {
     maxSizeForRequest = null,
     maxSizeForRequestOnError = null,
     lambdaTimeout = MAX_TRACER_ADDED_DURATION_ALLOWED,
-  }: TracerOptions) =>
+    maxSizeForStoredSpansInMemory = DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
+  }: TracerOptions) => {
+    const parsedMaxSizeForRequestOnError =
+      maxSizeForRequestOnError ||
+      (process.env['LUMIGO_MAX_SIZE_FOR_REQUEST_ON_ERROR']
+        ? parseInt(process.env.LUMIGO_MAX_SIZE_FOR_REQUEST_ON_ERROR)
+        : DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR);
+    const parsedMaxSizeForStoredSpansInMemory =
+      maxSizeForStoredSpansInMemory || parsedMaxSizeForRequestOnError * 10;
     Object.assign(tracerInputs, {
       token: token || process.env.LUMIGO_TRACER_TOKEN,
       debug: debug,
@@ -259,12 +283,10 @@ export const TracerGlobals = (() => {
         (process.env['LUMIGO_MAX_SIZE_FOR_REQUEST']
           ? parseInt(process.env.LUMIGO_MAX_SIZE_FOR_REQUEST)
           : DEFAULT_MAX_SIZE_FOR_REQUEST),
-      maxSizeForRequestOnError:
-        maxSizeForRequestOnError ||
-        (process.env['LUMIGO_MAX_SIZE_FOR_REQUEST_ON_ERROR']
-          ? parseInt(process.env.LUMIGO_MAX_SIZE_FOR_REQUEST_ON_ERROR)
-          : DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR),
+      maxSizeForRequestOnError: parsedMaxSizeForRequestOnError,
+      maxSizeForStoredSpansInMemory: parsedMaxSizeForStoredSpansInMemory,
     });
+  };
 
   const getTracerInputs = () => tracerInputs;
 
@@ -277,6 +299,7 @@ export const TracerGlobals = (() => {
       isStepFunction: false,
       maxSizeForRequest: DEFAULT_MAX_SIZE_FOR_REQUEST,
       maxSizeForRequestOnError: DEFAULT_MAX_SIZE_FOR_REQUEST_ON_ERROR,
+      maxSizeForStoredSpansInMemory: DEFAULT_MAX_SIZE_FOR_SPANS_STORED_IN_MEMORY,
     });
 
   return {

diff --git a/src/reporter.test.ts b/src/reporter.test.ts
@@ -1148,7 +1148,7 @@ describe('reporter', () => {
     expect(JSON.parse(logs[1].obj).stack).toBeTruthy();
   });
 
-  test('sending a huge payload, bigger than the regular limit, zipping and geeting is back completely', async () => {
+  test('sending a huge payload, bigger than the regular limit, zipping and getting is back completely', async () => {
     const token = 'DEADBEEF';
     TracerGlobals.setTracerInputs({ token });
     const span = {

diff --git a/src/reporter.ts b/src/reporter.ts
@@ -190,7 +190,7 @@ export const forgeAndScrubRequestBody = (
   ) {
     if (shouldTryZip) {
       logger.debug(
-        `Spans are too big, size [${size}], bigger than: [${maxRequestSize}], trying to split and zip`
+        `Spans are too big, size [${size}], [${spans.length}] spans, bigger than: [${maxRequestSize}], trying to split and zip`
       );
       const zippedSpansBulks = splitAndZipSpans(spans);
       const areAllSpansSmallEnough = zippedSpansBulks.every(

diff --git a/src/tracer/tracer-options.interface.ts b/src/tracer/tracer-options.interface.ts
@@ -8,4 +8,5 @@ export interface TracerOptions {
   maxSizeForRequestOnError?: number | null;
   lambdaTimeout?: number;
   verbose?: boolean;
+  maxSizeForStoredSpansInMemory?: number;
 }
diff --git a/src/tracer/tracer.ts b/src/tracer/tracer.ts
@@ -159,7 +159,7 @@ export const sendEndTraceSpans = async (functionSpan, handlerReturnValue) => {
   logLeakedSpans(spans);
 
   const { transactionId } = endFunctionSpan;
-  logger.debug('Tracer ended', { transactionId });
+  logger.debug('Tracer ended', { transactionId, totalSpans: spans.length });
   clearGlobals();
 };
 

diff --git a/src/utils.test.js b/src/utils.test.js
@@ -29,6 +29,9 @@ import {
   shouldScrubDomain,
   getTraceId,
   safeExecuteAsync,
+  getMaxSizeForStoredSpansInMemory,
+  LUMIGO_STORED_SPANS_MAX_SIZE_BYTES_ENV_VAR,
+  LUMIGO_SUPPORT_LARGE_INVOCATIONS,
 } from './utils';
 
 describe('utils', () => {
@@ -311,6 +314,15 @@ describe('utils', () => {
     expect(utils.getEventEntitySize()).toBe(DEFAULT_LUMIGO_MAX_ENTRY_SIZE);
   });
 
+  test('getStoredSpansMaxSize using env var value', () => {
+    const valueBefore = getMaxSizeForStoredSpansInMemory();
+    process.env[LUMIGO_STORED_SPANS_MAX_SIZE_BYTES_ENV_VAR] = `${valueBefore + 100}`;
+    expect(getMaxSizeForStoredSpansInMemory()).toBe(valueBefore);
+
+    process.env[LUMIGO_SUPPORT_LARGE_INVOCATIONS] = 'true';
+    expect(getMaxSizeForStoredSpansInMemory()).toBe(valueBefore + 100);
+  });
+
   test('getConnectionTimeout => simple flow', () => {
     process.env.LUMIGO_CONNECTION_TIMEOUT = '600';
     expect(utils.getConnectionTimeout()).toBe(600);

diff --git a/src/utils.ts b/src/utils.ts
@@ -36,6 +36,7 @@ export const LUMIGO_SECRET_MASKING_ALL_MAGIC = 'all';
 export const LUMIGO_SECRET_MASKING_EXACT_PATH = 'LUMIGO_SECRET_MASKING_EXACT_PATH';
 export const LUMIGO_WHITELIST_KEYS_REGEXES = 'LUMIGO_WHITELIST_KEYS_REGEXES';
 export const LUMIGO_SUPPORT_LARGE_INVOCATIONS = 'LUMIGO_SUPPORT_LARGE_INVOCATIONS';
+export const LUMIGO_STORED_SPANS_MAX_SIZE_BYTES_ENV_VAR = 'LUMIGO_STORED_SPANS_MAX_SIZE_BYTES';
 export const OMITTING_KEYS_REGEXES = [
   '.*pass.*',
   '.*key.*',
@@ -225,7 +226,6 @@ 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 TRACER_TIMEOUT_FLAG = 'LUMIGO_TRACER_TIMEOUT';
 const AGENT_KEEPALIVE = 'LUMIGO_AGENT_KEEPALIVE_MS';
 const REUSE_CONNECTION = 'LUMIGO_REUSE_HTTP_CONNECTION';
 const KEEP_HEADERS = 'LUMIGO_KEEP_HTTP_HEADERS';
@@ -240,6 +240,7 @@ const LUMIGO_STACK_PATTERNS = [
   new RegExp('/node_modules/@lumigo/tracer/', 'i'),
 ];
 
+export const TRACER_TIMEOUT_FLAG = 'LUMIGO_TRACER_TIMEOUT';
 export const SWITCH_OFF_FLAG = 'LUMIGO_SWITCH_OFF';
 
 const validateEnvVar = (envVar: string, value: string = 'TRUE'): boolean =>
@@ -342,8 +343,6 @@ export const isLambdaWrapped = (): boolean => validateEnvVar(WRAPPED_FLAG);
 
 export const shouldPropagateW3C = (): boolean => !validateEnvVar(LUMIGO_PROPAGATE_W3C, 'FALSE');
 
-export const shouldTryZip = (): boolean => validateEnvVar(LUMIGO_SUPPORT_LARGE_INVOCATIONS);
-
 export const setLambdaWrapped = (): void => {
   process.env[WRAPPED_FLAG] = 'TRUE';
 };
@@ -674,6 +673,31 @@ export const filterObjectKeys = (
       return Object.assign(cur, { [key]: obj[key] });
     }, {});
 
+export const shouldTryZip = () => validateEnvVar(LUMIGO_SUPPORT_LARGE_INVOCATIONS);
+
+const getLumigoStoredSpansMaxSizeBytesOverrideValue = () => {
+  const value = process.env[LUMIGO_STORED_SPANS_MAX_SIZE_BYTES_ENV_VAR];
+  if (value && shouldTryZip()) {
+    const parsedValue = parseInt(value);
+    if (!isNaN(parsedValue)) {
+      return parsedValue;
+    }
+  }
+  return undefined;
+};
+
+/**
+ * The maximum size of all spans stored in memory before sending them to lumigo.
+ * This limit is in place to prevent storing too many spans in memory and causing OOM errors.
+ * Note: when the invocation ends and the spans are processed before sending to Lumigo, more processing and truncating
+ * might take place
+ * @returns number maximum size in bytes
+ */
+export const getMaxSizeForStoredSpansInMemory = (): number => {
+  const overrideValue = getLumigoStoredSpansMaxSizeBytesOverrideValue();
+  return overrideValue || TracerGlobals.getTracerInputs().maxSizeForStoredSpansInMemory;
+};
+
 export const isLambdaTraced = () => isAwsEnvironment() && !isSwitchedOff();
 export const getRequestBodyMaskingRegex = (): string | undefined =>
   process.env[LUMIGO_SECRET_MASKING_REGEX_HTTP_REQUEST_BODIES];

diff --git a/src/utils/globalDurationTimer.ts b/src/utils/globalDurationTimer.ts
@@ -1,9 +1,13 @@
 import * as logger from '../logger';
-import { getTracerMaxDurationTimeout } from '../utils';
+import { getTracerMaxDurationTimeout, TRACER_TIMEOUT_FLAG } from '../utils';
 import { runOneTimeWrapper } from './functionUtils';
 
-const warnTimeoutOnce = runOneTimeWrapper(() => {
-  logger.warn('Lumigo tracer is no longer collecting data on the invocation.');
+const warnTimeoutOnce = runOneTimeWrapper((threshold: number, currentDuration: number) => {
+  logger.info(
+    `Stopped collecting data for this invocation because it reached the maximum ` +
+      `of ${threshold} ms added (added ${currentDuration} ms so far) to the duration of the Lambda. ` +
+      `This limit can be modified by setting the ${TRACER_TIMEOUT_FLAG} environment variable`
+  );
 }, {});
 
 export const GlobalDurationTimer = (() => {
@@ -32,7 +36,7 @@ export const GlobalDurationTimer = (() => {
     appendTime();
     threshold = threshold || getTracerMaxDurationTimeout();
     if (currentDuration >= threshold) {
-      warnTimeoutOnce();
+      warnTimeoutOnce(threshold, currentDuration);
       return true;
     }
     return false;