feat(logger): add clearState() method

[shdq]

Description of your changes

This PR introduces clearState() method, that flushes temporary log attributes (added using appendKeys()).

WIP:

• add tests for removeKeys() to test both permanently and temporary keys removal
• add tests for clearState() method
• add tests for child logger temporary keys, added with appendKeys()
• refactor verbose code removeKeys() to make it DRY. Something like that:

/**
   * Alias for removePersistentLogAttributes.
   *
   * @param {string[]} keys
   * @returns {void}
   */
  public removeKeys(keys: string[]): void {
    this.removeAttributes(keys, this.persistentLogAttributes);
    this.removeAttributes(keys, this.temporaryLogAttributes);
  }

  /**
   * It removes attributes based on provided keys to the specified attributes object.
   *
   * @param {string[]} keys
   * @param {LogAttributes} attributes
   * @returns {void}
   */
  private removeAttributes(keys: string[], attributes: LogAttributes): void {
    if (!attributes) return;

    for (const key of keys) {
      if (key in attributes) {
        delete attributes[key];
      }
    }
  }

• Update documentation
• update e2e tests?

Things to discuss:

• naming of temporaryLogAttributes and persistentLogAttributes
• discuss attributes with the same key priority in the output log. Look at an example:

const logger = new Logger({
  persistentLogAttributes: { // (1)
    accountId: '01234567891012'
  }
});

logger.appendKeys({ // (2)
  accountId: '21019876543210'
});

logger.addPersistentLogAttributes({ // (3)
  accountId: '77777777777777'
});

