mass-erase not working properly on STM32F405
Multiplatform USB DFU host utility
Brought to you by:
tormod
I'm using the latest dfu-util built from source (hash e123655469e1ef0a12f0a422583e9f480bc28af5)
I'm running on ubuntu 14.04 LTS.
I'm working with an STM32F405. Normal programming seems to be working fine.
If I try to do a mass erase, it says that it failed, even though the mass erase seems to actually work (the entire flash appears to be all 0xff's).
dfu-util -vvvvvvvvvv -s :mass-erase:force -a 0 -d 0483:df11 -D build-PYBV10/firmware.dfu
dfu-util 0.8
Copyright 2005-2009 Weston Schmidt, Harald Welte and OpenMoko Inc.
Copyright 2010-2014 Tormod Volden and Stefan Schmidt
This program is Free Software and has ABSOLUTELY NO WARRANTY
Please report bugs to http://sourceforge.net/p/dfu-util/tickets/
DFU suffix version 11a
libusbx: debug [libusb_get_device_list]
libusbx: debug [discovered_devs_append] need to increase capacity
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [parse_configuration] skipping descriptor 0xb
libusbx: debug [parse_endpoint] skipping descriptor 25
libusbx: debug [parse_endpoint] skipping descriptor 25
libusbx: debug [parse_endpoint] skipping descriptor 25
libusbx: debug [parse_endpoint] skipping descriptor b
libusbx: debug [parse_endpoint] skipping descriptor 25
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [parse_endpoint] skipping descriptor 21
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_open] open 5.17
libusbx: debug [usbi_add_pollfd] add fd 11 events 4
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=4
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=4
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=112
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=112
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=4
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=4
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=26
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=26
libusbx: debug [libusb_close]
libusbx: debug [usbi_remove_pollfd] remove fd 11
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
libusbx: debug [libusb_get_device_descriptor]
libusbx: debug [libusb_get_config_descriptor] index 0
Opening DFU capable USB device...
libusbx: debug [libusb_open] open 5.17
libusbx: debug [usbi_add_pollfd] add fd 11 events 4
ID 0483:df11
Run-time device DFU version 011a
Claiming USB DFU Interface...
libusbx: debug [libusb_claim_interface] interface 0
Setting Alternate Setting #0 ...
libusbx: debug [libusb_set_interface_alt_setting] interface 0 altsetting 0
Determining device status: libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=6
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=6
state = dfuERROR, status = 10
dfuERROR, clearing status
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=0
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=0
Determining device status: libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=6
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=6
state = dfuIDLE, status = 0
dfuIDLE, continuing
DFU mode device DFU version 011a
Device returned transfer size 2048
DfuSe interface name: "Internal Flash "
Memory segment at 0x08000000 4 x 16384 = 65536 (rew)
Memory segment at 0x08010000 1 x 65536 = 65536 (rew)
Memory segment at 0x08020000 7 x 131072 = 917504 (rew)
Performing mass erase, this can take a moment
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=1
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=1
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=0 transferred=6
libusbx: debug [handle_control_completion] handling completion status 0
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=6
Poll timeout 100 ms
libusbx: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
..... There is about a 4-5 second pause here .....
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [handle_events] timerfd triggered
libusbx: debug [libusb_cancel_transfer]
libusbx: debug [disarm_timerfd]
libusbx: debug [libusb_handle_events_timeout_completed] doing our own event handling
libusbx: debug [handle_events] poll() 4 fds with timeout in 60000ms
libusbx: debug [handle_events] poll() returned 1
libusbx: debug [reap_for_handle] urb type=2 status=-2 transferred=0
libusbx: debug [handle_control_completion] handling completion status -2
libusbx: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
libusbx: debug [disarm_timerfd]
libusbx: debug [usbi_handle_transfer_completion] transfer 0x16ee068 has callback 0x7f4394c6b7f0
libusbx: debug [sync_transfer_cb] actual_length=0
dfu-util: Error during special command "MASS_ERASE" get_status
Anonymous
So it seems the mass erase itself was successful, but it is unclear what to expect from the device once the erase has been initiated. AN3156 talks about "erase" returning to an dfuDNLOAD-IDLE state but is not specific about sector or mass erase, and at the same time the diagram shows the mass erase as a box with no continuation.
In any case it seems there is a silicon bug here since the bootloader returns a poll timeout of only 100 ms, whereas it might not be pollable before the mass erase has completed, which can take between 7 and 31 seconds on STM32F405.
The 5 second pause you see is probably something hardcoded in libusbx.
Can you please try, for instance, setting dst.bwPollTimeout to 35000 inside the "if (firstpoll)" clause in dfuse.c? Depending on operating voltage and the parallel erase settings in the option bytes this might be longer than needed though. Not easy for dfu-util to figure out if the reported bwPollTimeout is not correct.
SourceForge seems to have totally messed up the indentation.
Here's the patch I did: https://pastebin.mozilla.org/8838185
Setting bwPollTimeout to 35000 seems to have gotten past the mass-erase step and it's started to download. However it seems to be taking 35 seconds for each 2K to download, which means it will take about 75 minutes to download 256K :)
If I change it (in the somewhat hacky fashion) as follows:
then it will perform the mass erase and download the image afterwards.
(The indentation was at least fine in the e-mail notification I got)
Oops, that code is used for all dfuse special commands :) You are right about conditioning the workaround with command == MASS_ERASE. On the other hand the "else" clause should not be needed.
Thanks for trying this out. So indeed the device remains accessible after the erase, we just need to wait 350 times longer than it says :) In the cousin stm32flash project, where the serial interface is used and there is no means to communicate a poll timeout, we have hardcoded 35 seconds pause after mass erase. Maybe we can add a quirk here as well, at least for devices returning 100 ms and some other filter criteria. It would be good to know which devices report wrong poll timeout and what their maximum mass erase time is.
An alternative way would be to ignore USB timeouts after mass erase and keep on trying until a reasonable time has passed.
I have applied a workaround overriding the timeout to 35 seconds if the device reports 100 ms on mass erase.
https://sourceforge.net/p/dfu-util/dfu-util/ci/47af500fc7ecce434981b15b0dcb77e707afe420/