feat(logger): align sampling debug logs feature implementation with the other runtimes

[shdq]

Description of your changes

This PR introduces a new implementation for the sampling debug logs feature. It aligns with other runtimes, where log sampling decision is done at the per-function level.

Main changes:

• logsSampled field was removed in favor of the sample_rate
• setInitialSampleRate method initializes sampleRateValue in order like in initial log level method:

1. constructor
2. custom config
3. env var
4. default value (zero), it's never undefined now.

• validation added to sampleRateValue to be in range from 0.0 to 1.0. Before it could be any number. It doesn't throw an error and silently ignores invalid values. This could be improved on the types level, to only allow values in this range, but it's not trivial.

Related issues, RFCs

Issue number: #1136

Checklist

• My changes meet the tenets criteria
• I have performed a self-review of my own code
• I have commented my code where necessary, particularly in areas that should be flagged with a TODO, or hard-to-understand areas
• I have made corresponding changes to the documentation
• My changes generate no new warnings
• I have added tests that prove my change is effective and works
• The PR title follows the conventional commit semantics

Breaking change checklist

Is it a breaking change?: NO

• I have documented the migration process
• I have added, implemented necessary warnings (if it can live side by side)

---

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

Disclaimer: We value your time and bandwidth. As such, any pull requests created on non-triaged issues might not be successful.

[dreamorosi]

Hey Sergei, thanks a lot for the PR!

I need a bit more time to review it and try the code, but at first look it seems like you are in going in the right direction 😄

To answer your questions:

I removed refreshSampleRateCalculation() for now, should we make it an alias to configureSampling()?

In Python the method seems to be exclusively private (it starts with _), so maybe we don't need to.

Should we pollute log output when the log level is changed to DEBUG because of the sampling rate?
this.debug('Setting log level to DEBUG due to sampling rate') This behavior is ported from Python.

I'm not sure yet to be honest. On one hand, I can see how this could be useful to let people know that the log level has changed because of this feature.

On the other hand, I do kind of agree with your choice of wording (polluting), so I'm not sure.

Let me think about it a bit longer and I'll give you an answer when I review more in depth and run the code a few times, either way it should be an easy addition.

[shdq]

I removed refreshSampleRateCalculation() for now, should we make it an alias to configureSampling()?

In Python the method seems to be exclusively private (it starts with _), so maybe we don't need to.

My concern is that refreshSampleRateCalculation() is exposed in docs, so it would be another breaking change if we remove it.

[dreamorosi]

My concern is that refreshSampleRateCalculation() is exposed in docs, so it would be another breaking change if we remove it.

You are right, I would say let's keep it for now and adopt your suggestion.

[dreamorosi]

This is looking really good!

I have pulled the repo and made some suggestions. Also, as discussed on Discord, I'm sharing the modifications to adapt the integration tests.

