Skip to content

Add support for SpanTrace capture in ICE reports #103993

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.

Sign up for GitHub

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

Closed
wants to merge 1 commit into from
Closed

Add support for SpanTrace capture in ICE reports #103993

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 29 additions & 11 deletions Cargo.lock
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3323,6 +3323,16 @@ version = "0.3.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "61807f77802ff30975e01f4f071c8ba10c022052f98b3294119f3e615d13e5be"

[[package]]
name = "nu-ansi-term"
version = "0.46.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
dependencies = [
"overload",
"winapi",
]

[[package]]
name = "num-integer"
version = "0.1.43"
Expand Down Expand Up @@ -3500,6 +3510,12 @@ dependencies = [
"winapi",
]

[[package]]
name = "overload"
version = "0.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"

[[package]]
name = "owo-colors"
version = "3.5.0"
Expand Down Expand Up @@ -4588,6 +4604,7 @@ dependencies = [
"rustc_ty_utils",
"serde_json",
"tracing",
"tracing-error",
"winapi",
]

Expand Down Expand Up @@ -4919,6 +4936,7 @@ dependencies = [
"rustc_span",
"tracing",
"tracing-core",
"tracing-error",
"tracing-subscriber",
"tracing-tree",
]
Expand Down Expand Up @@ -5742,9 +5760,9 @@ dependencies = [

[[package]]
name = "sharded-slab"
version = "0.1.1"
version = "0.1.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "79c719719ee05df97490f80a45acfc99e5a30ce98a1e4fb67aee422745ae14e3"
checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
dependencies = [
"lazy_static",
]
Expand Down Expand Up @@ -6387,9 +6405,9 @@ dependencies = [

[[package]]
name = "tracing-core"
version = "0.1.28"
version = "0.1.30"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7"
checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a"
dependencies = [
"once_cell",
"valuable",
Expand All @@ -6407,9 +6425,9 @@ dependencies = [

[[package]]
name = "tracing-log"
version = "0.1.2"
version = "0.1.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3"
checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
dependencies = [
"lazy_static",
"log",
Expand All @@ -6418,14 +6436,14 @@ dependencies = [

[[package]]
name = "tracing-subscriber"
version = "0.3.3"
version = "0.3.16"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "245da694cc7fc4729f3f418b304cb57789f1bed2a78c575407ab8a23f53cb4d3"
checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70"
dependencies = [
"ansi_term",
"lazy_static",
"matchers",
"parking_lot 0.11.2",
"nu-ansi-term",
"once_cell",
"parking_lot 0.12.1",
"regex",
"sharded-slab",
"smallvec",
Expand Down
4 changes: 2 additions & 2 deletions compiler/rustc_driver_impl/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,7 @@ rustc_interface = { path = "../rustc_interface" }
rustc_ast = { path = "../rustc_ast" }
rustc_span = { path = "../rustc_span" }
rustc_hir_analysis = { path = "../rustc_hir_analysis" }
tracing-error = "0.2.0"

[target.'cfg(unix)'.dependencies]
libc = "0.2"
Expand All @@ -60,5 +61,4 @@ winapi = { version = "0.3", features = ["consoleapi", "debugapi", "processenv"]
[features]
llvm = ['rustc_interface/llvm']
max_level_info = ['rustc_log/max_level_info']
rustc_use_parallel_compiler = ['rustc_data_structures/rustc_use_parallel_compiler', 'rustc_interface/rustc_use_parallel_compiler',
'rustc_middle/rustc_use_parallel_compiler']
rustc_use_parallel_compiler = ['rustc_data_structures/rustc_use_parallel_compiler', 'rustc_interface/rustc_use_parallel_compiler', 'rustc_middle/rustc_use_parallel_compiler']
15 changes: 12 additions & 3 deletions compiler/rustc_driver_impl/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1245,6 +1245,15 @@ pub fn report_ice(info: &panic::PanicInfo<'_>, bug_report_url: &str) {

interface::try_print_query_stack(&handler, num_frames);

let spantrace = tracing_error::SpanTrace::capture().to_string();
if !spantrace.is_empty() {
eprintln!("SpanTrace:\n{}", spantrace);
} else {
eprintln!(
"note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace"
);
}

#[cfg(windows)]
unsafe {
if env::var("RUSTC_BREAK_ON_ICE").is_ok() {
Expand Down Expand Up @@ -1273,14 +1282,14 @@ pub fn install_ice_hook() {
/// This allows tools to enable rust logging without having to magically match rustc's
/// tracing crate version.
pub fn init_rustc_env_logger() {
init_env_logger("RUSTC_LOG");
init_env_logger("RUSTC_LOG", "RUSTC_ICE_LOG");
}

/// This allows tools to enable rust logging without having to magically match rustc's
/// tracing crate version. In contrast to `init_rustc_env_logger` it allows you to choose an env var
/// other than `RUSTC_LOG`.
pub fn init_env_logger(env: &str) {
if let Err(error) = rustc_log::init_env_logger(env) {
pub fn init_env_logger(env: &str, ice_env: &str) {
if let Err(error) = rustc_log::init_env_logger(env, ice_env) {
early_error(ErrorOutputType::default(), &error.to_string());
}
}
Expand Down
3 changes: 2 additions & 1 deletion compiler/rustc_log/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,9 +5,10 @@ edition = "2021"

[dependencies]
tracing = "0.1.28"
tracing-subscriber = { version = "0.3.3", default-features = false, features = ["fmt", "env-filter", "smallvec", "parking_lot", "ansi"] }
tracing-subscriber = { version = "0.3.16", default-features = false, features = ["registry", "fmt", "env-filter", "smallvec", "parking_lot", "ansi"] }
tracing-tree = "0.2.0"
tracing-core = "0.1.28"
tracing-error = "0.2.0"

[dev-dependencies]
rustc_span = { path = "../rustc_span" }
Expand Down
25 changes: 20 additions & 5 deletions compiler/rustc_log/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,20 +45,32 @@
use std::env::{self, VarError};
use std::fmt::{self, Display};
use std::io::{self, IsTerminal};
use std::str::FromStr;
use tracing_core::{Event, Subscriber};
use tracing_subscriber::filter::{Directive, EnvFilter, LevelFilter};
use tracing_subscriber::fmt::{
format::{self, FormatEvent, FormatFields},
FmtContext,
};
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::Layer;

pub fn init_env_logger(env: &str) -> Result<(), Error> {
let filter = match env::var(env) {
/// In contrast to `init_rustc_env_logger` this allows you to choose an env var
/// other than `RUSTC_LOG`.
pub fn init_env_logger(env: &str, ice_env: &str) -> Result<(), Error> {
let log_filter = match env::var(env) {
Ok(env) => EnvFilter::new(env),
_ => EnvFilter::default().add_directive(Directive::from(LevelFilter::WARN)),
};

let error_filter = match env::var(ice_env) {
Copy link
Contributor

Choose a reason for hiding this comment

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

I wonder if we should just enable all levels by default for the spantrace. if people see it as a problem we can always offer ways to reduce it. My use case would always unconditionally enable trace spans for ICEs.

Copy link
Member Author

Choose a reason for hiding this comment

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

I was just worried about causing perf issues, but that seems easy enough to test

Copy link
Member Author

Choose a reason for hiding this comment

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

Alright, so I tried this a while back and ran into some errors and ended up putting it down. Picked it back up, rebased, dealt with merge conflicts and got it working again and looked at the error in some more detail with @jyn514 and we came to the conclusion that it seems like it's a pre-existing error that I'm triggering but not causing. Jyn felt like they recall encountering the same error in the past.

I want to do some more testing to verify this theory and see if I can repro the issue without having tracing_error installed by enabling TRACE capture on all spans with a custom registry layer. I recall testing this in november and it works at trace level when reporting errors during compilation of other crates, it's only when it's compiling itself with trace enabled on spans that it's running into a panic from a diagnostic not being emitted in time.

Copy link
Contributor

Choose a reason for hiding this comment

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

oh, then let's land it as is, so we can debug it on master.

Ok(env) => tracing::Level::from_str(&env).unwrap(),
_ => tracing::Level::WARN,
};
let error_filter = tracing_subscriber::filter::filter_fn(move |metadata| {
metadata.is_span() && metadata.level() <= &error_filter
});

let color_logs = match env::var(String::from(env) + "_COLOR") {
Ok(value) => match value.as_ref() {
"always" => true,
Expand All @@ -75,7 +87,7 @@ pub fn init_env_logger(env: &str) -> Result<(), Error> {
Some(v) => &v != "0",
};

let layer = tracing_tree::HierarchicalLayer::default()
let log_layer = tracing_tree::HierarchicalLayer::default()
.with_writer(io::stderr)
.with_indent_lines(true)
.with_ansi(color_logs)
Expand All @@ -84,9 +96,12 @@ pub fn init_env_logger(env: &str) -> Result<(), Error> {
.with_verbose_entry(verbose_entry_exit)
.with_indent_amount(2);
#[cfg(parallel_compiler)]
let layer = layer.with_thread_ids(true).with_thread_names(true);
let log_layer = log_layer.with_thread_ids(true).with_thread_names(true);
let error_layer = tracing_error::ErrorLayer::default();
let subscriber = tracing_subscriber::Registry::default()
.with(error_layer.with_filter(error_filter))
.with(log_layer.with_filter(log_filter));

let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer);
match env::var(format!("{env}_BACKTRACE")) {
Ok(str) => {
let fmt_layer = tracing_subscriber::fmt::layer()
Expand Down
1 change: 1 addition & 0 deletions compiler/rustc_session/src/session.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -677,6 +677,7 @@ impl Session {
|| self.opts.unstable_opts.unpretty.is_some()
|| self.opts.output_types.contains_key(&OutputType::Mir)
|| std::env::var_os("RUSTC_LOG").is_some()
|| std::env::var_os("RUSTC_ICE_LOG").is_some()
Copy link
Member Author

Choose a reason for hiding this comment

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

@jyn514 identified the issue with defaulting the log level to TRACE as likely related to (and worked around by) this bit of logic. I don't know if we will want the default output to start to include SpanTraces or not but I'm leaning towards defaulting them to off for now. We can always bump Span levels up to WARN if they're super relevant and we want them to show up all the time.

This way we can leave actually increasing the usage of this functionality to later PRs where it can be based on more practical usage experience.

{
return;
}
Expand Down
2 changes: 1 addition & 1 deletion src/librustdoc/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -167,7 +167,7 @@ pub fn main() {
// `debug_logging = true` is because all rustc logging goes to its version of tracing (the one
// in the sysroot), and all of rustdoc's logging goes to its version (the one in Cargo.toml).
init_logging();
rustc_driver::init_env_logger("RUSTDOC_LOG");
rustc_driver::init_env_logger("RUSTDOC_LOG", "RUSTDOC_ICE_LOG");

let exit_code = rustc_driver::catch_with_exit_code(|| match get_args() {
Some(args) => main_args(&args),
Expand Down
11 changes: 11 additions & 0 deletions src/tools/tidy/src/deps.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -167,10 +167,12 @@ const PERMITTED_RUSTC_DEPENDENCIES: &[&str] = &[
"memmap2",
"memoffset",
"miniz_oxide",
"nu-ansi-term",
"num_cpus",
"object",
"odht",
"once_cell",
"overload",
"parking_lot",
"parking_lot_core",
"pathdiff",
Expand Down Expand Up @@ -237,6 +239,7 @@ const PERMITTED_RUSTC_DEPENDENCIES: &[&str] = &[
"tracing-log",
"tracing-subscriber",
"tracing-tree",
"tracing-error",
"twox-hash",
"type-map",
"typenum",
Expand Down Expand Up @@ -264,6 +267,14 @@ const PERMITTED_RUSTC_DEPENDENCIES: &[&str] = &[
"winapi-i686-pc-windows-gnu",
"winapi-util",
"winapi-x86_64-pc-windows-gnu",
"windows-sys",
"windows_aarch64_msvc",
"windows_aarch64_gnullvm",
"windows_i686_gnu",
"windows_i686_msvc",
"windows_x86_64_gnu",
"windows_x86_64_gnullvm",
"windows_x86_64_msvc",
"writeable",
// this is a false-positive: it's only used by rustfmt, but because it's enabled through a
// feature, tidy thinks it's used by rustc as well.
Expand Down
1 change: 1 addition & 0 deletions tests/ui/associated-inherent-types/bugs/ice-substitution.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,3 +4,4 @@ query stack during panic:
#0 [typeck] type-checking `weird`
#1 [typeck_item_bodies] type-checking all item bodies
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
1 change: 1 addition & 0 deletions tests/ui/chalkify/bugs/async.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
// edition:2021
// known-bug: unknown
// unset-rustc-env:RUST_BACKTRACE
// rustc-env:RUSTC_ICE_LOG=trace
Copy link
Member Author

Choose a reason for hiding this comment

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

I wanted to see one that actually captured some SpanTrace output just to make sure it's working and i understood why the other ones are empty.

I'm going to add some logic to skip adding the "SpanTrace:\n" bit if the SpanTrace itself is empty. I'm also wondering if I should add some cfg directives to set the RUSTC_ICE_LOG level to trace when we're not building rustc itself but I need to investigate how that would work.

Copy link
Member Author

@yaahc yaahc Mar 16, 2023 •
edited
Loading

Choose a reason for hiding this comment

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

This test suddenly started failing after rebasing on master and I do not yet know why

I tried building latest master to see if it was a bug that just happened to get through and it failed two entirely unrelated tests instead...

// compile-flags:-Z trait-solver=chalk
// error-pattern:internal compiler error
// failure-status:101
Expand Down
2 changes: 2 additions & 0 deletions tests/ui/chalkify/bugs/async.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,8 @@ LL | async fn foo(x: u32) -> u32 {
#8 [check_mod_item_types] checking item types in top-level module
#9 [analysis] running analysis passes on this crate
end of query stack
SpanTrace:

error: aborting due to 2 previous errors

For more information about this error, try `rustc --explain E0277`.
1 change: 1 addition & 0 deletions tests/ui/consts/const-eval/const-eval-query-stack.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,3 +11,4 @@ query stack during panic:
#3 [lint_mod] linting top-level module
#4 [analysis] running analysis passes on this crate
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
1 change: 1 addition & 0 deletions tests/ui/impl-trait/issues/issue-86800.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,3 +22,4 @@ query stack during panic:
#1 [check_mod_item_types] checking item types in top-level module
#2 [analysis] running analysis passes on this crate
end of query stack

1 change: 1 addition & 0 deletions tests/ui/impl-trait/normalize-tait-in-const.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,5 +4,6 @@ query stack during panic:
#0 [eval_to_allocation_raw] const-evaluating + checking `BAR`
#1 [eval_to_const_value_raw] simplifying constant for the type system `BAR`
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
error: aborting due to previous error

1 change: 1 addition & 0 deletions tests/ui/layout/valid_range_oob.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,3 +4,4 @@ query stack during panic:
#0 [layout_of] computing layout of `Foo`
#1 [eval_to_allocation_raw] const-evaluating + checking `FOO`
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
1 change: 1 addition & 0 deletions tests/ui/mir/validate/storage-live.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,3 +11,4 @@ query stack during panic:
#0 [mir_const] preparing `multiple_storage` for borrow checking
#1 [mir_promoted] processing MIR for `multiple_storage`
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
1 change: 1 addition & 0 deletions tests/ui/panics/default-backtrace-ice.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,3 +15,4 @@ error: the compiler unexpectedly panicked. this is a bug.
query stack during panic:
#0 [resolver_for_lowering] getting the resolver for lowering
end of query stack

1 change: 1 addition & 0 deletions tests/ui/treat-err-as-bug/delay_span_bug.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,3 +9,4 @@ error: the compiler unexpectedly panicked. this is a bug.
query stack during panic:
#0 [trigger_delay_span_bug] triggering a delay span bug
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace
1 change: 1 addition & 0 deletions tests/ui/treat-err-as-bug/err.stderr
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,3 +10,4 @@ query stack during panic:
#0 [eval_to_allocation_raw] const-evaluating + checking `C`
#1 [eval_to_allocation_raw] const-evaluating + checking `C`
end of query stack
note: run with `RUSTC_ICE_LOG=trace` environment variable to display a SpanTrace