io::cleanup() can panic in unusual circumstances

[jswrenn]

In the presence of a global allocator that prints on dealloc, the io::cleanup routine panics. This panic is surprising, because it occurs after main.

Example and Backtrace

(Playground)

#[global_allocator]
static ALLOCATOR: allocator::TracingSystemAllocator 
    = allocator::TracingSystemAllocator;

fn main() {
    let _ = std::io::stdout();
    allocator::enable_tracing();
    // allocator::disable_tracing(); // uncomment to fix panic
    // panic occurs after `main()`
}

// a global allocator that prints on `alloc` and `dealloc`
#[allow(dead_code)]
mod allocator {
    use core::{
        alloc::{GlobalAlloc, Layout},
        cell::{RefCell, RefMut},
    };

    use std::{
        alloc::System,
        panic::catch_unwind,
    };

    pub struct TracingSystemAllocator;

    unsafe impl GlobalAlloc for TracingSystemAllocator {
        unsafe fn alloc(&self, layout: Layout) -> *mut u8 {
            let ptr = System.alloc(layout);

            let _ = catch_unwind(|| maybe_with_guard(|trace_allocations| {
                if *trace_allocations {
                    println!("alloc({:?}) = {}", layout, ptr as usize);
                }
            }));

            ptr
        }

        unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) {
            System.dealloc(ptr, layout);

            let _ = catch_unwind(|| maybe_with_guard(|trace_allocations| {
                if *trace_allocations {
                    println!("dealloc({}, {:?})", ptr as usize, layout);
                }
            }));
        }
    }

    pub fn enable_tracing() { maybe_with_guard(|mut trace| *trace = true) }
    pub fn disable_tracing() { maybe_with_guard(|mut trace| *trace = false) }

    // maybe run `f`, if a unique, mutable reference to `TRACE_ALLOCATOR` can be
    // acquired.
    fn maybe_with_guard<F>(f: F)
    where
        F: for<'a> FnOnce(RefMut<'a, bool>),
    {
        let _ = TRACE_ALLOCATOR.try_with(|guard| guard.try_borrow_mut().map(f));
    }

    // used to prevent infinitely recursive tracing
    thread_local!{ static TRACE_ALLOCATOR: RefCell<bool> = RefCell::default(); }
}

Backtrace

