Feature request: Always log message even when sampling is enabled

[bestickley]

Use case

Important

See this comment for an updated scope & context on the issue.

I'd like to use Lambda Powertools Logger to log audit information. This info needs to be logged 100% of the time whereas my other log information doesn't. When I enable a sample rate, I'd like to be able to be sure the audit information is logged.

Solution/User Experience

const logger = new Logger({
  serviceName: "MyService",
});
// don't care about "always", could be whatever you think makes sense
logger.always.info("Here is my important log information");

Alternative solutions

No response

Acknowledgment

• This feature request meets Lambda Powertools Tenets
• Should this be considered in other Lambda Powertools languages? i.e. Python, Java

[dreamorosi]

Hi @bestickley thank you for opening this issue.

Please allow us some time to review this and come up with an answer.

[dreamorosi]

At the moment we don't support this type of behavior, however I think it's worth discussing and I would like also to hear the opinion of other maintainers and customers.

In the meantime, I would like to suggest an alternative to achieve a similar behavior. The alternative revolves around using two logger instances:

import { Logger, injectLambdaContext } from "@aws-lambda-powertools/logger";
import middy from "@middy/core";

const logger = new Logger({
  serviceName: "MyService",
  sampleRateValue: 0.01,
});
const auditLogger = logger.createChild({
  sampleRateValue: 1,
});

export const handler = middy(async () => {
  logger.info("I log sometimes");
  auditLogger.info("I always log");
})
  .use(injectLambdaContext(logger))
  .use(injectLambdaContext(auditLogger));

These should produce the following logs:

{
    "cold_start": false,
    "function_arn": "arn:aws:lambda:eu-west-1:536254204126:function:lambda-powertools-playground-fn",
    "function_memory_size": 128,
    "function_name": "lambda-powertools-playground-fn",
    "function_request_id": "6bb4c509-31d0-4dc7-9e16-f08f22a70b59",
    "level": "INFO",
    "message": "I log sometimes",
    "sampling_rate": 0.01,
    "service": "MyService",
    "timestamp": "2022-11-13T16:47:24.460Z",
    "xray_trace_id": "1-63711f9c-4c1fc3284f97466b7ff88473"
}
{
    "cold_start": false,
    "function_arn": "arn:aws:lambda:eu-west-1:536254204126:function:lambda-powertools-playground-fn",
    "function_memory_size": 128,
    "function_name": "lambda-powertools-playground-fn",
    "function_request_id": "6bb4c509-31d0-4dc7-9e16-f08f22a70b59",
    "level": "INFO",
    "message": "I always log",
    "sampling_rate": 1,
    "service": "service_undefined",
    "timestamp": "2022-11-13T16:47:24.461Z",
    "xray_trace_id": "1-63711f9c-4c1fc3284f97466b7ff88473"
}

Notice the usage of createChild & the fact that I'm using the injectLambdaContext middleware twice (however it would work also with decorator & manual modes using the corresponding methods).

---

I'm going to add the need-customer-feedback label to hear also from other customers. If anyone comes across this issue and finds it interesting, please add a 👍 and consider sharing your use case.

[saragerion]

Agree with Andrea. I would also like to add that to be even extra sure that all the audit logs will be logged, you can set a custom logLevel in the constructor that will override any level set via env variables:

const auditLogger = logger.createChild({
  sampleRateValue: 1,
  logLevel: 'DEBUG' 
});

This is a very valid and common use case and we may consider adding a dedicated section in the docs.

---

Edit

Example:

import { Logger } from "@aws-lambda-powertools/logger";

const logger = new Logger({
  serviceName: "MyService",
  logLevel: 'ERROR',
  sampleRateValue: 0.5,
});

const auditLogger = logger.createChild({
  sampleRateValue: 1,
  logLevel: 'DEBUG'
});

export const handler = async () => {
  
  logger.error("I always log");
  logger.info("I log 50% of the time");
  logger.info("I log 50% of the time");
  logger.info("I log 50% of the time");
  
  auditLogger.debug("I always log");
  
};

[nateiler]

Weighing in on this potential feature as well. Adding a child logger is an interesting approach (and works for now), however it doesn't excite me to have all the log levels available to the 'audit' logger... feels a bit like a hack.

In an ideal world, we could do something like logger.audit( ... ). Additionally, having a persistent attribute that we could filter on within CloudWatch is helpful.

At the moment, we're doing something like this:

const logger = new Logger({ logLevel: 'WARN' });
const audit = logger.createChild({
  logLevel: "INFO",
  persistentLogAttributes: { audit: true },
});

We're only logging with audit.info() as to not disturb WARN and ERROR metrics and in CloudWatch we can filter by the persistent 'audit' attribute.

[dreamorosi]

After reviewing this issue and also comparing the implementation in this version of the project with the other implementations found in Powertools for AWS Lambda Python, Java, and .NET we have decided to pivot this feature and align it with the other runtimes.

In this version of Powertools when enabled, the log sampling feature leaves the log level as-is and and emits logs from noisier log levels than the one set on a % of the invocations. The main issues with this implementation is that the log sampling decision is done at the execution environment level (as opposed to a per-function level) and the default sampling is 0.

The same feature in the Python, Java, and .NET versions of Powertools instead dynamically changes the log level to DEBUG on a % of the invocations, and the % is calculated at the execution environment level.

As part of the renewed scope for this issue we should align the implementation with the ones found in the other versions of Python. This way our customers will experience less cognitive load when using multiple runtimes and the default behavior won't risk causing data loss.

If there's demand for a true log sampling that allows to not emit a % of the logs at the function level, we'll consider this as a new feature and implement it properly this time.

[shdq]

Hello, Andrea 👋 I'm happy to help here!
I read through the issue and will look at the Python and other implementations. I would like you to share any additional context, if any. I'm also available in Discord.

[dreamorosi]

Hey @shdq so happy to see you again!

I think overall the feature will require quite a bit of refactor and potentially many changes in unit & integration tests. For this feature, as well as all the ones in the V2 milestone, we are going to work on the feat/v2 branch which has already diverged from main and is considered somewhat unstable at the moment. This means you'll have to create your working branch starting from feat/v2 and then once ready, open a PR against it.

When it comes to internal-facing changes, we have a lot of liberty as long as the changes don't disrupt other methods. When it comes to external-facing changes in contracts and APIs we have some liberty but I'd like to reserve breaking changes as a last resort. The less breaking changes we do, the easier the migration from v1 to v2 will be.

Regarding the specific feature, as you might recall, the Logger relies on a set of log thresholds that are numeric values that represent the log levels supported.

At the moment these thresholds are used together with the sample rate to decide whether a certain log entry is emitted or not. That logic is in this method.

I imagine that the changes required to change the behavior will have to involve that shouldPrint() method as well as likely adding new logic around the log level state. If I was going to work on this I would approach this in three steps:

1. Remove all the logic, tests, etc. related to the current log sampling implementation & get to a state where everything else in the Logger works
2. Review the implementation in Python and see a similar logic can be ported here. In their case they seem to define a _configure_sampling() private method that is called sometime during the initialization of the Logger and essentially overrides the log level and sets it to DEBUG if that instance is considered sampled based on the % calculated from the sample rate
3. Implement the logic in the codebase, write tests, amend docs

Note that this is just a suggestion. I'd be keen to hear your opinion as well after you've had some time to get acquainted with the implementation.

Let me know if you have any question, as usual I'll be available to discuss either here or on Discord.

Looking forward to collaborate on this!

[github-actions]

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.