tooling(ux): better logging in python tests

[felix314159]

🗒️ Description

Small change, big impact: With this instead of relying of of print() + -s we now can just use logging.info("abc"). This is better for many reasons:

• No need to add -s flag
• Shows in which FILE at which LINE the log is issued (great observability)
• Coloring of log levels
• Easy to format (e.g. show current date + time in specified format)
• Never again `if verboseLogging then foo else bar', just use logging.debug() and then temporarily toggle the log level to debug in the pytest.ini

These are the supported debugging levels that have a different color in the terminal:

• logging.debug("i am not shown by default cuz we defined log level INFO for now")
• logging.info("i am GREEN")
• logging.warning("i am BROWN")
• logging.error("i am light RED")
• logging.critical("im dark RED (much danger)")

Next steps:

• Replace all calls of "print()" we have today with logging equivalents

Visualization (subset of output of fill command of a test that uses new logging):

🔗 Related Issues

✅ Checklist

• [ ] All: Set appropriate labels for the changes.
• [ ] All: Considered squashing commits to improve commit history.
• [ ] All: Added an entry to CHANGELOG.md.
• [ ] All: Considered updating the online docs in the ./docs/ directory.
• [ ] Tests: All converted JSON/YML tests from ethereum/tests have been added to converted-ethereum-tests.txt.
• [ ] Tests: A PR with removal of converted JSON/YML tests from ethereum/tests have been opened.
• [ ] Tests: Included the type and version of evm t8n tool used to locally execute test cases: e.g., ref with commit hash or geth 1.13.1-stable-3f40e65.
• [ ] Tests: Ran mkdocs serve locally and verified the auto-generated docs for new tests in the Test Case Reference are correctly formatted.

[danceratopz]

Please check:

• https://github.com/ethereum/execution-spec-tests/pull/1361

I tried to use pytest's built-in logging config as you are in this PR, but I couldn't fufil the requirement of getting timestamps in the captured log output from within pytest. Frustratingly, they are visible in the console output, as in your screenshot: https://github.com/ethereum/execution-spec-tests/blob/c91549cf31c503d5ea9b3037093449dd0bb4d146/src/pytest_plugins/logging/logging.py#L4-L9

I'd be happy to be wrong! I find it hard to believe right now that this was an issue, but I remember feeling that way at the time too :laughing:! I even tried with pytest 8 to see if the behavior had changed.

If you can get it working to show timestamps in hiveview test reports, then we should use pytest's native method and delete the unnecessary code from #1361.

[felix314159]

We can use the custom logger you wrote, but this has nothing to do with this PR as far as I am concerned: I just want a way to help me debug while I am writing a test. Let's say I want to log a value, I can do:

from pytest_plugins.logging import get_logger
logger = get_logger(__name__)

logger.info("i want this to be logged along with time and file and line")

and while this does not lead to any errors, without this PR I won't see anything in my console when filling the test that contains this code. But with this PR (changes to the pytest.ini) I now can see my logged string in the console like I want to and like it is shown in the screenshot.

[felix314159]

I will keep this PR open I would like to be able to configure our logging wrapper so that it prints the filepath + linenumber

[felix314159]

I just noticed that it seems impossible to use the any kind of logging in files such as src/ethereum_clis_clis/geth.py, I added the -p pytest_plugins.logging.logging in every .ini file we have and also used

from pytest_plugins.logging import get_logger
logger = get_logger(__name__)
logger.info("abc")

and also added --eest-log-level=INFO and it still doesn't show any of the messages that should be logged.

Any idea what is going on? The function is definitely called (I try it in _consume_debug_dump()). Edit: I found a workaround to make it work, maybe that helps with debugging the issue: When I add

logger = get_logger(__name__)

# this is newly added:
if not logger.handlers:
    import logging
    handler = logging.StreamHandler()
    handler.setLevel(logging.INFO)
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    handler.setFormatter(formatter)
    logger.addHandler(handler)
print(f"Logger created: {logger}, level: {logger.level}, handlers: {logger.handlers}")

then the logging works (even without eest-log-level flag). So it seems like there is no handler being added to the logger in this specific scenario for some reason?