Debugging 504 DAPLink errors

[microbit-carlos]

Problem to investigate

Some environments are seeing DAPLink 504 time out errors more often than usual.

To debug this issue we've created a test Python script, that combined with a special DAPLink build, captures debug information while continously flashing a microbit.

Download the test programme

People having this issue will be directed to this GitHub issue to run this test programme and report back.

The test programme can be download it in this zip file: copyhex_v1.0.1.zip

Running the test programme

All the information required to run the test script is included in the README.md file inside the zip file.

In essence, there are two steps:

1. Update the micro:bit firmware with a special build included in the daplink folder
2. Connect the micro:bit to the PC and in a terminal run python3 test_cp_file.py

By default the script is configured to run 100 times, which will likely take around 1 hour to complete.
This might seem like a lot, but in some environments we only capture one or two errors per 100 runs.

If you can't run the test for that long, or there are enough failures captured in less runs (for some users this problem is a lot more frequent), then the number of runs can be changed by modifying the TOTAL_RUNS = 100 line at the top of the test_cp_file.py script. Or alternatively, the programme can be stopped at any point by pressing Ctrl+C in the terminal.

Test results

The test results are stored in the serial_output directory.
If you could zip and send us the serial_output folder we can then analyse the results.

[EricPobot]

I've just started the test with a V2.00 board I cannot program anymore because of repeated Err504 when downloading the hex to it from MakeCode.

The test is currently running, but 7 out of 17 runs have failed already. The common point I've noticed is that the mount and unmount delays are very different. When the test passes, they are both null. When it fails, unmounting takes between 18 and 24s and mounting takes between 3 and 6 seconds.

I'll execute the test anyway on a v2.20 board too ASAP.

Maybe this can help, there's a thing I've noticed when programming V1.5 boards. Even if the program hex file is correctly transferred and no anomaly occurs afterwards during the run, a FAIL.TXT file is present on the MICROBIT pseudo disk, with the "error: The transfer timed out." message in it. I could observe this behavior with every micro:bit v1 I've developed applications for since my the very first time.

[EDIT]
I don't know if this is important, but when the Err 504 scenario happens, the same sequence of events can be observed :

• the program is uploaded to the micro:bit
• it starts running and behaves as expected
• the Err 504 messages appears after some delay (can't say how long exactly, but it's at least 10 seconds or more)
• at the same time, the pseudo-disk is mounted (my settings opens the file browser automatically when a new volume is mounted) with the FAIL.TXT file in it

Hope this helps.

[kevinjwalters]

I've just copied my own build of MicroPython onto three boards and one persistently errors (board D) with a 504 error. It's not one I'd seen before but I found https://support.microbit.org/support/solutions/articles/19000129890-fail-txt and this ticket.

I think it's 100% reproducible. This is my pi4. I tried changing USB ports and things didn't improve.

pi4$ ls -l MICROBIT.hex
-r--r--r-- 1 kjw kjw 1240986 Aug 24 23:25 MICROBIT.hex

pi4$ fgrep PRETTY /etc/os-release
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
pi4$ uname -a
Linux pi4 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux

pi4$ time cp MICROBIT.hex /media/kjw/MICROBIT  # this 504ed

real    0m42.887s
user    0m0.001s
sys     0m0.019s

pi4$ time cp MICROBIT.hex /media/kjw/MICROBIT  # this is how long good boards took, but still 504ed

real    0m13.049s
user    0m0.001s
sys     0m0.019s

pi4$ ls -l /media/kjw/MICROBIT
total 136
-r--r--r-- 1 kjw kjw    572 Mar 22  2016 DETAILS.TXT
-r--r--r-- 1 kjw kjw     55 Mar 22  2016 FAIL.TXT
-r--r--r-- 1 kjw kjw    284 Mar 22  2016 MICROBIT.HTM
-r--r--r-- 1 kjw kjw 126976 Mar 22  2016 MY_DATA.HTM
pi4$ cat /media/kjw/MICROBIT/FAIL.TXT
error: The transfer timed out.
type: transient, user

