Ability to swap out the logger with default python logger during local testing

[bml1g12]

Is your feature request related to a problem? Please describe.

When working locally, we often wish to visualise the "message" of logs without structured logging as it is more readable and we have no intention of searching the logs. We also wish to log to file often when testing locally.

Is there any way we can hot-swap the default Python logger or replace the logger universally across a codebase?

Describe the solution you'd like

Ability to disable structured logging across a code base and default to a standard python logger such that we have a way to make the code base log to local file and display without structured logs during local testing.

Describe alternatives you've considered

I thought initially we could just mock out the logger with the default logger, but the introduction of child=True (which is not in the default logger) would mean that does not work I think.

I was thinking maybe we could also try and add the default logger as an additional logger by patching the init of the powertools logger maybe?

[heitorlessa]

hey @bml1g12 would the addition of a custom formatter (structured, not structured) and handler (file, stdout, etc.) as per #404 help?

If so, I can easily add an option to pass in a custom logging handler that writes to a file as that was going to be my last piece before merging that PR.

That way you can control what you want within your formatter, and optionally pass a handler when doing it locally. If not, I'd need some time to think this more deeply.

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
        # Convert logging record to any format you'd want, doesn't have to be JSON
        return json.dumps(
            {
                "message": super().format(record),
                "timestamp": self.formatTime(record),
                "my_default_key": "test",
                **self.custom_format,
            }
        )

custom_formatter = CustomFormatter()
handler = logging.FileHandler('logs.txt')

logger = Logger(logger_formatter=custom_formatter, logger_handler=handler)

Or for when you're not using append_keys, remove_keys, structure_logs, inject_lambda_context decorator, you can:

from aws_lambda_powertools import Logger
import logging

formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
handler = logging.FileHandler('logs.txt')    # log output to a file

logger = Logger(logger_formatter=formatter, logger_handler=handler)

[heitorlessa]

Also @bml1g12, if you're not on the AWS Developers Slack channel to chat directly on #lambda-powertools.. I'm happy to jump on a call to learn more about your use of Logger as I believe we can get this UX right for everyone :) You have my email

[StianHanssen]

Hi @heitorlessa!

I am from the same team as @bml1g12, to explain a little further:
We have a serverless application running in lambda that performs some work we would like to evaluate locally in a program that wraps around it. So we would like to have logging such that when we run our serverless application locally the logging calls, that would normally be JSON formatted and written to console, would instead be written to file in a traditional text format.

From what I understand that second example you provide would be able to do just that right? It would capture the logs from when we do powertools log calls, and save them to file in a text.

I will gladly give this a spin and let you know how it goes! Sounds like this is not merged yet, how would I go about testing the custom formater and handler? Getting a bit late here, but I can jump onto a slack call tomorrow!

[heitorlessa]

Perfect, thanks for the additional context. I haven’t pushed the handler changes as I had them staged. I’ll merge that on develop branch by tomorrow EOD and ping here so you can take it for a spin.

…

On Thu, 22 Apr 2021 at 11:58, Stian Hanssen ***@***.***> wrote: Hi @heitorlessa <https://github.com/heitorlessa>! I am from the same team as @bml1g12 <https://github.com/bml1g12>, to explain a little further: We have a serverless application running in lambda that performs some work we would like to evaluate locally in a program that wraps around it. So we would like to have to such that when we run out serverless application locally, the logging calls that would normally be JSON formatted and written to console, would instead be written to file in a traditional text format. From what I understand that second example you provide would be able to do just that right? It would capture the logs from when we do powertools log calls, and save them to file in a text (JSON format) If so I will gladly give this a spin and let you know how it goes! Sounds like this is not merged yet, what branch would have the ability to add custom formater and handler? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#409 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAZPQBDNSYZUZPTS7HWSTETTJ7XMZANCNFSM43L2XJ5A> .

[heitorlessa]

@StianHanssen this is now available in the develop branch - You can pip install directly against.

This is the UX to log directly to a file

from aws_lambda_powertools import Logger

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

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

For functional testing, you can also instruct Logger to a custom stream (will document in the next PR):

import json
import io

from aws_lambda_powertools import Logger

stdout = io.StringIO()
logger = Logger(stream=stdout)

logger.info("Hello")

log_output = json.loads(stdout.getvalue().strip())

assert "Hello" in log_output["message"]

PR for early docs on custom formatter, handler, UTC, etc. until I produce them: #404

