Printing / Formatting f64 crashes

[bjoernQ]

This code

#![no_std]
#![no_main]

use esp32_hal::{clock::ClockControl, pac::Peripherals, prelude::*, timer::TimerGroup, RtcCntl};
use esp_backtrace as _;
use esp_println::println;
use xtensa_lx_rt::entry;

#[entry]
fn main() -> ! {
    let peripherals = Peripherals::take().unwrap();
    let system = peripherals.DPORT.split();
    let clocks = ClockControl::boot_defaults(system.clock_control).freeze();

    // Disable the RTC and TIMG watchdog timers
    let mut rtc_cntl = RtcCntl::new(peripherals.RTC_CNTL);
    let timer_group0 = TimerGroup::new(peripherals.TIMG0, &clocks);
    let mut wdt0 = timer_group0.wdt;
    let timer_group1 = TimerGroup::new(peripherals.TIMG1, &clocks);
    let mut wdt1 = timer_group1.wdt;

    rtc_cntl.set_wdt_global_enable(false);
    wdt0.disable();
    wdt1.disable();

    println!("Howdy!");

    let foo = 3.14f32;
    println!("{}", foo * 2f32);

    let foo = 3.14f64;
    println!("{}", foo * 2f64);

    loop {

    }
}

works correct for debug builds on ESP32 but crashes for release builds like this:

Howdy!
6.28


!! A panic occured in 'C:\Users\Bjoern\.rustup\toolchains\esp\lib\rustlib\src\rust\library\core\src\num\flt2dec\mod.rs', at line 189, column 5

PanicInfo {
    payload: Any { .. },
    message: Some(
        assertion failed: buf[0] > b\'0\',
    ),
    location: Location {
        file: "C:\\Users\\Bjoern\\.rustup\\toolchains\\esp\\lib\\rustlib\\src\\rust\\library\\core\\src\\num\\flt2dec\\mod.rs",
        line: 189,
        col: 5,
    },
    can_unwind: true,
}

Backtrace:

0x400d7e8e
0x400d7e8e - _ZN4core3num7flt2dec17digits_to_dec_str17heb592f82a70d05d1E
    at ??:??
0x400d82e1
0x400d82e1 - _ZN4core3num7flt2dec15to_shortest_str17hb3626511ee59378eE
    at ??:??
0x400d6960
0x400d6960 - _ZN4core3fmt5float32float_to_decimal_common_shortest17hfff5f366670e650eE.llvm.14292657683144325728
    at ??:??
0x400d69cf
0x400d69cf - _ZN4core3fmt5float52_$LT$impl$u20$core..fmt..Display$u20$for$u20$f64$GT$3fmt17h0efd241b8f8506e7E
    at ??:??
0x400d6b12
0x400d6b12 - _ZN4core3fmt5write17hfeac229cab89db3fE
    at ??:??
0x400d08fc
0x400d08fc - main
    at ??:??
0x400d0b5a
0x400d0b5a - Reset
    at ??:??
0x400d0a98
0x400d0a98 - ESP32Reset
    at ??:??

This happens on the current (1.63.0.2) version and at least a few older ones

[MabezDev]

This should now be fixed by the 1.64.0.0 release.

[lynaghk]

I don't believe this has been fixed, I can repro on an esp32-s3 with:

use log::*;

fn main() -> ! {
    esp_idf_sys::link_patches();
    esp_idf_svc::log::EspLogger::initialize_default();

    info!("{}", 3.14_f64 * 2.0);

    loop {
        std::thread::sleep(std::time::Duration::from_millis(50));
    }
}

built with rustc 1.64.0-nightly (f53d2361e 2022-09-20) installed via

curl -LO https://github.com/esp-rs/rust-build/releases/download/v1.64.0.0/install-rust-toolchain.sh
bash install-rust-toolchain.sh --build-target esp32s3 --nightly-version nightly-2022-09-22 --export-file export-esp-rust.sh

Full trace:

$ espmonitor  /dev/tty.usbserial-*
ESPMonitor 0.10.0

Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

