version 1.7.0 and above broke pytest verbose output

[silvestriluca]

Problem description

During local tests is not infrequent to use Pytest with live log call output to watch logs as they are emitted and to help in debugging activities. The command to have this "verbose" output is the following
pytest -o log_cli=1

Until aws-lambda-powertools 1.6.1 the command worked fine.
Since version 1.7.0 all pytest live log call outputs are missing.

Expected behaviour

All function/test live log call outputs should be visible when issuing pytest -o log_cli=1

Current behaviour

No live log call outputs when issuing pytest -o log_cli=1 and using powertools 1.7.0 or above

How to reproduce

I've provided a simple gist to reproduce the issue.

1. Clone the following gist: https://gist.github.com/silvestriluca/95352eb38587cb6bc333f8ec790fb22a
2. Navigate to the repo folder

Working scenario

3. Set a virtual environment: python3 -m venv v-env-pt161
4. Activate the v-env-pt161 virtual environment
5. pip install -r requirements_powertools161.txt to install pytest and powertools v1.6.1
6. Run pytest -o log_cli=1
7. You should see the following output:

As you can see, all log lines appear as expected, with proper errorlevel => this powertool version works

Broken scenario

8. Now set a new virtual environment: python3 -m venv v-env-ptlatest
9. Activate the v-env-ptlatest virtual environment
10. pip install -r requirements.txt to install pytest and latest powertools (v1.9.1)
11. Run pytest -o log_cli=1
12. You should see the following output. As you can see, the logs are missing => this powertool version doesn't work
13. Going backwards with powertools versions, you can see that the issue starts with version 1.7.0

Possible cause

According to Powertools changelog, version 1.7.0 introduced the following bugfix:

