search

probe-rs / embedded-test

A test harness and runner for embedded devices
67 stars 10 forks source link

semihosting sys_get_cmdline fails on stm32 / cortex-m4 #34

Closed tomhampshire closed 5 months ago

tomhampshire commented 5 months ago

embedded-test throws the following error, when being run against a minimal project on a NUCLEO-F303ZE. Steps to reproduce the error are in the referenced repository. 

ERROR !! A panic occured: "PanicInfo { payload: Any { .. }, message: Some(assertion `left == right` failed\n  left: 255\n right: -1), location: Location { file: \"/home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs\", line: 221, col: 9 }, can_unwind: true, force_no_backtrace: false }"
└─ embedded_test::panic @ /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/embedded-test-0.4.0/src/fmt.rs:62  
Frame 0: syscall_readonly @ 0x080077ee
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/arm.rs:88:9
Frame 1: sys_exit_extended @ 0x080078c0
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:198:2
Frame 2: <unknown function @ 0x00020026> @ 0x00020026
Error: Unexpected semihosting command Unknown(UnknownCommandDetails { operation: 0, parameter: 536930668 }) cmdline_requested: true
error: test failed, to rerun pass `--test simple_test`

Caused by:
  process didn't exit successfully: `probe-rs run --chip STM32F303ZETx /home/tom/code/GSP/embedded-test-issue/minimal-firmware/target/thumbv7em-none-eabihf/debug/deps/simple_test-b5bfa186850e5427` (exit status: 1)
tomhampshire commented 5 months ago

probe-rs 0.24.0 (git commit: crates.io)

t-moe commented 5 months ago

Thanks a lot for creating a minimal example showing the problem.

Could you also add the debug logs of probe-rs? e.g. by appending --report to the probe-rs command line: probe-rs run --chip STM32F303ZETx /home/tom/code/GSP/embedded-test-issue/minimal-firmware/target/thumbv7em-none-eabihf/debug/deps/simple_test-b5bfa186850e5427 --report

This would help a lot, since I dont have a stm32 here at the moment. I might be able to organize one, but the trace output of probe-rs will probably also indicate where the issue lies already...

tomhampshire commented 5 months ago