In the packages/logger/tests/e2e/sampleRate.decorator.test.ts file, in the test case that starts with describe('Enabling sample rate', () => { (around L70), change the if/else to this:

if (logMessages.length === 1 && logMessages[0].includes('ERROR')) {
  countNotSampled++;
} else if (
  logMessages.length === 5 &&
  logMessages[0].includes(
    'Setting log level to DEBUG due to sampling rate'
  )
) {
  countSampled++;
} else {
  console.error(`Log group ${logGroupName} contains missing log`);
  throw new Error(
    'Sampled log should have either 1 error log or 4 logs of all levels'
  );
}

As you can see the test is the same, but now we are looking for 5 log entries when log sampling is enabled. The new log entry is the one that Logger emits to notify the user that debug log sampling is enabled, so we assert that it contains the correct string.

In order for this to work, we need to do a slight modification to the TestInvocationLogs class, which is used in this test (invocationLogs[i].getFunctionLogs()). The modification is needed because up until now we were looking only at log entries between the START and END logs of the invocation (which are the logs emitted within the scope of the function handler).

Now however we need also look at the ones emitted during the initialisation phase, since the debug log (Setting log level to DEBUG due to sampling rate) is emitted outside of the handler.

To do this we need to modify the file packages/testing/src/TestInvocationLogs.ts to the content below (collapsed for brevity).

import { LogLevel } from './constants.js';
import type { FunctionLog } from './types.js';

const CloudWatchLogKeywords = {
  END: 'END RequestId',
  INIT_START: 'INIT_START',
  REPORT: 'REPORT RequestId',
  START: 'START RequestId',
  XRAY: 'XRAY TraceId',
} as const;

class TestInvocationLogs {
  public static LEVEL = LogLevel;

  /**
   * Array of logs from invocation.
   *
   * The first element is START, and the last two elements are END, and REPORT.
   *    [
   *      'START RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678 Version: $LATEST',
   *      '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context and persistent key","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works"}',
   *      '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"INFO","message":"This is an INFO log with some context","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","additionalKey":"additionalValue"}',
   *      '{"cold_start":true,"function_arn":"arn:aws:lambda:eu-west-1:561912387782:function:loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_memory_size":128,"function_name":"loggerMiddyStandardFeatures-c555a2ec-1121-4586-9c04-185ab36ea34c","function_request_id":"7f586697-238a-4c3b-9250-a5f057c1119c","level":"ERROR","message":"There was an error","service":"logger-e2e-testing","timestamp":"2022-01-27T16:04:39.323Z","persistentKey":"works","error":{"name":"Error","location":"/var/task/index.js:2778","message":"you cannot prevent this","stack":"Error: you cannot prevent this\\n    at testFunction (/var/task/index.js:2778:11)\\n    at runRequest (/var/task/index.js:2314:36)"}}',
   *      'END RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678',
   *      'REPORT RequestId: c6af9ac6-7b61-11e6-9a41-93e812345678\tDuration: 2.16 ms\tBilled Duration: 3 ms\tMemory Size: 128 MB\tMax Memory Used: 57 MB\t',
   *    ]
   * See https://docs.aws.amazon.com/lambda/latest/dg/nodejs-logging.html for details
   */
  private logs: string[];

  public constructor(logResult: string) {
    const rawLog = Buffer.from(logResult, 'base64').toString('utf-8').trim();
    this.logs = rawLog.split('\n');
  }

  /**
   * Find all functional logs whether it contains a given text
   * @param text
   * @param levelToFilter level to filter
   * @returns
   */
  public doesAnyFunctionLogsContains(
    text: string,
    levelToFilter?: keyof typeof LogLevel
  ): boolean {
    const filteredLogs = this.getFunctionLogs(levelToFilter).filter((log) =>
      log.includes(text)
    );

    return filteredLogs.length > 0;
  }

  /**
   * Return all the log of the function
   * @returns Array of function logs
   */
  public getAllFunctionLogs(): string[] {
    return this.logs;
  }

  /**
   * Return the index of the log that contains `END RequestId`
   * @param logs
   * @returns {number} index of the log that contains END RequestId
   */
  public static getEndLogIndex(logs: string[]): number {
    return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.END));
  }

  /**
   * Return only logs from function, exclude INIT_START, START, END, REPORT,
   * and X-Ray log generated by the Lambda service.
   *
   * @param {typeof LogLevel} [levelToFilter] - Level to filter the logs
   * @returns Array of function logs, filtered by level if provided
   */
  public getFunctionLogs(levelToFilter?: keyof typeof LogLevel): string[] {
    const exclusionKeywords = Object.values(CloudWatchLogKeywords);
    let filteredLogs = this.logs.filter(
      (log) => !exclusionKeywords.some((keyword) => log.startsWith(keyword))
    );

    if (levelToFilter) {
      filteredLogs = filteredLogs.filter((log) => {
        try {
          const parsedLog = TestInvocationLogs.parseFunctionLog(log);

          return parsedLog.level == levelToFilter;
        } catch (error) {
          // If log is not from structured logging : such as metrics one.
          return (
            (log.split('\t')[2] as keyof typeof LogLevel) === levelToFilter
          );
        }
      });
    }

    return filteredLogs;
  }

  /**
   * Return the index of the log that contains `INIT_START`
   * @param logs
   * @returns {number} index of the log that contains `INIT_START`
   */
  public static getInitLogIndex(logs: string[]): number {
    return logs.findIndex((log) =>
      log.startsWith(CloudWatchLogKeywords.INIT_START)
    );
  }

  /**
   * Return the index of the log that contains `REPORT RequestId`
   * @param logs
   * @returns {number} index of the log that contains `REPORT RequestId`
   */
  public static getReportLogIndex(logs: string[]): number {
    return logs.findIndex((log) =>
      log.startsWith(CloudWatchLogKeywords.REPORT)
    );
  }

  /**
   * Return the index of the log that contains `START RequestId`
   * @param logs
   * @returns {number} index of the log that contains `START RequestId`
   */
  public static getStartLogIndex(logs: string[]): number {
    return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.START));
  }

  /**
   * Return the index of the log that contains `XRAY TraceId`
   * @param logs
   * @returns {number} index of the log that contains `XRAY TraceId`
   */
  public static getXRayLogIndex(logs: string[]): number {
    return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.XRAY));
  }

  /**
   * Each of log message contains a JSON with the structured Log object (e.g. {\"cold_start\":true, ..})
   * @param log
   */
  public static parseFunctionLog(log: string): FunctionLog {
    return JSON.parse(log);
  }
}

export { TestInvocationLogs };

After making the change in the testing package, if you want to run the tests, you'll have to run npm run build -w pacakges/testing first.

Hope this helps!

[sonarcloud]

Kudos, SonarCloud Quality Gate passed!   

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

No Coverage information
20.8% Duplication

[shdq]

Oh, one last thing to update is the docs section.

[dreamorosi]

I have just run the integration tests and they're passing 🎉

As discussed on Discord, I'm going to take care of the docs in a separate PR since I have to also create the v2 update guide.

Thanks A TON for the work on this, it's highly appreciated!

[dreamorosi]

The CI checks are failing due to an extra comma that I introduced a while ago in a previous commit - this is due to the version of Prettier on main being older than the one in this branch and it's formatting in that specific case having changed.

I have already fixed the issue in another commit on the branch being merged into (here), and the file wasn't touched in this PR, so merging anyway.