Endless loop in std::fmt caused by initializing WriteLogger twice

[LionsAd]

I tried this code:

git clone [email protected]:tag1consulting/goose.git
cargo test --test setup_teardown

with a test that initialized simple_log again after it was already initialized. (--tests-serial still triggered the bug)

I expected to see this happen: Tests pass

Instead, this happened: Stack overflow

Backtrace from rust-lldb is attached later.

While re-initializing the logger is clearly a bug in goose (tag1consulting/goose#122) and undefined behavior, I don't think this should lead to an endless loop in the stdlib.

Meta

rustc --version --verbose:

rustc 1.45.0 (5c1f21c3b 2020-07-13)
binary: rustc
commit-hash: 5c1f21c3b82297671ad3ae1e8c942d2ca92e84f2
commit-date: 2020-07-13
host: x86_64-apple-darwin
release: 1.45.0
LLVM version: 10.0

(but also happens on beta)

Backtrace from rust-lldb

    frame #19619: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #19620: 0x0000000100c3c83e setup_teardown-b971616726328643`core::fmt::Formatter::write_fmt::hf86f2b0bebdd7d52 at mod.rs:1505:9 [opt]
    frame #19621: 0x00000001000cc211 setup_teardown-b971616726328643`_$LT$ctrlc..error..Error$u20$as$u20$core..fmt..Display$GT$::fmt::h321ae19602832f09(self=&0x700009555838, f=&0x700009554460) at error.rs:24:9
    frame #19622: 0x00000001000cc0f8 setup_teardown-b971616726328643`_$LT$$RF$T$u20$as$u20$core..fmt..Display$GT$::fmt::h8da1869c7b991d97(self=&0x700009554560, f=&0x700009554460) at mod.rs:1981:62
    frame #19623: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #19624: 0x0000000100c3c83e setup_teardown-b971616726328643`core::fmt::Formatter::write_fmt::hf86f2b0bebdd7d52 at mod.rs:1505:9 [opt]
    frame #19625: 0x00000001000cc211 setup_teardown-b971616726328643`_$LT$ctrlc..error..Error$u20$as$u20$core..fmt..Display$GT$::fmt::h321ae19602832f09(self=&0x700009555838, f=&0x7000095545d0) at error.rs:24:9
    frame #19626: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #19627: 0x0000000100c3b51b setup_teardown-b971616726328643`_$LT$core..fmt..Arguments$u20$as$u20$core..fmt..Debug$GT$::fmt::h75ecacb307b1ffb2 [inlined] _$LT$core..fmt..Arguments$u20$as$u20$core..fmt..Display$GT$::fmt::h8d1074c567f05b9f at mod.rs:422:9 [opt]
    frame #19628: 0x0000000100c3b4d8 setup_teardown-b971616726328643`_$LT$core..fmt..Arguments$u20$as$u20$core..fmt..Debug$GT$::fmt::h75ecacb307b1ffb2 at mod.rs:415 [opt]
    frame #19629: 0x00000001007dc898 setup_teardown-b971616726328643`_$LT$$RF$T$u20$as$u20$core..fmt..Display$GT$::fmt::hb2dc8ebe93d2ba7d(self=&0x700009555470, f=&0x7000095546d0) at mod.rs:1981:62
    frame #19630: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #19631: 0x000000010005774f setup_teardown-b971616726328643`std::io::Write::write_fmt::he282639b82d1b4ff(self=&0x102702cd4, fmt=<unavailable>) at mod.rs:1537:15
    frame #19632: 0x000000010007ed21 setup_teardown-b971616726328643`_$LT$simplelog..loggers..writelog..WriteLogger$LT$W$GT$$u20$as$u20$log..Log$GT$::log::h33d7cf67046c67cd [inlined] simplelog::loggers::logging::write_args::hc28e0079714279aa(record=&0x700009555608, write=&0x102702cd4) at mod.rs:475:9

Here is another excerpt of the backtrace:

    frame #167: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #168: 0x0000000100c3c83e setup_teardown-b971616726328643`core::fmt::Formatter::write_fmt::hf86f2b0bebdd7d52 at mod.rs:1505:9 [opt]
    frame #169: 0x00000001000cc211 setup_teardown-b971616726328643`_$LT$ctrlc..error..Error$u20$as$u20$core..fmt..Display$GT$::fmt::h321ae19602832f09(self=&0x700009555838, f=&0x700009366600) at error.rs:24:9
    frame #170: 0x00000001000cc0f8 setup_teardown-b971616726328643`_$LT$$RF$T$u20$as$u20$core..fmt..Display$GT$::fmt::h8da1869c7b991d97(self=&0x700009366700, f=&0x700009366600) at mod.rs:1981:62
    frame #171: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #172: 0x0000000100c3c83e setup_teardown-b971616726328643`core::fmt::Formatter::write_fmt::hf86f2b0bebdd7d52 at mod.rs:1505:9 [opt]
    frame #173: 0x00000001000cc211 setup_teardown-b971616726328643`_$LT$ctrlc..error..Error$u20$as$u20$core..fmt..Display$GT$::fmt::h321ae19602832f09(self=&0x700009555838, f=&0x7000093667a0) at error.rs:24:9
    frame #174: 0x00000001000cc0f8 setup_teardown-b971616726328643`_$LT$$RF$T$u20$as$u20$core..fmt..Display$GT$::fmt::h8da1869c7b991d97(self=&0x7000093668a0, f=&0x7000093667a0) at mod.rs:1981:62
    frame #175: 0x0000000100c3b72c setup_teardown-b971616726328643`core::fmt::write::h8ef98027ac1df1be at mod.rs:1076:17 [opt]
    frame #176: 0x0000000100c3c83e setup_teardown-b971616726328643`core::fmt::Formatter::write_fmt::hf86f2b0bebdd7d52 at mod.rs:1505:9 [opt]
    frame #177: 0x00000001000cc211 setup_teardown-b971616726328643`_$LT$ctrlc..error..Error$u20$as$u20$core..fmt..Display$GT$::fmt::h321ae19602832f09(self=&0x700009555838, f=&0x700009366940) at error.rs:24:9
    frame #178: 0x00000001000cc0f8 setup_teardown-b971616726328643`_$LT$$RF$T$u20$as$u20$core..fmt..Display$GT$::fmt::h8da1869c7b991d97(self=&0x700009366a40, f=&0x700009366940) at mod.rs:1981:62

[nbdd0121]

This is not a bug in libstd. It is visible that a non-std call frame (<ctrlc:::Error as core::fmt::Display>::fmt) is the culprit.

[robojumper]

Bug in rust-ctrlc. See Detegr/rust-ctrlc#68.

(tag1consulting/goose makes the same error in GooseError and GooseTaskError)

[LionsAd]

Thank you for the advice - it was my first stack frame backtrace.

[jonas-schievink]

cc #57965, which would have caught this