PVF: Logging in PVF workers has no effect

[mrcnski]

ISSUE

Overview

See title. In the past to do print debugging from the workers I would write to a tmp file.

How does gum work beneath the hood? @sandreim any tips?

Steps to reproduce

1. Add sp_tracing::init_for_tests(); to execute_good_block_on_parent.
2. Run cargo test execute_good_block_on_parent -- --nocapture.
3. Confirm that worker logs do not appear, i.e.

gum::debug!(target: LOG_TARGET, %worker_pid, "starting pvf worker ({})", debug_id);

in worker_event_loop does not do anything.

[s0me0ne-unkn0wn]

Are you testing your version with the separate worker or the current master? I'm pretty sure logging was working before. Do you remember you were testing this? Point 10 in that list is a message coming from the worker itself from inside the worker_event_loop, and we both surely saw that message. So if it was broken, it happened later.

[s0me0ne-unkn0wn]

Run cargo test execute_good_block_on_parent -- --nocapture.

Haven't you forgotten to set up RUST_LOG environment variable properly?

[mrcnski]

Run cargo test execute_good_block_on_parent -- --nocapture.

Haven't you forgotten to set up RUST_LOG environment variable properly?

Ah, RUST_LOG=parachain::pvf-worker=trace did the trick. I was only seeing pvf logs even though I ran sp_tracing::init_for_tests(); in pvf-worker. 👀 So maybe that's the function that needs fixing. Quite sure I've run into this before as well, somehow.

Are you testing your version with the separate worker or the current master?

Separate worker (#7101).

[bkchr]

So maybe that's the function that needs fixing. Quite sure I've run into this before as well, somehow.

Nothing needs to be fixed. You are initializing the logger with TRACE logs in the test process. The test process is spawning the worker executable that doesn't know anything about your logging setup in the test process. As @s0me0ne-unkn0wn said, you need to set RUST_LOG as env variables are inherited to child processes.