wchisp hang after running once

[cjacker]

OS: fedora 36, glibc-2.35, kernel-6.1.9

rust: 1.67.0

wchisp: git and v0.20

Parts: tested with flappyboard and ch32v103

Problem:

run only once, hang on second running.

For example, run 'wchisp probe' once, no matter run 'wchisp xxx' again, it will hang.

Backtrace:

Ctrl-C to stop it, then 'bt'

(gdb) bt
#0  0x00007ffff7d05bcf in poll () from /lib64/libc.so.6
#1  0x00005555556f1c5e in usbi_wait_for_events (ctx=0x5555559cbb10,
    reported_events=0x7fffffff7a00, timeout_ms=60000)
    at libusb/libusb/os/events_posix.c:226
#2  0x00005555556e975b in handle_events (ctx=0x5555559cbb10, tv=0x7fffffff7a50)
    at libusb/libusb/io.c:2244
#3  0x00005555556e9a07 in libusb_handle_events_timeout_completed (ctx=0x5555559cbb10,
    tv=0x7fffffff7a90, completed=0x7fffffff7b2c) at libusb/libusb/io.c:2361
#4  0x00005555556e9b2e in libusb_handle_events_completed (ctx=0x5555559cbb10,
    completed=0x7fffffff7b2c) at libusb/libusb/io.c:2459
#5  0x00005555556ea3f6 in sync_transfer_wait_for_completion (transfer=0x5555559c04c0)
    at libusb/libusb/sync.c:49
#6  0x00005555556ea56e in do_sync_bulk_transfer (dev_handle=0x5555559d7940,
    endpoint=130 '\202', buffer=0x7fffffff7cb8 "", length=64,
    transferred=0x7fffffff7c04, timeout=0, type=2 '\002') at libusb/libusb/sync.c:194
#7  0x00005555556ea690 in libusb_bulk_transfer (dev_handle=0x5555559d7940,
    endpoint=130 '\202', data=0x7fffffff7cb8 "", length=64,
    transferred=0x7fffffff7c04, timeout=0) at libusb/libusb/sync.c:278
#8  0x00005555556126e5 in rusb::device_handle::DeviceHandle<rusb::context::Context>::read_bulk<rusb::context::Context> (self=0x7fffffff90e0, endpoint=130, buf=...,
    timeout=...)
    at /home/cjacker/.cargo/registry/src/git.luolix.top-1ecc6299db9ec823/rusb-0.9.1/src/devi--Type <RET> for more, q to quit, c to continue without paging--
ce_handle.rs:454
#9  0x0000555555611ff6 in wchisp::transport::usb::{impl#1}::recv_raw (
    self=0x7fffffff90e0, timeout=...) at src/transport/usb.rs:105
#10 0x000055555563858b in wchisp::transport::Transport::transfer_with_wait<wchisp::transport::usb::UsbTransport> (self=0x7fffffff90e0, cmd=..., wait=...)
    at src/transport/mod.rs:27
#11 0x0000555555637ff3 in wchisp::transport::Transport::transfer<wchisp::transport::usb::UsbTransport> (self=0x7fffffff90e0, cmd=...) at src/transport/mod.rs:19
#12 0x000055555564011c in wchisp::flashing::Flashing<wchisp::transport::usb::UsbTransport>::get_chip (transport=0x7fffffff90e0) at src/flashing.rs:28
#13 0x000055555559f49d in wchisp::main () at src/main.rs:130

[andelf]

How about v0.1.4?

[cjacker]

How about v0.1.4?

git checkout and rollback to 0.1.4, and got the same result.

Since no 'probe' cmd in 0.1.4, tested with 'wchisp info'. runing once, hang at the second time.

After read the codes, I do NOT think it's a bug of wchisp, but in rusb or libusb or base system, but need to be figured out and report to upstream.

[andelf]

I didn't find a flappyboard with CH32V103.
I have a flappyboard with CH32V203. I'll take a look.

[cjacker]

I didn't find a flappyboard with CH32V103. I have a flappyboard with CH32V203. I'll take a look.

Sorry for confusing.

What I mean is tested with a flappyboard (v203) and another ch32v103 breakout board.

Both have the same result.

[maxgerhardt]

Exact same problem here, using a "CH32V307 EVT by SCDZ" board from here. Running any wchisp command is death sentence for any consecutive wchisp command, it just hangs up. The only way to escape to unbrick the program is to remove the USB device and plug it back in again.

Running latest binary from 02e8d68.

Board info:

