macOS 15 Sequoia finder drag&drop flashing fails

[microbit-carlos]

Not quite the same, but similar to:

• macOS 13 Ventura finder drag&drop flashing fails #982

There has been reports of issues flashing in macOS 15 Sequoia via finder.

Some things we've noticed so far:

• There is a lot of USB activity when the drive is mounted, 20 to 60 seconds (might depend on computer speed, a colleague with a mac mini sees this for 20 seconds, the slow VM I use for testing takes 60 seconds).
• If a hex file is flashed during the activity period, the flash succeeds
• If a hex file is flashed after this activity is done, the flash fails
  • Most common errors encounter are ERROR_TRANSFER_TIMEOUT and ERROR_OOO_SECTOR
  • This is replicable in the CLI with the cp and rsync commands as well
• WebUSB flashing works correctly

Issue description

• Connect the micro:bit via USB to a macOS 15 computer
• Wait for the orange LED to stop blinking
• Drag & drop a Universal hex file into the micro:bit USB Drive (named "NO NAME" due to macOS 15 Sequoia USB drive name shows as NO NAME #1082)
  • Any file from the micro:bit MakeCode or Python editors will do, for example: universal-hex-micropython.hex.zip
  • A normal Intel Hex file also has this problem, but because the file can be much smaller it might present less obvious symptoms. For example: blink-a-b.hex.zip
• The file transfer starts and the normal Copying "file.hex" to ... window with a progress bar appears
  • While the window is open we can see the orange LED blinking
  • If a Universal Hex is used, the target is never halted, which is the first step before it erases the target flash and starts writing the hex data.
    • When DAPLink processes a Universal Hex it will only halt and erase the target when it reaches the V2 section of the hex, this is usually placed in the second half of the file. So, this can be caused if anything causes DAPLink to stop processing the hex data during the first half
• The time this file transfer window is open is usually shorter than a normal flash
  • Most of the time during a file transfer is spent processing the hex data and flashing the target, if DAPLink starts dropping the hex data blocks, then that normally shortens the file transfer time
• The file transfer window closes and the orange LED continues blinking for a few seconds
• After about 30 seconds the USB drive unmounts and remounts, a FAIL.TXT appears usually with the "timeout" or the "out of order blocks" error
• At this point DAPLink is meant to erase the target and reflash it with a hex file that scrolls the error code on the micro:bit display, this doesn't always happen

Initial findings

I've done an initial test by printing some vfs data to serial during the file transfer. I'll need to do a better capture using RTT next.

With this initial run, we can see that the captured flashing failures are not caused due to out-of-order blocks, but because the OS now sends continuous file blocks to non-continuous fs sectors (the fs is configured with 512 byte sectors).

• Hex file used: uhex-sectors-upy-longrecords.hex.zip
• Serial logs captured: serial_0.txt serial_1.txt

For example, in the serial_0.txt log we can see:

• It starts by doing a lot of read and writes, I don't have info about what these could be, more info should be collected with RTT
• It then starts to send the file data, starting from the beginning of the file to go into sector 357.
  • This is correctly parsed by DAPLink, in V2 this does not trigger the halt+erase yet, because I used a Universal Hex file and the first half of the hex file contains the V1 data
• Then 8 file blocks later, it sends the next file block that should normally go into sector 365 into sector 381 instead
  • DAPLink rejects this block as it was expecting a block for sector 365, and it will continue to reject all the blocks sent by the OS as it is waiting for a block for sector 365
• It does this a few more times, but at least the file blocks appear to be continuous
  • I'm checking this log manually, and haven't checked every single write entry to ensure they are all continuous, but every 100 or so blocks instead, and I haven't noticed any out of order block
• By the time it reaches sector 692, then next block is sent to sector 1677
• There are a few more smaller jumps and a slightly larger one (from sector 1996 to 2157), and then it finally writes the last file block into sector 4758
• There are a few more writes to lower sectors (below the initial sector 357 where the first hex file block was written into) all over the log, which we'll need to look into with RTT. Also a few more writes to sectors in-between the hex file jumps (for example around sector 1220, which is not used for the hex file)

Further Analysis

More technical details can be found further down in this issue thread, in comment: #1083 (comment)

[fabianhugo]

I am seeing something very similar on Ubuntu 22.04: uname -a shows:
Linux hugoUbu20 6.8.0-45-generic #45~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Wed Sep 11 15:25:05 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

Copying of universal hex often fails with error 504 and the fail.txt reads:

error: The transfer timed out.
type: transient, user

Around 3 of 4 file transfer fail. Using cp or rsync in the terminal do also not improve the behavior. And WebUSB is not affected as well.

One way for me to tell that the copying failed is to check the contents of the mass storage. If the hex is visible there, it failed.

[martinwork]

@fabianhugo
For Linux, this UDEV rules file 99-microbit-udisks.zip can help by adding the "sync" option to MICROBIT drives.

To install...

Connect micro:bit and check current options:
mount | grep MICROBIT

Unzip 99-microbit-udisks.zip, and copy the rules file to the udev rules.d folder. For example
sudo cp 99-microbit-udisks.rules /etc/udev/rules.d

Check it has the same owner, group and permissions as other rules files.
ls -l /etc/udev/rules.d

Restart UDEV.
sudo udevadm control --reload-rules ; sudo udevadm trigger

Disconnect and reconnect micro:bit then check what options are in use now.
mount | grep MICROBIT

The only difference should be the addition of "sync".

To uninstall, delete 99-microbit-udisks.rules from the rules.d folder.

[fabianhugo]

Seems to have fixed it! Thank you! :)

