sc-tracing may not print log in some case after the tracing-log update to v0.1.3 with feature interest-cache

[atenjin]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

after substrate pr "Turn on logger's interest cache (#11264 )" , the tracing-log has updated to 0.1.3 with the feature interest-cache. but it seems that the upstream crate tracing-log has some bug in 0.1.3, and can not print log when we using sc-tracing in some case. (I do not know why using in substrate there is no problem, but in our project it has....)

Steps to reproduce

the simplified case is like this:

# create a new empty project
cargo new --bin test_tracing

and the test code in main.rs is just like this:

fn main() {
    let mut builder = sc_tracing::logging::LoggerBuilder::new("");
    builder.with_log_reloading(true);
    builder.init();

    log::info!("aaaaaaaaaa");
}

and the Cargo.toml is like this:

[dependencies]
log = "0.4"
sc-tracing = { git = "https://github.com/paritytech/substrate", branch = "polkadot-v0.9.19" }
#
# [patch."https://github.com/paritytech/substrate"]
# sc-tracing = { path = "/<my path>/workspace/blockchain/paritytech/substrate/client/tracing" }

then compile and run the code, it can have normal output:

2022-06-17 11:31:50 aaaaaaaaaa

and when I switch the dependency from polkadot-v0.9.19 to polkadot-v0.9.22, it can not work, there is no normal output...

So I check the git history, can ensure the problem is coming from the pr #11264 .

Then I wanna to figure out more thing, so I use a patch to replace the sc-traing, just like the code in the abrove.

[patch."https://github.com/paritytech/substrate"]
sc-tracing = { path = "/<my path>/workspace/blockchain/paritytech/substrate/client/tracing" }

and in my local path, I remove the code in substrate for this part (my local substrate has switch to branch polkadot-v0.9.22):

in client/tracing/src/logging/mod.rs:L160

	tracing_log::LogTracer::builder()
		.with_max_level(max_level)
		// .with_interest_cache(tracing_log::InterestCacheConfig::default())
		.init()?;

I remove the line .with_interest_cache(tracing_log::InterestCacheConfig::default()) which is coming from pr #11264

Then I compile it again and run, it also has no output (I do not modify any rust code in main.rs in the test project).

Then I remove the feature in my local substrate's sc-tracing crate:

in client/tracing/Crago.toml:L29

# tracing-log = { version = "0.1.3", features = ["interest-cache"] }
tracing-log = { version = "0.1.3" }

Then I don't do anything for my test project, and re-compile it again, then it can work.

Thus at here, I ensure this problem is coming from the upstream crate tracing-log, and it only appear when the feature interest-cache is opened, even we do not call with_interest_cache in the code...

But I'm still confused for why it work for substrate project? like cumulus, but our project and the test project can appear this problem.

we meet the problem for we are developing a project which the struct is same as cumulus, which also contains a full-node during running, and we start all task base on the runner that is coming from substrate service (https://github.com/paritytech/substrate/blob/master/bin/node-template/node/src/command.rs#L109). The log init at here.

[atenjin]

@koute this pr is yours, so maybe you can help me..

[bkchr]

Yeah, I already looked into this. Upstream changed some code. I identified the bug and planning to fix it today.

[bkchr]

tokio-rs/tracing#2165 here is the upstream pr.

[atenjin]

Cool work, thanks for @bkchr .

But I'm still confused why the log print is fine in substrate/cumulus/polkadot, but not work for a normal project... is there any config or code to trigger this? though you have fix it in the upstream crate, but I wanna know why this happen...

So can you explain it in a short way? thanks.

[bkchr]

Pin tracing-core to 0.1.26 in your project and it will work as before.

[jsdw]

Just as another data point; I rely on log output from substrate telling us which port the jsonrpc WS server starts on, and on current master (well, 1f0253c) those lines aren't printed at all (at least on my mac) (which means the subxt integration tests are stuck waiting for the port to connect on indefinitely).

I found that removing the the couple of .with_interest_cache lines in client/tracing/src/logging/mod.rs was enough to get this log line showing up again.

Def keen on seeing the fix for this land :)

Edit: It's a bit weirder than just removing the .with_interest_cache lines by the looks of it: A debug build (produced as a result of a cargo run) seems to work fine, but a release build does not.. strange!

[jsdw]

(since the upstream fix has been lingering for a while now, what would be the impact of removing the interest cache from substrate until it's in? I'd quite like to have the RPC port logging back if possible!)

[bkchr]

#11854 disables it for now.