[StianHanssen]

Hey sorry for late reply! My info was slightly incorrect earlier, the output should go to txt files in a regular logging format like you would have with python's native logging library. I assume it would still just be a case of setting the formater and provide a txt file to the FileHandler.

What do you mean by "develop branch - You can pip install directly against"?
I can't find what version to set for pip to install develop, and I can't seem to be able to pip install the cloned repo. Planning to give it a try now :)

[heitorlessa]

Hey @StianHanssen, no problem, here's how you can do it - and yes you can use a custom formatter.

#Add this line in your requirements.txt
git+https://github.com/awslabs/aws-lambda-powertools-python

#Or if you're doing in a virtual environment to experiment in a quick script
pip install git+https://github.com/awslabs/aws-lambda-powertools-python

NOTE: While you can use any logging.Formatter to test this out and log into a file, it'll fail if you're using Logger decorator inject_lambda_context and structure_logs method, because logging.Formatter won't have append_keys, remove_keys. Checkout the PR readme on the how to do that while I update the docs today: #404

Let me know if you run into any trouble

[bml1g12]

I tried this but it does not log to file?

╰─❯ pip install aws-xray-sdk==2.8.0 git+https://github.com/awslabs/aws-lambda-powertools-python                                                                                                                                          ─╯
Collecting git+https://github.com/awslabs/aws-lambda-powertools-python
  Cloning https://github.com/awslabs/aws-lambda-powertools-python to /tmp/pip-req-build-c9_i29w9
  Running command git clone -q https://github.com/awslabs/aws-lambda-powertools-python /tmp/pip-req-build-c9_i29w9
  Installing build dependencies ... done
  Getting requirements to build wheel ... done
    Preparing wheel metadata ... done
Requirement already satisfied: aws-xray-sdk==2.8.0 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (2.8.0)
Requirement already satisfied: fastjsonschema<3.0.0,>=2.14.5 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-lambda-powertools==1.14.0) (2.15.0)
Requirement already satisfied: jmespath<0.11.0,>=0.10.0 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-lambda-powertools==1.14.0) (0.10.0)
Requirement already satisfied: boto3<2.0,>=1.12 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-lambda-powertools==1.14.0) (1.15.16)
Requirement already satisfied: botocore>=1.11.3 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-xray-sdk==2.8.0) (1.18.16)
Requirement already satisfied: future in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-xray-sdk==2.8.0) (0.18.2)
Requirement already satisfied: wrapt in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from aws-xray-sdk==2.8.0) (1.12.1)
Requirement already satisfied: s3transfer<0.4.0,>=0.3.0 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from boto3<2.0,>=1.12->aws-lambda-powertools==1.14.0) (0.3.6)
Requirement already satisfied: urllib3<1.26,>=1.20 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from botocore>=1.11.3->aws-xray-sdk==2.8.0) (1.25.11)
Requirement already satisfied: python-dateutil<3.0.0,>=2.1 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from botocore>=1.11.3->aws-xray-sdk==2.8.0) (2.8.1)
Requirement already satisfied: six>=1.5 in /home/ben/anaconda3/envs/lambda/lib/python3.7/site-packages (from python-dateutil<3.0.0,>=2.1->botocore>=1.11.3->aws-xray-sdk==2.8.0) (1.15.0)

╭─   /data/ServerlessDemoErrorHandlingPython on   feature/lambda_powertools *2 !5 ?3 ─────────────────────────────────────────────────────────────────────────────────────────────────────────────── ▼  lambda at  11:13:39 ─╮
╰─❯ cat test.py                                                                                                                                                                                                                          ─╯
import logging
from aws_lambda_powertools import Logger

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

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

╭─   /data/ServerlessDemoErrorHandlingPython on   feature/lambda_powertools *2 !5 ?3 ───────────────────────────────────────────────────────────────────────────────────────────────────────── ✘ INT ▼  lambda at  11:13:53 ─╮
╰─❯ python test.py                                                                                                                                                                                                                       ─╯
{"level": "INFO", "location": "<module>:7", "message": "Hello", "timestamp": "2021-05-04 11:13:56,491", "service": "main", "sampling_rate": 0.0, "logger_handler": "<FileHandler /data/gym_ai/ServerlessDemoErrorHandlingPython/log_file.json (NOTSET)>"}
╭─   /data/ServerlessDemoErrorHandlingPython on   feature/lambda_powertools *2 !5 ?3 ─────────────────────────────────────────────────────────────────────────────────────────────────────────────── ▼  lambda at  11:13:56 ─╮
╰─❯ cat log_file.json     

