Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(logger): add clearState() method #2408

Draft
wants to merge 11 commits into
base: main
Choose a base branch
from

Conversation

shdq
Copy link
Contributor

@shdq shdq commented Apr 22, 2024

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.

@boring-cyborg boring-cyborg bot added logger This item relates to the Logger Utility tests PRs that add or change tests labels Apr 22, 2024
@pull-request-size pull-request-size bot added the size/XL PRs between 500-999 LOC, often PRs that grown with feedback label Apr 22, 2024
@dreamorosi dreamorosi linked an issue Apr 22, 2024 that may be closed by this pull request
2 tasks
@github-actions github-actions bot added the feature PRs that introduce new features or minor changes label Apr 22, 2024
Copy link
Contributor

@dreamorosi dreamorosi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
* @private
* @returns {LogAttributes}
*/
public getTemporaryLogAttributes(): LogAttributes {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure we need this method, maybe I am missing something?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, we don't need it, we can access temporary attrs directly with this.temporaryLogAttributes(). getPersistentLogAttributes() exists to use inside middy.ts.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we'll need it anymore in middy.jts so we can remove it I think

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed that we can remove this.

packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
Logger.injectLambdaContextAfterOrOnError(
logger,
persistentAttributes[index],
logger.getPersistentLogAttributes(),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we are clearing the state right above, we can avoid calling the Logger.injectLambdaContextAfterOrOnError method entirely here as it does the same.

We can also probably mark it as deprecated.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I understand the logic here and in Logger correctly, this method injects logEvent and clearState parameters for the next invocations of the handler, not only to insert a snapshot of log attributes. In case of an error, will the before method executed? In Logger before function, it only injects logEvent, but middy seems to inject both logEventandclearState` before.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I went to check and the current implementation of the method on main looks like this:

public static injectLambdaContextAfterOrOnError(
    logger: Logger,
    initialPersistentAttributes: LogAttributes,
    options?: InjectLambdaContextOptions
  ): void {
    if (options && options.clearState === true) {
      logger.setPersistentLogAttributes(initialPersistentAttributes);
    }
  }

Given that you have added (correctly) the logger.clearState() right above this call (~L72), then calling the method is redundant as it would do the same thing.

@dreamorosi dreamorosi added the on-hold This item is on-hold and will be revisited in the future label Apr 29, 2024
Copy link
Contributor

@dreamorosi dreamorosi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
* @private
* @returns {LogAttributes}
*/
public getTemporaryLogAttributes(): LogAttributes {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed that we can remove this.

packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
packages/logger/src/Logger.ts Show resolved Hide resolved
packages/logger/src/Logger.ts Outdated Show resolved Hide resolved
@dreamorosi dreamorosi removed the on-hold This item is on-hold and will be revisited in the future label May 20, 2024
Copy link

sonarcloud bot commented May 23, 2024

Quality Gate Passed Quality Gate passed

Issues
2 New issues
0 Accepted issues

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

See analysis details on SonarCloud

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature PRs that introduce new features or minor changes logger This item relates to the Logger Utility size/XL PRs between 500-999 LOC, often PRs that grown with feedback tests PRs that add or change tests
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Feature request: Logger - ability to clear state
2 participants