feat(consume): enable logging, propagate logs to hive results #1361

danceratopz · 2025-03-27T10:06:12Z

🗒️ Description

The Besu Team reported some flaky looking eest/consume-rlp results in the Pectra dashboard, without any logging from the simulator side, we're essentially blind as to the timing of the simulator setup with regards to client startup. This PR adds logging to help debug this.

Changes

Use pytest's --tb short to only show relevant tracebacks for unexpected exceptions in test execution (e.g., timeout on rpc call; requests exceptions are notoriously noisy).
Add a new logging plugin. This is pretty ugly stuff, but the complexity seems necessary to achieve:
a. Getting timestamps in pytest's capd output (pytest has amazing logging, but this seemed unachievable with the built-in plugin, would be happy to be wrong).
b. Clean logging to file per logger with xdist.
c. Adding log lines to the file for start and end of test.
Propagates stdout and stderr capd from pytest to the pytest test result so it's available in the test result in hiveview.

Example of Hiveview test case fail

Still with a bug; setup stdout is duplicated in call stdout.

Example of Hiveview test case pass

With bug fix (setup stdout no longer duplicated to call stdout).

Example of file logging

2025-03-27 09:42:00.502+00:00 [INFO] pytest_plugins.logging: ℹ️  - START TEST: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Cancun-blockchain_test_from_state_test]-go-ethereum_default]
2025-03-27 09:42:00.531+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Starting client (go-ethereum_default)...
2025-03-27 09:42:01.409+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Client (go-ethereum_default) ready!
2025-03-27 09:42:01.411+00:00 [INFO] pytest_plugins.consume.hive_simulators.rlp.test_via_rlp: Calling getBlockByNumber to get genesis block...
2025-03-27 09:42:01.416+00:00 [INFO] pytest_plugins.consume.hive_simulators.rlp.test_via_rlp: Calling getBlockByNumber to get latest block...
2025-03-27 09:42:01.421+00:00 [INFO] pytest_plugins.logging: ✅ - PASSED in 0.01s: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Cancun-blockchain_test_from_state_test]-go-ethereum_default]
2025-03-27 09:42:01.421+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Stopping client (go-ethereum_default)...
2025-03-27 09:42:01.564+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Client (go-ethereum_default) stopped!
2025-03-27 09:42:01.569+00:00 [INFO] pytest_plugins.logging: ℹ️  - END TEST: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Cancun-blockchain_test_from_state_test]-go-ethereum_default]
2025-03-27 09:42:01.569+00:00 [INFO] pytest_plugins.logging: ℹ️  - START TEST: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Shanghai-blockchain_test_from_state_test]-go-ethereum_default]
2025-03-27 09:42:01.575+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Starting client (go-ethereum_default)...
2025-03-27 09:42:02.500+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Client (go-ethereum_default) ready!
2025-03-27 09:42:02.502+00:00 [INFO] pytest_plugins.consume.hive_simulators.rlp.test_via_rlp: Calling getBlockByNumber to get genesis block...
2025-03-27 09:42:02.507+00:00 [INFO] pytest_plugins.consume.hive_simulators.rlp.test_via_rlp: Calling getBlockByNumber to get latest block...
2025-03-27 09:42:02.512+00:00 [INFO] pytest_plugins.logging: ✅ - PASSED in 0.01s: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Shanghai-blockchain_test_from_state_test]-go-ethereum_default]
2025-03-27 09:42:02.513+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Stopping client (go-ethereum_default)...
2025-03-27 09:42:02.677+00:00 [INFO] pytest_plugins.consume.hive_simulators.conftest: Client (go-ethereum_default) stopped!
2025-03-27 09:42:02.688+00:00 [INFO] pytest_plugins.logging: ℹ️  - END TEST: src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py::test_via_rlp[tests/istanbul/eip1344_chainid/test_chainid.py::test_chainid[fork_Shanghai-blockchain_test_from_state_test]-go-ethereum_default]

Example of console logging with fail

Pytest provides this out the box, but without timestamps 😭

🔗 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.

Copilot

Pull Request Overview

