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

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

Author: danceratopz

docs/CHANGELOG.md

@@ -31,7 +31,9 @@ consume cache --help
 - ✨ Allow filtering of test cases by fork via pytest marks (e.g., `-m "Cancun or Prague"`) ([#1304](https://github.com/ethereum/execution-spec-tests/pull/1304), [#1318](https://github.com/ethereum/execution-spec-tests/pull/1318)).
 - ✨ Allow filtering of test cases by fixture format via pytest marks (e.g., `-m blockchain_test`) ([#1314](https://github.com/ethereum/execution-spec-tests/pull/1314)).
 - ✨ Add top-level entries `forks` and `fixture_formats` to the index file that list all the forks and fixture formats used in the indexed fixtures ([#1318](https://github.com/ethereum/execution-spec-tests/pull/1318)).
-- 🐞 Don't parametrize tests for unsupported fixture formats; improve `consume` test collection ([#1315](https://github.com/ethereum/execution-spec-tests/pull/1314)).
+- ✨ Enable logging from `consume` commands ([#1361](https://github.com/ethereum/execution-spec-tests/pull/1361)).
+- ✨ Propagate stdout and stderr (including logs) captured during test execution to the Hive test result ([#1361](https://github.com/ethereum/execution-spec-tests/pull/1361)).
+- 🐞 Don't parametrize tests for unsupported fixture formats; improve `consume` test collection ([#1315](https://github.com/ethereum/execution-spec-tests/pull/1315)).
 - 🐞 Fix the the hive command printed in test reports to reproduce tests in isolation by prefixing the `--sim.limit` flag value with `id:` ([#1333](https://github.com/ethereum/execution-spec-tests/pull/1333)).
 - 🐞 Improve index generation of [ethereum/tests](https://github.com/ethereum/tests) fixtures: Allow generation at any directory level and include `generatedTestHash` in the index file for the `fixture_hash` ([#1303](https://github.com/ethereum/execution-spec-tests/pull/1303)).
 - 🐞 Fix loading of [ethereum/tests](https://github.com/ethereum/tests) and [ethereum/legacytests](https://github.com/ethereum/legacytests) fixtures for the case of mixed `0x0` and `0x1` transaction types in multi-index (`data`, `gas`, `value`) state test fixtures ([#1330](https://github.com/ethereum/execution-spec-tests/pull/1330)).

docs/dev/index.md

@@ -7,6 +7,7 @@ This documentation is aimed at maintainers of `execution-spec-tests` but may be
 - [Generating documentation](./docs.md): Steps to create and build documentation for the project.
 - [Documenting CLI commands](./documenting_clis.md): Instructions for documenting command line interfaces (CLIs).
 - [Coding style](./coding_style.md): Standards and best practices for code formatting and to maintain consistency across the repository.
+- [Logging](./logging.md): Documentation on using the custom logging system with enhanced features.
 - [Enabling pre-commit checks](./precommit.md): A guide for setting up pre-commit hooks to enforce code quality before commits.
 - [Running github actions locally](./test_actions_locally.md): Instructions for testing GitHub Actions workflows on your local machine to streamline development and debugging.
 - [Porting tests](./porting_legacy_tests.md): A guide to porting legacy ethereum tests to EEST.

docs/dev/logging.md

@@ -0,0 +1,175 @@
+# Logging
+
+This document describes the logging system used in the Ethereum Execution Spec Tests project. Currently, logging is only supported for `consume` commands.
+
+## Overview
+
+The project uses Python's standard logging module with custom extensions to provide enhanced logging capabilities. Our logging system is implemented in the `src/pytest_plugins/logging.py` module and provides the following features:
+
+- Custom log levels between the standard Python log levels
+- Timestamps with millisecond precision in UTC
+- Color-coded log output (when not running in Docker)
+- File logging with a consistent naming pattern
+- Integration with pytest's output capture
+- Support for distributed test execution with pytest-xdist
+
+## Custom Log Levels
+
+In addition to the standard Python log levels (DEBUG, INFO, WARNING, ERROR, CRITICAL), we've added the following custom levels:
+
+| Level | Numeric Value | Purpose |
+|-------|--------------|---------|
+| VERBOSE | 15 | For messages more detailed than INFO but less verbose than DEBUG |
+| FAIL | 35 | For test failures and related issues (between WARNING and ERROR) |
+
+## Using the Logger
+
+### Getting a Logger
+
+To use the custom logger in your code, import the `get_logger` function from the logging module:
+
+```python
+from pytest_plugins.logging import get_logger
+
+# Create a logger with your module's name
+logger = get_logger(__name__)
+```
+
+### Logging at Different Levels
+
+You can use all standard Python log methods plus our custom methods:
+
+```python
+# Standard log levels
+logger.debug("Detailed debug information")
+logger.info("General information")
+logger.warning("Warning message")
+logger.error("Error message")
+logger.critical("Critical failure")
+
+# Custom log levels
+logger.verbose("More detailed than INFO, less than DEBUG")
+logger.fail("Test failure or similar issue")
+```
+
+### When to Use Each Level
+
+- **DEBUG (10)**: For very detailed diagnostic information useful for debugging
+- **VERBOSE (15)**: For information that's useful during development but more detailed than INFO
+- **INFO (20)**: For general information about program operation
+- **WARNING (30)**: For potential issues that don't prevent program execution
+- **FAIL (35)**: For test failures and related issues
+- **ERROR (40)**: For errors that prevent an operation from completing
+- **CRITICAL (50)**: For critical errors that may prevent the program from continuing
+
+## Configuration
+
+### Setting Log Level on the Command Line
+
+You can adjust the log level when running pytest with the `--eest-log-level` option:
+
+```bash
+consume engine --input=latest@stable --eest-log-level=VERBOSE -s --sim.limit=".*chainid.*"
+```
+
+The argument accepts both log level names (e.g., "DEBUG", "VERBOSE", "INFO") and numeric values.
+
+Adding pytest's `-s` flag writes the logging messages to the terminal; otherwise output will be written to the log file that is reported in the test session header at the end of the test session.
+
+### Log File Output
+
+Log files are automatically created in the `logs/` directory with a naming pattern that includes:
+
+- The command name, e.g. `consume`,
+- An optional subcommand (e.g., `engine`),
+- A timestamp in UTC,
+- The worker ID (when using pytest-xdist).
+
+Example: `consume-engine-20240101-123456-main.log`
+
+The log file path is displayed in the pytest header and summary.
+
+### Using the Standalone Configuration in Non-Pytest Projects
+
+The logging module can also be used in non-pytest projects by using the `configure_logging` function:
+
+```python
+from pytest_plugins.logging import configure_logging, get_logger
+
+# Configure logging with custom settings
+configure_logging(
+    log_level="VERBOSE",
+    log_file="my_application.log",
+    log_to_stdout=True,
+    log_format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
+    use_color=True
+)
+
+# Get a logger and use it
+logger = get_logger(__name__)
+logger.verbose("Logging configured in standalone application!")
+```
+
+The `configure_logging` function accepts the following parameters:
+
+- `log_level`: A string or numeric log level (default: "INFO")
+- `log_file`: Path to a log file, or None to disable file logging (default: None)
+- `log_to_stdout`: Whether to log to stdout (default: True)
+- `log_format`: The format string for log messages (default: "%(asctime)s [%(levelname)s] %(name)s: %(message)s")
+- `use_color`: Whether to use colors in stdout output, or None to auto-detect (default: None)
+
+## Implementation Details
+
+### The EESTLogger Class
+
+The `EESTLogger` class extends Python's `Logger` class to add the custom log methods. The main module logger is automatically configured to use this class.
+
+### Formatters
+
+Two formatter classes are available:
+
+- `UTCFormatter`: Formats timestamps with millisecond precision in UTC
+- `ColorFormatter`: Extends `UTCFormatter` to add ANSI colors to log level names in terminal output
+
+### Pytest and Hive Integration
+
+The logging module includes several pytest hooks to:
+
+- Configure logging at the start of a test session
+- Record logs during test execution
+- Display the log file path in the test report
+- Ensure logs are captured properly during fixture teardown
+
+The `hive_pytest` plugin has been extended to propagate the logs to the `hiveview` UI via the test case's `details` ("description" in `hiveview`).
+
+## Example Usage
+
+A complete example of using the logging system in a `consume` test (or plugin):
+
+```python
+from pytest_plugins.logging import get_logger
+
+# Get a properly typed logger for your module
+logger = get_logger(__name__)
+
+def test_something():
+    # Use standard log levels
+    logger.debug("Setting up test variables")
+    logger.info("Starting test")
+    
+    # Use custom log levels
+    logger.verbose("Additional details about test execution")
+    
+    # Log warnings or errors as needed
+    if something_concerning:
+        logger.warning("Something looks suspicious")
+    
+    if something_failed:
+        logger.fail("Test condition not met")
+        assert False, "Test failed"
+    
+    # Log successful completion
+    logger.info("Test completed successfully")
+```
+
+All log messages will be displayed according to the configured log level and captured in the log file.

docs/navigation.md

@@ -38,6 +38,7 @@
     * [Generating Documentation](dev/docs.md)
     * [Documenting CLI Commands](dev/documenting_clis.md)
     * [Coding Style](dev/coding_style.md)
+    * [Logging](dev/logging.md)
     * [Enabling Precommit Checks](dev/precommit.md)
     * [Running Github Actions Locally](dev/test_actions_locally.md)
     * [Porting Legacy Tests](dev/porting_legacy_tests.md)

pytest-consume.ini

@@ -6,5 +6,8 @@ addopts =
     -rxXs
     --tb short
     -p pytest_plugins.concurrency
+    # disable pytest built-in logging entirely `-p no:logging`
+    -p no:logging
+    -p pytest_plugins.logging.logging
     -p pytest_plugins.consume.consume
     -p pytest_plugins.help.help

src/pytest_plugins/consume/hive_simulators/conftest.py

@@ -2,6 +2,7 @@
 
 import io
 import json
+import logging
 from pathlib import Path
 from typing import Dict, Generator, List, Literal, cast
 
@@ -24,6 +25,8 @@
 
 from .timing import TimingData
 
+logger = logging.getLogger(__name__)
+
 
 def pytest_addoption(parser):
     """Hive simulator specific consume command line options."""
@@ -202,6 +205,7 @@ def client(
     total_timing_data: TimingData,
 ) -> Generator[Client, None, None]:
     """Initialize the client with the appropriate files and environment variables."""
+    logger.info(f"Starting client ({client_type.name})...")
     with total_timing_data.time("Start client"):
         client = hive_test.start_client(
             client_type=client_type, environment=environment, files=client_files
@@ -211,9 +215,12 @@ def client(
         "setup. Check the client or Hive server logs for more information."
     )
     assert client is not None, error_message
+    logger.info(f"Client ({client_type.name}) ready!")
     yield client
+    logger.info(f"Stopping client ({client_type.name})...")
     with total_timing_data.time("Stop client"):
         client.stop()
+    logger.info(f"Client ({client_type.name}) stopped!")
 
 
 @pytest.fixture(scope="function", autouse=True)

src/pytest_plugins/consume/hive_simulators/engine/test_via_engine.py

@@ -9,9 +9,12 @@
 from ethereum_test_rpc import EngineRPC, EthRPC
 from ethereum_test_rpc.types import ForkchoiceState, JSONRPCError, PayloadStatusEnum
 from pytest_plugins.consume.hive_simulators.exceptions import GenesisBlockMismatchExceptionError
+from pytest_plugins.logging import get_logger
 
 from ..timing import TimingData
 
+logger = get_logger(__name__)
+
 
 def test_blockchain_via_engine(
     timing_data: TimingData,
@@ -27,48 +30,72 @@ def test_blockchain_via_engine(
     """
     # Send a initial forkchoice update
     with timing_data.time("Initial forkchoice update"):
+        logger.info("Sending initial forkchoice update to genesis block...")
         forkchoice_response = engine_rpc.forkchoice_updated(
             forkchoice_state=ForkchoiceState(
                 head_block_hash=fixture.genesis.block_hash,
             ),
             payload_attributes=None,
             version=fixture.payloads[0].forkchoice_updated_version,
         )
+        status = forkchoice_response.payload_status.status
+        logger.info(f"Initial forkchoice update response: {status}")
         assert forkchoice_response.payload_status.status == PayloadStatusEnum.VALID, (
             f"unexpected status on forkchoice updated to genesis: {forkchoice_response}"
         )
 
     with timing_data.time("Get genesis block"):
+        logger.info("Calling getBlockByNumber to get genesis block...")
         genesis_block = eth_rpc.get_block_by_number(0)
         if genesis_block["hash"] != str(fixture.genesis.block_hash):
+            expected = fixture.genesis.block_hash
+            got = genesis_block["hash"]
+            logger.fail(f"Genesis block hash mismatch. Expected: {expected}, Got: {got}")
             raise GenesisBlockMismatchExceptionError(
                 expected_header=fixture.genesis,
                 got_genesis_block=genesis_block,
             )
 
     with timing_data.time("Payloads execution") as total_payload_timing:
+        logger.info(f"Starting execution of {len(fixture.payloads)} payloads...")
         for i, payload in enumerate(fixture.payloads):
+            logger.info(f"Processing payload {i + 1}/{len(fixture.payloads)}...")
             with total_payload_timing.time(f"Payload {i + 1}") as payload_timing:
                 with payload_timing.time(f"engine_newPayloadV{payload.new_payload_version}"):
+                    logger.info(f"Sending engine_newPayloadV{payload.new_payload_version}...")
+                    expected_validity = "VALID" if payload.valid() else "INVALID"
+                    logger.info(f"Expected payload validity: {expected_validity}")
                     try:
                         payload_response = engine_rpc.new_payload(
                             *payload.params,
                             version=payload.new_payload_version,
                         )
+                        logger.info(f"Payload response status: {payload_response.status}")
                         assert payload_response.status == (
                             PayloadStatusEnum.VALID
                             if payload.valid()
                             else PayloadStatusEnum.INVALID
                         ), f"unexpected status: {payload_response}"
                         if payload.error_code is not None:
+                            error_code = payload.error_code
+                            logger.fail(
+                                f"Client failed to raise expected Engine API error code: "
+                                f"{error_code}"
+                            )
                             raise Exception(
                                 "Client failed to raise expected Engine API error code: "
                                 f"{payload.error_code}"
                             )
                     except JSONRPCError as e:
+                        logger.info(f"JSONRPC error encountered: {e.code} - {e.message}")
                         if payload.error_code is None:
+                            logger.fail(f"Unexpected error: {e.code} - {e.message}")
                             raise Exception(f"unexpected error: {e.code} - {e.message}") from e
                         if e.code != payload.error_code:
+                            expected_code = payload.error_code
+                            logger.fail(
+                                f"Unexpected error code: {e.code}, expected: {expected_code}"
+                            )
                             raise Exception(
                                 f"unexpected error code: {e.code}, expected: {payload.error_code}"
                             ) from e
@@ -78,13 +105,18 @@ def test_blockchain_via_engine(
                         f"engine_forkchoiceUpdatedV{payload.forkchoice_updated_version}"
                     ):
                         # Send a forkchoice update to the engine
+                        version = payload.forkchoice_updated_version
+                        logger.info(f"Sending engine_forkchoiceUpdatedV{version}...")
                         forkchoice_response = engine_rpc.forkchoice_updated(
                             forkchoice_state=ForkchoiceState(
                                 head_block_hash=payload.params[0].block_hash,
                             ),
                             payload_attributes=None,
                             version=payload.forkchoice_updated_version,
                         )
+                        status = forkchoice_response.payload_status.status
+                        logger.info(f"Forkchoice update response: {status}")
                         assert (
                             forkchoice_response.payload_status.status == PayloadStatusEnum.VALID
                         ), f"unexpected status: {forkchoice_response}"
+        logger.info("All payloads processed successfully.")

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

@@ -5,12 +5,16 @@
 Clients consume the genesis and RLP-encoded blocks from input files upon start-up.
 """
 
+import logging
+
 from ethereum_test_fixtures import BlockchainFixture
 from ethereum_test_rpc import EthRPC
 from pytest_plugins.consume.hive_simulators.exceptions import GenesisBlockMismatchExceptionError
 
 from ..timing import TimingData
 
+logger = logging.getLogger(__name__)
+
 
 def test_via_rlp(
     timing_data: TimingData,
@@ -22,12 +26,16 @@ def test_via_rlp(
     2. Check the client last block hash matches `fixture.last_block_hash`.
     """
     with timing_data.time("Get genesis block"):
+        logger.info("Calling getBlockByNumber to get genesis block...")
         genesis_block = eth_rpc.get_block_by_number(0)
+        assert genesis_block, "`getBlockByNumber` didn't return a block."
         if genesis_block["hash"] != str(fixture.genesis.block_hash):
             raise GenesisBlockMismatchExceptionError(
                 expected_header=fixture.genesis,
                 got_genesis_block=genesis_block,
             )
     with timing_data.time("Get latest block"):
+        logger.info("Calling getBlockByNumber to get latest block...")
         block = eth_rpc.get_block_by_number("latest")
+        assert block, "`getBlockByNumber` didn't return a block."
         assert block["hash"] == str(fixture.last_block_hash), "hash mismatch in last block"