improv: keeps Lambda root logger handler intact, and add log filter instead to prevent child log records duplication (#198)

My guess is that this somehow steals the log handler from pytest, making -o log_cli=1 options useless.

Suggested fix implementation

Since this bug is relevant only during local unit tests and it was introduced with version 1.7.0, setting an environment variable that restores the pre-v1.7.0 log behaviour and that can be used only during local tests could do the job.

Environment

• Tested with both Python 3.9.1 and 3.8.3
• Pip package

[heitorlessa]

Hey @silvestriluca, thank you for raising this -- It's definitely an interesting one.

I did some quick analysis before I get back to this on Friday before the 1.10.0 release, and I can't see anything obvious at the moment --- It's almost as if our logging filter is suppressing its output despite Pytest logger being completely independent for Live Log feature.

What we did in 1.7.0 was basically add a filter to all existing loggers (root in particular) to filter out any child logger messages from our Logger, and that was deliberate to not impact any other existing loggers but our child ones.

here are my notes for now before I get back to it.

---

Pytest Live Log Logger registered: logging.root.manager.loggerDict["Main function"]

1.9.1 version

LogCaptureHandler
============================= test session starts ==============================
platform darwin -- Python 3.7.4, pytest-5.4.3, py-1.9.0, pluggy-0.13.1
rootdir: /private/tmp/bug-262
plugins: mock-2.0.0, asyncio-0.12.0, cov-2.10.1
collected 1 item

test_main.py
logging.root.handlers[0].__dict__
{'_name': None, 'filters': [], 'formatter': <_pytest.logging.Col...102e1eed0>, 'level': 0, 'lock': <unlocked _thread.RL...102ee1b70>, 'records': [<LogRecord: UNIT_TES...nit test">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun... handler">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun...evel log">], 'stream': <_io.StringIO object...103ba9f50>}
special variables:
function variables:
'filters': []
'_name': None
'level': 0
'formatter': <_pytest.logging.ColoredLevelFormatter object at 0x102e1eed0>
'lock': <unlocked _thread.RLock object owner=0 count=0 at 0x102ee1b70>
'stream': <_io.StringIO object at 0x103ba9f50>
'records': [<LogRecord: UNIT_TES...nit test">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun... handler">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun...evel log">]
len(): 7

1.6.1 version

============================= test session starts ==============================
platform darwin -- Python 3.7.4, pytest-5.4.3, py-1.9.0, pluggy-0.13.1
rootdir: /private/tmp/bug-262
plugins: mock-2.0.0, asyncio-0.12.0, cov-2.10.1
collected 1 item

test_main.py
logging.root.handlers[0].__dict__
{'_name': None, 'filters': [], 'formatter': <_pytest.logging.Col...104a31210>, 'level': 0, 'lock': <unlocked _thread.RL...104b00b40>, 'records': [<LogRecord: UNIT_TES...nit test">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun... handler">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun...evel log">], 'stream': <_io.StringIO object...1078444b0>}
special variables:
function variables:
'filters': []
'_name': None
'level': 0
'formatter': <_pytest.logging.ColoredLevelFormatter object at 0x104a31210>
'lock': <unlocked _thread.RLock object owner=0 count=0 at 0x104b00b40>
'stream': <_io.StringIO object at 0x1078444b0>
'records': [<LogRecord: UNIT_TES...nit test">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun... handler">, <LogRecord: Main fun...t_test'}">, <LogRecord: Main fun...evel log">]
len(): 7

[heitorlessa]

Forgot to mention, the log records are being registered as expected - use -s option to see them, but for some reason it doesn't without

[silvestriluca]

Hello @heitorlessa .

Thank you for the quick reply and preliminary analysis.
It's actually tricky. Looking forward to your further investigations!

[heitorlessa]

Alright @silvestriluca, finally found the why and it's not pretty - Pytest Live Log feature changes the logging root stream with a ColorFormatter formatter to propagate what any Logger logs (hence why you see in the tests).

Why this happens

1. We filter out any duplicated logs coming from our Logger namespace

This allows us to have child loggers sharing changes bi-directionally. For example, if a Parent logger adds a new structured key, it'll reflect in the Child and vice-versa e.g. folks using multiple loggers across multiple files or in Layers

2. We cannot easily differentiate between Pytest Live Log messages

Log filters are applied right after a Log Record is created[1], and until it reaches the handler space[2] there's not much contextual information that can be injected to differentiate between the two. It's a great feature of Pytest, that's for sure, but it leaves no trace that I can think of to make these calls.

Options as of now

• Disable duplicate log filter when not running in Lambda-like environment. Relatively straightforward as we have checks like this for Tracer. When running locally Pytest Live log feature will be able to successfully duplicate both log messages.
  • Cons: It can impact customers' test for those using multiple Logger instances (parent + child), including non-Lambda environments despite the lack of official support.
• Introduce a feature flag to disable log filter. An environment variable to purposefully disable duplicate log filter. This has the benefit of not impacting any current usage, no side effects, and is explicit on its intentions when enabled - need ideas on the env var name :D
• Work with Pytest team to ask for alternatives. They might have ideas in this space.
• Drop bi-directional support between parent and child Loggers. I've been contemplating this but will need a v2, and given my current bandwidth I can see this becoming a possibility in early Q2 only.

What would you suggest @silvestriluca? I'd vote for an env var

---

[1] Log record originally produced compared with Pytest Live Log record that will be suppressed in the next step.

Powertools Log record

{
 'args': (),
 'created': 1610706539.410131,
 'exc_info': None,
 'exc_text': None,
 'filename': 'main.py',
 'funcName': 'handler',
 'levelname': 'ERROR',
 'levelno': 40,
 'lineno': 11,
 'message': 'Some error level log',
 'module': 'main',
 'msecs': 410.13097763061523,
 'msg': 'Some error level log',
 'name': 'Main function',
 'pathname': '/private/tmp/bug-262/main.py',
 'process': 97653,
 'processName': 'MainProcess',
 'relativeCreated': 504.8849582672119,
 'stack_info': None,
 'thread': 4557233600,
 'threadName': 'MainThread'
}

Pytest live log record

{
 'args': (),
 'created': 1610706539.410131,
 'exc_info': None,
 'exc_text': None,
 'filename': 'main.py',
 'funcName': 'handler',
 'levelname': 'ERROR',
 'levelno': 40,
 'lineno': 11,
 'message': 'Some error level log',
 'module': 'main',
 'msecs': 410.13097763061523,
 'msg': 'Some error level log',
 'name': 'Main function',
 'pathname': '/private/tmp/bug-262/main.py',
 'process': 97653,
 'processName': 'MainProcess',
 'relativeCreated': 504.8849582672119,
 'stack_info': None,
 'thread': 4557233600,
 'threadName': 'MainThread'
}

[2]

[silvestriluca]

Hello @heitorlessa .

Great analysis, kudos for that!
My two cents:

• Quick fix: I agree with you in approaching the issue in the most unobtrusive way, and Introduce a feature flag to disable log filter (env var). I would suggest POWERTOOLS_LOG_FILTER_DISABLED with a default value of 0 (pretty much like POWERTOOLS_TRACE_DISABLED flag)
• I would document this flag in Logger documentation under "Testing your code" section, explaining why is needed.
• Long term plan: I would also open an issue in Pytest repo, linking this issue, explaining this usecase and asking them to implement some way to track live log messages so they can be intercepted/differentiated. As an alternative, they could provide some ideas, as you pointed out. I guess that this is not the only library that has issues with this drastic approach of overtaking on the root logger.

What do you think?

[heitorlessa]

Perfect - I'll see if I can ship this with 1.10 early next week, or as a fast follow by next Friday then ;)