[heitorlessa]

The direct install didn't seem to work as you shouldn't be seeing "logger_handler" as a logging key nor the output in the console.

It's working on a fresh new environment - I'm uploading a build from develop branch. Also, we're releasing 1.15.0 as soon as #418 PR gets merged.

aws_lambda_powertools-1.14.0b.tar.gz

[bml1g12]

Great thanks, indeed a fresh environment sorted me out and this seems to work nicely:

import logging
from typing import Iterable

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 f"{self.formatTime(record)} — {record.levelname} — {record.funcName}:" \
               f"{record.lineno} —" \
               f" {super().format(record)} " \
               f"—" \
               f" {self.custom_format}"


handler = logging.FileHandler(filename="log_file.json")
custom_formatter = CustomFormatter()
logger = Logger(logger_formatter=custom_formatter, logger_handler=handler)

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

[bml1g12]

Ah but apologies if the answer is obvious - but I not entirely sure how we could apply this in our context. The context here we are trying to hot-swap out our production code when testing locally with a logger that is human readable - particularly for stack traces, and as it is local, we need a way to record logs to file (no cloudwatch). To do this, we cannot edit the production source code directly, to need to use mocks.

So if we take the example above, and then hot-swap out the logger maybe by changing the global variable itself:

import logging
import time
from typing import Iterable

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

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

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 f"{self.formatTime(record)} — {record.levelname} — {record.funcName}:" \
               f"{record.lineno} —" \
               f" {super().format(record)} " \
               f"—" \
               f" {self.custom_format}"

#### the below would be in another file ####
handler = logging.FileHandler(filename="log_file.json")
custom_formatter = CustomFormatter()
logger = Logger(logger_formatter=custom_formatter, logger_handler=handler)
LOGGER = logger
LOGGER.info("Hello")

The above does not seem to work (the LOGGER variable remains logging to stdout with log_file.json empty.)

A more realistic example of what we are intending would be something like:

production_foo.py

from aws_lambda_powertools import Logger

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



def main():
    LOGGER.info("Hello")

test_bar.py

from unittest.mock import patch
import logging
import time
from typing import Iterable

from aws_lambda_powertools import Logger
from aws_lambda_powertools.logging.formatter import BasePowertoolsFormatter
import production_foo
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 f"{self.formatTime(record)} — {record.levelname} — {record.funcName}:" \
               f"{record.lineno} —" \
               f" {super().format(record)} " \
               f"—" \
               f" {self.custom_format}"
               
handler = logging.FileHandler(filename="log_file.json")
custom_formatter = CustomFormatter()
logger = Logger(logger_formatter=custom_formatter, logger_handler=handler)
with patch('production_foo.LOGGER', logger):
    production_foo.main()

[heitorlessa]

No problem, I'll give you a working sample this week as soon as I get 1.15.0 out so you don't need to have a hacky install.

As you're trying to patch, there's a better way to intercept the serialisation and create less code by overriding the serialize method (new).

A flag like an environment variable to switch between structured and non-structured would work best here - no patch necessary. You could also use the flag to decide whether to add a file handler.

[heitorlessa]

All of this is now out in 1.15.0 release: #423.

I'll work on a sample solution to switch handlers and a custom formatter that relies on a flag for that. In the meantime, the Pytest Live Log feature might be helpful to quickly visualize logging statements during the tests without having to hack or patch any code: https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#pytest-live-log-feature, if you're using Pytest of course :)

[heitorlessa]

Here's two examples - 1/ Using Pytest Live Log feature w/ no code change, 2/ Conditionally adding a plain text formatter and logging to a file when a flag is set

https://gist.github.com/heitorlessa/cc36ca86c26ce83eec855b9c250b9e1c

I personally prefer 1 as this is primarily for testing, where 2 being a cleaner than monkey patching IMHO.

[bml1g12]

Thanks for these examples. This works nicely, but it occurs to me that being able to log to both standard out and a file simultaneously would be even better. It seems I can get away with doing using the protected attribute _logger.addHandler to get the best of both worlds. Is this safe?

def _create_console_handler(log_level):
    """Setup logging to console and the logger's logging level."""

    console_handler = logging.StreamHandler(sys.stdout)
    console_format = logging.Formatter(LOG_FORMAT)
    console_handler.setFormatter(console_format)
    console_handler.setLevel(log_level)

    return console_handler