This PR adds logging capabilities to help debug timing issues in simulator and client interactions by propagating logs to hive test results and configuring more concise tracebacks.

Use pytest’s --tb short for cleaner tracebacks.
Introduce a new logging plugin to add timestamps and per-worker log files.
Propagate captured stdout/stderr into test result details for hiveview.

Reviewed Changes

Copilot reviewed 4 out of 6 changed files in this pull request and generated 2 comments.

File	Description
src/pytest_plugins/pytest_hive/pytest_hive.py	Adjusts test reporting to include captured output and modifies how test details are aggregated.
src/pytest_plugins/logging.py	Introduces a logging plugin that creates per-worker log files with UTC timestamps and colorful terminal output.
src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py	Adds logging statements before RPC calls and improves assertion messages for clarity.
src/pytest_plugins/consume/hive_simulators/conftest.py	Inserts logging calls to mark the lifecycle events of clients.

Files not reviewed (2)

pytest-consume.ini: Language not supported
whitelist.txt: Language not supported

src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py

Co-authored-by: Copilot <[email protected]>

spencer-tb

This must have been hard to get working! Really happy to have this. Minor comments below :)

Assuming consume engine additions in another PR?

pytest-consume.ini

src/pytest_plugins/logging.py

Co-authored-by: spencer <[email protected]>

Co-authored-by: Copilot <[email protected]>

danceratopz · 2025-03-27T14:23:49Z

Assuming consume engine additions in another PR?

@spencer-tb We should probably add a couple here for good measure. I was hoping to do a fast follow-up PR with rpc call retries, in which case the logging will require re-writing anyway. But let's get them in here, it's only a few mins.

marioevz

Some comments, or just like questions in general, but overall looks pretty good.

src/pytest_plugins/logging.py

src/pytest_plugins/consume/hive_simulators/conftest.py

The `get_logger()` helper function enables typechecking for our custom log-levels without the need for devs to explicitly cast to `EESTLogger` every time.

marioevz

LGTM, I think we could improve this in the future, by adding fill for example, but as of now seems good to go. Thanks!

marioevz · 2025-04-02T18:51:17Z

I've debugged the unit test fail and funnily enough, it does not fail when you select the failing test only:

uv run pytest -c ./pytest-framework.ini src/pytest_plugins/consume/tests/test_consume_args.py

passes all tests, but doing:

uv run pytest -c ./pytest-framework.ini src/pytest_plugins/consume/tests/test_consume_args.py src/pytest_plugins/logging/tests/test_logging.py

makes them fail.

danceratopz · 2025-04-02T20:16:44Z

I've debugged the unit test fail and funnily enough, it does not fail when you select the failing test only:
uv run pytest -c ./pytest-framework.ini src/pytest_plugins/consume/tests/test_consume_args.py
passes all tests, but doing:
uv run pytest -c ./pytest-framework.ini src/pytest_plugins/consume/tests/test_consume_args.py src/pytest_plugins/logging/tests/test_logging.py
makes them fail.

Thanks so much for starting to debug this, I was confused about the CI fail as I was sure that I fixed it locally.

Should be sorted now.

…um#1361) Co-authored-by: spencer <[email protected]>

danceratopz added 3 commits March 27, 2025 00:28

feat(consume): enable logging; add a few examples

cc50c11

fix(consume): don't colorize log output if running in docker

88e70bc

feat(consume): propagate stdout and stderr in hive test result

00b37a0

danceratopz added type:feat type: Feature scope:consume Scope: Consume command suite labels Mar 27, 2025

danceratopz requested a review from Copilot March 27, 2025 10:06

Copilot AI reviewed Mar 27, 2025

View reviewed changes

src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py Outdated Show resolved Hide resolved

src/pytest_plugins/consume/hive_simulators/rlp/test_via_rlp.py Outdated Show resolved Hide resolved

Apply suggestions from code review

cdf21f6

Co-authored-by: Copilot <[email protected]>

spencer-tb reviewed Mar 27, 2025

View reviewed changes

danceratopz and others added 3 commits March 27, 2025 15:16

Apply suggestions from code review

