diff --git a/addon/discimage/mdsfile.cpp b/addon/discimage/mdsfile.cpp index d9bcc8be..db150469 100644 --- a/addon/discimage/mdsfile.cpp +++ b/addon/discimage/mdsfile.cpp @@ -290,11 +290,23 @@ 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); } + // 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); + } + } + LOGNOTE("=== Image has subchannel data: %s ===", m_hasSubchannels ? "YES (SafeDisc compatible)" : "NO"); LOGNOTE("=== Disc length: %u frames ===", m_nTotalFrames); @@ -325,7 +337,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 +355,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 +380,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 +408,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 +472,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 +500,29 @@ 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; + + // 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); - + 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 +531,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 +539,25 @@ 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); - + + // 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; + } + 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; } @@ -618,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; @@ -651,20 +755,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..3b4a6551 100644 --- a/addon/discimage/mdsfile.h +++ b/addon/discimage/mdsfile.h @@ -82,11 +82,22 @@ 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; + + /// 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/addon/discimage/util.cpp b/addon/discimage/util.cpp index 52ddb9f0..6f18f0e0 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,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); + // "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; @@ -293,6 +325,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 +411,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 +427,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/filelogdaemon/filelogdaemon.cpp b/addon/filelogdaemon/filelogdaemon.cpp index 837dbfb7..6e2f9821 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; } @@ -79,6 +93,42 @@ 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_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 { + 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; @@ -96,36 +146,61 @@ 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 whatever the loglevel, so the configured + // level applies here. LogPanic(0)..LogDebug(4) maps to config 1..5. + if ((unsigned)Severity >= m_uiLogLevel) { + continue; + } + + 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; } - m_Event.Wait(); + 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 @@ -157,18 +232,22 @@ boolean 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) { - // TODO implement proper error handling here!!! - LOGERR("Failed to write to log file!"); - return FALSE; + 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 TRUE; + return LogResult::Written; } void CFileLogDaemon::EventNotificationHandler(void) { diff --git a/addon/filelogdaemon/filelogdaemon.h b/addon/filelogdaemon/filelogdaemon.h index 8e34d737..4fd20f36 100644 --- a/addon/filelogdaemon/filelogdaemon.h +++ b/addon/filelogdaemon/filelogdaemon.h @@ -42,6 +42,20 @@ 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; } + + // 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); @@ -49,9 +63,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,9 +81,18 @@ 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; + + // 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/addon/scsitbservice/scsitbservice.cpp b/addon/scsitbservice/scsitbservice.cpp index 09acde5a..cb4224b1 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; @@ -246,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) { @@ -339,13 +323,11 @@ 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"); - } 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"); + // Even with no same-stem .bin, which also hid split-track rips. + listIt = true; } + // 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); @@ -397,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; @@ -443,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; } } @@ -469,31 +476,59 @@ 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; } - 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') { + 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; } 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 f0830290..c2a47a1a 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,16 @@ class SCSITBService : public CTask bool m_bBootEjectPending = false; bool m_bPersistedEjected = false; + // 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/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/addon/webserver/handlers/configpage.cpp b/addon/webserver/handlers/configpage.cpp index 216e3071..e51171bd 100644 --- a/addon/webserver/handlers/configpage.cpp +++ b/addon/webserver/handlers/configpage.cpp @@ -32,6 +32,61 @@ std::string ConfigPageHandler::GetHTML() { return std::string(s_Config); } +// 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) { + 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 +181,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 +249,19 @@ 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."; + // 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 new CShutdown(ShutdownReboot, 3000); @@ -208,6 +275,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/imagenameapi.cpp b/addon/webserver/handlers/imagenameapi.cpp index 072b3b84..84387e81 100644 --- a/addon/webserver/handlers/imagenameapi.cpp +++ b/addon/webserver/handlers/imagenameapi.cpp @@ -23,9 +23,19 @@ 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 + // 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; } 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/handlers/pagehandlerbase.cpp b/addon/webserver/handlers/pagehandlerbase.cpp index ca046ebe..2dc69c5b 100644 --- a/addon/webserver/handlers/pagehandlerbase.cpp +++ b/addon/webserver/handlers/pagehandlerbase.cpp @@ -61,8 +61,16 @@ 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. + 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/config.html b/addon/webserver/pages/config.html index d9823cec..467c104e 100644 --- a/addon/webserver/pages/config.html +++ b/addon/webserver/pages/config.html @@ -130,7 +130,8 @@

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.
+
Status: {{logfile_status}}
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}} 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..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) @@ -18,8 +48,34 @@ 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"); + + // 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"; + } + } + + // 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"); + } if (!f) { return FR_NO_FILE; } @@ -78,14 +134,42 @@ 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; + } + 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/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 269edfab..fc3732ca 100644 --- a/integration-tests/harness/framework.cpp +++ b/integration-tests/harness/framework.cpp @@ -59,6 +59,8 @@ namespace {"test_realimages", "Real disc images"}, {"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/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_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); 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()); +} diff --git a/integration-tests/test-suite/test_logdaemon.cpp b/integration-tests/test-suite/test_logdaemon.cpp new file mode 100644 index 00000000..8e8bce98 --- /dev/null +++ b/integration-tests/test-suite/test_logdaemon.cpp @@ -0,0 +1,356 @@ +// +// 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 "fatfs_host.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 +// --------------------------------------------------------------------------- + +// 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(); + + // 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 stale +// memory. Asserts the behaviour, not the flag: reading an invalid bool is UB. +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); +} + +// 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(); + 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) +{ + 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); +} + +// 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); +} diff --git a/integration-tests/test-suite/test_mdsimages.cpp b/integration-tests/test-suite/test_mdsimages.cpp index 4f2517e7..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,6 +1195,209 @@ TEST(mds_unstored_pregap_reads_as_zeros) delete disc; } +// 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, + // 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 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; +} + +// 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 +1521,86 @@ TEST(mds_subchannel_image_strips_and_exposes_subchannel_data) } } +// 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; + 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 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++) { + 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 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()); } } }