is_human_readable_enabled = ast.literal_eval(os.environ.get("HUMAN_READABLE_LOGGING"))
log_level = os.environ.get("LOG_LEVEL", "INFO")
if is_human_readable_enabled:
    file_handler = logging.FileHandler(
        "entrance_counter.log")
    file_handler.setLevel(log_level)
else:
    file_handler = None
formatter = _log_utils.LocalPlainFormatter() if is_human_readable_enabled else None
logger = Logger(datefmt="%Y-%m-%dT%H:%M:%SZ",
                utc=True,
                logger_formatter=formatter,
                logger_handler=file_handler)
if is_human_readable_enabled:
    console_handler = _create_console_handler(log_level)
    logger._logger.addHandler(console_handler)  # pylint: disable = protected-access

[bml1g12]

Will need to test in more detail later and produce a minimal example but it seems some part of the above changes means that we string substitution into the structured logging is not working.

i.e. is_human_readable_enabled = False (structured logging enabled)

LOGGER.info("Hello %s", 1)

Shows in CloudWatch "hello %s" rather than "hello 1"

[heitorlessa]

It’s merged in develop. I’ll make a release tomorrow to include it

…

On Thu, 13 May 2021 at 11:57, Benjamin Lowe ***@***.***> wrote: Will need to test in more detail later and produce a minimal example but it seems some part of the above changes means that we string substitution into the structured logging is not working. i.e. is_human_readable_enabled = False (structured logging enabled) LOGGER.info("Hello %s", 1) Shows in CloudWatch "hello %s" rather than "hello 1" — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub <#409 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAZPQBBHRPKGGB266WJIDEDTNOPBPANCNFSM43L2XJ5A> .

[heitorlessa]

@bml1g12 the regression fix is now out as part of 1.15.1 - would you mind triple check that for us?

[bml1g12]

I can confirm it fixes this issue for me

[bml1g12]

When running your gist example

╭─   ~/Dow/cc36ca86c26ce83eec855b9c250b9e1c-770519f51fdb44176053bbe490292bbb03af5455 ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────── ✘ INT  lambda at  15:15:34 ─╮
╰─❯ PT_409="1" python prod.py                                                                                                                                                                                                            ─╯
─╮────────────────────────────────────────────────────────────  lambda at  15:15:37 ─╮
╰─❯ cat log.txt                                                                                                                                                                                                                          ─╯
2021-05-13 15:15:36,936+0100 — INFO — main:28 — Hello
2021-05-13 15:15:36,936+0100 — ERROR — main:32 — Log stacktrace...

The stacktrace is not logged by a logger.exception call - how does one provide a nicely formatted stack trace?

Would:

class LocalPlainFormatter(LambdaPowertoolsFormatter):
    def serialize(self, log: Dict) -> str:
        print(log)
        timestamp = log["timestamp"]
        level = log["level"]
        funcNameLoc = log["location"]
        message = log["message"]
        exception_name = log.get("exception_name", "")
        traceback = log.get("exception", "")

        return f"{timestamp} — {level} — {funcNameLoc} — {message} - {exception_name} - {traceback}"

Be the recommended approach?

[heitorlessa]

I'd do what you basically did - Extract exception_name and exception and use it just like you did.

I've updated the gist to include the exception and the traceback. The stack trace is formatted in an earlier step of the LambdaPowertoolsFormatter named format(), so all you need to do within serialize is to decide how the final output should be.

If you want, you could use a if bloc to check whether there's a traceback in the first place before adding it to the final string, so you don't have blanks - {}, but that's more of an micro-optimization than anything else.

Let me know if there's anything else I can do to make this experience better for you.

---

log.txt: https://gist.github.com/heitorlessa/cc36ca86c26ce83eec855b9c250b9e1c#file-log-txt

2021-05-13 19:03:27,637+0200 — INFO — main:32 — Hello - {'context': {'device_id': '11e9034354f', 'device_location': 'London'}} - None - None
2021-05-13 19:03:27,637+0200 — ERROR — main:36 — Log stacktrace... - {} - ZeroDivisionError - Traceback (most recent call last):
  File "prod.py", line 34, in main
    1 / 0
ZeroDivisionError: division by zero

[heitorlessa]

Hey @bml1g12 checking in to see if you still need any help here :)

[bml1g12]

Ah all good thanks; working nicely and thanks for your assistance with this one.