pi4$ cat /media/kjw/MICROBIT/DETAILS.TXT   # same output as my board E (apart from Unique ID)
# DAPLink Firmware - see https://daplink.io
Build ID: v0257-gc782a5ba (gcc)
Unique ID: 9906360200052820396a0eaedb339029000000006e052820
HIC ID: 6e052820
Auto Reset: 1
Automation allowed: 0
Overflow detection: 0
Incompatible image detection: 1
Page erasing: 0
Daplink Mode: Interface
Interface Version: 0257
Bootloader Version: 0257
Git SHA: c782a5ba907377658bc28aa8d132a0fa44543687
Local Mods: 0
USB Interfaces: MSD, CDC, HID, WebUSB
Bootloader CRC: 0x725bea7d
Interface CRC: 0xe561f1de
Remount count: 0
URL: https://microbit.org/device/?id=9906&v=0257

Out of desperation I tried dd without any particular parameters and it worked.

kjw@pi4:~/pwmbugfix/mp-mb-pwmfix-rc1.1.32kfs $ dd if=MICROBIT.hex of=/media/kjw/MICROBIT/MICROBIT.hex
2423+1 records in
2423+1 records out
1240986 bytes (1.2 MB, 1.2 MiB) copied, 13.1123 s, 94.6 kB/s

I've got some other things to do but I can probably dig deeper in a week's time. I'll avoid updating the o/s. Any pointers?

---

I've attached the MICROBIT.hex to end of lancaster-university/codal-nrf52#59 (comment) in a zip file.

[kevinjwalters]

Other tickets mentioning 5xx errors:

• 504: Getting 504 error after flashing the newest micro:bit firmware makinteract/vscode-microbit-micropython#9
• 521 and 537: unreliable flashing of microbit v2 (521 error) mu-editor/mu#1536

[kevinjwalters]

I had a further play with this. I have three micro:bits plugged in and the problem has "moved" to board F. I've unplugged it from

I had a look at cp and its copying in blocks of 128k. I can make dd error most of the time with bs=128k. This one is showing a 521 error.

Details

