On the Ferrocene team, we deal with a lot of tricky problems, as Aïssata Maïga describes in her recent RustWeek talk, The trials of qualifying Rust.
This post dives into a particularly thorny problem that crashed my computer, took me over a week to debug, and ended up being 3 different bugs combining into one very unhelpful error.
It would be nice to have an error message …
Ferrocene regularly merges in changes from the upstream Rust compiler. A few months ago, we encountered the following error in CI after a merge:
test [ui] tests/ui/delegation/bad-resolve.rs has been running for a long time
[ui] tests/ui/delegation/bad-resolve.rs ... F
test [ui] tests/ui/delegation/body-identity-glob.rs has been running for a long time
Too long with no output (exceeded 20m0s): context deadline exceeded
I took a look at this on a local build of the compiler. I do a lot of my work on "devpods": these are similar to the dev-desktops of the upstream Rust project, but hosted on Ferrocene's private infrastructure, and with custom Docker images that set up a lot of the build requirements beforehand. Unlike dev-desktops, they're Kubernetes pods, not full virtual machines. I like them because they're much faster than my local MacBook Air, and also can run x86 natively rather than through emulation.
I started the test without a problem, wandered away for lunch, and came back to this error:
ci@devpod-pr-rotation-0 ~/ferrocene (automation/pull-upstream-HEAD/mscy1uah)> Connection to bastion.devpods.infra.ferrous-systems.net closed by remote host.
client_loop: send disconnect: Broken pipe
Connection to devpod-pr-rotation-jynn.ferrocene-devpods.svc.cluster.local closed by remote host.
Connection to devpod-pr-rotation-jynn.ferrocene-devpods.svc.cluster.local closed.
Well, that's odd. I tried to reconnect:
$ ssh devpod-pr-rotation-jynn.ferrocene-devpods.svc.cluster.local -J bastion.devpods.infra.ferrous-systems.net
channel 0: open failed: connect failed: Connection refused
stdio forwarding failed
Connection closed by UNKNOWN port 65535
That's really odd! That's the error I get when DNS resolution doesn't work within the bastion container. At that point I started looking at the state of the devpod:
$ kubectl get pods
devpod-pr-rotation-0 0/1 OOMKilled 0 16d
… oh.
Well! Clearly something here has gone very wrong. I couldn't get the pod back; to bring it back up I had to run kubectl --namespace ferrocene-devpods delete pod devpod-pr-rotation-0, which deletes the whole container, including the data on disk. Welp. There goes an hour.
What even triggers the problem?
I got myself a cozy little dev loop:
$ git fetch origin eb655d5b3f940faf9b25749e84efed1b79944e98 && git checkout FETCH_HEAD
# Create a build cache so we can set a reasonable timeout.
$ ./x test tests/ui/diagnostic-width
# `timeout` is to make sure that we don't immediately crash the devpod again.
# `--no-capture` is to see output from RUSTC_LOG.
# `--force-rerun` is to rerun the test even if neither the compiler nor the test have changed,
# since compiletest doesn't count RUSTC_LOG as invalidating the cache.
# `--keep-stage-std` is to avoid rebuilding the standard library when the compiler changes,
# since none of our changes affect code that doesn't use delegation.
$ timeout 10 ./x test tests/ui/delegations/bad-resolve.rs —-force-rerun --verbose --no-capture --keep-stage-std=1
and minimized the crash to the following Rust source code:
#![feature(fn_delegation)]
#![allow(incomplete_features)]
trait Trait {
type Type;
fn bar() {}
}
struct F;
impl Trait for F {
type Type = i32;
}
struct S(F);
impl Trait for S {
reuse <F as Trait>::bar;
}
fn main() {}
The reuse syntax here is part of the unstable fn_delegation feature, which rustc notes is incomplete and buggy. On upstream rustc, this program gives the following error:
On Ferrocene, it hangs indefinitely without output.
First I tried cranking debug logging all the way up to the max:
{ \
RUSTC_LOG=debug,rustc_middle::ty::print=info,rustc_span=info,rustc_parse=info \
timeout 5 rustc +ferrocene ./bad-resolve.rs || true
} 2>&1 | less
and got this output towards the end:
0ms DEBUG rustc_ast_lowering return=HirId(DefId(0:14 ~ bad_resolve[627f]::{impl#1}::bar).9)
0ms DEBUG rustc_middle::middle::codegen_fn_attrs::ferrocene parent=DefId(0:3 ~ bad_resolve[627f]::Trait), kind=Trait
That's promising! This ferrocene module is one we just added last week; it's very possible that it still has a few bugs.
I HAVE NO TOOLS BECAUSE I'VE DESTROYED MY TOOLS WITH MY TOOLS
I suspected from the start that this was infinite recursion somehow, so I pulled out GDB. My normal trick for infinite recursion is just to Ctrl-C it after a few seconds: GDB will automatically drop into an interactive session when it gets SIGINT, even if you haven't set a breakpoint.
$ gdb --quiet --args $(rustup which rustc --toolchain ferrocene) ./bad-resolve.rs
Reading symbols from /home/ci/.rustup/toolchains/f1/bin/rustc...
(gdb) run
Starting program: /home/ci/ferrocene/build/x86_64-unknown-linux-gnu/stage1/bin/rustc bad-resolve.rs
[New Thread 0x7fc650170700 (LWP 620169)]
[New Thread 0x7fc64ff6f700 (LWP 620170)]
[New Thread 0x7fc64f76b700 (LWP 620171)]
^C
Thread 1 "rustc" received signal SIGINT, Interrupt.
__pthread_clockjoin_ex (threadid=140489721837312, thread_return=0x0, clockid=<optimized out>, abstime=<optimized out>, block=<optimized out>)
at pthread_join_common.c:145
145 pthread_join_common.c: No such file or directory.
(gdb) info threads
Id Target Id Frame
* 1 Thread 0x7fc650179580 (LWP 620165) "rustc" __pthread_clockjoin_ex (threadid=140489721837312, thread_return=0x0, clockid=<optimized out>,
abstime=<optimized out>, block=<optimized out>) at pthread_join_common.c:145
2 Thread 0x7fc650170700 (LWP 620169) "ctrl-c" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0,
futex_word=0x7fc660b60498 <_RNvNtNtNtCsia3Q7nEBThM_5ctrlc8platform4unix14implementation9SEMAPHORE>) at ../sysdeps/nptl/futex-internal.h:320
3 Thread 0x7fc64ff6f700 (LWP 620170) "rustc" 0x00007fc65e63835f in new<(core::option::Option<rustc_span::symbol::Symbol>, rustc_middle::query::pl
umbing::ActiveKeyStatus)> () at /home/ci/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hashbrown-0.16.1/src/raw/mod.rs:3584
4 Thread 0x7fc64f76b700 (LWP 620171) "rustc" syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:3
Thread 1 just points to <rustc_interface::util::run_in_thread_pool_with_globals::<rustc_interface::interface::run_compiler>> and then to std::thread::join, that doesn't tell us much. Thread 3 looks interesting here, let's take a look.
(gdb) backtrace
#0 0x00007fc65e9b0e4c in {closure#0}<rustc_middle::query::caches::SingleCache<rustc_middle::query::erase::ErasedData<[u8; 0]>>> ()
at compiler/rustc_query_impl/src/execution.rs:74
#1 collect_active_query_jobs_inner<rustc_middle::query::caches::SingleCache<rustc_middle::query::erase::ErasedData<[u8; 0]>>> ()
at compiler/rustc_query_impl/src/execution.rs:93
#2 0x00007fc65ea89257 in {closure#108} () at compiler/rustc_query_impl/src/execution.rs:56
#3 collect_active_query_jobs () at compiler/rustc_query_impl/src/query_impl.rs:240
#4 0x00007fc65e9a9c19 in find_and_handle_cycle<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_query_impl/src/execution.rs:206
#5 0x00007fc65e932240 in try_execute_query<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>, false> ()
at compiler/rustc_query_impl/src/execution.rs:333
#6 0x00007fc65e6773a8 in {closure#0}<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_query_impl/src/execution.rs:596
#7 maybe_grow<rustc_middle::query::erase::ErasedData<[u8; 8]>, rustc_query_impl::execution::execute_query_non_incr_inner::{closure_env#0}<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>>> ()
at /home/ci/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/stacker-0.1.21/src/lib.rs:57
#8 ensure_sufficient_stack<rustc_middle::query::erase::ErasedData<[u8; 8]>, rustc_query_impl::execution::execute_query_non_incr_inner::{closure_env#0}<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>>> () at compiler/rustc_data_structures/src/stack.rs:21
#9 execute_query_non_incr_inner<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_query_impl/src/execution.rs:596
#10 __rust_end_short_backtrace () at compiler/rustc_query_impl/src/query_impl.rs:80
#11 0x00007fc65fd568c2 in query_get_at<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_middle/src/query/inner.rs:45
#12 def_span<rustc_span::def_id::DefId> () at compiler/rustc_middle/src/query/plumbing.rs:571
#13 def_span<rustc_span::def_id::DefId> () at compiler/rustc_middle/src/query/plumbing.rs:559
#14 default_span () at compiler/rustc_middle/src/query/keys.rs:141
#15 0x00007fc65fd5675e in _RNvXs7_NtNtCs4dSIRTpZwWb_12rustc_middle5query4keysNtNtCs8PBYVrj6O0O_10rustc_span6def_id10LocalDefIdNtB5_8QueryKey12default_span () at compiler/rustc_middle/src/query/keys.rs:129
#16 0x00007fc65fd83976 in default_span () at compiler/rustc_middle/src/query/plumbing.rs:447
#17 0x00007fc65e79c050 in create_cycle_error () at compiler/rustc_query_impl/src/job.rs:474
#18 0x00007fc65e9044de in _RINvNtCse5jIZt3jLA6_16rustc_query_impl9execution12handle_cycleINtNtNtCs4dSIRTpZwWb_12rustc_middle5query6caches10DefIdCacheINtNtB13_5erase10ErasedDataAhj8_EEEB4_ () at compiler/rustc_query_impl/src/execution.rs:117
#19 0x00007fc65e9a9c82 in find_and_handle_cycle<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_query_impl/src/execution.rs:209
...
#1048575 0x00007fcfee1dead in find_and_handle_cycle<rustc_middle::query::caches::DefIdCache<rustc_middle::query::erase::ErasedData<[u8; 8]>>> ()
at compiler/rustc_query_impl/src/execution.rs:209
client_loop: send disconnect: Broken pipe
oh. well. there goes the dev pod again.
We got some useful info out before it crashed, though! Firstly, over a million frames is just an absolutely absurd number. The default stack limit on Linux is 8 MB:
$ ulimit --stack-size
8176
I'm used to seeing stack traces for infinite recursion that are 2,000-20,000 frames long, not … millions of frames. So something weird is going on there. That's probably why GDB OOM'ed.
Secondly, this is definitely infinite recursion. There is a cycle of period 15 going find_and_handle_query_cycle -> default_span -> def_span -> try_execute_query -> find_and_handle_query_cycle.
On frame 8 there's a call to ensure_sufficient_stack. The doc-comment on that function reads:
Grows the stack on demand to prevent stack overflow. Call this in strategic locations to "break up" recursive calls.
… It turns out that when we hit the limit of our stack, the compiler's runtime would detect that, copy the stack onto the heap, and then resume executing from the heap with more stack space. That allowed us to get that absurdly long backtrace before crashing from an OOM.
Query cycles
Now, some background about query cycles. The rustc-dev-guide has this to say about queries:
The compiler query system is the key to rustc’s demand-driven organization. Instead of entirely independent passes (parsing, type-checking, etc.), a set of function-like queries compute information about the input source.
For example, there is a query called def_span that, given the DefId of some item, will compute the source Span of that item and return it to you.
Query execution is memoized. The first time you invoke a query, it will go do the computation, but the next time, the result is returned from a hashtable. Moreover, query execution fits nicely into incremental computation; the idea is roughly that, when you invoke a query, the result may be returned to you by loading stored data from disk.
Rustc's query system combines this memoization technique with a fancy set of wrappers around function pointers. Rust doesn't have header files, so interposing function pointers everywhere allows all the queries to be declared in one place (currently rustc_middle::queries) but defined anywhere in the workspace. 1 Rustc calls these definitions providers.
For example, we could implement def_span like this:
providers.queries.def_span = |tcx: TyCtxt, def_id: DefId| tcx.hir_span(tcx.local_def_id_to_hir_id(def_id));
Queries are allowed to call other queries. The query system has a runtime that dynamically tracks dependencies between queries in order to make sure they're rerun if necessary, but cached otherwise.
The query system identifies queries by a (query_name, arguments) tuple. Queries can be mutually recursive as long as their arguments differ, just like normal function recursion:
providers.queries.hofstadter_m = |queries, n| if n == 0 { 0 } else {
n - queries.hofstadter_f(queries.hofstadter_m(n-1))
};
providers.queries.hofstadter_f = |queries, n| if n == 0 { 1 } else {
n - queries.hofstadter_m(queries.hofstadter_f(n-1))
}
/* ... a whole bunch of setup ... */
assert_eq!(query_ctxt.hofstadter_m(5), 2);
However, if both the query name and its arguments are the same as a previous call in the same stack, that indicates that we've hit infinite recursion, which is a bug. The query system calls this a query cycle. The function that handles this is called find_and_handle_cycle, and normally it will even print a diagnostic error:
So there are actually three different bugs here:
- Someone, somewhere in the compiler, is introducing a query cycle in Ferrocene but not in upstream rustc.
- The query system fails to handle that query cycle correctly and instead recurses forever.
ensure_sufficient_stackdoesn't catch infinite recursion; it has no stack guards and will happily let you allocate arbitrary amounts of memory.
Let's start by fixing 2. Then we'll get a nice helpful diagnostic that tells us about 1, and we won't have to worry about 3.
Finding the murder weapon
The first frame we see that leads out of cycle handling is frame 16, default_span. That function looks like this:
/// Returns the default span for this query if `span` is a dummy span.
pub fn default_span(&self, tcx: TyCtxt<'tcx>, span: Span) -> Span {
if !span.is_dummy() {
return span
}
if let TaggedQueryKey::def_span(..) = self {
// The `def_span` query is used to calculate `default_span`,
// so exit to avoid infinite recursion.
return DUMMY_SP
}
match self {
$(
TaggedQueryKey::$name(key) =>
$crate::query::QueryKey::default_span(key, tcx),
)*
}
}
So this is quite odd! The query system internals are calling back into the query system in order to get a span to annotate the error message. Whoever wrote this code knew about the possibility of infinite recursion and added a check, but somehow the check isn't firing and it's still recursing forever.
We should fix the underlying check at some point, but first let's just get an error message at all. We can avoid the recursion by just always returning a dummy span:
$ git diff -U0
diff --git a/compiler/rustc_middle/src/query/plumbing.rs b/compiler/rustc_middle/src/query/plumbing.rs
index ef6259b1a0c..2efa5d82158 100644
--- a/compiler/rustc_middle/src/query/plumbing.rs
+++ b/compiler/rustc_middle/src/query/plumbing.rs
@@ -435,0 +436 @@ pub fn default_span(&self, tcx: TyCtxt<'tcx>, span: Span) -> Span {
+ return span;
That gets us this error:
This is starting to be quite helpful. "codegen attributes" calling "entry function" looks familiar, didn't I write that code …
… oh yeah I totally did.
/// Process the builtin attrs ([`hir::Attribute`]) on the item.
/// Many of them directly translate to codegen attrs.
fn process_builtin_attrs(
tcx: TyCtxt<'_>,
did: LocalDefId,
attrs: &[Attribute],
codegen_fn_attrs: &mut CodegenFnAttrs,
) -> InterestingAttributeDiagnosticSpans {
// Ferrocene addition
if let ValidatedStatus::Validated { .. } = item_is_validated(tcx, did.into()) {
codegen_fn_attrs.validated = Some(Validated {});
}
// ...
}
item_is_validated wants to know if this is fn main so it can treat it as if you always wrote #[ferrocene::prevalidated] before it. This code doesn't exist upstream, which is why it only caused a cycle in Ferrocene.
Why is that causing a cycle, though? Why now, when it didn't a week ago? And why only on this code? And why can't the query system handle it when it does?
Nested query cycles
I started by adding some tracing of the query executions themselves:
$ git diff -U1
diff --git a/compiler/rustc_middle/src/query/plumbing.rs b/compiler/rustc_middle/src/query/plumbing.rs
index ef6259b1a0c..a9090d4c7f6 100644
--- a/compiler/rustc_middle/src/query/plumbing.rs
+++ b/compiler/rustc_middle/src/query/plumbing.rs
@@ -434,2 +434,3 @@ pub fn description(&self, tcx: TyCtxt<'tcx>) -> String {
/// Returns the default span for this query if `span` is a dummy span.
+ #[tracing::instrument(level = "debug", skip(tcx, span))]
pub fn default_span(&self, tcx: TyCtxt<'tcx>, span: Span) -> Span {
diff --git a/compiler/rustc_query_impl/src/execution.rs b/compiler/rustc_query_impl/src/execution.rs
index 8844d40f49c..ff427919ede 100644
--- a/compiler/rustc_query_impl/src/execution.rs
+++ b/compiler/rustc_query_impl/src/execution.rs
@@ -203,2 +203,4 @@ fn find_and_handle_cycle<'tcx, C: QueryCache>(
) -> (C::Value, Option<DepNodeIndex>) {
+ tracing::info!("hit a query cycle evaluating {}!", query.name);
+
// Ensure there were no errors collecting all active jobs.
@@ -258,2 +260,3 @@ fn wait_for_query<'tcx, C: QueryCache>(
#[inline(never)]
+#[tracing::instrument(level = "debug", skip_all, fields(query = query.name, key))]
fn try_execute_query<'tcx, C: QueryCache, const INCR: bool>(
That shows us the following trace on our bad-resolve.rs file:
rustc_query_impl::execution::try_execute_query query="hir_crate_items"
...
rustc_query_impl::execution::try_execute_query query="lower_delayed_owner"
...
rustc_query_impl::execution::try_execute_query query="codegen_fn_attrs"
rustc_query_impl::execution::try_execute_query query="hir_crate_items"
0ms INFO rustc_query_impl::execution hit a query cycle evaluating hir_crate_items!
rustc_middle::queries::default_span self=hir_crate_items(())
rustc_middle::queries::default_span self=lower_delayed_owner(DefId(0:14 ~ bad_resolve[0a7b]::{impl#1}::bar))
rustc_query_impl::execution::try_execute_query query="def_span"
rustc_query_impl::execution::try_execute_query query="local_def_id_to_hir_id"
rustc_query_impl::execution::try_execute_query query="lower_delayed_owner"
0ms INFO rustc_query_impl::execution hit a query cycle evaluating lower_delayed_owner!
rustc_middle::queries::default_span self=lower_delayed_owner(DefId(0:14 ~ bad_resolve[0a7b]::{impl#1}::bar))
rustc_query_impl::execution::try_execute_query query="def_span"
0ms INFO rustc_query_impl::execution hit a query cycle evaluating def_span!
rustc_middle::queries::default_span self=def_span(DefId(0:14 ~ bad_resolve[0a7b]::{impl#1}::bar))
rustc_query_impl::execution::try_execute_query query="def_span"
rustc_query_impl::execution::try_execute_query query="local_def_id_to_hir_id"
rustc_query_impl::execution::try_execute_query query="opt_hir_owner_nodes"
rustc_middle::queries::default_span self=local_def_id_to_hir_id(DefId(0:14 ~ bad_resolve[0a7b]::{impl#1}::bar))
rustc_query_impl::execution::try_execute_query query="def_span"
...
This is uh. This is generally referred to as "not good".
Let me note a few things.
- We see the original cycle from the screenshot above, the one that looped in
hir_crate_items. - We see the call to
default_span, just like we expected. - We see another cycle: this one goes
def_span->local_def_id_to_hir_id->lower_delayed_owner. The query system correctly detects that we're already executinglower_delayed_owner(from the first cycle!) and tries to report another cycle error. - This calls
default_span, which causes a third cycle: the query system correctly detects that we're already executingdef_span(from the second cycle). - The query system tries to report the third cycle by calling
def_spanforlocal_def_id_to_hir_id, over and over in an infinite loop until we OOM.
What on earth is going on here?
Let's start by looking at the implementation of the def_span query:
// rustc_middle::hir::provide
providers.def_span = |tcx, def_id| tcx.hir_span(tcx.local_def_id_to_hir_id(def_id));
We can already see the problem here: def_span unconditionally calls local_def_id_to_hir_id. So if we try to get a span for local_def_id_to_hir_id, we will always end up recursing back into it and causing a new cycle. Our default_span function above didn't catch that because it forgot that the def_span query might have dependencies.
That's the cause of the third cycle, the infinite one. The first and second cycles are more complicated; see this merged PR for more information. The gist is that the unstable fn_delegation feature introduces an idea of "delayed HIR owners" that didn't exist before, which means that queries which used to assume it was fine to call hir_crate_items can no longer do so without causing a query cycle.
The fixes
At this point I think we can say we've solved the mystery! The following PRs have changes related to these bugs:
- Improved handling for cycles within the query system itself, which fixes issues 2 and 3 (infinite cycles within the query system, and missing stack guards in
ensure_sufficient_stack). - Add more robust handling of nested query cycles, which reports all cycles that happen, not just the most recent.
- delegation: fix cycles during delayed lowering, which fixes the original cycle in
hir_crate_items.
Why did Ferrocene hit this?
Ferrocene has a custom ferrocene::unvalidated lint which detects when certified code calls uncertified code. For more information about the lint and about certification itself, see my previous blog post, Callgraph analysis.
Despite the bugs we've encountered, I still believe a custom lint to be the right choice here. The bugs are pre-existing issues in the upstream rust compiler, and fixing them will make the development experience better for everyone working on Rustc, not just Ferrocene developers. In particular, I remember the author of delegation mentioning it was mostly unstable due to infinite cycles; the fixes found here will help unblock that work.
Takeaways
-
Correctness is not enough when the bugs are in your testing infrastructure! The explicit timeouts for CI really helped here, and the lack of them when running locally really hurt. One thing I might do in the future is to set a global memory limit across the test runner, and only allow specific tests (such as
tests/ui/codegen/huge-stacks.rs) to go above that limit, so that local tests can't crash their surrounding environment like this. -
The state of debugging Rust is … not great. Because
rustcuses interned arenas heavily, it's hard to get any info at all out of a debugger unless you can usecall, which is quite buggy in Rust programs, at least in GDB. There are very few alternatives to debug logging, and debug logging is not always going to be in the places you need it. This hurts especially badly when you have slow compile times, which Rust also has, especiallyrustcitself. -
As in my coverage talk, Precise, consistent, and reliable code coverage, the problem here was largely in the infrastructure, not in the code itself. Sometimes you really do have to drop down to the supporting code rather than thinking about your domain.
We offer consulting services and Rust trainings — contact us for a quote and consider subscribing to our Trainings newsletter!
-
This is good for compilation times of rustc itself, because it allows building more crates in parallel, but bad for the runtime of rustc itself because it imposes overhead between queries. Note that the "runtime of rustc" is what we normally consider compile-time in other contexts. ↩