max@virtualbox:~/ch32$ sudo ./wchisp info
19:26:45 [INFO] Chip: CH32V307VCT6[0x7017] (Code Flash: 256KiB)
19:26:45 [INFO] Chip UID: 90-D7-3E-26-3B-38-09-36
19:26:45 [INFO] BTVER(bootloader ver): 02.80
19:26:45 [INFO] Code Flash protected: false
19:26:45 [INFO] Current config registers: a55abf40ff00ff00ffffffff
RDPR_USER: 0x40BF5AA5
  [7:0]   RDPR 0xA5 (0b10100101)
    `- Unprotected
  [16:16] IWDG_SW 0x1 (0b1)
    `- IWDG enabled by the software, and disabled by hardware
  [17:17] STOP_RST 0x1 (0b1)
    `- Disable
  [18:18] STANDBY_RST 0x1 (0b1)
    `- Disable, entering standby-mode without RST
  [23:22] SRAM_CODE_MODE 0x2 (0b10)
    `- CODE-256KB + RAM-64KB
DATA: 0x00FF00FF
  [7:0]   DATA0 0xFF (0b11111111)
  [23:16] DATA1 0xFF (0b11111111)
WRP: 0xFFFFFFFF
  `- Unprotected

max@virtualbox:~/ch32$ sudo ./wchisp probe
19:45:13 [INFO] Found 1 devices
19:45:13 [INFO] hint: use `wchisp info` to check chip info
Device #0: CH32V307VCT6[0x7017]
max@virtualbox:~/ch32$ sudo ./wchisp probe
19:45:14 [INFO] Found 1 devices
19:45:14 [INFO] hint: use `wchisp info` to check chip info
<infinite hang>

[andelf]

@maxgerhardt Thanks for your report.
Could you provide more detailed logs using wchisp --verbose?

UPDATE: I can reproduce this on my ArchLinux machine. (🥲I use macOS as the primary dev platform)

[andelf]

@cjacker @maxgerhardt Fixed in v0.2.2 release.

[cjacker]

@cjacker @maxgerhardt Fixed in v0.2.2 release.

Not hang now, but 'probe' still has some issue: running once, the second time will report 'timeout' and other commands not work anymore.

But if I not run 'wchisp probe' at first, not matter run 'wchisp info' for any times, it's ok.

Should reopen this issue?

[maxgerhardt]