$ cd pwmbugfix/mp-mb-pwmfix-rc1.1.32kfs 
$ date ; strace -f -tt dd bs=128k if=MICROBIT.hex of=/media/kjw/MICROBIT2/MICROBIT.hex    # board F
Wed  3 Sep 13:59:42 BST 2025
13:59:42.604880 execve("/usr/bin/dd", ["dd", "bs=128k", "if=MICROBIT.hex", "of=/media/kjw/MICROBIT2/MICROBIT"...], 0x7fde3d1db8 /* 23 vars */) = 0
13:59:42.606462 brk(NULL)               = 0x558af18000
13:59:42.607023 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa3374000
13:59:42.607482 faccessat(AT_FDCWD, "/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
13:59:42.608380 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
13:59:42.608853 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=68383, ...}, AT_EMPTY_PATH) = 0
13:59:42.609492 mmap(NULL, 68383, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa3363000
13:59:42.609740 close(3)                = 0
13:59:42.610448 openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
13:59:42.610744 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0000y\2\0\0\0\0\0"..., 832) = 832
13:59:42.611306 newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=1651408, ...}, AT_EMPTY_PATH) = 0
13:59:42.611606 mmap(NULL, 1826912, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa317c000
13:59:42.612163 mmap(0x7fa3180000, 1761376, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0x7fa3180000
13:59:42.612530 munmap(0x7fa317c000, 16384) = 0
13:59:42.613000 munmap(0x7fa332f000, 45152) = 0
13:59:42.613379 mprotect(0x7fa3307000, 86016, PROT_NONE) = 0
13:59:42.613772 mmap(0x7fa331c000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18c000) = 0x7fa331c000
13:59:42.614312 mmap(0x7fa3322000, 49248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa3322000
13:59:42.614787 close(3)                = 0
13:59:42.615300 set_tid_address(0x7fa3374fd0) = 2706
13:59:42.615684 set_robust_list(0x7fa3374fe0, 24) = 0
13:59:42.616038 rseq(0x7fa3375620, 0x20, 0, 0xd428bc00) = 0
13:59:42.616519 mprotect(0x7fa331c000, 16384, PROT_READ) = 0
13:59:42.616940 mprotect(0x5569d4f000, 4096, PROT_READ) = 0
13:59:42.617455 mprotect(0x7fa3379000, 8192, PROT_READ) = 0
13:59:42.617821 prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
13:59:42.618511 munmap(0x7fa3363000, 68383) = 0
13:59:42.618952 rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
13:59:42.619571 rt_sigaction(SIGUSR1, {sa_handler=0x5569d23fa4, sa_mask=[INT USR1], sa_flags=0}, NULL, 8) = 0
13:59:42.619831 rt_sigaction(SIGINT, {sa_handler=0x5569d23f94, sa_mask=[INT USR1], sa_flags=SA_NODEFER|SA_RESETHAND|0xffffffff00000000}, NULL, 8) = 0
13:59:42.620433 getrandom("\x48\xbc\xd7\x27\x44\x19\x5f\xf4", 8, GRND_NONBLOCK) = 8
13:59:42.620680 brk(NULL)               = 0x558af18000
13:59:42.621203 brk(0x558af39000)       = 0x558af39000
13:59:42.621509 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
13:59:42.622035 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=3048976, ...}, AT_EMPTY_PATH) = 0
13:59:42.622621 mmap(NULL, 3048976, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa2e97000
13:59:42.623052 close(3)                = 0
13:59:42.623504 openat(AT_FDCWD, "MICROBIT.hex", O_RDONLY) = 3
13:59:42.623968 dup3(3, 0, 0)           = 0
13:59:42.624509 close(3)                = 0
13:59:42.624755 lseek(0, 0, SEEK_CUR)   = 0
13:59:42.625286 openat(AT_FDCWD, "/media/kjw/MICROBIT2/MICROBIT.hex", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
13:59:42.625881 dup3(3, 1, 0)           = 1
13:59:42.626311 close(3)                = 0
13:59:42.626733 mmap(NULL, 139264, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa2e75000
13:59:42.627241 read(0, ":1000000000040020810A00001507000"..., 131072) = 131072
13:59:42.628058 write(1, ":1000000000040020810A00001507000"..., 131072) = 131072
13:59:42.629785 read(0, "839\n:10BF300001F02CF8072089F8000"..., 131072) = 131072
13:59:42.630245 write(1, "839\n:10BF300001F02CF8072089F8000"..., 131072) = 131072
13:59:42.632031 read(0, "0D21A12B2002A03DD90429E\n:1079600"..., 131072) = 131072
13:59:42.632725 write(1, "0D21A12B2002A03DD90429E\n:1079600"..., 131072) = 131072
13:59:42.634284 read(0, ":103F800010B5044B036000230446C38"..., 131072) = 131072
13:59:42.634727 write(1, ":103F800010B5044B036000230446C38"..., 131072) = 131072
13:59:42.636378 read(0, "ED5\n:10F9B000B378D906BBD43378EA1"..., 131072) = 131072
13:59:42.636841 write(1, "ED5\n:10F9B000B378D906BBD43378EA1"..., 131072) = 131072
13:59:42.638263 read(0, "FC4E90170D4E90210F5F73B\n:10B3E00"..., 131072) = 131072
13:59:42.638765 write(1, "FC4E90170D4E90210F5F73B\n:10B3E00"..., 131072) = 131072
13:59:42.640447 read(0, ":106E0000048005DDFFF722FE2369334"..., 131072) = 131072
13:59:42.640891 write(1, ":106E0000048005DDFFF722FE2369334"..., 131072) = 131072
13:59:42.642111 read(0, "99847E36A94F93210CC\n:102830005B8"..., 131072) = 131072
13:59:42.642555 write(1, "99847E36A94F93210CC\n:102830005B8"..., 131072) = 131072
13:59:42.643816 read(0, "F0300392704005CD10500F6\n:10E2600"..., 131072) = 131072
13:59:42.644233 write(1, "F0300392704005CD10500F6\n:10E2600"..., 131072) = 131072
13:59:42.645517 read(0, "0013BA36002F045\n:109060007F03BB4"..., 131072) = 61338
13:59:42.645865 write(1, "0013BA36002F045\n:109060007F03BB4"..., 61338) = 61338
13:59:42.646606 read(0, "", 131072)     = 0
13:59:42.646876 close(0)                = 0
13:59:42.647142 close(1)                = 0
13:59:54.712616 openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 0
13:59:54.712956 newfstatat(0, "", {st_mode=S_IFREG|0644, st_size=2996, ...}, AT_EMPTY_PATH) = 0
13:59:54.713282 read(0, "# Locale name alias data base.\n#"..., 4096) = 2996
13:59:54.713591 read(0, "", 4096)       = 0
13:59:54.713827 close(0)                = 0
13:59:54.714088 openat(AT_FDCWD, "/usr/share/locale/en_GB.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.714466 openat(AT_FDCWD, "/usr/share/locale/en_GB.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.714734 openat(AT_FDCWD, "/usr/share/locale/en_GB/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.715018 openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.715273 openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.715514 openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
13:59:54.715836 write(2, "9+1 records in\n9+1 records out\n", 319+1 records in
9+1 records out
) = 31
13:59:54.716183 write(2, "1240986 bytes (1.2 MB, 1.2 MiB) "..., 591240986 bytes (1.2 MB, 1.2 MiB) copied, 12.0894 s, 103 kB/s) = 59
13:59:54.716462 write(2, "\n", 1
)       = 1
13:59:54.716716 close(2)                = 0
13:59:54.717113 exit_group(0)           = ?
13:59:54.717752 +++ exited with 0 +++

$ ls /media/kjw/MICROBIT2
ls: cannot access '/media/kjw/MICROBIT2': No such file or directory
$ ls /media/kjw/MICROBIT2
DETAILS.TXT  FAIL.TXT  MICROBIT.HTM  MY_DATA.HTM
$ diff /media/kjw/MICROBIT/DETAILS.TXT /media/kjw/MICROBIT2/DETAILS.TXT   ### comparing okay D with problematic F
3c3
< Unique ID: 9906360200052820396a0eaedb339029000000006e052820
---
> Unique ID: 99063602000528200d15f269ae4096ea000000006e052820
18c18
< Remount count: 1
---
> Remount count: 17

Am I likely to be able to caputre anything from the host computer that would help here or is the bug going to be in the bootloader thingy?

[kevinjwalters]

I don't know anything about USB protocol but I had a play with tshark and it seems to use SCSI commands for the file system operations. I did some crude gluing of the responses with prior requests to show how the problem can manifest itself at the USB layer.

Good (large) hex file

 19 2025-09-03 22:26:59.627647 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000195, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (242.819 ms)
   25 2025-09-03 22:26:59.870559 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000285, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (242.507 ms)
   31 2025-09-03 22:27:00.113136 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000375, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (242.800 ms)
   37 2025-09-03 22:27:00.355985 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000465, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (243.025 ms)
   43 2025-09-03 22:27:00.599094 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000555, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (243.187 ms)
   53 2025-09-03 22:27:00.842516 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000645, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1471.211 ms)
   59 2025-09-03 22:27:02.313795 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000735, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1503.600 ms)
   65 2025-09-03 22:27:03.817502 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000825, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1505.059 ms)
   71 2025-09-03 22:27:05.322708 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000915, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1481.165 ms)
   81 2025-09-03 22:27:06.804275 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000a05, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1504.780 ms)
   87 2025-09-03 22:27:08.309187 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000af5, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1506.020 ms)
   93 2025-09-03 22:27:09.815323 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000be5, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1483.693 ms)
   99 2025-09-03 22:27:11.299167 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000cd5, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1504.906 ms)
  109 2025-09-03 22:27:12.804533 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000dc5, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1480.563 ms)
  115 2025-09-03 22:27:14.285228 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000eb5, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1577.844 ms)
  121 2025-09-03 22:27:15.863287 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000fa5, Len: 68) Response LUN: 0x00 (Write(10)) (Good) (503.262 ms)
  127 2025-09-03 22:27:16.367955 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000001, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (2.193 ms)
  137 2025-09-03 22:27:16.370529 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000042, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (2.158 ms)
  143 2025-09-03 22:27:16.372759 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000083, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.555 ms)
  967 2025-09-03 22:27:23.185115 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.261 ms)