So, the output is as below, but the probe-rs process does not terminate. It fires up 4 threads. One runs continuously at 100% and the other 3 sit idle at 0%. I've had this running for a few minutes now and none of the threads terminate...

      Erasing ✔ [00:00:01] [#########################################################################################] 60.00 KiB/60.00 KiB @ 37.72 KiB/s (eta 0s )
  Programming ✔ [00:00:04] [#########################################################################################] 60.00 KiB/60.00 KiB @ 14.15 KiB/s (eta 0s )    Finished in 5.854s
Frame 0: syscall_readonly @ 0x080077ee
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/arm.rs:88:9
Frame 1: sys_exit_extended @ 0x080078c0
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:198:2
Frame 2: <unknown function @ 0x00020026> @ 0x00020026
tomhampshire commented 5 months ago

I can run in release mode, with a similar result (does not terminate). This time I have 2 threads which both run at 100% but do not terminate. cargo test --release -- --report produces:

Frame 0: syscall_readonly @ 0x0800081a inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/arm.rs:88:9
Frame 1: syscall0 @ 0x0000000008000814 inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/mod.rs:91:14
Frame 2: sys_errno @ 0x0000000008000814 inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:158:24
Frame 3: sys_get_cmdline @ 0x0000000008000814 inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:222:38
Frame 4: args_bytes<1024> @ 0x0000000008000448 inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/experimental/env.rs:104:17
Frame 5: args<1024> @ 0x0000000008000432 inline
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/experimental/env.rs:14:5
Frame 6: run_tests<113> @ 0x0000000008000432
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/embedded-test-0.4.0/src/export.rs:56:21
Frame 7: {closure#0} @ 0x08000ecc
       /home/tom/code/GSP/embedded-test-issue/minimal-firmware/tests/simple_test.rs:5:1
t-moe commented 5 months ago

--report should actually generate a report.zip in the current folder. But its possible that this is only written if probe-rs terminates sucessfully :thinking:

What I need are the debug logs of probe-rs. You can probably also get them by setting the RUST_LOG=debug env variable.

tomhampshire commented 5 months ago

I've copied the trace from the point (I think) that the flash writing is complete:

TRACE session_drop:debug_core_stop: probe_rs::probe::stlink::usb_interface: USB write done!
TRACE async_io::main_loop: async_io::driver: notified
TRACE async_io::main_loop: async_io::driver: waiting on I/O
TRACE session_drop:debug_core_stop:get_last_rw_status: probe_rs::probe::stlink::usb_interface: Sending command [f2, 3e] to STLink, timeout: 1s
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: nusb::platform::linux_usbfs::device: Submitted URB 0x593816fdd5e0 on ep 1    
TRACE session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: async_io::driver: sleep until notification
TRACE async_io::main_loop:react:Poller::wait:wait: polling::epoll: new events epoll_fd=5 res=1 timeout=None epoll_fd=5 timeout=None
DEBUG nusb::platform::linux_usbfs::device: Handling events for device 0    
DEBUG nusb::platform::linux_usbfs::device: URB 0x593816fdd5e0 for ep 1 completed, status=0 actual_length=16    
TRACE session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: async_io::driver: completed
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: nusb::platform::linux_usbfs::device: Submitted URB 0x593816fdd5e0 on ep 81    
TRACE session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: async_io::driver: sleep until notification
TRACE async_io::main_loop:react: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop: async_io::driver: sleeping for 50 us
TRACE async_io::main_loop: async_io::driver: notified
TRACE async_io::main_loop: async_io::driver: waiting on I/O
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG nusb::platform::linux_usbfs::device: Handling events for device 0    
DEBUG nusb::platform::linux_usbfs::device: URB 0x593816fdd5e0 for ep 81 completed, status=0 actual_length=12    
TRACE session_drop:debug_core_stop:get_last_rw_status:async_io::block_on: async_io::driver: completed
TRACE session_drop:debug_core_stop:get_last_rw_status: probe_rs::probe::stlink::usb_interface: Read 12 bytes, 0 bytes remaining
TRACE async_io::main_loop:react:Poller::wait:wait: polling::epoll: new events epoll_fd=5 res=1 timeout=Some(999.93601ms) epoll_fd=5 timeout=Some(999.935919ms)
TRACE probe_rs::probe::stlink: Getting current mode of device...
TRACE probe_rs::probe::stlink::usb_interface: Sending command [f5] to STLink, timeout: 1s
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG async_io::block_on: nusb::platform::linux_usbfs::device: Submitted URB 0x593816fdd5e0 on ep 1    
TRACE async_io::block_on: async_io::driver: sleep until notification
TRACE async_io::main_loop:react: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop: async_io::driver: sleeping for 50 us
TRACE async_io::main_loop: async_io::driver: notified
DEBUG nusb::platform::linux_usbfs::device: Handling events for device 0    
DEBUG nusb::platform::linux_usbfs::device: URB 0x593816fdd5e0 for ep 1 completed, status=0 actual_length=16    
TRACE async_io::main_loop: async_io::driver: waiting on I/O
TRACE async_io::block_on: async_io::driver: completed
DEBUG async_io::block_on: nusb::platform::linux_usbfs::device: Submitted URB 0x593816fdd5e0 on ep 81    
TRACE async_io::block_on: async_io::driver: sleep until notification
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG nusb::platform::linux_usbfs::device: Handling events for device 0    
DEBUG nusb::platform::linux_usbfs::device: URB 0x593816fdd5e0 for ep 81 completed, status=0 actual_length=2    
TRACE async_io::block_on: async_io::driver: completed
TRACE probe_rs::probe::stlink::usb_interface: Read 2 bytes, 0 bytes remaining
DEBUG probe_rs::probe::stlink: Current device mode: Jtag
TRACE probe_rs::probe::stlink::usb_interface: Sending command [f2, 21] to STLink, timeout: 1s
TRACE async_io::main_loop:react:Poller::wait:wait: polling::epoll: new events epoll_fd=5 res=1 timeout=Some(999.91394ms) epoll_fd=5 timeout=Some(999.91383ms)
DEBUG async_io::block_on: nusb::platform::linux_usbfs::device: Submitted URB 0x593816fdd5e0 on ep 1    
TRACE async_io::block_on: async_io::driver: sleep until notification
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop:react: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop: async_io::driver: sleeping for 50 us
TRACE async_io::main_loop: async_io::driver: notified
DEBUG nusb::platform::linux_usbfs::device: Handling events for device 0    
DEBUG nusb::platform::linux_usbfs::device: URB 0x593816fdd5e0 for ep 1 completed, status=0 actual_length=16    
TRACE async_io::main_loop: async_io::driver: waiting on I/O
TRACE async_io::block_on: async_io::driver: completed
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
DEBUG nusb::platform::linux_usbfs::device: Released interface 0 on device 0: Ok(())    
DEBUG nusb::platform::linux_usbfs::device: Closing device 0    
TRACE async_io::main_loop:react:Poller::wait:wait: polling::epoll: new events epoll_fd=5 res=1 timeout=Some(999.863135ms) epoll_fd=5 timeout=Some(999.863065ms)
Error: Unexpected semihosting command Unknown(UnknownCommandDetails { operation: 0, parameter: 536930668 }) cmdline_requested: true
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop:react: async_io::reactor: 0 ready wakers
TRACE async_io::main_loop: async_io::driver: waiting on I/O
TRACE async_io::main_loop:react:process_timers: async_io::reactor: 0 ready wakers
error: test failed, to rerun pass `--test simple_test`
t-moe commented 5 months ago

unfortunately, I cannot spot the relevant output. can you rerun with RUST_LOG="probe_rs::cmd=debug" ?

tomhampshire commented 5 months ago 
 INFO probe_rs::cmd::run::test_run_mode: libtest args Arguments { include_ignored: false, ignored: false, test: false, bench: false, list: false, nocapture: false, show_output: false, unstable_flags: None, exact: false, quiet: false, test_threads: Some(1), logfile: None, skip: [], color: None, format: None, filter: None }
DEBUG probe_rs::cmd::run::test_run_mode: target asked for cmdline. send 'list'
ERROR !! A panic occured: "PanicInfo { payload: Any { .. }, message: Some(assertion `left == right` failed\n  left: 255\n right: -1), location: Location { file: \"/home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs\", line: 221, col: 9 }, can_unwind: true, force_no_backtrace: false }"
└─ embedded_test::panic @ /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/embedded-test-0.4.0/src/fmt.rs:62  
Frame 0: syscall_readonly @ 0x080077ee
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/arm.rs:88:9
Frame 1: sys_exit_extended @ 0x080078c0
       /home/tom/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:198:2
Frame 2: <unknown function @ 0x00020026> @ 0x00020026
Error: Unexpected semihosting command Unknown(UnknownCommandDetails { operation: 0, parameter: 536930668 }) cmdline_requested: true
error: test failed, to rerun pass `--test simple_test`
t-moe commented 5 months ago

Thank you, thats helpful. This indeed looks like a problem on our side... We possibly broke semihosting for arm with the latest embedded-test PR.

EDIT: Found a Nucleo-144 somewhere (stm32f767, which is the same architecture) and I can reproduce the issue.

Notes to myself:

tomhampshire commented 5 months ago

No problem. Thank you for looking into the issue! If there's anything else I can run on my side to help troubleshoot the issue, please let me know.

skibon02 commented 5 months ago

Same issue here on AT32F437 microcontroller (cortex-m4) but slightly different:

Frame 0: syscall_readonly @ 0x08004ebe inline
       /home/skygrel19/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/syscall/arm.rs:88:9
Frame 1: sys_exit_extended @ 0x0000000008004ebc inline
       /home/skygrel19/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:196:9
Frame 2: exit @ 0x0000000008004eb0 inline
       /home/skygrel19/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/sys/arm_compat/mod.rs:165:5
Frame 3: exit @ 0x0000000008004eb0
       /home/skygrel19/.cargo/registry/src/index.crates.io-6f17d22bba15001f/semihosting-0.1.10/src/process.rs:14:5
Frame 4: panic_cold_display<i32> @ 0x08004ede
       /rustc/bdbbb6c6a718d4d196131aa16bafb60e850311d9/library/core/src/panic.rs:98:1
Error: Unexpected semihosting command Unknown(UnknownCommandDetails { operation: 0, parameter: 536879848 }) cmdline_requested: true

I use master branch version of probe-rs.

skibon02 commented 5 months ago

Output when using embeddet-test 0.3.0 with same latest version of probe-rs:

 WARN probe_rs::cmd::run::normal_run_mode: Target wanted to run semihosting operation SYS_GET_CMDLINE, but probe-rs does not support this operation yet. Continuing...
t-moe commented 5 months ago

Ok. I've isolated the problem. Here is a branch of probe-rs that contains a fix: https://github.com/probe-rs/probe-rs/tree/fix/arm_semihosting With this fix is was able to run the minimal project from @tomhampshire on my Nucleo-144 (stm32f767).

It might take a while until we merge this back to master, as the entire "semihosting caching logic" is prone to error and needs a refactoring.

tomhampshire commented 5 months ago

Awesome - thanks. I installed with: cargo install --git https://github.com/probe-rs/probe-rs --branch fix/arm_semihosting probe-rs-tools and I have everything working!

tomhampshire commented 5 months ago

Darn, I'm now getting compile errors on installing this branch:

error[E0658]: use of unstable library feature 'offset_of'
  --> probe-rs/src/rtt/channel.rs:32:9
   |
32 |         std::mem::offset_of!(RttChannelBufferInner<T>, write_offset)
   |         ^^^^^^^^^^^^^^^^^^^
   |
   = note: see issue #106655 <https://github.com/rust-lang/rust/issues/106655> for more information

error[E0658]: use of unstable library feature 'offset_of'
  --> probe-rs/src/rtt/channel.rs:36:9
   |
36 |         std::mem::offset_of!(RttChannelBufferInner<T>, read_offset)
   |         ^^^^^^^^^^^^^^^^^^^
   |
   = note: see issue #106655 <https://github.com/rust-lang/rust/issues/106655> for more information

error[E0658]: use of unstable library feature 'offset_of'
  --> probe-rs/src/rtt/channel.rs:40:9
   |
40 |         std::mem::offset_of!(RttChannelBufferInner<T>, flags)
   |         ^^^^^^^^^^^^^^^^^^^
   |
   = note: see issue #106655 <https://github.com/rust-lang/rust/issues/106655> for more information

@t-moe is there anything I can do about this to get a version of probe-rs to work with v0.4 of embedded-test

t-moe commented 5 months ago

@tomhampshire std::mem::offset_of! has been stabilized in rust 1.77.0. Did you downgrade your compiler? I didnt change a thing on my end...

tomhampshire commented 5 months ago

Woopsie. Yes, I'm working on a different machine. Sorry about that. All sorted now.