sp-runtime-interface-test: Fix flaky test

[bkchr]

No description provided.

[ggwpez]

Ran it 5 times in parallel on Thread 1 with 1000 reps and no failure. But also no on master…
PS: Will re-test with release.

[michalkucharczyk]

Why the test was failing if run in parallel with other tests within single process?
Was tracing::subscriber::default overwritten by other test?

[michalkucharczyk]

Why the test was failing if run in parallel with other tests within single process? Was tracing::subscriber::default overwritten by other test?

It should be thread_local, hm, idk...

[ggwpez]

It should be thread_local, hm, idk...

Yes that seems to cause it. Running on one thread is fine, but on multiple it errors:
while cargo test --offline --release -p sp-runtime-interface-test -- --test-threads 1; do true; done
vs
while cargo test --offline --release -p sp-runtime-interface-test -- --test-threads 10; do true; done
So basically the opposite of #10479 😆

[michalkucharczyk]

I played with this a little. Seems that duplicating this line:

substrate/primitives/runtime-interface/test/src/lib.rs

Line 228 in 4c7866a

let _guard = tracing::subscriber::set_default(subscriber.clone());

works around the problem. The span also always contains 4 elements:

    "free_version_1",                              
    "blake2_256_version_1",
    "return_input_version_1",                                                                                          
    "malloc_version_1",

Without duplication the content seems to be random.

Does it look like some race-condition in registering the subscriber? If it is then we have hidden problem somewhere. Maybe not important, idk...

[michalkucharczyk]

One more observation: on my local computer only this pair of tests is causing failures (50%):

cargo test -- test_return_data test_tracing

[bkchr]

Does it look like some race-condition in registering the subscriber?

Yes this is the problem. I should have made the comment more "extended"

// Run in a different process to ensure that the `Span` is registered with our local
// `TracingSubscriber`.

This stuff is already tracked upstream tokio-rs/tracing#2436 tokio-rs/tracing#2411

We register the subcriber in a node early enough, at least I hope :D

substrate/client/cli/src/config.rs

Lines 632 to 649 in 53f5bef

	let mut logger = LoggerBuilder::new(self.log_filters()?);
	logger
	.with_log_reloading(self.enable_log_reloading()?)
	.with_detailed_output(self.detailed_log_output()?);
	if let Some(tracing_targets) = self.tracing_targets()? {
	let tracing_receiver = self.tracing_receiver()?;
	logger.with_profiling(tracing_receiver, tracing_targets);
	}
	if self.disable_log_color()? {
	logger.with_colors(false);
	}
	// Call hook for custom profiling setup.
	logger_hook(&mut logger, config);
	logger.init()?;