Bad (small) hex file.

   23 2025-09-03 22:46:41.879279 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000018d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1708.994 ms)
   29 2025-09-03 22:46:43.588346 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000027d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1512.327 ms)
   35 2025-09-03 22:46:45.100817 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000036d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1510.732 ms)
   45 2025-09-03 22:46:46.611882 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000045d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1482.353 ms)
   51 2025-09-03 22:46:48.094372 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000054d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1500.553 ms)
   57 2025-09-03 22:46:49.595041 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000063d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1498.005 ms)
   63 2025-09-03 22:46:51.093177 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000072d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1475.874 ms)
   73 2025-09-03 22:46:52.569410 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000081d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1514.449 ms)
   79 2025-09-03 22:46:54.083995 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000090d, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1491.902 ms)
   85 2025-09-03 22:46:55.576024 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x000009fd, Len: 240) NO RESPONSE
  123 2025-09-03 22:47:27.241084 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x000009fd, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1721.236 ms)
  129 2025-09-03 22:47:28.962396 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000aed, Len: 24) Response LUN: 0x00 (Write(10)) (Good) (258.037 ms)
  139 2025-09-03 22:47:29.221063 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000001, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (1.975 ms)
  145 2025-09-03 22:47:29.223080 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000042, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (2.194 ms)
  151 2025-09-03 22:47:29.225316 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000083, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.500 ms)
 1027 2025-09-03 22:47:56.310051 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.050 ms)

