esp-rs / esp-println Goto Github PK

Update with esp-rs/esp-backtrace#48 changes

I try to collect traces from the execution of a program on an ESP32C3 via UART with a serial console on my PC but it does not work.

I can upload and run a minimalist blinky program without problem. I then use cargo espmonitor --chip esp32c3 /dev/ttyUSB0 and I get the println! messages ("switching LED"):

❯ cargo espmonitor --chip esp32c3 /dev/ttyUSB0
ESPMonitor 0.10.0

Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

Opening /dev/ttyUSB0 with speed 115200
WARNING: Unable to open flash image /home/jeancf/Documents/esp32-c3/barebones/target/riscv32imc-esp-espidf/debug/barebones: No such file or directory (os error 2)
Resetting device... done
ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6100,len:0x172c
load:0x403ce000,len:0x928
load:0x403d0000,len:0x2ce0
SHA-256 comparison failed:
Calculated: f75e5faaee9719bd137d0b01302b9f3a1088de2f9e75b28595c121f9aa850912
Expected: 7060ddceb031623b32a44a14bd182ec3ffe6abf45dfcafbbd77d04f329a4974c
Attempting to boot anyway...
entry 0x403ce000
I (48) boot: ESP-IDF v4.4-dev-2825-gb63ec47238 2nd stage bootloader
I (49) boot: compile time 12:10:40
I (49) boot: chip revision: 3
I (52) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (59) boot.esp32c3: SPI Speed      : 80MHz
I (64) boot.esp32c3: SPI Mode       : DIO
I (68) boot.esp32c3: SPI Flash Size : 2MB
I (73) boot: Enabling RNG early entropy source...
I (79) boot: Partition Table:
I (82) boot: ## Label            Usage          Type ST Offset   Length
I (89) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (97) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (104) boot:  2 factory          factory app      00 00 00010000 001f0000
I (112) boot: End of partition table
I (116) boot_comm: chip revision: 3, min. application chip revision: 0
I (123) esp_image: segment 0: paddr=00010020 vaddr=3c010020 size=027e4h ( 10212) map
I (133) esp_image: segment 1: paddr=0001280c vaddr=00000000 size=0d80ch ( 55308) 
I (148) esp_image: segment 2: paddr=00020020 vaddr=42000020 size=0d670h ( 54896) map
I (157) boot: Loaded app from partition at offset 0x10000
I (157) boot: Disabling RNG early entropy source...
switching LED
switching LED
switching LED
switching LED

However, when I try to connect with a serial console (minicom -D /dev/ttyUSB0 configured with 115200 8N1) I get no output. I also notice that the execution of the program is suspended on the controller while minicom is running (LED does not blink anymore).

Is this the expected behaviour? What do I need to do to get serial output?

Given that Printer can essentially be created as many times as we want by virtue of it not being a singleton, &mut self doesn't actually guarantee against concurrent access to the registers being operated on. So why is this not unsound?
I could see it being sound if the critical section was always present, but its not, depending on the feature flags.

I know that in single core systems the volatile writes/reads probably are atomic so that should free of data races, but what about multicore systems like the esp32 and esp32s3? And if we take a very pedantic view on it, volatile writes are != atomic writes so this is still undefined behavior and could be a data race.

Furthermore I would expect that if I am writing to a peripheral, there would be some state in it that has some state sensitive to race conditions, such as the FIFO queues etc, racy not just in terms of "my data is being interleaved" but rather actually causing the peripheral to be in an invalid state (I'm less sure about this because I'm not sure if any of these peripherals would actually have race conditions like that).

I wanted to build on esp-println to implement a defmt global logger, since defmt is great and esp support for defmt is still nascent.

I ended up making defmt_esp_println, and thought it might be helpful for others too, so I wanted to create this issue. Was unsure if this would make more sense to live inside this repo or the esp-rs organization or not. Feel free to close it if its not helpful or too unrelated.

The newest nightly seems to have broken this:

error[E0658]: use of unstable library feature 'core_intrinsics': intrinsics are unlikely to ever be stabilized, instead they should be used through stabilized interfaces in the rest of the standard library
  --> /Users/jesse/.cargo/registry/src/github.com-1ecc6299db9ec823/esp-println-0.2.0/src/rtt.rs:64:9
   |