On Windows this does not occur with the latest build (using the CI binaries from https://github.com/Community-PIO-CH32V/wchisp/actions/runs/4226243545 for f36a05c)

On Linux (Ubuntu 22.04 in VM) I can confirm that the eternal hangup error is now converted into always returning "Operation Timed Out" after running it once.

max@virtualbox:~/ch32$ sudo ./wchisp probe
21:23:34 [INFO] Found 1 devices
21:23:34 [INFO] hint: use `wchisp info` to check chip info
Device #0: CH32V307VCT6[0x7017]
max@virtualbox:~/ch32$ sudo ./wchisp probe
21:23:35 [INFO] Found 1 devices
21:23:35 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out
max@virtualbox:~/ch32$ sudo ./wchisp probe
21:23:38 [INFO] Found 1 devices
21:23:38 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out

Verbose logs

max@virtualbox:~/ch32$ sudo ./wchisp --verbose probe 
21:25:32 [DEBUG] (1) wchisp::transport::usb: Found WCH ISP USB device #0: [Bus 001 Device 004: ID 4348:55e0]
21:25:32 [INFO] Found 1 devices
21:25:32 [INFO] hint: use `wchisp info` to check chip info
21:25:32 [DEBUG] (1) wchisp::transport::usb: Found USB Device Bus 001 Device 004: ID 4348:55e0
21:25:32 [DEBUG] (1) wchisp::transport: => a11200   00004d4355204953502026205743482e434e
21:25:32 [DEBUG] (1) wchisp::transport: <= a1000200 7017
Device #0: CH32V307VCT6[0x7017]
max@virtualbox:~/ch32$ sudo ./wchisp --verbose probe 
21:25:33 [DEBUG] (1) wchisp::transport::usb: Found WCH ISP USB device #0: [Bus 001 Device 004: ID 4348:55e0]
21:25:33 [INFO] Found 1 devices
21:25:33 [INFO] hint: use `wchisp info` to check chip info
21:25:33 [DEBUG] (1) wchisp::transport::usb: Found USB Device Bus 001 Device 004: ID 4348:55e0
21:25:33 [DEBUG] (1) wchisp::transport: => a11200   00004d4355204953502026205743482e434e
Error: Operation timed out

[andelf]

I have reproduced this bug on my Pop!_OS.
The USB driver behaves differently on different Linux distributions. 🥲

[andelf]

Fixed in 17c853b. I tested on Pop!_OS(should be the same as Ubuntu) & CH32V203.
1μs sleep is required before reading USB packets from MCU.
This might be an implementation restriction on these MCUs.
I haven't tested this on old MCUs.

[maxgerhardt]

I see, I'll retest today. And btw, the Rust CI again did not run to produce the binaries, I think because of the path restrictions in the rust.yml for src when the file was changed in src/transport.

[cjacker]

Fixed in 17c853b. I tested on Pop!_OS(should be the same as Ubuntu) & CH32V203. 1μs sleep is required before reading USB packets from MCU. This might be an implementation restriction on these MCUs. I haven't tested this on old MCUs.

Confirm works !

[maxgerhardt]

I've grabbed the latest binaries from https://github.com/ch32-rs/wchisp/actions/runs/4245422276 and sadly it still doesn't work. Only getting timeout errors after the first time.

max@virtualbox:~/ch32$ ./wchisp probe
11:26:02 [INFO] Found 1 devices
11:26:02 [INFO] hint: use `wchisp info` to check chip info
Device #0: CH32V307VCT6[0x7017]
max@virtualbox:~/ch32$ ./wchisp probe
11:26:03 [INFO] Found 1 devices
11:26:03 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out
max@virtualbox:~/ch32$ ./wchisp probe
11:26:05 [INFO] Found 1 devices
11:26:05 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out
max@virtualbox:~/ch32$ ./wchisp probe
11:26:06 [INFO] Found 1 devices
11:26:06 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out
max@virtualbox:~/ch32$ ./wchisp probe
11:26:07 [INFO] Found 1 devices
11:26:07 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out
max@virtualbox:~/ch32$ ./wchisp probe
11:26:09 [INFO] Found 1 devices
11:26:09 [INFO] hint: use `wchisp info` to check chip info
Error: Operation timed out

max@virtualbox:~/ch32$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 22.10
Release:	22.10
Codename:	kinetic
max@virtualbox:~/ch32$ uname -a
Linux virtualbox 5.19.0-29-generic #30-Ubuntu SMP PREEMPT_DYNAMIC Wed Jan 4 12:14:09 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

[cjacker]

Recently I bought a CH32V305 from Muse Lab, it doesn't work again with CH32V305.

[andelf]

@cjacker I'll check this.

[OpusElectronics]

Hi, same kind of issue here on Arch Linux with a CH32V307. Latest git revision of wchisp, Rust 1.73.0.
I get "operation timed out" very often.

I can confirm the behavior above: a first 'wchisp probe' will work, after that subsequent commands usually fail with "operation timed out".

Also, I tried flashing the MCU with a "wchisp flash" command right after booting the MCU in USB ISP mode.
The command started OK, but ended with a "Pipe error". The flashing was not successful. Here's the output:

[INFO] Chip: CH32V307VCT6[0x7017] (Code Flash: 256KiB)
[INFO] Chip UID: 4F-04-BE-7B-54-50-61-D0
[INFO] BTVER(bootloader ver): 02.90
[INFO] Code Flash protected: false
[INFO] Current config registers: a55a9f6000ff00ffffffffff000209004f04be7b545061d0
RDPR_USER: 0x609F5AA5
  [7:0]   RDPR 0xA5 (0b10100101)
    `- Unprotected
  [16:16] IWDG_SW 0x1 (0b1)
    `- IWDG enabled by the software, and disabled by hardware
  [17:17] STOP_RST 0x1 (0b1)
    `- Disable
  [18:18] STANDBY_RST 0x1 (0b1)
    `- Disable, entering standby-mode without RST
  [23:22] SRAM_CODE_MODE 0x2 (0b10)
    `- CODE-256KB + RAM-64KB
DATA: 0xFF00FF00
  [7:0]   DATA0 0x0 (0b0)
  [23:16] DATA1 0x0 (0b0)
WRP: 0xFFFFFFFF
  `- Unprotected
[INFO] Read xxxx.elf as ELF format
[INFO] Found loadable segment, physical address: 0x00000000, virtual address: 0x00000000, flags: 0x5
[INFO] Section names: [".init", ".vector", ".text"]
[INFO] Found loadable segment, physical address: 0x00000cc0, virtual address: 0x20000000, flags: 0x6
[INFO] Section names: [".data"]
[INFO] Firmware size: 4096
[INFO] Erasing...
[WARN] erase_code: set min number of erased sectors to 8
[INFO] Erased 8 code flash sectors
[INFO] Erase done
[INFO] Writing to code flash...
Error: Pipe error

[Schildkroet]

Hello,

i also have this timeout error. Tested with 3 different boards. Running Ubuntu 22.04 LTS