[microbit-carlos]

Analysis

With macOS 14 and older, hex files were written by the OS into continuous FAT sectors. On macOS 15 the hex file blocks are sent in order, but they are not written into continuous filesystem sectors. This is due to fragmentation introduced by previously created metadata files, the reason the orange LED blinks for so long after the USB drive is mounted.

I added additional RTT logging into a DAPLink test build, to capture the filesystem traffic data to check what data blocks are written into what the file system sectors. The following files have been captured:

• drive-mount.log: captures the filesystem traffic when the micro:bit USB is connected to the computer, macOS mounts the drive, and starts creating metadata files.
• flashing-ih-9903.log: captures the filesystem traffic when the ih-9903.txt file was copied into the micro:bit USB drive
• ih-9903.hex.zip: is the hex file copied into the USB drive

In these files we can see the following:

• The flashing-ih-9903.txt shows the Hex file data is being sent in order
• The first file block is written into filesystem sector 373
• It writes 32 file blocks up to filesystem sector 404, and then the following block is sent to sector 413
• Then it continues writing the file in continuous sector, until sector 452, where it jumps to 549
• It does a few more jumps like that for the rest of the file
• Looking at drive-mount.log we can see that the OS had previously already written some kind metadata file content into sector 407 (first jump), in sectors 453 to 455, sectors 461 to 475 (second jump), etc.

This suggests that the hex file blocks are written into non-consecutive filesystem sectors because the OS has already created several metadata files on the drive occupying the sectors that would have otherwise be used by the hex file.

This is the file structure of the micro:bit USB drive in macOS 12, where no metadata files are created by the OS:

📂 /Volumes/MICROBIT
┣━━ 📄 DETAILS.TXT (592 bytes)
┣━━ 📄 FAIL.TXT (55 bytes)
┗━━ 📄 MICROBIT.HTM (284 bytes)

In contrast, this is the file structure of the same micro:bit USB drive in macOS 15:

📂 /Volumes/NO NAME
┣━━ 📂 .fseventsd
┃   ┗━━ 📄 fseventsd-uuid (36 bytes)
┣━━ 📂 .Spotlight-V100
┃   ┣━━ 📂 Store-V2
┃   ┃   ┗━━ 📂 B8624886-8BF7-4584-8688-AEBC5B953367
┃   ┃       ┣━━ 📂 journals.assisted_import_post
┃   ┃       ┣━━ 📂 journals.assisted_import_pre
┃   ┃       ┣━━ 📂 journals.corespotlight
┃   ┃       ┣━━ 📂 journals.health_check
┃   ┃       ┣━━ 📂 journals.live
┃   ┃       ┣━━ 📂 journals.live_priority
┃   ┃       ┣━━ 📂 journals.live_system
┃   ┃       ┣━━ 📂 journals.live_user
┃   ┃       ┣━━ 📂 journals.migration
┃   ┃       ┣━━ 📂 journals.migration_secondchance
┃   ┃       ┣━━ 📂 journals.scan
┃   ┃       ┣━━ 📄 .store.db (36.9 kB)
┃   ┃       ┣━━ 📄 0.directoryStoreFile (65.5 kB)
┃   ┃       ┣━━ 📄 0.directoryStoreFile.shadow (1.2 kB)
┃   ┃       ┣━━ 📄 0.indexArrays (73.0 kB)
┃   ┃       ┣━━ 📄 0.indexBigDates (20 bytes)
┃   ┃       ┣━━ 📄 0.indexCompactDirectory (1.1 kB)
┃   ┃       ┣━━ 📄 0.indexDirectory (2.1 kB)
┃   ┃       ┣━━ 📄 0.indexGroups (3.3 kB)
┃   ┃       ┣━━ 📄 0.indexHead (4.1 kB)
┃   ┃       ┣━━ 📄 0.indexId (1 byte)
┃   ┃       ┣━━ 📄 0.indexIds (40 bytes)
┃   ┃       ┣━━ 📄 0.indexPositions (281 bytes)
┃   ┃       ┣━━ 📄 0.indexPostings (1.1 kB)
┃   ┃       ┣━━ 📄 0.shadowIndexGroups (4 bytes)
┃   ┃       ┣━━ 📄 0.shadowIndexHead (4.1 kB)
┃   ┃       ┣━━ 📄 Cab.created (0 bytes)
┃   ┃       ┣━━ 📄 dbStr-1.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-1.map.data (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-1.map.header (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-1.map.header.shadow (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-1.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-2.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-2.map.data (8.2 kB)
┃   ┃       ┣━━ 📄 dbStr-2.map.header (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-2.map.header.shadow (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-2.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-3.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-3.map.data (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-3.map.header (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-3.map.header.shadow (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-3.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-4.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-4.map.data (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-4.map.header (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-4.map.header.shadow (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-4.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-5.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-5.map.data (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-5.map.header (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-5.map.header.shadow (56 bytes)
┃   ┃       ┣━━ 📄 dbStr-5.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-6.map.buckets (4.1 kB)
┃   ┃       ┣━━ 📄 dbStr-6.map.header (84 bytes)
┃   ┃       ┣━━ 📄 dbStr-6.map.header.shadow (84 bytes)
┃   ┃       ┣━━ 📄 dbStr-6.map.offsets (4.1 kB)
┃   ┃       ┣━━ 📄 Glow.created (0 bytes)
┃   ┃       ┣━━ 📄 indexState (28 bytes)
┃   ┃       ┣━━ 📄 journalExclusion (0 bytes)
┃   ┃       ┣━━ 📄 Lion.created (0 bytes)
┃   ┃       ┣━━ 📄 live.0.directoryStoreFile (65.5 kB)
┃   ┃       ┣━━ 📄 live.0.directoryStoreFile.shadow (1.1 kB)
┃   ┃       ┣━━ 📄 live.0.indexArrays (65.5 kB)
┃   ┃       ┣━━ 📄 live.0.indexBigDates (16.4 kB)
┃   ┃       ┣━━ 📄 live.0.indexCompactDirectory (1.0 kB)
┃   ┃       ┣━━ 📄 live.0.indexDirectory (8.2 kB)
┃   ┃       ┣━━ 📄 live.0.indexGroups (3.3 kB)
┃   ┃       ┣━━ 📄 live.0.indexHead (4.1 kB)
┃   ┃       ┣━━ 📄 live.0.indexId (1 byte)
┃   ┃       ┣━━ 📄 live.0.indexIds (32.8 kB)
┃   ┃       ┣━━ 📄 live.0.indexPositions (4.1 kB)
┃   ┃       ┣━━ 📄 live.0.indexPositionTable (8.2 kB)
┃   ┃       ┣━━ 📄 live.0.indexPostings (4.1 kB)
┃   ┃       ┣━━ 📄 live.0.indexTermIds (8.2 kB)
┃   ┃       ┣━━ 📄 live.0.indexUpdates (0 bytes)
┃   ┃       ┣━━ 📄 live.0.shadowIndexArrays (65.5 kB)
┃   ┃       ┣━━ 📄 live.0.shadowIndexCompactDirectory (8 bytes)
┃   ┃       ┣━━ 📄 live.0.shadowIndexDirectory (2.1 kB)
┃   ┃       ┣━━ 📄 live.0.shadowIndexGroups (1 byte)
┃   ┃       ┣━━ 📄 live.0.shadowIndexHead (4.1 kB)
┃   ┃       ┣━━ 📄 live.0.shadowIndexPositionTable (0 bytes)
┃   ┃       ┣━━ 📄 live.0.shadowIndexTermIds (0 bytes)
┃   ┃       ┣━━ 📄 psid.db (8.2 kB)
┃   ┃       ┣━━ 📄 reverseDirectoryStore (65.5 kB)
┃   ┃       ┣━━ 📄 reverseDirectoryStore.shadow (3.1 kB)
┃   ┃       ┣━━ 📄 reverseStore.updates (2 bytes)
┃   ┃       ┣━━ 📄 shutdown_time (4 bytes)
┃   ┃       ┣━━ 📄 store.db (36.9 kB)
┃   ┃       ┣━━ 📄 store.updates (3 bytes)
┃   ┃       ┣━━ 📄 store_generation (4 bytes)
┃   ┃       ┣━━ 📄 tmp.Cab (0 bytes)
┃   ┃       ┣━━ 📄 tmp.Glow (0 bytes)
┃   ┃       ┣━━ 📄 tmp.Lion (0 bytes)
┃   ┃       ┣━━ 📄 tmp.spotlight.loc (9.1 kB)
┃   ┃       ┣━━ 📄 tmp.spotlight.state (4.1 kB)
┃   ┃       ┗━━ 📄 tmp.Star (0 bytes)
┃   ┗━━ 📄 VolumeConfiguration.plist (4.5 kB)
┣━━ 📄 DETAILS.TXT (592 bytes)
┣━━ 📄 FAIL.TXT (55 bytes)
┗━━ 📄 MICROBIT.HTM (284 bytes)