64 |         core::intrinsics::copy_nonoverlapping(
   |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   |
   = help: add `#![feature(core_intrinsics)]` to the crate attributes to enable

For more information about this error, try `rustc --explain E0658`.
error: could not compile `esp-println` due to previous error
warning: build failed, waiting for other jobs to finish...

If using the builtin USB-JTAG interface, esp-println tends to misbehave differently under different circumstances. The issues are most visible using defmt but I'm not sure if this issue is defmt-specific:

• with uart a simple defmt demo stops working after a few seconds
• with uart a real-world application works, but can lag if the same output is printed multiple times
• with serial_jtag the simple demo works exactly as expected
• with serial_jtag the real-world application sometimes outputs defmt frames that espflash can't parse.

That one feature works in one application, the other in another, but they won't work when switched around is weird.

Reproduction: https://github.com/bugadani/esp32s3-defmt-example (current state is working as expected, switching to uart does not.)

I experience my issues on Windows 11 which may or may not affect it

I have a very simple app:

#![no_std]
#![no_main]

use esp_backtrace as _;
use esp_println::println;
use hal::entry;
#[entry]
fn main() -> ! {
    esp_println::logger::init_logger_from_env();
    println!("{:#04x}", 0xFFFF_FFFF_FFFF_FFFFu64);
    loop {}
}

and a very simple Cargo.toml

[package]
#.....

[dependencies]
hal = { package = "esp32c6-hal", version = "0.5.0" }
esp-backtrace = { version = "0.8.0", features = ["esp32c6", "panic-handler", "exception-handler", "print-jtag-serial"] }
esp-println = { version = "0.6.0", features = ["esp32c6", "log", "jtag_serial"], default-features = false}

When i type cargo run i get the following output:

   Compiling esp-backtrace v0.8.0
   Compiling u64print v0.1.0 (/tmp/u64print)
    Finished dev [unoptimized + debuginfo] target(s) in 0.25s
     Running `espflash flash --monitor target/riscv32imac-unknown-none-elf/debug/u64print`
[2023-10-26T13:07:10Z INFO ] Serial port: '/dev/ttyACM0'
[2023-10-26T13:07:10Z INFO ] Connecting...
[2023-10-26T13:07:11Z INFO ] Using flash stub
Chip type:         esp32c6 (revision v0.0)
Crystal frequency: 40MHz
Flash size:        8MB
Features:          WiFi 6, BT 5
MAC address:       40:4c:ca:45:60:2c
App/part. size:    188,880/8,323,072 bytes, 2.27%
[00:00:00] [========================================]      13/13      0x0                                                                                                                
[00:00:00] [========================================]       1/1       0x8000                                                                                                             
[00:00:01] [========================================]      74/74      0x10000                                                                                                            [2023-10-26T13:07:13Z INFO ] Flashing has completed!
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0xc (SPI_FAST_FLASH_BOOT)
Saved PC:0x408007fe
0x408007fe - software_reset_cpu
    at ??:??
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
0x4086c410 - __global_pointer$
    at ??:??
load:0x4086e610,len:0x2d68
0x4086e610 - __global_pointer$
    at ??:??
load:0x40875720,len:0x1800
0x40875720 - __global_pointer$
    at ??:??
SHA-256 comparison failed:
Calculated: 377c26481ad6ab0cce508450f353a55f4bd7eb9159aaf85fde3111071f164514
Expected: 0af544a033ab3492852b8232c904c578d5f07c9d4a423a64473f060db374ab32
Attempting to boot anyway...
entry 0x4086c410
0x4086c410 - __global_pointer$
    at ??:??
I (41) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (42) boot: compile time Jun  7 2023 08:02:08
I (43) boot: chip revision: v0.0
I (46) boot.esp32c6: SPI Speed      : 40MHz
I (51) boot.esp32c6: SPI Mode       : DIO
I (56) boot.esp32c6: SPI Flash Size : 8MB
I (61) boot: Enabling RNG early entropy source...
I (66) boot: Partition Table:
I (70) boot: ## Label            Usage          Type ST Offset   Length
I (77) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (84) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (92) boot:  2 factory          factory app      00 00 00010000 007f0000
I (99) boot: End of partition table
I (103) esp_image: segment 0: paddr=00010020 vaddr=42000020 size=25fech (155628) map
I (144) esp_image: segment 1: paddr=00036014 vaddr=40808000 size=00014h (    20) load
I (145) esp_image: segment 2: paddr=00036030 vaddr=42026030 size=07100h ( 28928) map
I (155) esp_image: segment 3: paddr=0003d138 vaddr=40808014 size=0106ch (  4204) load
I (159) boot: Loaded app from partition at offset 0x10000
I (164) boot: Disabling RNG early entropy source...
0xffffffffffffffff
0xffffffff - _rtc_fast_data_end
    at ??:??

What is that last line?

I tried to create a PR and had a lot of trouble, because the code isn't formatted with rustfmt. I therefore needed to manually go through and delete everything that got formatted, so that I didn't submit a bunch of formatting noise and risk getting my PR rejected.

Would it be ok to add a rustfmt.toml file to the repo to indicate that the use of an autoformatter is permissible in PRs and define the format?

Would be nice to have this documented :)

