From c81541c27fd44e2feffb675a455613eb4a6ab111 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Thu, 30 Jul 2026 10:50:08 -0400 Subject: [PATCH 01/13] mount: report why an image would not mount A mount is queued and finishes long after the web request was answered "ok", so a failure had no way back to the user: the page said nothing and the reason only reached the log. The service now records why the last attempt failed and the image-name endpoint the page already polls carries it back. --- addon/scsitbservice/scsitbservice.cpp | 9 +++++++++ addon/scsitbservice/scsitbservice.h | 6 ++++++ addon/webserver/handlers/imagenameapi.cpp | 8 ++++++++ 3 files changed, 23 insertions(+) diff --git a/addon/scsitbservice/scsitbservice.cpp b/addon/scsitbservice/scsitbservice.cpp index 09acde5a..3cd7c02e 100644 --- a/addon/scsitbservice/scsitbservice.cpp +++ b/addon/scsitbservice/scsitbservice.cpp @@ -469,11 +469,16 @@ void SCSITBService::ProcessPendingMount() { return; } + + m_LastMountError[0] = '\0'; + // Build full path using relativePath from cache const char* relativePath = m_FileEntries[next_cd].relativePath; // Ensure we have room for "1:/" prefix (3 chars) + relativePath + null terminator if (strlen(relativePath) > MAX_PATH_LEN - 4) { LOGERR("Path too long: %s", relativePath); + snprintf(m_LastMountError, sizeof(m_LastMountError), + "Path is too long to mount: %s", relativePath); next_cd = -1; return; } @@ -483,6 +488,10 @@ void SCSITBService::ProcessPendingMount() { if (imageDevice == nullptr) { LOGERR("Failed to load image: %s", m_CurrentImagePath); + snprintf(m_LastMountError, sizeof(m_LastMountError), + "Could not load %s. It may be an unsupported or damaged image; " + "the log has the details. The previous disc is still mounted.", + relativePath); next_cd = -1; return; } diff --git a/addon/scsitbservice/scsitbservice.h b/addon/scsitbservice/scsitbservice.h index f0830290..404a0ce4 100644 --- a/addon/scsitbservice/scsitbservice.h +++ b/addon/scsitbservice/scsitbservice.h @@ -56,6 +56,9 @@ class SCSITBService : public CTask void SetPendingInsert(); bool IsEjected() const; // delegates to cdromservice + // Why the last mount attempt failed, or "" if it worked. + const char* GetLastMountError() const { return m_LastMountError; } + // Task entry point void Run(void); @@ -81,6 +84,9 @@ class SCSITBService : public CTask bool m_bBootEjectPending = false; bool m_bPersistedEjected = false; + // Set by ProcessPendingMount() on every failure path, cleared on success. + char m_LastMountError[160] = {0}; + // Full path of currently mounted image (e.g., "1:/Games/game.iso") char m_CurrentImagePath[MAX_PATH_LEN]; diff --git a/addon/webserver/handlers/imagenameapi.cpp b/addon/webserver/handlers/imagenameapi.cpp index 072b3b84..5d85351f 100644 --- a/addon/webserver/handlers/imagenameapi.cpp +++ b/addon/webserver/handlers/imagenameapi.cpp @@ -26,6 +26,14 @@ THTTPStatus ImageNameAPIHandler::GetJson(nlohmann::json& j, j = { {"name", svc->GetCurrentCDName()} }; + + // Mounting finishes long after the request was answered "ok", so a failure + // has no other way back to the user. The page already polls this endpoint. + const char* mountError = svc->GetLastMountError(); + if (mountError != nullptr && mountError[0] != '\0') { + j["mount_error"] = mountError; + } + return HTTPOK; } From 3b85341792aa30feb29be2e998c001039d1e7330 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Thu, 30 Jul 2026 10:50:36 -0400 Subject: [PATCH 02/13] mount: say why a load failed, not just that it did Every loader returns nullptr on failure, so the reason it gave never left the log. The loaders now record it and the web UI shows it, which turns "it did not mount" into something a user can act on. Cue sheets are listed whether or not a same-stem .bin sits beside them: hiding them made a rip that needs attention look like it was never there. --- addon/discimage/util.cpp | 29 ++++++++++++++++++++ addon/discimage/util.h | 4 +++ addon/scsitbservice/scsitbservice.cpp | 20 +++++++++----- addon/webserver/handlers/pagehandlerbase.cpp | 7 +++++ addon/webserver/pages/template.html | 6 ++++ 5 files changed, 59 insertions(+), 7 deletions(-) diff --git a/addon/discimage/util.cpp b/addon/discimage/util.cpp index 52ddb9f0..8cb3161a 100644 --- a/addon/discimage/util.cpp +++ b/addon/discimage/util.cpp @@ -25,8 +25,29 @@ #include "mdsfile.h" #include "chdfile.h" +#include + LOGMODULE("discimage-util"); +// Reason the last load failed. Every loader returns nullptr, so without this the +// reason only ever reached the log. +static char s_LastImageLoadError[192] = {0}; + +const char* GetLastImageLoadError() { + return s_LastImageLoadError; +} + +static void ClearImageLoadError() { + s_LastImageLoadError[0] = '\0'; +} + +static void SetImageLoadError(const char* format, ...) { + va_list args; + va_start(args, format); + vsnprintf(s_LastImageLoadError, sizeof(s_LastImageLoadError), format, args); + va_end(args); +} + char tolower(char c) { if (c >= 'A' && c <= 'Z') return c + ('a' - 'A'); @@ -200,6 +221,7 @@ IImageDevice* loadMDSFileDevice(const char* imagePath) { size_t mds_size = 0; if (!ReadFileToString(fullPath, &mds_str, &mds_size)) { LOGERR("Failed to read MDS file: %s", fullPath); + SetImageLoadError("Could not read the .mds file. It may be unreadable or too large."); return nullptr; } @@ -207,6 +229,7 @@ IImageDevice* loadMDSFileDevice(const char* imagePath) { CMDSFileDevice* mdsDevice = new CMDSFileDevice(fullPath, mds_str, mds_size, mediaType); if (!mdsDevice->Init()) { LOGERR("Failed to initialize MDS device: %s", imagePath); + SetImageLoadError("Not a valid Alcohol 120%% image, or its .mdf data file is missing."); delete mdsDevice; return nullptr; } @@ -246,6 +269,7 @@ IImageDevice* loadCueBinIsoFileDevice(const char* imagePath) { LOGNOTE("Loading CUE sheet from: %s", fullPath); if (!ReadFileToString(fullPath, &cue_str)) { LOGERR("Failed to read CUE file: %s", fullPath); + SetImageLoadError("Could not read the cue sheet for this image."); delete imageFile; return nullptr; } @@ -260,6 +284,7 @@ IImageDevice* loadCueBinIsoFileDevice(const char* imagePath) { FRESULT result = f_open(imageFile, fullPath, FA_READ); if (result != FR_OK) { LOGERR("Cannot open data file for reading: %s (error %d)", fullPath, result); + SetImageLoadError("The data file this image needs is missing: %s", fullPath); delete imageFile; if (cue_str) delete[] cue_str; return nullptr; @@ -293,6 +318,7 @@ IImageDevice* loadCHDFileDevice(const char* imagePath) { CCHDFileDevice* chdDevice = new CCHDFileDevice(fullPath, mediaType); if (!chdDevice->Init()) { LOGERR("Failed to initialize CHD device: %s", imagePath); + SetImageLoadError("Not a valid CHD image, or it uses an unsupported compression."); delete chdDevice; return nullptr; } @@ -378,6 +404,8 @@ IImageDevice* loadImageDevice(const char* imagePath) { // imagePath is a full path like "1:/Games/game.iso" LOGNOTE("loadImageDevice called for: %s", imagePath); + ClearImageLoadError(); + if (hasMdsExtension(imagePath)) { LOGNOTE("Detected MDS format - using MDS plugin"); return loadMDSFileDevice(imagePath); @@ -392,6 +420,7 @@ IImageDevice* loadImageDevice(const char* imagePath) { } else { LOGERR("Unknown file format: %s", imagePath); + SetImageLoadError("Unsupported file type. USBODE mounts .iso, .cue/.bin, .chd, .mds and .toast images."); return nullptr; } } \ No newline at end of file diff --git a/addon/discimage/util.h b/addon/discimage/util.h index 41a60378..3b469438 100644 --- a/addon/discimage/util.h +++ b/addon/discimage/util.h @@ -24,6 +24,10 @@ bool hasDvdHint(const char* imageName); // Image loading - returns base IImageDevice interface IImageDevice* loadImageDevice(const char* imageName); +// Why the last loadImageDevice() failed, in words a user can act on, or "" if it +// succeeded. Written by the loaders, read by SCSITBService when a mount is refused. +const char* GetLastImageLoadError(); + // Format-specific loaders IImageDevice* loadMDSFileDevice(const char* imageName); IImageDevice* loadCueBinIsoFileDevice(const char* imageName); diff --git a/addon/scsitbservice/scsitbservice.cpp b/addon/scsitbservice/scsitbservice.cpp index 3cd7c02e..97c23429 100644 --- a/addon/scsitbservice/scsitbservice.cpp +++ b/addon/scsitbservice/scsitbservice.cpp @@ -339,9 +339,8 @@ void SCSITBService::ScanDirectoryRecursive(const char* fullPath, const char* rel bool listIt = iequals(ext, ".iso") || iequals(ext, ".mds") || iequals(ext, ".chd") || iequals(ext, ".toast"); if (!listIt && iequals(ext, ".cue")) { - // Mounting a .cue opens the same-stem .bin, so only list - // cue sheets whose data file is actually there - listIt = siblingWithExtExists(fullPath, fno.fname, ".bin"); + // Even with no same-stem .bin, which also hid split-track rips. + listIt = true; } else if (!listIt && iequals(ext, ".bin")) { // Hide the raw .bin of a cue/bin pair; its .cue is listed listIt = !siblingWithExtExists(fullPath, fno.fname, ".cue"); @@ -488,10 +487,17 @@ void SCSITBService::ProcessPendingMount() { if (imageDevice == nullptr) { LOGERR("Failed to load image: %s", m_CurrentImagePath); - snprintf(m_LastMountError, sizeof(m_LastMountError), - "Could not load %s. It may be an unsupported or damaged image; " - "the log has the details. The previous disc is still mounted.", - relativePath); + // The generic wording below is only for paths with no reason of their own. + const char* why = GetLastImageLoadError(); + if (why != nullptr && why[0] != '\0') { + snprintf(m_LastMountError, sizeof(m_LastMountError), + "%s (%s) The previous disc is still mounted.", why, relativePath); + } else { + snprintf(m_LastMountError, sizeof(m_LastMountError), + "Could not load %s. It may be an unsupported or damaged image; " + "the log has the details. The previous disc is still mounted.", + relativePath); + } next_cd = -1; return; } diff --git a/addon/webserver/handlers/pagehandlerbase.cpp b/addon/webserver/handlers/pagehandlerbase.cpp index ca046ebe..ff712057 100644 --- a/addon/webserver/handlers/pagehandlerbase.cpp +++ b/addon/webserver/handlers/pagehandlerbase.cpp @@ -64,6 +64,13 @@ THTTPStatus PageHandlerBase::GetContent(const char *pPath, // Get current loaded image std::string current_image = svc->GetCurrentCDName(); + // Say so on every page: the request is answered "ok" before the image has + // loaded. Set only when non-empty, so the template section stays falsy. + const char* mountError = svc->GetLastMountError(); + if (mountError != nullptr && mountError[0] != '\0') { + context.set("mount_error", std::string(mountError)); + } + // Get our config service ConfigService* config = static_cast(CScheduler::Get()->GetTask("configservice")); diff --git a/addon/webserver/pages/template.html b/addon/webserver/pages/template.html index bac2dd14..d16af1f7 100644 --- a/addon/webserver/pages/template.html +++ b/addon/webserver/pages/template.html @@ -19,6 +19,12 @@

USB Optical Drive Emulator

