Is there a way to change event logging to debug instead of info

[FlemmingBehrend]

Hi,

What do I want to achieve?

I want to use powertools logging to log successful lambda invocations with a sampling rate of 0.1, and when an error happens I want to always log all debug statements.

I have the following setup for all lambda functions in production

// Environment variables set for lambda
// POWERTOOLS_LOGGER_SAMPLE_RATE: '0.1', // 10% of debug logs are logged to cloundwatch
// POWERTOOLS_LOG_LEVEL: 'DEBUG'

// in the lambda code
const log = new Logger({
  correlationIdSearchFn: search,
  serviceName,
  logBufferOptions: {
    bufferAtVerbosity: 'DEBUG',
    flushOnErrorLog: true
  }
});

// I use middy to inject the lambdaContext
middy(lambdaFunction).use(injectLambdaContext(log, { logEvent: true, flushBufferOnUncaughtError: true }));

The problem

My problem is that the input event to the lambda function is logged as INFO and therefore is always applied to the CloudWatch logs.

I would like to only log input events for the lambda function if an error occurs.

I can choose not to use injectLambdaContexts logEvent feature and manually add debug logs to all my lambda functions to log the event, but it seams to go against what is the idea with logEvent.

Is there a way to change the logEvent to log as DEBUG instead of INFO?

[dreamorosi]

Hi @FlemmingBehrend, thank you for opening this discussion.

Generally speaking we wouldn't advise to follow that pattern and leave the logEvent feature enabled in production, even if sampled, because depending the contents of your event payload there's a risk to log/leak sensitive data.

With that said, if your use case allows it, then I can see why you'd want to emit that log as DEBUG and buffer/sample it. At the moment there's no out-of-the-box way of doing this, the only way you can achieve this would be to extend the logger like so:

class MyLogger extends Logger {
  public logEventIfEnabled(event: unknown, overwriteValue?: boolean): void {
    if (!this.shouldLogEvent(overwriteValue)) return;
    this.debug('event', { event });
  }
}

const log = MyLogger({
  // ... your existing config
})

This way you'd be taking over the internal method/logic used to determine if the event payload should be logged, which gives you the ability to control the log level. The pattern of extending the Logger class is relatively common and I've seen many customers use it when they want to have more control over certain aspects that are not exposed via configuration.

This would be a medium term solution, however if you think this is a common enough of a need, maybe we could have a discussion on whether this should be the default behavior (most definitely in a future major version) or be configurable in an easy way (perhaps via environment variable/constructor prop).

to log successful lambda invocations with a sampling rate of 0.1, and when an error happens

As a final side note, make sure to test how sampling and buffering play together. If I remember correctly, once buffering is enabled, even those debug logs that were part of a sampled invocations will be buffered - so essentially you'd be never seeing these logs unless there's an error.

If this is what you intended, then no action required, but this sentence from your original post suggests you might be expecting something different to happen.

[FlemmingBehrend]

Hi @dreamorosi

Thank you for taking the time to give me a detailed answer.

Generally speaking we wouldn't advise to follow that pattern and leave the logEvent feature enabled in production, even if sampled, because depending the contents of your event payload there's a risk to log/leak sensitive data.

The setup we have logs to the lambdas CloudWatch group. This log group can not be read as it requires the breakglass user to view logs in the group. When a log group is created for a lambda we automatically attach a subscription lambda that handles log statements added to the log group, filter out sensitive data and put the logs in our log solution that is elastic search.

My understanding of the sampling rate

Maybe I have misunderstood the way it works, my understanding was that when sampling was enabled and set to 0.1 etc, then when the sampling was calculated to "on" the log level would always be set to DEBUG (regardless of what it was set to when the logger was created)

I have tried to test that out with the following snippet and it seams to work that way.

import { Logger } from '@aws-lambda-powertools/logger';
import process from 'node:process';

process.env['POWERTOOLS_LOG_LEVEL'] = 'ERROR';
process.env['POWERTOOLS_LOGGER_SAMPLE_RATE'] = '0.1';

function simulateInvocation(invocationNumber) {
  const log = new Logger({
    serviceName: 'quokka-test-sampling'
  });

  console.log(`Simulating invocation ${invocationNumber}... ${log.getLevelName()}`);

  log.debug(`Invocation ${invocationNumber}: Debugging information`); // only logged when sampling is "on"
  log.info(`Invocation ${invocationNumber}: Informational message`); // only logged when sampling is "on"
  log.warn(`Invocation ${invocationNumber}: Warning message`); // only logged when sampling is "on"
  log.error(`Invocation ${invocationNumber}: Error message`); // always logged
}

// Simulate 10 invocations
for (let i = 1; i <= 10; i++) {
  simulateInvocation(i);
}

It give the following output and as you see the log.getLogLevel() returns DEBUG when sampling is "on"

Why I set the log level to debug

My usecase is that normal lambda invocations should almost never do any logging (This should be handled by the sampling). This is to save CloudWatch costs as it is one of our most expensive areas because developers are logging debug all the time. They do that to make sure that they have the information to debug an error for a customer.

So my intend is to keep log cost to a minimum. For a lambda invocation with no errors not much should be logged, but when an error occurs we flush the logs and have debug logs available.

This is the reason for setting log level to DEBUG and enable buffering, so we always buffer DEBUG, but do not write them to CloudWatch unless an error is happening.

To achieve that I set flushOnErrorLog: true and flushBufferOnUncaughtError: true so when I log an error message or an uncaught error happens I flush the logs.

I seams like the logEvent: true in injectLambdaContext does not honor the sampling rate and is not buffered, it will log the event as INFO every time if the log level is DEBUG even though the sampling rate was calculated to "off".

Maybe this is the real problem.