We should document the available features in the readme. Also we should note conflicts with default features. eg: If you enable rtt, defatuls-features must be false, otherwise there will be a conflict with uart

When using the library (0.6) from an embassy task (using log::info!), my program always gets stuck on https://github.com/esp-rs/esp-println/blob/main/src/lib.rs#L173 . I've tried this with the critical-section flag enabled and disabled. https://github.com/espressif/esp-idf/blob/master/components/esp_rom/include/esp32/rom/uart.h#L230 suggests that the function will block until the FIFO (guess this is defined in the ROM) is empty. Are you aware of how that FIFO is serviced? I'm trying to pin down where I might be causing this to block. My suspects are currently either embassy-futures, embassy-sync (channels) or esp-wifi.

I also saw that there is a workaround for the S2, what type of flaky did you experience that required that fix? I haven't looked into the details of that fix but that seems like you're bypassing the UART driver but I did not spot where you got the 0x3f400004 and 0x3f400010 addresses from.

Thanks for any hints you can provide on this.

While it's not a problem it's annoying to see that in build logs

Consider the following loop and output:

loop { 
      defmt::println!("Loop... {}", x);
      x += 1;
      delay.delay_ms(500u32);
      if x > 10 {
          defmt::println!("About to use println!");
          esp_println::println!("Loop {}", x);
      }
  }

Loop... 0
Loop... 1
Loop... 2
Loop... 3
Loop... 4
Loop... 5
Loop... 6
Loop... 7
Loop... 8
Loop... 9
Loop... 10
 WARN session_drop: probe_rs::session: Could not clear all hardware breakpoints: Riscv(AbstractCommand(HaltResume))
 WARN session_drop: probe_rs::session: Failed to deconfigure device during shutdown: Riscv(AbstractCommand(HaltResume))
 INFO probe_rs: Wrote log to "/home/mabez/.local/share/probe-rs/1699374676691.log"
Error: Unrecoverable error while decoding Defmt data and some data may have been lost: Malformed

By extension of this issue, esp-backtrace is broken in this configuration because it uses esp_println::println!.

Hi. It seems esp-println cannot fully support ESP8266 or something wrong with my setup or board. I know that ESP8266 is quite old and is not actively supported but decided to create issue if someone else will encounter this issue.

println!

Trying to print with println!("any string") works fine, but when I use formatting string to actually add some variables, the board does not print any output e.g. println!("delay {}ms", 1u8).

If I change the print statement to println!("delay {}ms", -1i8); I see the following output repeatedly:

Fatal exception (2): 
epc1=0x3ffe848c, epc2=0x00000000, epc3=0x00000000, excvaddr=0x3ffe848c, depc=0x00000000
0x3ffe848c - _data_end
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??
0x3ffe848c - _data_end
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??

But if I flash the board with cargo run --release it works in both cases above.

dbg!

And final observation, using dbg! causes errors.

    let mut i = 0u8;
    loop {
        i += 1;
        dbg!(i);
        timer1.delay_ms(100);
    }

If using cargo run will output rubbish indefinitely.
And using cargo run --release will output the following error repeatedly

Fatal exception (2): 
epc1=0x3ffe8050, epc2=0x00000000, epc3=0x00000000, excvaddr=0x3ffe8050, depc=0x00000000
0x3ffe8050 - _rodata_start
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??
0x3ffe8050 - _rodata_start
    at ??:??
0x00000000 - XT_STK_PC
    at ??:??

