refactor(logger): BYOFormatter and Handler, UTC support, and more

[heitorlessa]

Issue #, if available: #381 #387 #215 #98

Description of changes:

Major refactor of Logger to a) make it more flexible for those coming from other loggers, b) bring your own formatter for those with a common structure that differs from our opinionated one, c) UX enhancements to add or remove keys from the logger, d) address long standing tech debts on LambdaPowertoolsFormatter.

UTC support

Note: By default, Python standard logging use local time.

from aws_lambda_powertools import Logger

logger = Logger(utc=True)

logger.info("Hello")  # "timestamp":"2021-04-19 12:58:46.635+0100", dst

New convenience property to change logger handler, if necessary

from aws_lambda_powertools import Logger

logger = Logger()

handler = logger.registered_handler  # takes into account parent or child loggers

Bring your own handler

Note: By default, we log to standard output due to Lambda integration. This unlocks using Logger in places like Glue, or locally when you want to log into a filename for example.

from aws_lambda_powertools import Logger

handler = logging.FileHandler(filename="log_file.json")
logger = Logger(logger_handler=handler)

logger.info("Hello")  # populatest `log_file.json` in your filesystem

Bring your own formatter

from aws_lambda_powertools import Logger
from aws_lambda_powertools.logging.formatter import BasePowertoolsFormatter

class CustomFormatter(BasePowertoolsFormatter):
    custom_format = {}

    def append_keys(self, **additional_keys):
        # used by inject_lambda_context decorator, Logger initialization, and structure_log
        self.custom_format.update(additional_keys)

    def remove_keys(self, keys: Iterable[str]):
        # used by Logger public method
        for key in keys:
            self.custom_format.pop(key, None)

    def format(self, record: logging.LogRecord) -> str:  # noqa: A003
        return json.dumps(
            {
                "message": super().format(record),
                "timestamp": self.formatTime(record),
                "my_default_key": "test",
                **self.custom_format,
            }
        )

custom_formatter = CustomFormatter()
logger = Logger(logger_formatter=custom_formatter)

Updating formatter made easier

from aws_lambda_powertools import Logger

logger = Logger()

logger.append_keys(request_id="id", order_id="id")
logger.info("with both request and order id keys")

logger.remove_keys(["request_id"])
logger.info("with request id key only")

Checklist

• Meet tenets criteria
• Update tests
• Update docs
• PR title follows conventional commit semantics
• New features
  • Bring your own formatter via Logger(log_formatter=...)
    • Create ABC to support custom formatters to enforce append_keys and remove_keys
    • Update Logger to use append_keys for Lambda decorator and structure_log calls
  • Add support for utc=True
    • Include timezone in timestamp key
    • Create custom msec string interpolation to not break previous format (RFC 3339), since std logging doesn't support msec when built-in formatTime is overriden
• Tech debt
  • Introduce append_keys, remove_keys over structure_log(append=True) to align with other runtimes
  • Allow customers to set bare minimum (only message, and xray_trace_id)
    • Allow to suppress sampling_rate
    • Remove sampling_rate when not in use (set to None by default over 0.0)
  • Allow custom JSON serializer/deserializer for those seeking faster performance
  • Compact logging to save on ingestion & storage cost (separators[] to remove whitespace)
  • [Internal] Refactor standalone methods into staticmethods
  • Rename testing to powertools formatter given we have vastly deviated from the original implementation
    • Create alias for JsonFormatter to prevent breaking existing customers
  • Add convenience properties to access handler and formatter
  • Support all standard log attrs (%()s) if given via kwargs
• Support custom handler
• Update docstring parameters in Logger
• Update docstring parameters in Formatter

---

Create separate PR for docs to include enhancements:

• Document examples
  • Default JSON fn for unserializable (json.dumps(data, default=json_default))
  • Std log attrs %()s support
  • Bring your own formatter
  • Bare minimal attrs (level, message, service)
  • Update all docs with additional TZ in timestamp
  • Bringing orjson for those seeking to gain every possible microsecond
• Update Testing your code section to include how to use stream=sys.stdout

Breaking change checklist

RFC issue #:

• Migration process documented
• Implement 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.

[michaelbrewer]

@heitorlessa nice, this would help alot when you have company mandated structured logging formats.

[heitorlessa]

@bml1g12 - what are your thoughts on the UTC UX for your use case?

Anything else you need while I'm at it?

[bml1g12]

Currently, I am declaring in each handler

LOGGER = Logger(datefmt="%Y-%m-%dT%H:%M:%SZ")
LOGGER._logger.handlers[0].formatter.converter = time.gmtime  #pylint: disable = protected-access

So in this new UX I would instead simply do

LOGGER = Logger(datefmt="%Y-%m-%dT%H:%M:%SZ", utc=True)

In each handler and the child would inherit this right?

If so, looks great to me! Much appreciated addition.

[heitorlessa]

Yes exactly. I noticed you’re using RFC 8601 in your datefmt, I’ll make sure this will be the default timestamp in v2, as changing now would break customers.

…

On Wed, 21 Apr 2021 at 08:06, Benjamin Lowe ***@***.***> wrote: Currently, I am declaring in each handler LOGGER = Logger(datefmt="%Y-%m-%dT%H:%M:%SZ") LOGGER._logger.handlers[0].formatter.converter = time.gmtime #pylint: disable = protected-access So in this new UX I would instead simply do LOGGER = Logger(datefmt="%Y-%m-%dT%H:%M:%SZ", utc=True) In each handler and the child would inherit this right? If so, looks great to me! Much appreciated addition. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#404 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAZPQBA6QLUPK7IESZ3EUXTTJZTORANCNFSM43FYVHHQ> .

[bml1g12]

Nice! Yes I chose this as I saw a few blogs recommending it as a standard across languages for structured logging; I think its the default for javascript time logging maybe for example

[michaelbrewer]

@heitorlessa I am liking these changes so long, I am glad to see that now even sampling_rate can be suppressed :)

[michaelbrewer]

LGTM, just a minor tweak and typo

[codecov-commenter]

Codecov Report

Merging #404 (b328431) into develop (0edec8e) will decrease coverage by 0.05%.
The diff coverage is 100.00%.

@@             Coverage Diff             @@
##           develop     #404      +/-   ##
===========================================
- Coverage    99.94%   99.89%   -0.06%     
===========================================
  Files           98      100       +2     
  Lines         3688     3816     +128     
  Branches       174      176       +2     
===========================================
+ Hits          3686     3812     +126     
- Misses           0        1       +1     
- Partials         2        3       +1     

Impacted Files	Coverage Δ
aws_lambda_powertools/logging/formatter.py	100.00% <100.00%> (ø)
aws_lambda_powertools/logging/logger.py	100.00% <100.00%> (ø)
...bda_powertools/utilities/parser/models/__init__.py	100.00% <0.00%> (ø)
..._powertools/utilities/parser/envelopes/__init__.py	100.00% <0.00%> (ø)
...bda_powertools/utilities/parser/envelopes/apigw.py	100.00% <0.00%> (ø)
...lambda_powertools/utilities/parser/models/apigw.py	97.40% <0.00%> (ø)

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9be19b2...b328431. Read the comment docs.