For now, temporary keys added with appendKeys() method will overwrite the persistent keys, even in this order (I've realized the order (3) problem writing this). Maybe there is something more sophisticated needed here, rather than just merge in specific order.

• Logic of injectLambdaContextAfterOrOnError() method, there can be room for refactoring. I need to understand the logic better.
• Many tests test implementation details (checks what's inside objects), rather than actual behavior (log output check with console mocks). E.g. adding temporaryLogAttributes field forced me to change several tests by adding a new empty object.

@dreamorosi take a look at the code, please. If you have any questions or concerns, I'm happy to discuss them here or in Discord.

Related issues, RFCs

Issue number: #2337

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]

Thank you for working on this PR Sergei!

I have left a few comments on some of the new methods / logic but I think we are going in the right direction.

I am still unsure about how we should handle the merging/precedence aspect, but my current position is that whatever is added last is what we log, meaning if I set a key in the constructor and then I overwrite it with appendKeys or the other method, then the last value is what counts.

What I am still unsure is the cleanup part, but now that we are keeping them separate I think it's expected that if I do this:

const logger = new Logger({
  persistentLogAttributes: { // (1)
    accountId: '01234567891012'
  }
});

export const handler = async (event: { accountId: string }) => {
  logger.appendKeys({ // (2)
    accountId: event.accountId
  });

  // do other stuff, emit logs

  logger.clearState();
}

Then at the end of the invocation the value will revert to '01234567891012' which was set at point (1).

Like I said, I am still unsure so I'd like to hear opinions from other maintainers as well before setting on one.

[dreamorosi]

Hey Sergei, thank you so much for your patience and apologies for the slow progress.

As I mentioned on Discord I was busy with other tasks and we had an uptick of issues that I had to attend to before having enough headspace to think about this feature. In addition to that, the more I thought about it and the more I found edge cases or inconsistencies with the existing API.

After discussing about this also with the rest of the team I think I got to a mental model that should work - even though I don't fully have an answer on how to implement it (more on this later)

Before getting into the changes/action items, I want to say that we are already going in the right way, however there was an unanswered question of which mental model to adopt when thinking about the two types of attributes (persistent and temporary), how they interact with each others, and how to describe this feature to customers/users.

To explain the mental model I'm going to show a few examples of increasing complexity that I think cover most of the cases related to this feature. All the examples clear the state manually, but the same reasoning applies to Middy.js middleware and decorators since the state is cleared the same way, only behind the scenes.

Likewise, to keep the examples focused, I'll use the new method/parameters/option names. We'll worry later about the changes necessary to get there.

Base case

As a customer I want to set some key/value pairs that appear to every log emitted by a given logger instance across function invocations. In most cases, these are configurations that are known at initialization time (think environment id, or region), so I can do it by using the persistentKeys constructor option (1).

Later, at runtime (aka during my function invocation) I want to append other key/value pairs that also appear on every log emitted by a given instance (2), but that are scoped to a certain function invocation (for example a accountId coming from the event payload).

This can be achieved like this:

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

const logger = new Logger({
  persistentKeys: { // (1) These keys will be appended to every log emitted by this logger instance
    region: 'eu-west-1'
  }
});

export const handler = async (event: { accountId: string }) => {
  logger.appendKeys({ // (2) These "temporary" keys will be appended to every log emitted until resetState() is called
    accountId: event.accountId
  });

  // do other stuff, emit logs

  logger.resetState(); // (3) Clear all "temporary" keys
}

Temporarily overwriting persistent key

In some other cases, for example in multi-tenant applications, I want to set persistentKeys when I instantiate the logger and then within the scope of a function I want to temporarily overwrite the key with a temporary value. This temporary value will be the one used in logs until I call resetState():

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

const logger = new Logger({
  persistentKeys: { // (1) Adding the region key to the persistent keys
    region: 'eu-west-1'
  }
});

export const handler = async (event: { accountId: string, region: string }) => {
  logger.appendKeys({ // (2) These "temporary" keys will be appended to every log emitted 
    accountId: event.accountId,
    region: event.region // us-east-2
  });

  // do other stuff, emit logs

  logger.resetState(); // (3) Resets the state to the persistent keys
}

The two key details to call out here are:

• Regardless of whether they are persistent or temporary, if a key is overwritten all the logs after that and until the resetState() method is called will have the last value (in the example above we are overwriting region)
• When calling resetState() the keys are restored to the last persistent state, in this case to the initial persistentKeys initialized with the class

Mutating persistent keys

In other cases, I might set persistentKeys when initializing the Logger instance, and then later on mutate them. This can be done using the addPersistentKeys():

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

const logger = new Logger({
  persistentKeys: { // (1) Creates a checkpoint with the region key
    region: 'eu-west-1'
  }
});

export const handler = async (event: { accountId: string, region: string }) => {
  logger.appendKeys({ // (2) Appends keys but doesn't change the checkpoint
    accountId: event.accountId,
    region: event.region // us-east-2
  });

  if (event.region !== process.env.AWS_REGION) {
    logger.addPersistentKeys({ // (3) this mutates the checkpoint
      region: 'us-east-1'
    });
  }

  // do other stuff, emit logs

  logger.resetState(); // (3) Resets the state to the last known checkpoint (us-east-1)
}

The mental model that we want to adopt here is that both setting persistentKeys and calling the addPersistentKeys() method create kind of a checkpoint/snapshot of the attributes, and that calling resetState() restores the state to that last known checkpoint.

For instance, in the example above we are mutating the region attribute, which means that later on when resetState() is called the attributes will be restored to that known state at that point.

--

In terms of changes required to get there, as I mentioned I think we are already going in the right direction, however we need to do a few small tweaks, and resolve one bigger question mark.

For the smaller/easier changes, I have left comments near the code so that it's easier to discuss and address them in context.

For the larger question mark, at the moment we don't have a way to merge temporary and persistent attributes in a way that considers the last value added for a given key. To explain what I mean by this, let's look at this code:

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

const logger = new Logger({
  persistentKeys: { // (1) Creates a checkpoint with the region key
    region: 'eu-west-1'
  }
});

export const handler = async (event: { accountId: string, region: string, extra: boolean }) => {
  logger.info('should have region eu-west-1 only');

  logger.appendKeys({ // (2) Appends keys but doesn't change the checkpoint
    accountId: event.accountId,
    region: event.region // us-east-2
  });

  logger.info(`should have region ${event.region} and accountId ${event.accountId}`);

  logger.addPersistentKeys({ // (3) this mutates the checkpoint
    region: 'us-east-1'
  });

  logger.info(`should have region us-east-1 and accountId ${event.accountId}`);

  logger.resetState(); // (3) Resets the state to the last known checkpoint (us-east-1)
}

This code should log this:

{"level":"INFO","message":"should have region eu-west-1 only","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.691Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"eu-west-1"}
{"level":"INFO","message":"should have region us-east-2 and accountId 12345","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.726Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"us-east-2","accountId":"12345"}
{"level":"INFO","message":"should have region us-east-1 and accountId 12345","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.727Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"us-east-1","accountId":"12345"}

But instead it logs this:

{"level":"INFO","message":"should have region eu-west-1 only","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.691Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"eu-west-1"}
{"level":"INFO","message":"should have region us-east-2 and accountId 12345","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.726Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"us-east-2","accountId":"12345"}
{"level":"INFO","message":"should have region us-east-1 and accountId 12345","sampling_rate":0,"service":"service_undefined","timestamp":"2024-05-17T12:24:40.727Z","xray_trace_id":"1-66474c88-27cdfff37ef2d60843eaaec7","region":"us-east-2","accountId":"12345"}

The issue is that the last log should have the attribute region set to us-east-1 which is the value we gave it the last time it was assigned, but instead it has us-east-2.

This is because the merging of the attributes in createAndPopulateLogItem always puts the temporary ones after the persistent ones, which causes to always overwrite them:

let additionalLogAttributes = {
  ...this.getPersistentLogAttributes(),
  ...this.getTemporaryLogAttributes(),
};

I don't yet have a clear solution for this, and I am open for suggestions, but for now I would say let's focus on addressing all the other changes, so that we can then write unit tests for the end state that we want to reach, and iterate from there.

[dreamorosi]

I have added two commits: one to create some additional test cases resembling the edge cases we discussed, and another to propose an implementation that should solve the issue and makes the test pass.

Now that I am part of the committers for this PR, I would like to ask for a review from @am29d before merging.

I am also marking the PR as ready for review, but given the feature will require some explanation both in the docs and in the release notes I would target for not merging before Thursday (release day) and instead include in the following week's release (Week of June 17th).

[am29d]

I have a minor confusion on the deprecation of the method and aliases, otherwise it's good to merge.

[sonarqubecloud]

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
No data about Coverage
5.5% Duplication on New Code

See analysis details on SonarCloud

Stale