Cargo.toml and main.rs

main.rs

#![no_std]
#![no_main]

use esp8266_hal::prelude::*;
use esp8266_hal::target::Peripherals;
use esp_println::{dbg, print, println};
use panic_halt as _;

#[entry]
fn main() -> ! {
    let dp = Peripherals::take().unwrap();
    let (mut timer1, _) = dp.TIMER.timers();

    loop {
        println!("main loop delaying for {}ms", 1u8);
        // println!("a");
        // dbg!("hello");
        timer1.delay_ms(1500);
    }
}

Cargo.toml

[package]
name = "esp8266"
version = "0.1.0"
edition = "2021"
readme = "README.md"

[dependencies]
esp-println = { version = "0.5.0", default-features = false, features = [
    "esp8266",
    "uart",
] }
esp8266-hal = "0.5.1"
panic-halt = "0.2.0"

[profile.dev]
lto = true
opt-level = "z"
debug = false
overflow-checks = false

[profile.release]
lto = true
opt-level = "s"

Hello, I tried to update this crate in my existing no-std project from 0.3.1 to 0.4.0 but it is not building. I am using a esp32c3 board without a serial bridge, and 0.3.1 was working fine.

esp-println = { version = "0.4.0", features = ["esp32c3", "jtag_serial"] } results in the error: Exactly 1 communication method must be enabled via its Cargo feature, 2 provided.

esp-println = { version = "0.4.0", default-features = false, features = ["esp32c3", "jtag_serial"] } results in the error: Exactly 1 communication method must be enabled via its Cargo feature, 0 provided

Tried many other combinations too.

Anything blocking us from atleast a 0.1 release?

While an example wouldn't really help to understand the usage of the library it would make it easier to smoke-test things on PRs

@jessebraham pointed out it's not possible to have two versions of esp-println targetting different chips. Adding the log facade means we can instrument logging in libraries without depending on esp-println directly.

All the docs.rs builds fail since the beginning.
Here're the logs for the last one in September and it failed:

https://docs.rs/crate/esp-println/0.3.1/builds/633020

See https://doc.rust-lang.org/std/macro.println.html

On all platforms, the newline is the LINE FEED character (\n/U+000A) alone (no additional CARRIAGE RETURN (\r/U+000D)).

We shouldn't have this feature in the first place and it just was a workaround for environments which were not able to deal with just a LINE FEED

I've generated a template project (cargo generate esp-rs/esp-template --name test -d mcu=esp32c3 -d advanced=false), updated the esp-println feature to esp-println = { git = "https://github.com/esp-rs/esp-println", features = ["esp32c3", "defmt"] }, included the defmt crate and tried several things:

• If we use espflash v2.1.0 which does not have defmt support:
  • esp_println::println!("Hello world!") prints the message
  • Using any defmt macro results in a linker error, which I guess is expected
• If we use espflash v2.1.1-dev (main branch) with defmt feature
  • defmt::println!("Hello world!") results in a linker error
  • defmt::debug!("Hello world!") builds but does not print the message, same for defmt::info and defmt::warn
  • defmt::error! results in a linker error
  • esp_println::println prints the message fine
• If we use espflash v2.1.1-dev (main branch) with defmt feature
  • defmt::println!("Hello world!") results in a linker error
  • defmt::debug!("Hello world!") builds but does not print the message, same for defmt::info and defmt::warn
  • defmt::error! results in a linker error
  • esp_println::println prints the message fine
    Using the defmt-raw instead of the defmt feature in esp-println results in similar outputs.

cc @bugadani

Sometimes it seems like writing to UART via the ROM functions is a bit flaky on ESP32-S2
Don't have an example to reproduce currently but maybe let us keep an eye on this

I want to implement a defmt global logger using esp-println. Defmt writes &[u8] rather than &str.

It looks like the implementation of esp-println just writes my_str.as_bytes() anyway, so can the ability to just print bytes be added?

Otherwise, I must unsoundly turn my &[u8] into a &str and then pass it to esp-println

While esp-backtrace uses esp_println::println! which bypasses defmt, the two still doesn't play nice together. defmt prints the panic message, then fires the panic handler, but in there the println! calls don't seem to do anything. defmt::println!, however, works.

Neither jtag_serial nor uart output options work.

Using esp-println/log seems to work just fine.