Bug(logging): appended keys do not get captured by caplog

[amin-farjadi]

Expected Behaviour

The following test should pass

def test_logger_with_caplog_with_appended_keys(caplog):
    caplog.set_level("INFO")
    logger = Logger(service="abcd")
    logger.info("testing, testing...")
    logger.append_keys(
        context={
            "testing": "true",
        },
    )
    logger.info("testing, testing, now with context...")
    assert len(caplog.records) == 2
    assert caplog.records[0].message == "testing, testing..."
    assert caplog.records[1].message == "testing, testing, now with context..."
    assert caplog.records[1].context == {"testing": "true"}

Current Behaviour

The above test fails with error AttributeError: 'LogRecord' object has no attribute 'context'.

But, the test below passes:

def test_logger_with_caplog_with_extra(caplog, service_name):
    caplog.set_level("INFO")
    logger = Logger(service=service_name)
    logger.info("testing, testing...")
    logger.thread_safe_append_keys(
        context={
            "testing": "true",
        },
    )
    logger.info(
        "testing, testing, now with extra...",
        extra={
            "context": {"testing": "true"},
        },
    )
    assert len(caplog.records) == 2
    assert caplog.records[0].message == "testing, testing..."
    assert caplog.records[1].message == "testing, testing, now with extra..."
    assert caplog.records[1].context == {"testing": "true"}

Code snippet

Provided above ^

Possible Solution

No response

Steps to Reproduce

• Add tests above to tests/functional/logger/required_dependencies/test_logger.py
• Run make test

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.12

Packaging format used

PyPi

Debugging logs

[leandrodamascena]

Hey @amin-farjadi I might be wrong but this happens because the test is trying to access the context attribute directly on the LogRecord object captured by pytest's caplog fixture. However, when you append keys to a Logger using logger.append_keys(), these keys are added to the logger's formatter state, not directly to the LogRecord objects.

In your second test, you're doing something a little bit different - regardless of whether you're thread-safe or not. You're passing the context attribute directly in the logger.info line, and in this case, we passes the extra attributes directly to the logging library to serialize it, so LogRecord will contain this key.

I don't think this is a bug in the codebase, nor do I think there is a workaround for it in our current implementation. If you have a way to improve this without a major refactor and not breaking anything, I'd love to accept a PR.

You can think about changing your test like this:

def test_logger_with_caplog_with_appended_keys(caplog, service_name):
    caplog.set_level("INFO")
    logger = Logger(service=service_name)
    logger.info("testing, testing...")
    logger.append_keys(a="b")
    logger.append_keys(
        context={
            "testing": "true",
        },
    )
    logger.info("testing, testing, now with context...")
    assert len(caplog.records) == 2
    print(caplog.text, "AAA")
    assert caplog.records[0].message == "testing, testing..."
    assert caplog.records[1].message == "testing, testing, now with context..."
    # Check if context is in the logger's current keys instead of directly on the LogRecord
    current_keys = logger.get_current_keys()
    assert "context" in current_keys
    assert current_keys["context"] == {"testing": "true"}

Thanks

[amin-farjadi]

Hi @leandrodamascena, thanks for the quick response. You're right. I don't see a clean and simple fix for this. Will reopen the issue if anything comes to mind.

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.