+ {{#mount_error}} +
+ Last mount failed: {{mount_error}} +
+ {{/mount_error}} + {{#cdrom}} {{>content}} {{/cdrom}} From 433748c537f40e64c023581c5144e92d11bf76c7 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 14:52:58 -0400 Subject: [PATCH 03/13] browser: stop listing .bin files, which were never mountable 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. (cherry picked from commit da3e0a2eaf5135552063288f20129bc1b3fc87b2) --- addon/scsitbservice/scsitbservice.cpp | 23 ++--------------------- 1 file changed, 2 insertions(+), 21 deletions(-) diff --git a/addon/scsitbservice/scsitbservice.cpp b/addon/scsitbservice/scsitbservice.cpp index 97c23429..44f5e2dd 100644 --- a/addon/scsitbservice/scsitbservice.cpp +++ b/addon/scsitbservice/scsitbservice.cpp @@ -51,24 +51,6 @@ static bool iequals(const char* a, const char* b) { return *a == *b; } -// True if a file with the same stem but a different extension exists next to -// fileName in dirFullPath (e.g. "game.bin" + ".cue" -> "1:/Games/game.cue"). -// FAT name matching is case-insensitive, so GAME.CUE is found too. -static bool siblingWithExtExists(const char* dirFullPath, const char* fileName, const char* newExt) { - const char* dot = strrchr(fileName, '.'); - if (dot == nullptr) - return false; - - char sibling[MAX_PATH_LEN]; - int n = snprintf(sibling, sizeof(sibling), "%s/%.*s%s", - dirFullPath, (int)(dot - fileName), fileName, newExt); - if (n < 0 || (size_t)n >= sizeof(sibling)) - return false; - - FILINFO fi; - return f_stat(sibling, &fi) == FR_OK && !(fi.fattrib & AM_DIR); -} - int compareFileEntries(const void* a, const void* b) { const FileEntry* fa = (const FileEntry*)a; const FileEntry* fb = (const FileEntry*)b; @@ -341,10 +323,9 @@ void SCSITBService::ScanDirectoryRecursive(const char* fullPath, const char* rel if (!listIt && iequals(ext, ".cue")) { // Even with no same-stem .bin, which also hid split-track rips. listIt = true; - } else if (!listIt && iequals(ext, ".bin")) { - // Hide the raw .bin of a cue/bin pair; its .cue is listed - listIt = !siblingWithExtExists(fullPath, fno.fname, ".cue"); } + // Never a .bin: mounting reads the .cue first, so a .bin is either + // unmountable or already represented by that cue. if (listIt) { size_t len = my_strnlen(fno.fname, MAX_FILENAME_LEN - 1); memcpy(m_FileEntries[m_FileCount].name, fno.fname, len); From 78541421b4441099a7583f2c7fb603e0233fc266 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 15:01:28 -0400 Subject: [PATCH 04/13] mount: stop reporting a disc that failed to load as the mounted one 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. (cherry picked from commit 7d0934d78ef6ce4bdab10f5d47a7704281c78b84) --- addon/scsitbservice/scsitbservice.cpp | 59 ++++++++++++++++---- addon/scsitbservice/scsitbservice.h | 11 +++- addon/webserver/handlers/imagenameapi.cpp | 4 +- addon/webserver/handlers/pagehandlerbase.cpp | 5 +- 4 files changed, 64 insertions(+), 15 deletions(-) diff --git a/addon/scsitbservice/scsitbservice.cpp b/addon/scsitbservice/scsitbservice.cpp index 44f5e2dd..cb4224b1 100644 --- a/addon/scsitbservice/scsitbservice.cpp +++ b/addon/scsitbservice/scsitbservice.cpp @@ -228,7 +228,9 @@ bool SCSITBService::IsEjected() const { } const char* SCSITBService::GetCurrentCDName() { - return GetName(GetCurrentCD()); + // Never nullptr: callers feed this straight into std::string. + const char* name = GetName(GetCurrentCD()); + return name != nullptr ? name : ""; } bool SCSITBService::SetNextCDByName(const char* file_name) { @@ -377,6 +379,25 @@ bool SCSITBService::RefreshCache() { LOGNOTE("SCSITBService::RefreshCache() Found %d total entries", (int)m_FileCount); + // The list was just rebuilt, so re-derive current_cd from the mounted path. + { + int resolved = -1; + if (m_MountedRelativePath[0] != '\0') { + for (size_t i = 0; i < m_FileCount; ++i) { + if (!m_FileEntries[i].isDirectory && + strcmp(m_FileEntries[i].relativePath, m_MountedRelativePath) == 0) { + resolved = (int)i; + break; + } + } + } + if (resolved != current_cd) { + LOGNOTE("SCSITBService::RefreshCache() current index %d -> %d after rescan", + current_cd, resolved); + } + current_cd = resolved; + } + // Find the current image in cache by matching relative path const char* searchPath = current_image; bool found = false; @@ -423,12 +444,18 @@ bool SCSITBService::RefreshCache() { // then persist "inserted" over the saved state. if (!found && m_FileCount > 0 && !IsEjected()) { for (size_t i = 0; i < m_FileCount; ++i) { - if (!m_FileEntries[i].isDirectory) { - LOGNOTE("SCSITBService::RefreshCache() Current image not found, using: %s", - m_FileEntries[i].relativePath); - next_cd = i; - break; + if (m_FileEntries[i].isDirectory) { + continue; } + // Or every rescan picks it again and re-raises the error banner. + if (m_LastFailedRelativePath[0] != '\0' && + strcmp(m_FileEntries[i].relativePath, m_LastFailedRelativePath) == 0) { + continue; + } + LOGNOTE("SCSITBService::RefreshCache() Current image not found, using: %s", + m_FileEntries[i].relativePath); + next_cd = i; + break; } } @@ -462,12 +489,17 @@ void SCSITBService::ProcessPendingMount() { next_cd = -1; return; } - snprintf(m_CurrentImagePath, sizeof(m_CurrentImagePath), "1:/%s", relativePath); + // Local, not m_CurrentImagePath, which would make a failed mount report a + // disc the host was never given. + char candidatePath[MAX_PATH_LEN]; + snprintf(candidatePath, sizeof(candidatePath), "1:/%s", relativePath); - IImageDevice* imageDevice = loadImageDevice(m_CurrentImagePath); + IImageDevice* imageDevice = loadImageDevice(candidatePath); if (imageDevice == nullptr) { - LOGERR("Failed to load image: %s", m_CurrentImagePath); + LOGERR("Failed to load image: %s", candidatePath); + strncpy(m_LastFailedRelativePath, relativePath, sizeof(m_LastFailedRelativePath) - 1); + m_LastFailedRelativePath[sizeof(m_LastFailedRelativePath) - 1] = '\0'; // The generic wording below is only for paths with no reason of their own. const char* why = GetLastImageLoadError(); if (why != nullptr && why[0] != '\0') { @@ -484,12 +516,19 @@ void SCSITBService::ProcessPendingMount() { } LOGNOTE("Loaded image: %s (format: %d, has subchannels: %s)", - m_CurrentImagePath, + candidatePath, (int)imageDevice->GetFileType(), imageDevice->HasSubchannelData() ? "yes" : "no"); cdromservice->SetDevice(imageDevice); + // Committed only now that the disc is really the one the host has. + strncpy(m_CurrentImagePath, candidatePath, sizeof(m_CurrentImagePath) - 1); + m_CurrentImagePath[sizeof(m_CurrentImagePath) - 1] = '\0'; + strncpy(m_MountedRelativePath, relativePath, sizeof(m_MountedRelativePath) - 1); + m_MountedRelativePath[sizeof(m_MountedRelativePath) - 1] = '\0'; + m_LastFailedRelativePath[0] = '\0'; + // Save relative path to config (without "1:/" prefix) configservice->SetCurrentImage(relativePath); diff --git a/addon/scsitbservice/scsitbservice.h b/addon/scsitbservice/scsitbservice.h index 404a0ce4..c2a47a1a 100644 --- a/addon/scsitbservice/scsitbservice.h +++ b/addon/scsitbservice/scsitbservice.h @@ -84,8 +84,15 @@ class SCSITBService : public CTask bool m_bBootEjectPending = false; bool m_bPersistedEjected = false; - // Set by ProcessPendingMount() on every failure path, cleared on success. - char m_LastMountError[160] = {0}; + // 320 because at 160 the split-track message was cut off mid-word. + char m_LastMountError[320] = {0}; + + // What is ACTUALLY mounted, written only after a load succeeds. current_cd is + // an index into a rebuilt list, so it is re-derived from this. + char m_MountedRelativePath[MAX_PATH_LEN] = {0}; + + // So the fallback in RefreshCache does not keep picking the same bad image. + char m_LastFailedRelativePath[MAX_PATH_LEN] = {0}; // Full path of currently mounted image (e.g., "1:/Games/game.iso") char m_CurrentImagePath[MAX_PATH_LEN]; diff --git a/addon/webserver/handlers/imagenameapi.cpp b/addon/webserver/handlers/imagenameapi.cpp index 5d85351f..84387e81 100644 --- a/addon/webserver/handlers/imagenameapi.cpp +++ b/addon/webserver/handlers/imagenameapi.cpp @@ -23,8 +23,10 @@ THTTPStatus ImageNameAPIHandler::GetJson(nlohmann::json& j, return HTTPInternalServerError; } + // Defensive: nlohmann's string construction is undefined on a null char*. + const char* name = svc->GetCurrentCDName(); j = { - {"name", svc->GetCurrentCDName()} + {"name", name != nullptr ? name : ""} }; // Mounting finishes long after the request was answered "ok", so a failure diff --git a/addon/webserver/handlers/pagehandlerbase.cpp b/addon/webserver/handlers/pagehandlerbase.cpp index ff712057..2dc69c5b 100644 --- a/addon/webserver/handlers/pagehandlerbase.cpp +++ b/addon/webserver/handlers/pagehandlerbase.cpp @@ -61,8 +61,9 @@ THTTPStatus PageHandlerBase::GetContent(const char *pPath, if (!svc) return HTTPInternalServerError; - // Get current loaded image - std::string current_image = svc->GetCurrentCDName(); + // std::string from a null char* is undefined, and this runs for every page. + const char* current_image_name = svc->GetCurrentCDName(); + std::string current_image = current_image_name != nullptr ? current_image_name : ""; // Say so on every page: the request is answered "ok" before the image has // loaded. Set only when non-empty, so the template section stays falsy. From 6edcace60532a06fe0dbf1161a9c4a672afb760f Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 12:52:53 -0400 Subject: [PATCH 05/13] logging: stop a bad log file path from taking the system down with 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. (cherry picked from commit e54ecceab0f1338d8bf43ec2acdc8b12beb97ba9) --- addon/filelogdaemon/filelogdaemon.cpp | 85 ++++--- addon/filelogdaemon/filelogdaemon.h | 31 ++- addon/webserver/handlers/configpage.cpp | 77 ++++++- integration-tests/Makefile | 9 +- integration-tests/README.md | 33 ++- integration-tests/harness/fatfs_host.cpp | 29 ++- integration-tests/harness/framework.cpp | 1 + integration-tests/harness/stubs.cpp | 125 +++++++++- .../harness/stubs/circle/logger.h | 23 ++ .../harness/stubs/circle/sched/scheduler.h | 11 +- .../stubs/circle/sched/synchronizationevent.h | 12 +- .../harness/stubs/circle/sched/task.h | 22 +- .../harness/stubs/circle/string.h | 8 + integration-tests/harness/stubs/circle/time.h | 10 + integration-tests/harness/stubs/fatfs/ff.h | 1 + .../test-suite/test_logdaemon.cpp | 214 ++++++++++++++++++ src/kernel.cpp | 19 +- 17 files changed, 640 insertions(+), 70 deletions(-) create mode 100644 integration-tests/harness/stubs/circle/string.h create mode 100644 integration-tests/harness/stubs/circle/time.h create mode 100644 integration-tests/test-suite/test_logdaemon.cpp diff --git a/addon/filelogdaemon/filelogdaemon.cpp b/addon/filelogdaemon/filelogdaemon.cpp index 837dbfb7..7b6c5139 100644 --- a/addon/filelogdaemon/filelogdaemon.cpp +++ b/addon/filelogdaemon/filelogdaemon.cpp @@ -33,8 +33,11 @@ LOGMODULE("filelogdaemon"); CFileLogDaemon *CFileLogDaemon::s_pThis = nullptr; CFileLogDaemon::CFileLogDaemon(const char *pLogFilePath, unsigned uiLogLevel) - : m_pLogFilePath(pLogFilePath), - m_uiLogLevel(uiLogLevel > 5 ? 5 : uiLogLevel) { + : m_uiLogLevel(uiLogLevel > 5 ? 5 : uiLogLevel) { + if (pLogFilePath != nullptr) { + strncpy(m_LogFilePath, pLogFilePath, sizeof(m_LogFilePath) - 1); + m_LogFilePath[sizeof(m_LogFilePath) - 1] = '\0'; + } // I am the one and only! assert(s_pThis == nullptr); s_pThis = this; @@ -52,10 +55,21 @@ void CFileLogDaemon::SetLogLevel(unsigned uiLogLevel) { } boolean CFileLogDaemon::Initialize() { + if (m_LogFilePath[0] == '\0') { + // An empty path is the config saying "no file logging", not an error. + m_OpenResult = FR_INVALID_NAME; + LOGNOTE("No log file configured; file logging is off"); + return FALSE; + } + // Open log file for writing (append mode) - FRESULT Result = f_open(&m_LogFile, m_pLogFilePath, FA_WRITE | FA_OPEN_ALWAYS); + FRESULT Result = f_open(&m_LogFile, m_LogFilePath, FA_WRITE | FA_OPEN_ALWAYS); + m_OpenResult = Result; if (Result != FR_OK) { - LOGERR("Failed to open log file"); + // Name the path and the reason; this is the only evidence the user gets. + // Only volume 0: is mounted this early, so a path on 1: lands here. + LOGERR("Failed to open log file '%s' (FatFs error %d); file logging is off", + m_LogFilePath, (int)Result); return FALSE; } @@ -96,36 +110,45 @@ void CFileLogDaemon::Run(void) { while (true) { m_Event.Clear(); + DrainOnce(); + m_Event.Wait(); + } +} - TLogSeverity Severity; - char Source[LOG_MAX_SOURCE]; - char Message[LOG_MAX_MESSAGE]; - time_t Time; - unsigned nHundredthTime; - int nTimeZone; - while (pLogger->ReadEvent(&Severity, Source, Message, - &Time, &nHundredthTime, &nTimeZone)) { - // CLogger queues every event regardless of its loglevel (that - // only filters the serial/screen target), so the configured - // level is applied here. Severity LogPanic(0)..LogDebug(4) - // maps to config levels 1..5; level 0 drops everything. - if ((unsigned)Severity >= m_uiLogLevel) { - continue; - } - if (!LogMessage(Severity, Time, nHundredthTime, nTimeZone, Source, Message)) { - CScheduler::Get()->Sleep(20); - } +void CFileLogDaemon::DrainOnce(void) { + CLogger *pLogger = CLogger::Get(); + assert(pLogger != nullptr); + + TLogSeverity Severity; + char Source[LOG_MAX_SOURCE]; + char Message[LOG_MAX_MESSAGE]; + time_t Time; + unsigned nHundredthTime; + int nTimeZone; + while (pLogger->ReadEvent(&Severity, Source, Message, + &Time, &nHundredthTime, &nTimeZone)) { + // CLogger queues every event regardless of loglevel, which only filters + // the serial/screen target, so the configured level is applied here. + // LogPanic(0)..LogDebug(4) maps to config levels 1..5; 0 drops everything. + if ((unsigned)Severity >= m_uiLogLevel) { + continue; } - m_Event.Wait(); + // Only back off for a failure that might not repeat: with no file open, + // sleeping per message throttled the queue to 50 events a second. + if (LogMessage(Severity, Time, nHundredthTime, nTimeZone, Source, Message) == + LogResult::WriteFailed) { + CScheduler::Get()->Sleep(20); + } } } -boolean CFileLogDaemon::LogMessage(TLogSeverity Severity, - time_t FullTime, unsigned nPartialTime, int nTimeNumOffset, - const char *pAppName, const char *pMsg) { +CFileLogDaemon::LogResult CFileLogDaemon::LogMessage(TLogSeverity Severity, + time_t FullTime, unsigned nPartialTime, + int nTimeNumOffset, + const char *pAppName, const char *pMsg) { if (!m_bFileInitialized) { - return FALSE; + return LogResult::NoFile; } // Format the log entry similar to base logger but tailored for file @@ -161,14 +184,14 @@ boolean CFileLogDaemon::LogMessage(TLogSeverity Severity, UINT BytesWritten; FRESULT Result = f_write(&m_LogFile, LogEntry, strlen(LogEntry), &BytesWritten); if (Result != FR_OK) { - // TODO implement proper error handling here!!! - LOGERR("Failed to write to log file!"); - return FALSE; + // Not logged: this runs while draining the log queue, so a message here + // would queue another event that fails the same way. + return LogResult::WriteFailed; } f_sync(&m_LogFile); - return TRUE; + return LogResult::Written; } void CFileLogDaemon::EventNotificationHandler(void) { diff --git a/addon/filelogdaemon/filelogdaemon.h b/addon/filelogdaemon/filelogdaemon.h index 8e34d737..536b3f02 100644 --- a/addon/filelogdaemon/filelogdaemon.h +++ b/addon/filelogdaemon/filelogdaemon.h @@ -42,6 +42,16 @@ class CFileLogDaemon : public CTask { boolean Initialize(); void Run(void); + // One pass of Run()'s loop, split out so it can be tested; Run() never returns. + void DrainOnce(void); + + // The constructor cannot report a failed open, so callers ask afterwards. + boolean IsFileLogging(void) const { return m_bFileInitialized; } + + const char *GetLogFilePath(void) const { return m_LogFilePath; } + + FRESULT GetOpenResult(void) const { return m_OpenResult; } + // Takes effect immediately; only affects the log file, not the // loglevel= filtering Circle applies to the serial/screen target. void SetLogLevel(unsigned uiLogLevel); @@ -49,9 +59,17 @@ class CFileLogDaemon : public CTask { static CFileLogDaemon *Get(void); private: - boolean LogMessage(TLogSeverity Severity, - time_t FullTime, unsigned nPartialTime, int nTimeNumOffset, - const char *pAppName, const char *pMsg); + // A failed write is worth backing off for; a file never opened is not. + enum class LogResult + { + Written, + WriteFailed, // transient: the file is open, this write did not land + NoFile // permanent for this boot: there is nothing to write to + }; + + LogResult LogMessage(TLogSeverity Severity, + time_t FullTime, unsigned nPartialTime, int nTimeNumOffset, + const char *pAppName, const char *pMsg); static void EventNotificationHandler(void); static void PanicHandler(void); @@ -59,8 +77,11 @@ class CFileLogDaemon : public CTask { private: CSynchronizationEvent m_Event; static CFileLogDaemon *s_pThis; - boolean m_bFileInitialized; - const char *m_pLogFilePath; + // Must start FALSE, or a failed open still writes to an unopened FIL. + boolean m_bFileInitialized = FALSE; + // Copied, not aliased: the config store may replace the caller's string. + char m_LogFilePath[256] = {0}; + FRESULT m_OpenResult = FR_NOT_READY; unsigned m_uiLogLevel; FIL m_LogFile; }; diff --git a/addon/webserver/handlers/configpage.cpp b/addon/webserver/handlers/configpage.cpp index 216e3071..867edefd 100644 --- a/addon/webserver/handlers/configpage.cpp +++ b/addon/webserver/handlers/configpage.cpp @@ -32,6 +32,62 @@ std::string ConfigPageHandler::GetHTML() { return std::string(s_Config); } +// Normalize a user-typed log path onto volume 0: and reject what FatFs cannot +// open - the only validation it gets, and a bad path is not discovered until the +// next boot. An empty result means logging is off, which is a choice. +static bool NormalizeLogfilePath(std::string& path, std::string& error) { + const size_t first = path.find_first_not_of(" \t"); + if (first == std::string::npos) { + path.clear(); + return true; + } + path = path.substr(first, path.find_last_not_of(" \t") - first + 1); + + // FatFs accepts either separator and users type both. + std::replace(path.begin(), path.end(), '\\', '/'); + + // Refuse any volume but the boot partition: 1: is real but is not mounted + // until well after the log daemon starts. + const size_t colon = path.find(':'); + if (colon != std::string::npos) { + const std::string volume = path.substr(0, colon); + if (volume != "0") { + error = "Log file must be on the boot partition. Remove the \"" + volume + + ":\" prefix and give a path like usbode-log.txt."; + return false; + } + path.erase(0, colon + 1); + } + while (!path.empty() && path[0] == '/') { + path.erase(0, 1); + } + + if (path.empty() || path.back() == '/') { + error = "Log file path has to name a file, not a directory."; + return false; + } + if (path.find(':') != std::string::npos) { + error = "Log file path cannot contain a colon."; + return false; + } + + // FatFs will not create a directory. f_opendir, not f_stat, which cannot + // describe a volume root. + const size_t slash = path.find_last_of('/'); + if (slash != std::string::npos) { + const std::string dir = path.substr(0, slash); + DIR probe; + if (f_opendir(&probe, ("0:/" + dir).c_str()) != FR_OK) { + error = "Directory \"" + dir + "\" does not exist on the boot partition."; + return false; + } + f_closedir(&probe); + } + + path = "0:/" + path; + return true; +} + std::map ConfigPageHandler::ParseFormData(const char* pFormData) { std::map params; @@ -126,15 +182,16 @@ THTTPStatus ConfigPageHandler::PopulateContext(kainjow::mustache::data& context, config->SetST7789SleepBrightness(std::atoi(form_params["st7789_sleep_brightness"].c_str())); } - // Log file configuration + // An empty value means "off"; the write path used to ignore it. if (form_params.count("logfile")) { std::string logfile = form_params["logfile"]; - if (!logfile.empty()) { - // Ensure 0:/ prefix - if (logfile.find("0:/") != 0) { - logfile = "0:/" + logfile; - } + std::string logfileError; + if (NormalizeLogfilePath(logfile, logfileError)) { config->SetLogfile(logfile.c_str()); + } else { + error_message = logfileError; + LOGWARN("Rejected log file path '%s': %s", + form_params["logfile"].c_str(), logfileError.c_str()); } } @@ -193,8 +250,12 @@ THTTPStatus ConfigPageHandler::PopulateContext(kainjow::mustache::data& context, // Check for action parameter to determine what to do after saving std::string action = form_params.count("action") ? form_params["action"] : "save"; - - if (action == "save_reboot") { + + // "Saved successfully" next to a rejection would read as though the + // rejected value went in too. + if (!error_message.empty()) { + error_message += " Other settings were saved."; + } else if (action == "save_reboot") { success_message = "Configuration saved successfully. Rebooting in 3 seconds..."; // Schedule a reboot in 3 seconds new CShutdown(ShutdownReboot, 3000); diff --git a/integration-tests/Makefile b/integration-tests/Makefile index 22f5b23c..ded6d990 100644 --- a/integration-tests/Makefile +++ b/integration-tests/Makefile @@ -68,6 +68,13 @@ DISCIMAGE_SRCS := \ $(ADDON)/discimage/mdsfile.cpp \ $(ADDON)/mdsparser/mdsparser.cpp +# The file log daemon. Not a disc-image path, but it reaches the SD card +# through the same FatFs seam, and what it does when that open FAILS is the +# behaviour worth pinning: a bad path used to cost 20 ms of scheduler time per +# log event, which presented as the whole Pi having gone slow. +SERVICE_SRCS := \ + $(ADDON)/filelogdaemon/filelogdaemon.cpp + CHDR_OBJS := ifeq ($(WITH_CHD),1) DISCIMAGE_SRCS += $(ADDON)/discimage/chdfile.cpp @@ -97,7 +104,7 @@ endif HARNESS_SRCS := $(wildcard harness/*.cpp) TEST_SRCS := $(wildcard test-suite/*.cpp) -CXX_SRCS := $(GADGET_SRCS) $(DISCIMAGE_SRCS) $(HARNESS_SRCS) $(TEST_SRCS) +CXX_SRCS := $(GADGET_SRCS) $(DISCIMAGE_SRCS) $(SERVICE_SRCS) $(HARNESS_SRCS) $(TEST_SRCS) CXX_OBJS := $(addprefix $(BUILD)/,$(notdir $(CXX_SRCS:.cpp=.o))) OBJS := $(CXX_OBJS) $(CHDR_OBJS) diff --git a/integration-tests/README.md b/integration-tests/README.md index d5777a9f..47ecdd92 100644 --- a/integration-tests/README.md +++ b/integration-tests/README.md @@ -11,6 +11,22 @@ make -C integration-tests WITH_CHD=1 # also run the real .chd image through libc USBODE_TEST_VERBOSE=1 integration-tests/out/usbode-host-tests # with firmware logs ``` +Under a sanitizer. Note that a `CXXFLAGS` on the command line **replaces** the +one the Makefile builds up rather than adding to it, so `-std=c++17` has to be +repeated or the build fails: + +``` +make -C integration-tests clean +make -C integration-tests \ + CXXFLAGS="-std=c++17 -O0 -g -fsanitize=address,undefined" \ + CFLAGS="-O0 -g -fsanitize=address,undefined" \ + LDFLAGS="-fsanitize=address,undefined" +``` + +Worth running when a fix is about an uninitialised member: a `bool` that holds +neither 0 nor 1 is undefined to read, so an ordinary assertion cannot pin it - +the optimizer folds the test - but UBSan names the exact line. + ## What this is The **real firmware sources** — all of `addon/usbcdgadget` (command @@ -198,17 +214,26 @@ integration-tests/ Makefile host build; `make` = build + run, WITH_CHD=1 adds CHD harness/ stubs/ minimal Circle/service headers (circle/, cdplayer/, fatfs/, ...) - stubs.cpp logger/scheduler/timer/endpoint implementations + stubs.cpp logger/scheduler/timer/endpoint implementations; the + logger keeps a real event queue and the scheduler counts + sleeps, so a task that drains the log can be tested testbus.h records BeginTransfer()/Stall() from the gadget fakedisc.* in-memory disc images + cue sheets - fatfs_host.cpp FatFs f_open/f_read/... over host stdio (real-image reads) + fatfs_host.cpp FatFs f_open/f_read/... over host stdio (real-image + reads, and writes for the log daemon) discimage_host.cpp FatFsOptimizer no-op backing (fast seek n/a on host) bench.* the virtual USB host framework.* tiny TEST()/CHECK() runner - test-suite/ one file per command family, plus test_realimages.cpp - and test_mdsimages.cpp + test-suite/ one file per command family, plus test_realimages.cpp, + test_mdsimages.cpp and test_logdaemon.cpp ``` +Not everything here is a SCSI command. `addon/filelogdaemon` is compiled in +too, because it reaches the SD card through the same FatFs seam and its +interesting behaviour is what it does when that open **fails**: a log path +under a directory that does not exist used to cost 20 ms of scheduler time per +log event, which presented as the whole Pi having gone slow. + Two production accommodations (both inert on the device): - `tcdstate_update.cpp`: the ARM cache-maintenance asm is guarded by diff --git a/integration-tests/harness/fatfs_host.cpp b/integration-tests/harness/fatfs_host.cpp index 01bf1c34..b4202108 100644 --- a/integration-tests/harness/fatfs_host.cpp +++ b/integration-tests/harness/fatfs_host.cpp @@ -18,8 +18,25 @@ FRESULT f_open(FIL* fp, const TCHAR* path, BYTE mode) if (!fp || !path) { return FR_INVALID_PARAMETER; } - // The readers only ever open images read-only. - FILE* f = fopen(path, "rb"); + + // The mode has to be honoured: whether the log daemon's append open succeeds + // is the whole subject of its tests. FA_OPEN_ALWAYS is "r+b" falling back to + // "w+b" only when the file is missing, which keeps a bad directory an error. + const char* stdioMode = "rb"; + if (mode & (FA_WRITE | FA_CREATE_ALWAYS | FA_CREATE_NEW | FA_OPEN_ALWAYS)) { + if (mode & FA_CREATE_ALWAYS) { + stdioMode = "w+b"; + } else if ((mode & FA_OPEN_APPEND) == FA_OPEN_APPEND) { + stdioMode = "a+b"; + } else { + stdioMode = "r+b"; + } + } + + FILE* f = fopen(path, stdioMode); + if (!f && (mode & (FA_OPEN_ALWAYS | FA_CREATE_NEW))) { + f = fopen(path, "w+b"); + } if (!f) { return FR_NO_FILE; } @@ -86,6 +103,14 @@ FRESULT f_write(FIL* fp, const void* buff, UINT btw, UINT* bw) return (n == btw) ? FR_OK : FR_DISK_ERR; } +FRESULT f_sync(FIL* fp) +{ + if (!fp || !fp->host_fp) { + return FR_INVALID_OBJECT; + } + return fflush((FILE*)fp->host_fp) == 0 ? FR_OK : FR_DISK_ERR; +} + FRESULT f_lseek(FIL* fp, FSIZE_t ofs) { if (!fp || !fp->host_fp) { diff --git a/integration-tests/harness/framework.cpp b/integration-tests/harness/framework.cpp index 269edfab..ccad7cc6 100644 --- a/integration-tests/harness/framework.cpp +++ b/integration-tests/harness/framework.cpp @@ -59,6 +59,7 @@ namespace {"test_realimages", "Real disc images"}, {"test_mdsimages", "MDS/MDF images"}, {"test_multisession", "Multi-session and CD Extra"}, + {"test_logdaemon", "File log daemon"}, }; // "test-suite/test_read10.cpp" -> "SCSI read commands" diff --git a/integration-tests/harness/stubs.cpp b/integration-tests/harness/stubs.cpp index 37dddad1..4c3639f9 100644 --- a/integration-tests/harness/stubs.cpp +++ b/integration-tests/harness/stubs.cpp @@ -43,23 +43,116 @@ CLogger *CLogger::Get(void) return &instance; } +namespace +{ +struct LogEvent +{ + TLogSeverity severity; + std::string source; + std::string message; +}; + +// Bounded, like the real logger's ring. What matters is that events survive +// until something drains them. +const size_t kMaxQueuedEvents = 256; + +std::vector &EventQueue() +{ + static std::vector queue; + return queue; +} + +TLogEventNotificationHandler *g_pEventHandler = nullptr; +TLogPanicHandler *g_pPanicHandler = nullptr; +} // namespace + void CLogger::Write(const char *pSource, TLogSeverity Severity, const char *pMessage, ...) { static const bool verbose = getenv("USBODE_TEST_VERBOSE") != nullptr; + + char formatted[LOG_MAX_MESSAGE]; + va_list var; + va_start(var, pMessage); + vsnprintf(formatted, sizeof(formatted), pMessage, var); + va_end(var); + + // Queue first, and unconditionally: the real logger does not consult any + // loglevel here. + TestQueueEvent(Severity, pSource, formatted); + if (!verbose) { return; } static const char *severityNames[] = {"panic", "error", "warn", "note", "debug"}; - fprintf(stdout, "[%s] %s: ", severityNames[Severity], pSource); + fprintf(stdout, "[%s] %s: %s\n", severityNames[Severity], pSource, formatted); +} - va_list var; - va_start(var, pMessage); - vfprintf(stdout, pMessage, var); - va_end(var); +void CLogger::TestQueueEvent(TLogSeverity Severity, const char *pSource, const char *pMessage) +{ + std::vector &queue = EventQueue(); + if (queue.size() >= kMaxQueuedEvents) + { + queue.erase(queue.begin()); + } + queue.push_back({Severity, pSource ? pSource : "", pMessage ? pMessage : ""}); - fprintf(stdout, "\n"); + if (g_pEventHandler != nullptr) + { + g_pEventHandler(); + } +} + +void CLogger::TestClearEvents(void) +{ + EventQueue().clear(); +} + +unsigned CLogger::TestQueuedEventCount(void) +{ + return (unsigned)EventQueue().size(); +} + +boolean CLogger::ReadEvent(TLogSeverity *pSeverity, char *pSource, char *pMessage, + time_t *pTime, unsigned *pHundredthTime, int *pTimeZone) +{ + std::vector &queue = EventQueue(); + if (queue.empty()) + { + return FALSE; + } + + LogEvent event = queue.front(); + queue.erase(queue.begin()); + + if (pSeverity) *pSeverity = event.severity; + if (pSource) + { + strncpy(pSource, event.source.c_str(), LOG_MAX_SOURCE - 1); + pSource[LOG_MAX_SOURCE - 1] = '\0'; + } + if (pMessage) + { + strncpy(pMessage, event.message.c_str(), LOG_MAX_MESSAGE - 1); + pMessage[LOG_MAX_MESSAGE - 1] = '\0'; + } + // A fixed time keeps log lines byte-comparable between runs. + if (pTime) *pTime = 0; + if (pHundredthTime) *pHundredthTime = 0; + if (pTimeZone) *pTimeZone = 0; + + return TRUE; +} + +void CLogger::RegisterEventNotificationHandler(TLogEventNotificationHandler *pHandler) +{ + g_pEventHandler = pHandler; +} + +void CLogger::RegisterPanicHandler(TLogPanicHandler *pHandler) +{ + g_pPanicHandler = pHandler; } // --------------------------------------------------------------------------- @@ -103,6 +196,26 @@ void CScheduler::TestClearTasks(void) TaskRegistry().clear(); } +namespace +{ +unsigned g_nSleepCount = 0; +} + +void CScheduler::TestNoteSleep(void) +{ + g_nSleepCount++; +} + +unsigned CScheduler::TestSleepCount(void) +{ + return g_nSleepCount; +} + +void CScheduler::TestResetSleepCount(void) +{ + g_nSleepCount = 0; +} + // --------------------------------------------------------------------------- // CTimer // --------------------------------------------------------------------------- diff --git a/integration-tests/harness/stubs/circle/logger.h b/integration-tests/harness/stubs/circle/logger.h index be9b05a5..b7251a67 100644 --- a/integration-tests/harness/stubs/circle/logger.h +++ b/integration-tests/harness/stubs/circle/logger.h @@ -7,6 +7,7 @@ #define _circle_logger_h #include +#include enum TLogSeverity { @@ -17,12 +18,34 @@ enum TLogSeverity LogDebug }; +// Sizes as declared by the real circle/logger.h, since CFileLogDaemon sizes +// its own ReadEvent() buffers from them. +#define LOG_MAX_SOURCE 50 +#define LOG_MAX_MESSAGE 200 + +typedef void TLogEventNotificationHandler(void); +typedef void TLogPanicHandler(void); + class CLogger { public: static CLogger *Get(void); void Write(const char *pSource, TLogSeverity Severity, const char *pMessage, ...); + + // The real CLogger queues EVERY event whatever the loglevel; consumers + // filter as they drain. Dropping here would hide a daemon filtering wrongly. + boolean ReadEvent(TLogSeverity *pSeverity, char *pSource, char *pMessage, + time_t *pTime, unsigned *pHundredthTime, int *pTimeZone); + + void RegisterEventNotificationHandler(TLogEventNotificationHandler *pHandler); + void RegisterPanicHandler(TLogPanicHandler *pHandler); + + // Test-side control: queue an event as firmware would, and empty the queue + // between tests so one test's chatter is not read by the next. + static void TestQueueEvent(TLogSeverity Severity, const char *pSource, const char *pMessage); + static void TestClearEvents(void); + static unsigned TestQueuedEventCount(void); }; // Match the real Circle logging macros so firmware sources that use diff --git a/integration-tests/harness/stubs/circle/sched/scheduler.h b/integration-tests/harness/stubs/circle/sched/scheduler.h index 9dd0a7a4..6a3ab8b4 100644 --- a/integration-tests/harness/stubs/circle/sched/scheduler.h +++ b/integration-tests/harness/stubs/circle/sched/scheduler.h @@ -17,14 +17,19 @@ class CScheduler CTask *GetTask(const char *pTaskName); - void Sleep(unsigned nSeconds) {} - void MsSleep(unsigned nMilliSeconds) {} - void usSleep(unsigned nMicroSeconds) {} + // Sleeping cannot happen on a single-threaded host, but it is counted: on a + // real Pi a sleep on a per-event path costs the whole system. + void Sleep(unsigned nSeconds) { TestNoteSleep(); } + void MsSleep(unsigned nMilliSeconds) { TestNoteSleep(); } + void usSleep(unsigned nMicroSeconds) { TestNoteSleep(); } void Yield(void) {} // Test control void TestRegisterTask(const char *pName, CTask *pTask); void TestClearTasks(void); + static void TestNoteSleep(void); + static unsigned TestSleepCount(void); + static void TestResetSleepCount(void); }; #endif diff --git a/integration-tests/harness/stubs/circle/sched/synchronizationevent.h b/integration-tests/harness/stubs/circle/sched/synchronizationevent.h index 7d89e45f..23124c84 100644 --- a/integration-tests/harness/stubs/circle/sched/synchronizationevent.h +++ b/integration-tests/harness/stubs/circle/sched/synchronizationevent.h @@ -4,13 +4,19 @@ #ifndef _circle_sched_synchronizationevent_h #define _circle_sched_synchronizationevent_h +// State is tracked so a test can tell whether a daemon was woken. Wait() cannot +// block on a single-threaded host, so tasks are driven one step at a time. class CSynchronizationEvent { public: - CSynchronizationEvent(void) {} - void Set(void) {} - void Clear(void) {} + CSynchronizationEvent(void) : m_bState(false) {} + void Set(void) { m_bState = true; } + void Clear(void) { m_bState = false; } void Wait(void) {} + bool GetState(void) const { return m_bState; } + +private: + bool m_bState; }; #endif diff --git a/integration-tests/harness/stubs/circle/sched/task.h b/integration-tests/harness/stubs/circle/sched/task.h index f9e69476..90c2d23b 100644 --- a/integration-tests/harness/stubs/circle/sched/task.h +++ b/integration-tests/harness/stubs/circle/sched/task.h @@ -6,13 +6,33 @@ #include +#include + class CTask { public: - CTask(void) {} + CTask(void) { m_Name[0] = '\0'; } virtual ~CTask(void) {} virtual void Run(void) {} + + // Circle finds tasks by name through CScheduler::GetTask(), so the stub has + // to keep the name rather than discard it. + void SetName(const char *pName) + { + if (pName == nullptr) + { + m_Name[0] = '\0'; + return; + } + strncpy(m_Name, pName, sizeof(m_Name) - 1); + m_Name[sizeof(m_Name) - 1] = '\0'; + } + + const char *GetName(void) const { return m_Name; } + +private: + char m_Name[32]; }; #endif diff --git a/integration-tests/harness/stubs/circle/string.h b/integration-tests/harness/stubs/circle/string.h new file mode 100644 index 00000000..5ffbf38d --- /dev/null +++ b/integration-tests/harness/stubs/circle/string.h @@ -0,0 +1,8 @@ +// +// Host-build stub for . Deliberately empty: nothing the suite +// compiles uses CString. Add it here if that changes. +// +#ifndef _circle_string_h +#define _circle_string_h + +#endif diff --git a/integration-tests/harness/stubs/circle/time.h b/integration-tests/harness/stubs/circle/time.h new file mode 100644 index 00000000..d8216ef6 --- /dev/null +++ b/integration-tests/harness/stubs/circle/time.h @@ -0,0 +1,10 @@ +// +// Host-build stub for . Only time_t is used, so defer to the +// host's own rather than restating CTime. +// +#ifndef _circle_time_h +#define _circle_time_h + +#include + +#endif diff --git a/integration-tests/harness/stubs/fatfs/ff.h b/integration-tests/harness/stubs/fatfs/ff.h index 61bda71f..f7312908 100644 --- a/integration-tests/harness/stubs/fatfs/ff.h +++ b/integration-tests/harness/stubs/fatfs/ff.h @@ -110,6 +110,7 @@ FRESULT f_open (FIL* fp, const TCHAR* path, BYTE mode); FRESULT f_close (FIL* fp); FRESULT f_read (FIL* fp, void* buff, UINT btr, UINT* br); FRESULT f_write (FIL* fp, const void* buff, UINT btw, UINT* bw); +FRESULT f_sync (FIL* fp); FRESULT f_lseek (FIL* fp, FSIZE_t ofs); // Directory walk: link-only stubs for mdsfile.cpp (MDS is not under test). diff --git a/integration-tests/test-suite/test_logdaemon.cpp b/integration-tests/test-suite/test_logdaemon.cpp new file mode 100644 index 00000000..f4e3fe43 --- /dev/null +++ b/integration-tests/test-suite/test_logdaemon.cpp @@ -0,0 +1,214 @@ +// +// test_logdaemon.cpp +// +// The file log daemon on the host FatFs seam, mostly about what it does when the +// file it was told to open is not there. Run() never returns, so the tests drive +// DrainOnce(), one pass of its loop. +// +#include "framework.h" + +#include +#include +#include +#include + +#include +#include + +#include +#include +#include + +// --------------------------------------------------------------------------- +// Helpers +// --------------------------------------------------------------------------- + +static std::string TestDataDir() +{ +#ifdef USBODE_TESTDATA + return USBODE_TESTDATA; +#else + return "out/images"; +#endif +} + +static void QueueEvents(unsigned n, TLogSeverity severity = LogError) +{ + for (unsigned i = 0; i < n; i++) { + char msg[64]; + snprintf(msg, sizeof(msg), "event %u", i); + CLogger::TestQueueEvent(severity, "test", msg); + } +} + +static std::string ReadWholeFile(const std::string &path) +{ + FILE *f = fopen(path.c_str(), "rb"); + if (!f) { + return std::string(); + } + std::string out; + char buf[4096]; + size_t n; + while ((n = fread(buf, 1, sizeof(buf), f)) > 0) { + out.append(buf, n); + } + fclose(f); + return out; +} + +static void RemoveFile(const std::string &path) +{ + remove(path.c_str()); +} + +// The rest of the suite logs freely into this same queue, so start each test clean. +static void ResetLogging() +{ + CLogger::TestClearEvents(); + CScheduler::TestResetSleepCount(); +} + +// --------------------------------------------------------------------------- +// Tests +// --------------------------------------------------------------------------- + +// The headline defect: with no file open, the drain loop slept 20 ms per failed +// message, retiring 50 events a second and taking the scheduler down with it. +// The events must still be consumed, just not paid for. +TEST(logdaemon_unopenable_path_drains_without_sleeping) +{ + ResetLogging(); + + // A missing directory, the shape of the reported value "0:/SD:/usbode-logs.txt". + const std::string path = TestDataDir() + "/no-such-dir/usbode-logs.txt"; + + CFileLogDaemon daemon(path.c_str(), 5); + CHECK(!daemon.IsFileLogging()); + CHECK(daemon.GetOpenResult() != FR_OK); + + // The constructor logs its own failure; clear so the count below is ours. + ResetLogging(); + + const unsigned kEvents = 200; + QueueEvents(kEvents); + CHECK_EQ(CLogger::TestQueuedEventCount(), kEvents); + + daemon.DrainOnce(); + + // Consumed, and for free. + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + CHECK_EQ(CScheduler::TestSleepCount(), 0u); +} + +// m_bFileInitialized had no initializer, so a failed open left it holding +// whatever was in that memory. Constructing over poisoned storage exposes it. +// Reading an invalid bool is undefined, so this asserts the behaviour rather +// than the flag; -fsanitize=undefined catches the read itself. +TEST(logdaemon_failed_open_leaves_the_file_flag_false) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/no-such-dir/usbode-logs.txt"; + + alignas(CFileLogDaemon) static unsigned char storage[sizeof(CFileLogDaemon)]; + memset(storage, 0xAA, sizeof(storage)); + + CFileLogDaemon *daemon = new (storage) CFileLogDaemon(path.c_str(), 5); + CHECK(!daemon->IsFileLogging()); + + ResetLogging(); + QueueEvents(4); + daemon->DrainOnce(); + CHECK_EQ(CScheduler::TestSleepCount(), 0u); + + daemon->~CFileLogDaemon(); +} + +// An empty path is the config's way of saying "no file logging", not a +// mistake, so it must not be reported as a failure to open something. +TEST(logdaemon_empty_path_is_logging_disabled) +{ + ResetLogging(); + + CFileLogDaemon daemon("", 5); + CHECK(!daemon.IsFileLogging()); + CHECK_EQ(daemon.GetOpenResult(), FR_INVALID_NAME); + + ResetLogging(); + QueueEvents(16); + daemon.DrainOnce(); + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + CHECK_EQ(CScheduler::TestSleepCount(), 0u); +} + +// The path that has to keep working. CLogger queues every event regardless of +// level, so the configured level has to be applied on this side of the queue. +TEST(logdaemon_writes_and_applies_the_configured_level) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/logdaemon.txt"; + RemoveFile(path); + + { + // Level 3 keeps panic(0), error(1) and warning(2); notice(3) and + // debug(4) are dropped. + CFileLogDaemon daemon(path.c_str(), 3); + CHECK(daemon.IsFileLogging()); + CHECK_EQ(daemon.GetOpenResult(), FR_OK); + + ResetLogging(); + CLogger::TestQueueEvent(LogError, "src", "an error"); + CLogger::TestQueueEvent(LogWarning, "src", "a warning"); + CLogger::TestQueueEvent(LogNotice, "src", "a notice"); + CLogger::TestQueueEvent(LogDebug, "src", "a debug line"); + daemon.DrainOnce(); + + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + CHECK_EQ(CScheduler::TestSleepCount(), 0u); + } + + const std::string contents = ReadWholeFile(path); + CHECK(contents.find("an error") != std::string::npos); + CHECK(contents.find("a warning") != std::string::npos); + CHECK(contents.find("a notice") == std::string::npos); + CHECK(contents.find("a debug line") == std::string::npos); + + RemoveFile(path); +} + +// The daemon kept the caller's pointer rather than the string, and the config +// store replaces that value when the web UI edits the log path. +TEST(logdaemon_keeps_its_own_copy_of_the_path) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/logdaemon-copy.txt"; + RemoveFile(path); + + char caller[256]; + strncpy(caller, path.c_str(), sizeof(caller) - 1); + caller[sizeof(caller) - 1] = '\0'; + + { + CFileLogDaemon daemon(caller, 5); + CHECK(daemon.IsFileLogging()); + + // The config store hands out a new value for the key. + memset(caller, 0, sizeof(caller)); + strncpy(caller, "0:/somewhere-else.txt", sizeof(caller) - 1); + + CHECK(strcmp(daemon.GetLogFilePath(), path.c_str()) == 0); + + ResetLogging(); + CLogger::TestQueueEvent(LogError, "src", "still the original file"); + daemon.DrainOnce(); + CHECK_EQ(CScheduler::TestSleepCount(), 0u); + } + + const std::string contents = ReadWholeFile(path); + CHECK(contents.find("still the original file") != std::string::npos); + + RemoveFile(path); +} diff --git a/src/kernel.cpp b/src/kernel.cpp index 66550815..c9337a27 100644 --- a/src/kernel.cpp +++ b/src/kernel.cpp @@ -43,7 +43,6 @@ #define FIRMWARE_PATH ROOTDRIVE "/firmware/" #define SUPPLICANT_CONFIG_FILE ROOTDRIVE "/wpa_supplicant.conf" #define CONFIG_FILE ROOTDRIVE "/config.txt" -#define LOG_FILE ROOTDRIVE "/logfile.txt" #define HOSTNAME "usbode" #define SPI_MASTER_DEVICE 0 @@ -142,13 +141,21 @@ boolean CKernel::Initialize(void) m_pConfigService = new ConfigService(); LOGNOTE("Initialized Config service"); - // Start file logging with proper config + // The daemon runs either way, so a bad path otherwise leaves a system + // that looks fine and logs nothing. Only volume 0: is mounted here. const char *logfile = m_pConfigService->GetLogfile(); - if (logfile) + CFileLogDaemon *pLogDaemon = + new CFileLogDaemon(logfile ? logfile : "", m_pConfigService->GetLogLevel()); + if (pLogDaemon->IsFileLogging()) { - new CFileLogDaemon(logfile, m_pConfigService->GetLogLevel()); - // CScheduler::Get()->MsSleep(100); - LOGNOTE("Started early file logging"); + LOGNOTE("Started early file logging to %s", pLogDaemon->GetLogFilePath()); + } + else if (pLogDaemon->GetLogFilePath()[0] != '\0') + { + LOGWARN("File logging is OFF: cannot open '%s' (FatFs error %d). " + "Check the log path on the web UI's config page; it must be " + "a file in an existing directory on the boot partition.", + pLogDaemon->GetLogFilePath(), (int)pLogDaemon->GetOpenResult()); } } } From 7c8a76005ca8d85d11ea4df920df0d78dcdab0c7 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 13:40:16 -0400 Subject: [PATCH 06/13] config page: describe the log path rule the form now enforces 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. (cherry picked from commit a846639e16d8db86e47b9fad3723b6e3d7e494ef) --- addon/webserver/pages/config.html | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/addon/webserver/pages/config.html b/addon/webserver/pages/config.html index d9823cec..7de3e552 100644 --- a/addon/webserver/pages/config.html +++ b/addon/webserver/pages/config.html @@ -130,7 +130,7 @@

Logging Configuration

Current: {{current_logfile}}
-
Leave empty to disable file logging. Will be automatically prefixed with 0:/
+
A file on the boot partition, e.g. usbode-log.txt. The directory must already exist. Leave empty to disable file logging.
From 75a8da33c32f046f2a713ed251dfb6ed4f016ee0 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 13:55:18 -0400 Subject: [PATCH 07/13] logging: show in the web UI whether file logging is actually working 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. (cherry picked from commit 20d12cbf0f1edc506b39a116d39e491517f71687) --- addon/filelogdaemon/filelogdaemon.cpp | 31 +++++++++++ addon/filelogdaemon/filelogdaemon.h | 8 ++- addon/webserver/handlers/configpage.cpp | 13 +++++ addon/webserver/handlers/logpage.cpp | 27 ++++++++-- addon/webserver/pages/config.html | 1 + .../test-suite/test_logdaemon.cpp | 51 +++++++++++++++++++ 6 files changed, 126 insertions(+), 5 deletions(-) diff --git a/addon/filelogdaemon/filelogdaemon.cpp b/addon/filelogdaemon/filelogdaemon.cpp index 7b6c5139..f94e1535 100644 --- a/addon/filelogdaemon/filelogdaemon.cpp +++ b/addon/filelogdaemon/filelogdaemon.cpp @@ -93,6 +93,37 @@ boolean CFileLogDaemon::Initialize() { return TRUE; } +void CFileLogDaemon::GetStatusText(char *pBuffer, size_t nBufferSize) const { + if (pBuffer == nullptr || nBufferSize == 0) { + return; + } + + if (m_LogFilePath[0] == '\0') { + snprintf(pBuffer, nBufferSize, "File logging is off (no log file configured)."); + } else if (m_bFileInitialized) { + snprintf(pBuffer, nBufferSize, "Writing to %s", m_LogFilePath); + } else { + snprintf(pBuffer, nBufferSize, + "NOT LOGGING: cannot open %s (FatFs error %d). " + "The file must be on the boot partition and its directory must already exist.", + m_LogFilePath, (int)m_OpenResult); + } +} + +void CFileLogDaemon::GetStdioPath(char *pBuffer, size_t nBufferSize) const { + if (pBuffer == nullptr || nBufferSize == 0) { + return; + } + + // Config stores the FatFs form ("0:/usbode-log.txt"); newlib wants an + // ordinary path ("/usbode-log.txt"). + const char *p = m_LogFilePath; + if (p[0] == '0' && p[1] == ':') { + p += 2; + } + snprintf(pBuffer, nBufferSize, "%s", p); +} + CFileLogDaemon::~CFileLogDaemon(void) { s_pThis = nullptr; diff --git a/addon/filelogdaemon/filelogdaemon.h b/addon/filelogdaemon/filelogdaemon.h index 536b3f02..684d1312 100644 --- a/addon/filelogdaemon/filelogdaemon.h +++ b/addon/filelogdaemon/filelogdaemon.h @@ -47,11 +47,15 @@ class CFileLogDaemon : public CTask { // The constructor cannot report a failed open, so callers ask afterwards. boolean IsFileLogging(void) const { return m_bFileInitialized; } - const char *GetLogFilePath(void) const { return m_LogFilePath; } - FRESULT GetOpenResult(void) const { return m_OpenResult; } + // One line for the web UI; SCREEN_HEADLESS has nowhere else to report this. + void GetStatusText(char *pBuffer, size_t nBufferSize) const; + + // Without the volume prefix, for callers using newlib rather than FatFs. + void GetStdioPath(char *pBuffer, size_t nBufferSize) const; + // Takes effect immediately; only affects the log file, not the // loglevel= filtering Circle applies to the serial/screen target. void SetLogLevel(unsigned uiLogLevel); diff --git a/addon/webserver/handlers/configpage.cpp b/addon/webserver/handlers/configpage.cpp index 867edefd..015250d2 100644 --- a/addon/webserver/handlers/configpage.cpp +++ b/addon/webserver/handlers/configpage.cpp @@ -269,6 +269,19 @@ THTTPStatus ConfigPageHandler::PopulateContext(kainjow::mustache::data& context, } } + // The boot-time warning goes to the serial console, which SCREEN_HEADLESS + // has no equivalent of. + { + char status[256] = {0}; + if (CFileLogDaemon::Get() != nullptr) { + CFileLogDaemon::Get()->GetStatusText(status, sizeof(status)); + } + context["logfile_status"] = std::string(status); + context["logfile_broken"] = (CFileLogDaemon::Get() != nullptr && + !CFileLogDaemon::Get()->IsFileLogging() && + CFileLogDaemon::Get()->GetLogFilePath()[0] != '\0'); + } + // Set current values for display std::string current_displayhat = config->GetDisplayHat(); std::string current_low_power_timeout = std::to_string(config->GetLowPowerTimeout()); diff --git a/addon/webserver/handlers/logpage.cpp b/addon/webserver/handlers/logpage.cpp index f5012681..81100cf5 100644 --- a/addon/webserver/handlers/logpage.cpp +++ b/addon/webserver/handlers/logpage.cpp @@ -15,6 +15,7 @@ #include "logpage.h" #include "../util.h" #include +#include using namespace kainjow; @@ -61,8 +62,28 @@ THTTPStatus LogPageHandler::PopulateContext(kainjow::mustache::data& context, const char *pFormData) { LOGNOTE("Log page called"); - - context["log_lines"] = read_loglines("/usbode-logs.txt"); - + + // The configured file, not the hardcoded "/usbode-logs.txt" this used to + // read, which gave a blank page to anyone who changed the setting. + char path[256] = {0}; + char status[256] = {0}; + CFileLogDaemon *pDaemon = CFileLogDaemon::Get(); + if (pDaemon != nullptr) { + pDaemon->GetStdioPath(path, sizeof(path)); + pDaemon->GetStatusText(status, sizeof(status)); + } + + std::string lines = path[0] != '\0' ? read_loglines(path) : std::string(); + + // Never an empty page: a missing and an empty log file look identical. + if (lines.empty()) { + lines = status[0] != '\0' + ? std::string(status) + : std::string("No log file is available."); + } + + context["log_lines"] = lines; + context["log_status"] = std::string(status); + return HTTPOK; } diff --git a/addon/webserver/pages/config.html b/addon/webserver/pages/config.html index 7de3e552..467c104e 100644 --- a/addon/webserver/pages/config.html +++ b/addon/webserver/pages/config.html @@ -131,6 +131,7 @@

Logging Configuration

Current: {{current_logfile}}
A file on the boot partition, e.g. usbode-log.txt. The directory must already exist. Leave empty to disable file logging.
+
Status: {{logfile_status}}
diff --git a/integration-tests/test-suite/test_logdaemon.cpp b/integration-tests/test-suite/test_logdaemon.cpp index f4e3fe43..b2a75a68 100644 --- a/integration-tests/test-suite/test_logdaemon.cpp +++ b/integration-tests/test-suite/test_logdaemon.cpp @@ -178,6 +178,57 @@ TEST(logdaemon_writes_and_applies_the_configured_level) RemoveFile(path); } +// What the web UI shows. The boot-time warning goes to the serial console, which +// a SCREEN_HEADLESS build has no equivalent of, so without this a user with a bad +// path sees a device that lists a log file and silently has none. +TEST(logdaemon_reports_its_status_for_the_web_ui) +{ + ResetLogging(); + char status[256]; + + // Working. + const std::string good = TestDataDir() + "/logdaemon-status.txt"; + RemoveFile(good); + { + CFileLogDaemon daemon(good.c_str(), 5); + CHECK(daemon.IsFileLogging()); + daemon.GetStatusText(status, sizeof(status)); + CHECK(strstr(status, "Writing to") != nullptr); + CHECK(strstr(status, "NOT LOGGING") == nullptr); + } + RemoveFile(good); + + // Broken: must name the path and say it is not logging. + ResetLogging(); + const std::string bad = TestDataDir() + "/no-such-dir/usbode-logs.txt"; + { + CFileLogDaemon daemon(bad.c_str(), 5); + CHECK(!daemon.IsFileLogging()); + daemon.GetStatusText(status, sizeof(status)); + CHECK(strstr(status, "NOT LOGGING") != nullptr); + CHECK(strstr(status, "usbode-logs.txt") != nullptr); + } + + // Off on purpose is not an error and must not read like one. + ResetLogging(); + { + CFileLogDaemon daemon("", 5); + daemon.GetStatusText(status, sizeof(status)); + CHECK(strstr(status, "off") != nullptr); + CHECK(strstr(status, "NOT LOGGING") == nullptr); + } + + // The log viewer opens the file through newlib, which wants an ordinary path + // rather than the FatFs volume form the config stores. + ResetLogging(); + { + CFileLogDaemon daemon("0:/somewhere/usbode-log.txt", 5); + char path[256]; + daemon.GetStdioPath(path, sizeof(path)); + CHECK(strcmp(path, "/somewhere/usbode-log.txt") == 0); + } +} + // The daemon kept the caller's pointer rather than the string, and the config // store replaces that value when the web UI edits the log path. TEST(logdaemon_keeps_its_own_copy_of_the_path) From 527b6a524344576581100a9efe4f7a54fca63383 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Tue, 28 Jul 2026 12:39:31 -0400 Subject: [PATCH 08/13] mds: track the read position instead of inferring it from the file pointer 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. (cherry picked from commit 16abff1dff9fe0b9a9972588004324e6719e7942) --- addon/discimage/mdsfile.cpp | 101 ++++-- addon/discimage/mdsfile.h | 9 +- .../test-suite/test_mdsimages.cpp | 290 ++++++++++++++++++ 3 files changed, 366 insertions(+), 34 deletions(-) diff --git a/addon/discimage/mdsfile.cpp b/addon/discimage/mdsfile.cpp index d9bcc8be..183f1c11 100644 --- a/addon/discimage/mdsfile.cpp +++ b/addon/discimage/mdsfile.cpp @@ -295,6 +295,26 @@ bool CMDSFileDevice::Init() { m_nTotalFrames); } + // Does the MDF omit any frames? Alcohol drops the pregap by default, so most + // multi-track images have a 150-frame hole and reads must walk frame by frame. + // Summing short means a hole; overlapping tracks sum high and also walk it. + u32 covered = 0; + for (int i = 0; i < m_parser->getNumSessions(); i++) { + MDS_SessionBlock* session = m_parser->getSession(i); + for (int j = 0; j < session->num_all_blocks; j++) { + MDS_TrackBlock* track = m_parser->getTrack(i, j); + if (track->point == 0 || track->point >= 0xA0) { + continue; + } + MDS_TrackExtraBlock* extra = m_parser->getTrackExtra(i, j); + covered += extra ? extra->length : 0; + } + } + m_bHasUnstoredGaps = (covered != m_nTotalFrames); + if (m_bHasUnstoredGaps) { + LOGNOTE("=== MDF is sparse: %u of %u frames stored ===", covered, m_nTotalFrames); + } + LOGNOTE("=== Image has subchannel data: %s ===", m_hasSubchannels ? "YES (SafeDisc compatible)" : "NO"); LOGNOTE("=== Disc length: %u frames ===", m_nTotalFrames); @@ -325,7 +345,7 @@ CMDSFileDevice::~CMDSFileDevice(void) { } bool CMDSFileDevice::TouchesUnstoredGap(u32 firstLBA, size_t nSectors) const { - if (!m_parser) { + if (!m_parser || !m_bHasUnstoredGaps) { return false; } for (size_t i = 0; i < nSectors; i++) { @@ -343,17 +363,20 @@ bool CMDSFileDevice::TouchesUnstoredGap(u32 firstLBA, size_t nSectors) const { int CMDSFileDevice::ReadAcrossGaps(void *pBuffer, size_t nSize) { u8* dest = (u8*)pBuffer; - const size_t sectors = nSize / 2352; size_t total_read = 0; - for (size_t i = 0; i < sectors; i++) { + while (total_read < nSize) { + // A short read would look like an I/O error rather than a hole. + const size_t remaining = nSize - total_read; + const size_t chunk = remaining < 2352 ? remaining : 2352; + int session, trackIdx; MDS_TrackBlock* track = FindTrackForLBA(m_nCurrentLBA, &session, &trackIdx); if (!track) { // Unstored pregap. Zeros are what the pregap of a data track holds // anyway, and they keep the transfer whole instead of failing it. - memset(dest, 0, 2352); + memset(dest, 0, chunk); } else { // Seek per frame rather than trusting the file pointer: a gap // consumed no file position, so it is stale after one. @@ -365,17 +388,20 @@ int CMDSFileDevice::ReadAcrossGaps(void *pBuffer, size_t nSize) { return total_read > 0 ? (int)total_read : -1; } UINT bytes_read = 0; - FRESULT result = f_read(m_pFile, dest, 2352, &bytes_read); - if (result != FR_OK || bytes_read != 2352) { + FRESULT result = f_read(m_pFile, dest, chunk, &bytes_read); + if (result != FR_OK || bytes_read != chunk) { LOGERR("Gap-aware read: LBA %u returned %u bytes (err %d)", m_nCurrentLBA, bytes_read, result); return total_read > 0 ? (int)total_read : -1; } } - dest += 2352; - total_read += 2352; - m_nCurrentLBA++; + dest += chunk; + total_read += chunk; + // A partial tail leaves the position inside the frame it stopped in. + if (chunk == 2352) { + m_nCurrentLBA++; + } } return (int)total_read; @@ -390,8 +416,10 @@ int CMDSFileDevice::Read(void *pBuffer, size_t nSize) { // A transfer that crosses a pregap the MDF does not store cannot be one // f_read, because part of it has no bytes behind it. That is rare enough // to be worth detecting rather than paying for frame-by-frame reads on - // every transfer, so the paths below are left as they were. - if (nSize >= 2352 && TouchesUnstoredGap(m_nCurrentLBA, nSize / 2352)) { + // every transfer, so the paths below are unchanged. Sub-frame transfers are + // still checked; gating on nSize let them return stale bytes. + const size_t framesTouched = (nSize + 2351) / 2352; + if (framesTouched > 0 && TouchesUnstoredGap(m_nCurrentLBA, framesTouched)) { return ReadAcrossGaps(pBuffer, nSize); } @@ -452,6 +480,11 @@ int CMDSFileDevice::Read(void *pBuffer, size_t nSize) { LOGERR("Failed to read %d bytes into memory, err %d", nSize, result); return -1; } + + // Advance by what was consumed, as the two paths above do, or a caller + // reading on judges every later frame against the first one's address. + m_nCurrentLBA += nBytesRead / 2352; + return nBytesRead; } @@ -475,18 +508,17 @@ u64 CMDSFileDevice::Seek(u64 nOffset) { return static_cast(-1); } - // Don't seek if we're already there - if (Tell() == nOffset) - return nOffset; - // Calculate which LBA is being requested u32 lba = nOffset / 2352; // Assuming 2352 bytes per sector u32 offset_in_sector = nOffset % 2352; - + + // Before any early exit can skip it: Read() keys its gap detection off this. + m_nCurrentLBA = lba; + // Find which track contains this LBA int session, trackIdx; MDS_TrackBlock* track = FindTrackForLBA(lba, &session, &trackIdx); - + if (!track) { // An LBA inside the disc but outside every track is a pregap the // imaging tool chose not to store - Alcohol omits them by default, so @@ -495,7 +527,6 @@ u64 CMDSFileDevice::Seek(u64 nOffset) { // track lands here legitimately, and a real drive answers rather than // failing. There is no file position to take up; Read() serves zeros. if (lba < m_nTotalFrames) { - m_nCurrentLBA = lba; return nOffset; } LOGERR("Seek: LBA %u not found in any track", lba); @@ -504,23 +535,26 @@ u64 CMDSFileDevice::Seek(u64 nOffset) { // Calculate offset into MDF file u32 sectors_from_track_start = lba - track->start_sector; - u64 actual_file_offset = track->start_offset + - (sectors_from_track_start * track->sector_size) + + u64 actual_file_offset = track->start_offset + + ((u64)sectors_from_track_start * track->sector_size) + offset_in_sector; - - // LOGDBG("Seek: LBA %u (offset %llu) -> track %d, file offset %llu", + + // LOGDBG("Seek: LBA %u (offset %llu) -> track %d, file offset %llu", // lba, nOffset, track->point, actual_file_offset); - + + // Don't seek if we're already there. Compare against the FILE offset just + // computed, not the disc address nOffset, which coincides often enough to + // skip a seek that was needed. + if (Tell() == actual_file_offset) { + return nOffset; + } + FRESULT result = f_lseek(m_pFile, actual_file_offset); if (result != FR_OK) { LOGERR("Seek to file offset %llu failed, err %d", actual_file_offset, result); return static_cast(-1); } - // Remember which frame this was: Read() cannot recover it from the file - // position once subchannel data makes the physical stride 2448 bytes. - m_nCurrentLBA = lba; - // Return the logical offset that was requested (not the physical file offset) return nOffset; } @@ -651,20 +685,25 @@ int CMDSFileDevice::ReadSubchannel(u32 lba, u8* subchannel) { int session, trackIdx; MDS_TrackBlock* track = FindTrackForLBA(lba, &session, &trackIdx); - + if (!track) { + // An unstored pregap, which Seek() and Read() answer with zeros. + if (lba < m_nTotalFrames) { + memset(subchannel, 0, 96); + return 96; + } LOGERR("LBA %u not found in any track", lba); return -1; } - + // Check if this track has subchannel data if (track->subchannel == 0) { return -1; } - + // Calculate offset into the MDF file u32 sectors_from_track_start = lba - track->start_sector; - u64 sector_offset = track->start_offset + (sectors_from_track_start * track->sector_size); + u64 sector_offset = track->start_offset + ((u64)sectors_from_track_start * track->sector_size); // Subchannel data is stored in the last 96 bytes of each raw sector // Raw sector format: 2352 bytes user data + 96 bytes subchannel diff --git a/addon/discimage/mdsfile.h b/addon/discimage/mdsfile.h index a9498648..9782d9ec 100644 --- a/addon/discimage/mdsfile.h +++ b/addon/discimage/mdsfile.h @@ -82,11 +82,14 @@ class CMDSFileDevice : public IMDSDevice { /// bytes, so its length divided by 2352 over-reports the disc. u32 m_nTotalFrames = 0; - /// The LBA Seek() last resolved. Read() needs it because Tell() reports - /// a PHYSICAL offset in the MDF, which on a 2448-byte-per-sector track - /// is not lba * 2352. + /// The reader's position: set by Seek(), advanced by Read(). Not recoverable + /// from Tell(), which reports a physical MDF offset. u32 m_nCurrentLBA = 0; + /// True if the MDF omits at least one frame. Cached because the alternative + /// is an O(frames x tracks) lookup per read, and most images have no hole. + bool m_bHasUnstoredGaps = false; + // Helper to find track containing an LBA MDS_TrackBlock* FindTrackForLBA(u32 lba, int* sessionOut, int* trackOut) const; diff --git a/integration-tests/test-suite/test_mdsimages.cpp b/integration-tests/test-suite/test_mdsimages.cpp index 4f2517e7..efa3b017 100644 --- a/integration-tests/test-suite/test_mdsimages.cpp +++ b/integration-tests/test-suite/test_mdsimages.cpp @@ -1015,6 +1015,213 @@ TEST(mds_unstored_pregap_reads_as_zeros) delete disc; } +// The gap handling only works if the reader knows which frame it is on. Seek() +// used to compare Tell(), a physical offset, against the logical offset asked +// for, and exit early without recording the LBA. The fixture above misses this +// because every read there jumps to a new address. +TEST(mds_gap_reached_by_a_sequential_read_still_reads_as_zeros) +{ + // On a contiguous 2352-byte image the two offsets coincide at every frame, + // so reading the last stored frame parks the pointer where the early exit fires. + const u32 kTrack1Len = 16; // LBA 0..15; the file's next frame is the ISO PVD + const u32 kGap = 150; + const u32 kTrack2LBA = kTrack1Len + kGap; + const u32 kTrack2Len = 16; + + std::vector raw = RawMode1Sectors(kIso, 0, kTrack1Len + kTrack2Len); + CHECK_EQ(raw.size(), (size_t)(kTrack1Len + kTrack2Len) * 2352); + if (raw.size() != (size_t)(kTrack1Len + kTrack2Len) * 2352) { + return; + } + + const std::string mds = TestDataDir() + "/mdsgapseq.mds"; + const std::string mdf = TestDataDir() + "/mdsgapseq.mdf"; + WriteBytes(mdf, raw); + + MdsTrackSpec t1; + t1.mode = 0xAA; + t1.point = 1; + t1.sectorSize = 2352; + t1.startSector = 0; + t1.startOffset = 0; + t1.length = kTrack1Len; + + MdsTrackSpec t2; + t2.mode = 0xAA; + t2.point = 2; + t2.sectorSize = 2352; + t2.startSector = kTrack2LBA; // 150 frames later on the disc + t2.startOffset = (u64)kTrack1Len * 2352; // but straight after in the file + t2.pregap = kGap; + t2.length = kTrack2Len; + + WriteMdsFile(mds, {t1, t2}, "mdsgapseq.mdf"); + + CMDSFileDevice *disc = OpenMds(mds); + CHECK(disc != nullptr); + if (!disc) { + return; + } + + CGadgetTestBench bench(disc); + bench.Activate(); + bench.RequestSense(); + + auto read = [&bench](u32 lba, u32 blocks) { + const u8 cdb[10] = {0x28, 0, (u8)(lba >> 24), (u8)(lba >> 16), (u8)(lba >> 8), (u8)lba, + 0, (u8)(blocks >> 8), (u8)blocks, 0}; + return bench.SendCommand(cdb, sizeof(cdb), blocks * 2048); + }; + + // Setup: this read parks the file pointer on the boundary. + auto last = read(kTrack1Len - 1, 1); + CHECK_EQ(last.csw.bmCSWStatus, 0); + + // The hole must read as zeros. Serving the file pointer instead is + // unmistakable: track 2's primary volume descriptor is sitting there. + auto gap = read(kTrack1Len, 1); + CHECK_EQ(gap.csw.bmCSWStatus, 0); + CHECK_EQ(gap.data.size(), (size_t)2048); + if (gap.data.size() == 2048) { + CHECK(memcmp(gap.data.data() + 1, "CD001", 5) != 0); + for (size_t i = 0; i < 2048; i++) { + if (gap.data[i] != 0) { + char msg[128]; + snprintf(msg, sizeof(msg), + "gap frame LBA %u: byte %zu is 0x%02x, expected the hole to read as zeros", + kTrack1Len, i, gap.data[i]); + ReportFailure(__FILE__, __LINE__, msg); + break; + } + } + } + + // Track 2 still resolves, so the fix was not to stop trusting start_offset. + auto t2read = read(kTrack2LBA, 1); + CHECK_EQ(t2read.csw.bmCSWStatus, 0); + if (t2read.data.size() == 2048) { + CHECK(memcmp(t2read.data.data() + 1, "CD001", 5) == 0); + } + + // The same defect without a Seek(). The gadget seeks before every batch, so + // it does not produce this caller, but the plain path is the only one of the + // three that used to leave the position behind. + CHECK_EQ(disc->Seek((u64)(kTrack1Len - 2) * 2352), (u64)(kTrack1Len - 2) * 2352); + std::vector twoFrames(2 * 2352); + CHECK_EQ(disc->Read(twoFrames.data(), twoFrames.size()), (int)twoFrames.size()); + + std::vector nextFrame(2352, 0xAA); + CHECK_EQ(disc->Read(nextFrame.data(), nextFrame.size()), (int)nextFrame.size()); + for (size_t i = 0; i < nextFrame.size(); i++) { + if (nextFrame[i] != 0) { + char msg[128]; + snprintf(msg, sizeof(msg), + "read on into the hole: byte %zu is 0x%02x, expected zeros", + i, nextFrame[i]); + ReportFailure(__FILE__, __LINE__, msg); + break; + } + } + + delete disc; +} + +// The two ways to reach a hole other than a whole-frame READ(10). A sub-frame +// read used to skip the gap check on size alone, and ReadSubchannel() used to +// fail on a frame that Seek() and Read() answer with zeros. +TEST(mds_gap_answers_short_reads_and_subchannel_requests_too) +{ + const u32 kTrack1Len = 16; + const u32 kGap = 150; + const u32 kTrack2LBA = kTrack1Len + kGap; + const u32 kTrack2Len = 16; + const u32 kTotal = kTrack2LBA + kTrack2Len; + + std::vector raw = RawMode1Sectors(kIso, 0, kTrack1Len + kTrack2Len); + if (raw.empty()) { + CHECK(false); + return; + } + // Subchannel bytes on both stored tracks, so the hole is the only place a + // request can come back empty. + std::vector image((size_t)(kTrack1Len + kTrack2Len) * 2448); + for (u32 i = 0; i < kTrack1Len + kTrack2Len; i++) { + memcpy(image.data() + (size_t)i * 2448, raw.data() + (size_t)i * 2352, 2352); + for (u32 j = 0; j < 96; j++) { + image[(size_t)i * 2448 + 2352 + j] = SubchannelByte(i, j); + } + } + + const std::string mds = TestDataDir() + "/mdsgapsub.mds"; + const std::string mdf = TestDataDir() + "/mdsgapsub.mdf"; + WriteBytes(mdf, image); + + MdsTrackSpec t1; + t1.mode = 0xAA; + t1.subchannel = 0x08; + t1.point = 1; + t1.sectorSize = 2448; + t1.startSector = 0; + t1.startOffset = 0; + t1.length = kTrack1Len; + + MdsTrackSpec t2; + t2.mode = 0xAA; + t2.subchannel = 0x08; + t2.point = 2; + t2.sectorSize = 2448; + t2.startSector = kTrack2LBA; + t2.startOffset = (u64)kTrack1Len * 2448; + t2.pregap = kGap; + t2.length = kTrack2Len; + + WriteMdsFile(mds, {t1, t2}, "mdsgapsub.mdf"); + + CMDSFileDevice *disc = OpenMds(mds); + CHECK(disc != nullptr); + if (!disc) { + return; + } + + // A stored frame's subchannel still comes back as itself. + u8 sub[96]; + memset(sub, 0xAA, sizeof(sub)); + CHECK_EQ(disc->ReadSubchannel(kTrack1Len - 1, sub), 96); + u8 expected[96]; + for (u32 i = 0; i < 96; i++) { + expected[i] = SubchannelByte(kTrack1Len - 1, i); + } + CHECK_BYTES(sub, sizeof(sub), expected, sizeof(expected)); + + // A frame in the hole answers with zeros rather than failing. + memset(sub, 0xAA, sizeof(sub)); + CHECK_EQ(disc->ReadSubchannel(kTrack1Len, sub), 96); + u8 zeros[96]; + memset(zeros, 0, sizeof(zeros)); + CHECK_BYTES(sub, sizeof(sub), zeros, sizeof(zeros)); + + // Past the disc is still an error, not another hole. + CHECK_EQ(disc->ReadSubchannel(kTotal + 4, sub), -1); + + // A read of less than one frame, landing in the hole. + u8 partial[2048]; + memset(partial, 0xAA, sizeof(partial)); + CHECK_EQ(disc->Seek((u64)kTrack1Len * 2352), (u64)kTrack1Len * 2352); + CHECK_EQ(disc->Read(partial, sizeof(partial)), (int)sizeof(partial)); + for (size_t i = 0; i < sizeof(partial); i++) { + if (partial[i] != 0) { + char msg[128]; + snprintf(msg, sizeof(msg), + "short read in the hole: byte %zu is 0x%02x, expected zeros", + i, partial[i]); + ReportFailure(__FILE__, __LINE__, msg); + break; + } + } + + delete disc; +} + // --------------------------------------------------------------------------- // Subchannel images (2448-byte sectors) // --------------------------------------------------------------------------- @@ -1138,6 +1345,89 @@ TEST(mds_subchannel_image_strips_and_exposes_subchannel_data) } } +// The same defect from the other direction. On a 2448-byte image the physical +// and logical offsets coincide every 49th frame (49 * 2448 == 51 * 2352), so a +// sequential run to frame 48 followed by a seek to LBA 51 hits the early exit +// and serves frame 49 while reporting success. +TEST(mds_subchannel_seek_after_a_read_does_not_serve_a_stale_frame) +{ + const u32 nSectors = 64; + const u32 kSetupLBA = 48; // leaves the file pointer at 49 * 2448 + const u32 kTargetLBA = 51; // whose logical offset is the same 119952 + static_assert(kSetupLBA + 1 == 49 && 49 * 2448 == 51 * 2352, + "the coincidence this test relies on"); + + const std::string mds = TestDataDir() + "/mdsstale.mds"; + const std::string mdf = TestDataDir() + "/mdsstale.mdf"; + + std::vector raw = RawMode1Sectors(kIso, 0, nSectors); + if (raw.empty()) { + CHECK(false); + return; + } + std::vector image((size_t)nSectors * 2448); + for (u32 lba = 0; lba < nSectors; lba++) { + memcpy(image.data() + (size_t)lba * 2448, raw.data() + (size_t)lba * 2352, 2352); + for (u32 i = 0; i < 96; i++) { + image[(size_t)lba * 2448 + 2352 + i] = SubchannelByte(lba, i); + } + } + // Past the ISO's system area every frame here would otherwise be zeros, + // which cannot tell a stale frame from the right one. Stamp each frame's + // user data with its own LBA so a misread names the frame it came from. + for (u32 lba = 0; lba < nSectors; lba++) { + u8 *user = image.data() + (size_t)lba * 2448 + 16; + for (u32 i = 0; i < 2048; i++) { + user[i] = (u8)(lba * 7u + i * 3u + 11u); + } + memcpy(raw.data() + (size_t)lba * 2352 + 16, user, 2048); + } + WriteBytes(mdf, image); + + MdsTrackSpec track; + track.mode = 0xAA; + track.subchannel = 0x08; + track.point = 1; + track.sectorSize = 2448; + track.length = nSectors; + WriteMdsFile(mds, {track}, "mdsstale.mdf"); + + CMDSFileDevice *disc = OpenMds(mds); + CHECK(disc != nullptr); + if (!disc) { + return; + } + + CGadgetTestBench bench(disc); + bench.Activate(); + bench.RequestSense(); + + auto read = [&bench](u32 lba) { + const u8 cdb[10] = {0x28, 0, (u8)(lba >> 24), (u8)(lba >> 16), (u8)(lba >> 8), (u8)lba, + 0, 0, 1, 0}; + return bench.SendCommand(cdb, sizeof(cdb), 2048); + }; + auto expectFrame = [&raw](const std::vector &d, u32 lba) { + if (d.size() != 2048) { + return; + } + u8 expected[2048]; + memcpy(expected, raw.data() + (size_t)lba * 2352 + 16, 2048); + CHECK_BYTES(d.data(), d.size(), expected, sizeof(expected)); + }; + + auto setup = read(kSetupLBA); + CHECK_EQ(setup.csw.bmCSWStatus, 0); + expectFrame(setup.data, kSetupLBA); + + auto target = read(kTargetLBA); + CHECK_EQ(target.csw.bmCSWStatus, 0); + CHECK_EQ(target.data.size(), (size_t)2048); + expectFrame(target.data, kTargetLBA); + + delete disc; +} + // READ CD (0xBE) asking for the subchannel data alongside the user data. // This is the whole point of the format - it is how a copy-protection check // gets at the P-W subchannel - and it is the only path that carries those From 356e71dc220e05227f4d2c5fde0ff3d714226359 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Wed, 29 Jul 2026 21:44:40 -0400 Subject: [PATCH 09/13] gadget: stop audio commands leaving a read pending The audio control commands have no data phase, but several left m_nnumber_blocks set: PLAY AUDIO (10)/(12) parked the track length there, and SEEK, PAUSE/RESUME, STOP and PLAY AUDIO MSF left whatever a read in flight had put there. onXferCmplt reads that counter to decide whether more data is owed or the CSW should go out, which is why every other data-returning handler zeroes it. Left set, the next command that returns data streams raw sectors where its status belongs: a MECHANISM STATUS asking for 8 bytes came back with 1024008, the endpoint stalled, and a host waiting on that transfer hung until the drive was unplugged. Skipping tracks quickly is what makes it likely. The test table-drives all six opcodes with a read deliberately left pending. (cherry picked from commit 7d018535a3e129e6e3cf8ec965af0cae5b8c6d87) --- addon/usbcdgadget/scsi_read.cpp | 13 ++++ integration-tests/test-suite/test_audio.cpp | 82 +++++++++++++++++++++ 2 files changed, 95 insertions(+) diff --git a/addon/usbcdgadget/scsi_read.cpp b/addon/usbcdgadget/scsi_read.cpp index 32c0b7d4..63f07bd6 100644 --- a/addon/usbcdgadget/scsi_read.cpp +++ b/addon/usbcdgadget/scsi_read.cpp @@ -210,6 +210,10 @@ void SCSIRead::DoPlayAudio(CUSBCDGadget* gadget, int cdbSize) } } + // The count above was audio to play, not a transfer owed: onXferCmplt reads + // it to decide whether to keep streaming instead of sending the CSW. + gadget->m_nnumber_blocks = 0; // nothing more after this send + gadget->m_CSW.bmCSWStatus = gadget->bmCSWStatus; gadget->SendCSW(); } @@ -264,6 +268,8 @@ void SCSIRead::PlayAudioMSF(CUSBCDGadget* gadget) gadget->setSenseData(0x05, 0x64, 0x00); // ILLEGAL MODE FOR THIS TRACK OR INCOMPATIBLE MEDIUM } + gadget->m_nnumber_blocks = 0; // nothing more after this send + gadget->m_CSW.bmCSWStatus = gadget->bmCSWStatus; gadget->SendCSW(); } @@ -281,6 +287,9 @@ void SCSIRead::Seek(CUSBCDGadget* gadget) cdplayer->Seek(gadget->m_nblock_address); } + // The cursor moved, so a count still standing no longer matches it. + gadget->m_nnumber_blocks = 0; // nothing more after this send + gadget->m_CSW.bmCSWStatus = gadget->bmCSWStatus; gadget->SendCSW(); } @@ -299,6 +308,8 @@ void SCSIRead::PauseResume(CUSBCDGadget* gadget) cdplayer->Pause(); } + gadget->m_nnumber_blocks = 0; // nothing more after this send + gadget->m_CSW.bmCSWStatus = gadget->bmCSWStatus; gadget->SendCSW(); } @@ -313,6 +324,8 @@ void SCSIRead::StopScan(CUSBCDGadget* gadget) cdplayer->Pause(); } + gadget->m_nnumber_blocks = 0; // nothing more after this send + gadget->m_CSW.bmCSWStatus = gadget->bmCSWStatus; gadget->SendCSW(); } diff --git a/integration-tests/test-suite/test_audio.cpp b/integration-tests/test-suite/test_audio.cpp index 2706c14a..6252816b 100644 --- a/integration-tests/test-suite/test_audio.cpp +++ b/integration-tests/test-suite/test_audio.cpp @@ -46,6 +46,88 @@ TEST(play_audio_10_reaches_player) CHECK_EQ(player.lastPlayBlocks, 500u); } +// PLAY AUDIO parked the track length in the counter onXferCmplt uses to decide +// "more data owed" vs "send the CSW", so the next command streamed raw sectors. +TEST(play_audio_does_not_leave_a_read_pending) +{ + CFakeImageDevice *disc = MakeAudioCD(3, 3000); + CCDPlayer player; + CGadgetTestBench bench(disc, false, &player); + bench.Activate(); + bench.RequestSense(); + + const u8 cdb10[10] = {0x45, 0x00, 0x00, 0x00, 0x0B, 0xB8, 0x00, 0x01, 0xF4, 0x00}; + auto play = bench.SendCommand(cdb10, sizeof(cdb10), 0); + CHECK_EQ(play.csw.bmCSWStatus, 0); + CHECK_EQ(player.playCalls, 1); + + // MECHANISM STATUS pays for it: it has a data phase and, unlike INQUIRY or + // READ TOC, does not zero the counter itself. + const u8 mech[12] = {0xBD, 0, 0, 0, 0, 0, 0, 0, 0, 8, 0, 0}; + auto ms = bench.SendCommand(mech, sizeof(mech), 8); + CHECK(ms.gotCSW); + CHECK_EQ(ms.csw.bmCSWStatus, 0); + CHECK_EQ(ms.data.size(), (size_t)8); +} + +// PLAY AUDIO(12) carries the count in a 4-byte field and had the same problem. +TEST(play_audio_12_does_not_leave_a_read_pending) +{ + CFakeImageDevice *disc = MakeAudioCD(3, 3000); + CCDPlayer player; + CGadgetTestBench bench(disc, false, &player); + bench.Activate(); + bench.RequestSense(); + + const u8 cdb12[12] = {0xA5, 0x00, 0x00, 0x00, 0x0B, 0xB8, + 0x00, 0x00, 0x01, 0xF4, 0x00, 0x00}; + auto play = bench.SendCommand(cdb12, sizeof(cdb12), 0); + CHECK_EQ(play.csw.bmCSWStatus, 0); + + const u8 mech[12] = {0xBD, 0, 0, 0, 0, 0, 0, 0, 0, 8, 0, 0}; + auto ms = bench.SendCommand(mech, sizeof(mech), 8); + CHECK(ms.gotCSW); + CHECK_EQ(ms.csw.bmCSWStatus, 0); + CHECK_EQ(ms.data.size(), (size_t)8); +} + +// Skipping tracks drives the whole audio-control family; none has a data phase, +// so none may leave a count standing for the next command to act on. +TEST(audio_control_commands_leave_no_read_pending) +{ + struct Case { const char *name; u8 cdb[12]; size_t len; }; + const Case cases[] = { + {"PLAY AUDIO(10)", {0x45, 0, 0, 0, 0x0B, 0xB8, 0, 0x01, 0xF4, 0, 0, 0}, 10}, + {"PLAY AUDIO(12)", {0xA5, 0, 0, 0, 0x0B, 0xB8, 0, 0, 0x01, 0xF4, 0, 0}, 12}, + {"PLAY AUDIO MSF", {0x47, 0, 0, 0, 2, 0, 0, 4, 0, 0, 0, 0}, 10}, + {"SEEK(10)", {0x2B, 0, 0, 0, 0x0B, 0xB8, 0, 0, 0, 0, 0, 0}, 10}, + {"PAUSE/RESUME", {0x4B, 0, 0, 0, 0, 0, 0, 0, 0x01, 0, 0, 0}, 10}, + {"STOP PLAY/SCAN", {0x4E, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 10}, + }; + + for (const Case &c : cases) { + CFakeImageDevice *disc = MakeAudioCD(3, 3000); + CCDPlayer player; + CGadgetTestBench bench(disc, false, &player); + bench.Activate(); + bench.RequestSense(); + + // A multi-batch read still owing blocks, which is the state a host that + // is reading the disc while playing leaves behind. + bench.SetPendingBlocks(500); + auto ctrl = bench.SendCommand(c.cdb, c.len, 0); + CHECK(ctrl.gotCSW); + + const u8 mech[12] = {0xBD, 0, 0, 0, 0, 0, 0, 0, 0, 8, 0, 0}; + auto ms = bench.SendCommand(mech, sizeof(mech), 8); + if (!ms.gotCSW || ms.data.size() != 8) { + ReportFailure(__FILE__, __LINE__, + std::string(c.name) + " left a read pending: got " + + std::to_string(ms.data.size()) + " bytes, expected 8"); + } + } +} + TEST(play_audio_on_data_track_fails) { CFakeImageDevice *disc = MakeDataISO(1200); From 2e109d1bb435ea04d88fb935844f55edb3c39642 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Wed, 29 Jul 2026 21:44:41 -0400 Subject: [PATCH 10/13] mds: read an image that records no track lengths Some .mds files carry no track lengths and the frame count falls back to the MDF size. That can only happen when every length is zero, which also means no frame counts as stored and FindTrackForLBA never matches, so the sparse check declared the whole disc a hole and served zeros instead of the image. Seek had the same blind spot: with no track containing the LBA it took the pregap path and left the file pointer alone, so only a sequential read worked. These images now map LBA straight onto the MDF. Coverage is measured with the track ranges merged rather than summed. An overlap was counted twice, so an overlap the size of a real hole added up to a full disc and turned gap-aware reads back off. Both found by CodeRabbit. (cherry picked from commit 9232280077703c050de392c21e3acda237fbfda5) --- addon/discimage/mdsfile.cpp | 110 ++++++++-- addon/discimage/mdsfile.h | 8 + .../test-suite/test_mdsimages.cpp | 205 ++++++++++++++++-- 3 files changed, 287 insertions(+), 36 deletions(-) diff --git a/addon/discimage/mdsfile.cpp b/addon/discimage/mdsfile.cpp index 183f1c11..db150469 100644 --- a/addon/discimage/mdsfile.cpp +++ b/addon/discimage/mdsfile.cpp @@ -290,30 +290,22 @@ bool CMDSFileDevice::Init() { if (m_nTotalFrames == 0) { // No track lengths recorded. Fall back to the old behaviour rather // than presenting an empty disc. + m_bFlatOffsets = true; m_nTotalFrames = (u32)(f_size(m_pFile) / 2352); LOGWARN("No track lengths in MDS; deriving %u frames from the MDF size", m_nTotalFrames); } - // Does the MDF omit any frames? Alcohol drops the pregap by default, so most - // multi-track images have a 150-frame hole and reads must walk frame by frame. - // Summing short means a hole; overlapping tracks sum high and also walk it. - u32 covered = 0; - for (int i = 0; i < m_parser->getNumSessions(); i++) { - MDS_SessionBlock* session = m_parser->getSession(i); - for (int j = 0; j < session->num_all_blocks; j++) { - MDS_TrackBlock* track = m_parser->getTrack(i, j); - if (track->point == 0 || track->point >= 0xA0) { - continue; - } - MDS_TrackExtraBlock* extra = m_parser->getTrackExtra(i, j); - covered += extra ? extra->length : 0; + // Alcohol drops the pregap, so most multi-track images have a hole. Not asked + // when the count came from the file size: nothing would count as stored. + m_bHasUnstoredGaps = false; + if (!m_bFlatOffsets) { + const u32 covered = CountStoredFrames(); + m_bHasUnstoredGaps = (covered != m_nTotalFrames); + if (m_bHasUnstoredGaps) { + LOGNOTE("=== MDF is sparse: %u of %u frames stored ===", covered, m_nTotalFrames); } } - m_bHasUnstoredGaps = (covered != m_nTotalFrames); - if (m_bHasUnstoredGaps) { - LOGNOTE("=== MDF is sparse: %u of %u frames stored ===", covered, m_nTotalFrames); - } LOGNOTE("=== Image has subchannel data: %s ===", m_hasSubchannels ? "YES (SafeDisc compatible)" : "NO"); @@ -515,6 +507,18 @@ u64 CMDSFileDevice::Seek(u64 nOffset) { // Before any early exit can skip it: Read() keys its gap detection off this. m_nCurrentLBA = lba; + // No track table to map through, so the MDF is a flat run of frames from LBA 0. + // Otherwise the branch below leaves the file position untouched. + if (m_bFlatOffsets) { + FRESULT flat = f_lseek(m_pFile, nOffset); + if (flat != FR_OK) { + LOGERR("Seek to flat offset %llu failed, err %d", + (unsigned long long)nOffset, flat); + return static_cast(-1); + } + return nOffset; + } + // Find which track contains this LBA int session, trackIdx; MDS_TrackBlock* track = FindTrackForLBA(lba, &session, &trackIdx); @@ -542,9 +546,8 @@ u64 CMDSFileDevice::Seek(u64 nOffset) { // LOGDBG("Seek: LBA %u (offset %llu) -> track %d, file offset %llu", // lba, nOffset, track->point, actual_file_offset); - // Don't seek if we're already there. Compare against the FILE offset just - // computed, not the disc address nOffset, which coincides often enough to - // skip a seek that was needed. + // Compare the FILE offset just computed, not the disc address nOffset, which + // coincides often enough to skip a seek that was needed. if (Tell() == actual_file_offset) { return nOffset; } @@ -652,6 +655,73 @@ bool CMDSFileDevice::IsAudioTrack(int track) const { return false; } +// Distinct frames stored. Summing counts an overlap twice, and an overlap the +// size of a real hole then adds up to a full disc, hiding the hole. +u32 CMDSFileDevice::CountStoredFrames() const { + struct Range { + u32 start; + u32 end; + }; + + // 99 tracks is the Red Book limit, so this only has to be big enough not to + // truncate a legitimate image. + static const size_t kMaxRanges = 128; + Range Ranges[kMaxRanges]; + size_t nRanges = 0; + + for (int i = 0; i < m_parser->getNumSessions(); i++) { + MDS_SessionBlock* session = m_parser->getSession(i); + for (int j = 0; j < session->num_all_blocks; j++) { + MDS_TrackBlock* track = m_parser->getTrack(i, j); + if (track->point == 0 || track->point >= 0xA0) { + continue; + } + MDS_TrackExtraBlock* extra = m_parser->getTrackExtra(i, j); + const u32 length = extra ? extra->length : 0; + if (length == 0) { + continue; + } + if (nRanges == kMaxRanges) { + // Walking gaps needlessly is slow; missing one serves wrong bytes. + LOGWARN("More than %u stored ranges; assuming the MDF is sparse", + (unsigned)kMaxRanges); + return 0; + } + Ranges[nRanges].start = track->start_sector; + Ranges[nRanges].end = track->start_sector + length; + nRanges++; + } + } + + // Insertion sort: a disc has few tracks and they arrive nearly ordered. + for (size_t i = 1; i < nRanges; i++) { + const Range Key = Ranges[i]; + size_t j = i; + while (j > 0 && Ranges[j - 1].start > Key.start) { + Ranges[j] = Ranges[j - 1]; + j--; + } + Ranges[j] = Key; + } + + u32 covered = 0; + size_t i = 0; + while (i < nRanges) { + u32 end = Ranges[i].end; + const u32 start = Ranges[i].start; + while (i + 1 < nRanges && Ranges[i + 1].start <= end) { + if (Ranges[i + 1].end > end) { + end = Ranges[i + 1].end; + } + i++; + } + covered += end - start; + i++; + } + + return covered; +} + MDS_TrackBlock* CMDSFileDevice::FindTrackForLBA(u32 lba, int* sessionOut, int* trackOut) const { if (!m_parser) return nullptr; diff --git a/addon/discimage/mdsfile.h b/addon/discimage/mdsfile.h index 9782d9ec..3b4a6551 100644 --- a/addon/discimage/mdsfile.h +++ b/addon/discimage/mdsfile.h @@ -90,6 +90,14 @@ class CMDSFileDevice : public IMDSDevice { /// is an O(frames x tracks) lookup per read, and most images have no hole. bool m_bHasUnstoredGaps = false; + /// No track lengths recorded, so the count came from the MDF size and the + /// file is read as a flat run of frames from LBA 0. + bool m_bFlatOffsets = false; + + /// Distinct frames in the MDF, overlapping ranges merged. 0 if there are too + /// many to merge, which reads as sparse and costs speed, not correctness. + u32 CountStoredFrames() const; + // Helper to find track containing an LBA MDS_TrackBlock* FindTrackForLBA(u32 lba, int* sessionOut, int* trackOut) const; diff --git a/integration-tests/test-suite/test_mdsimages.cpp b/integration-tests/test-suite/test_mdsimages.cpp index efa3b017..b2ae00c0 100644 --- a/integration-tests/test-suite/test_mdsimages.cpp +++ b/integration-tests/test-suite/test_mdsimages.cpp @@ -260,6 +260,31 @@ static std::vector RawMode1Sectors(const std::string &isoPath, u32 firstLBA, return out; } +// Raw MODE1 sectors filled with odd bytes, so a frame reading back as zeros can +// only have come from a hole, not from an ISO's zero-filled system area. +static std::vector PatternMode1Sectors(u32 firstLBA, u32 nSectors) +{ + static const u8 kSync[12] = {0x00, 0xFF, 0xFF, 0xFF, 0xFF, 0xFF, + 0xFF, 0xFF, 0xFF, 0xFF, 0xFF, 0x00}; + auto bcd = [](u32 v) { return (u8)(((v / 10) << 4) | (v % 10)); }; + + std::vector out((size_t)nSectors * 2352, 0); + for (u32 i = 0; i < nSectors; i++) { + u8 *sector = out.data() + (size_t)i * 2352; + const u32 lba = firstLBA + i; + memcpy(sector, kSync, sizeof(kSync)); + u32 amsf = lba + 150; + sector[12] = bcd(amsf / (60 * 75)); + sector[13] = bcd((amsf / 75) % 60); + sector[14] = bcd(amsf % 75); + sector[15] = 0x01; // MODE1 + for (u32 b = 0; b < 2048; b++) { + sector[16 + b] = (u8)((lba * 7u + b * 3u) | 1u); // odd, so never zero + } + } + return out; +} + static void WriteBytes(const std::string &path, const std::vector &bytes) { FILE *f = fopen(path.c_str(), "wb"); @@ -438,6 +463,161 @@ TEST(mds_data_disc_reads_through_the_gadget) CHECK_EQ(toc.data[5] & 0x04, 0x04); // track 1 control: data } +// With no track lengths the frame count comes from the MDF size, and nothing +// then counts as stored - which used to declare the whole disc a hole. +TEST(mds_disc_without_track_lengths_still_reads_its_content) +{ + const u32 nSectors = 32; + CHECK(FileSize(kIso) > 0); + + const std::string mds = TestDataDir() + "/mdsnolen.mds"; + const std::string mdf = TestDataDir() + "/mdsnolen.mdf"; + std::vector raw = RawMode1Sectors(kIso, 0, nSectors); + CHECK_EQ(raw.size(), (size_t)nSectors * 2352); + if (raw.empty()) { + return; + } + WriteBytes(mdf, raw); + + MdsTrackSpec track; + track.mode = 0xAA; + track.point = 1; + track.sectorSize = 2352; + track.startSector = 0; + track.startOffset = 0; + track.length = 0; // what the fallback exists for + WriteMdsFile(mds, {track}, "mdsnolen.mdf"); + + CMDSFileDevice *disc = OpenMds(mds); + CHECK(disc != nullptr); + if (!disc) { + return; + } + + CGadgetTestBench bench(disc); + bench.Activate(); + bench.RequestSense(); + + // The frame count came from the MDF size, so the disc is as long as the file. + const u8 capCdb[10] = {0x25, 0, 0, 0, 0, 0, 0, 0, 0, 0}; + auto cap = bench.SendCommand(capCdb, sizeof(capCdb), 8); + CHECK_EQ(cap.csw.bmCSWStatus, 0); + u32 lastLBA = (cap.data[0] << 24) | (cap.data[1] << 16) | (cap.data[2] << 8) | cap.data[3]; + CHECK_EQ(lastLBA, nSectors - 1); + + // The PVD, not zeros. This is the whole point: the bytes have to come out of + // the MDF even though no track claims to contain this LBA. + const u8 pvdCdb[10] = {0x28, 0, 0, 0, 0, 16, 0, 0, 1, 0}; + auto pvd = bench.SendCommand(pvdCdb, sizeof(pvdCdb), 2048); + CHECK_EQ(pvd.csw.bmCSWStatus, 0); + CHECK_EQ(pvd.data.size(), (size_t)2048); + if (pvd.data.size() == 2048) { + CHECK_EQ(pvd.data[0], 0x01); + CHECK(memcmp(pvd.data.data() + 1, "CD001", 5) == 0); + CHECK(memcmp(pvd.data.data() + 40, "FREEDOS_TEST", 12) == 0); + } + + // And the stride, so this cannot pass on a single lucky offset. + const u8 svdCdb[10] = {0x28, 0, 0, 0, 0, 17, 0, 0, 1, 0}; + auto svd = bench.SendCommand(svdCdb, sizeof(svdCdb), 2048); + CHECK_EQ(svd.csw.bmCSWStatus, 0); + if (svd.data.size() == 2048) { + CHECK_EQ(svd.data[0], 0x02); + CHECK(memcmp(svd.data.data() + 1, "CD001", 5) == 0); + } +} + +// Overlapping track ranges used to be counted twice, so an overlap the same size +// as a real hole added up to a full disc and turned gap-aware reads back off. +TEST(mds_overlapping_tracks_do_not_hide_a_real_gap) +{ + const u32 kTrack1Len = 20; + const u32 kGap = 10; // frames the MDF does not store + const u32 kTrack2LBA = kTrack1Len + kGap; + const u32 kTrack2Len = 20; + // Track 3 starts inside track 2 and ends where it does, so the double-counted + // overlap is exactly kGap and the plain sum reaches the disc length. + const u32 kTrack3LBA = kTrack2LBA + kTrack2Len - kGap; + const u32 kTrack3Len = kGap; + const u32 kTotal = kTrack2LBA + kTrack2Len; + + const std::string mds = TestDataDir() + "/mdsoverlap.mds"; + const std::string mdf = TestDataDir() + "/mdsoverlap.mdf"; + + // Stored frames only, all non-zero, so "the gap reads as zeros" cannot pass + // by landing on empty ISO system area. + std::vector raw = PatternMode1Sectors(0, kTrack1Len + kTrack2Len); + CHECK_EQ(raw.size(), (size_t)(kTrack1Len + kTrack2Len) * 2352); + WriteBytes(mdf, raw); + + MdsTrackSpec t1; + t1.mode = 0xAA; + t1.point = 1; + t1.startSector = 0; + t1.startOffset = 0; + t1.length = kTrack1Len; + + MdsTrackSpec t2; + t2.mode = 0xAA; + t2.point = 2; + t2.startSector = kTrack2LBA; + t2.startOffset = (u64)kTrack1Len * 2352; + t2.pregap = kGap; + t2.length = kTrack2Len; + + MdsTrackSpec t3; + t3.mode = 0xAA; + t3.point = 3; + t3.startSector = kTrack3LBA; + t3.startOffset = (u64)(kTrack1Len + kTrack3LBA - kTrack2LBA) * 2352; + t3.length = kTrack3Len; + + WriteMdsFile(mds, {t1, t2, t3}, "mdsoverlap.mdf"); + + // Summing lengths gives 20 + 20 + 10 = 50 = the disc length, so the gap + // would look stored; merging the ranges gives 40 and keeps it visible. + CHECK_EQ(kTrack1Len + kTrack2Len + kTrack3Len, kTotal); + + CMDSFileDevice *disc = OpenMds(mds); + CHECK(disc != nullptr); + if (!disc) { + return; + } + + CGadgetTestBench bench(disc); + bench.Activate(); + bench.RequestSense(); + + auto read = [&bench](u32 lba) { + const u8 cdb[10] = {0x28, 0, (u8)(lba >> 24), (u8)(lba >> 16), (u8)(lba >> 8), (u8)lba, + 0, 0, 1, 0}; + return bench.SendCommand(cdb, sizeof(cdb), 2048); + }; + + // A stored frame first, to prove the fixture and leave the file pointer on + // real data: an unrecognised gap then continues from here and is non-zero. + auto stored = read(kTrack1Len - 1); + CHECK_EQ(stored.csw.bmCSWStatus, 0); + CHECK_EQ(stored.data.size(), (size_t)2048); + if (stored.data.size() == 2048) { + CHECK_EQ(stored.data[0], (u8)(((kTrack1Len - 1) * 7u + 0u) | 1u)); + CHECK_EQ(stored.data[1], (u8)(((kTrack1Len - 1) * 7u + 3u) | 1u)); + } + + // And now a frame inside the hole. + auto gap = read(kTrack1Len + 2); + CHECK_EQ(gap.csw.bmCSWStatus, 0); + CHECK_EQ(gap.data.size(), (size_t)2048); + bool zeros = true; + for (size_t i = 0; i < gap.data.size(); i++) { + if (gap.data[i] != 0) { + zeros = false; + break; + } + } + CHECK(zeros); +} + // --------------------------------------------------------------------------- // MDF filename resolution // --------------------------------------------------------------------------- @@ -1015,10 +1195,8 @@ TEST(mds_unstored_pregap_reads_as_zeros) delete disc; } -// The gap handling only works if the reader knows which frame it is on. Seek() -// used to compare Tell(), a physical offset, against the logical offset asked -// for, and exit early without recording the LBA. The fixture above misses this -// because every read there jumps to a new address. +// Seek() compared Tell(), a physical offset, against the logical one asked for +// and exited early without recording the LBA. TEST(mds_gap_reached_by_a_sequential_read_still_reads_as_zeros) { // On a contiguous 2352-byte image the two offsets coincide at every frame, @@ -1103,8 +1281,7 @@ TEST(mds_gap_reached_by_a_sequential_read_still_reads_as_zeros) CHECK(memcmp(t2read.data.data() + 1, "CD001", 5) == 0); } - // The same defect without a Seek(). The gadget seeks before every batch, so - // it does not produce this caller, but the plain path is the only one of the + // The same defect without a Seek(): the plain path is the only one of the // three that used to leave the position behind. CHECK_EQ(disc->Seek((u64)(kTrack1Len - 2) * 2352), (u64)(kTrack1Len - 2) * 2352); std::vector twoFrames(2 * 2352); @@ -1126,9 +1303,8 @@ TEST(mds_gap_reached_by_a_sequential_read_still_reads_as_zeros) delete disc; } -// The two ways to reach a hole other than a whole-frame READ(10). A sub-frame -// read used to skip the gap check on size alone, and ReadSubchannel() used to -// fail on a frame that Seek() and Read() answer with zeros. +// A sub-frame read used to skip the gap check on size alone, and ReadSubchannel() +// used to fail on a frame that Seek() and Read() answer with zeros. TEST(mds_gap_answers_short_reads_and_subchannel_requests_too) { const u32 kTrack1Len = 16; @@ -1345,10 +1521,8 @@ TEST(mds_subchannel_image_strips_and_exposes_subchannel_data) } } -// The same defect from the other direction. On a 2448-byte image the physical -// and logical offsets coincide every 49th frame (49 * 2448 == 51 * 2352), so a -// sequential run to frame 48 followed by a seek to LBA 51 hits the early exit -// and serves frame 49 while reporting success. +// On a 2448-byte image the offsets coincide every 49th frame (49*2448 == +// 51*2352), so a run to 48 then a seek to LBA 51 used to serve frame 49. TEST(mds_subchannel_seek_after_a_read_does_not_serve_a_stale_frame) { const u32 nSectors = 64; @@ -1372,9 +1546,8 @@ TEST(mds_subchannel_seek_after_a_read_does_not_serve_a_stale_frame) image[(size_t)lba * 2448 + 2352 + i] = SubchannelByte(lba, i); } } - // Past the ISO's system area every frame here would otherwise be zeros, - // which cannot tell a stale frame from the right one. Stamp each frame's - // user data with its own LBA so a misread names the frame it came from. + // Past the system area every frame would otherwise be zeros. Stamp each with + // its own LBA so a misread names the frame it came from. for (u32 lba = 0; lba < nSectors; lba++) { u8 *user = image.data() + (size_t)lba * 2448 + 16; for (u32 i = 0; i < 2048; i++) { From 6df2e4ce481dabcc471801b94815e82890309cbd Mon Sep 17 00:00:00 2001 From: David Hauf Date: Wed, 29 Jul 2026 21:44:59 -0400 Subject: [PATCH 11/13] logging: notice a full card instead of logging into it f_write reports a full volume as FR_OK with a short byte count, and f_sync can fail after it, so checking only the FRESULT called a lost entry written. That alone would have reintroduced the collapse this daemon exists to avoid: a card that stays full fails every write, and backing off 20 ms per event is the same starvation an unopenable path used to cause. A run of failures now gives up on the file and says so in the web UI. Short write and failed sync found by CodeRabbit. (cherry picked from commit 5fd1fabf6d4f991a221cb8fd243bfb15fb7d05ac) --- addon/filelogdaemon/filelogdaemon.cpp | 49 ++++++-- addon/filelogdaemon/filelogdaemon.h | 6 + .../test-suite/test_logdaemon.cpp | 111 ++++++++++++++++-- 3 files changed, 144 insertions(+), 22 deletions(-) diff --git a/addon/filelogdaemon/filelogdaemon.cpp b/addon/filelogdaemon/filelogdaemon.cpp index f94e1535..6e2f9821 100644 --- a/addon/filelogdaemon/filelogdaemon.cpp +++ b/addon/filelogdaemon/filelogdaemon.cpp @@ -100,6 +100,11 @@ void CFileLogDaemon::GetStatusText(char *pBuffer, size_t nBufferSize) const { if (m_LogFilePath[0] == '\0') { snprintf(pBuffer, nBufferSize, "File logging is off (no log file configured)."); + } else if (m_bWritesGaveUp) { + snprintf(pBuffer, nBufferSize, + "NOT LOGGING: writes to %s kept failing, so logging stopped. " + "The card is most likely full.", + m_LogFilePath); } else if (m_bFileInitialized) { snprintf(pBuffer, nBufferSize, "Writing to %s", m_LogFilePath); } else { @@ -158,19 +163,35 @@ void CFileLogDaemon::DrainOnce(void) { int nTimeZone; while (pLogger->ReadEvent(&Severity, Source, Message, &Time, &nHundredthTime, &nTimeZone)) { - // CLogger queues every event regardless of loglevel, which only filters - // the serial/screen target, so the configured level is applied here. - // LogPanic(0)..LogDebug(4) maps to config levels 1..5; 0 drops everything. + // CLogger queues every event whatever the loglevel, so the configured + // level applies here. LogPanic(0)..LogDebug(4) maps to config 1..5. if ((unsigned)Severity >= m_uiLogLevel) { continue; } - // Only back off for a failure that might not repeat: with no file open, - // sleeping per message throttled the queue to 50 events a second. - if (LogMessage(Severity, Time, nHundredthTime, nTimeZone, Source, Message) == - LogResult::WriteFailed) { - CScheduler::Get()->Sleep(20); + const LogResult result = + LogMessage(Severity, Time, nHundredthTime, nTimeZone, Source, Message); + + if (result == LogResult::Written) { + m_nConsecutiveWriteFailures = 0; + continue; } + if (result != LogResult::WriteFailed) { + continue; + } + + // Back off for a busy card, but a full one fails every write, and 20 ms + // per event starves the scheduler exactly as the no-file case used to. + if (++m_nConsecutiveWriteFailures >= MaxConsecutiveWriteFailures) { + if (!m_bWritesGaveUp) { + m_bWritesGaveUp = TRUE; + m_bFileInitialized = FALSE; + f_close(&m_LogFile); + } + continue; + } + + CScheduler::Get()->Sleep(20); } } @@ -211,16 +232,20 @@ CFileLogDaemon::LogResult CFileLogDaemon::LogMessage(TLogSeverity Severity, snprintf(LogEntry, sizeof(LogEntry), "[%lu] [%s] %s: %s\n", FullTime, pAppName, pSeverityName, pMsg); - // Write to file + // Write to file. A short write means a full card, which f_write reports as + // success, and an unchecked f_sync would then call the lost entry written. + const UINT EntryLength = strlen(LogEntry); UINT BytesWritten; - FRESULT Result = f_write(&m_LogFile, LogEntry, strlen(LogEntry), &BytesWritten); - if (Result != FR_OK) { + FRESULT Result = f_write(&m_LogFile, LogEntry, EntryLength, &BytesWritten); + if (Result != FR_OK || BytesWritten != EntryLength) { // Not logged: this runs while draining the log queue, so a message here // would queue another event that fails the same way. return LogResult::WriteFailed; } - f_sync(&m_LogFile); + if (f_sync(&m_LogFile) != FR_OK) { + return LogResult::WriteFailed; + } return LogResult::Written; } diff --git a/addon/filelogdaemon/filelogdaemon.h b/addon/filelogdaemon/filelogdaemon.h index 684d1312..4fd20f36 100644 --- a/addon/filelogdaemon/filelogdaemon.h +++ b/addon/filelogdaemon/filelogdaemon.h @@ -87,6 +87,12 @@ class CFileLogDaemon : public CTask { char m_LogFilePath[256] = {0}; FRESULT m_OpenResult = FR_NOT_READY; unsigned m_uiLogLevel; + + // So a permanently failing write (a full card) stops costing 20 ms an event. + unsigned m_nConsecutiveWriteFailures = 0; + static const unsigned MaxConsecutiveWriteFailures = 8; + boolean m_bWritesGaveUp = FALSE; + FIL m_LogFile; }; diff --git a/integration-tests/test-suite/test_logdaemon.cpp b/integration-tests/test-suite/test_logdaemon.cpp index b2a75a68..8e8bce98 100644 --- a/integration-tests/test-suite/test_logdaemon.cpp +++ b/integration-tests/test-suite/test_logdaemon.cpp @@ -6,6 +6,7 @@ // DrainOnce(), one pass of its loop. // #include "framework.h" +#include "fatfs_host.h" #include #include @@ -73,9 +74,8 @@ static void ResetLogging() // Tests // --------------------------------------------------------------------------- -// The headline defect: with no file open, the drain loop slept 20 ms per failed -// message, retiring 50 events a second and taking the scheduler down with it. -// The events must still be consumed, just not paid for. +// With no file open the drain loop slept 20 ms per message, retiring 50 events a +// second and taking the scheduler with it. They must be consumed, not paid for. TEST(logdaemon_unopenable_path_drains_without_sleeping) { ResetLogging(); @@ -101,10 +101,8 @@ TEST(logdaemon_unopenable_path_drains_without_sleeping) CHECK_EQ(CScheduler::TestSleepCount(), 0u); } -// m_bFileInitialized had no initializer, so a failed open left it holding -// whatever was in that memory. Constructing over poisoned storage exposes it. -// Reading an invalid bool is undefined, so this asserts the behaviour rather -// than the flag; -fsanitize=undefined catches the read itself. +// m_bFileInitialized had no initializer, so a failed open left it holding stale +// memory. Asserts the behaviour, not the flag: reading an invalid bool is UB. TEST(logdaemon_failed_open_leaves_the_file_flag_false) { ResetLogging(); @@ -178,9 +176,8 @@ TEST(logdaemon_writes_and_applies_the_configured_level) RemoveFile(path); } -// What the web UI shows. The boot-time warning goes to the serial console, which -// a SCREEN_HEADLESS build has no equivalent of, so without this a user with a bad -// path sees a device that lists a log file and silently has none. +// What the web UI shows. The boot warning goes to a serial console SCREEN_HEADLESS +// does not have, so a bad path otherwise looks like a device that just works. TEST(logdaemon_reports_its_status_for_the_web_ui) { ResetLogging(); @@ -263,3 +260,97 @@ TEST(logdaemon_keeps_its_own_copy_of_the_path) RemoveFile(path); } + +// A full card is the write failure this daemon will actually meet, and FatFs +// reports it as FR_OK with a short count, so the FRESULT alone is not enough. +TEST(logdaemon_treats_a_short_write_as_a_failure) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/logdaemon-fullcard.txt"; + RemoveFile(path); + + { + CFileLogDaemon daemon(path.c_str(), 5); + CHECK(daemon.IsFileLogging()); + + // Room for part of one entry and no more. + ResetLogging(); + FatFsHostSetWriteLimit(8); + + QueueEvents(3); + daemon.DrainOnce(); + + FatFsHostClearFaults(); + + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + // The 20 ms back-off is the only outward sign the daemon noticed. + CHECK(CScheduler::TestSleepCount() > 0u); + } + + RemoveFile(path); +} + +// A full card fails every write, so 20 ms per event is the same starvation an +// unopenable path used to cause. It gives up on the file instead, and says so. +TEST(logdaemon_stops_writing_when_the_card_stays_full) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/logdaemon-givesup.txt"; + RemoveFile(path); + + { + CFileLogDaemon daemon(path.c_str(), 5); + CHECK(daemon.IsFileLogging()); + + ResetLogging(); + FatFsHostSetWriteLimit(4); + + QueueEvents(60); + daemon.DrainOnce(); + + FatFsHostClearFaults(); + + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + // Bounded, not one per event. + CHECK(CScheduler::TestSleepCount() > 0u); + CHECK(CScheduler::TestSleepCount() <= 8u); + + CHECK(!daemon.IsFileLogging()); + char status[256]; + daemon.GetStatusText(status, sizeof(status)); + CHECK(strstr(status, "NOT LOGGING") != nullptr); + CHECK(strstr(status, "logdaemon-givesup.txt") != nullptr); + } + + RemoveFile(path); +} + +// f_sync() is the other half: f_write() can report every byte taken and the +// entry still be lost when the flush fails. +TEST(logdaemon_treats_a_failed_sync_as_a_failure) +{ + ResetLogging(); + + const std::string path = TestDataDir() + "/logdaemon-badsync.txt"; + RemoveFile(path); + + { + CFileLogDaemon daemon(path.c_str(), 5); + CHECK(daemon.IsFileLogging()); + + ResetLogging(); + FatFsHostFailSync(true); + + QueueEvents(2); + daemon.DrainOnce(); + + FatFsHostClearFaults(); + + CHECK_EQ(CLogger::TestQueuedEventCount(), 0u); + CHECK(CScheduler::TestSleepCount() > 0u); + } + + RemoveFile(path); +} From 055f06ec886d0279fb81077d0209b4c2bf7f15c8 Mon Sep 17 00:00:00 2001 From: David Hauf Date: Thu, 30 Jul 2026 10:51:03 -0400 Subject: [PATCH 12/13] ui: report what actually went wrong A data file that would not open was always called missing, sending the user after a file that was sitting right there. Only FR_NO_FILE and FR_NO_PATH mean missing now; anything else says it would not open and carries the FatFs code. The config page also dropped a requested reboot silently when the log path was rejected. It now says the reboot was cancelled, which keeps the error on screen long enough to read. Both found by CodeRabbit. --- addon/discimage/util.cpp | 9 ++++++++- addon/webserver/handlers/configpage.cpp | 12 +++++++++--- 2 files changed, 17 insertions(+), 4 deletions(-) diff --git a/addon/discimage/util.cpp b/addon/discimage/util.cpp index 8cb3161a..6f18f0e0 100644 --- a/addon/discimage/util.cpp +++ b/addon/discimage/util.cpp @@ -284,7 +284,14 @@ IImageDevice* loadCueBinIsoFileDevice(const char* imagePath) { FRESULT result = f_open(imageFile, fullPath, FA_READ); if (result != FR_OK) { LOGERR("Cannot open data file for reading: %s (error %d)", fullPath, result); - SetImageLoadError("The data file this image needs is missing: %s", fullPath); + // "Missing" sends the user looking for a file that may be sitting right + // there: FR_DENIED, FR_INVALID_NAME and a failing card all land here too. + if (result == FR_NO_FILE || result == FR_NO_PATH) { + SetImageLoadError("The data file this image needs is missing: %s", fullPath); + } else { + SetImageLoadError("The data file this image needs would not open: %s (FatFs error %d)", + fullPath, (int)result); + } delete imageFile; if (cue_str) delete[] cue_str; return nullptr; diff --git a/addon/webserver/handlers/configpage.cpp b/addon/webserver/handlers/configpage.cpp index 015250d2..e51171bd 100644 --- a/addon/webserver/handlers/configpage.cpp +++ b/addon/webserver/handlers/configpage.cpp @@ -32,9 +32,8 @@ std::string ConfigPageHandler::GetHTML() { return std::string(s_Config); } -// Normalize a user-typed log path onto volume 0: and reject what FatFs cannot -// open - the only validation it gets, and a bad path is not discovered until the -// next boot. An empty result means logging is off, which is a choice. +// Normalize onto volume 0: and reject what FatFs cannot open; a bad path is not +// otherwise discovered until the next boot. Empty means logging is off. static bool NormalizeLogfilePath(std::string& path, std::string& error) { const size_t first = path.find_first_not_of(" \t"); if (first == std::string::npos) { @@ -255,6 +254,13 @@ THTTPStatus ConfigPageHandler::PopulateContext(kainjow::mustache::data& context, // rejected value went in too. if (!error_message.empty()) { error_message += " Other settings were saved."; + // The reboot used to be dropped silently here, leaving the user + // waiting for one that was never coming. + if (action == "save_reboot") { + error_message += " The reboot was cancelled so you can correct this."; + } else if (action == "save_shutdown") { + error_message += " The shutdown was cancelled so you can correct this."; + } } else if (action == "save_reboot") { success_message = "Configuration saved successfully. Rebooting in 3 seconds..."; // Schedule a reboot in 3 seconds From 632e6cf9306528406510ead3f7a438f353579ede Mon Sep 17 00:00:00 2001 From: David Hauf Date: Thu, 30 Jul 2026 10:51:35 -0400 Subject: [PATCH 13/13] tests: make the FatFs seam behave like FatFs FA_CREATE_NEW opened an existing file through "r+b" instead of returning FR_EXIST, and f_write never maintained obj.objsize, leaving f_size stale after an append. The seam now injects the two ways a full card presents, FR_OK with a short count and a failing f_sync, which is what the log daemon's write checks are tested against. Both shim defects found by CodeRabbit. --- integration-tests/harness/fatfs_host.cpp | 67 +++++++++- integration-tests/harness/fatfs_host.h | 22 ++++ integration-tests/harness/framework.cpp | 1 + .../test-suite/test_fatfsseam.cpp | 116 ++++++++++++++++++ 4 files changed, 202 insertions(+), 4 deletions(-) create mode 100644 integration-tests/harness/fatfs_host.h create mode 100644 integration-tests/test-suite/test_fatfsseam.cpp diff --git a/integration-tests/harness/fatfs_host.cpp b/integration-tests/harness/fatfs_host.cpp index b4202108..46be18a9 100644 --- a/integration-tests/harness/fatfs_host.cpp +++ b/integration-tests/harness/fatfs_host.cpp @@ -9,8 +9,38 @@ // #include +#include "fatfs_host.h" + #include +namespace { + +constexpr size_t kNoWriteLimit = (size_t)-1; + +size_t s_WriteLimit = kNoWriteLimit; +size_t s_BytesAccepted = 0; +bool s_SyncFails = false; + +} // namespace + +void FatFsHostSetWriteLimit(size_t nBytes) +{ + s_WriteLimit = nBytes; + s_BytesAccepted = 0; +} + +void FatFsHostFailSync(bool bFail) +{ + s_SyncFails = bFail; +} + +void FatFsHostClearFaults(void) +{ + s_WriteLimit = kNoWriteLimit; + s_BytesAccepted = 0; + s_SyncFails = false; +} + extern "C" { FRESULT f_open(FIL* fp, const TCHAR* path, BYTE mode) @@ -19,9 +49,8 @@ FRESULT f_open(FIL* fp, const TCHAR* path, BYTE mode) return FR_INVALID_PARAMETER; } - // The mode has to be honoured: whether the log daemon's append open succeeds - // is the whole subject of its tests. FA_OPEN_ALWAYS is "r+b" falling back to - // "w+b" only when the file is missing, which keeps a bad directory an error. + // FA_OPEN_ALWAYS is "r+b" falling back to "w+b" only when the file is + // missing, which keeps a bad directory an error. const char* stdioMode = "rb"; if (mode & (FA_WRITE | FA_CREATE_ALWAYS | FA_CREATE_NEW | FA_OPEN_ALWAYS)) { if (mode & FA_CREATE_ALWAYS) { @@ -33,6 +62,16 @@ FRESULT f_open(FIL* fp, const TCHAR* path, BYTE mode) } } + // stdio has no "create only if absent" mode, and "r+b" would open the very + // file the caller asked to be protected from. + if (mode & FA_CREATE_NEW) { + FILE* existing = fopen(path, "rb"); + if (existing) { + fclose(existing); + return FR_EXIST; + } + } + FILE* f = fopen(path, stdioMode); if (!f && (mode & (FA_OPEN_ALWAYS | FA_CREATE_NEW))) { f = fopen(path, "w+b"); @@ -95,16 +134,36 @@ FRESULT f_write(FIL* fp, const void* buff, UINT btw, UINT* bw) if (!fp || !fp->host_fp || !buff) { return FR_INVALID_OBJECT; } - size_t n = fwrite(buff, 1, btw, (FILE*)fp->host_fp); + UINT nAccept = btw; + if (s_WriteLimit != kNoWriteLimit) { + const size_t room = (s_WriteLimit > s_BytesAccepted) ? s_WriteLimit - s_BytesAccepted : 0; + if (room < nAccept) { + nAccept = (UINT)room; + } + } + + size_t n = nAccept > 0 ? fwrite(buff, 1, nAccept, (FILE*)fp->host_fp) : 0; + s_BytesAccepted += n; fp->fptr += n; + if (fp->fptr > fp->obj.objsize) { + fp->obj.objsize = fp->fptr; + } if (bw) { *bw = (UINT)n; } + // A full card is FR_OK with a short count. Only the injected cap gets that; + // past it a short write is a real host I/O error. + if (nAccept < btw) { + return FR_OK; + } return (n == btw) ? FR_OK : FR_DISK_ERR; } FRESULT f_sync(FIL* fp) { + if (s_SyncFails) { + return FR_DISK_ERR; + } if (!fp || !fp->host_fp) { return FR_INVALID_OBJECT; } diff --git a/integration-tests/harness/fatfs_host.h b/integration-tests/harness/fatfs_host.h new file mode 100644 index 00000000..6de12e52 --- /dev/null +++ b/integration-tests/harness/fatfs_host.h @@ -0,0 +1,22 @@ +// +// fatfs_host.h +// +// Fault injection for the FatFs seam in fatfs_host.cpp. The host filesystem will +// not run out of room on demand, so a full card is simulated instead. +// +#ifndef _harness_fatfs_host_h +#define _harness_fatfs_host_h + +#include + +// Writes past nBytes return FR_OK with a short count, which is how FatFs reports +// a full volume: not an error return, so FRESULT-only callers miss it. +void FatFsHostSetWriteLimit(size_t nBytes); + +// Make every f_sync() report FR_DISK_ERR. +void FatFsHostFailSync(bool bFail); + +// Back to a healthy card; the state is process-wide, so injectors must reset it. +void FatFsHostClearFaults(void); + +#endif diff --git a/integration-tests/harness/framework.cpp b/integration-tests/harness/framework.cpp index ccad7cc6..fc3732ca 100644 --- a/integration-tests/harness/framework.cpp +++ b/integration-tests/harness/framework.cpp @@ -60,6 +60,7 @@ namespace {"test_mdsimages", "MDS/MDF images"}, {"test_multisession", "Multi-session and CD Extra"}, {"test_logdaemon", "File log daemon"}, + {"test_fatfsseam", "FatFs host seam"}, }; // "test-suite/test_read10.cpp" -> "SCSI read commands" diff --git a/integration-tests/test-suite/test_fatfsseam.cpp b/integration-tests/test-suite/test_fatfsseam.cpp new file mode 100644 index 00000000..902e537e --- /dev/null +++ b/integration-tests/test-suite/test_fatfsseam.cpp @@ -0,0 +1,116 @@ +// +// test_fatfsseam.cpp +// +// The host backend for FatFs itself. Everything else in the suite trusts this +// seam to behave like the real thing, so where stdio and FatFs disagree the +// difference is pinned here rather than discovered as a firmware "bug" that +// only reproduces on the Pi. +// +#include "framework.h" +#include "fatfs_host.h" + +#include + +#include +#include + +#include + +static std::string TestDataDir() +{ +#ifdef USBODE_TESTDATA + return USBODE_TESTDATA; +#else + return "out/images"; +#endif +} + +// stdio has no "create only if absent" mode, so the shim reached for "r+b", +// which opens the existing file the caller asked to be protected from. +TEST(fatfs_seam_create_new_refuses_an_existing_file) +{ + const std::string path = TestDataDir() + "/seam-create-new.bin"; + remove(path.c_str()); + + FIL File; + CHECK_EQ(f_open(&File, path.c_str(), FA_CREATE_NEW | FA_WRITE), FR_OK); + UINT nWritten = 0; + CHECK_EQ(f_write(&File, "first", 5, &nWritten), FR_OK); + CHECK_EQ(nWritten, 5u); + f_close(&File); + + // Second time round the file is there, so this must fail rather than + // handing back a writable handle to it. + CHECK_EQ(f_open(&File, path.c_str(), FA_CREATE_NEW | FA_WRITE), FR_EXIST); + + // And the original contents survived the refused open. + CHECK_EQ(f_open(&File, path.c_str(), FA_READ), FR_OK); + char buf[8] = {0}; + UINT nRead = 0; + CHECK_EQ(f_read(&File, buf, 5, &nRead), FR_OK); + CHECK_EQ(nRead, 5u); + CHECK(memcmp(buf, "first", 5) == 0); + f_close(&File); + + remove(path.c_str()); +} + +// The fault hooks the write-path tests depend on: a full card is FR_OK with a +// short count, which is the trap, not an error return. +TEST(fatfs_seam_reports_a_full_card_as_a_short_write) +{ + const std::string path = TestDataDir() + "/seam-full-card.bin"; + remove(path.c_str()); + + FIL File; + CHECK_EQ(f_open(&File, path.c_str(), FA_CREATE_ALWAYS | FA_WRITE), FR_OK); + + FatFsHostSetWriteLimit(4); + + UINT nWritten = 0; + CHECK_EQ(f_write(&File, "0123456789", 10, &nWritten), FR_OK); + CHECK_EQ(nWritten, 4u); + + // Nothing more fits, and it is still not an error. + nWritten = 99; + CHECK_EQ(f_write(&File, "more", 4, &nWritten), FR_OK); + CHECK_EQ(nWritten, 0u); + + FatFsHostFailSync(true); + CHECK_EQ(f_sync(&File), FR_DISK_ERR); + + FatFsHostClearFaults(); + + CHECK_EQ(f_sync(&File), FR_OK); + f_close(&File); + + remove(path.c_str()); +} + +// f_size() is read straight out of the FIL, so a write that does not maintain it +// leaves an appending caller seeking to a stale end of file. +TEST(fatfs_seam_tracks_the_file_size_across_writes) +{ + const std::string path = TestDataDir() + "/seam-objsize.bin"; + remove(path.c_str()); + + FIL File; + CHECK_EQ(f_open(&File, path.c_str(), FA_CREATE_ALWAYS | FA_WRITE), FR_OK); + CHECK_EQ((unsigned long long)f_size(&File), (unsigned long long)0); + + UINT nWritten = 0; + CHECK_EQ(f_write(&File, "0123456789", 10, &nWritten), FR_OK); + CHECK_EQ(nWritten, 10u); + CHECK_EQ((unsigned long long)f_size(&File), (unsigned long long)10); + f_close(&File); + + // Reopening and appending has to carry on from 10, not from 0. + CHECK_EQ(f_open(&File, path.c_str(), FA_WRITE | FA_OPEN_ALWAYS), FR_OK); + CHECK_EQ((unsigned long long)f_size(&File), (unsigned long long)10); + CHECK_EQ(f_lseek(&File, f_size(&File)), FR_OK); + CHECK_EQ(f_write(&File, "abc", 3, &nWritten), FR_OK); + CHECK_EQ((unsigned long long)f_size(&File), (unsigned long long)13); + f_close(&File); + + remove(path.c_str()); +}