Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a logger to unit tests #6125

Closed
Tracked by #6119
franciscoaguirre opened this issue Oct 18, 2024 · 5 comments
Closed
Tracked by #6119

Add a logger to unit tests #6125

franciscoaguirre opened this issue Oct 18, 2024 · 5 comments
Assignees
Labels
T6-XCM This PR/Issue is related to XCM. T10-tests This PR/Issue is related to tests.

Comments

@franciscoaguirre
Copy link
Contributor

Logs are very helpful for xcm debugging in particular, where we mark them all with target: xcm and get them by specifying RUST_LOG=xcm.
However, this doesn't work out-of-the-box with unit tests, since we need a logger.
We can use env_logger but then each test needs this line in the start: let _ = env_logger::init();.
The other option is to add test-log as a dependency and import the test macro from it.
This was already done in polkadot/xcm/docs/src/cookbook/relay_token_transactor/tests.rs.

We could either adopt this everywhere or create a README of how to enable logs to make people's lives easier when debugging.

@bkchr
Copy link
Member

bkchr commented Oct 19, 2024

We have tons of tests with logging. However, I don't see the reason for this issue. If someone is debugging a test, they can just add a logger. There is no need to have a logger in every test, because not every test will always fail.

Also not sure how many people are "debugging these tests" constantly that we need an issue for this.

@bkchr
Copy link
Member

bkchr commented Oct 19, 2024

And also don't use env_logger, we have already sp_tracing::init_for_tests().

@raymondkfcheung raymondkfcheung self-assigned this Feb 17, 2025
@raymondkfcheung raymondkfcheung added the T10-tests This PR/Issue is related to tests. label Feb 19, 2025
@raymondkfcheung
Copy link
Contributor

I agree that using sp_tracing::init_for_tests() is a good approach for enabling logs in test runs:

cargo test -p xcm-simulator-example reserve_asset_transfer_nft -- --nocapture

Example output:

2025-02-20T14:23:56.650382Z TRACE trie: insert: ...
2025-02-20T14:23:56.650752Z TRACE trie: augmented ...

To further improve XCM debugging, I’ve proposed enhancing debugging with log capture in unit tests in PR #7594. This provides a structured way to capture logs in unit tests.

github-merge-queue bot pushed a commit that referenced this issue Feb 24, 2025
# Description

This PR introduces a lightweight log-capturing mechanism for XCM unit
tests, simplifying debugging by enabling structured log assertions. It
partially addresses #6119 and #6125, offering an optional way to verify
logs in tests while remaining unobtrusive in normal execution.

# Key Changes

* [x] Introduces a log capture utility in `sp_tracing`.
* [x] Adds XCM test examples demonstrating how and when to use log
capturing.

# Review Notes:

* The log capture mechanism is opt-in and does not affect existing tests
unless explicitly used.
* The implementation is minimal and does not add complexity to existing
test setups.
* It provides a structured alternative to
[`sp_tracing::init_for_tests()`](https://paritytech.github.io/polkadot-sdk/master/sp_tracing/fn.init_for_tests.html)
for log verification in automated tests.

---------

Co-authored-by: cmd[bot] <41898282+github-actions[bot]@users.noreply.github.com>
@raymondkfcheung
Copy link
Contributor

Here's a video clip explaining how to use sp_tracing::init_for_tests() on XCM E2E Integration Testing.

github-merge-queue bot pushed a commit that referenced this issue Mar 6, 2025
This PR enhances **`test_log_capture`**, ensuring logs are **captured
for assertions** and **printed to the console** during test execution.

## **Motivation**  

- Partially addresses #6119 and #6125, to improves developer **tracing
and debugging** in XCM-related tests.
- Builds on #7594, improving **log visibility** while maintaining test
**log capture capabilities**.
- While writing tests for #7234, I noticed this function was missing.
This PR adds it to streamline log handling in unit tests.

## **Changes**  

- Ensures logs up to `TRACE` level are **captured** (for assertions) and
**printed** (for visibility).
- Refines documentation to clearly specify **when to use** each
function.
- **Removes ANSI escape codes** from captured logs to ensure clean,
readable assertions.

## **When to Use?**  

| Usage | Captures Logs? | Prints Logs? | Example |

|----------------------------------------------|-----------------|--------------|-----------------------------------------------|
| `init_log_capture(LevelFilter::INFO, false)` | ✅ Yes | ❌ No | Capture
logs for assertions without printing. |
| `init_log_capture(LevelFilter::TRACE, true)` | ✅ Yes | ✅ Yes | Capture
logs and print them in test output. |
| `sp_tracing::init_for_tests()` | ❌ No | ✅ Yes | Print logs to the
console without capturing. |

---------

Co-authored-by: cmd[bot] <41898282+github-actions[bot]@users.noreply.github.com>
@raymondkfcheung
Copy link
Contributor

raymondkfcheung commented Mar 6, 2025

The improvements to log capture in testing, along with updated documentation, have been addressed in PR #7769.

To clarify the usage of the related functions, here's a breakdown:

Function Captures Logs? Prints Logs? Purpose & Usage
init_for_tests() Prints logs to the console without capturing.
try_init_simple() Initialises a simple subscriber using the default filter.
test_log_capture::init_log_capture(max_level, false) Captures logs for assertions without printing.
test_log_capture::init_log_capture(max_level, true) Captures logs and prints them in test output.
capture_test_logs!(max_level, print_logs, { block }) Macro for capturing logs within test blocks, with an option to print.

This ensures that each function’s behavior is clearly defined. Let me know if any adjustments are needed!

If there are no objections, I'll close this issue next Monday.

@raymondkfcheung raymondkfcheung moved this to In-Review in Bridges + XCM Mar 6, 2025
@raymondkfcheung raymondkfcheung added the T6-XCM This PR/Issue is related to XCM. label Mar 6, 2025
@raymondkfcheung raymondkfcheung moved this from In-Review to Done in Bridges + XCM Mar 6, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
T6-XCM This PR/Issue is related to XCM. T10-tests This PR/Issue is related to tests.
Projects
Status: Done
Development

No branches or pull requests

3 participants