thread 'main' panicked at 'already borrowed: BorrowMutError', library/std/src/io/stdio.rs:864:20
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'already borrowed: BorrowMutError', library/std/src/io/stdio.rs:864:20
stack backtrace:
   0:     0x56295cb1663c - std::backtrace_rs::backtrace::libunwind::trace::h91c465e73bf6c785
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x56295cb1663c - std::backtrace_rs::backtrace::trace_unsynchronized::hae9da36f5d58b5f3
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x56295cb1663c - std::sys_common::backtrace::_print_fmt::h7f499fa126a7effb
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x56295cb1663c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h3e2b509ce2ce6007
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x56295cb3290c - core::fmt::write::h753c7571fa063ecb
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/fmt/mod.rs:1168:17
   5:     0x56295cb13523 - std::io::Write::write_fmt::h2815c0519c99ba09
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/mod.rs:1660:15
   6:     0x56295cb184f2 - std::sys_common::backtrace::_print::h64941a6fc8b0ed9b
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x56295cb184f2 - std::sys_common::backtrace::print::hcf25e43e1a9b0766
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x56295cb184f2 - std::panicking::default_hook::{{closure}}::h78d3e6cf97fc623d
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:211:50
   9:     0x56295cb180d5 - std::panicking::default_hook::hda898f8d3ad1a5ae
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:228:9
  10:     0x56295cb18b43 - std::panicking::rust_panic_with_hook::h1a5ea2d6c23051aa
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:606:17
  11:     0x56295cb18860 - std::panicking::begin_panic_handler::{{closure}}::h07f549390938b73f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:502:13
  12:     0x56295cb16ae4 - std::sys_common::backtrace::__rust_end_short_backtrace::h5ec3758a92cfb00d
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sys_common/backtrace.rs:139:18
  13:     0x56295cb18599 - rust_begin_unwind
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:498:5
  14:     0x56295caff371 - core::panicking::panic_fmt::h3a79a6a99affe1d5
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/panicking.rs:116:14
  15:     0x56295caff403 - core::result::unwrap_failed::ha0327e3803285d6e
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/result.rs:1690:5
  16:     0x56295cb129ba - core::result::Result<T,E>::expect::hd92a85caa762cf4d
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/result.rs:975:23
  17:     0x56295cb129ba - core::cell::RefCell<T>::borrow_mut::h222a43ad92e47b29
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/cell.rs:946:9
  18:     0x56295cb129ba - <std::io::stdio::StdoutLock as std::io::Write>::write_all::h0485fa4c76ef33a0
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:864:9
  19:     0x56295cb136f3 - <std::io::Write::write_fmt::Adapter<T> as core::fmt::Write>::write_str::h0469fbf51f460f83
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/mod.rs:1649:23
  20:     0x56295cb328fc - core::fmt::write::h753c7571fa063ecb
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/fmt/mod.rs:1166:21
  21:     0x56295cb126bd - std::io::Write::write_fmt::h14847b988808b22b
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/mod.rs:1660:15
  22:     0x56295cb126bd - <&std::io::stdio::Stdout as std::io::Write>::write_fmt::hbedd013841f7b2e2
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:844:9
  23:     0x56295cb12b1b - <std::io::stdio::Stdout as std::io::Write>::write_fmt::h606f3fb18c36d7de
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:818:9
  24:     0x56295cb12b1b - std::io::stdio::print_to::h30cc8f14d9cb96a3
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:1186:21
  25:     0x56295cb12b1b - std::io::stdio::_print::h4dabb72d0b79d2de
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:1199:5
  26:     0x56295cb0015d - <playground::allocator::TracingSystemAllocator as core::alloc::global::GlobalAlloc>::dealloc::{{closure}}::{{closure}}::h7d6128ea2f7a151d
                               at /playground/src/main.rs:45:21
  27:     0x56295cb01e3c - core::result::Result<T,E>::map::h713c34b4fa0d9fd8
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/result.rs:709:25
  28:     0x56295cb002e9 - playground::allocator::maybe_with_guard::{{closure}}::h1cabc2e8cd20fc8b
                               at /playground/src/main.rs:60:50
  29:     0x56295cb00ade - std::thread::local::LocalKey<T>::try_with::he04bc4e8d7dba087
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/thread/local.rs:412:16
  30:     0x56295cb0021e - playground::allocator::maybe_with_guard::h51f94e4a4fcfca48
                               at /playground/src/main.rs:60:17
  31:     0x56295cafffd7 - <playground::allocator::TracingSystemAllocator as core::alloc::global::GlobalAlloc>::dealloc::{{closure}}::h7be36579f26cfcec
                               at /playground/src/main.rs:43:37
  32:     0x56295cb0249b - std::panicking::try::do_call::h616a99828a3d0f34
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:406:40
  33:     0x56295cb02a3b - __rust_try
  34:     0x56295cb022cd - std::panicking::try::h1da88df9552726f4
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:370:19
  35:     0x56295cb01c83 - std::panic::catch_unwind::h4c11da4187c3b896
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panic.rs:133:14
  36:     0x56295cafff96 - <playground::allocator::TracingSystemAllocator as core::alloc::global::GlobalAlloc>::dealloc::h6009103950d84ca5
                               at /playground/src/main.rs:43:21
  37:     0x56295cb004ec - __rg_dealloc
                               at /playground/src/main.rs:2:1
  38:     0x56295cb24bdb - alloc::alloc::dealloc::haa3492954d12ce5f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/alloc.rs:105:14
  39:     0x56295cb24bdb - <alloc::alloc::Global as core::alloc::Allocator>::deallocate::hb4b305912aa4cfca
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/alloc.rs:242:22
  40:     0x56295cb24bdb - alloc::alloc::box_free::ha1cc9603ca4735c5
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/alloc.rs:340:9
  41:     0x56295cb24bdb - panic_unwind::real_imp::cleanup::h752dae465f50738f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/panic_unwind/src/gcc.rs:83:5
  42:     0x56295cb24bdb - __rust_panic_cleanup
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/panic_unwind/src/lib.rs:97:19
  43:     0x56295cafe87d - std::panicking::try::cleanup::he69b6749f8de9285
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:387:42
  44:     0x56295cb02573 - std::panicking::try::do_catch::he816bc138d82a8be
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:431:23
  45:     0x56295cb02a53 - __rust_try
  46:     0x56295cb022cd - std::panicking::try::h1da88df9552726f4
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:370:19
  47:     0x56295cb01c83 - std::panic::catch_unwind::h4c11da4187c3b896
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panic.rs:133:14
  48:     0x56295cafff96 - <playground::allocator::TracingSystemAllocator as core::alloc::global::GlobalAlloc>::dealloc::h6009103950d84ca5
                               at /playground/src/main.rs:43:21
  49:     0x56295cb004ec - __rg_dealloc
                               at /playground/src/main.rs:2:1
  50:     0x56295cb155ab - alloc::alloc::dealloc::haa3492954d12ce5f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/alloc.rs:105:14
  51:     0x56295cb155ab - <alloc::alloc::Global as core::alloc::Allocator>::deallocate::hb4b305912aa4cfca
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/alloc.rs:242:22
  52:     0x56295cb155ab - <alloc::raw_vec::RawVec<T,A> as core::ops::drop::Drop>::drop::h5cc422f24c20fbcc
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/alloc/src/raw_vec.rs:479:22
  53:     0x56295cb155ab - core::ptr::drop_in_place<alloc::raw_vec::RawVec<u8>>::hec44dd4b63d893d3
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/ptr/mod.rs:188:1
  54:     0x56295cb155ab - core::ptr::drop_in_place<alloc::vec::Vec<u8>>::h8549a3bfcac0511f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/ptr/mod.rs:188:1
  55:     0x56295cb155ab - core::ptr::drop_in_place<std::io::buffered::bufwriter::BufWriter<std::io::stdio::StdoutRaw>>::h03be3001ed541bd0
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/ptr/mod.rs:188:1
  56:     0x56295cb155ab - core::ptr::drop_in_place<std::io::buffered::linewriter::LineWriter<std::io::stdio::StdoutRaw>>::hca1184e7a5ab199b
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/ptr/mod.rs:188:1
  57:     0x56295cb155ab - std::io::stdio::cleanup::hc7c677e6c351f70b
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/io/stdio.rs:720:13
  58:     0x56295cb155ab - std::rt::cleanup::{{closure}}::h3b61a35d525b7463
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/rt.rs:97:9
  59:     0x56295cb155ab - std::sync::once::Once::call_once::{{closure}}::hc7434a57984866e6
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sync/once.rs:269:41
  60:     0x56295cafe63a - std::sync::once::Once::call_inner::h222a34e71c71c7d0
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sync/once.rs:426:21
  61:     0x56295cb15d30 - std::sync::once::Once::call_once::h1832fcdcd1b2c564
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/sync/once.rs:269:9
  62:     0x56295cb15d30 - std::rt::cleanup::h56ad3aee2a9e3759
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/rt.rs:95:5
  63:     0x56295cb15d30 - core::ops::function::FnOnce::call_once::h2b4de7e60e48388d
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/core/src/ops/function.rs:227:5
  64:     0x56295cb15d30 - std::panicking::try::do_call::h4cec8f0c5cfc7b8d
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:406:40
  65:     0x56295cb15d30 - std::panicking::try::h8c85538cac59ef3f
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panicking.rs:370:19
  66:     0x56295cb15d30 - std::panic::catch_unwind::had8717965d8fd960
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/panic.rs:133:14
  67:     0x56295cb15d30 - std::rt::lang_start_internal::h52e73755f77c7dd9
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/rt.rs:133:5
  68:     0x56295cb02040 - std::rt::lang_start::h8ddb7db3dfeaadab
                               at /rustc/9d1b2106e23b1abd32fce1f17267604a5102f57a/library/std/src/rt.rs:144:17
  69:     0x56295cb02a7c - main
  70:     0x7f591eed30b3 - __libc_start_main
  71:     0x56295caffa6e - _start
  72:                0x0 - <unknown>
thread panicked while panicking. aborting.

Meta

At the time of writing, this bug occurs on stable (v1.59.0), beta (1.60.0-beta.5), and nightly (1.61.0-nightly 2022-03-18 1bfe40d).

Sequence of Events

• first, io::cleanup borrow_muts Stdout's LineWriter and drops it
  

  rust/library/std/src/io/stdio.rs

  Line 624 in 9c7f6d6

  *lock.borrow_mut() = LineWriter::with_capacity(0, stdout_raw());

  • then, that previous LineWriter<BufWriter> of Stdout is deallocated
    • then, TracingSystemAllocator::dealloc invokes println!
      • ...which eventually invokes StdoutLock<'_>::write_all
        

        rust/library/std/src/io/stdio.rs

        Lines 863 to 865 in 9d1b210

        	fn write_all(&mut self, buf: &[u8]) -> io::Result<()> {
        	self.inner.borrow_mut().write_all(buf)
        	}

        • ...which tries to borrow_mut() the Stdout's LineWriter. This fails because io::cleanup already holds the mutable borrow.