I don't know if they are all like this but for this problematic case there's a SCSI Write(10) with no response. That provokes a retry and a load of other USB activity, some sort of USB reset not shown above about 31 seconds later. The 240 sector writes seem to take either 243ms or around 1500ms to be acknowledged, the bimodal distribution looks peculiar.

[kevinjwalters]

I've done a bit of testing with always power cycling the micro:bit by disconnecting it. I've just tried this custom debug DAPlink (v0258-beta1-1-g5ecc8207). It errors most of the time with my custom microbit hex file. The ninth try worked. The output doesn't show anything revelatory to a non-expert. It'a all the same until there's some sort of timeout which has no associated debug output to explain it. I watched it and the vfs_mngr_periodic() pops out after a weird/bogus period of inactivity.

Something is gumming up the works here. Is any of the code that runs periodically (like board_30ms_hook) capable of messing up the usb or file system code? There does appear to be both a

1. hex file content factor and
2. a timing factor
   at play here where sometimes the hex file copy gets lucky and sometimes unlucky.

$ diff --side-by-side -W 160 screen.out.error.8.txt screen.out.okay.9.txt  | grep -a -A 54 'Write: 1246'
Write: 1246                                                                     Write: 1246
Hex:                                                                            Hex:
:102EC000CDE9093424F010F820230B908020CDE9BF                                     :102EC000CDE9093424F010F820230B908020CDE9BF
:102ED0000C3424F009F82146CDE90E0                                                :102ED0000C3424F009F82146CDE90E0
...                                                                             ...
04E                                                                             04E
:102F6000010F02F1FF3340F03B81012B1FD0E8E05D                                     :102F6000010F02F1FF3340F03B81012B1FD0E8E05D
:102F70003D22BFE702B1D3B106E---                                                 :102F70003D22BFE702B1D3B106E---
sect[1246] st[149] exp[1246]                                                    sect[1246] st[149] exp[1246]
sizeproc=561664                                                                 sizeproc=561664
flash_wr(addr=0x32ec0, size=176)                                                flash_wr(addr=0x32ec0, size=176)
        flash_data ret 0                                                                flash_data ret 0
stream_write ret=0                                                              stream_write ret=0
updatestate:                                                                    updatestate:
        sz_trans=562176                                                                 sz_trans=562176
        f_sz=0                                                                          f_sz=0
        f_st=-1                                                                         f_st=-1
vfs_mngr_periodic()                                                           |
        time_usb_idle=20160                                                   | Write: 1247
        vfs_state=2                                                           | Hex:
        vfs_state_next=1                                                      | B4206904501D82E
        transfer_state=1                                                      | :102F80000123BFE7B24636F8023B03EA0B01B1F575
        state 2->1                                                            | :102F9000805F0ED
        transfer timeout                                                      | ...
                                                                              > 01AF0400F00F088806A
                                                                              > :10302000002631467EE0012AAAD995F84030052BCA
                                                                              > :1030300040F---
                                                                              > sect[1247] st[149] exp[1247]
                                                                              > sizeproc=562176
                                                                              > flash_wr(addr=0x32f70, size=192)
                                                                              >         flash_data ret 0
                                                                              > stream_write ret=0
