Skip to content

Allow initializing logger with additional tracing Layer #140969

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

Merged
merged 3 commits into from
Jun 14, 2025

Conversation

Stypox
Copy link
Contributor

@Stypox Stypox commented May 13, 2025

This PR adds functions to the rustc_log and rustc_driver_impl crates to allow initializing the logger with an additional tracing_subscriber::Layer. This will be used in Miri to save trace events to file using e.g. tracing-chrome's or tracing-tracy's Layers.

Additional context on the choice of signature can be found in this Zulip thread.

I re-exported tracing_subscriber::{Layer, Registry}; from rustc_log so that rustc_driver_impl can use them in the function signature without depending on tracing_subscriber directly. I did this to avoid copy-pasting the dependency line with all of the enabled features from the rustc_log to the rustc_driver_impl's Cargo.toml, which would have possibly led to redundancies and inconsistencies.

r? @RalfJung

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels May 13, 2025
@Stypox
Copy link
Contributor Author

Stypox commented May 13, 2025

I don't understand why the build fails, locally it works. The CI logs are 400MB, but here are the last few lines:

2025-05-13T14:08:30.4734576Z thread 'rustc' panicked at compiler/rustc_errors/src/lib.rs:702:17:
2025-05-13T14:08:30.4735249Z `trimmed_def_paths` called, diagnostics were expected but none were emitted. Use `with_no_trimmed_paths` for debugging. Backtraces are currently disabled: set `RUST_BACKTRACE=1` and re-run to see where it happened.
2025-05-13T14:08:30.4735388Z stack backtrace:
2025-05-13T14:08:30.4735786Z    0:     0x7fd7099338f0 - <<std[97575463abcf64a5]::sys::backtrace::BacktraceLock>::print::DisplayBacktrace as core[5399894434fbec0e]::fmt::Display>::fmt
2025-05-13T14:08:30.4735913Z    1:     0x7fd70998d87f - core[5399894434fbec0e]::fmt::write
2025-05-13T14:08:30.4736216Z    2:     0x7fd709927359 - <std[97575463abcf64a5]::sys::stdio::unix::Stderr as std[97575463abcf64a5]::io::Write>::write_fmt
2025-05-13T14:08:30.4736418Z    3:     0x7fd709933792 - <std[97575463abcf64a5]::sys::backtrace::BacktraceLock>::print
2025-05-13T14:08:30.4736605Z    4:     0x7fd709937ea8 - std[97575463abcf64a5]::panicking::default_hook::{closure#0}
2025-05-13T14:08:30.4736755Z    5:     0x7fd709937c42 - std[97575463abcf64a5]::panicking::default_hook
2025-05-13T14:08:30.4737255Z    6:     0x7fd704fe8814 - std[97575463abcf64a5]::panicking::update_hook::<alloc[55daa3099f06b8bf]::boxed::Box<rustc_driver_impl[b0c8405f4b17ef2d]::install_ice_hook::{closure#1}>>::{closure#0}
2025-05-13T14:08:30.4737431Z    7:     0x7fd709938a23 - std[97575463abcf64a5]::panicking::rust_panic_with_hook
2025-05-13T14:08:30.4737638Z    8:     0x7fd70993863e - std[97575463abcf64a5]::panicking::begin_panic_handler::{closure#0}
2025-05-13T14:08:30.4738114Z    9:     0x7fd709933f09 - std[97575463abcf64a5]::sys::backtrace::__rust_end_short_backtrace::<std[97575463abcf64a5]::panicking::begin_panic_handler::{closure#0}, !>
2025-05-13T14:08:30.4738268Z   10:     0x7fd70993824d - __rustc[764efdf202547135]::rust_begin_unwind
2025-05-13T14:08:30.4738418Z   11:     0x7fd704f94eb0 - core[5399894434fbec0e]::panicking::panic_fmt
2025-05-13T14:08:30.4738714Z   12:     0x7fd709435626 - <rustc_errors[32afd76b4a624ea]::DiagCtxtInner as core[5399894434fbec0e]::ops::drop::Drop>::drop
2025-05-13T14:08:30.4738967Z   13:     0x7fd70509df57 - core[5399894434fbec0e]::ptr::drop_in_place::<rustc_errors[32afd76b4a624ea]::DiagCtxt>
2025-05-13T14:08:30.4739250Z   14:     0x7fd70509fdaa - core[5399894434fbec0e]::ptr::drop_in_place::<rustc_session[d2bb1a5a081367de]::parse::ParseSess>
2025-05-13T14:08:30.4739599Z   15:     0x7fd70509ef04 - core[5399894434fbec0e]::ptr::drop_in_place::<rustc_interface[9f985b9f50803c10]::interface::Compiler>
2025-05-13T14:08:30.4740739Z   16:     0x7fd705097bdd - rustc_span[bfb9d5ad06f84935]::create_session_globals_then::<(), rustc_interface[9f985b9f50803c10]::util::run_in_thread_with_globals<rustc_interface[9f985b9f50803c10]::util::run_in_thread_pool_with_globals<rustc_interface[9f985b9f50803c10]::interface::run_compiler<(), rustc_driver_impl[b0c8405f4b17ef2d]::run_compiler::{closure#0}>::{closure#1}, ()>::{closure#0}, ()>::{closure#0}::{closure#0}::{closure#0}>
2025-05-13T14:08:30.4741865Z   17:     0x7fd70501f939 - std[97575463abcf64a5]::sys::backtrace::__rust_begin_short_backtrace::<rustc_interface[9f985b9f50803c10]::util::run_in_thread_with_globals<rustc_interface[9f985b9f50803c10]::util::run_in_thread_pool_with_globals<rustc_interface[9f985b9f50803c10]::interface::run_compiler<(), rustc_driver_impl[b0c8405f4b17ef2d]::run_compiler::{closure#0}>::{closure#1}, ()>::{closure#0}, ()>::{closure#0}::{closure#0}, ()>
2025-05-13T14:08:30.4743175Z   18:     0x7fd705022634 - <<std[97575463abcf64a5]::thread::Builder>::spawn_unchecked_<rustc_interface[9f985b9f50803c10]::util::run_in_thread_with_globals<rustc_interface[9f985b9f50803c10]::util::run_in_thread_pool_with_globals<rustc_interface[9f985b9f50803c10]::interface::run_compiler<(), rustc_driver_impl[b0c8405f4b17ef2d]::run_compiler::{closure#0}>::{closure#1}, ()>::{closure#0}, ()>::{closure#0}::{closure#0}, ()>::{closure#1} as core[5399894434fbec0e]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
2025-05-13T14:08:30.4743457Z   19:     0x7fd70993c275 - <std[97575463abcf64a5]::sys::pal::unix::thread::Thread>::new::thread_start
2025-05-13T14:08:30.4743547Z   20:     0x7fd70426bac3 - <unknown>
2025-05-13T14:08:30.4743623Z   21:     0x7fd7042fd850 - <unknown>
2025-05-13T14:08:30.4743696Z   22:                0x0 - <unknown>
2025-05-13T14:08:30.4743703Z 
2025-05-13T14:08:30.4744054Z error: the compiler unexpectedly panicked. this is a bug.
2025-05-13T14:08:30.4744073Z 
2025-05-13T14:08:30.4744376Z note: using internal features is not supported and expected to cause internal compiler errors when used incorrectly
2025-05-13T14:08:30.4744386Z 
2025-05-13T14:08:30.4744977Z note: please attach the file at `/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/compiler_builtins-0.1.159/rustc-ice-2025-05-13T14_08_10-13489.txt` to your bug report
2025-05-13T14:08:30.4744989Z 
2025-05-13T14:08:30.4746676Z note: compiler flags: --crate-type lib -C opt-level=3 -C embed-bitcode=no -C codegen-units=10000 -C debug-assertions=on -C strip=debuginfo -C symbol-mangling-version=v0 -Z unstable-options -Z macro-backtrace -C split-debuginfo=off -C prefer-dynamic -Z inline-mir -Z inline-mir-preserve-debug -Z mir_strip_debuginfo=locals-in-tiny-functions -C link-args=-Wl,-z,origin -C link-args=-Wl,-rpath,$ORIGIN/../lib -C embed-bitcode=yes -C force-frame-pointers=yes -Z crate-attr=doc(html_root_url="https://doc.rust-lang.org/nightly/") -Z binary-dep-depinfo -Z force-unstable-if-unmarked
2025-05-13T14:08:30.4746687Z 
2025-05-13T14:08:30.4746831Z note: some of the compiler flags provided by cargo are hidden
2025-05-13T14:08:30.4746901Z 
2025-05-13T14:08:30.4746986Z query stack during panic:
2025-05-13T14:08:30.4747058Z end of query stack
2025-05-13T14:08:30.4747177Z [RUSTC-TIMING] compiler_builtins test:false 11.033
2025-05-13T14:08:30.4747549Z �[1m�[31merror�[0m�[1m:�[0m could not compile `compiler_builtins` (lib)
2025-05-13T14:08:30.4747556Z 
2025-05-13T14:08:30.4747622Z Caused by:
2025-05-13T14:08:30.4777986Z   process didn't exit successfully: `/checkout/obj/build/bootstrap/debug/rustc /checkout/obj/build/bootstrap/debug/rustc --crate-name compiler_builtins --edition=2021 /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/compiler_builtins-0.1.159/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi,artifacts,future-incompat --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 -C embed-bitcode=no -C codegen-units=10000 --warn=unexpected_cfgs --check-cfg 'cfg(bootstrap)' --check-cfg 'cfg(target_os, values("cygwin"))' -C debug-assertions=on --cfg 'feature="c"' --cfg 'feature="compiler-builtins"' --cfg 'feature="default"' --cfg 'feature="rustc-dep-of-std"' --check-cfg 'cfg(docsrs,test)' --check-cfg 'cfg(feature, values("c", "compiler-builtins", "default", "mangled-names", "mem", "no-asm", "no-f16-f128", "rustc-dep-of-std", "unstable-public-internals"))' -C metadata=919ee2511425e9b1 -C extra-filename=-3b881170269c3765 --out-dir /checkout/obj/build/x86_64-unknown-linux-gnu/stage1-std/x86_64-unknown-linux-gnu/release/deps --target x86_64-unknown-linux-gnu -C strip=debuginfo -L dependency=/checkout/obj/build/x86_64-unknown-linux-gnu/stage1-std/x86_64-unknown-linux-gnu/release/deps -L dependency=/checkout/obj/build/x86_64-unknown-linux-gnu/stage1-std/release/deps --extern core=/checkout/obj/build/x86_64-unknown-linux-gnu/stage1-std/x86_64-unknown-linux-gnu/release/deps/librustc_std_workspace_core-1e0d89774044867a.rmeta --cap-lints allow -Csymbol-mangling-version=v0 '--check-cfg=cfg(feature,values(any()))' -Zunstable-options '--check-cfg=cfg(bootstrap)' -Zmacro-backtrace -Csplit-debuginfo=off -Cprefer-dynamic -Zinline-mir -Zinline-mir-preserve-debug -Zmir_strip_debuginfo=locals-in-tiny-functions -Clink-args=-Wl,-z,origin '-Clink-args=-Wl,-rpath,$ORIGIN/../lib' -Alinker-messages -Cembed-bitcode=yes -Cforce-frame-pointers=yes '-Zcrate-attr=doc(html_root_url="https://doc.rust-lang.org/nightly/")' -Z binary-dep-depinfo -L native=/checkout/obj/build/x86_64-unknown-linux-gnu/stage1-std/x86_64-unknown-linux-gnu/release/build/compiler_builtins-b88ca2fb4d6611a2/out -l static=compiler-rt --cfg f16_enabled --cfg f128_enabled --cfg intrinsics_enabled --cfg arch_enabled --cfg optimizations_enabled --cfg 'feature="unstable-intrinsics"' --cfg 'feature="mem-unaligned"' --cfg '__absvdi2="optimized-c"' --cfg '__absvsi2="optimized-c"' --cfg '__absvti2="optimized-c"' --cfg '__addvdi3="optimized-c"' --cfg '__addvsi3="optimized-c"' --cfg '__addvti3="optimized-c"' --cfg '__cmpdi2="optimized-c"' --cfg '__cmpti2="optimized-c"' --cfg '__divdc3="optimized-c"' --cfg '__divsc3="optimized-c"' --cfg '__ffsti2="optimized-c"' --cfg '__int_util="optimized-c"' --cfg '__muldc3="optimized-c"' --cfg '__mulsc3="optimized-c"' --cfg '__mulvdi3="optimized-c"' --cfg '__mulvsi3="optimized-c"' --cfg '__mulvti3="optimized-c"' --cfg '__negdf2="optimized-c"' --cfg '__negdi2="optimized-c"' --cfg '__negsf2="optimized-c"' --cfg '__negti2="optimized-c"' --cfg '__negvdi2="optimized-c"' --cfg '__negvsi2="optimized-c"' --cfg '__negvti2="optimized-c"' --cfg '__paritydi2="optimized-c"' --cfg '__paritysi2="optimized-c"' --cfg '__parityti2="optimized-c"' --cfg '__popcountdi2="optimized-c"' --cfg '__popcountsi2="optimized-c"' --cfg '__popcountti2="optimized-c"' --cfg '__subvdi3="optimized-c"' --cfg '__subvsi3="optimized-c"' --cfg '__subvti3="optimized-c"' --cfg '__ucmpdi2="optimized-c"' --cfg '__ucmpti2="optimized-c"' --check-cfg 'cfg(__ashldi3, values("optimized-c"))' --check-cfg 'cfg(__ashlsi3, values("optimized-c"))' --check-cfg 'cfg(__ashrdi3, values("optimized-c"))' --check-cfg 'cfg(__ashrsi3, values("optimized-c"))' --check-cfg 'cfg(__bswapsi2, values("optimized-c"))' --check-cfg 'cfg(__bswapdi2, values("optimized-c"))' --check-cfg 'cfg(__bswapti2, values("optimized-c"))' --check-cfg 'cfg(__divdi3, values("optimized-c"))' --check-cfg 'cfg(__divsi3, values("optimized-c"))' --check-cfg 'cfg(__divmoddi4, values("optimized-c"))' --check-cfg 'cfg(__divmodsi4, values("optimized-c"))' --check-cfg 'cfg(__divmodsi4, values("optimized-c"))' --check-cfg 'cfg(__divmodti4, values("optimized-c"))' --check-cfg 'cfg(__lshrdi3, values("optimized-c"))' --check-cfg 'cfg(__lshrsi3, values("optimized-c"))' --check-cfg 'cfg(__moddi3, values("optimized-c"))' --check-cfg 'cfg(__modsi3, values("optimized-c"))' --check-cfg 'cfg(__muldi3, values("optimized-c"))' --check-cfg 'cfg(__udivdi3, values("optimized-c"))' --check-cfg 'cfg(__udivmoddi4, values("optimized-c"))' --check-cfg 'cfg(__udivmodsi4, values("optimized-c"))' --check-cfg 'cfg(__udivsi3, values("optimized-c"))' --check-cfg 'cfg(__umoddi3, values("optimized-c"))' --check-cfg 'cfg(__umodsi3, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas16_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas16_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas16_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_cas16_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldadd8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldclr8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldeor8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_
ldset8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_ldset8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp1_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp1_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp1_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp1_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp2_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp2_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp2_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp2_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp4_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp4_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp4_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp4_acq_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp8_relax, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp8_acq, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp8_rel, values("optimized-c"))' --check-cfg 'cfg(__aarch64_swp8_acq_rel, values("optimized-c"))' --check-cfg 'cfg(target_feature, values("vis3"))' --check-cfg 'cfg(feature, values("checked"))' --check-cfg 'cfg(assert_no_panic)' --check-cfg 'cfg(f16_enabled)' --check-cfg 'cfg(f128_enabled)' --check-cfg 'cfg(thumb)' --check-cfg 'cfg(thumb_1)' --check-cfg 'cfg(intrinsics_enabled)' --check-cfg 'cfg(arch_enabled)' --check-cfg 'cfg(optimizations_enabled)' --check-cfg 'cfg(feature, values("unstable-public-internals"))' --check-cfg 'cfg(optimizations_enabled)' --check-cfg 'cfg(x86_no_sse)' --check-cfg 'cfg(feature, values("mem-unaligned"))' --check-cfg 'cfg(kernel_user_helpers)'` (exit status: 101)
2025-05-13T14:08:30.4778629Z Build completed unsuccessfully in 0:06:51
2025-05-13T14:08:30.4778720Z   local time: Tue May 13 14:08:21 UTC 2025
2025-05-13T14:08:30.4778852Z   network time: Tue, 13 May 2025 14:08:21 GMT
2025-05-13T14:08:30.4791852Z ##[error]Process completed with exit code 1.

@RalfJung
Copy link
Member

Looks like something in this PR is causing a lot more debug messages to be emitted. Some of those debug messages use the "def path formatting" machinery, which is expensive and so there are safeguards that this machinery is only called when there are actual compilation errors to emit -- which isn't the case here, so we ultimately get an ICE.

But the ICE isn't the actual problem, the actual problem is that debug tracing now seems to be enabled by default.

@@ -124,7 +135,8 @@ pub fn init_logger(cfg: LoggerConfig) -> Result<(), Error> {
Err(_) => {} // no wraptree
}

let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer);
let subscriber =
Registry::default().with(additional_tracing_layer).with(layer.with_filter(filter));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems to change the way the filter is applied, which might explain the explosion of debug messages?

@RalfJung
Copy link
Member

@rustbot author

@rustbot rustbot added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels May 23, 2025
@rustbot
Copy link
Collaborator

rustbot commented May 23, 2025

Reminder, once the PR becomes ready for a review, use @rustbot ready.

@rustbot

This comment has been minimized.

Stypox added 2 commits June 11, 2025 10:41
The previous method, where a layer would be passed directly,
required to pass a "no-op" layer when no custom layer was needed.
This should have in theory worked, however having a no-op layer
seems to change the way the tracing lib applies filters internally,
leading to some debug!() being printed despite them being out of
the minimum level for the filters. Note however that this behavior
was very inconsistent, and e.g. some debug!() would get printed
and some others wouldn't, for no apparent reason.
@Stypox
Copy link
Contributor Author

Stypox commented Jun 11, 2025

@rustbot ready

Sorry for the late response. I went down a rabbit hole trying to figure out why tracing was emitting a lot of debug messages even though they should have been filtered out by the EnvFilter. The strange thing is, only some of the debug!() calls end up in stderr, while some others don't, and it seems to happen arbitrarily (see below).

I still haven't got to the culprit, but I have a feeling that it might be due to the default implementation of Layer::enabled() used for Identity which always returns true, combined with the Registry which thinks that since one of its layers is enabled it needs to process events. However, take this with a grain of salt, as this doesn't really explain why some debug!() appear in stderr and some others don't.

Anyway, for now I changed the code in this PR to use Registry::default().with(layer.with_filter(filter)) instead of Identity when no custom layer is needed, which seems to behave correctly despite being slightly different than the original Registry::default().with(filter).with(layer). Note that Registry::default() is the result of a closure passed as argument (to avoid code duplication), and if a custom layer is needed, the closure might e.g. return Registry::default().with(custom_layer). I tested this interface in Miri and it plugs in correctly.

Example of debug!() behaving arbitrarily + bootstrap config

This is file compiler/rustc_hir/src/definitions.rs, the first place during the build where debug!() starts to misbehave. As you can see, the two lines are almost the same. Even after expanding the macros, the only difference between the two expansions is a format_args!() down the line which does not explain why one of the two would be enabled and the other not.

// This line will print "create_def(parent=, data=TypeNs("core"))"
debug!("create_def(parent={}, data={data:?})", self.def_path(parent).to_string_no_crate_verbose());
// This line gets filtered out (`parent.to_def_id().index.as_u32()` is just some dummy code I added)
debug!("create_def(parent={}, data={data:?})", parent.to_def_id().index.as_u32());

I am building with ./x build std --stage=1 and bootstrap.toml has these contents (taken from the CI):

# See bootstrap.example.toml for documentation of available options
#
profile = "dist"  # Includes one of the default files in src/bootstrap/defaults
change-id = 140732

# '--set', 'build.optimized-compiler-builtins',
build.configure-args = ['--build=x86_64-unknown-linux-gnu', '--save-toolstates=/tmp/toolstate/toolstates.json', '--enable-new-symbol-mangling', '--set', 'build.print-step-timings', '--enable-verbose-tests', '--set', 'build.metrics', '--enable-verbose-configure', '--enable-sccache', '--disable-manage-submodules', '--enable-locked-deps', '--enable-cargo-native-static', '--set', 'rust.codegen-units-std=1', '--set', 'dist.compression-profile=balanced', '--dist-compression-formats=xz', '--disable-dist-src', '--release-channel=nightly', '--enable-debug-assertions', '--enable-overflow-checks', '--enable-llvm-assertions', '--set', 'rust.verify-llvm-ir', '--set', 'rust.codegen-backends=llvm,cranelift', '--set', 'llvm.download-ci-llvm=if-unchanged', '--set', 'gcc.download-ci-gcc=true', '--set', 'rust.download-rustc=if-unchanged']
build.build          = "x86_64-unknown-linux-gnu"
rust.new-symbol-mangling = true
build.print-step-timings = true
build.metrics        = true
rust.codegen-units-std = 1
build.optimized-compiler-builtins = false
rust.verify-llvm-ir  = true
rust.codegen-backends = [ "llvm", "cranelift" ]
gcc.download-ci-gcc  = true
rust.verbose-tests   = true
build.submodules     = false
build.locked-deps    = true
build.cargo-native-static = true
dist.compression-formats = ['xz']
rust.dist-src        = false
rust.debug-assertions = true
rust.overflow-checks = true
llvm.assertions      = true
llvm.download-ci-llvm = true

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Jun 11, 2025
@Stypox
Copy link
Contributor Author

Stypox commented Jun 11, 2025

Actually, after further testing in Miri, I noticed that adding any custom layer (e.g. by calling rustc_driver::init_logger_with_additional_layer(early_dcx, rustc_logger_config(), || Registry::default().with(chrome_layer))) results in a lot of trace/debug messages going to stderr even though they should be disabled. This is only visible when building with the bootstrap config that I attached above, but is not visible when building with profile = "tools" or when doing an out-of-tree build from the Miri repo, because in those cases the trace/debug statements will be disabled and removed at compile time. Let me know if I should look deeper in the tracing crate to understand why this strange behavior happens, or if for now we can keep the current state (which won't affect the compiler but just Miri when built with the "tracing" feature). Regardless of this, I will open an issue on the tracing crate, possibly with a minimum reproducible example (which I couldn't obtain so far).

@@ -124,7 +150,7 @@ pub fn init_logger(cfg: LoggerConfig) -> Result<(), Error> {
Err(_) => {} // no wraptree
}

let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer);
let subscriber = build_subscriber().with(layer.with_filter(filter));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So making this .with(filter).with(layer) as before does not work?

This is the one part of the PR I am not sure about, since I don't know much about tracing.
Cc @oli-obk

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, because it will apply the filter to every layer, including any custom layer we might add

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So despite the fact that the filter is added after the custom layers, it takes effect before them, preventing events from reaching them...?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wow, that's not what I expected.^^

@RalfJung
Copy link
Member

Actually, after further testing in Miri, I noticed that adding any custom layer (e.g. by calling rustc_driver::init_logger_with_additional_layer(early_dcx, rustc_logger_config(), || Registry::default().with(chrome_layer))) results in a lot of trace/debug messages going to stderr even though they should be disabled. This is only visible when building with the bootstrap config that I attached above, but is not visible when building with profile = "tools" or when doing an out-of-tree build from the Miri repo, because in those cases the trace/debug statements will be disabled and removed at compile time. Let me know if I should look deeper in the tracing crate to understand why this strange behavior happens, or if for now we can keep the current state (which won't affect the compiler but just Miri when built with the "tracing" feature). Regardless of this, I will open an issue on the tracing crate, possibly with a minimum reproducible example (which I couldn't obtain so far).

If it doesn't happen from this PR alone, I'm fine with landing it. However it'd still be worth finding a minimal example for a bugreport.

@Stypox
Copy link
Contributor Author

Stypox commented Jun 12, 2025

@rustbot ready

Thank you for the review, I removed the pub use and added documentation (sorry for not adding it before, I was not sure if we were to keep this structure in the end).

@RalfJung
Copy link
Member

This LGTM from my side. @oli-obk do you want to take a look or should I just r+?
(Worst-case, if there's problems we revert.)

@oli-obk
Copy link
Contributor

oli-obk commented Jun 13, 2025

@bors r=RalfJung,oli-obk

@bors
Copy link
Collaborator

bors commented Jun 13, 2025

📌 Commit 781baaf has been approved by RalfJung,oli-obk

It is now in the queue for this repository.

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jun 13, 2025
@RalfJung
Copy link
Member

@bors rollup

bors added a commit that referenced this pull request Jun 14, 2025
Rollup of 16 pull requests

Successful merges:

 - #140969 (Allow initializing logger with additional tracing Layer)
 - #141352 (builtin dyn impl no guide inference)
 - #142046 (add Vec::peek_mut)
 - #142273 (tests: Minicore `extern "gpu-kernel"` feature test)
 - #142302 (Rework how the disallowed qualifier in function type diagnostics are generated)
 - #142405 (Don't hardcode the intrinsic return types twice in the compiler)
 - #142434 ( Pre-install JS dependencies in tidy Dockerfile)
 - #142439 (doc: mention that intrinsics should not be called in user code)
 - #142441 (Delay replacing escaping bound vars in `FindParamInClause`)
 - #142449 (Require generic params for const generic params)
 - #142452 (Remove "intermittent" wording from `ReadDir`)
 - #142459 (Remove output helper bootstrap)
 - #142460 (cleanup search graph impl)
 - #142461 (compiletest: Clarify that `--no-capture` is needed with `--verbose`)
 - #142475 (Add platform support docs & maintainers for *-windows-msvc)
 - #142480 (tests: Convert two handwritten minicores to add-core-stubs)

r? `@ghost`
`@rustbot` modify labels: rollup
@bors bors merged commit 94dfe49 into rust-lang:master Jun 14, 2025
10 checks passed
@rustbot rustbot added this to the 1.89.0 milestone Jun 14, 2025
rust-timer added a commit that referenced this pull request Jun 14, 2025
Rollup merge of #140969 - Stypox:logger-layer, r=RalfJung,oli-obk

Allow initializing logger with additional tracing Layer

This PR adds functions to the `rustc_log` and `rustc_driver_impl` crates to allow initializing the logger with an additional `tracing_subscriber::Layer`. This will be used in Miri to save trace events to file using e.g. [`tracing-chrome`](https://github.com/thoren-d/tracing-chrome)'s or [`tracing-tracy`](https://github.com/nagisa/rust_tracy_client)'s `Layer`s.

Additional context on the choice of signature can be found in [this Zulip thread](https://rust-lang.zulipchat.com/#narrow/channel/131828-t-compiler/topic/Adding.20a.20dependency.20to.20Miri.20that.20depends.20on.20a.20rustc.20dep/near/515707776).

I re-exported `tracing_subscriber::{Layer, Registry};` from `rustc_log` so that `rustc_driver_impl` can use them in the function signature without depending on `tracing_subscriber` directly. I did this to avoid copy-pasting the dependency line with all of the enabled features from the `rustc_log` to the `rustc_driver_impl`'s Cargo.toml, which would have possibly led to redundancies and inconsistencies.

r? `@RalfJung`
@RalfJung RalfJung mentioned this pull request Jun 14, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants