Mount reliability, logging, FTP and MDS fixes - #238
Closed
iTechMedic wants to merge 14 commits into
Closed
Conversation
A cue sheet that names one .bin per track cannot work here. The loader picks its data file by rewriting the cue's own extension, so it only ever opens the first one, and the parser cannot place a later file's tracks without knowing how long the earlier files are - every firmware caller uses the no-argument next_track(), which passes a previous size of zero. The arithmetic was bounded earlier so those tracks no longer land at LBAs in the billions. That stopped the nonsense but not the wrongness: the disc still mounted, with a TOC that put the wrong tracks in the wrong places. Refusing the image says what is actually true. Detection lives in cueutil.cpp and runs the real parser rather than scanning for the word FILE, so quoting, case and REM lines are read exactly as they will be when the sheet is used - a disc called "MY FILE (1996).bin" is not a split rip, and a rem'd-out FILE line is not a second file. It also lives there rather than in util.cpp so it can be tested: util.cpp is deliberately outside the host suite. Refusing is only an improvement if the user finds out, and until now they could not. Mounting is asynchronous: SetNextCDByName() queues an index and returns, so the web UI's "ok" only means the name was in the catalog. When the load failed afterwards, the old disc stayed mounted, current_cd went on pointing at it, and the sole record was one line in a log file the user has no reason to read - an unmountable image looked exactly like a mountable one. The service now keeps the reason for the last failed mount and the image-name endpoint the page already polls reports it.
…lit cues David put a split-track rip on the card and the browser offered him the individual track .bin files while the cue sheet itself was nowhere to be seen. Three separate things were wrong. The scanner listed a .cue only when a same-stem .bin sat next to it. That rule was written to keep a cue whose data file is missing out of the way, but a split-track rip is exactly the case where the stems differ - "Game.cue" against "Game (Track 1).bin" - so the disc vanished from the browser and its raw tracks were offered instead. Every cue is now listed; one that cannot be mounted says why when you try, which is more use than not being there. Nothing displayed the mount error. The previous commit gave SCSITBService a reason and put it in the /api/imagename JSON, which no page consumes - so the information existed and no user could reach it. Same mistake as reporting a bad log path only to the serial console. It is now a banner on every page, from the shared page handler. And the reason was generic. The loaders all report failure the same way, by returning nullptr, so "unsupported or damaged image" was the best the UI could say about a split-track cue, a missing .bin, a bad .mds and an unknown extension alike. They now record what actually went wrong and the mount error repeats it: a split rip says it is a split rip and what to do about it.
The rule was "list a .bin unless a same-stem .cue exists", which is exactly backwards. Mounting a .bin rewrites its extension and reads the .cue first, so a .bin whose cue is missing cannot be mounted at all - and that is precisely the set the browser was offering. The ones that could be mounted, through their cue, were the ones it hid. Nobody noticed while stems matched, because the cue was listed alongside and the hidden .bin was the right thing to hide. A split-track rip broke the symmetry: "Game.cue" against "Game (Track 1).bin" share no stem, so the browser filled up with track files, every one of them a dead end. A .bin is now never listed. Either its cue is there, and that cue represents the disc, or it is not, and there is nothing to mount. Drops siblingWithExtExists(), which has no callers left.
David mounted a split-track cue, got the refusal banner, and the page went on to say "Current File Loaded: Alien Trilogy (USA).cue" with that same file marked (Current) in the list. The host had never been given it - SetDevice() is not reached on a failed load - so the UI was reporting a disc that does not exist. Three causes, all of which the new error banner made visible rather than created. m_CurrentImagePath was filled in before the load was attempted and never put back when it failed, so a refused image immediately became the "current" path and its folder the current folder. current_cd is an index into the file list, and RefreshCache rebuilds that list without revisiting it. Any rescan that changes the ordering silently repoints it at a different file - and hiding .bin files, one commit ago, shifted every index on a card with cue/bin pairs. The mounted disc is now remembered by path and the index re-derived from it after each scan, which also means the UI reports nothing as current when the mounted file has genuinely gone away. The pick-something-to-mount fallback chose the first image in the list with no memory of what had just failed, so on a card whose only image is unmountable it retried the same one on every upload, delete and FTP change, re-raising the banner each time. Also widens the error buffer: the split-track message was being cut off mid-word at 160 characters. Re-deriving the index has a consequence that has to be handled in the same breath. current_cd is an int that is legitimately -1 when nothing is mounted; GetCurrentCD() returns it as size_t, so -1 becomes SIZE_MAX and GetName() answers an out-of-range index with nullptr. Both callers used that pointer where null is undefined - pagehandlerbase constructs a std::string from it on every page the web server serves, and the image-name API hands it to nlohmann's JSON. That was survivable only while current_cd was set once at the first successful mount and never cleared, so outside a narrow window at boot it was always valid. Re-deriving it makes "nothing is mounted" a state the UI can actually reach: an ejected drive that has not mounted anything this session, or a mounted file that is no longer in the list. GetCurrentCDName() now returns "" and both callers are guarded. Without this the device froze hard enough to need a power cycle after swapping to and from an image that refuses to mount.
The web UI announced "Successfully mounted: Alien Trilogy (USA).cue" and then
the very next page said the image needed re-ripping. Both were generated from
the same request. Mounting is asynchronous - SetNextCDByName() hands an index
to the service task and returns as soon as it has found the name in the
catalogue - so the mount page was reporting that the file exists, in the words
of a successful mount.
SCSITBService now counts the requests its Run() loop retires, so a caller can
wait for a specific one and find out what happened to it. MountByNameAndWait()
does that and answers Success, Failed, NotFound or Timeout; the timeout is
deliberately not called a failure, because a large CHD on a slow card takes a
while and guessing wrong there would be worse than saying "still loading".
The mount page now shows the refusal and its reason and stays put instead of
bouncing to the homepage, and the mount API returns the reason rather than
{"status":"ok"}.
The HAT had the same problem in a worse form: it jumped to the homepage on any
key press, so a disc that refused to load was indistinguishable from one the
user had changed their mind about - the previously mounted image simply
reappeared as current. It now waits, stays on the image list when the mount
fails, and says so in the page title. Short, because that is all an OLED header
holds; the reason is in the web UI and the log.
The HAT cannot wait the obvious way, and this is the one thing to be careful of
here. OnButtonPress does not run in task context on every display:
PageManager::HandleButtonPress says so in a comment, and sh1106/display.cpp:299
and st7789/display.cpp:425 both call it straight from the GPIO interrupt
handler. MountByNameAndWait() sleeps on the scheduler, so calling it there puts
a task switch inside an interrupt handler and freezes the Pi hard enough to
need a power cycle - on every mount, whatever the image, success or failure.
ssd1306 escapes only because it already defers presses to ProcessPendingInput();
its own comment states the rule: the handler must do quick, lock-free work only.
So the button handler only queues the request with SetNextCDByName() and
remembers the retired-request counter, and ResolvePendingMount(), called from
Refresh() in task context, waits for that counter to move and applies the
outcome. Done on all three drivers rather than the two that would crash: on
ssd1306 the wait was safe but still blocked the display loop for up to eight
seconds, stalling the screen and the backlight timeout. MountByNameAndWait() is
documented as task-context-only, naming the two handlers that are not.
The vendor toolbox picker is deliberately left asynchronous. It runs inside a
SCSI command handler, where sleeping is not acceptable, and DOS has nowhere to
show a result anyway.
…rent disc An image that had been renamed, deleted, or left behind on another card was silently replaced by whichever file sorted first. The drive came up holding a game the user had never chosen, with nothing anywhere to say why, and the only clue was a log line nobody reads. Asked directly whether a missing image now gives an empty drive, the honest answer was no. RefreshCache now adopts a stand-in but presents the drive EMPTY, and records which image went missing so every web page can say so. The stand-in is still loaded behind the scenes because the gadget needs a geometry, and because it makes Insert instant if the user does want a disc. Three things this has to get right: - A fresh card must still auto-mount. GetCurrentImage() answers with "image.iso" whether the key is missing or genuinely set to that, so it cannot tell a remembered image from a card that has never mounted anything. Asking with an empty default can, and only a genuinely remembered image triggers the empty drive. - The stand-in must not be saved as the user's image. Recording it would lose the missing name, so the explanation would vanish on the next boot and putting the file back would no longer bring it up. - Adopting while ejected must stay ejected, and must still happen. SetDevice() clears the ejected latch unless the boot-eject is armed, so the arm is not optional here. And the fallback's !IsEjected() guard had to gain an exception for a gadget that has never come up: adopting is the only thing that initializes it, so refusing would have left the host seeing no USB device at all rather than an empty drive - reachable on the second boot after this code had itself come up empty and persisted the eject. An empty images partition still adopts nothing and still leaves the gadget uninitialized, which the QEMU boot test in tests/qemu-boot relies on: it boots a virgin card with the images partition swept, so m_FileCount is 0, the fallback never runs, and SetDevice() is never reached. CDROMService gained IsGadgetInitialized() to make that condition testable rather than inferred, and the deferred init is now commented as load-bearing rather than looking like an optimization someone could helpfully remove - naming the three symptoms validate_boot_log.py treats as FORBIDDEN_ANYWHERE, so the next person to touch it knows what depends on it.
The empty-drive behaviour for a missing image worked on a reboot and silently did nothing on a running system. Renaming the mounted image over FTP left a different game mounted and readable, with no sign the saved one had gone. SetDevice() arms the disc-swap sequence whenever one device replaces another, and Update() drove NO_MEDIUM -> UNIT_ATTENTION without ever consulting the ejected latch. So adopting a stand-in put it in the drive 100 ms later. At boot m_pDevice is null, no swap is armed, and that transition never runs - which is exactly why the boot restore looked correct and hid this for as long as the boot restore has existed. The gadget was internally inconsistent while it happened: IsEjected() kept returning true the whole time it was serving READ(10) from the disc it had supposedly ejected. Update() now refuses the transition while ejected. Insert() is unaffected and still works - the drive is empty, not disabled. Test adopting_an_image_while_ejected_stays_ejected pins it, and fails without the fix on all three of the sense key, the additional sense code, and the READ(10) status. Also: the file list no longer names the stand-in as the current image. It is what the gadget holds open, not what the user mounted, and calling it "current" while the drive reads as empty is what made a vanished image look like an ordinary disc swap. m_CurrentImagePath still points at it so the FTP and web delete guards keep protecting it.
A user reported a Pi that had gone slow and had no log file. His log path was "0:/SD:/usbode-logs.txt" - which the web form built for him out of "SD:/usbode-logs.txt", by pasting "0:/" on the front of anything that did not already start with it. That path cannot be opened, and everything that follows from a failed open was wrong. The cost. Run() backed off 20 ms whenever a message failed to reach the file, which is right for a write that might succeed next time and useless when there is no file at all: every message failed, so the log queue retired 50 events a second, on a scheduler task, and dragged the rest of the system along with it. The daemon now distinguishes a transient write failure from having no file to write to, and only pays for the first. The hazard. m_bFileInitialized had no initializer and was not in the constructor's init list, so on the failing path it held whatever was in that memory. Non-zero meant LogMessage() wrote to an unopened FIL and the destructor closed one. The silence. Initialize()'s result was discarded by the constructor, which was itself discarded by the caller, and the message it did log named neither the path nor the reason. Boot now says which file it could not open, with the FatFs error, and where to go and fix it. The path itself was borrowed rather than copied, from the config store, which is free to replace it while the daemon is still running - and does, when the log path is edited from the web UI. Validation moves to where the bad value came from. The form now strips whatever volume the user typed, refuses one that is not the boot partition (only 0: is mounted when the daemon starts), refuses a directory or a leftover colon, and checks that the parent directory exists - FatFs will not create one, so a path under a missing directory is accepted and then fails at every boot with nothing to show for it. An empty value now means "off", which the page already displayed but the write path ignored, so the setting could not be cleared. The daemon is now compiled into the host test suite, which needed a real event queue on the logger stub, a sleep counter on the scheduler stub, and write support in the FatFs shim. Four of the five fixes are pinned by a test that goes red when the fix is reverted; the uninitialised flag is a bool, so reading a poisoned one is undefined and no assertion can pin it - the sanitizer build names all three read sites instead, and the README now says so. Also drops an unused LOG_FILE define in kernel.cpp that named a different file from the actual default.
The help text still promised the old behaviour - that whatever you type gets 0:/ pasted on the front - which is exactly how the reported bad value was produced. It now says what is actually accepted.
Found by David testing the reported bad path on hardware: he set logfile=0:/SD:/usbode-logs.txt, rebooted, and "didn't see any warning". The warning was emitted - to the serial console, which is the only target a SCREEN_HEADLESS build has. So the config page went on presenting a log path that was doing nothing, which is the situation this whole fix exists to end. The config page now shows the daemon's live status next to the path, in red when the file could not be opened, naming the path and the FatFs error. The log viewer had two problems of its own. It opened a hardcoded "/usbode-logs.txt" regardless of what was configured, so anyone who set a different path got a blank page and no hint they were looking in the wrong place; it now reads the configured file. And a missing log file rendered exactly like an empty one - nothing at all - so it now says why there is nothing to show. Both take the text from the daemon rather than working it out for themselves, so the two pages cannot drift apart or from what the daemon actually did.
…inter
Seek() decided it was already in position by comparing Tell() against the
offset it was asked for. Those are not the same kind of number: Tell() is a
byte offset into the MDF, the argument is an address on the disc. On an image
with 2448-byte sectors they run at different rates, and on one with an
unstored pregap the disc address moves where the file offset does not.
When they did coincide the function returned early, and the early return
skipped recording the LBA. Read() takes both its gap detection and its
subchannel stride from that LBA, so it went on serving whichever frame the
reader was last on - and reported success doing it.
Two ways in, both ordinary:
* a contiguous 2352-byte image makes the two offsets equal at every frame,
so reading a track to its end and then reading on lands in the pregap
with a stale LBA, the hole goes undetected, and the next track's bytes
come back where zeros belong. This is the Video CD case: on the real
SVIDEOCD image, LBA 526 returned track 2's volume descriptor.
* a 2448-byte image makes them equal every 49th frame, since 49 * 2448 is
51 * 2352. Ending a read at frame 48 and then reading frame 51 served
frame 49.
Compare against the file offset actually computed, and set the LBA before any
early exit can skip it. The plain read path now advances the position like the
other two already did, so the class keeps one definition of where it is.
Two smaller holes closed alongside, both reachable through the same gap:
a read shorter than one frame skipped the gap check on its size alone, and
ReadSubchannel() failed outright on a frame Seek() and Read() were both
willing to answer with zeros.
Gap detection was also O(frames x tracks) on every read - a full track-table
walk per frame - and most images have no hole at all. Init() now settles that
once by comparing the summed track lengths against the disc length, which
makes the common path cheaper than it was before this change.
Four tests, one per fix, each verified by putting the bug back and watching
that test go red. Checked against real Alcohol images too (DESCENT_II,
SVIDEOCD, NFSSEBBC): the sparse ones take the walk path, the single-track one
does not, and the pre-fix reader fails the pregap read on SVIDEOCD itself.
The web UI has always refused to delete the image the host has mounted
(deleteapi.cpp:43, "cannot delete the mounted image - mount another one
first"). FTP had no such guard, so the same card could be broken over FTP in a
way the browser would not allow - and a user reported the device locking up
after the image file stopped existing.
Three FTP paths could do it:
DELE f_unlink on the mounted image, leaving the gadget reading storage with
no directory entry while the host keeps issuing READ(10).
RNTO f_rename moves it out from under the mount just as effectively, and
renaming something else ONTO it destroys it.
STOR opens FA_CREATE_ALWAYS, which truncates. Uploading over the mounted
image is the worst of the three: the directory entry survives, so
nothing looks wrong until a read comes back short.
The comparison is the whole difficulty here, and it is not obvious. The same
file reaches the guard spelled three different ways:
"1:/x.cue" what SCSITBService::GetCurrentCDPath() always reports.
"1://x.cue" RealPath() formats "%s/%s" onto m_CurrentPath, and m_CurrentPath
is "1:/" for the whole session whenever the worker auto-enters
the images partition on connect - which it does for every client
that does not CWD somewhere first.
"1:x.cue" FTPPathToFatFsPath() consumes the separator after the volume
when it converts an absolute FTP path, and never restores it.
FatFs resolves all three to the same file - a drive-relative path is taken
against that volume's current directory, which is its root - so every spelling
works for f_open/f_unlink/f_rename and only a string comparison can tell them
apart. A guard that compares them naively is silently inert for the most
ordinary case there is, and looks like it works the moment the client happens
to CWD first.
So paths are normalized before comparing: separators collapsed, trailing one
dropped, and one guaranteed after the volume colon. Case-insensitively, because
FAT is.
That comparison lives in fatfspath.h rather than in the worker because
ftpworker.cpp cannot be compiled into the host suite - it needs the socket
stack - and a guard nothing can test is a guard that quietly stops working.
test_ftppaths.cpp asserts every spelling the worker actually produces, and the
negative cases too: a prefix, a deeper path, or a same-named file on 0: must
NOT match, because a guard that over-refuses is its own bug.
Two smaller things in the same code:
Log the refusal before sending it. SendStatus() formats the reply into
m_CommandBuffer (ftpworker.cpp:349) and pArgs points into that same buffer, so
replying first overwrites the argument being logged - the line prints the reply
back to itself, offset by the five bytes of "553 T".
Delete and RenameTo looked the service up by task name and dereferenced the
result without checking it, on a path that already tolerates its absence
elsewhere. Both now go through RefreshImageCache().
This does not address a mounted image that goes missing by other means - a card
pulled, or an image deleted before this build. That is the separate
missing-image-at-boot behaviour.
CDUtils::GetBlocksizeForTrack logged its result at NOTICE on every branch, with a bare MLOGNOTE rather than the CDROM_DEBUG_LOG macro its neighbours use. It is called once per READ(10) and once per READ CD (scsi_read.cpp:129 and :436), in IRQ context, which makes it the hottest path in the device. A log pulled off David's Zero 2 W today contained 13,069 of these lines, peaking at 929 in a single second. The cost is not the log file, and it is not avoidable by configuration: CLogger::WriteV() builds a CString and queues the event BEFORE it consults the log level, so each call heap-allocates inside an interrupt no matter what loglevel is set to. Downstream it is worse - the file log daemon f_writes and f_syncs each line (filelogdaemon.cpp:223,231), CEMMCDevice pulses the ACT LED around every SD transfer (emmc.cpp:680-703), and on a Zero 2 W that LED is a CVirtualGPIOPin driven through the VideoCore mailbox, whose spinlock is TASK_LEVEL and does not hold off IRQs. So one log line per sector read turns into SD writes and mailbox round-trips at kilohertz rates. That is worth removing on its own. It is also the leading suspect for two symptoms David reports - the device running hot, and random hard lockups with a solid ACT LED - because mailbox contention is exactly what locked up this same board on 2026-07-21, and a mailbox wedged mid-operation would leave the LED stuck on. Not proven, and deliberately not claimed: the point of this commit is that a per-sector NOTICE has no business being unconditional. Now gated behind m_bDebugLogging like every other diagnostic in the file. The MLOGERR for an unhandled track mode stays - it is rare and it matters.
This was referenced Jul 29, 2026
Trim the explanatory comments added by this branch down to the density of the code around them. Several blocks had grown into essays that restated the diff or recorded the debugging story rather than the reason, and a few files gained nothing but comments. No code changes. Comment share of the added lines drops from 43% to 30%; the surrounding files sit around 20%.
Collaborator
Author
|
Replaced by #239, which is the same 13 commits with the comments trimmed down, so there is only one thing to review. Closing this one. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
This collects the work from yesterday into a single branch instead of six. It is 13 commits on top of main (558bf4e), rebased clean with no merge commits. Tested on hardware: ran on a Pi yesterday, stable, no lockups.
Mounting and cue handling
A cue sheet that splits its tracks across several files used to mount anyway, and the drive would come up with the wrong disc in it. It is now refused outright. Along with that, the mount path stopped reporting success when the image had actually failed to load, and it now says what the mount did rather than just that the filename was found. When an image cannot be mounted, the reason is shown to the user instead of being swallowed. Saved images that have gone missing now leave the drive empty rather than quietly substituting a different disc, and an ejected drive no longer puts a disc back in by itself. The file browser also stopped listing .bin files, which were never mountable on their own.
Logging
A bad log file path could take the whole system down with it. It cannot now. The web UI shows whether file logging is actually working, and the config page describes the path rule that the form enforces.
FTP
Deleting, renaming or overwriting the currently mounted image is now refused.
MDS
The reader tracks its read position directly instead of inferring it from the file pointer.
Hot path
Removed the log line that fired on every SCSI read.
Tests
The host regression suite passes at 162 tests, 0 failures, including two new groups added here: FTP path matching, and file log daemon.