1f8cda2

Co-authored-by: spencer <[email protected]>

Apply suggestions from code review

6b53b3c

Co-authored-by: Copilot <[email protected]>

chore(consume): tidy-up ini file

7ebc526

fix(consume): don't include setup logs from call logs

4e58741

marioevz reviewed Mar 27, 2025

View reviewed changes

src/pytest_plugins/logging.py Outdated Show resolved Hide resolved

src/pytest_plugins/logging.py Outdated Show resolved Hide resolved

src/pytest_plugins/consume/hive_simulators/conftest.py Show resolved Hide resolved

danceratopz added 9 commits April 2, 2025 01:01

refactor(logging): avoid modifying original log record in ColorFormatter

22329e9

refactor(consume): improve docstring and clean-up

b164510

feat(consume): subclass Logger and add a get_logger helper

d8d78bd

The `get_logger()` helper function enables typechecking for our custom log-levels without the need for devs to explicitly cast to `EESTLogger` every time.

docs(logging): add logger to online docs

694ff1e

chore(logger): remove unused attribute

24a73d3

feat(logger): allow logger to be used by standalone (none-pytest) apps

0196295

tests(logger): make logging a package and add unit tests

3a04328

refactor(logger): use a ClassVar for running_in_docker

e12258d

feat(consume): add logging to consume engine

623b0df

spencer-tb mentioned this pull request Apr 2, 2025

feat(release): tasks for version v4.2.0 #1383

Closed

11 tasks

marioevz approved these changes Apr 2, 2025

View reviewed changes

danceratopz added 2 commits April 2, 2025 22:06

tests(consume): improve test id pattern matching in collect-only test

39c39b6

tests(logging): fix-up color formatter monkeypatching

11debfb

danceratopz added 3 commits April 2, 2025 22:45

feat(consume): improve formatting of hive propagated captured output

76eea0d

chore(consume): minor change in propagated hive test detail

549b4a6

chore(consume): moar minor change in propagated hive test detail

48e3ce7

danceratopz merged commit 3eddd28 into main Apr 2, 2025
21 checks passed

danceratopz deleted the consume-add-logging branch April 2, 2025 21:19

spencer-tb mentioned this pull request Apr 3, 2025

feat(hive): add hive engine-api simulator and eest execute ethpandaops/pectra-devnets#104

Draft

3 tasks

danceratopz mentioned this pull request May 6, 2025

tooling(ux): better logging in python tests #1562

Open

8 tasks

felix314159 pushed a commit to felix314159/execution-spec-tests that referenced this pull request May 16, 2025

feat(consume): enable logging, propagate logs to hive results (ethere…

d10db64

…um#1361) Co-authored-by: spencer <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

feat(consume): enable logging, propagate logs to hive results #1361

feat(consume): enable logging, propagate logs to hive results #1361

Uh oh!

danceratopz commented Mar 27, 2025 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

spencer-tb left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

danceratopz commented Mar 27, 2025 •

edited

Loading

Uh oh!

marioevz left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

marioevz left a comment

Uh oh!

marioevz commented Apr 2, 2025

Uh oh!

danceratopz commented Apr 2, 2025

Uh oh!

Uh oh!

Uh oh!

feat(consume): enable logging, propagate logs to hive results #1361

feat(consume): enable logging, propagate logs to hive results #1361

Uh oh!

Conversation

danceratopz commented Mar 27, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

🗒️ Description

Changes

Example of Hiveview test case fail

Example of Hiveview test case pass

Example of file logging

Example of console logging with fail

🔗 Related Issues

✅ Checklist

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Reviewed Changes

Uh oh!

Uh oh!

Uh oh!

spencer-tb left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

danceratopz commented Mar 27, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

marioevz left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

marioevz left a comment

Choose a reason for hiding this comment

Uh oh!

marioevz commented Apr 2, 2025

Uh oh!

danceratopz commented Apr 2, 2025

Uh oh!

Uh oh!

Uh oh!

danceratopz commented Mar 27, 2025 •

edited

Loading

danceratopz commented Mar 27, 2025 •

edited

Loading