updatestate:                                                                    updatestate:
        sz_trans=562176                                                       |         sz_trans=562688
        f_sz=0                                                                          f_sz=0
        f_st=-1                                                                         f_st=-1
        TRANSFER_TIMEOUT status=0, out_of_order=0, transfer_started=1         |
                stream=1, size_processed=562176                               | Write: 1248
                stream_finished=0, stream_opt_finish=0, file_opt_finish=0     | Hex:
vfs_manager transfer_update_state(status=0)                                   | 0148149494A4808F002FBAA6B29680C
        file=0, start_sect= 149 -1, size=0                                    | :103040000446002308F0B7FB2046FDF71DFB039460
        stream=1, size_processed=562176, opt_finish=0, timeout=1              |
                                                                              > ...
                                                                              > 0494609A8FFF7DCFC69E7002892D003798C
                                                                              > :1030E0003A2BEDD08EE733F8022D02EA0B01B1F---
                                                                              > sect[1248] st[149] exp[1248]
                                                                              > sizeproc=562688
                                                                              > flash_wr(addr=0x33030, size=176)
                                                                              >         flash_data ret 0
                                                                              > stream_write ret=0
                                                                              > updatestate:
                                                                              >         sz_trans=563200
                                                                              >         f_sz=0
                                                                              >         f_st=-1
                                                                              >

The SCSI commands are similar to previous working and non working ones but not identical to the stuff I got from 0257. They appear to get proper responses now.

Details

# tshark -t ad -r smallbadhex-8-error.daplinkdebug.cp.pcap | perl -ane 'chomp; s/\s+\S+\s*→\s*\S+\s+/ /; @time = split(/:/,$F[2]); $crude_time = 3600 * $time[0] + 60 * $time[1] + $time[2]; if (m/SCSI: Response/) { push(@response, $_); } elsif (m/SCSI: Data/) { } elsif (m/SCSI: /) { push(@request, $_); $request_time = $crude_time } if (@request && @response) { $sr = shift(@response); $sr =~ s/^.*SCSI://; printf("%s%s (%.3f ms)\n",shift(@request), $sr, ($crude_time - $request_time)*1000) } elsif (scalar(@request) >= 2) { print(shift(@request), " NO RESPONSE\n") }' | fgrep Write
  Running as user "root" and group "root". This could be dangerous.
  633 2025-09-08 23:25:40.298648 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.156 ms)
 1250 2025-09-08 23:25:55.823902 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000095, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1831.843 ms)
 2732 2025-09-08 23:25:57.655948 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000185, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1629.868 ms)
 4216 2025-09-08 23:25:59.286001 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000275, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1630.801 ms)
 5714 2025-09-08 23:26:00.917182 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000365, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1605.818 ms)
 7202 2025-09-08 23:26:02.523119 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000455, Len: 240) Response LUN: 0x00 (Write(10)) (Check Condition) (21136.954 ms)
 8094 2025-09-08 23:26:23.660647 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000545, Len: 240) Response LUN: 0x00 (Write(10)) (Check Condition) (1.871 ms)
 8110 2025-09-08 23:26:23.663007 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000001, Len: 2) Response LUN: 0x00 (Write(10)) (Check Condition) (2.060 ms)
 8126 2025-09-08 23:26:23.665572 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000635, Len: 240) Response LUN: 0x00 (Write(10)) (Check Condition) (1.945 ms)
 8152 2025-09-08 23:26:23.668615 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000042, Len: 2) Response LUN: 0x00 (Write(10)) (Check Condition) (1.472 ms)
 8168 2025-09-08 23:26:23.670739 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000725, Len: 240) Response LUN: 0x00 (Write(10)) (Check Condition) (1.782 ms)
 8184 2025-09-08 23:26:23.673004 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000083, Len: 1) Response LUN: 0x00 (Write(10)) (Check Condition) (2.085 ms)
 8200 2025-09-08 23:26:23.675717 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000815, Len: 184) Response LUN: 0x00 (Write(10)) (Check Condition) (1.837 ms)
 8216 2025-09-08 23:26:23.680622 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x000008cd, Len: 240) Response LUN: 0x00 (Write(10)) (Check Condition) (3.483 ms)
 8232 2025-09-08 23:26:23.685398 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x000009bd, Len: 80) Response LUN: 0x00 (Write(10)) (Check Condition) (1.124 ms)