Opening /dev/tty.usbserial-110 with speed 115200
Resetting device... done
tloade�ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x18 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fcd0108,len:0x1710
load:0x403b6000,len:0x8c8
load:0x403ba000,len:0x2eb4
SHA-256 comparison failed:
Calculated: 1549cc352de9d9bcb10175fcd43380ff2e0209e9a6b10dd38e454bc060f04976
Expected: ab492d70a98095a7841c7bfbf1d6d0b6161e082227abfb2028c51ce7cbe6144a
Attempting to boot anyway...
entry 0x403b61c0
I (50) boot: ESP-IDF v4.4-dev-3540-g4e03a9c34c 2nd stage bootloader
I (50) boot: compile time 09:24:35
I (50) boot: chip revision: 0
I (53) boot.esp32s3: Boot SPI Speed : 80MHz
I (58) boot.esp32s3: SPI Mode       : SLOW READ
I (63) boot.esp32s3: SPI Flash Size : 4MB
I (68) boot: Enabling RNG early entropy source...
W (73) bootloader_random: RNG for ESP32-S3 not currently supported
I (80) boot: Partition Table:
I (84) boot: ## Label            Usage          Type ST Offset   Length
I (91) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (99) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (106) boot:  2 factory          factory app      00 00 00010000 003f0000
I (114) boot: End of partition table
I (118) esp_image: segment 0: paddr=00010020 vaddr=3c050020 size=10950h ( 67920) map
I (143) esp_image: segment 1: paddr=00020978 vaddr=3fc8f8a0 size=02710h ( 10000) load
I (145) esp_image: segment 2: paddr=00023090 vaddr=40374000 size=0b894h ( 47252) load
I (161) esp_image: segment 3: paddr=0002e92c vaddr=50000000 size=00010h (    16) load
I (162) esp_image: segment 4: paddr=0002e944 vaddr=00000000 size=016d4h (  5844) 
I (168) esp_image: segment 5: paddr=00030020 vaddr=42000020 size=4337ch (275324) map
I (244) boot: Loaded app from partition at offset 0x10000
I (245) boot: Disabling RNG early entropy source...
W (245) bootloader_random: RNG for ESP32-S3 not currently supported
I (263) cpu_start: Pro cpu up.
I (263) cpu_start: Starting app cpu, entry point is 0x40375394
I (0) cpu_start: App cpu up.
I (277) cpu_start: Pro cpu start user code
I (277) cpu_start: cpu freq: 240000000
I (277) cpu_start: Application information:
I (280) cpu_start: Project name:     libespidf
I (285) cpu_start: App version:      1
I (290) cpu_start: Compile time:     Oct  7 2022 09:54:31
I (296) cpu_start: ELF file SHA256:  0000000000000000...
I (302) cpu_start: ESP-IDF:          1b16ef6cf-dirty
I (307) heap_init: Initializing. RAM available for dynamic allocation:
I (315) heap_init: At 3FC92A58 len 0004D5A8 (309 KiB): D/IRAM
I (321) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM
I (328) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (334) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
I (341) spi_flash: detected chip: mxic
W (345) spi_flash: Detected flash size > 16 MB, but access beyond 16 MB is not supported for this flash model yet.
I (356) spi_flash: flash io: dio
W (360) spi_flash: Detected size(32768k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (373) sleep: Configure to isolate all GPIO pins in sleep state
I (380) sleep: Enable automatic switching of GPIO sleep configuration
I (387) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
thread 'main' panicked at 'assertion failed: buf[0] > b\'0\'', /root/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/num/flt2dec/mod.rs:189:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
abort() was called at PC 0x4201d256 on core 0

[MabezDev]

You're right, thanks, I guess I wasn't compiling in release when I tested this again. I will reopen and will investigate shortly.

[zRedShift]

@MabezDev, I noticed the same bug when formatting f32 on release mode. Tested on 1.65.0.0.
It's both misprinting and crashing with f32 and f64. f32:

I (312) esp_spinlock_repro: counter at 0
I (322) esp_spinlock_repro: counter at 0.000@
I (342) esp_spinlock_repro: counter at 0.000P
I (382) esp_spinlock_repro: counter at 3
I (392) esp_spinlock_repro: counter at 0.000p
I (452) esp_spinlock_repro: counter at 5
I (462) esp_spinlock_repro: counter at 6
I (472) esp_spinlock_repro: counter at 7
I (482) esp_spinlock_repro: counter at 0.000�
I (592) esp_spinlock_repro: counter at 9
I (602) esp_spinlock_repro: counter at 10
I (612) esp_spinlock_repro: counter at 11
I (622) esp_spinlock_repro: counter at 12
I (632) esp_spinlock_repro: counter at 13
I (642) esp_spinlock_repro: counter at 14
I (662) esp_spinlock_repro: counter at 15
thread 'main' panicked at 'assertion failed: buf[0] > b\'0\'', ~/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/num/flt2dec/mod.rs:189:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
abort() was called at PC 0x420095f2 on core 0
0x420095f2 - _ZN11panic_abort18__rust_start_panic5abort17hd15b097d1e251a58E
    at ??:??

f64:

I (312) esp_spinlock_repro: counter at 0
I (322) esp_spinlock_repro: counter at 1
I (332) esp_spinlock_repro: counter at 2
I (342) esp_spinlock_repro: counter at 0.000`
I (372) esp_spinlock_repro: counter at 4
I (382) esp_spinlock_repro: counter at 0.000�
I (442) esp_spinlock_repro: counter at 0.000�
I (492) esp_spinlock_repro: counter at 0.000�
I (532) esp_spinlock_repro: counter at 8
I (542) esp_spinlock_repro: counter at 0.000�
I (652) esp_spinlock_repro: counter at 0.000�
I (752) esp_spinlock_repro: counter at 0.000�
I (842) esp_spinlock_repro: counter at 0.000�
thread 'main' panicked at 'assertion failed: buf[0] > b\'0\'', ~/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/num/flt2dec/mod.rs:189:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
abort() was called at PC 0x4200962e on core 0
0x4200962e - _ZN11panic_

On the dev profile It doesn't happen, f32 and f64 print normally.
If I enable debug-assertions but not overflow-checks for `release, I get a panic in float formatting:

I (371) esp_spinlock_repro: counter at 0
I (381) esp_spinlock_repro: counter at 1
I (391) esp_spinlock_repro: counter at 2
thread 'main' panicked at 'assertion failed: f >= (1 << 63)', ~/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/num/diy_float.rs:68:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
abort() was called at PC 0x4202003e on core 0
0x4202003e - panic_abort::__rust_start_panic::abort
    at ~/.rustup/toolchains/esp/lib/rustlib/src/rust/library/panic_abort/src/lib.rs:42

And if I enable overflow-checks, everything seems to work , regardless of debug-assertions being enabled or not.

[MabezDev]

This issue has been found and fixed with this commit in llvm: espressif/llvm-project@7c941f4 we expect to close this issue (for good this time :D) with the 1.66.0.0 rust release :).