Bug: child logger with overwritten options clear all other options

[dreamorosi]

Expected Behaviour

When creating a child logger (see "Code snippet" section) and passing some options the child logger should retain all the parent properties/options except the ones explicitly overwritten.

Current Behaviour

The child logger won't have all the same options that the parent has whenever the user creates the logger while also passing some options to overwrite. For example:

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

From the example above, I would expect auditLogger to have the same serviceName as logger and only differ in sampleRateValue - however as you can see from the logs in the "Debugging logs" section, serviceName is undefined in auditLogger.

Code snippet

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));

Possible Solution

Rework the createChild function in Logger to account for passed options and add unit tests to confirm fix & prevent future regressions.

Steps to Reproduce

Deploy a function using the code shared in the "Code snippet" section, then execute it, finally observe the logs (see example in Debugging logs section).

AWS Lambda Powertools for TypeScript version

latest

AWS Lambda function runtime

16.x

Packaging format used

Npm

Debugging 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": "MyService",
    "timestamp": "2022-11-13T16:47:24.461Z",
    "xray_trace_id": "1-63711f9c-4c1fc3284f97466b7ff88473"
}

[shdq]

@dreamorosi hi, let's fix this! 😉

Maybe you copy-pasted the debugging logs wrong, so there isn't an undefined value for the "service" key.

I ran the snippet in my lambda, and it logged "service":"service_undefined" for the child logger.

I will look at it and come up with a plan.

[dreamorosi]

Hey @shdq, indeed I copy-pasted the logs wrong. I just checked and it's like you say (which is the issue I was trying to report).

Thank you for stepping up on this, I'll assign the issue to you and will be happy to collaborate.

[shdq]

Hello @dreamorosi I hope you're doing well.

The problem in this line in setPowertoolLogData:

serviceName: serviceName || this.getCustomConfigService()?.getServiceName() || this.getEnvVarsService().getServiceName() || this.getDefaultServiceName(),

I created a Frankenstein, that fix that issue, but it should be killed 😁

serviceName:
  serviceName ||
  (this.powertoolLogData.serviceName &&
    this.powertoolLogData.serviceName !== this.getDefaultServiceName() ?
      this.powertoolLogData.serviceName :
      this.getCustomConfigService()?.getServiceName() ||
        this.getEnvVarsService().getServiceName() ||
        this.getDefaultServiceName()),

Let's keep going, we have parent and child:

const parentLogger = new Logger({
  serviceName: "test-service-name",
  sampleRateValue: 0.01,
});

const childLogger = parentLogger.createChild({ sampleRateValue: 1 });

if we create a grandson from the child:

const grandsonLogger = childLogger.createChild({ serviceName: "grand-son-logger-name" });

It works with serviceName, thanks to Frankie, but now lost "sampleRateValue": 1 value and "logsSampled": true. We can patch this too in setOptions():

this.setSampleRateValue(sampleRateValue || this.powertoolLogData.sampleRateValue);

I haven't tested other options. It may require to patch many things. Test every possible config option is possible, but not easy to maintain. There is a chance to miss something.

I think it can be solved completely. What if we "store" custom options when a parent is created? We can merge them later with new options used in .createChild(newOptions) and create a new Logger(mergedOptions) instead of cloning. I lean toward this option to store the initial config in the logger. So all the descendants will have the DNA of their ancestors.

Pros:

• avoid population logic with many conditionals while setting options
• remove dependency on lodash.clonedeep
  Cons:
• additional field in the logger object

Another thought was to "read" from the parent's options which are different from the default. Like getOptions(logger). But it needed to introduce "default" options, and this operation is "heavy" and similar to cloning. I don't like it.

Thoughts? I'm still exploring the project and could miss something.

[dreamorosi]

Hi @shdq, doing well, hope you are too!

Thanks for looking into this and producing the report. I agree that we should let Frankie go 😄

I think it can be solved completely. What if we "store" custom options when a parent is created? We can merge them later with new options used in .createChild(newOptions) and create a new Logger(mergedOptions) instead of cloning. I lean toward this option to store the initial config in the logger. So all the descendants will have the DNA of their ancestors.

Looking at the "pros" that you shared, the prospect of removing one dependency is pretty attractive and when stacked against the additional field(s) and slightly expanded logic in the createChild method, the scale is still in favor of your proposal.

I think we can move forward with that and continue the discussion over a PR.