13118 2025-09-08 23:26:30.435736 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.307 ms)

# tshark -t ad -r smallbadhex-9-okay.daplinkdebug.cp.pcap | perl -ane 'chomp; s/\s+\S+\s*→\s*\S+\s+/ /; @time = split(/:/,$F[2]); $crude_time = 3600 * $time[0] + 60 * $time[1] + $time[2]; if (m/SCSI: Response/) { push(@response, $_); } elsif (m/SCSI: Data/) { } elsif (m/SCSI: /) { push(@request, $_); $request_time = $crude_time } if (@request && @response) { $sr = shift(@response); $sr =~ s/^.*SCSI://; printf("%s%s (%.3f ms)\n",shift(@request), $sr, ($crude_time - $request_time)*1000) } elsif (scalar(@request) >= 2) { print(shift(@request), " NO RESPONSE\n") }' | fgrep Write
   Running as user "root" and group "root". This could be dangerous.
  637 2025-09-08 23:27:28.246782 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.181 ms)
 1256 2025-09-08 23:27:41.934490 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000095, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1825.066 ms)
 2740 2025-09-08 23:27:43.759821 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000185, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1629.699 ms)
 4222 2025-09-08 23:27:45.389681 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000275, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1630.105 ms)
 5720 2025-09-08 23:27:47.020181 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000365, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1605.355 ms)
 7208 2025-09-08 23:27:48.625661 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000455, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1629.510 ms)
 8706 2025-09-08 23:27:50.255294 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000545, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1629.426 ms)
10204 2025-09-08 23:27:51.884848 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000001, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (2.465 ms)
10218 2025-09-08 23:27:51.887444 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000635, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1606.205 ms)
11716 2025-09-08 23:27:53.494097 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000042, Len: 2) Response LUN: 0x00 (Write(10)) (Good) (2.431 ms)
11728 2025-09-08 23:27:53.496654 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000725, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1629.645 ms)
13216 2025-09-08 23:27:55.126411 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000083, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (2.436 ms)
13228 2025-09-08 23:27:55.128940 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000815, Len: 152) Response LUN: 0x00 (Write(10)) (Good) (1014.713 ms)
14182 2025-09-08 23:27:56.144557 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x000008ad, Len: 240) Response LUN: 0x00 (Write(10)) (Good) (1657.224 ms)
15668 2025-09-08 23:27:57.801935 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x0000099d, Len: 112) Response LUN: 0x00 (Write(10)) (Good) (860.541 ms)
21290 2025-09-08 23:28:05.362487 USBMS 95 SCSI: Write(10) LUN: 0x00 (LBA: 0x00000000, Len: 1) Response LUN: 0x00 (Write(10)) (Good) (1.185 ms)

[microbit-carlos]

@kevinjwalters the majority of errors we've seen in this area is because the operating system sent the file blocks out of order, and DAPLink needs the file blocks to be sent sequentially.

Could you share your hex file and steps to reproduce it? like operating system, etc

---

Edit: Sorry, with the rush to dig into this I forgot to say thank you for looking into this and the detailed information!

[kevinjwalters]

The SCSI LBA are ascending in my captures, does that mean the file is in order or likely to be in order in a typical FAT file system?

I'm using a Raspberry Pi 4 with a V2.21 micro:bit plugged into the bottom left (black, not blue) USB port if you are looking at the ports. I unplug the micro:bit for each test now to start it from a known state and to be able to capture all the USB traffic from plugin.

 $ fgrep PRETTY /etc/os-release
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"

 $ uname -a
Linux pi4 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux

I've attached the hex file (in zip below). It's the version of MicroPython (for V2 only) from lancaster-university/codal-nrf52#59 but with a 32k file system rather than the normal 24k. This was failing about 90% of the file in my testing from yesterday

• using cp to deploy with the debug daplink firmware installed.
• I had screen running as a terminal emulator to observe debug output and capture to a file so a lot of data will be flowing and that adds to USB traffic.
• I had tshark running and capturing usbmon1 to a file.

MICROBIT.mp-mb-pwmfix-rc1.1.32kfs.zip