Add `tracing-subscriber` to itf #1430

jbesraa · 2025-01-31T16:13:24Z

This should allow us to examine the logs from the roles that are using tracing crate for logging. As a default only ERROR logs will be shown, in order to examine a different level of logging, RUST_LOG env variable should be modified.

For example RUST_LOG=info cargo test --test '*'

resolves #1370

jbesraa · 2025-01-31T16:17:39Z

roles/tests-integration/tests/pool_integration.rs

@@ -16,6 +17,9 @@ use roles_logic_sv2::{
 // Pool will connect to the Sniffer, and the Sniffer will connect to the Template Provider.
 #[tokio::test]
 async fn success_pool_template_provider_connection() {
+    tracing_subscriber::fmt()


This is initialized in a single test in each file. This way it works for all tests in the file.. it is repetitive but could not think about a better way..

We can set up a static logger in lib/mod.rs, so every time the module is used, logger initialization runs automatically. Using once_cell::sync::Lazy, we make sure it only initializes once. This should work I hope. Something like this

static LOGGER: Lazy<()> = Lazy::new(|| { once_cell.call_once(|| { tracing_subscriber::fmt() .with_env_filter(EnvFilter::from_default_env()) .init();; }); });

deleted my previous comments here as I just realized I was writing nonsense... apologies for the noise!

please ignore them in case you're reading notifications on Discord

anyways, I could not get the suggestion from @Shourya742 above to work, as there seems to be no call_once API on the once_cell crate:

error[E0423]: expected value, found crate `once_cell` --> tests-integration/lib/mod.rs:24:5 | 24 | once_cell.call_once(|| { | ^^^^^^^^^- help: use the path separator to refer to an item: `::`

I suspect @Shourya742 mixed this with std::sync::Once.

but indeed, the problem with the current approach is:

it's repetitive, as we're forced to initialize the subscriber on each file

it's a bit counter-intuitive, because if we initialize the subscriber more than 1x on each file, it breaks with:

Unable to install global subscriber: SetGlobalDefaultError("a global default trace dispatcher has already been set")

not the end of the world... just something we would have to be careful with...

but one middle-ground approach (that I validated locally) could be to add this to lib/mod.rs:

use tracing_subscriber::EnvFilter; use std::sync::Once; static INIT: Once = Once::new(); pub fn init_tracing() { INIT.call_once(|| { tracing_subscriber::fmt() .with_env_filter(EnvFilter::from_default_env()) .init(); }); }

then call init_tracing() on the test.

it should be sufficient to call init_tracing() only 1x per file and it will enable logging on all tests of such file, just like it's currently done on this PR.

however, the advantage here is:

if for some reason init_tracing() is called on multiple tests on the same file, it will not break with the error mentioned above.

I just wrote psuedo code, as API's were not on top of my head. Let me check with concrete implementation of what meant and revert

Sorry for the late response. I received the notification when @jbesraa made changes. We can add the ctor crate so that whenever the integration_tests_sv2 module is referenced, the logger is automatically called without any manual intervention.

I've added commit dba3624 on my fork for cherry-picking.

@jbesraa the ctor approach above seems like an interesting alternative to the current approach of initializing the logger 1x per file

not entirely sold on this. adding new dep just for this feels too much, and current approach is not too bad IMO. If you both think otherwise, happy to add it though.

I don’t have a strong opinion on this either. It’s a nice feature to have, but it would have been even better if we could achieve something similar without an external dependency. Apparently, lazy initialization does not automatically trigger invocation upon module reference. The main reason this would make sense is to prevent confusion for new contributors regarding logger_initialization. Either we avoid initializing the logger in tests altogether or ensure it is initialized in every test.

codecov · 2025-01-31T16:22:08Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 18.05%. Comparing base (49c78e3) to head (af7bd32).
Report is 1 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1430      +/-   ##
==========================================
- Coverage   18.06%   18.05%   -0.02%     
==========================================
  Files         127      127              
  Lines        9555     9555              
==========================================
- Hits         1726     1725       -1     
- Misses       7829     7830       +1

Flag	Coverage Δ
binary_codec_sv2-coverage	`0.00% <ø> (ø)`
binary_sv2-coverage	`6.95% <ø> (ø)`
bip32_derivation-coverage	`0.00% <ø> (ø)`
buffer_sv2-coverage	`25.02% <ø> (ø)`
codec_sv2-coverage	`0.02% <ø> (ø)`
common_messages_sv2-coverage	`0.17% <ø> (ø)`
const_sv2-coverage	`0.00% <ø> (ø)`
error_handling-coverage	`0.00% <ø> (ø)`
framing_sv2-coverage	`0.37% <ø> (ø)`
jd_client-coverage	`0.42% <ø> (ø)`
jd_server-coverage	`9.02% <ø> (ø)`
job_declaration_sv2-coverage	`0.00% <ø> (ø)`
key-utils-coverage	`2.39% <ø> (ø)`
mining-coverage	`3.14% <ø> (-0.03%)`	⬇️
mining_device-coverage	`0.00% <ø> (ø)`
mining_proxy_sv2-coverage	`0.82% <ø> (ø)`
noise_sv2-coverage	`5.78% <ø> (ø)`
protocols	`23.90% <ø> (-0.02%)`	⬇️
roles	`6.43% <ø> (ø)`
roles_logic_sv2-coverage	`11.64% <ø> (ø)`
sv2_ffi-coverage	`0.00% <ø> (ø)`
template_distribution_sv2-coverage	`0.00% <ø> (ø)`
translator_sv2-coverage	`9.53% <ø> (ø)`
utils	`25.13% <ø> (ø)`
v1-coverage	`3.11% <ø> (ø)`

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

plebhash · 2025-01-31T22:56:09Z

As a default only ERROR logs will be shown, in order to examine a different level of logging, RUST_LOG env variable should be modified.

I think for local execution it's fine to leave this default, but we should consider doing RUST_LOG=debug on CI for max verbosity, hopefully it could help us debug un-deterministic behavior

jbesraa · 2025-02-10T08:02:53Z

Made changes based on the discussion above. Thank you.

roles/tests-integration/tests/jd_integration.rs

Shourya742 · 2025-02-11T03:18:49Z

roles/tests-integration/lib/mod.rs

+        tracing_subscriber::fmt()
+            .with_env_filter(EnvFilter::from_default_env())
+            .init();


Suggested change

tracing_subscriber::fmt()

.with_env_filter(EnvFilter::from_default_env())

.init();

tracing_subscriber::registry()

.with(fmt::layer())

.with(

EnvFilter::builder()

.with_default_directive(LevelFilter::DEBUG.into())

.from_env_lossy(),

)

.init();

Should we switch to this? Instead of relying on the env variables, we can override the log levels using an EnvFilter layer in the tracing registry.

Hmm current approach seems more versatile - allowing us to have different level in CI and locally. I prefer to keep it simple as is.

This sets a default log level, eliminating the need to specify the RUST_LOG environment variable every time we run a test. However, if RUST_LOG is set, its value will take precedence over the default DEBUG level. The logger will still be versatile but with a default log level to fallback on.

current approach does not require setting RUST_LOG, if it is not set it will fallback to ERROR

Ah!!!... I thought it might not set any level... works...

This should allow us to examine the logs from the roles that are using `tracing` crate for logging. As a default only ERROR logs will be shown, in order to examine a different level of logging, `RUST_LOG` env variable should be modified. For example `RUST_LOG=info cargo test --test '*'`

..previously musl were used

.. for more verbosity

..to more descriptive one

jbesraa · 2025-02-11T07:17:25Z

Rebased without further changes

jbesraa force-pushed the 2025-01-31/show-roles-logs-in-itf branch from 2ba08cc to 0e5079f Compare January 31, 2025 16:15

jbesraa commented Jan 31, 2025

View reviewed changes

plebhash mentioned this pull request Jan 31, 2025

Translator Proxy shuts down after disconnecting downstream miner #1426

Closed

jbesraa force-pushed the 2025-01-31/show-roles-logs-in-itf branch 3 times, most recently from f3e58c7 to 8b0da8e Compare February 10, 2025 08:01

plebhash reviewed Feb 10, 2025

View reviewed changes

roles/tests-integration/tests/jd_integration.rs Outdated Show resolved Hide resolved

jbesraa force-pushed the 2025-01-31/show-roles-logs-in-itf branch from 8b0da8e to 33f58d1 Compare February 10, 2025 17:27

plebhash approved these changes Feb 10, 2025

View reviewed changes

Shourya742 reviewed Feb 11, 2025

View reviewed changes

jbesraa added 5 commits February 11, 2025 09:17

Use linux 64bit target

8c027e2

..previously musl were used

Show debug level logs for integration tests in CI

e931aa2

.. for more verbosity

Add top level docs for itests

08b904f

Change test name ..

af7bd32

..to more descriptive one

jbesraa force-pushed the 2025-01-31/show-roles-logs-in-itf branch from 33f58d1 to af7bd32 Compare February 11, 2025 07:17

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add `tracing-subscriber` to itf #1430

Add `tracing-subscriber` to itf #1430

jbesraa commented Jan 31, 2025

jbesraa Jan 31, 2025

Shourya742 Jan 31, 2025 •

edited

Loading

plebhash Feb 1, 2025

Shourya742 Feb 1, 2025

Shourya742 Feb 10, 2025

plebhash Feb 11, 2025

jbesraa Feb 11, 2025

Shourya742 Feb 11, 2025

codecov bot commented Jan 31, 2025 •

edited

Loading

plebhash commented Jan 31, 2025

jbesraa commented Feb 10, 2025

Shourya742 Feb 11, 2025

jbesraa Feb 11, 2025

Shourya742 Feb 11, 2025

jbesraa Feb 11, 2025

Shourya742 Feb 11, 2025

jbesraa commented Feb 11, 2025

-        tracing_subscriber::fmt()
-            .with_env_filter(EnvFilter::from_default_env())
-            .init();
+        tracing_subscriber::registry()
+        .with(fmt::layer())
+        .with(
+            EnvFilter::builder()
+                .with_default_directive(LevelFilter::DEBUG.into())
+                .from_env_lossy(),
+        )
+        .init();

Add tracing-subscriber to itf #1430

Are you sure you want to change the base?

Add tracing-subscriber to itf #1430

Conversation

jbesraa commented Jan 31, 2025

Choose a reason for hiding this comment

Shourya742 Jan 31, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Jan 31, 2025 • edited Loading

Codecov Report

plebhash commented Jan 31, 2025

jbesraa commented Feb 10, 2025

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbesraa commented Feb 11, 2025

Add `tracing-subscriber` to itf #1430

Add `tracing-subscriber` to itf #1430

Shourya742 Jan 31, 2025 •

edited

Loading

codecov bot commented Jan 31, 2025 •

edited

Loading