diff --git a/CHANGELOG.md b/CHANGELOG.md index 40e968a..9412413 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -468,6 +468,59 @@ Changes you will notice: and an older result can no longer overwrite a newer one. - Test runs that failed with every test passing: a log-file error arriving after logging had shut down was written to a console that was already gone. Such late errors are no longer printed. +- **Organize no longer shows "1% confidence" on its strongest matches.** A match boosted by its + cluster got a score above 100%, which the card read as a percentage and divided by 100 again. The + card and the details panel now show the same value, capped at 100%. +- **Target-folder descriptions in Organize keep the letter s at both ends.** "sales reports" was + shown as "ales report". +- **A file the watcher is already analyzing is not queued again by the watcher's own read of it.** + On Windows, reading a file updates its last-access time, which was reported as a change. +- **An image batch whose files are all analyzed already no longer swaps models** to analyze nothing. +- **Content dates:** a written year of 0000–0099 is no longer read as 1900–1999, a year of five or + six digits is rejected, a date written with `Z` keeps its day west of Greenwich, and a number from + the model is a year or nothing. Search results and cluster time ranges show a document's own day, + not the day before. +- **Smart-folder watcher, embedding retries.** A retry that only embeds a finished result no longer + replaces a reanalysis or a change waiting for the same file, no longer leaves the file without an + embedding when the waiting item is skipped, does not embed a result for a file that has changed + since, and no longer hides a real edit made while it runs. +- **Smart-folder watcher:** a recording gets the three hours a Discover run allows instead of ten + minutes; a file deleted or renamed during its analysis gets no history entry or notification; and + "Reanalyze all" can no longer start the same file beside itself. +- **A transcript the text model gave no answer for is tried again** by the watcher, and is recorded + as provisional instead of as a finished transcription with confidence 0. The same holds when the + model is not installed or its answer cannot be read. +- **Stop works while a batch is still checking its files,** when it was answered "unknown batch" + before. A batch also ends when the window that asked for it is closed or reloaded, and a batch + that has ended or was cancelled sends no late progress. +- **A batch that ran to its end sends its last progress report,** so the search and embedding counts + that refresh on it are current. +- **The history keeps the size and date a file had when its analysis started,** not those of a + version saved while the model worked. +- **A Discover run that stops making progress says so.** A silent five-minute check ended the run + before the ten-minute check that would have shown a notice. There is one check now, and it shows + the notice without stating a duration it cannot know. On the one-file-at-a-time path a slow file + fails alone instead of ending the run. +- **Stop no longer turns vision off.** Five cancelled vision requests opened the breaker and every + image got OCR only for five minutes. A request the user stopped is no longer counted; one that + timed out still is. +- **An OCR result that stands in for the vision model is never cached,** whatever made the vision + model unavailable, so the next analysis asks the vision model again. +- **An image that cannot be decoded is not sent to the vision model.** An SVG, a TIFF or a damaged + WebP whose conversion failed went to the model as if it were a PNG, was rejected and retried, and + each rejection counted toward turning vision off for the images after it. Such a file is now + analyzed from its text if it has any, else from its name, and the reason shown names the file. + Text from the vision runtime's error log no longer appears in error messages. +- **In an image batch, an image waits for a document that is still using the text model** (up to 45 + s) instead of losing its vision analysis, and an image that arrives while the text model is still + loading no longer starts the vision runtime on top of it. +- **Embedding models and a small GPU.** An embedding load that starts while the text model is still + loading runs on the CPU instead of waiting and then unloading the text model. Inside an image + batch, an embedding load no longer unloads the text model that took the vision runtime's place. +- **A text model larger than the memory budget loads without waiting out the full timeout** once + nothing else is left to unload. +- **Whisper runs on the CPU while the text model is still being loaded** onto a GPU that cannot hold + both. ## [5.1.2] - 2026-11-01 diff --git a/docs/CONFIG.md b/docs/CONFIG.md index 87d0ae1..a5c0cd3 100644 --- a/docs/CONFIG.md +++ b/docs/CONFIG.md @@ -274,8 +274,8 @@ organized into categories: | `AI_ANALYSIS_MEDIUM` | 60,000 | Medium AI analysis timeout | | `AI_ANALYSIS_LONG` | 300,000 | Long AI analysis timeout (5 min; CPU vision) | | `AI_ANALYSIS_BATCH` | 1,800,000 | Batch analysis timeout (30 min) | -| `ANALYSIS_LOCK` | 300,000 | Max lock duration before force release | -| `GLOBAL_ANALYSIS` | 600,000 | Max total analysis time (10 min) | +| `ANALYSIS_LOCK` | 300,000 | A Discover run with no progress for this long is stopped and its lock released (5 min) | +| `GLOBAL_ANALYSIS` | 600,000 | Watcher limit for one document or image (10 min); base of the Discover run cap (6x, at least 60 min) | | `WINDOW_SHOW_FALLBACK` | 4,000 | Show the main window if `ready-to-show` has not fired | | `FIRST_PAINT_GATE` | 5,100 | Longest wait for the first paint before AI bring-up starts; outlasts `WINDOW_SHOW_FALLBACK` plus the ~100 ms show delay | | `COORDINATED_STARTUP_SOFT` | 45,000 | After this, coordinated startup is reported as degraded ("still starting" warning) but keeps running | diff --git a/src/main/analysis/imageAnalysis.js b/src/main/analysis/imageAnalysis.js index 1654d3a..52beeb8 100644 --- a/src/main/analysis/imageAnalysis.js +++ b/src/main/analysis/imageAnalysis.js @@ -1280,6 +1280,22 @@ async function preprocessImageBuffer(imageBuffer, fileExtension, options = {}) { } } +/** + * Whether these are bytes the vision runtime and Tesseract decode without + * our preprocessing: PNG, JPEG, GIF or BMP by their signature. + * @param {Buffer | null | undefined} buffer + * @returns {boolean} + */ +function decodesWithoutPreprocessing(buffer) { + if (!buffer || buffer.length < 4) return false; + if (buffer[0] === 0x89 && buffer[1] === 0x50 && buffer[2] === 0x4e && buffer[3] === 0x47) { + return true; + } + if (buffer[0] === 0xff && buffer[1] === 0xd8 && buffer[2] === 0xff) return true; + const head = buffer.toString('latin1', 0, 4); + return head === 'GIF8' || head.startsWith('BM'); +} + // ============================================================================ // Main Analysis Function // ============================================================================ @@ -1474,6 +1490,8 @@ async function runImageAnalysis(filePath, smartFolders, options) { // Handle TOCTOU race condition - file could be deleted between stat() and readFile() let imageBuffer; let imageBufferPreprocessed = false; + /** @type {string | null} why the image cannot go to the vision model */ + let undecodableReason = null; try { imageBuffer = predecodedBuffer || (await fs.readFile(filePath)); } catch (readError) { @@ -1515,10 +1533,21 @@ async function runImageAnalysis(filePath, smartFolders, options) { imageBuffer = await preprocessImageBuffer(imageBuffer, effectiveExtension); imageBufferPreprocessed = true; } catch (preErr) { - logger.warn('[IMAGE] Preprocessing failed, continuing with original buffer', { - path: filePath, - error: preErr.message - }); + if (decodesWithoutPreprocessing(imageBuffer)) { + logger.warn('[IMAGE] Preprocessing failed, continuing with original buffer', { + path: filePath, + error: preErr.message + }); + } else { + // SVG markup, a TIFF, a damaged WebP: the runtime was sent these + // labelled image/png and rejected each one, and every rejection + // counted toward shutting vision off for the images after it. + undecodableReason = String(preErr?.message || 'unknown error').slice(0, 120); + logger.warn('[IMAGE] Preprocessing failed; not sending these bytes to the vision model', { + path: filePath, + error: preErr.message + }); + } } // Validate buffer is not empty @@ -1667,6 +1696,10 @@ async function runImageAnalysis(filePath, smartFolders, options) { extractedText = result._ocrText; delete result._ocrText; } + // Usable, but only what OCR text could tell, and every caller is here + // because the vision model did not answer: never serve it from the + // cache, so the next analysis of this image tries the vision model again. + if (result) result._skipCache = true; return result; }; @@ -1685,10 +1718,13 @@ async function runImageAnalysis(filePath, smartFolders, options) { visionSupported = false; } - if (!visionSupported) { - logger.warn('[IMAGE] Vision input unsupported, falling back to OCR/text', { - filePath - }); + if (undecodableReason || !visionSupported) { + logger.warn( + undecodableReason + ? '[IMAGE] Image could not be decoded, falling back to its text' + : '[IMAGE] Vision input unsupported, falling back to OCR/text', + { filePath } + ); const fallbackAnalysis = await tryTextFallback(); if (fallbackAnalysis) { analysis = fallbackAnalysis; @@ -1697,7 +1733,11 @@ async function runImageAnalysis(filePath, smartFolders, options) { { fileName, fileExtension, - reason: `Vision model '${visionModelName}' not loaded`, + // The file's own fault is said as such: "vision analysis + // unavailable" sent people looking for a model problem. + reason: undecodableReason + ? `Image could not be decoded (${undecodableReason})` + : `Vision model '${visionModelName}' not loaded`, smartFolders, confidence: 55, type: 'image' @@ -1791,9 +1831,6 @@ async function runImageAnalysis(filePath, smartFolders, options) { const fallbackAnalysis = await tryTextFallback(); if (fallbackAnalysis) { fallbackAnalysis.analysisWarning = analysis.error; - // Usable, but only what OCR text could tell: never serve it from the - // cache, so the next analysis of this image tries the vision model again. - fallbackAnalysis._skipCache = true; analysis = fallbackAnalysis; } else { analysis = createVisionUnavailableFallback( @@ -2375,6 +2412,13 @@ async function extractTextFromImage(filePath, options = {}) { maxDimension: OCR_MAX_DIMENSION }); } catch (preprocessError) { + if (!decodesWithoutPreprocessing(imageBuffer)) { + logger.warn('[IMAGE-OCR] Preprocessing failed; no OCR on bytes that were not decoded', { + filePath, + error: preprocessError.message + }); + return null; + } logger.warn('[IMAGE-OCR] Preprocessing failed, continuing OCR with original buffer', { filePath, error: preprocessError.message diff --git a/src/main/analysis/mediaAnalysis.js b/src/main/analysis/mediaAnalysis.js index 6afa76b..512ca29 100644 --- a/src/main/analysis/mediaAnalysis.js +++ b/src/main/analysis/mediaAnalysis.js @@ -615,6 +615,8 @@ async function analyzeMediaFile(filePath, dependencies = {}, options = {}) { const hasUsableTranscript = transcriptForLlm.trim().length > 0; let llmResult = cloudAnalysis; + /** @type {string|null} Why the text model gave no answer for a transcript it was sent. */ + let llmFailure = null; if (!llmResult && hasUsableTranscript) { try { // analyzeTextWithLlama is positional: @@ -630,6 +632,21 @@ async function analyzeMediaFile(filePath, dependencies = {}, options = {}) { smartFolderId, fileType: kind }); + // The text model reports a failure it survived (engine error, model + // not installed, an answer it could not parse) by returning + // `{ error }`, not by throwing. Spread into the result below, that + // object was stored as a finished transcription with confidence 0. + if (llmResult?.error) { + if (isMemoryBudgetExceeded(llmResult.error)) { + const budgetError = /** @type {Error & { code?: string }} */ ( + new Error(String(llmResult.error)) + ); + budgetError.code = 'MODEL_MEMORY_BUDGET_EXCEEDED'; + throw budgetError; + } + llmFailure = String(llmResult.error); + llmResult = null; + } } catch (err) { // A cancel, or a model load refused while another model holds the // memory, is not a result. Storing the confidence-60 stub below would @@ -642,9 +659,12 @@ async function analyzeMediaFile(filePath, dependencies = {}, options = {}) { ) { throw err; } + llmFailure = String(err?.message || 'AI analysis failed for the transcript.'); + } + if (llmFailure) { logger.warn('[Media] LLM transcript analysis failed', { file: fileName, - error: err?.message + error: llmFailure }); } } @@ -685,7 +705,18 @@ async function analyzeMediaFile(filePath, dependencies = {}, options = {}) { : 'Spoken content transcribed via whisper.cpp' : 'Media file with no detectable speech'), contentLength: transcriptForLlm.length, - extractionMethod + extractionMethod, + // The transcript is real, the category and keywords are placeholders: + // provisional, as a document whose text was read but not analyzed, so + // it is retried when the model answers again and not embedded as is. + ...(llmFailure + ? { + error: llmFailure, + fallbackReason: 'ai_analysis_failed', + isFallback: true, + _isFallback: true + } + : {}) }, baseFallback ); diff --git a/src/main/ipc/analysis.js b/src/main/ipc/analysis.js index aec3ecb..bcf38b0 100644 --- a/src/main/ipc/analysis.js +++ b/src/main/ipc/analysis.js @@ -23,7 +23,11 @@ const { } = require('./analysisUtils'); const BatchAnalysisService = require('../services/BatchAnalysisService'); const { claimUserAnalysis, withUserAnalysis } = require('../analysis/userAnalysisInFlight'); -const { sendOperationProgress, sendFileComplete } = require('./files/batchProgressReporter'); +const { + sendOperationProgress, + flushOperationProgress, + sendFileComplete +} = require('./files/batchProgressReporter'); const { createMediaAnalyzerAdapter } = require('../services/mediaAnalyzerAdapter'); const { getInstance: getWhisperService } = require('../services/WhisperService'); @@ -44,6 +48,64 @@ function safeGetWhisperService() { } } +/** + * The size and dates of a file before its analysis. Nothing holds the file + * open while the model works, so it can be saved again in that time. Read + * after the pass, the history kept the size and date of a version the result + * does not describe, and that version then counted as analyzed. + * @param {string} filePath + * @returns {Promise} + */ +async function statBeforeAnalysis(filePath) { + try { + return await fs.stat(filePath); + } catch { + return null; + } +} + +/** + * The stats to record with a result: those from before the pass. None when + * the file is gone by now, so the record reads the file itself and fails, as + * it always did for a file removed during its analysis. + * @param {string} filePath + * @param {import('fs').Stats|null} before + * @returns {Promise} + */ +async function statsToRecord(filePath, before) { + if (!before) return null; + try { + await fs.stat(filePath); + return before; + } catch { + return null; + } +} + +// The same events the live log feed detaches on (liveLogFeed.js). +// 'did-navigate' and not 'did-start-navigation': that one also fires for a +// navigation that 'will-navigate' then blocks, with the page still there. +const SENDER_GONE_EVENTS = ['destroyed', 'render-process-gone', 'did-navigate']; + +/** + * Stops a batch when the renderer that asked for it goes away: its process + * died, its window closed, or the page was loaded again (Reload, the + * automatic reload after a crash). Nothing told main, so the batch ran on + * with no owner: the watcher waited behind it, its progress was written into + * the new page, and a new Analyze ran the same files beside it. + * @param {any} sender - event.sender (a WebContents) + * @param {(reason: string) => void} cancelRun + * @returns {() => void} Removes the listeners. + */ +function cancelWhenSenderGoesAway(sender, cancelRun) { + if (typeof sender?.on !== 'function' || typeof sender?.removeListener !== 'function') { + return () => {}; + } + const onGone = () => cancelRun('The window that started the analysis closed or was reloaded'); + SENDER_GONE_EVENTS.forEach((name) => sender.on(name, onGone)); + return () => SENDER_GONE_EVENTS.forEach((name) => sender.removeListener(name, onGone)); +} + /** @type {InstanceType | null} */ let batchAnalysisService = null; /** @type {Map>} */ @@ -90,6 +152,7 @@ async function resolveNamingSettings(settingsService, namingOverride) { * @param {import('./ipcWrappers').LoggerLike} logger * @param {string} logPrefix * @param {Record|null|undefined} [namingOverride] - Discover session naming (wins over Settings when set) + * @param {import('fs').Stats|null} [fileStats] - Stats read before the analysis; read now when absent */ async function applyUserNamingFromSettings( filePath, @@ -97,7 +160,8 @@ async function applyUserNamingFromSettings( settingsService, logger, logPrefix, - namingOverride = null + namingOverride = null, + fileStats = null ) { if (!result || typeof result !== 'object') { return result; @@ -120,7 +184,7 @@ async function applyUserNamingFromSettings( if (!namingSettings) { return result; } - const stats = await fs.stat(filePath); + const stats = fileStats || (await fs.stat(filePath)); const fileTimestamps = { created: stats.birthtime, modified: stats.mtime }; const originalFileName = path.basename(filePath); const preservedLlm = @@ -486,6 +550,7 @@ function registerAnalysisIpc(servicesOrParams) { getFolderNamesString(folderCategories) ); + const statsBefore = await statBeforeAnalysis(cleanPath); const result = await analyzeDocumentFile(cleanPath, folderCategories, { abortSignal }); await applyUserNamingFromSettings( cleanPath, @@ -493,7 +558,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -504,6 +570,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'llm', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -608,6 +675,7 @@ function registerAnalysisIpc(servicesOrParams) { getFolderNamesString(folderCategories) ); + const statsBefore = await statBeforeAnalysis(cleanPath); const result = await analyzeImageFile(cleanPath, folderCategories, { abortSignal }); await applyUserNamingFromSettings( cleanPath, @@ -615,7 +683,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, IMAGE_LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -626,6 +695,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'vision', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -736,6 +806,7 @@ function registerAnalysisIpc(servicesOrParams) { }) ); const isCancelled = () => Boolean(abortSignal?.aborted); + const statsBefore = await statBeforeAnalysis(cleanPath); const result = await analyzer(cleanPath, folderCategories, { isCancelled, abortSignal }); await applyUserNamingFromSettings( cleanPath, @@ -743,7 +814,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, MEDIA_LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -754,6 +826,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'whisper', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -872,91 +945,15 @@ function registerAnalysisIpc(servicesOrParams) { } } - const pathValidation = await Promise.allSettled( - rawPaths.map((/** @type {string} */ filePath) => validateAnalysisPath(filePath)) - ); - /** @type {string[]} */ - const validatedPaths = []; - /** @type {Array>} */ - const validationErrors = []; - /** @type {Array>} */ - const validationFailureResults = []; - - pathValidation.forEach((result, index) => { - const originalPath = rawPaths[index]; - if (result.status === 'fulfilled') { - validatedPaths.push(result.value); - return; - } - - const reasonMessage = - result.reason && typeof result.reason.message === 'string' - ? result.reason.message - : 'Invalid file path provided'; - const validationError = { - filePath: originalPath, - error: reasonMessage, - code: 'INVALID_PATH' - }; - validationErrors.push(validationError); - validationFailureResults.push({ - filePath: originalPath, - success: false, - error: reasonMessage, - code: 'INVALID_PATH' - }); - }); - - if (validationErrors.length > 0) { - logger.warn(`${LOG_PREFIX} Batch path validation failed for some files`, { - batchId, - invalidCount: validationErrors.length, - totalCount: rawPaths.length - }); - } - - if (validatedPaths.length === 0 || (options.stopOnError && validationErrors.length > 0)) { - return { - success: false, - cancelled: false, - results: validationFailureResults, - errors: validationErrors, - total: rawPaths.length, - processed: 0, - successful: 0, - hasErrors: validationErrors.length > 0, - batchId - }; - } - /** @type {any[]} */ - let folderCategories = []; - if ( - Array.isArray(normalizedPayload.smartFolders) && - normalizedPayload.smartFolders.length > 0 - ) { - try { - folderCategories = mapFoldersToCategories(normalizedPayload.smartFolders); - } catch (folderError) { - logger.warn(`${LOG_PREFIX} Failed to normalize provided smart folders`, { - error: folderError?.message - }); - } - } - if (!Array.isArray(folderCategories) || folderCategories.length === 0) { - folderCategories = getFolderCategories(getCustomFolders, mapFoldersToCategories, logger); - } - - logger.info(`${LOG_PREFIX} Starting batch analysis`, { - batchId, - totalFiles: validatedPaths.length, - folders: folderCategories.length, - sectionOrder: options.sectionOrder || 'documents-first' - }); - // Batch-scoped AbortController: every cancel path (renderer - // CANCEL_BATCH, IPC abort signal, app shutdown) aborts it so in-flight - // LLM/vision inference stops immediately instead of waiting for the - // next cooperative isCancelled() poll. + // CANCEL_BATCH, IPC abort signal, app shutdown, the renderer going + // away) aborts it so in-flight LLM/vision inference stops immediately + // instead of waiting for the next cooperative isCancelled() poll. + // + // The run is registered before its paths are checked. The check reads + // the disk for every file, and a Stop that arrived during it was + // answered "unknown batch" and never sent again: the batch then ran to + // its end with nothing able to stop it. const batchAbortController = new AbortController(); /** @type {Record} */ const runState = { @@ -969,6 +966,18 @@ function registerAnalysisIpc(servicesOrParams) { abortController: batchAbortController }; activeBatchRuns.set(batchId, runState); + const cancelRun = (/** @type {string} */ reason) => { + runState.cancelled = true; + if (!runState.reason) { + runState.reason = reason; + runState.requestedAt = Date.now(); + } + batchAbortController.abort(); + }; + // A report of this run is shown only while the run is wanted: not after + // a cancel, and not after the run ended or its id went to another run. + const progressStillWanted = () => + !runState.cancelled && activeBatchRuns.get(batchId) === runState; // Bridge the ipcRegistry AbortSignal into runState.cancelled so a // preload-timeout or renderer cancel flips the cooperative cancel @@ -980,49 +989,126 @@ function registerAnalysisIpc(servicesOrParams) { const ipcAbortSignal = event?.abortSignal; if (ipcAbortSignal) { if (ipcAbortSignal.aborted) { - runState.cancelled = true; - runState.reason = runState.reason || 'ipc-abort-signal'; - runState.requestedAt = runState.requestedAt || Date.now(); - batchAbortController.abort(); + cancelRun('ipc-abort-signal'); } else { - const onAbort = () => { - runState.cancelled = true; - if (!runState.reason) { - runState.reason = 'ipc-abort-signal'; - runState.requestedAt = Date.now(); - } - batchAbortController.abort(); - }; + const onAbort = () => cancelRun('ipc-abort-signal'); ipcAbortSignal.addEventListener('abort', onAbort, { once: true }); removeAbortListener = () => ipcAbortSignal.removeEventListener?.('abort', onAbort); } } + const stopWatchingSender = cancelWhenSenderGoesAway(event?.sender, cancelRun); + + /** @type {ReturnType | null} */ + let progressHeartbeat = null; + let releaseUserAnalysis = () => {}; + try { + const pathValidation = await Promise.allSettled( + rawPaths.map((/** @type {string} */ filePath) => validateAnalysisPath(filePath)) + ); + /** @type {string[]} */ + const validatedPaths = []; + /** @type {Array>} */ + const validationErrors = []; + /** @type {Array>} */ + const validationFailureResults = []; + + pathValidation.forEach((result, index) => { + const originalPath = rawPaths[index]; + if (result.status === 'fulfilled') { + validatedPaths.push(result.value); + return; + } + + const reasonMessage = + result.reason && typeof result.reason.message === 'string' + ? result.reason.message + : 'Invalid file path provided'; + const validationError = { + filePath: originalPath, + error: reasonMessage, + code: 'INVALID_PATH' + }; + validationErrors.push(validationError); + validationFailureResults.push({ + filePath: originalPath, + success: false, + error: reasonMessage, + code: 'INVALID_PATH' + }); + }); - // The service reports only when a file starts or finishes, and one long - // recording is many minutes of work. The renderer takes 5 minutes without - // a report for a stuck analysis and resets it. So the last report is - // repeated while the batch runs: silence then means main stopped - // answering. Only for as long as one file may take, so a file that hangs - // is still noticed. - const quietBudgetMs = validatedPaths.some((/** @type {string} */ p) => isMediaPath(p)) - ? TIMEOUTS.BATCH_MEDIA_QUIET_MAX - : TIMEOUTS.BATCH_FILE_QUIET_MAX; - /** @type {Record | null} */ - let lastProgressPayload = null; - let lastProgressAt = 0; - const progressHeartbeat = setInterval(() => { - if (!lastProgressPayload || runState.cancelled) return; - if (Date.now() - lastProgressAt > quietBudgetMs) return; - if (typeof getMainWindow === 'function') { - sendOperationProgress(getMainWindow, lastProgressPayload); + if (validationErrors.length > 0) { + logger.warn(`${LOG_PREFIX} Batch path validation failed for some files`, { + batchId, + invalidCount: validationErrors.length, + totalCount: rawPaths.length + }); } - }, TIMEOUTS.HEARTBEAT_INTERVAL); - progressHeartbeat.unref?.(); - // The smart-folder watcher defers these files until the batch is done, - // so a file it also sees is not analyzed twice at once. - const releaseUserAnalysis = claimUserAnalysis(validatedPaths); - try { + if (validatedPaths.length === 0 || (options.stopOnError && validationErrors.length > 0)) { + return { + success: false, + cancelled: false, + results: validationFailureResults, + errors: validationErrors, + total: rawPaths.length, + processed: 0, + successful: 0, + hasErrors: validationErrors.length > 0, + batchId + }; + } + /** @type {any[]} */ + let folderCategories = []; + if ( + Array.isArray(normalizedPayload.smartFolders) && + normalizedPayload.smartFolders.length > 0 + ) { + try { + folderCategories = mapFoldersToCategories(normalizedPayload.smartFolders); + } catch (folderError) { + logger.warn(`${LOG_PREFIX} Failed to normalize provided smart folders`, { + error: folderError?.message + }); + } + } + if (!Array.isArray(folderCategories) || folderCategories.length === 0) { + folderCategories = getFolderCategories(getCustomFolders, mapFoldersToCategories, logger); + } + + logger.info(`${LOG_PREFIX} Starting batch analysis`, { + batchId, + totalFiles: validatedPaths.length, + folders: folderCategories.length, + sectionOrder: options.sectionOrder || 'documents-first' + }); + + // The service reports only when a file starts or finishes, and one long + // recording is many minutes of work. The renderer takes 5 minutes without + // a report for a stuck analysis and resets it. So the last report is + // repeated while the batch runs: silence then means main stopped + // answering. Only for as long as one file may take, so a file that hangs + // is still noticed. + const quietBudgetMs = validatedPaths.some((/** @type {string} */ p) => isMediaPath(p)) + ? TIMEOUTS.BATCH_MEDIA_QUIET_MAX + : TIMEOUTS.BATCH_FILE_QUIET_MAX; + /** @type {Record | null} */ + let lastProgressPayload = null; + let lastProgressAt = 0; + progressHeartbeat = setInterval(() => { + if (!lastProgressPayload || runState.cancelled) return; + if (Date.now() - lastProgressAt > quietBudgetMs) return; + if (typeof getMainWindow === 'function') { + sendOperationProgress(getMainWindow, lastProgressPayload, { + stillWanted: progressStillWanted + }); + } + }, TIMEOUTS.HEARTBEAT_INTERVAL); + progressHeartbeat.unref?.(); + + // The smart-folder watcher defers these files until the batch is done, + // so a file it also sees is not analyzed twice at once. + releaseUserAnalysis = claimUserAnalysis(validatedPaths); // BatchAnalysisService.analyzeFiles' JSDoc enumerates only a subset of // the options it consumes and elides successful/cancelled from its // return type; cast until that service opts in to checkjs. @@ -1047,7 +1133,9 @@ function registerAnalysisIpc(servicesOrParams) { lastProgressPayload = { type: 'batch_analyze', batchId, ...progress }; lastProgressAt = Date.now(); if (typeof getMainWindow === 'function') { - sendOperationProgress(getMainWindow, lastProgressPayload); + sendOperationProgress(getMainWindow, lastProgressPayload, { + stillWanted: progressStillWanted + }); } }, onFileComplete: (/** @type {any} */ item) => { @@ -1113,6 +1201,7 @@ function registerAnalysisIpc(servicesOrParams) { logPrefix: LOG_PREFIX, fn: async () => { const started = performance.now(); + const statsBefore = await statBeforeAnalysis(filePath); const result = await analyzeDocumentFile(filePath, smartFolders, { abortSignal: batchAbortController.signal }); @@ -1122,7 +1211,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1130,6 +1220,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'llm', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1148,6 +1239,7 @@ function registerAnalysisIpc(servicesOrParams) { logPrefix: '[IPC-IMAGE-ANALYSIS]', fn: async () => { const started = performance.now(); + const statsBefore = await statBeforeAnalysis(filePath); const result = await analyzeImageFile(filePath, smartFolders, { abortSignal: batchAbortController.signal }); @@ -1157,7 +1249,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, '[IPC-IMAGE-ANALYSIS]', - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1165,6 +1258,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'vision', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1200,6 +1294,7 @@ function registerAnalysisIpc(servicesOrParams) { whisperService: safeGetWhisperService() }) ); + const statsBefore = await statBeforeAnalysis(filePath); const result = await adapter(filePath, smartFolders, { ...opts, abortSignal: batchAbortController.signal @@ -1210,7 +1305,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, '[IPC-MEDIA-ANALYSIS]', - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1218,6 +1314,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'media', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1233,6 +1330,13 @@ function registerAnalysisIpc(servicesOrParams) { ); const batchResult = await batchPromise; + // The last report is usually still held by the throttle, and is dropped + // once this run is unregistered below. The search and embedding counts + // refresh on it, so a run that reached its end sends it itself. + if (lastProgressPayload && !runState.cancelled && typeof getMainWindow === 'function') { + flushOperationProgress(getMainWindow, lastProgressPayload); + } + // Whole-batch wall-clock is used for the completion log only. // Per-file processing samples are recorded in onFileComplete so the // diagnostics avg reflects per-file timing, not the batch duration. @@ -1262,9 +1366,10 @@ function registerAnalysisIpc(servicesOrParams) { batchId }; } finally { - clearInterval(progressHeartbeat); + if (progressHeartbeat) clearInterval(progressHeartbeat); releaseUserAnalysis(); removeAbortListener?.(); + stopWatchingSender(); // Only this run's own entry: an evicted run that finishes late must // not remove the run that replaced it, or that run can no longer be // cancelled. diff --git a/src/main/ipc/files/batchProgressReporter.js b/src/main/ipc/files/batchProgressReporter.js index 526685e..6c88d5e 100644 --- a/src/main/ipc/files/batchProgressReporter.js +++ b/src/main/ipc/files/batchProgressReporter.js @@ -18,6 +18,8 @@ let _lastProgressSendMs = 0; let _pendingGetMainWindow = null; /** @type {*} */ let _pendingProgressPayload = null; +/** @type {(() => boolean)|null} */ +let _pendingStillWanted = null; /** @type {ReturnType|null} */ let _pendingProgressTimer = null; @@ -35,10 +37,18 @@ function _doSend(getMainWindow, payload) { /** * Throttled progress sender. Emits at most once per THROTTLE_MS. * The final update in a batch is always delivered (via trailing flush). + * + * The trailing flush runs up to THROTTLE_MS after the call, and the operation + * can have ended or been stopped by then. A caller whose report must not + * arrive after that passes stillWanted: it is asked when the window closes, + * and the held report is dropped when it answers false. A Discover analysis + * that was stopped got its counts sent again this way, after the renderer had + * cleared them, and counts without a running analysis read as a paused one. * @param {GetMainWindowFn} getMainWindow * @param {*} payload + * @param {{ stillWanted?: () => boolean }} [options] */ -function sendOperationProgress(getMainWindow, payload) { +function sendOperationProgress(getMainWindow, payload, { stillWanted } = {}) { const now = Date.now(); const elapsed = now - _lastProgressSendMs; @@ -49,27 +59,54 @@ function sendOperationProgress(getMainWindow, payload) { } _pendingGetMainWindow = null; _pendingProgressPayload = null; + _pendingStillWanted = null; _lastProgressSendMs = now; _doSend(getMainWindow, payload); return; } - // Trailing edge: buffer the latest payload and window getter for flush + // Trailing edge: buffer the latest payload and window getter for flush. + // The check belongs to the held payload: a later caller without one is not + // held back by the check of the caller before it. _pendingGetMainWindow = getMainWindow; _pendingProgressPayload = payload; + _pendingStillWanted = typeof stillWanted === 'function' ? stillWanted : null; if (!_pendingProgressTimer) { _pendingProgressTimer = setTimeout(() => { _pendingProgressTimer = null; if (_pendingProgressPayload && _pendingGetMainWindow) { - _lastProgressSendMs = Date.now(); - _doSend(_pendingGetMainWindow, _pendingProgressPayload); + if (!_pendingStillWanted || _pendingStillWanted()) { + _lastProgressSendMs = Date.now(); + _doSend(_pendingGetMainWindow, _pendingProgressPayload); + } _pendingGetMainWindow = null; _pendingProgressPayload = null; + _pendingStillWanted = null; } }, THROTTLE_MS - elapsed); } } +/** + * Send an operation's closing report now, outside the throttle. The operation + * ends before the window closes, so a held report of it would be dropped by + * its own stillWanted; listeners that refresh on the closing report would + * never hear that it finished. Takes the place of a held report of the same + * batch. + * @param {GetMainWindowFn} getMainWindow + * @param {*} payload + */ +function flushOperationProgress(getMainWindow, payload) { + const held = _pendingProgressPayload; + if (held && (held === payload || (held.batchId && held.batchId === payload?.batchId))) { + _pendingGetMainWindow = null; + _pendingProgressPayload = null; + _pendingStillWanted = null; + } + _lastProgressSendMs = Date.now(); + _doSend(getMainWindow, payload); +} + /** * Deliver batch results to the renderer in fixed-size chunks. * @param {GetMainWindowFn} getMainWindow @@ -162,6 +199,7 @@ function sendFileOperationBatchComplete(getMainWindow, { operation, files, desti module.exports = { sendOperationProgress, + flushOperationProgress, sendChunkedResults, sendFileComplete, sendFileOperationBatchComplete diff --git a/src/main/ipc/semantic.js b/src/main/ipc/semantic.js index 326bc46..7bd754d 100644 --- a/src/main/ipc/semantic.js +++ b/src/main/ipc/semantic.js @@ -1321,7 +1321,7 @@ async function handleComputeClusters( ); } else if (!memoryAllowsOptionalText) { logger.info( - '[EMBEDDINGS] Skipping background LLM label refinement — text model not loaded and memory budget is tight' + '[EMBEDDINGS] Skipping background LLM label refinement — no memory headroom for optional text work right now' ); } else { service.generateClusterLabels({ skipLLM: false }).catch((/** @type {any} */ err) => { diff --git a/src/main/services/ClusteringService.js b/src/main/services/ClusteringService.js index 5d48bb4..1377f78 100644 --- a/src/main/services/ClusteringService.js +++ b/src/main/services/ClusteringService.js @@ -22,6 +22,7 @@ const { withAbortableTimeout } = require('../../shared/promiseUtils'); const { getTextModel } = require('../llamaUtils'); const { AI_DEFAULTS } = require('../../shared/constants'); const { isInteractiveTextRequestActive } = require('./textModelActivity'); +const { toLocalCalendarMs } = require('../../shared/contentDateSanity'); const { FILE_TYPE_CATEGORIES, getFileTypeSingular } = require('./autoOrganize/fileTypeUtils'); const { deriveClusterDisplayLabel, @@ -1542,11 +1543,10 @@ Examples of good names: "Q4 Financial Reports", "Employee Onboarding Materials", } const totalDocs = memberSignals.size; - const parseDateCandidateMs = (/** @type {any} */ value) => { - if (!value) return null; - const ms = Date.parse(String(value)); - return Number.isFinite(ms) ? ms : null; - }; + // A document date is a day ("2024-05-05"): local midnight, so the + // range labels the renderer formats in local time name that day. + const parseDateCandidateMs = (/** @type {any} */ value) => + value ? toLocalCalendarMs(value) : null; const getMemberPath = (/** @type {any} */ member) => coerceIndexedPath(member?.metadata || {}, member?.id || ''); diff --git a/src/main/services/LlamaResilience.js b/src/main/services/LlamaResilience.js index a8e9e48..c90c063 100644 --- a/src/main/services/LlamaResilience.js +++ b/src/main/services/LlamaResilience.js @@ -53,6 +53,9 @@ const NON_TRANSIENT_ERROR_PATTERNS = [ 'unsupported image format', 'zero length image', 'invalid image', + // llama-server's answer for bytes it cannot decode ("Failed to load image + // or audio file"): the file's fault, not the runtime's. + 'failed to load image', // The memory manager refusing a load is a sizing decision, not a backend // fault. Five refusals in a row used to open the text breaker for 300 s. 'memory budget exceeded' diff --git a/src/main/services/LlamaService.js b/src/main/services/LlamaService.js index 2ecb09b..ba66da1 100644 --- a/src/main/services/LlamaService.js +++ b/src/main/services/LlamaService.js @@ -20,7 +20,7 @@ const { createSingletonHelpers } = require('../../shared/singletonFactory'); const { AI_DEFAULTS, DEFAULT_AI_MODELS } = require('../../shared/constants'); const { getModel } = require('../../shared/modelRegistry'); const { resolveEmbeddingDimension } = require('../../shared/embeddingDimensions'); -const { isVisionDecodePressureError } = require('./visionErrorClassification'); +const { isVisionRuntimeDecodePressure } = require('./visionErrorClassification'); const { ERROR_CODES } = require('../../shared/errorCodes'); const { attachErrorCode } = require('../../shared/errorHandlingUtils'); const { looksLikeCpuIncompatibility } = require('../../shared/llamaErrorClassifier'); @@ -320,6 +320,11 @@ class LlamaService extends EventEmitter { // starts from a fresh signal (some consumers cache the signal across // operations). this._shutdownAbort = new AbortController(); + // How long an image in a batch waits for a text request to let go of + // the text model (_releaseMemoryForBatchVisionRespawn). Well inside the + // 300 s an image analysis is allowed, with the runtime start to come. + this._batchTextDrainWaitMs = 45000; + this._batchTextDrainSliceMs = 2500; // Vision batch mode — keeps vision server alive across multiple images this._visionBatchMode = false; @@ -707,7 +712,7 @@ class LlamaService extends EventEmitter { } _isVisionDecodePressureError(/** @type {any} */ errorLike) { - return isVisionDecodePressureError(errorLike); + return isVisionRuntimeDecodePressure(errorLike); } _getContextSequences(type = 'text') { @@ -1767,7 +1772,10 @@ class LlamaService extends EventEmitter { // Set after the load, too: a batch that ended while this load was in // flight could not unload a model that was not registered yet, so the // next embedding load must still move it back to the GPU. - if (loadOptions?.cpuByDesign && loadOptions.besideResident === VISION_RUNTIME_MEMORY_TYPE) { + if ( + loadOptions?.cpuByDesign && + (loadOptions.forVisionBatch || loadOptions.besideResident === VISION_RUNTIME_MEMORY_TYPE) + ) { this._embeddingCpuForBatch = true; } return context; @@ -2146,6 +2154,40 @@ class LlamaService extends EventEmitter { throw budgetError; } + /** + * Make room for the vision runtime an image in a batch has to respawn + * (see _textResidentWhileVisionDown). + * + * The text model there belongs to a request that is still running: its + * load ended with the request's pin on it, so the first attempt is + * refused. One image then lost its vision analysis for a text request + * that ends seconds later. The request gets a bounded time to end, in + * slices so a cancelled or shut-down call stops waiting, and the attempt + * is made once more. The wait is here and not in + * _releaseMemoryForVisionRuntime: entering batch mode calls that under + * the batch-mode lock, which leaving batch mode needs. + * @param {AbortSignal} [signal] + * @throws {Error & { code: 'MODEL_MEMORY_BUDGET_EXCEEDED' }} the first + * refusal, when the text model is still in use after the wait + */ + async _releaseMemoryForBatchVisionRespawn(signal) { + try { + await this._releaseMemoryForVisionRuntime('batch'); + return; + } catch (error) { + if (/** @type {any} */ (error)?.code !== 'MODEL_MEMORY_BUDGET_EXCEEDED') throw error; + const manager = this._modelMemoryManager; + const stopped = () => Boolean(signal?.aborted || this._shutdownAbort?.signal?.aborted); + const deadline = Date.now() + this._batchTextDrainWaitMs; + let drained = false; + while (!drained && !stopped() && Date.now() < deadline) { + drained = await manager.unloadModel('text', { waitMs: this._batchTextDrainSliceMs }); + } + if (!drained) throw error; + } + await this._releaseMemoryForVisionRuntime('batch'); + } + async _waitForIdleOperations( /** @type {any} */ reason, timeoutMs = 30000, @@ -4221,13 +4263,14 @@ class LlamaService extends EventEmitter { /** * True during a vision batch when the runtime is gone and the text model - * sits in memory instead: a text load from inside the batch evicted the - * runtime. The next image must free that memory before respawning it. + * sits in memory instead, or is still being loaded: a text load from + * inside the batch evicted the runtime. The next image frees that memory + * before it respawns the runtime (_releaseMemoryForBatchVisionRespawn). * @returns {boolean} * @private */ _textResidentWhileVisionDown() { - if (!this._visionBatchMode || !this._modelMemoryManager?.getLoadedContext?.('text')) { + if (!this._visionBatchMode || !this._modelMemoryManager?.isLoadedOrLoading?.('text')) { return false; } try { @@ -4238,8 +4281,9 @@ class LlamaService extends EventEmitter { } /** - * Load options for the embedding model while the text model holds a GPU - * too small for both (a 7B text model on a 6 GB card). Without them every + * Load options for the embedding model while the text model holds, or is + * being loaded onto, a GPU too small for both (a 7B text model on a 6 GB + * card). Without them every * file evicted the text model to load the ~200 MB embedding model and then * reloaded the text model, about 4-5 s per file. The embedding model runs * on the CPU beside it instead, without the "running on CPU" warning; it @@ -4252,7 +4296,7 @@ class LlamaService extends EventEmitter { if (modelType !== 'embedding') return undefined; if (!this._gpuBackend || this._gpuBackend === 'cpu') return undefined; const memory = this._modelMemoryManager; - if (!memory?.getLoadedContext?.('text') || memory.getLoadedContext?.('embedding')) { + if (!memory?.isLoadedOrLoading?.('text') || memory.getLoadedContext?.('embedding')) { return undefined; } // Both fit on the GPU: load the embedding model there as usual. @@ -4263,14 +4307,33 @@ class LlamaService extends EventEmitter { /** * Load options for a model while a vision batch holds the runtime: the * embedding model runs on the CPU beside it instead of evicting it. + * + * The pin outlasts the runtime: a text load inside the batch evicts it and + * the text model holds the memory until the next image. The load is then + * beside the text model. Declared beside a runtime that is not there, it + * evicted the text model (or waited minutes for it) to make room for a + * model that takes no VRAM. * @private * @param {string} modelType * @returns {Record | undefined} */ _loadOptionsBesideVisionBatch(modelType) { if (modelType !== 'embedding' || !this._visionRuntimePinned) return undefined; - if (this._modelMemoryManager?.getLoadedContext?.('embedding')) return undefined; + const memory = this._modelMemoryManager; + if (memory?.getLoadedContext?.('embedding')) return undefined; this._embeddingCpuForBatch = true; + if ( + memory?.isLoadedOrLoading?.('text') && + !memory.isLoadedOrLoading(VISION_RUNTIME_MEMORY_TYPE) + ) { + return { + gpuLayersOverride: 0, + besideResident: 'text', + keepBeside: true, + cpuByDesign: true, + forVisionBatch: true + }; + } return { gpuLayersOverride: 0, besideResident: VISION_RUNTIME_MEMORY_TYPE, cpuByDesign: true }; } @@ -4405,7 +4468,7 @@ class LlamaService extends EventEmitter { if (!this._visionBatchMode && this._modelMemoryManager) { await this._releaseMemoryForVisionRuntime('single'); } else if (this._textResidentWhileVisionDown()) { - await this._releaseMemoryForVisionRuntime('batch'); + await this._releaseMemoryForBatchVisionRespawn(signal); } const visionService = getVisionService(); diff --git a/src/main/services/ModelMemoryManager.js b/src/main/services/ModelMemoryManager.js index 02abeb4..9463b50 100644 --- a/src/main/services/ModelMemoryManager.js +++ b/src/main/services/ModelMemoryManager.js @@ -81,6 +81,11 @@ class ModelMemoryManager { const estimatedUsage = Math.ceil(fileSizeBytes * 1.3); const oldEstimate = this._modelSizeEstimates[modelType]; this._modelSizeEstimates[modelType] = estimatedUsage; + // A load of this model that is in progress reserved the old guess. The + // first text load of a session held 4 GiB for a 5.8 GiB model, so an + // embedding model asked for meanwhile was told both fit on the GPU. + const pending = this._pendingLoads.get(modelType); + if (pending) pending.sizeBytes = estimatedUsage; logger.debug('[Memory] Updated model size estimate from file', { modelType, fileSizeMB: Math.round(fileSizeBytes / 1024 / 1024), @@ -210,6 +215,19 @@ class ModelMemoryManager { return null; } + /** + * Whether a model holds memory or is about to: it is in memory, or a load + * of it is in progress. A caller that asked only getLoadedContext saw + * nothing for the seconds a load takes, while the budget already counted + * it. Asking does not count as using the model. + * @param {string} modelType + * @returns {boolean} + */ + isLoadedOrLoading(modelType) { + const entry = this._loadedModels.get(modelType); + return Boolean(entry && !entry.disposing) || this._pendingLoads.has(modelType); + } + /** * Check if we can load a model of given type */ @@ -364,8 +382,9 @@ class ModelMemoryManager { /** * Whether optional background work may use a model without forcing a load. - * Returns true when the model is already resident, or when a fresh load fits - * within the current budget. Unlike ensureModelLoaded(), this never proceeds + * Returns true when the model is the only thing in memory (a call on a + * loaded context loads nothing), when it is resident with headroom left + * beside the others, or when a fresh load fits within the current budget. Unlike ensureModelLoaded(), this never proceeds * when the budget is exceeded — callers use it to skip non-critical inference * (e.g. graph cluster label refinement) instead of risking native OOM. * @@ -374,7 +393,13 @@ class ModelMemoryManager { */ canRunOptionalLoad(modelType) { this._refreshMemoryBudget(); - if (this._loadedModels.has(modelType)) { + const entry = this._loadedModels.get(modelType); + if (entry) { + if (entry.disposing) return false; + // A model whose estimate is above the budget on its own (7B on a 6 GB + // card) never has headroom, so this said no for the rest of the session + // while the model sat idle in memory. + if (this._loadedModels.size === 1 && this._pendingLoadEntries().length === 0) return true; const remaining = Math.max( 0, this._maxMemoryUsage - this._currentMemoryUsage - this._pendingLoadBytes() @@ -475,7 +500,10 @@ class ModelMemoryManager { // evicted here once it is idle. if (!fits() && othersHoldMemory() && this._pinnedResidentWaitMs > 0) { const deadline = Date.now() + this._pinnedResidentWaitMs; - while (!fits() && Date.now() < deadline) { + // Once nothing else holds memory there is nothing left to wait for: a + // model whose own estimate exceeds the budget never fits, and waited + // out the whole three minutes after the resident had gone. + while (!fits() && othersHoldMemory() && Date.now() < deadline) { await delay(this._pinnedResidentPollMs); this._refreshMemoryBudget(); while (!fits() && this._loadedModels.size > 0) { diff --git a/src/main/services/SmartFolderWatcher.js b/src/main/services/SmartFolderWatcher.js index 72d4edf..4f6c040 100644 --- a/src/main/services/SmartFolderWatcher.js +++ b/src/main/services/SmartFolderWatcher.js @@ -141,20 +141,50 @@ function analysisRetryDelayMs(retryCount) { } /** - * A reanalysis the user asked for stays one when a newer item for the same - * file takes its place. Replaced by a plain file event, it would run as a - * content update (original name kept, folder kept) or be skipped as already - * analyzed. + * What the item that gives way asked for stays asked for when another item + * for the same file takes its place. + * + * A reanalysis the user asked for stays one. Replaced by a plain file event, + * it would run as a content update (original name kept, folder kept) or be + * skipped as already analyzed. + * + * An embedding still owed stays owed (see embedFallbackOf). * @param {any} replaced the item that gives way * @param {any} replacement the item that stays in the queue */ -function keepReanalysisRequest(replaced, replacement) { - if (replaced?.eventType !== 'reanalyze' || replacement.eventType === 'reanalyze') return; +function keepAnalysisRequest(replaced, replacement) { + if (!replaced) return; + if (!replacement.cachedAnalysis && !replacement.embedFallback) { + const owed = embedFallbackOf(replaced); + if (owed) replacement.embedFallback = owed; + } + if (replaced.eventType !== 'reanalyze' || replacement.eventType === 'reanalyze') return; replacement.eventType = 'reanalyze'; replacement.applyNaming = replaced.applyNaming; if (replaced.bulk) replacement.bulk = true; } +/** + * The embedding an item still owes its file, in the form another item for + * the file can carry (`embedFallback`). + * + * An embedding retry carries the result of a pass that is over + * (`cachedAnalysis`) and only embeds it. It gives way to an item that asks + * for a new pass, but that item is skipped when its turn comes and the + * history already has the file, and then nothing embedded the file at all. + * The item that stays carries the result along and embeds it in that case. + * @param {any} item + * @returns {{ analysis: any, passStats: any, retryCount: number } | undefined} + */ +function embedFallbackOf(item) { + if (!item.cachedAnalysis) return item.embedFallback; + return { + analysis: item.cachedAnalysis, + passStats: item._passStats, + retryCount: item.retryCount || 0 + }; +} + // CRITICAL: Prevent unbounded memory growth under heavy file activity (e.g., large archive extraction). // We bound the analysis queue and apply light deduplication by filePath. const MAX_ANALYSIS_QUEUE_SIZE = LIMITS.ANALYSIS_QUEUE_SIZE ?? 1000; @@ -309,6 +339,11 @@ class SmartFolderWatcher { // Processing state this.processingFiles = new Set(); + // mtime and size each file in processingFiles had when its analysis + // began, so a change event raised by our own read of it can be told from + // an edit (see _isOwnReadEcho). + /** @type {Map} */ + this._analysisStartStats = new Map(); this.pendingAnalysis = new Map(); // filePath -> { mtime, timeout } /** @type {any[]} */ this.analysisQueue = []; @@ -328,8 +363,9 @@ class SmartFolderWatcher { /** @type {Promise | null} */ this._queuePersistPromise = null; // Items spliced out of analysisQueue and handed to _analyzeFile. They are - // in no queue for up to the 10-minute analysis timeout, so without this - // they'd be absent from the durable record for that whole window. + // in no queue for as long as the analysis may take (_analysisTimeoutMs: + // ten minutes, three hours for a recording), so without this they'd be + // absent from the durable record for that whole window. /** @type {Map} */ this._inFlightItems = new Map(); /** @type {'image' | 'media' | 'document' | null} */ @@ -942,6 +978,7 @@ class SmartFolderWatcher { this.isStarting = false; this.watchedPaths.clear(); this.processingFiles.clear(); + this._analysisStartStats.clear(); this.analysisQueue = []; // K-07: the overflow buffer must be cleared alongside the main queue. // _restoreQueue pushes onto it, so leaving it populated made every @@ -1396,6 +1433,13 @@ class SmartFolderWatcher { } } + if (eventType === 'change' && (await this._isOwnReadEcho(lookupKey, filePath))) { + logger.debug('[SMART-FOLDER-WATCHER] Change event from our own read; not queued', { + filePath + }); + return; + } + // Check if analysis is needed const needsAnalysis = await this._needsAnalysis(filePath, mtime, stats); @@ -1433,6 +1477,26 @@ class SmartFolderWatcher { } } + /** + * Whether a change event for a file we are analyzing right now is only the + * trace of our own read. On NTFS the first read of a file in an hour + * rewrites its last-access time, Windows reports that as a change, and + * chokidar passes it on. The event lands a few seconds into the analysis, + * before the history has the file, so every file the watcher analyzed was + * queued a second time. An edit moves the mtime or the size; a read does + * not. + * @private + * @param {string} key - canonical key of the file (as in processingFiles) + * @param {string} filePath + * @returns {Promise} + */ + async _isOwnReadEcho(key, filePath) { + const atStart = this._analysisStartStats.get(key); + if (!atStart) return false; + const now = await fs.stat(filePath); + return now.mtimeMs === atStart.mtimeMs && now.size === atStart.size; + } + /** * Add an item to the analysis queue with bounds + best-effort deduplication. * @private @@ -1455,7 +1519,17 @@ class SmartFolderWatcher { (q) => (q.dedupKey || q.filePath) === dedupKey || q.filePath === filePath ); if (existingIndex !== -1) { - keepReanalysisRequest(this.analysisQueue[existingIndex], item); + const existing = this.analysisQueue[existingIndex]; + // An embedding retry carries the result of a pass that is over. The + // queued item asks for a new pass (a newer file event, or a reanalysis + // the user asked for) and embeds what that pass finds: it stays. The + // retry used to take its place, and the file was not read again. + // The queued item carries the result along in case it is skipped. + if (item.cachedAnalysis && !existing.cachedAnalysis) { + existing.embedFallback = embedFallbackOf(item); + return; + } + keepAnalysisRequest(existing, item); this.analysisQueue[existingIndex] = item; this._scheduleQueuePersist(); return; @@ -2107,7 +2181,7 @@ class SmartFolderWatcher { stored.provisional === true && (Number(stored.provisionalRetries) || 0) < PROVISIONAL_MAX_RETRIES && isCapabilityFallback(stored) && - (await this._capabilityNowAvailable(filePath)) + (await this._capabilityNowAvailable(filePath, stored)) ) { return true; } @@ -2128,7 +2202,7 @@ class SmartFolderWatcher { } /** - * Run one analysis under the global timeout AND abort the work when the + * Run one analysis under its timeout (_analysisTimeoutMs) AND abort the work when the * timeout fires. Before this the timed-out promise kept running (pinning a * worker for the full OCR/LLM call) while the item was re-queued behind it * (F-196 / K-07). @@ -2142,7 +2216,7 @@ class SmartFolderWatcher { try { return await withTimeout( this._analyzeFile(item, controller.signal), - TIMEOUTS.GLOBAL_ANALYSIS || 10 * 60 * 1000, + this._analysisTimeoutMs(item?.filePath), `SmartFolderWatcher analyze ${item?.filePath}` ); } catch (error) { @@ -2153,6 +2227,44 @@ class SmartFolderWatcher { } } + /** + * The longest the analysis of one file may take. A recording is + * transcribed in one piece, and on the CPU while the text model has the + * GPU: an hour of audio outlasts the ten minutes a document or an image + * gets. It was aborted at ten minutes, retried from the start and given up + * on. A recording gets what a Discover run allows one. + * @private + * @param {string} [filePath] + * @returns {number} + */ + _analysisTimeoutMs(filePath) { + const toMediaAnalyzer = + typeof filePath === 'string' && + chooseAnalyzerForFile(filePath, { + hasMediaAnalyzer: typeof this.analyzeMediaFile === 'function' + }) === 'media'; + return toMediaAnalyzer + ? TIMEOUTS.BATCH_MEDIA_QUIET_MAX || 3 * 60 * 60 * 1000 + : TIMEOUTS.GLOBAL_ANALYSIS || 10 * 60 * 1000; + } + + /** + * Whether a path has gone from the disk. Only a definite "not found" says + * so: any other failure to stat it (a share that dropped, access denied) + * is left to the code that works with the file. + * @private + * @param {string} filePath + * @returns {Promise} + */ + async _goneFromDisk(filePath) { + try { + await fs.stat(filePath); + return false; + } catch (error) { + return isNotFoundError(error); + } + } + /** * Resolve the in-process AI service (overridable in tests). * @private @@ -2174,9 +2286,10 @@ class SmartFolderWatcher { * files costs one lookup, not one per file. * @private * @param {string} filePath + * @param {Record} [stored] - the provisional history row * @returns {Promise} */ - async _capabilityNowAvailable(filePath) { + async _capabilityNowAvailable(filePath, stored) { const now = Date.now(); const cache = this._capabilityProbeCache; let probe = cache && now - cache.at < 60000 ? cache : null; @@ -2212,7 +2325,12 @@ class SmartFolderWatcher { // Audio/video fall back because Whisper is missing, not the text model. // Probing the text model retried every skipped video while Whisper was // still absent, spent the retry budget, and never retried once it arrived. - if (isMediaPath(filePath)) return probe.whisper; + // A transcript the text model gave no answer for is the exception: + // Whisper is plainly there, and re-transcribing while the text model is + // still absent would spend both retries for nothing. + if (isMediaPath(filePath)) { + return stored?.fallbackReason === 'ai_analysis_failed' ? probe.text : probe.whisper; + } return probe.text; } @@ -2321,9 +2439,11 @@ class SmartFolderWatcher { try { // Find the first available item that is NOT currently being processed - // and is not waiting out a retry delay. Compare by canonical dedupKey so - // case-variant duplicates are caught. - const procKey = (/** @type {any} */ item) => item.dedupKey || item.filePath; + // and is not waiting out a retry delay. Compare by the canonical queue + // key so case-variant duplicates are caught. Items pushed straight onto + // the queue (Reanalyze all) carry no dedupKey; the key is derived from + // the path then, as _enqueueAnalysisItem and _analyzeFile derive it. + const procKey = (/** @type {any} */ item) => this._queueItemKey(item); const isRunnable = this._makeRunnableCheck(); let firstAvailableIndex = this.analysisQueue.findIndex(isRunnable); @@ -2381,10 +2501,24 @@ class SmartFolderWatcher { llamaService = null; } + // ...but only when some image in it will reach the model. Entering + // unloads the text and embedding models and starts the vision + // runtime, and leaving loads the text model again: about ten seconds + // of model swapping, which a batch of items _analyzeFile then drops + // (analyzed since they were queued, excluded, deleted) spent for + // nothing. + let batchNeedsVision = false; + for (const item of batch) { + if (await this._imageItemNeedsVision(item)) { + batchNeedsVision = true; + break; + } + } + // Exit only a batch mode this run entered. Exiting after a failed // enter dropped another owner's ref and ended its batch mid-run. let visionBatchEntered = false; - if (llamaService) { + if (llamaService && batchNeedsVision) { try { await llamaService.enterVisionBatchMode(); visionBatchEntered = true; @@ -2422,8 +2556,17 @@ class SmartFolderWatcher { const handedBack = []; for (const waiting of rest) { const newer = queuedByKey.get(procKey(waiting)); - if (newer) keepReanalysisRequest(waiting, newer); - else handedBack.push(waiting); + if (!newer) { + handedBack.push(waiting); + } else if (newer.cachedAnalysis && !waiting.cachedAnalysis) { + // An embedding retry gives way to a pass still to come, + // as in _enqueueAnalysisItem: the waiting item takes its + // place in the queue. + waiting.embedFallback = embedFallbackOf(newer); + this.analysisQueue[this.analysisQueue.indexOf(newer)] = waiting; + } else { + keepAnalysisRequest(waiting, newer); + } this._inFlightItems.delete(procKey(waiting)); } this.analysisQueue.unshift(...handedBack); @@ -2543,6 +2686,35 @@ class SmartFolderWatcher { } } + /** + * Whether an image item taken into a batch will reach the vision model. + * Answers the cheap questions _analyzeFile asks before it analyzes, without + * its side effects; _analyzeFile still asks them itself. Anything that + * cannot be told counts as needing the model. + * @private + * @param {any} item + * @returns {Promise} + */ + async _imageItemNeedsVision(item) { + try { + // An embedding retry reuses the analysis it already has. + if (item.cachedAnalysis) return false; + if (!this._isExclusionExempt(item) && this._matchUserExclusion(item.filePath)) return false; + if (item.eventType === 'reanalyze') return true; + if (isUserAnalysisInFlight(item.filePath)) return false; + let stats; + try { + stats = await fs.stat(item.filePath); + } catch (error) { + if (isNotFoundError(error)) return false; + throw error; + } + return await this._needsAnalysis(item.filePath, item.mtime, stats); + } catch { + return true; + } + } + /** * Predicate for queued items _processQueue may take now: not still being * analyzed by an earlier pass and not waiting out a retry delay. @@ -2551,8 +2723,7 @@ class SmartFolderWatcher { */ _makeRunnableCheck() { const now = Date.now(); - return (item) => - !this.processingFiles.has(item.dedupKey || item.filePath) && !(item.notBefore > now); + return (item) => !this.processingFiles.has(this._queueItemKey(item)) && !(item.notBefore > now); } /** @@ -2752,6 +2923,14 @@ class SmartFolderWatcher { // Verify file still exists and capture stats for reuse below const fileStats = await fs.stat(filePath); + // Only a pass that reads the file: an embedding retry reads nothing, + // so no change event during it is its own echo, and the result it + // carries belongs to the file as its own pass found it. + if (!item.cachedAnalysis) { + const passStats = { mtimeMs: fileStats.mtimeMs, size: fileStats.size }; + this._analysisStartStats.set(processingKey, passStats); + item._passStats = passStats; + } // Ask the history again, now that the file's turn has come. The answer // from when it was queued can be minutes old: the queue is held while a @@ -2764,14 +2943,23 @@ class SmartFolderWatcher { // already has its analysis in the history. if (!isReanalyze && !item.cachedAnalysis) { const stillNeedsAnalysis = await this._needsAnalysis(filePath, item.mtime, fileStats); - if (!stillNeedsAnalysis) { + if (!stillNeedsAnalysis && !item.embedFallback) { logger.debug('[SMART-FOLDER-WATCHER] Already analyzed since it was queued; skipping', { filePath, eventType }); return; } + if (!stillNeedsAnalysis) { + // No pass to run, but an embedding retry gave way to this item + // (embedFallbackOf): it becomes that retry. + item.cachedAnalysis = item.embedFallback.analysis; + item._passStats = item.embedFallback.passStats; + item.retryCount = item.embedFallback.retryCount; + } } + // A pass of this item's own embeds what it finds. + delete item.embedFallback; logger.info('[SMART-FOLDER-WATCHER] Analyzing file:', filePath, { applyNaming: applyNaming !== false, @@ -2841,6 +3029,19 @@ class SmartFolderWatcher { if (this._isStopping) return; + // Nothing holds the file open during the model pass, so it can be + // renamed, moved or deleted meanwhile. The result then describes a path + // that is gone. Recorded with the size and date read before the pass, + // it left a history entry, a notification and learning feedback for a + // file that is not there. A renamed file arrives as a new one and is + // analyzed under its new name. + if (result && (await this._goneFromDisk(filePath))) { + logger.info('[SMART-FOLDER-WATCHER] File gone during its analysis; result dropped', { + filePath + }); + return; + } + if (result) { const analysis = result.analysis || result; const originalFileName = path.basename(filePath); @@ -2858,6 +3059,19 @@ class SmartFolderWatcher { // notification, learning feedback) since they already ran on the original pass. // Only re-attempt the embedding. if (isEmbeddingRetry) { + // The file changed since the pass this result is from: embedded + // now, it would replace what the pass for the new content stored + // (or will store) with the old content's vector and chunks. + const passStats = item._passStats; + if ( + passStats && + (passStats.mtimeMs !== fileStats.mtimeMs || passStats.size !== fileStats.size) + ) { + logger.debug('[SMART-FOLDER-WATCHER] File changed since its analysis; retry dropped', { + filePath + }); + return; + } try { // Embedding retry should only retry embedding and then stop. // Do not run analysis side effects or stats updates. @@ -3193,6 +3407,7 @@ class SmartFolderWatcher { } } finally { this.processingFiles.delete(processingKey); + this._analysisStartStats.delete(processingKey); } } diff --git a/src/main/services/VisionService.js b/src/main/services/VisionService.js index 45a05f5..8ef48e9 100644 --- a/src/main/services/VisionService.js +++ b/src/main/services/VisionService.js @@ -24,7 +24,7 @@ const { createLogger } = require('../../shared/logger'); const { createSingletonHelpers } = require('../../shared/singletonFactory'); const { resolveRuntimePath } = require('../utils/runtimePaths'); const { TIMEOUTS } = require('../../shared/performanceConstants'); -const { delay, createBackgroundWorkTracker } = require('../../shared/promiseUtils'); +const { delay, createBackgroundWorkTracker, isTimeoutAbort } = require('../../shared/promiseUtils'); const { isVisionDecodePressureError } = require('./visionErrorClassification'); const { getInstance: getGPUMonitor } = require('./GPUMonitor'); const { resolveVisionRuntimeBackend } = require('../utils/llamaBackendSelector'); @@ -868,7 +868,7 @@ async function getAvailablePort() { } /** - * The caller gave up before the request was sent; nothing reached the runtime. + * The caller gave up, before the request was sent or while the runtime worked on it. * Named AbortError so LlamaResilience does not count it against the breaker. */ function createVisionAbortError() { @@ -968,8 +968,14 @@ async function requestJson( // signal forever. Reused AbortControllers across many requests would // accumulate listeners unbounded. cleanupSignal() runs in both // settle paths so the listener is always released. + // A caller that gave up (Stop, a closed window) says nothing about the + // runtime, so it must not count against the vision breaker; an analysis + // that ran out of time does. Same message either way: the catch in + // _analyzeImageWithRuntime restarts the runtime on it. abortListener = () => { - req.destroy(new Error('Vision request aborted')); + req.destroy( + isTimeoutAbort(signal) ? new Error('Vision request aborted') : createVisionAbortError() + ); }; signal.addEventListener('abort', abortListener, { once: true }); } @@ -2201,8 +2207,19 @@ class VisionService { if (response?.json?.error) { const baseMessage = response.json.error.message || 'Vision runtime error'; + // The stderr excerpt rides beside the message, never in it: see + // isVisionRuntimeDecodePressure. + const runtimeError = /** @type {Error & { visionRuntimeHint?: string }} */ ( + new Error(baseMessage) + ); const decodePressureHint = this._extractDecodePressureHint(); - throw new Error(`${baseMessage}${decodePressureHint}`); + if (decodePressureHint) { + runtimeError.visionRuntimeHint = decodePressureHint; + logger.debug('[VisionService] Runtime stderr when the request failed', { + hint: decodePressureHint + }); + } + throw runtimeError; } const content = response?.json?.choices?.[0]?.message?.content; diff --git a/src/main/services/WhisperService.js b/src/main/services/WhisperService.js index ef67189..74278b3 100644 --- a/src/main/services/WhisperService.js +++ b/src/main/services/WhisperService.js @@ -2183,8 +2183,8 @@ class WhisperService extends EventEmitter { } /** - * Whether to run Whisper on the CPU because the text model holds a - * dedicated GPU that cannot also fit it. Never on unified memory, where CPU + * Whether to run Whisper on the CPU because the text model holds, or is + * being loaded onto, a dedicated GPU that cannot also fit it. Never on unified memory, where CPU * and GPU share the same budget and moving Whisper would gain nothing. * @param {string} modelPath * @returns {Promise} @@ -2192,7 +2192,12 @@ class WhisperService extends EventEmitter { */ async _shouldRunOnCpuBesideText(modelPath) { const manager = this._getMemoryManager(); - if (!manager?.getLoadedContext?.('text')) return false; + // Loaded or being loaded: a load in progress has reserved the GPU already. + const textHoldsGpu = + typeof manager?.isLoadedOrLoading === 'function' + ? manager.isLoadedOrLoading('text') + : Boolean(manager?.getLoadedContext?.('text')); + if (!manager || !textHoldsGpu) return false; if (typeof manager.canFitExternalLoad !== 'function') return false; const gpu = /** @type {any} */ (this._gpuInfo); if (gpu?.type === 'metal' || gpu?.isAppleSilicon || gpu?.unifiedMemory) return false; diff --git a/src/main/services/organization/suggestionRanker.js b/src/main/services/organization/suggestionRanker.js index 8eb1412..d6af1ac 100644 --- a/src/main/services/organization/suggestionRanker.js +++ b/src/main/services/organization/suggestionRanker.js @@ -97,6 +97,10 @@ function calculateConfidence(suggestion) { confidence = Math.min(1.0, confidence * 1.3); } + // `score` is also the ranking key, and the cluster boost multiplies it past + // 1. Callers read anything above 1 as a percentage (1.24 became "1%"). + confidence = Math.min(1.0, confidence); + return Math.round(confidence * 100) / 100; } diff --git a/src/main/services/visionErrorClassification.js b/src/main/services/visionErrorClassification.js index b616599..b2b7a91 100644 --- a/src/main/services/visionErrorClassification.js +++ b/src/main/services/visionErrorClassification.js @@ -37,6 +37,22 @@ function isVisionDecodePressureError(/** @type {any} */ errorLike) { return VISION_DECODE_PRESSURE_PATTERNS.some((pattern) => message.includes(pattern)); } +/** + * Decode pressure as the vision runtime reports it: in the server's own + * message, or in the stderr excerpt VisionService attaches to the error + * (`visionRuntimeHint`). The excerpt stays out of the message because the + * retry and model-availability classifiers match substrings of it, and the + * runtime's load banner ("CUDA0", "projector") is in that excerpt. + * @param {any} errorLike + * @returns {boolean} + */ +function isVisionRuntimeDecodePressure(errorLike) { + return ( + isVisionDecodePressureError(errorLike) || + isVisionDecodePressureError(String(errorLike?.visionRuntimeHint || '')) + ); +} + function isVisionInputDataError(/** @type {any} */ errorLike) { const message = normalizeErrorMessage(errorLike); if (isVisionDecodePressureError(message)) { @@ -55,6 +71,7 @@ function classifyVisionError(/** @type {any} */ errorLike) { } module.exports = { + isVisionRuntimeDecodePressure, VISION_DECODE_PRESSURE_PATTERNS, VISION_INPUT_DATA_PATTERNS, normalizeErrorMessage, diff --git a/src/main/utils/llmJsonRepair.js b/src/main/utils/llmJsonRepair.js index b840863..f6a5d50 100644 --- a/src/main/utils/llmJsonRepair.js +++ b/src/main/utils/llmJsonRepair.js @@ -106,7 +106,7 @@ ${trimmed}`; signal: abortController.signal }), JSON_REPAIR_TIMEOUT_MS, - `JSON repair timed out after ${JSON_REPAIR_TIMEOUT_MS}ms` + 'JSON repair' ); if (result?.response) { @@ -187,7 +187,7 @@ Rules: signal: abortController.signal }), PROSE_EXTRACTION_TIMEOUT_MS, - `Prose extraction timed out after ${PROSE_EXTRACTION_TIMEOUT_MS}ms` + 'Prose extraction' ); if (result?.response) { diff --git a/src/renderer/components/organize/TargetFolderList.jsx b/src/renderer/components/organize/TargetFolderList.jsx index b0463b9..51e8d04 100644 --- a/src/renderer/components/organize/TargetFolderList.jsx +++ b/src/renderer/components/organize/TargetFolderList.jsx @@ -18,7 +18,7 @@ const VIRTUALIZATION_THRESHOLD = 20; export const unquoteDescription = (text) => String(text || '') .trim() - .replace(/^[s"'“”‘’]+|[s"'“”‘’]+$/g, ''); + .replace(/^[\s"'“”‘’]+|[\s"'“”‘’]+$/g, ''); const getListHeight = (folderCount, viewportHeight) => { const maxFraction = folderCount <= 10 ? 0.35 : 0.45; diff --git a/src/renderer/components/search/ResultRow.jsx b/src/renderer/components/search/ResultRow.jsx index 18dd3b2..0e9b0b3 100644 --- a/src/renderer/components/search/ResultRow.jsx +++ b/src/renderer/components/search/ResultRow.jsx @@ -7,6 +7,7 @@ import { Text } from '../ui/Typography'; import normalizeList from '../../utils/normalizeList'; import { normalizeConfidence } from '../../utils/scoreUtils'; import { getMetadataPath, getMetadataName } from './utils'; +import { toLocalCalendarMs } from '../../../shared/contentDateSanity'; const ResultRow = memo(function ResultRow({ result, @@ -29,9 +30,10 @@ const ResultRow = memo(function ResultRow({ // Format date and confidence // The vector DB stores the date under 'documentDate'; 'date' is a legacy alias const rawDate = result?.metadata?.documentDate || result?.metadata?.date; - const parsedDate = rawDate ? new Date(rawDate) : null; - const dateStr = - parsedDate && !Number.isNaN(parsedDate.getTime()) ? parsedDate.toLocaleDateString() : ''; + // A document date is a day ("2024-05-05"); new Date() reads that as UTC + // midnight and the row showed the day before west of Greenwich. + const dateMs = toLocalCalendarMs(rawDate); + const dateStr = dateMs === null ? '' : new Date(dateMs).toLocaleDateString(); const confidence = result?.metadata?.confidence || 0; diff --git a/src/renderer/phases/discover/useAnalysis.js b/src/renderer/phases/discover/useAnalysis.js index 9d55005..5c4354b 100644 --- a/src/renderer/phases/discover/useAnalysis.js +++ b/src/renderer/phases/discover/useAnalysis.js @@ -126,6 +126,10 @@ function isMediaFilePath(filePath) { return MEDIA_EXTENSIONS.has(filePath.slice(dot).toLowerCase()); } +// What one file gets on the per-file path: under the time a run may go +// without progress, so the file is what fails, not the run. +const PER_FILE_LIMIT_MS = Math.min(TIMEOUTS.AI_ANALYSIS_LONG, TIMEOUTS.ANALYSIS_LOCK - 5000); + /** * A run with audio or video always takes the batch path. One recording is * many minutes of work; the per-file path gives a file 5 minutes, then @@ -1057,7 +1061,9 @@ export function useAnalysis(options = {}) { return { started: false, reason: 'superseded' }; } - // Safety timeout - store in ref for proper cleanup + // The one check for a run that stopped making progress (a second one, + // after twice this long, could never fire first and was the only one + // that told the user). Stored in a ref for cleanup. const scheduleLockTimeoutCheck = () => { lockTimeoutRef.current = setTimeout(() => { if (!isActiveRun()) { @@ -1083,6 +1089,12 @@ export function useAnalysis(options = {}) { }); resetAnalysisState('Analysis lock timeout'); lockTimeoutRef.current = null; + addNotification( + 'Analysis was stopped because it stopped making progress. Unfinished files are ready to analyze again.', + 'warning', + 5000, + 'analysis-timeout' + ); }, TIMEOUTS.ANALYSIS_LOCK); }; scheduleLockTimeoutCheck(); @@ -1154,22 +1166,17 @@ export function useAnalysis(options = {}) { }, TIMEOUTS.HEARTBEAT_INTERVAL); heartbeatIntervalRef.current = heartbeat; - // Global analysis watchdog: - // - inactivity timeout: reset only when there is no progress for GLOBAL_ANALYSIS window - // - hard cap timeout: absolute upper bound to avoid runaway background loops + // Global analysis watchdog: an absolute upper bound on one run, to + // avoid runaway background loops. A run that stops making progress is + // ended by the lock check above. const analysisStartedAt = Date.now(); const fallbackPerFileMs = 45000; const maxHardCapMs = TIMEOUTS.ANALYSIS_RUN_MAX; const baselineHardCapMs = Math.max(TIMEOUTS.GLOBAL_ANALYSIS * 6, 60 * 60 * 1000); let hardCapMs = baselineHardCapMs; let hardCapLabel = `${Math.round(hardCapMs / 60000)} min`; - const windowLabel = `${Math.round(TIMEOUTS.GLOBAL_ANALYSIS / 60000)} min`; - const stopAnalysisForTimeout = (/** @type {any} */ reason) => { - logger.warn('Global analysis timeout', { - reason, - windowLabel, - hardCapLabel - }); + const stopAnalysisForTimeout = () => { + logger.warn('Global analysis timeout', { hardCapLabel }); captureCancelledBatchSnapshot(runId); if (analysisRunIdRef.current === runId) { analysisRunIdRef.current += 1; @@ -1189,10 +1196,7 @@ export function useAnalysis(options = {}) { clearTimeout(lockTimeoutRef.current); lockTimeoutRef.current = null; } - const timeoutMessage = - reason === 'hard_cap' - ? `Analysis exceeded the safety window (${hardCapLabel}). Consider reducing file count per run.` - : `Analysis was stopped after no progress for ${windowLabel}.`; + const timeoutMessage = `Analysis exceeded the safety window (${hardCapLabel}). Consider reducing file count per run.`; startTransition(() => { flushPendingResults(true); pendingFilesRef.current = []; @@ -1211,10 +1215,6 @@ export function useAnalysis(options = {}) { return; } const elapsedMs = Date.now() - analysisStartedAt; - const lastProgressAt = Number.isFinite(lastProgressAtRef.current) - ? lastProgressAtRef.current - : 0; - const inactivityMs = lastProgressAt ? Date.now() - lastProgressAt : Infinity; const state = /** @type {any} */ (store.getState()); const progressState = state.analysis.analysisProgress || analysisProgressRef.current || {}; @@ -1228,12 +1228,7 @@ export function useAnalysis(options = {}) { } if (elapsedMs >= hardCapMs) { analysisTimeoutRef.current = null; - queueMicrotask(() => stopAnalysisForTimeout('hard_cap')); - return; - } - if (inactivityMs >= TIMEOUTS.GLOBAL_ANALYSIS) { - analysisTimeoutRef.current = null; - queueMicrotask(() => stopAnalysisForTimeout('inactivity')); + queueMicrotask(() => stopAnalysisForTimeout()); return; } scheduleGlobalTimeoutCheck(); @@ -1330,7 +1325,7 @@ export function useAnalysis(options = {}) { logger.info('Configured global analysis watchdog', { fileCount: uniqueFiles.length, concurrency, - inactivityWindowMin: Math.round(TIMEOUTS.GLOBAL_ANALYSIS / 60000), + inactivityWindowMin: Math.round(TIMEOUTS.ANALYSIS_LOCK / 60000), hardCapMin: Math.round(hardCapMs / 60000) }); logger.info(`Starting analysis of ${uniqueFiles.length} files`); @@ -1624,10 +1619,14 @@ export function useAnalysis(options = {}) { modified: file.modified }; + // Counted from here, with a limit just under the run's own, a slow + // file fails first and the run goes on to the next. + lastProgressAtRef.current = Date.now(); + try { const analysis = await withTimeout( analyzeWithRetry(file.path, 1, abortSignal, namingSettings), - TIMEOUTS.AI_ANALYSIS_LONG, + PER_FILE_LIMIT_MS, `Analysis for ${fileName}` ); diff --git a/src/renderer/store/middleware/ipcMiddleware.js b/src/renderer/store/middleware/ipcMiddleware.js index e87b1ad..4ada22d 100644 --- a/src/renderer/store/middleware/ipcMiddleware.js +++ b/src/renderer/store/middleware/ipcMiddleware.js @@ -106,6 +106,20 @@ function isAnalysisProgressPayload(payload) { return type === 'batch_analyze' || type === 'analyze'; } +/** + * A batch report that arrives while no analysis is running was sent before + * main heard of the Stop, or by a batch that nothing here waits for. Written + * to the store, its counts read as a paused analysis in Discover. + * + * @param {*} payload + * @returns {boolean} + */ +function isBatchProgressWithoutAnalysis(payload) { + if (String(payload?.type || '').toLowerCase() !== 'batch_analyze') return false; + const analysis = storeRef?.getState?.()?.analysis; + return Boolean(analysis) && analysis.isAnalyzing === false; +} + function dedupePathsByCanonicalValue(/** @type {any} */ paths) { const canonicalSeen = new Set(); const deduped = []; @@ -400,7 +414,10 @@ const ipcMiddleware = (/** @type {any} */ store) => { (/** @type {any} */ data) => { const { valid, data: validatedData } = validateIncomingEvent('operation-progress', data); if (!valid) return; - if (isAnalysisProgressPayload(validatedData)) { + if ( + isAnalysisProgressPayload(validatedData) && + !isBatchProgressWithoutAnalysis(validatedData) + ) { dispatchThrottledProgressToStore(normalizeAnalysisProgressPayload(validatedData)); } // Re-dispatch every event as a DOM CustomEvent: runBatchPath's progress diff --git a/src/shared/analysisProvenance.js b/src/shared/analysisProvenance.js index e597c51..51d258e 100644 --- a/src/shared/analysisProvenance.js +++ b/src/shared/analysisProvenance.js @@ -52,6 +52,8 @@ const CAPABILITY_REASON_PATTERN = const PROVISIONAL_MAX_RETRIES = 2; /** + * `provisional` is how a history row says it: the row keeps that stamp and + * the reason, not the `isFallback` flags the fresh result carried. * @param {Record | null | undefined} analysis * @returns {boolean} */ @@ -60,6 +62,7 @@ function isFallbackAnalysis(analysis) { return ( analysis._isFallback === true || analysis.isFallback === true || + analysis.provisional === true || analysis.category === 'error' || FALLBACK_METHODS.has(String(analysis.extractionMethod || '')) ); diff --git a/src/shared/contentDateSanity.js b/src/shared/contentDateSanity.js index 8594580..8b31602 100644 --- a/src/shared/contentDateSanity.js +++ b/src/shared/contentDateSanity.js @@ -19,6 +19,9 @@ const CONTENT_DATE_MIN_YEAR = 1900; const CONTENT_DATE_FUTURE_SLACK_YEARS = 1; +// A year is exactly four digits: "20255-01-01" is the year 20255, not 2025. +const LEADING_YEAR_RE = /^(\d{4})(?!\d)/; + /** * Whether an ISO-leading date string ("YYYY-MM-DD...") carries a plausible * content year. Purely lexical on the year — calendar validity is the ISO @@ -28,9 +31,10 @@ const CONTENT_DATE_FUTURE_SLACK_YEARS = 1; * @returns {boolean} */ function isPlausibleContentDate(iso, now = new Date()) { - if (typeof iso !== 'string' || iso.length < 4) return false; - const year = Number(iso.slice(0, 4)); - if (!Number.isInteger(year)) return false; + if (typeof iso !== 'string') return false; + const leading = iso.match(LEADING_YEAR_RE); + if (!leading) return false; + const year = Number(leading[1]); return ( year >= CONTENT_DATE_MIN_YEAR && year <= now.getUTCFullYear() + CONTENT_DATE_FUTURE_SLACK_YEARS ); @@ -64,14 +68,43 @@ function toLocalCalendarDay(ms) { return `${d.getFullYear()}-${pad(d.getMonth() + 1)}-${pad(d.getDate())}`; } +/** + * Epoch ms of a stored date, for the local calendar: the local date + * formatters, and comparison with file times. A date-only value names a + * calendar day and is read as local midnight of that day. Date.parse reads + * it as UTC midnight, which is the evening before west of Greenwich, so a + * document dated "2024-05-05" was shown as May 4. + * @param {any} value + * @returns {number|null} + */ +function toLocalCalendarMs(value) { + if (value === null || value === undefined || value === '') return null; + const text = String(value).trim(); + const dayOnly = text.match(/^(\d{4})-(\d{2})-(\d{2})$/); + if (dayOnly) { + const year = Number(dayOnly[1]); + const local = new Date(year, Number(dayOnly[2]) - 1, Number(dayOnly[3])); + // The constructor reads the years 0-99 as 1900-1999. + if (year < 100) local.setFullYear(year); + const localMs = local.getTime(); + return Number.isFinite(localMs) ? localMs : null; + } + const ms = Date.parse(text); + return Number.isFinite(ms) ? ms : null; +} + /** * The calendar day a written date names (model output such as "2024-05-05" * or "May 5, 2024"), as YYYY-MM-DD, or null when it does not parse. * * A leading YYYY-MM-DD is kept as written, whatever time and offset follow - * it, and so is a value that is only YYYY or YYYY-MM. Anything else ("May 5, - * 2024", "2024 May 5") is parsed by V8 as LOCAL time, so its local day is - * the day written; toISOString moved it back a day east of Greenwich. + * it, and so is a value that is only YYYY or YYYY-MM, with or without a "Z" + * after it. Anything else ("May 5, 2024", "2024 May 5") is parsed by V8 as + * LOCAL time, so its local day is the day written; toISOString moved it back + * a day east of Greenwich. + * + * A year outside 0000-9999 is not a day anyone wrote ("20255-01-01" parses + * as the year 20255) and gives null. * @param {any} value * @returns {string|null} */ @@ -79,15 +112,26 @@ function toWrittenCalendarDay(value) { if (typeof value !== 'string' && typeof value !== 'number' && !(value instanceof Date)) { return null; } + // A model that answers {"date": 2024} wrote a year. new Date(2024) is 2024 + // milliseconds after 1970. + if (typeof value === 'number') { + return Number.isInteger(value) && value >= 1000 && value <= 9999 ? `${value}-01-01` : null; + } const parsed = new Date(value); if (Number.isNaN(parsed.getTime())) return null; - if (typeof value !== 'string') return toLocalCalendarDay(parsed.getTime()); - const written = value.trim().match(/^(\d{4})(?:-(\d{2})(?:-(\d{2})(?:[T\s].*)?)?)?$/); - if (!written) return toLocalCalendarDay(parsed.getTime()); - // Through Date.UTC so "2024-02-31" rolls over the way Date itself reads it. - const day = new Date( - Date.UTC(Number(written[1]), Number(written[2] || 1) - 1, Number(written[3] || 1)) - ); + const written = + typeof value === 'string' + ? value.trim().match(/^(\d{4})(?:-(\d{2})(?:-(\d{2})(?:[T\s].*)?)?)?Z?$/i) + : null; + if (!written) { + const year = parsed.getFullYear(); + return year >= 0 && year <= 9999 ? toLocalCalendarDay(parsed.getTime()) : null; + } + // Through the UTC setter so "2024-02-31" rolls over the way Date itself + // reads it. Not Date.UTC, which reads the years 0-99 as 1900-1999 and + // would turn a misread "0024-05-05" into a plausible 1924. + const day = new Date(0); + day.setUTCFullYear(Number(written[1]), Number(written[2] || 1) - 1, Number(written[3] || 1)); return Number.isNaN(day.getTime()) ? null : day.toISOString().split('T')[0]; } @@ -97,5 +141,6 @@ module.exports = { isPlausibleContentDate, isIsoDateOnly, toLocalCalendarDay, + toLocalCalendarMs, toWrittenCalendarDay }; diff --git a/src/shared/performanceConstants.js b/src/shared/performanceConstants.js index e07c113..0d0f9c1 100644 --- a/src/shared/performanceConstants.js +++ b/src/shared/performanceConstants.js @@ -122,8 +122,13 @@ const TIMEOUTS = { // GPU process exits before the sticky .gpu-fallback flag is cleared. GPU_FALLBACK_STABLE_RUN: 30000, // Analysis lock and monitoring timeouts - ANALYSIS_LOCK: 5 * 60 * 1000, // 5 minutes - forces lock release if analysis hangs - GLOBAL_ANALYSIS: 10 * 60 * 1000, // 10 minutes - max total analysis time + // A Discover run with no progress for this long is stopped and its lock + // released; one file on the per-file path gets 5 s less. + ANALYSIS_LOCK: 5 * 60 * 1000, + // What the smart-folder watcher allows one document or image. Not a limit + // on a Discover run: there it is the base of the run cap (6x, at least an + // hour, up to ANALYSIS_RUN_MAX) and how often that cap is checked. + GLOBAL_ANALYSIS: 10 * 60 * 1000, HEARTBEAT_INTERVAL: 30000, // 30 seconds - progress heartbeat during analysis // Longest a Discover analysis run may take before it is stopped as runaway. ANALYSIS_RUN_MAX: 6 * 60 * 60 * 1000, @@ -131,6 +136,8 @@ const TIMEOUTS = { // still be reported as alive. Each is longer than what main allows one // file: text extraction plus the model call for a document or image; a // recording of up to 4 hours, transcribed in one piece, for audio/video. + // BATCH_MEDIA_QUIET_MAX is also what the smart-folder watcher allows one + // recording (SmartFolderWatcher._analysisTimeoutMs). BATCH_FILE_QUIET_MAX: 15 * 60 * 1000, BATCH_MEDIA_QUIET_MAX: 3 * 60 * 60 * 1000, STALE_ACTIVITY: 15 * 60 * 1000, // 15 minutes - activity considered stale diff --git a/src/shared/promiseUtils.js b/src/shared/promiseUtils.js index 46e84d5..df6f606 100644 --- a/src/shared/promiseUtils.js +++ b/src/shared/promiseUtils.js @@ -147,6 +147,40 @@ function withTimeout(fnOrPromise, timeoutMs, operationName = 'Operation') { }; } +// The reason main aborts an invoke with when the renderer's limit on it ran +// out (ipcAbortRegistry's default reason). +const IPC_TIMEOUT_REASON = 'ipc-timeout'; + +/** + * The reason a signal is aborted with when the time ran out, so the work can + * tell that apart from a caller that gave up. Same name and message as the + * default reason: work that rethrows it is classified as it was before. + * @returns {Error & { timedOut?: boolean }} + */ +function createTimeoutAbortReason() { + const reason = /** @type {Error & { timedOut?: boolean }} */ ( + new Error('This operation was aborted') + ); + reason.name = 'AbortError'; + reason.timedOut = true; + return reason; +} + +/** + * True when the signal was aborted because the time ran out (by + * withAbortableTimeout, AbortSignal.timeout or the renderer's limit on an + * invoke), false when its caller gave up. + * @param {AbortSignal|null|undefined} signal + * @returns {boolean} + */ +function isTimeoutAbort(signal) { + if (!signal?.aborted) return false; + const reason = /** @type {any} */ (signal.reason); + return ( + reason?.timedOut === true || reason?.name === 'TimeoutError' || reason === IPC_TIMEOUT_REASON + ); +} + /** * Execute a promise with timeout and AbortController support. * Enhanced version of withTimeout that provides an AbortController signal @@ -155,6 +189,7 @@ function withTimeout(fnOrPromise, timeoutMs, operationName = 'Operation') { * @param {(abortController: AbortController) => Promise} fn - Function that receives AbortController and returns a Promise * @param {number} timeoutMs - Timeout in milliseconds * @param {string} [operationName='Operation'] - Name of the operation for error messages + * @param {{ signal?: AbortSignal }} [options] - `signal`: the caller's own signal; aborting it cancels the work * @returns {Promise<*>} Result of the promise * @throws {Error} If the operation times out or the promise rejects * @@ -165,13 +200,6 @@ function withTimeout(fnOrPromise, timeoutMs, operationName = 'Operation') { * 'API fetch' * ); */ -/** - * @param {(abortController: AbortController) => Promise} fn - * @param {number} timeoutMs - * @param {string} [operationName] - * @param {{ signal?: AbortSignal }} [options] - * @returns {Promise} - */ async function withAbortableTimeout(fn, timeoutMs, operationName = 'Operation', options = {}) { const externalSignal = options.signal || null; const abortController = new AbortController(); @@ -195,7 +223,7 @@ async function withAbortableTimeout(fn, timeoutMs, operationName = 'Operation', const timeoutPromise = new Promise((_, reject) => { timeoutId = setTimeout(() => { - abortController.abort(); + abortController.abort(createTimeoutAbortReason()); reject(new Error(`${operationName} timed out after ${timeoutMs}ms`)); }, timeoutMs); // Allow process to exit if this timer is the only thing keeping it alive @@ -208,7 +236,11 @@ async function withAbortableTimeout(fn, timeoutMs, operationName = 'Operation', // the timeout. if (externalSignal) { onExternalAbort = () => { - abortController.abort(); + // Out of time is passed on as out of time: the work treats that + // differently from a caller that gave up. + abortController.abort( + isTimeoutAbort(externalSignal) ? createTimeoutAbortReason() : undefined + ); reject(makeCancelledError()); }; externalSignal.addEventListener('abort', onExternalAbort, { once: true }); @@ -913,6 +945,7 @@ module.exports = { throwIfAborted, withTimeout, withAbortableTimeout, + isTimeoutAbort, createTimeoutRace, // Retry diff --git a/test/ClusteringService.test.js b/test/ClusteringService.test.js index 2d0881c..540ffd0 100644 --- a/test/ClusteringService.test.js +++ b/test/ClusteringService.test.js @@ -17,6 +17,12 @@ jest.mock('../src/shared/logger', () => { }); // Mock llama utils +// The real function, wrapped so a test can see the service use it. +jest.mock('../src/shared/contentDateSanity', () => { + const actual = jest.requireActual('../src/shared/contentDateSanity'); + return { ...actual, toLocalCalendarMs: jest.fn(actual.toLocalCalendarMs) }; +}); + jest.mock('../src/main/llamaUtils', () => ({ getTextModel: jest.fn(() => 'qwen3:0.6b') })); @@ -590,6 +596,75 @@ describe('ClusteringService', () => { expect(graphData[0].memberMeta).toHaveLength(2); }); + test('a document date is a day: the range starts and ends at local midnight', () => { + // Parsed as UTC midnight, the range of a cluster dated May 5 to June 1 + // was labelled "May 4 – May 31" west of Greenwich. + service.clusters = [ + { + id: 0, + members: [ + { + id: 'file:first', + embedding: [1, 0], + metadata: { filePath: 'C:\\Docs\\first.pdf', documentDate: '2024-05-05' } + }, + { + id: 'file:last', + embedding: [1, 0.02], + metadata: { filePath: 'C:\\Docs\\last.pdf', documentDate: '2024-06-01' } + } + ] + } + ]; + service.centroids = [[1, 0]]; + + const { timeRange } = service.getClustersForGraph()[0]; + + expect(timeRange.startMs).toBe(new Date(2024, 4, 5).getTime()); + expect(timeRange.endMs).toBe(new Date(2024, 5, 1).getTime()); + expect(new Date(timeRange.start).getDate()).toBe(5); + expect(new Date(timeRange.end).getDate()).toBe(1); + }); + + // Where the zone is UTC, as on CI, Date.parse gives the test above the + // same instants. The ones the helper is made to return here come from no + // parse of the stored values. + test('the range comes from the calendar-day helper, in every time zone', () => { + const { toLocalCalendarMs } = require('../src/shared/contentDateSanity'); + const days = { + '2024-05-05': new Date(2031, 0, 15, 12).getTime(), + '2024-06-01': new Date(2031, 2, 20, 12).getTime() + }; + toLocalCalendarMs.mockImplementation((value) => days[value] ?? null); + service.clusters = [ + { + id: 0, + members: [ + { + id: 'file:first', + embedding: [1, 0], + metadata: { filePath: 'C:\\Docs\\first.pdf', documentDate: '2024-05-05' } + }, + { + id: 'file:last', + embedding: [1, 0.02], + metadata: { filePath: 'C:\\Docs\\last.pdf', documentDate: '2024-06-01' } + } + ] + } + ]; + service.centroids = [[1, 0]]; + + try { + const { timeRange } = service.getClustersForGraph()[0]; + expect(timeRange.startMs).toBe(days['2024-05-05']); + expect(timeRange.endMs).toBe(days['2024-06-01']); + } finally { + const actual = jest.requireActual('../src/shared/contentDateSanity'); + toLocalCalendarMs.mockImplementation(actual.toLocalCalendarMs); + } + }); + test('derives member path and folder from metadata.filePath fallback', () => { service.clusters = [ { diff --git a/test/LlamaResilience.test.js b/test/LlamaResilience.test.js index 22c3eff..e68ed6c 100644 --- a/test/LlamaResilience.test.js +++ b/test/LlamaResilience.test.js @@ -216,6 +216,25 @@ describe('LlamaResilience', () => { expect(breaker.getStats().failedRequests).toBe(0); }); + // What llama-server answers for bytes it cannot decode: the file is at + // fault, and five of them in a row used to shut vision off for 300 s. + test('an image the runtime could not load does not open the circuit breaker', async () => { + withRetry.mockImplementation((operation) => operation); + const rejectedOp = jest + .fn() + .mockRejectedValue(new Error('Failed to load image or audio file')); + + for (let i = 0; i < 5; i++) { + await expect( + withLlamaResilience(rejectedOp, { modelType: 'vision', allowCPUFallback: false }) + ).rejects.toThrow(/failed to load image/i); + } + + const breaker = _circuitBreakers.get('vision'); + expect(breaker.getState()).toBe('CLOSED'); + expect(breaker.getStats().failedRequests).toBe(0); + }); + test('getLlamaCircuitSummary lists breaker states and the open ones', () => { expect(getLlamaCircuitSummary()).toEqual({ states: {}, open: [] }); diff --git a/test/LlamaService.inference.test.js b/test/LlamaService.inference.test.js index 9245456..e800650 100644 --- a/test/LlamaService.inference.test.js +++ b/test/LlamaService.inference.test.js @@ -377,16 +377,21 @@ describe('LlamaService – inference methods', () => { describe('in vision batch mode', () => { // A text load inside the batch can evict the runtime and leave the text // model resident. Respawning vision on top of it raced into held VRAM. - function batchImageService({ textResident, visionAlive }) { + function batchImageService({ textResident, textLoading = false, visionAlive }) { const service = createTestService(); service._coordinator = { withModel: jest.fn((_, fn) => fn()) }; service._visionProjectorStatus = { required: false, available: true, projectorPath: null }; service._resolveGpuLayersForVisionServer = jest.fn().mockResolvedValue(999); service._releaseMemoryForVisionRuntime = jest.fn().mockResolvedValue(undefined); + service._batchTextDrainWaitMs = 40; + service._batchTextDrainSliceMs = 10; service._visionBatchMode = true; mockModelMemoryManager.getLoadedContext = jest.fn((type) => type === 'text' && textResident ? mockContext : null ); + mockModelMemoryManager.isLoadedOrLoading = jest.fn( + (type) => type === 'text' && Boolean(textResident || textLoading) + ); mockVisionService.isAlive = jest.fn(() => visionAlive); return service; } @@ -399,7 +404,9 @@ describe('LlamaService – inference methods', () => { afterEach(() => { delete mockModelMemoryManager.getLoadedContext; + delete mockModelMemoryManager.isLoadedOrLoading; delete mockVisionService.isAlive; + mockModelMemoryManager.unloadModel = jest.fn().mockResolvedValue(undefined); }); test('frees the text model a batch text load left behind before respawning vision', async () => { @@ -419,6 +426,96 @@ describe('LlamaService – inference methods', () => { await service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }); expect(service._releaseMemoryForVisionRuntime).not.toHaveBeenCalled(); }); + + // The text model takes seconds to load. An image that arrived in that + // window saw no text model in memory and respawned the runtime on top + // of the load. + test('makes room again once a text load in progress has ended', async () => { + const service = batchImageService({ + textResident: false, + textLoading: true, + visionAlive: false + }); + await service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }); + expect(service._releaseMemoryForVisionRuntime).toHaveBeenCalledWith('batch'); + }); + + // The load ends with its request still running on the model, so the + // first attempt finds the text model pinned and refuses. + const budgetRefusal = () => + Object.assign(new Error('Cannot start the vision runtime (batch)'), { + code: 'MODEL_MEMORY_BUDGET_EXCEEDED' + }); + + test('waits for the text request to end when the text model is pinned', async () => { + const service = batchImageService({ textResident: true, visionAlive: false }); + service._releaseMemoryForVisionRuntime + .mockRejectedValueOnce(budgetRefusal()) + .mockResolvedValue(undefined); + mockModelMemoryManager.unloadModel = jest + .fn() + .mockResolvedValueOnce(false) + .mockResolvedValue(true); + + await expect( + service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }) + ).resolves.toBeDefined(); + + expect(mockModelMemoryManager.unloadModel).toHaveBeenCalledWith( + 'text', + expect.objectContaining({ waitMs: 10 }) + ); + expect(service._releaseMemoryForVisionRuntime).toHaveBeenCalledTimes(2); + }); + + test('gives the refusal back when the text request outlasts the wait', async () => { + const service = batchImageService({ textResident: true, visionAlive: false }); + service._releaseMemoryForVisionRuntime.mockRejectedValue(budgetRefusal()); + mockModelMemoryManager.unloadModel = jest.fn(async () => { + await new Promise((resolve) => setTimeout(resolve, 10)); + return false; + }); + + await expect( + service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }) + ).rejects.toMatchObject({ code: 'MODEL_MEMORY_BUDGET_EXCEEDED' }); + expect(mockModelMemoryManager.unloadModel).toHaveBeenCalled(); + expect(service._releaseMemoryForVisionRuntime).toHaveBeenCalledTimes(1); + }); + + test('does not wait for a request that was cancelled', async () => { + const service = batchImageService({ textResident: true, visionAlive: false }); + service._releaseMemoryForVisionRuntime.mockRejectedValue(budgetRefusal()); + mockModelMemoryManager.unloadModel = jest.fn().mockResolvedValue(false); + const cancelled = new AbortController(); + cancelled.abort(); + + await expect( + service._releaseMemoryForBatchVisionRespawn(cancelled.signal) + ).rejects.toMatchObject({ code: 'MODEL_MEMORY_BUDGET_EXCEEDED' }); + expect(mockModelMemoryManager.unloadModel).not.toHaveBeenCalled(); + }); + + test('a failure that is not about memory is not waited on', async () => { + const service = batchImageService({ textResident: true, visionAlive: false }); + service._releaseMemoryForVisionRuntime.mockRejectedValue(new Error('manager broke')); + mockModelMemoryManager.unloadModel = jest.fn().mockResolvedValue(true); + + await expect(service._releaseMemoryForBatchVisionRespawn()).rejects.toThrow( + 'manager broke' + ); + expect(mockModelMemoryManager.unloadModel).not.toHaveBeenCalled(); + }); + + test('a text load in progress does not disturb a runtime that is up', async () => { + const service = batchImageService({ + textResident: false, + textLoading: true, + visionAlive: true + }); + await service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }); + expect(service._releaseMemoryForVisionRuntime).not.toHaveBeenCalled(); + }); }); test('uses unique vision operation IDs across same-millisecond calls', async () => { diff --git a/test/LlamaService.visionBatchPin.test.js b/test/LlamaService.visionBatchPin.test.js index feea1aa..42ade72 100644 --- a/test/LlamaService.visionBatchPin.test.js +++ b/test/LlamaService.visionBatchPin.test.js @@ -106,6 +106,32 @@ describe('LlamaService vision batch keeps the runtime', () => { expect(service._loadOptionsBesideVisionBatch('embedding')).toBeUndefined(); }); + // A text load inside the batch evicted the runtime: declared beside a + // runtime that is not there, the load evicted the text model instead. + test('an embedding load is CPU-only beside the text model that replaced the runtime', async () => { + await service.enterVisionBatchMode(); + mockManager.isLoadedOrLoading = jest.fn((type) => type === 'text'); + try { + expect(service._loadOptionsBesideVisionBatch('embedding')).toEqual({ + gpuLayersOverride: 0, + besideResident: 'text', + keepBeside: true, + cpuByDesign: true, + forVisionBatch: true + }); + // Still the batch's CPU model: unloaded when the batch ends. + expect(service._embeddingCpuForBatch).toBe(true); + + // The runtime is up (or starting) again: beside the runtime as before. + mockManager.isLoadedOrLoading = jest.fn(() => true); + expect(service._loadOptionsBesideVisionBatch('embedding').besideResident).toBe( + 'vision-runtime' + ); + } finally { + delete mockManager.isLoadedOrLoading; + } + }); + test('outside a batch an embedding load gets no special options', () => { expect(service._loadOptionsBesideVisionBatch('embedding')).toBeUndefined(); }); diff --git a/test/ModelMemoryManager.pendingLoads.test.js b/test/ModelMemoryManager.pendingLoads.test.js index e409bb4..df0b481 100644 --- a/test/ModelMemoryManager.pendingLoads.test.js +++ b/test/ModelMemoryManager.pendingLoads.test.js @@ -266,3 +266,61 @@ describe('reserveLoad — an external load in progress (the vision runtime start expect(manager.canRunOptionalLoad('text')).toBe(false); }); }); + +describe('a model whose own estimate is larger than the budget', () => { + // A 7B model on a 6 GB card: 5.8 GiB against a 4.8 GiB budget. No amount + // of eviction makes it fit, so it loads once nothing else holds memory. + function oversized() { + const made = makeManager({ budgetBytes: 4.8 * GiB }); + made.manager._modelSizeEstimates.text = 5.8 * GiB; + made.manager._modelSizeEstimates.embedding = 0.2 * GiB; + return made; + } + + test('loads as soon as the model that was in use is gone, not when the wait runs out', async () => { + const { manager, llamaService } = oversized(); + manager._pinnedResidentWaitMs = 5000; + await manager.ensureModelLoaded('embedding'); + manager.acquireRef('embedding'); + + const startedAt = Date.now(); + const loading = manager.ensureModelLoaded('text'); + await tick(30); + manager.releaseRef('embedding'); + await loading; + + expect(Date.now() - startedAt).toBeLessThan(2000); + expect(manager._loadedModels.has('embedding')).toBe(false); + expect(llamaService._loadModel).toHaveBeenCalledWith('text', expect.anything()); + }); + + test('optional work may use it once it is the only thing in memory', async () => { + const { manager } = oversized(); + await manager.ensureModelLoaded('text'); + + expect(manager.canRunOptionalLoad('text')).toBe(true); + + manager.reserveLoad('vision-runtime', 5 * GiB); + expect(manager.canRunOptionalLoad('text')).toBe(false); + }); + + test('a load in progress is counted at the size found in the model file', async () => { + const { manager, llamaService } = makeManager({ budgetBytes: 4.8 * GiB }); + manager._modelSizeEstimates.embedding = 0.2 * GiB; + const gate = deferred(); + llamaService._loadModel.mockImplementation(async () => { + // LlamaService._loadModel does this right after it stats the file. + manager.updateModelSizeEstimate('text', (5.8 * GiB) / 1.3); + await gate.promise; + return {}; + }); + + const loading = manager.ensureModelLoaded('text'); + await tick(); + // 4 GiB (the default) + 0.2 would have fitted in 4.8. + expect(manager.canLoadModel('embedding')).toBe(false); + + gate.resolve(); + await loading; + }); +}); diff --git a/test/ModelMemoryManager.test.js b/test/ModelMemoryManager.test.js index 7d79959..5dd8ce1 100644 --- a/test/ModelMemoryManager.test.js +++ b/test/ModelMemoryManager.test.js @@ -34,7 +34,7 @@ describe('ModelMemoryManager', () => { expect(manager.canRunOptionalLoad('embedding')).toBe(false); }); - test('canRunOptionalLoad allows resident optional call only with inference headroom', () => { + test('canRunOptionalLoad allows a resident beside another model only with inference headroom', () => { const llamaService = { _models: {}, _contexts: {}, _loadModel: jest.fn() }; const manager = new ModelMemoryManager(llamaService); jest.spyOn(manager, '_refreshMemoryBudget').mockImplementation(() => {}); @@ -46,6 +46,8 @@ describe('ModelMemoryManager', () => { lastUsed: Date.now(), sizeBytes: 10 * GB }); + // Alone in memory it may always be used; the headroom is for a neighbour. + manager._loadedModels.set('embedding', { context: {}, lastUsed: Date.now(), sizeBytes: GB }); manager._currentMemoryUsage = manager._maxMemoryUsage - Math.floor(headroom384 / 2); expect(manager.canRunOptionalLoad('text')).toBe(false); diff --git a/test/SmartFolderWatcher.coverage.test.js b/test/SmartFolderWatcher.coverage.test.js index 71c2306..933289e 100644 --- a/test/SmartFolderWatcher.coverage.test.js +++ b/test/SmartFolderWatcher.coverage.test.js @@ -1816,7 +1816,54 @@ describe('SmartFolderWatcher', () => { }); watcher._capabilityNowAvailable = jest.fn().mockResolvedValue(true); await expect(watcher._needsAnalysis('/docs/a.pdf', 1000, stats)).resolves.toBe(true); - expect(watcher._capabilityNowAvailable).toHaveBeenCalledWith('/docs/a.pdf'); + expect(watcher._capabilityNowAvailable).toHaveBeenCalledWith( + '/docs/a.pdf', + expect.objectContaining({ provisional: true }) + ); + }); + + // A transcript the text model failed on is stored with its real + // extraction method; only `provisional` and the reason mark it. + const transcribedOnly = (provisionalRetries) => ({ + provisional: true, + provisionalRetries, + category: 'audio', + extractionMethod: 'whisper-transcription', + fallbackReason: 'ai_analysis_failed' + }); + + test('retries a transcript the text model gave no answer for', async () => { + armHistory(transcribedOnly(0)); + watcher._capabilityNowAvailable = jest.fn().mockResolvedValue(true); + await expect(watcher._needsAnalysis('/media/talk.mp3', 1000, stats)).resolves.toBe(true); + }); + + test('stops retrying that transcript after the budget is spent', async () => { + armHistory(transcribedOnly(2)); + watcher._capabilityNowAvailable = jest.fn().mockResolvedValue(true); + await expect(watcher._needsAnalysis('/media/talk.mp3', 1000, stats)).resolves.toBe(false); + }); + + test('_capabilityNowAvailable asks for the text model when a transcript is waiting on it', async () => { + const llama = { + getConfig: jest.fn().mockResolvedValue({ textModel: 'mistral-7b.gguf' }), + listModels: jest.fn().mockResolvedValue([]) + }; + watcher._getLlamaService = () => llama; + watcher._whisperAvailable = jest.fn().mockResolvedValue(true); + watcher._capabilityProbeCache = null; + + // Whisper is there, which is how the transcript exists; the text model is not. + await expect( + watcher._capabilityNowAvailable('/media/talk.mp3', transcribedOnly(0)) + ).resolves.toBe(false); + // A media file skipped for want of Whisper still asks for Whisper. + await expect( + watcher._capabilityNowAvailable('/media/talk.mp3', { + provisional: true, + extractionMethod: 'media-skipped-no-whisper' + }) + ).resolves.toBe(true); }); test('does not retry while the model is still missing', async () => { diff --git a/test/SmartFolderWatcher.embeddingRetryFreshness.test.js b/test/SmartFolderWatcher.embeddingRetryFreshness.test.js new file mode 100644 index 0000000..410a057 --- /dev/null +++ b/test/SmartFolderWatcher.embeddingRetryFreshness.test.js @@ -0,0 +1,158 @@ +/** + * @jest-environment node + * + * An embedding retry carries the result of a pass that is over and only + * embeds it again. Two ways that went wrong: + * + * - the retry gave way to an item already queued for the file, and that item + * was then skipped as already analyzed, so nothing embedded the file; + * - the file changed after the pass, and the retry embedded the old result + * over whatever the newer pass had stored. + */ +jest.mock('fs', () => jest.requireActual('fs')); +jest.mock('fs/promises', () => jest.requireActual('fs/promises')); +jest.mock('os', () => jest.requireActual('os')); +jest.mock('chokidar', () => ({ + watch: jest.fn(() => ({ + on: jest.fn().mockReturnThis(), + once: jest.fn(), + close: jest.fn().mockResolvedValue() + })) +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const SmartFolderWatcher = require('../src/main/services/SmartFolderWatcher'); + +let root; +let file; +let watcher; +let duringAnalysis; + +const RESULT = { + analysis: { category: 'Finance', keywords: ['invoice'], summary: 'An invoice', confidence: 90 } +}; + +beforeEach(() => { + root = fs.mkdtempSync(path.join(os.tmpdir(), 'sfw-fresh-')); + file = path.join(root, 'invoice.pdf'); + fs.writeFileSync(file, 'synthetic'); + duringAnalysis = () => {}; + watcher = new SmartFolderWatcher({ + getSmartFolders: () => [{ id: 'f1', name: 'Finance', path: root }], + analysisHistoryService: { + recordAnalysis: jest.fn().mockResolvedValue(undefined), + getAnalysisByPath: jest.fn().mockResolvedValue(null), + getAnalysisByHash: jest.fn().mockResolvedValue(null) + }, + settingsService: { load: jest.fn().mockResolvedValue({}) }, + notificationService: { + notifyFileAnalyzed: jest.fn().mockResolvedValue(undefined), + notifyLowConfidence: jest.fn().mockResolvedValue(undefined) + }, + analyzeDocumentFile: jest.fn(async () => { + await duringAnalysis(); + return RESULT; + }), + analyzeImageFile: jest.fn() + }); + watcher.isRunning = true; + watcher.watchedPaths = new Set([root]); + // The embedding after the first pass fails; later ones work. + watcher._embedAnalyzedFile = jest + .fn() + .mockRejectedValueOnce(new Error('embedding model busy')) + .mockResolvedValue(undefined); + watcher._recordLearningFeedback = jest.fn().mockResolvedValue(undefined); +}); + +afterEach(() => { + watcher._isStopping = true; + fs.rmSync(root, { recursive: true, force: true }); +}); + +const settle = () => new Promise((resolve) => setImmediate(resolve)); + +async function firstPass() { + await watcher._analyzeFile({ filePath: file, eventType: 'add', mtime: Date.now() }); + await settle(); +} + +const takeQueued = () => watcher.analysisQueue.splice(0); + +describe('an embedding retry that gave way to a queued item', () => { + // A scan reaches the file while its pass is running and queues it again. + const scanDuringPass = () => { + duringAnalysis = () => + watcher._enqueueAnalysisItem({ filePath: file, mtime: Date.now(), eventType: 'scan' }); + }; + + test('is embedded when that item turns out to need no analysis', async () => { + scanDuringPass(); + await firstPass(); + + const queued = takeQueued(); + expect(queued).toEqual([expect.objectContaining({ eventType: 'scan' })]); + expect(queued[0].cachedAnalysis).toBeUndefined(); + + // The history has the file by now. + watcher._needsAnalysis = jest.fn().mockResolvedValue(false); + await watcher._analyzeFile(queued[0]); + + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(1); + expect(watcher._embedAnalyzedFile).toHaveBeenCalledTimes(2); + expect(watcher._embedAnalyzedFile).toHaveBeenLastCalledWith(file, RESULT); + expect(watcher.analysisHistoryService.recordAnalysis).toHaveBeenCalledTimes(1); + }); + + test('is left alone when that item runs a pass of its own', async () => { + scanDuringPass(); + await firstPass(); + const [queued] = takeQueued(); + duringAnalysis = () => {}; + + watcher._needsAnalysis = jest.fn().mockResolvedValue(true); + await watcher._analyzeFile(queued); + await settle(); + + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(2); + // Once after each pass; the result of the first is not embedded a third time. + expect(watcher._embedAnalyzedFile).toHaveBeenCalledTimes(2); + expect(watcher.analysisQueue).toEqual([]); + }); +}); + +describe('an embedding retry for a file that changed since its pass', () => { + test('embeds nothing: the result is of the content before', async () => { + await firstPass(); + const [retry] = takeQueued(); + expect(retry.cachedAnalysis).toBe(RESULT); + + fs.writeFileSync(file, 'synthetic, edited after the pass'); + await watcher._analyzeFile(retry); + + expect(watcher._embedAnalyzedFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisQueue).toEqual([]); + }); + + test('a file that did not change is embedded as before', async () => { + await firstPass(); + const [retry] = takeQueued(); + + await watcher._analyzeFile(retry); + + expect(watcher._embedAnalyzedFile).toHaveBeenCalledTimes(2); + expect(watcher._embedAnalyzedFile).toHaveBeenLastCalledWith(file, RESULT); + }); +}); diff --git a/test/SmartFolderWatcher.embeddingRetryReplace.test.js b/test/SmartFolderWatcher.embeddingRetryReplace.test.js new file mode 100644 index 0000000..f29ae61 --- /dev/null +++ b/test/SmartFolderWatcher.embeddingRetryReplace.test.js @@ -0,0 +1,213 @@ +/** + * @jest-environment node + * + * An embedding retry is a queue item that carries the result of the analysis + * before it (`cachedAnalysis`) and only embeds that again. When one took the + * place of a queued item that was still to run the model (a reanalysis the + * user asked for, a newer change event), the request was lost: the item kept + * the old result, so the file was never read again. + */ +jest.mock('fs', () => jest.requireActual('fs')); +jest.mock('fs/promises', () => jest.requireActual('fs/promises')); +jest.mock('os', () => jest.requireActual('os')); +jest.mock('chokidar', () => ({ + watch: jest.fn(() => ({ + on: jest.fn().mockReturnThis(), + once: jest.fn(), + close: jest.fn().mockResolvedValue() + })) +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const SmartFolderWatcher = require('../src/main/services/SmartFolderWatcher'); +const { + claimUserAnalysis, + _resetUserAnalysisInFlight +} = require('../src/main/analysis/userAnalysisInFlight'); + +let root; +let file; +let watcher; + +const OLD_RESULT = { analysis: { category: 'Finance', keywords: ['old'], summary: 'Old text' } }; + +beforeEach(() => { + _resetUserAnalysisInFlight(); + root = fs.mkdtempSync(path.join(os.tmpdir(), 'sfw-retry-')); + file = path.join(root, 'invoice.pdf'); + fs.writeFileSync(file, 'synthetic'); + watcher = new SmartFolderWatcher({ + getSmartFolders: () => [{ id: 'f1', name: 'Finance', path: root }], + analysisHistoryService: { + recordAnalysis: jest.fn().mockResolvedValue(undefined), + getAnalysisByPath: jest.fn().mockResolvedValue(null), + getAnalysisByHash: jest.fn().mockResolvedValue(null) + }, + settingsService: { load: jest.fn().mockResolvedValue({}) }, + analyzeDocumentFile: jest.fn().mockRejectedValue(new Error('stop after analyzer call')), + analyzeImageFile: jest.fn() + }); + watcher.isRunning = true; + watcher.watchedPaths = new Set([root]); + watcher._embedAnalyzedFile = jest.fn().mockResolvedValue(undefined); +}); + +afterEach(() => { + watcher._isStopping = true; + clearTimeout(watcher._userAnalysisHoldTimer); + _resetUserAnalysisInFlight(); + fs.rmSync(root, { recursive: true, force: true }); +}); + +const embeddingRetry = (filePath, extra = {}) => ({ + filePath, + mtime: 1000, + eventType: 'add', + retryCount: 1, + cachedAnalysis: OLD_RESULT, + ...extra +}); + +describe('an embedding retry and a queued request for the same file', () => { + test('a reanalysis the user asked for still runs the model', async () => { + watcher._enqueueAnalysisItem({ filePath: file, eventType: 'reanalyze', applyNaming: true }); + watcher._enqueueAnalysisItem(embeddingRetry(file)); + + expect(watcher.analysisQueue).toHaveLength(1); + const [queued] = watcher.analysisQueue; + expect(queued).toEqual(expect.objectContaining({ eventType: 'reanalyze', applyNaming: true })); + expect(queued.cachedAnalysis).toBeUndefined(); + + await watcher._analyzeFile(queued).catch(() => {}); + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(1); + }); + + test('a second reanalysis is not replaced by the retry of the first', () => { + watcher._enqueueAnalysisItem({ filePath: file, eventType: 'reanalyze', applyNaming: false }); + watcher._enqueueAnalysisItem(embeddingRetry(file, { eventType: 'reanalyze' })); + + expect(watcher.analysisQueue).toHaveLength(1); + expect(watcher.analysisQueue[0].cachedAnalysis).toBeUndefined(); + expect(watcher.analysisQueue[0].applyNaming).toBe(false); + }); + + test('a queued change event is not replaced by the retry of the pass before it', async () => { + watcher._enqueueAnalysisItem({ filePath: file, mtime: 2000, eventType: 'change' }); + watcher._enqueueAnalysisItem(embeddingRetry(file)); + + expect(watcher.analysisQueue).toHaveLength(1); + const [queued] = watcher.analysisQueue; + expect(queued).toEqual(expect.objectContaining({ eventType: 'change', mtime: 2000 })); + expect(queued.cachedAnalysis).toBeUndefined(); + + await watcher._analyzeFile(queued).catch(() => {}); + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(1); + }); + + test('a retry still replaces the retry before it', () => { + watcher._enqueueAnalysisItem(embeddingRetry(file)); + watcher._enqueueAnalysisItem(embeddingRetry(file, { retryCount: 2 })); + + expect(watcher.analysisQueue).toHaveLength(1); + expect(watcher.analysisQueue[0]).toEqual( + expect.objectContaining({ retryCount: 2, cachedAnalysis: OLD_RESULT }) + ); + }); + + test('a change event still replaces a queued retry and runs the model', () => { + watcher._enqueueAnalysisItem(embeddingRetry(file)); + watcher._enqueueAnalysisItem({ filePath: file, mtime: 2000, eventType: 'change' }); + + expect(watcher.analysisQueue).toHaveLength(1); + expect(watcher.analysisQueue[0].eventType).toBe('change'); + expect(watcher.analysisQueue[0].cachedAnalysis).toBeUndefined(); + }); + + test('a retry with nothing queued for the file is queued as one', () => { + watcher._enqueueAnalysisItem(embeddingRetry(file)); + + expect(watcher.analysisQueue).toEqual([ + expect.objectContaining({ filePath: file, cachedAnalysis: OLD_RESULT }) + ]); + }); +}); + +describe('an image batch handed back when a Discover analysis starts', () => { + // The images of a batch are off the queue while it runs. A retry for one of + // them can be queued meanwhile; when the batch is handed back, that queued + // item is the one that stays. + function batchOfTwo(secondItem) { + const first = path.join(root, 'a.png'); + const second = path.join(root, 'b.png'); + watcher._imageItemNeedsVision = jest.fn().mockResolvedValue(false); + watcher._analyzeFile = jest.fn(async () => { + // The embedding of an earlier pass over the second image fails now... + watcher._enqueueAnalysisItem(embeddingRetry(second)); + // ...and the user starts a Discover analysis. + claimUserAnalysis(path.join(root, 'discover-file.pdf')); + }); + watcher.analysisQueue.push( + { filePath: first, mtime: 1, eventType: 'add' }, + { filePath: second, ...secondItem } + ); + return second; + } + + test('a reanalysis waiting in the batch is not turned into an embedding retry', async () => { + const second = batchOfTwo({ mtime: 1, eventType: 'reanalyze', applyNaming: true }); + + await watcher._processQueue(); + + expect(watcher._analyzeFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisQueue).toHaveLength(1); + const [queued] = watcher.analysisQueue; + expect(queued).toEqual( + expect.objectContaining({ filePath: second, eventType: 'reanalyze', applyNaming: true }) + ); + expect(queued.cachedAnalysis).toBeUndefined(); + }); + + test('a change event waiting in the batch is not turned into one either', async () => { + const second = batchOfTwo({ mtime: 2000, eventType: 'change' }); + + await watcher._processQueue(); + + expect(watcher._analyzeFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisQueue).toHaveLength(1); + const [queued] = watcher.analysisQueue; + // The waiting item itself, not the retry with its result taken off: that + // one ran as the 'add' of the pass before, with a retry already spent. + expect(queued).toEqual( + expect.objectContaining({ filePath: second, eventType: 'change', mtime: 2000 }) + ); + expect(queued.cachedAnalysis).toBeUndefined(); + expect(queued.retryCount).toBeUndefined(); + }); +}); + +describe('an item put on the queue without a key (Reanalyze all)', () => { + // The analysis holds the file under its normalized path. The check for + // "is this file being analyzed" looked the raw path up instead, so a second + // item for the file was started beside the first. + test('is not started while an analysis of the same file is running', () => { + const item = { filePath: file, mtime: 1, eventType: 'reanalyze' }; + watcher.processingFiles.add(watcher._queueItemKey(item)); + + expect(watcher._makeRunnableCheck()(item)).toBe(false); + + watcher.processingFiles.clear(); + expect(watcher._makeRunnableCheck()(item)).toBe(true); + }); +}); diff --git a/test/SmartFolderWatcher.mediaTimeout.test.js b/test/SmartFolderWatcher.mediaTimeout.test.js new file mode 100644 index 0000000..93f17f7 --- /dev/null +++ b/test/SmartFolderWatcher.mediaTimeout.test.js @@ -0,0 +1,108 @@ +/** + * @jest-environment node + * + * The watcher gave every file ten minutes. A recording is transcribed in one + * piece, and on the CPU while the text model has the GPU, so an hour of audio + * takes longer than that: it was aborted, started again from the beginning on + * each retry, and given up on. A Discover run allows a recording three hours. + */ +jest.mock('chokidar', () => ({ + watch: jest.fn(() => ({ + on: jest.fn().mockReturnThis(), + once: jest.fn(), + close: jest.fn().mockResolvedValue() + })) +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const SmartFolderWatcher = require('../src/main/services/SmartFolderWatcher'); +const { TIMEOUTS } = require('../src/shared/performanceConstants'); + +const MINUTE = 60 * 1000; + +function makeWatcher({ analyzeMediaFile = jest.fn() } = {}) { + const watcher = new SmartFolderWatcher({ + getSmartFolders: () => [], + analysisHistoryService: {}, + settingsService: { load: jest.fn().mockResolvedValue({}) }, + analyzeDocumentFile: jest.fn(), + analyzeImageFile: jest.fn(), + analyzeMediaFile + }); + // An analysis that never ends, as a long transcription looks to the timer. + watcher._analyzeFile = jest.fn(() => new Promise(() => {})); + return watcher; +} + +/** Runs the item and reports whether it was timed out after `ms`. */ +async function timedOutAfter(watcher, filePath, ms) { + let outcome = 'running'; + watcher._analyzeWithTimeout({ filePath }).catch(() => { + outcome = 'timed out'; + }); + await jest.advanceTimersByTimeAsync(ms); + return outcome; +} + +describe('how long the watcher lets one file take', () => { + beforeEach(() => { + jest.useFakeTimers(); + }); + + afterEach(() => { + jest.useRealTimers(); + }); + + test.each(['C:\\Watched\\meeting.mp3', 'C:\\Watched\\lecture.mp4', 'C:\\Watched\\memo.WAV'])( + 'a recording (%s) is still running after two hours', + async (filePath) => { + expect(await timedOutAfter(makeWatcher(), filePath, 120 * MINUTE)).toBe('running'); + } + ); + + test('a recording is stopped once the three hours are over', async () => { + const watcher = makeWatcher(); + + expect(await timedOutAfter(watcher, 'C:\\Watched\\meeting.mp3', 181 * MINUTE)).toBe( + 'timed out' + ); + // The signal the analysis was given is aborted, as for any timeout. + expect(watcher._analyzeFile.mock.calls[0][1].aborted).toBe(true); + }); + + test.each(['C:\\Watched\\invoice.pdf', 'C:\\Watched\\scan.png'])( + 'a document or an image (%s) keeps its ten minutes', + async (filePath) => { + const watcher = makeWatcher(); + + expect(await timedOutAfter(watcher, filePath, 9 * MINUTE)).toBe('running'); + await jest.advanceTimersByTimeAsync(2 * MINUTE); + expect(watcher._analyzeFile.mock.calls[0][1].aborted).toBe(true); + } + ); + + test('without a media analyzer a recording keeps the document limit', async () => { + const watcher = makeWatcher({ analyzeMediaFile: null }); + + expect(await timedOutAfter(watcher, 'C:\\Watched\\meeting.mp3', 11 * MINUTE)).toBe('timed out'); + }); + + test('the limits are the shared ones', () => { + const watcher = makeWatcher(); + + expect(watcher._analysisTimeoutMs('C:\\Watched\\meeting.mp3')).toBe( + TIMEOUTS.BATCH_MEDIA_QUIET_MAX + ); + expect(watcher._analysisTimeoutMs('C:\\Watched\\invoice.pdf')).toBe(TIMEOUTS.GLOBAL_ANALYSIS); + expect(watcher._analysisTimeoutMs(undefined)).toBe(TIMEOUTS.GLOBAL_ANALYSIS); + }); +}); diff --git a/test/SmartFolderWatcher.readEcho.test.js b/test/SmartFolderWatcher.readEcho.test.js new file mode 100644 index 0000000..7c30b1a --- /dev/null +++ b/test/SmartFolderWatcher.readEcho.test.js @@ -0,0 +1,151 @@ +/** + * @jest-environment node + * + * Reading a file can raise a change event for it. On NTFS the first read in + * an hour rewrites the last-access time, Windows reports a change, and + * chokidar 6 passes it on although mtime and size are what they were. The + * event reaches the watcher a few seconds into its own analysis of the file, + * before the history has it, so every file the watcher analyzed was queued a + * second time (and, for an image, cost a vision batch that analyzed nothing). + */ +jest.mock('fs', () => jest.requireActual('fs')); +jest.mock('fs/promises', () => jest.requireActual('fs/promises')); +jest.mock('os', () => jest.requireActual('os')); +jest.mock('chokidar', () => ({ + watch: jest.fn(() => ({ + on: jest.fn().mockReturnThis(), + once: jest.fn(), + close: jest.fn().mockResolvedValue() + })) +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const SmartFolderWatcher = require('../src/main/services/SmartFolderWatcher'); + +let root; +let file; + +beforeEach(() => { + root = fs.mkdtempSync(path.join(os.tmpdir(), 'sfw-echo-')); + file = path.join(root, 'report.pdf'); + fs.writeFileSync(file, 'synthetic'); +}); + +afterEach(() => { + fs.rmSync(root, { recursive: true, force: true }); +}); + +/** + * A watcher whose analyzer runs `duringAnalysis` (the moment the change event + * arrives) and then fails, which ends _analyzeFile without the history ever + * getting the file: the state the event finds in a live run. + */ +function makeWatcher(duringAnalysis) { + const watcher = new SmartFolderWatcher({ + getSmartFolders: () => [{ id: 'f1', name: 'Finance', path: root }], + analysisHistoryService: { + recordAnalysis: jest.fn().mockResolvedValue(undefined), + getAnalysisByPath: jest.fn().mockResolvedValue(null), + getAnalysisByHash: jest.fn().mockResolvedValue(null) + }, + settingsService: { load: jest.fn().mockResolvedValue({}) }, + analyzeDocumentFile: jest.fn(async () => { + await duringAnalysis(watcher); + throw new Error('stop after analyzer call'); + }), + analyzeImageFile: jest.fn() + }); + watcher.isRunning = true; + watcher.watchedPaths = new Set([root]); + return watcher; +} + +const changeEvent = (watcher) => + watcher._queueFileForAnalysis(file, Date.now(), 'change', undefined, undefined); + +const analyze = (watcher) => + watcher._analyzeFile({ filePath: file, eventType: 'add', mtime: Date.now() }).catch(() => {}); + +describe('SmartFolderWatcher and change events from its own read', () => { + test('a change event for a file it is analyzing, with mtime and size unchanged, is not queued', async () => { + const watcher = makeWatcher(changeEvent); + + await analyze(watcher); + + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisQueue).toEqual([]); + }); + + test('a file edited during its analysis is queued again', async () => { + const watcher = makeWatcher(async (w) => { + fs.writeFileSync(file, 'synthetic, edited while it was analyzed'); + await changeEvent(w); + }); + + await analyze(watcher); + + expect(watcher.analysisQueue).toEqual([ + expect.objectContaining({ filePath: file, eventType: 'change' }) + ]); + }); + + test('a rewrite of the same length during its analysis is queued again', async () => { + const watcher = makeWatcher(async (w) => { + fs.writeFileSync(file, 'SYNTHETIC'); + const later = new Date(Date.now() + 5000); + fs.utimesSync(file, later, later); + await changeEvent(w); + }); + + await analyze(watcher); + + expect(watcher.analysisQueue).toEqual([ + expect.objectContaining({ filePath: file, eventType: 'change' }) + ]); + }); + + // An embedding retry reads nothing, so no event during it is its echo. + // The edit here was saved before the retry began: the retry stats the file + // as edited, and the event for the edit arrives while it embeds. + test('a change event during an embedding retry is judged by the history', async () => { + const watcher = makeWatcher(async () => {}); + watcher._embedAnalyzedFile = jest.fn(() => changeEvent(watcher)); + + await watcher._analyzeFile({ + filePath: file, + eventType: 'add', + mtime: Date.now(), + retryCount: 1, + cachedAnalysis: { analysis: { category: 'Finance' } } + }); + + expect(watcher._embedAnalyzedFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisQueue).toEqual([ + expect.objectContaining({ filePath: file, eventType: 'change' }) + ]); + }); + + test('a change event after the analysis ended is judged by the history as before', async () => { + const watcher = makeWatcher(async () => {}); + + await analyze(watcher); + await changeEvent(watcher); + + // The analyzer failed, so the history has no entry: still to be analyzed. + expect(watcher.analysisQueue).toEqual([ + expect.objectContaining({ filePath: file, eventType: 'change' }) + ]); + }); +}); diff --git a/test/SmartFolderWatcher.vanishedFile.test.js b/test/SmartFolderWatcher.vanishedFile.test.js new file mode 100644 index 0000000..b398b33 --- /dev/null +++ b/test/SmartFolderWatcher.vanishedFile.test.js @@ -0,0 +1,155 @@ +/** + * @jest-environment node + * + * Nothing holds a file open while the model works on it, so it can be + * renamed, moved or deleted in that time. The watcher records the result with + * the size and date it read before the pass, so the record no longer touches + * the disk: a file that vanished during its analysis got a history entry, a + * "file analyzed" notification and learning feedback all the same. + */ +jest.mock('fs', () => jest.requireActual('fs')); +jest.mock('fs/promises', () => jest.requireActual('fs/promises')); +jest.mock('os', () => jest.requireActual('os')); +jest.mock('chokidar', () => ({ + watch: jest.fn(() => ({ + on: jest.fn().mockReturnThis(), + once: jest.fn(), + close: jest.fn().mockResolvedValue() + })) +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const SmartFolderWatcher = require('../src/main/services/SmartFolderWatcher'); + +let root; +let file; + +beforeEach(() => { + root = fs.mkdtempSync(path.join(os.tmpdir(), 'sfw-gone-')); + file = path.join(root, 'invoice.pdf'); + fs.writeFileSync(file, 'synthetic'); +}); + +afterEach(() => { + fs.rmSync(root, { recursive: true, force: true }); +}); + +const RESULT = { + analysis: { category: 'Finance', keywords: ['invoice'], summary: 'An invoice', confidence: 90 } +}; + +/** A watcher whose analyzer runs `duringAnalysis` and then returns a result. */ +function makeWatcher(duringAnalysis) { + const watcher = new SmartFolderWatcher({ + getSmartFolders: () => [{ id: 'f1', name: 'Finance', path: root }], + analysisHistoryService: { + recordAnalysis: jest.fn().mockResolvedValue(undefined), + getAnalysisByPath: jest.fn().mockResolvedValue(null), + getAnalysisByHash: jest.fn().mockResolvedValue(null) + }, + settingsService: { load: jest.fn().mockResolvedValue({}) }, + notificationService: { + notifyFileAnalyzed: jest.fn().mockResolvedValue(undefined), + notifyLowConfidence: jest.fn().mockResolvedValue(undefined) + }, + analyzeDocumentFile: jest.fn(async () => { + await duringAnalysis(); + return RESULT; + }), + analyzeImageFile: jest.fn() + }); + watcher.isRunning = true; + watcher.watchedPaths = new Set([root]); + watcher._embedAnalyzedFile = jest.fn().mockResolvedValue(undefined); + watcher._recordLearningFeedback = jest.fn().mockResolvedValue(undefined); + return watcher; +} + +const analyze = (watcher) => + watcher._analyzeFile({ filePath: file, eventType: 'add', mtime: Date.now() }); + +function expectNothingRecorded(watcher) { + expect(watcher.analyzeDocumentFile).toHaveBeenCalledTimes(1); + expect(watcher.analysisHistoryService.recordAnalysis).not.toHaveBeenCalled(); + expect(watcher.notificationService.notifyFileAnalyzed).not.toHaveBeenCalled(); + expect(watcher._embedAnalyzedFile).not.toHaveBeenCalled(); + expect(watcher._recordLearningFeedback).not.toHaveBeenCalled(); + expect(watcher.stats.filesAnalyzed).toBe(0); + expect(watcher.stats.errors).toBe(0); +} + +describe('SmartFolderWatcher and a file that vanishes during its analysis', () => { + test('a file deleted during the model pass is not recorded', async () => { + const watcher = makeWatcher(async () => fs.rmSync(file)); + + await analyze(watcher); + + expectNothingRecorded(watcher); + }); + + test('a file renamed during the model pass is not recorded under its old name', async () => { + const watcher = makeWatcher(async () => + fs.renameSync(file, path.join(root, 'invoice-2026.pdf')) + ); + + await analyze(watcher); + + expectNothingRecorded(watcher); + }); + + test('an embedding retry for a file that goes during it embeds nothing', async () => { + const watcher = makeWatcher(async () => {}); + // Gone after the retry found the file, before it embeds: the folder + // lookup is the one step in between. + const linkCheck = watcher._linkEscapeReason.bind(watcher); + let found = false; + watcher._linkEscapeReason = async (filePath) => { + const reason = await linkCheck(filePath); + found = true; + return reason; + }; + watcher.getSmartFolders = () => { + if (found) fs.rmSync(file, { force: true }); + return [{ id: 'f1', name: 'Finance', path: root }]; + }; + + await watcher._analyzeFile({ + filePath: file, + eventType: 'add', + retryCount: 1, + cachedAnalysis: RESULT + }); + + expect(fs.existsSync(file)).toBe(false); + expect(watcher._embedAnalyzedFile).not.toHaveBeenCalled(); + expect(watcher.analysisQueue).toEqual([]); + }); + + test('a file that is still there is recorded as before', async () => { + const watcher = makeWatcher(async () => {}); + const before = fs.statSync(file); + + await analyze(watcher); + + const { recordAnalysis } = watcher.analysisHistoryService; + expect(recordAnalysis).toHaveBeenCalledTimes(1); + expect(recordAnalysis.mock.calls[0][0]).toEqual( + expect.objectContaining({ size: before.size, lastModified: before.mtimeMs }) + ); + expect(watcher.notificationService.notifyFileAnalyzed).toHaveBeenCalledTimes(1); + expect(watcher._embedAnalyzedFile).toHaveBeenCalledWith(file, RESULT); + expect(watcher.stats.filesAnalyzed).toBe(1); + }); +}); diff --git a/test/SmartFolderWatcher.visionBatchOwner.test.js b/test/SmartFolderWatcher.visionBatchOwner.test.js index feb0957..ce65051 100644 --- a/test/SmartFolderWatcher.visionBatchOwner.test.js +++ b/test/SmartFolderWatcher.visionBatchOwner.test.js @@ -243,6 +243,79 @@ describe('SmartFolderWatcher image batch and vision batch mode', () => { expect(mockLlama.exitVisionBatchMode).not.toHaveBeenCalled(); }); + describe('when images in the batch need no analysis', () => { + // _analyzeFile drops an item the history has caught up with, most often + // the change event that follows the watcher's own read of a file. The + // batch used to enter vision batch mode before that was known: text and + // embedding models unloaded, the vision runtime started, the text model + // loaded again on the way out, and nothing analyzed. + const fsPromises = require('fs').promises; + const upToDate = { fileSize: 10, lastModified: 1000 }; + + beforeEach(() => { + fsPromises.stat.mockResolvedValue({ mtimeMs: 1000, size: 10 }); + }); + afterEach(() => { + fsPromises.stat.mockReset(); + }); + + test('does not enter vision batch mode when the history has every image', async () => { + watcher.analysisHistoryService.getAnalysisByPath.mockResolvedValue(upToDate); + queueImages(watcher, 2); + + await watcher._processQueue(); + + expect(mockLlama.enterVisionBatchMode).not.toHaveBeenCalled(); + expect(mockLlama.exitVisionBatchMode).not.toHaveBeenCalled(); + // The items still go through _analyzeFile, which drops and logs them. + expect(watcher._analyzeWithTimeout).toHaveBeenCalledTimes(2); + expect(watcher._inFlightItems.size).toBe(0); + expect(watcher.analysisQueue).toEqual([]); + }); + + test('enters once when one image of the batch still needs analysis', async () => { + watcher.analysisHistoryService.getAnalysisByPath.mockImplementation(async (filePath) => + filePath.endsWith('photo-1.png') ? null : upToDate + ); + queueImages(watcher, 3); + + await watcher._processQueue(); + + expect(mockLlama.enterVisionBatchMode).toHaveBeenCalledTimes(1); + expect(scopeAtAnalysis).toEqual([true, true, true]); + expect(mockLlama.exitVisionBatchMode).toHaveBeenCalledTimes(1); + }); + + test('an embedding retry, which reuses its analysis, does not enter', async () => { + queueImages(watcher, 1); + watcher.analysisQueue[0].cachedAnalysis = { category: 'Photos' }; + + await watcher._processQueue(); + + expect(mockLlama.enterVisionBatchMode).not.toHaveBeenCalled(); + expect(watcher._analyzeWithTimeout).toHaveBeenCalledTimes(1); + }); + + test('an image deleted since it was queued does not enter', async () => { + fsPromises.stat.mockRejectedValue(Object.assign(new Error('gone'), { code: 'ENOENT' })); + queueImages(watcher, 1); + + await watcher._processQueue(); + + expect(mockLlama.enterVisionBatchMode).not.toHaveBeenCalled(); + }); + + test('an explicit reanalysis enters although the history has the image', async () => { + watcher.analysisHistoryService.getAnalysisByPath.mockResolvedValue(upToDate); + queueImages(watcher, 1); + watcher.analysisQueue[0].eventType = 'reanalyze'; + + await watcher._processQueue(); + + expect(mockLlama.enterVisionBatchMode).toHaveBeenCalledTimes(1); + }); + }); + describe('when a Discover analysis starts during the batch', () => { // The queue is held while the user analyzes, but that was only looked at // before a batch began: up to 19 more images then ran beside the user. diff --git a/test/VisionService.test.js b/test/VisionService.test.js index 06cab33..d94dad5 100644 --- a/test/VisionService.test.js +++ b/test/VisionService.test.js @@ -474,6 +474,48 @@ describe('VisionService', () => { requestSpy.mockRestore(); } }); + // The stderr tail is whatever the runtime last wrote: its load banner + // names the GPU backend, and "cuda" in the message made a rejected image + // a retryable error. + test('an error the runtime answers with keeps stderr text out of its message', async () => { + const http = require('http'); + await startReadyServer(); + service._ensureServer = jest.fn().mockResolvedValue(undefined); + service._recentStderr = + 'clip_ctx: CLIP using CUDA0 backend\nload_hparams: projector: mlp\ndecode: failed to find a memory slot for batch of size 1024'; + const requestSpy = jest.spyOn(http, 'request').mockImplementation((options, callback) => { + const req = new EventEmitter(); + req.setTimeout = jest.fn(); + req.write = jest.fn(); + req.destroy = jest.fn(); + req.end = jest.fn(() => { + const res = new EventEmitter(); + res.statusCode = 400; + callback(res); + res.emit( + 'data', + JSON.stringify({ error: { message: 'Failed to load image or audio file' } }) + ); + res.emit('end'); + }); + return req; + }); + + try { + const error = await service + .analyzeImage({ + imageBase64: 'iVBORw0KGgoAAAANSUhEUgAAAAEAAAAB', + config: { modelPath: '/models/vision.gguf', contextSize: 4096, threads: 4 } + }) + .catch((e) => e); + + expect(error.message).toBe('Failed to load image or audio file'); + expect(error.visionRuntimeHint).toMatch(/CUDA0/); + } finally { + requestSpy.mockRestore(); + } + }); + describe('the hold a request takes on the registration', () => { const image = { imageBase64: 'iVBORw0KGgoAAAANSUhEUgAAAAEAAAAB', diff --git a/test/WhisperService.test.js b/test/WhisperService.test.js index d89325b..655308e 100644 --- a/test/WhisperService.test.js +++ b/test/WhisperService.test.js @@ -1959,6 +1959,14 @@ describe('WhisperService — CPU beside a GPU-filling text model', () => { expect(memory.registerExternalConsumer.mock.calls[0][0].sizeBytes).toBeGreaterThan(0); }); + test('runs on the CPU when the text model is still being loaded', async () => { + // The load has reserved the GPU but has no context yet. + const memory = memoryWith({ textResident: false, fits: false }); + memory.isLoadedOrLoading = jest.fn((type) => type === 'text'); + const { init } = await load(memory); + expect(init.mock.calls[0][0].useGpu).toBe(false); + }); + test('uses the GPU when no text model is resident', async () => { const { init } = await load(memoryWith({ textResident: false, fits: false })); expect(init.mock.calls[0][0].useGpu).toBe(true); diff --git a/test/analysis-ipc-handlers.test.js b/test/analysis-ipc-handlers.test.js index 2dd1508..abd1f99 100644 --- a/test/analysis-ipc-handlers.test.js +++ b/test/analysis-ipc-handlers.test.js @@ -64,6 +64,7 @@ jest.mock('../src/main/services/BatchAnalysisService', () => jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ sendFileOperationBatchComplete: jest.fn(), + flushOperationProgress: jest.fn(), sendOperationProgress: jest.fn() })); diff --git a/test/analysis.classifyOutcome.formatUnsupported.test.js b/test/analysis.classifyOutcome.formatUnsupported.test.js index 950675d..d1f51a2 100644 --- a/test/analysis.classifyOutcome.formatUnsupported.test.js +++ b/test/analysis.classifyOutcome.formatUnsupported.test.js @@ -50,6 +50,7 @@ jest.mock('../src/main/services/BatchAnalysisService', () => jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ sendFileOperationBatchComplete: jest.fn(), + flushOperationProgress: jest.fn(), sendOperationProgress: jest.fn(), sendFileComplete: jest.fn() })); diff --git a/test/analysisIpc.batchLifecycle.test.js b/test/analysisIpc.batchLifecycle.test.js new file mode 100644 index 0000000..e8ac763 --- /dev/null +++ b/test/analysisIpc.batchLifecycle.test.js @@ -0,0 +1,415 @@ +/** + * @jest-environment node + * + * A Discover batch in main, from the first await to the last report: + * - a Stop that arrives while the paths are still being checked, + * - a renderer that reloads, crashes or is destroyed while the batch runs, + * - progress that is still on its way when the batch has ended, + * - the size and date the history keeps for a file that was analyzed. + */ +jest.mock('fs', () => jest.requireActual('fs')); + +const mockBatchAnalyzeFiles = jest.fn(); + +const mockIpcWrappers = { + createHandler: jest.fn(({ handler }) => handler), + withErrorLogging: jest.fn((logger, handler) => handler), + withValidation: jest.fn((logger, schema, handler) => handler), + safeHandle: jest.fn(), + z: null +}; +jest.mock('../src/main/ipc/ipcWrappers', () => mockIpcWrappers); + +jest.mock('../src/main/utils/safeAccess', () => ({ + safeFilePath: jest.fn((filePath) => filePath) +})); +jest.mock('../src/shared/pathSanitization', () => ({ + validateFileOperationPath: jest.fn(async (filePath) => ({ + valid: true, + normalizedPath: filePath + })) +})); +jest.mock('../src/shared/folderUtils', () => ({ + mapFoldersToCategories: jest.fn().mockReturnValue(['cat1']), + getFolderNamesString: jest.fn().mockReturnValue('cat1') +})); +jest.mock('../src/shared/logger', () => { + const logger = { debug: jest.fn(), info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + return { logger, createLogger: jest.fn(() => logger) }; +}); + +const mockAnalysisUtils = { + withProcessingState: jest.fn(), + buildErrorContext: jest.fn().mockReturnValue({}), + createAnalysisFallback: jest.fn().mockReturnValue({ fallback: true }), + recordAnalysisResult: jest.fn(), + getFolderCategories: jest.fn().mockReturnValue(['cat1']) +}; +jest.mock('../src/main/ipc/analysisUtils', () => mockAnalysisUtils); + +jest.mock('../src/main/utils/tesseractUtils', () => ({ recognizeIfAvailable: jest.fn() })); +jest.mock('../src/main/services/BatchAnalysisService', () => + jest.fn().mockImplementation(() => ({ + analyzeFiles: (...args) => mockBatchAnalyzeFiles(...args), + shutdown: jest.fn() + })) +); +jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ + sendFileComplete: jest.fn(), + sendOperationProgress: jest.fn(), + flushOperationProgress: jest.fn() +})); + +const mockMediaAnalyzer = jest.fn(); +jest.mock('../src/main/services/mediaAnalyzerAdapter', () => ({ + createMediaAnalyzerAdapter: () => mockMediaAnalyzer, + buildSkipResult: jest.fn() +})); +jest.mock('../src/main/services/WhisperService', () => ({ getInstance: jest.fn(() => null) })); + +const { EventEmitter } = require('events'); +const fsPromises = require('fs').promises; +const registerAnalysisIpc = require('../src/main/ipc/analysis'); +const { validateFileOperationPath } = require('../src/shared/pathSanitization'); +const { + sendOperationProgress, + flushOperationProgress +} = require('../src/main/ipc/files/batchProgressReporter'); + +const IPC_CHANNELS = { + ANALYSIS: { + ANALYZE_DOCUMENT: 'analyze-document', + ANALYZE_IMAGE: 'analyze-image', + ANALYZE_MEDIA: 'analyze-media', + ANALYZE_BATCH: 'analyze-batch', + CANCEL_BATCH: 'cancel-batch', + EXTRACT_IMAGE_TEXT: 'extract-image-text', + GET_READY_QUEUE: 'get-ready-queue' + } +}; + +const BATCH_DONE = { success: true, results: [], errors: [], total: 1, successful: 1 }; + +let handlers; +let analyzeDocumentFile; +let analyzeImageFile; +let batchCounter = 0; + +/** Resolves after the promise jobs that are already queued have run. */ +const settle = () => new Promise((resolve) => setImmediate(resolve)); + +beforeEach(() => { + jest.clearAllMocks(); + mockBatchAnalyzeFiles.mockReset(); + mockMediaAnalyzer.mockReset(); + mockAnalysisUtils.withProcessingState.mockImplementation(async ({ fn }) => fn()); + mockAnalysisUtils.recordAnalysisResult.mockResolvedValue({ persisted: true }); + handlers = {}; + mockIpcWrappers.safeHandle.mockImplementation((_ipc, channel, handler) => { + handlers[channel] = handler; + }); + analyzeDocumentFile = jest.fn(); + analyzeImageFile = jest.fn(); + registerAnalysisIpc({ + ipcMain: { handle: jest.fn() }, + IPC_CHANNELS, + logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() }, + systemAnalytics: { recordProcessingTime: jest.fn(), recordFailure: jest.fn() }, + analyzeDocumentFile, + analyzeImageFile, + getServiceIntegration: jest.fn().mockReturnValue({ analysisHistory: {} }), + getCustomFolders: jest.fn().mockReturnValue([]), + getMainWindow: () => ({}) + }); +}); + +const analyzeBatch = (event, payload) => + handlers[IPC_CHANNELS.ANALYSIS.ANALYZE_BATCH](event, payload); +const cancelBatch = (batchId) => handlers[IPC_CHANNELS.ANALYSIS.CANCEL_BATCH]({}, { batchId }); +const nextBatchId = () => `lifecycle-${++batchCounter}`; + +/** + * Starts a batch whose service call stays open. Returns the options the + * service was given and a way to let the batch end. + */ +async function startOpenBatch(event = {}, filePaths = ['C:\\Docs\\a.pdf']) { + const batchId = nextBatchId(); + let finish; + let options; + mockBatchAnalyzeFiles.mockImplementationOnce((_paths, _folders, batchOptions) => { + options = batchOptions; + return new Promise((resolve) => { + finish = () => resolve(BATCH_DONE); + }); + }); + const done = analyzeBatch(event, { batchId, filePaths }); + await settle(); + return { + batchId, + done, + options, + end: async () => { + finish(); + await done; + } + }; +} + +describe('Stop while the paths of a batch are still being checked', () => { + test('the batch is known to the cancel handler and does not analyze', async () => { + const batchId = nextBatchId(); + let releaseValidation; + validateFileOperationPath.mockImplementationOnce( + (filePath) => + new Promise((resolve) => { + releaseValidation = () => resolve({ valid: true, normalizedPath: filePath }); + }) + ); + let options; + mockBatchAnalyzeFiles.mockImplementationOnce(async (_paths, _folders, batchOptions) => { + options = batchOptions; + return { ...BATCH_DONE, success: false, cancelled: true, successful: 0 }; + }); + + const done = analyzeBatch({}, { batchId, filePaths: ['C:\\Docs\\a.pdf'] }); + await settle(); + expect(mockBatchAnalyzeFiles).not.toHaveBeenCalled(); + + const answer = await cancelBatch(batchId); + expect(answer).toEqual(expect.objectContaining({ success: true, cancelled: true })); + expect(answer.notFound).toBeUndefined(); + + releaseValidation(); + const result = await done; + + // The service is told at once: it starts no file. + expect(options.isCancelled()).toBe(true); + expect(options.abortSignal.aborted).toBe(true); + expect(result.cancelled).toBe(true); + }); + + test('a batch that ends at the path check leaves nothing behind', async () => { + const batchId = nextBatchId(); + validateFileOperationPath.mockResolvedValueOnce({ valid: false, error: 'outside' }); + + const refused = await analyzeBatch({}, { batchId, filePaths: ['C:\\Nope\\a.pdf'] }); + expect(refused.success).toBe(false); + expect(mockBatchAnalyzeFiles).not.toHaveBeenCalled(); + + expect(await cancelBatch(batchId)).toEqual(expect.objectContaining({ notFound: true })); + + // The id is free again. + mockBatchAnalyzeFiles.mockResolvedValueOnce(BATCH_DONE); + const again = await analyzeBatch({}, { batchId, filePaths: ['C:\\Docs\\a.pdf'] }); + expect(again.success).toBe(true); + }); +}); + +describe('a batch whose renderer goes away', () => { + const expectCancelled = (options, cancelled) => { + expect(options.isCancelled()).toBe(cancelled); + expect(options.abortSignal.aborted).toBe(cancelled); + }; + + test.each([ + ['its process is gone', (sender) => sender.emit('render-process-gone', {}, { reason: 'oom' })], + // Emitted once the main frame has loaded another document. + ['it is reloaded', (sender) => sender.emit('did-navigate', {}, 'app://index.html', 200, 'OK')], + ['it is destroyed', (sender) => sender.emit('destroyed')] + ])('is cancelled when %s', async (_what, goAway) => { + const sender = new EventEmitter(); + const batch = await startOpenBatch({ sender }); + expectCancelled(batch.options, false); + + goAway(sender); + + expectCancelled(batch.options, true); + await batch.end(); + }); + + test.each([ + [ + 'a navigation inside the page', + (sender) => sender.emit('did-navigate-in-page', {}, 'app://index.html#/discover', true) + ], + [ + 'a navigation of a frame inside the page', + (sender) => sender.emit('did-frame-navigate', {}, 'about:blank', 200, 'OK', false) + ], + [ + // 'did-start-navigation' comes before 'will-navigate', which blocks a + // link to another site: the page is still there afterwards. + 'a navigation that starts and is then blocked', + (sender) => + sender.emit('did-start-navigation', { + url: 'https://example.com/', + isMainFrame: true, + isSameDocument: false + }) + ] + ])('keeps running through %s', async (_what, happen) => { + const sender = new EventEmitter(); + const batch = await startOpenBatch({ sender }); + + happen(sender); + + expectCancelled(batch.options, false); + await batch.end(); + }); + + test('another window going away does not stop it', async () => { + const sender = new EventEmitter(); + const other = new EventEmitter(); + const batch = await startOpenBatch({ sender }); + const otherBatch = await startOpenBatch({ sender: other }, ['C:\\Docs\\b.pdf']); + + other.emit('destroyed'); + + expectCancelled(batch.options, false); + expectCancelled(otherBatch.options, true); + await batch.end(); + await otherBatch.end(); + }); + + test('nothing is left listening on the renderer when the batch has ended', async () => { + const sender = new EventEmitter(); + const batch = await startOpenBatch({ sender }); + expect(sender.listenerCount('destroyed')).toBe(1); + + await batch.end(); + + for (const name of ['render-process-gone', 'did-navigate', 'destroyed']) { + expect(sender.listenerCount(name)).toBe(0); + } + }); +}); + +describe('progress of a batch that is on its way when the batch ends', () => { + const stillWanted = (call) => sendOperationProgress.mock.calls[call][2]?.stillWanted?.(); + + test('a report says whether its batch still wants it: yes while it runs', async () => { + const batch = await startOpenBatch(); + + batch.options.onProgress({ completed: 1, total: 2 }); + + expect(sendOperationProgress).toHaveBeenCalledTimes(1); + expect(stillWanted(0)).toBe(true); + await batch.end(); + }); + + test('no longer once the batch was cancelled', async () => { + const batch = await startOpenBatch(); + batch.options.onProgress({ completed: 1, total: 2 }); + + await cancelBatch(batch.batchId); + + expect(stillWanted(0)).toBe(false); + await batch.end(); + }); + + test('no longer once the batch has returned', async () => { + const batch = await startOpenBatch(); + batch.options.onProgress({ completed: 2, total: 2 }); + + await batch.end(); + + expect(stillWanted(0)).toBe(false); + }); + + test('a batch that ran to its end sends its last report itself', async () => { + const batch = await startOpenBatch(); + batch.options.onProgress({ completed: 2, total: 2 }); + + await batch.end(); + + expect(flushOperationProgress).toHaveBeenCalledTimes(1); + expect(flushOperationProgress.mock.calls[0][1]).toMatchObject({ + type: 'batch_analyze', + batchId: batch.batchId, + completed: 2, + total: 2 + }); + }); + + test('a cancelled batch does not', async () => { + const batch = await startOpenBatch(); + batch.options.onProgress({ completed: 1, total: 2 }); + + await cancelBatch(batch.batchId); + await batch.end(); + + expect(flushOperationProgress).not.toHaveBeenCalled(); + }); +}); + +describe('the size and date the history keeps for an analyzed file', () => { + const BEFORE = { size: 10, mtimeMs: 1000, mtime: new Date(1000), birthtime: new Date(500) }; + const AFTER = { size: 20, mtimeMs: 2000, mtime: new Date(2000), birthtime: new Date(500) }; + let stat; + let analyzed; + let gone; + + beforeEach(() => { + analyzed = false; + gone = false; + stat = jest.spyOn(fsPromises, 'stat').mockImplementation(async () => { + if (analyzed && gone) throw Object.assign(new Error('ENOENT'), { code: 'ENOENT' }); + return analyzed ? AFTER : BEFORE; + }); + // The file is saved again (or removed) while the model works on it. + const analyzer = async () => { + analyzed = true; + return { category: 'Finance', keywords: ['invoice'] }; + }; + analyzeDocumentFile.mockImplementation(analyzer); + analyzeImageFile.mockImplementation(analyzer); + mockMediaAnalyzer.mockImplementation(analyzer); + }); + + afterEach(() => { + stat.mockRestore(); + }); + + const recordedStats = () => mockAnalysisUtils.recordAnalysisResult.mock.calls[0][0].fileStats; + + const viaBatch = (analyzerName) => async (filePath) => { + mockBatchAnalyzeFiles.mockImplementationOnce(async (paths, folders, batchOptions) => { + await batchOptions[analyzerName](paths[0], folders); + return BATCH_DONE; + }); + await analyzeBatch({}, { batchId: nextBatchId(), filePaths: [filePath] }); + }; + const viaHandler = (channel) => (filePath) => handlers[channel]({}, filePath); + + const WAYS = [ + ['a document', 'C:\\Docs\\a.pdf', viaHandler(IPC_CHANNELS.ANALYSIS.ANALYZE_DOCUMENT)], + ['an image', 'C:\\Docs\\a.png', viaHandler(IPC_CHANNELS.ANALYSIS.ANALYZE_IMAGE)], + ['a recording', 'C:\\Docs\\a.mp3', viaHandler(IPC_CHANNELS.ANALYSIS.ANALYZE_MEDIA)], + ['a document in a batch', 'C:\\Docs\\a.pdf', viaBatch('documentAnalyzer')], + ['an image in a batch', 'C:\\Docs\\a.png', viaBatch('imageAnalyzer')], + ['a recording in a batch', 'C:\\Docs\\a.mp3', viaBatch('mediaAnalyzer')] + ]; + + test.each(WAYS)( + '%s saved during its analysis is recorded as it was read', + async (_what, filePath, analyze) => { + await analyze(filePath); + + expect(mockAnalysisUtils.recordAnalysisResult).toHaveBeenCalledTimes(1); + expect(recordedStats()).toEqual(expect.objectContaining({ size: 10, mtimeMs: 1000 })); + } + ); + + test.each(WAYS)( + '%s removed during its analysis is not recorded from the earlier read', + async (_what, filePath, analyze) => { + gone = true; + + await analyze(filePath); + + // Without stats the record reads the file itself and fails, as before. + expect(mockAnalysisUtils.recordAnalysisResult).toHaveBeenCalledTimes(1); + expect(recordedStats() ?? null).toBeNull(); + } + ); +}); diff --git a/test/analysisIpc.realZod.test.js b/test/analysisIpc.realZod.test.js index 9d750d2..2994c0d 100644 --- a/test/analysisIpc.realZod.test.js +++ b/test/analysisIpc.realZod.test.js @@ -57,6 +57,7 @@ jest.mock('../src/main/services/BatchAnalysisService', () => jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ sendFileOperationBatchComplete: jest.fn(), + flushOperationProgress: jest.fn(), sendOperationProgress: jest.fn() })); @@ -269,10 +270,12 @@ describe('registerAnalysisIpc (real Zod)', () => { describe('single-file analyze payload with namingSettings', () => { test('ANALYZE_DOCUMENT accepts object payload and applies naming override', async () => { const fsPromises = require('fs').promises; + // Noon local time: the name carries the local day, and noon UTC is + // already the 2nd at UTC+12 and beyond. fsPromises.stat.mockResolvedValueOnce({ size: 1024, - birthtime: new Date('2026-06-01T12:00:00Z'), - mtime: new Date('2026-06-01T12:00:00Z') + birthtime: new Date(2026, 5, 1, 12), + mtime: new Date(2026, 5, 1, 12) }); mockAnalyzeDocumentFile.mockResolvedValueOnce({ diff --git a/test/analysisIpc.test.js b/test/analysisIpc.test.js index 1728a48..58f86f6 100644 --- a/test/analysisIpc.test.js +++ b/test/analysisIpc.test.js @@ -62,6 +62,7 @@ jest.mock('../src/main/services/BatchAnalysisService', () => jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ sendFileOperationBatchComplete: jest.fn(), + flushOperationProgress: jest.fn(), sendOperationProgress: jest.fn(), sendFileComplete: jest.fn() })); diff --git a/test/analysisProvenance.test.js b/test/analysisProvenance.test.js index 46c404c..8008dc4 100644 --- a/test/analysisProvenance.test.js +++ b/test/analysisProvenance.test.js @@ -11,6 +11,17 @@ const { } = require('../src/shared/analysisProvenance'); describe('analysisProvenance', () => { + // History keeps `provisional` and drops the `isFallback` flags. + test('a stored row marked provisional is a fallback, retried only for a capability reason', () => { + const row = { provisional: true, category: 'audio', extractionMethod: 'whisper-transcription' }; + expect(isFallbackAnalysis(row)).toBe(true); + expect(isCapabilityFallback(row)).toBe(false); + expect(isCapabilityFallback({ ...row, fallbackReason: 'ai_analysis_failed' })).toBe(true); + expect(isCapabilityFallback({ provisional: true, extractionMethod: 'pdf_no_text' })).toBe( + false + ); + }); + test.each([ ['explicit _isFallback', { _isFallback: true }, true], ['explicit isFallback', { isFallback: true }, true], diff --git a/test/batchProgressReporter.trailingFlush.test.js b/test/batchProgressReporter.trailingFlush.test.js new file mode 100644 index 0000000..8efba73 --- /dev/null +++ b/test/batchProgressReporter.trailingFlush.test.js @@ -0,0 +1,122 @@ +/** + * @jest-environment node + * + * Progress is sent at most once per window; a report inside the window is + * held and sent when the window closes. The operation can have ended or been + * stopped by then. A Discover analysis that was stopped got its held counts + * sent after the renderer had cleared them, and counts without a running + * analysis read as "Analysis paused. Click to resume." + */ +jest.mock('../src/main/ipc/ipcWrappers', () => ({ + safeSend: jest.fn() +})); + +const { BATCH } = require('../src/shared/performanceConstants'); + +const WINDOW_MS = BATCH.PROGRESS_UPDATE_INTERVAL; + +describe('a progress report held back by the throttle', () => { + let safeSend; + let sendOperationProgress; + let flushOperationProgress; + const getMainWindow = () => ({ isDestroyed: () => false, webContents: {} }); + const sentPayloads = () => safeSend.mock.calls.map((call) => call[2]); + + beforeEach(() => { + jest.useFakeTimers(); + jest.resetModules(); + ({ safeSend } = require('../src/main/ipc/ipcWrappers')); + ({ + sendOperationProgress, + flushOperationProgress + } = require('../src/main/ipc/files/batchProgressReporter')); + // The first report of a window is sent at once; the next one is held. + sendOperationProgress(getMainWindow, { completed: 1 }); + jest.advanceTimersByTime(10); + }); + + afterEach(() => { + jest.useRealTimers(); + }); + + test('is sent when the window closes', () => { + sendOperationProgress(getMainWindow, { completed: 2 }); + expect(sentPayloads()).toEqual([{ completed: 1 }]); + + jest.advanceTimersByTime(WINDOW_MS); + + expect(sentPayloads()).toEqual([{ completed: 1 }, { completed: 2 }]); + }); + + test('is sent when its operation still wants it', () => { + const stillWanted = jest.fn(() => true); + sendOperationProgress(getMainWindow, { completed: 2 }, { stillWanted }); + // Asked when the window closes, not when the report is handed in. + expect(stillWanted).not.toHaveBeenCalled(); + + jest.advanceTimersByTime(WINDOW_MS); + + expect(stillWanted).toHaveBeenCalledTimes(1); + expect(sentPayloads()).toEqual([{ completed: 1 }, { completed: 2 }]); + }); + + test('the closing report of an operation is sent at once, and once', () => { + // The operation ends inside the window, so its check answers false and + // the held report is dropped. Listeners that refresh on the closing + // report (search and embedding counts) never heard that it finished. + let running = true; + const closing = { batchId: 'b1', completed: 2, total: 2 }; + sendOperationProgress(getMainWindow, closing, { stillWanted: () => running }); + + flushOperationProgress(getMainWindow, closing); + running = false; + + expect(sentPayloads()).toEqual([{ completed: 1 }, closing]); + jest.advanceTimersByTime(WINDOW_MS); + expect(sentPayloads()).toEqual([{ completed: 1 }, closing]); + }); + + test('is dropped when its operation was stopped inside the window', () => { + let running = true; + sendOperationProgress(getMainWindow, { completed: 2 }, { stillWanted: () => running }); + + running = false; + jest.advanceTimersByTime(WINDOW_MS); + + expect(sentPayloads()).toEqual([{ completed: 1 }]); + }); + + test('a dropped report does not hold back the report after it', () => { + sendOperationProgress(getMainWindow, { completed: 2 }, { stillWanted: () => false }); + jest.advanceTimersByTime(WINDOW_MS); + expect(sentPayloads()).toEqual([{ completed: 1 }]); + + // Nothing was sent in that window, so this one is not throttled by it. + sendOperationProgress(getMainWindow, { completed: 3 }); + + expect(sentPayloads()).toEqual([{ completed: 1 }, { completed: 3 }]); + }); + + test('a later report of another sender is not held back by the check before it', () => { + // A stopped analysis and an organize batch share the throttle. + sendOperationProgress(getMainWindow, { type: 'batch_analyze' }, { stillWanted: () => false }); + sendOperationProgress(getMainWindow, { type: 'batch_organize' }); + + jest.advanceTimersByTime(WINDOW_MS); + + expect(sentPayloads()).toEqual([{ completed: 1 }, { type: 'batch_organize' }]); + }); + + test('a report sent at once clears the check of the report it replaces', () => { + sendOperationProgress(getMainWindow, { completed: 2 }, { stillWanted: () => false }); + jest.advanceTimersByTime(WINDOW_MS + 10); + expect(sentPayloads()).toEqual([{ completed: 1 }]); + + sendOperationProgress(getMainWindow, { completed: 3 }); + jest.advanceTimersByTime(10); + sendOperationProgress(getMainWindow, { completed: 4 }); + jest.advanceTimersByTime(WINDOW_MS); + + expect(sentPayloads()).toEqual([{ completed: 1 }, { completed: 3 }, { completed: 4 }]); + }); +}); diff --git a/test/calendarDayLocalTime.test.js b/test/calendarDayLocalTime.test.js index 01848cb..50cbb7b 100644 --- a/test/calendarDayLocalTime.test.js +++ b/test/calendarDayLocalTime.test.js @@ -27,7 +27,7 @@ const PROBE = ` process.env.TZ = process.argv[1]; require.cache[require.resolve('electron')] = { exports: {}, loaded: true }; const { generateSuggestedNameFromAnalysis, formatDate } = require('./src/shared/namingConventions'); -const { toWrittenCalendarDay } = require('./src/shared/contentDateSanity'); +const { toWrittenCalendarDay, toLocalCalendarDay, toLocalCalendarMs } = require('./src/shared/contentDateSanity'); const { buildAnalysisFromModelJson } = require('./src/main/analysis/modelAnalysisResult'); const { getAnalysisByDateRange } = require('./src/main/services/analysisHistory/queries'); const foundInRange = (at, start, end) => @@ -62,6 +62,23 @@ process.stdout.write( toWrittenCalendarDay ), writtenYearFirst: ['2024 May 5', '2024 June', '2024 May 5 10:00'].map(toWrittenCalendarDay), + shownDays: ['2024-05-05', '2024-01-01', '2024-12-31', '0024-05-05'].map((day) => { + const shown = new Date(toLocalCalendarMs(day)); + return [shown.getFullYear(), shown.getMonth() + 1, shown.getDate(), shown.getHours()]; + }), + shownInstant: toLocalCalendarMs('2024-05-05T03:00:00Z') === Date.parse('2024-05-05T03:00:00Z'), + shownNothing: [null, undefined, '', 'not a date'].map(toLocalCalendarMs), + writtenWithZone: ['2024-05-05Z', '2024-05Z', '2024Z', '2024-05-05z'].map(toWrittenCalendarDay), + writtenOddYears: ['0001-01-01', '0024-05-05', '0099-12-31', '20255-01-01', '19999', '202501'].map( + toWrittenCalendarDay + ), + oddYearModelDates: ['0024-05-05', '20255-01-01', '19999'].map( + (date) => + buildAnalysisFromModelJson( + { date, category: 'Finance', keywords: ['invoice'], confidence: 80 }, + { originalFileName: 'invoice.pdf', smartFolders: [], fileDate: '2026-01-02', logger: quiet } + ).date + ), rangeEndingLateOnItsLastDay: foundInRange( new Date(2026, 11, 31, 23, 29), new Date(2026, 10, 15, 0, 30), @@ -160,6 +177,61 @@ describe('a date the model wrote out is stored as the day written', () => { ); }); +describe('a written date with nothing but a Z after it is the day written', () => { + // "2024-05-05Z" is midnight UTC. Only "T" or a space was let through after + // the day, so this one was read as a moment and came out as the 4th west of + // Greenwich. + test.each(['America/Los_Angeles', 'America/New_York', 'Europe/Berlin', 'Asia/Tokyo', 'UTC'])( + 'in %s', + (zone) => { + expect(inZone(zone).writtenWithZone).toEqual([ + '2024-05-05', + '2024-05-01', + '2024-01-01', + '2024-05-05' + ]); + } + ); +}); + +describe('a stored day is shown as that day', () => { + // Search results and the time ranges of clusters parsed "2024-05-05" as + // UTC midnight and formatted it in local time: May 4 west of Greenwich. + test.each(['America/Los_Angeles', 'America/New_York', 'Europe/Berlin', 'Asia/Tokyo', 'UTC'])( + 'in %s', + (zone) => { + expect(inZone(zone).shownDays).toEqual([ + [2024, 5, 5, 0], + [2024, 1, 1, 0], + [2024, 12, 31, 0], + [24, 5, 5, 0] + ]); + // A moment in time is still that moment. + expect(inZone(zone).shownInstant).toBe(true); + expect(inZone(zone).shownNothing).toEqual([null, null, null, null]); + } + ); +}); + +describe('a year that is not four digits of a real year', () => { + // Date.UTC reads the years 0-99 as 1900-1999, so a misread "0024-05-05" + // was stored as 1924 and passed the plausibility window. A year of five + // or six digits parses as that year; its first four digits looked + // plausible. + test.each(['America/Los_Angeles', 'Asia/Tokyo', 'UTC'])('in %s', (zone) => { + expect(inZone(zone).writtenOddYears).toEqual([ + '0001-01-01', + '0024-05-05', + '0099-12-31', + null, + null, + null + ]); + // None of them is a content date: the file's date is used. + expect(inZone(zone).oddYearModelDates).toEqual(['2026-01-02', '2026-01-02', '2026-01-02']); + }); +}); + describe('a range of local days finds the history entries in it', () => { // The index is keyed by the UTC month of each entry. Walking the range in // local months and reading the UTC key of each step left out a month: diff --git a/test/components/ResultRow.documentDate.test.js b/test/components/ResultRow.documentDate.test.js new file mode 100644 index 0000000..ca7559d --- /dev/null +++ b/test/components/ResultRow.documentDate.test.js @@ -0,0 +1,83 @@ +/** + * @jest-environment jsdom + * + * A search result shows the date of its document. That date is stored as a + * day ("2024-05-05"). The row parsed it with new Date(), which reads a + * date-only string as UTC midnight, and formatted it in local time: the day + * before, anywhere west of Greenwich. + */ +import React from 'react'; +import { render, screen } from '@testing-library/react'; +import '@testing-library/jest-dom'; + +import ResultRow from '../../src/renderer/components/search/ResultRow'; +import { toLocalCalendarMs } from '../../src/shared/contentDateSanity'; + +// The real function, wrapped so a test can see the row use it. +jest.mock('../../src/shared/contentDateSanity', () => { + const actual = jest.requireActual('../../src/shared/contentDateSanity'); + return { ...actual, toLocalCalendarMs: jest.fn(actual.toLocalCalendarMs) }; +}); + +const noop = () => {}; + +function renderRow(metadata) { + return render( + + ); +} + +describe('the date on a search result', () => { + test('a document date is shown as the day it names', () => { + renderRow({ documentDate: '2024-05-05' }); + + expect(screen.getByText(new Date(2024, 4, 5).toLocaleDateString())).toBeInTheDocument(); + }); + + // The test above cannot tell new Date('2024-05-05') from the day it + // names where the zone is UTC, as on CI. This one can, in any zone: no + // parse of the stored value gives the instant the helper is made to return. + test('the day comes from the calendar-day helper, in every time zone', () => { + const elsewhere = new Date(2031, 0, 15, 12); + toLocalCalendarMs.mockReturnValueOnce(elsewhere.getTime()); + + renderRow({ documentDate: '2024-05-05' }); + + expect(toLocalCalendarMs).toHaveBeenCalledWith('2024-05-05'); + expect(screen.getByText(elsewhere.toLocaleDateString())).toBeInTheDocument(); + }); + + test('the legacy date field is read the same way', () => { + renderRow({ date: '2023-12-31' }); + + expect(screen.getByText(new Date(2023, 11, 31).toLocaleDateString())).toBeInTheDocument(); + }); + + test('a full timestamp is shown as its local day', () => { + const at = new Date(2024, 4, 5, 23, 30); + renderRow({ documentDate: at.toISOString() }); + + expect(screen.getByText(at.toLocaleDateString())).toBeInTheDocument(); + }); + + test('a value that is not a date shows no date', () => { + renderRow({ documentDate: 'not a date', category: 'Finance' }); + + expect(screen.getByText('Finance')).toBeInTheDocument(); + expect(screen.queryByText('Invalid Date')).not.toBeInTheDocument(); + }); +}); diff --git a/test/components/TargetFolderList.unquoteDescription.test.js b/test/components/TargetFolderList.unquoteDescription.test.js new file mode 100644 index 0000000..5b1d82a --- /dev/null +++ b/test/components/TargetFolderList.unquoteDescription.test.js @@ -0,0 +1,38 @@ +/** + * Organize's target-folder cards show a folder's description inside curly + * quotes and drop quotes the user typed around it. The character class that + * does this held a literal `s` where `\s` was meant, so every description + * lost the letter "s" at both ends: "Scans and receipts" read "cans and + * receipt". + */ +import { unquoteDescription } from '../../src/renderer/components/organize/TargetFolderList'; + +describe('unquoteDescription', () => { + test('keeps a description that starts and ends with the letter s', () => { + expect(unquoteDescription('Scans and receipts')).toBe('Scans and receipts'); + expect(unquoteDescription('statements')).toBe('statements'); + expect(unquoteDescription('sss')).toBe('sss'); + }); + + test('drops quotes typed around the text, of any kind', () => { + expect(unquoteDescription('"Tax documents"')).toBe('Tax documents'); + expect(unquoteDescription("'Tax documents'")).toBe('Tax documents'); + expect(unquoteDescription('“Tax documents”')).toBe('Tax documents'); + expect(unquoteDescription('‘Tax documents’')).toBe('Tax documents'); + }); + + test('drops whitespace inside the quotes as well as outside', () => { + expect(unquoteDescription(' " Scans " ')).toBe('Scans'); + expect(unquoteDescription('"\tstatements\n"')).toBe('statements'); + }); + + test('keeps quotes and apostrophes inside the text', () => { + expect(unquoteDescription('Sam\'s "final" drafts')).toBe('Sam\'s "final" drafts'); + }); + + test('an empty or missing description stays empty', () => { + expect(unquoteDescription('')).toBe(''); + expect(unquoteDescription(undefined)).toBe(''); + expect(unquoteDescription('""')).toBe(''); + }); +}); diff --git a/test/contentDateSanity.test.js b/test/contentDateSanity.test.js index 37efe68..13d1082 100644 --- a/test/contentDateSanity.test.js +++ b/test/contentDateSanity.test.js @@ -3,6 +3,7 @@ */ const { isPlausibleContentDate, + toWrittenCalendarDay, CONTENT_DATE_MIN_YEAR } = require('../src/shared/contentDateSanity'); @@ -26,6 +27,24 @@ describe('isPlausibleContentDate (F-158)', () => { expect(isPlausibleContentDate(String(CONTENT_DATE_MIN_YEAR - 1) + '-12-31', now)).toBe(false); }); + test('a year is four digits, not the first four of a longer number', () => { + expect(isPlausibleContentDate('20255-01-01', now)).toBe(false); + expect(isPlausibleContentDate('19999', now)).toBe(false); + expect(isPlausibleContentDate('20240505', now)).toBe(false); + expect(isPlausibleContentDate('2024', now)).toBe(true); + expect(isPlausibleContentDate('2024-05', now)).toBe(true); + expect(isPlausibleContentDate('2024-05-05T10:00:00.000Z', now)).toBe(true); + }); + + test('a number from the model is a year or nothing, never milliseconds', () => { + // {"date": 2024} was read as 2024 ms after 1970 and kept as the date. + expect(toWrittenCalendarDay(2024)).toBe('2024-01-01'); + expect(toWrittenCalendarDay(20240505)).toBeNull(); + expect(toWrittenCalendarDay(1714867200)).toBeNull(); + expect(toWrittenCalendarDay(2024.5)).toBeNull(); + expect(toWrittenCalendarDay(0)).toBeNull(); + }); + test('rejects non-strings and short/garbage input', () => { expect(isPlausibleContentDate(null, now)).toBe(false); expect(isPlausibleContentDate(undefined, now)).toBe(false); diff --git a/test/discoverBatchBusy.test.js b/test/discoverBatchBusy.test.js index f3f78ac..b814a7f 100644 --- a/test/discoverBatchBusy.test.js +++ b/test/discoverBatchBusy.test.js @@ -100,18 +100,41 @@ describe('runBatchPathWhenFree', () => { }); test('the real wait resolves early when aborted', async () => { - const controller = new AbortController(); - const runBatchPath = jest.fn(async () => { - throw busy(); - }); - const pending = runBatchPathWhenFree({ - runBatchPath, - isActiveRun: () => true, - abortSignal: controller.signal, - retryMs: 60_000 - }); - controller.abort(); - await expect(pending).resolves.toBe('superseded'); + jest.useFakeTimers(); + try { + const controller = new AbortController(); + const runBatchPath = jest.fn(async () => { + throw busy(); + }); + const onWaiting = jest.fn(); + let outcome = 'still waiting'; + runBatchPathWhenFree({ + runBatchPath, + isActiveRun: () => true, + abortSignal: controller.signal, + onWaiting, + retryMs: 60_000 + }).then((value) => { + outcome = value; + }); + + // Let the refusal arrive first. An abort before it is caught by the + // check ahead of the wait, and the wait itself is never entered. + await jest.advanceTimersByTimeAsync(1000); + expect(onWaiting).toHaveBeenCalledTimes(1); + expect(jest.getTimerCount()).toBe(1); + expect(outcome).toBe('still waiting'); + + controller.abort(); + // Well short of the minute the wait was given. + await jest.advanceTimersByTimeAsync(1000); + + expect(outcome).toBe('superseded'); + expect(jest.getTimerCount()).toBe(0); + expect(runBatchPath).toHaveBeenCalledTimes(1); + } finally { + jest.useRealTimers(); + } }); }); diff --git a/test/embeddingBesideText.test.js b/test/embeddingBesideText.test.js index 0f5e24f..0bc3d17 100644 --- a/test/embeddingBesideText.test.js +++ b/test/embeddingBesideText.test.js @@ -75,11 +75,19 @@ describe('LlamaService._loadOptionsBesideText', () => { const LlamaService = LlamaServiceModule.LlamaService || LlamaServiceModule; const pick = LlamaService.prototype._loadOptionsBesideText; - const service = ({ backend = 'cuda', text = true, embedding = false, fits = false } = {}) => ({ + const service = ({ + backend = 'cuda', + text = true, + textLoading = false, + embedding = false, + fits = false + } = {}) => ({ _gpuBackend: backend, _modelMemoryManager: { getLoadedContext: (type) => (type === 'text' && text) || (type === 'embedding' && embedding) ? {} : null, + isLoadedOrLoading: (type) => + (type === 'text' && (text || textLoading)) || (type === 'embedding' && embedding), canLoadModel: () => fits } }); @@ -106,4 +114,105 @@ describe('LlamaService._loadOptionsBesideText', () => { test('only the embedding model is affected', () => { expect(pick.call(service(), 'text')).toBeUndefined(); }); + + describe('while the text model is still loading', () => { + // The first document's text load takes several seconds. An embedding + // request in that window was offered no CPU option, because only a text + // model already in memory counted: it waited for the text model to go + // idle and then evicted it. + function managerLoadingText() { + const llamaService = { + _models: { text: null, vision: null, embedding: null }, + _contexts: { text: null, vision: null, embedding: null }, + _loadModel: jest.fn().mockResolvedValue({ ctx: 'embedding' }), + _unloadModel: jest.fn().mockResolvedValue(undefined) + }; + const manager = new ModelMemoryManager(llamaService); + manager._maxMemoryUsage = 5 * GiB; + jest.spyOn(manager, '_refreshMemoryBudget').mockImplementation(() => {}); + manager._modelSizeEstimates.embedding = 181 * MiB; + manager._pinnedResidentWaitMs = 0; + const endTextLoad = manager.reserveLoad('text', 5806 * MiB); + return { manager, llamaService, endTextLoad }; + } + + test('a text load in progress counts as the text model holding the GPU', () => { + expect(pick.call(service({ text: false, textLoading: true }), 'embedding')).toEqual({ + gpuLayersOverride: 0, + besideResident: 'text', + keepBeside: true, + cpuByDesign: true + }); + }); + + test('the embedding model loads on the CPU beside it, without waiting for it', async () => { + const { manager, llamaService } = managerLoadingText(); + + const options = pick.call({ _gpuBackend: 'cuda', _modelMemoryManager: manager }, 'embedding'); + await manager.ensureModelLoaded('embedding', options); + + expect(llamaService._loadModel).toHaveBeenCalledWith( + 'embedding', + expect.objectContaining({ gpuLayersOverride: 0 }) + ); + // The text load is still in progress and was not disturbed. + expect(manager.getMemoryStatus().pendingLoads).toContain('text'); + expect(llamaService._unloadModel).not.toHaveBeenCalled(); + }); + + test('once the text load failed, the embedding model loads on the GPU as usual', () => { + const { manager, endTextLoad } = managerLoadingText(); + endTextLoad(); + + expect( + pick.call({ _gpuBackend: 'cuda', _modelMemoryManager: manager }, 'embedding') + ).toBeUndefined(); + }); + }); +}); + +describe('ModelMemoryManager.isLoadedOrLoading', () => { + function emptyManager() { + const manager = new ModelMemoryManager({ + _models: {}, + _contexts: {}, + _loadModel: jest.fn(), + _unloadModel: jest.fn() + }); + jest.spyOn(manager, '_refreshMemoryBudget').mockImplementation(() => {}); + return manager; + } + + test('false for a model that is neither in memory nor being loaded', () => { + expect(emptyManager().isLoadedOrLoading('text')).toBe(false); + }); + + test('true for a model in memory, without marking it as used', () => { + const manager = emptyManager(); + manager._loadedModels.set('text', { context: {}, lastUsed: 1, sizeBytes: GiB }); + + expect(manager.isLoadedOrLoading('text')).toBe(true); + expect(manager._loadedModels.get('text').lastUsed).toBe(1); + }); + + test('true while a load is in progress, false once it ended without a model', () => { + const manager = emptyManager(); + const endLoad = manager.reserveLoad('text', GiB); + + expect(manager.isLoadedOrLoading('text')).toBe(true); + endLoad(); + expect(manager.isLoadedOrLoading('text')).toBe(false); + }); + + test('false for a model that is being unloaded', () => { + const manager = emptyManager(); + manager._loadedModels.set('text', { + context: {}, + lastUsed: 1, + sizeBytes: GiB, + disposing: true + }); + + expect(manager.isLoadedOrLoading('text')).toBe(false); + }); }); diff --git a/test/imageAnalysis.behavior.test.js b/test/imageAnalysis.behavior.test.js index 4b07e9b..719e13c 100644 --- a/test/imageAnalysis.behavior.test.js +++ b/test/imageAnalysis.behavior.test.js @@ -242,7 +242,9 @@ describe('Image Analysis Behavior', () => { }); test('the HEIC filename fallback carries the file date it says it organizes by', async () => { - fs.stat.mockResolvedValue({ size: 1024, mtimeMs: Date.UTC(2024, 6, 4, 12, 0, 0) }); + // Noon local time: the fallback names the local day, and noon UTC is + // already the 5th at UTC+12 and beyond. + fs.stat.mockResolvedValue({ size: 1024, mtimeMs: new Date(2024, 6, 4, 12).getTime() }); const result = await analyzeImageFile('/photos/IMG_0042.heic', [{ name: 'Photos' }]); @@ -341,6 +343,89 @@ describe('Image Analysis Behavior', () => { expect(result.category).toBe('Finance'); }); + describe('an image whose preprocessing fails', () => { + const sharp = require('sharp'); + let workingSharp; + + beforeEach(() => { + workingSharp = sharp.getMockImplementation(); + sharp.mockImplementation(() => ({ + metadata: jest.fn().mockRejectedValue(new Error('XML parse error')), + rotate: jest.fn().mockReturnThis(), + resize: jest.fn().mockReturnThis(), + png: jest.fn().mockReturnThis(), + toBuffer: jest.fn().mockRejectedValue(new Error('XML parse error')) + })); + }); + + afterEach(() => { + sharp.mockImplementation(workingSharp); + }); + + // The vision runtime was sent the markup labelled image/png, twice, and + // each rejection counted against the vision breaker. + test('is not sent to the vision model when its bytes are not ones the runtime decodes', async () => { + fs.readFile.mockResolvedValue(Buffer.from('Tom & Jerry')); + + const result = await analyzeImageFile('/diagrams/broken.svg'); + + expect(mockLlamaService.analyzeImage).not.toHaveBeenCalled(); + expect( + require('../src/main/utils/tesseractUtils').recognizeIfAvailable + ).not.toHaveBeenCalled(); + expect(result.isFallback).toBe(true); + expect(result.extractionMethod).toBe('filename_fallback'); + // The mocked builder hands its `reason` back as it got it. + expect(result.reason).toMatch(/could not be decoded/i); + expect(result.reason).not.toMatch(/vision|unavailable|not loaded/i); + }); + + test('is still analyzed from the text its markup carries', async () => { + const svgText = 'Quarterly revenue by region\nNorth 42%\nSouth 31%'; + require('../src/main/analysis/extractors/svgText').extractTextFromSvg.mockReturnValueOnce( + svgText + ); + fs.readFile.mockResolvedValue(Buffer.from('Revenue & costs')); + + const result = await analyzeImageFile('/diagrams/revenue.svg'); + + expect(mockLlamaService.analyzeImage).not.toHaveBeenCalled(); + expect(require('../src/main/analysis/documentLlm').analyzeTextWithLlama).toHaveBeenCalledWith( + svgText, + 'revenue.svg', + expect.anything(), + expect.anything(), + expect.anything(), + expect.objectContaining({ forceLocal: true }) + ); + expect(result.isFallback).toBeFalsy(); + expect(result.category).toBe('General'); + }); + + test('still goes to the vision model when the bytes are a PNG', async () => { + fs.readFile.mockResolvedValue( + Buffer.concat([ + Buffer.from([0x89, 0x50, 0x4e, 0x47, 0x0d, 0x0a, 0x1a, 0x0a]), + Buffer.alloc(32) + ]) + ); + mockLlamaService.analyzeImage.mockResolvedValue({ + response: JSON.stringify({ + category: 'Photos', + keywords: ['beach'], + confidence: 85, + suggestedName: 'beach_day', + has_text: false + }) + }); + + const result = await analyzeImageFile('/photos/beach.png'); + + expect(mockLlamaService.analyzeImage).toHaveBeenCalledTimes(1); + expect(result.category).toBe('Photos'); + }); + }); + test('analyzes image successfully with AI', async () => { // Mock successful AI response const aiResponse = { @@ -700,6 +785,12 @@ describe('Image Analysis Behavior', () => { }); test('continues OCR/text fallback when OCR preprocessing fails', async () => { + // Bytes Tesseract reads as they are: a PNG by its signature. + const pngBytes = Buffer.concat([ + Buffer.from([0x89, 0x50, 0x4e, 0x47, 0x0d, 0x0a, 0x1a, 0x0a]), + Buffer.from('image-data') + ]); + fs.readFile.mockResolvedValue(pngBytes); const sharp = require('sharp'); sharp .mockImplementationOnce(() => ({ @@ -740,7 +831,7 @@ describe('Image Analysis Behavior', () => { const result = await analyzeImageFile('/path/to/image.png'); expect(recognizeIfAvailable).toHaveBeenCalled(); - expect(recognizeIfAvailable.mock.calls[0][1]).toEqual(Buffer.from('image-data')); + expect(recognizeIfAvailable.mock.calls[0][1]).toEqual(pngBytes); expect(result.error).toBeUndefined(); expect(result.category).toBe('Work'); }); @@ -984,6 +1075,83 @@ describe('Image Analysis Behavior', () => { expect(result.error).toBeUndefined(); }); + describe('an OCR result that stands in for the vision model is not cached', () => { + const visionAnswer = { + response: JSON.stringify({ + category: 'Photos', + keywords: ['desk', 'paper'], + confidence: 88, + suggestedName: 'desk_photo' + }) + }; + + const ocrReadsAnInvoice = () => { + const { recognizeIfAvailable } = require('../src/main/utils/tesseractUtils'); + recognizeIfAvailable.mockResolvedValueOnce({ + success: true, + text: 'Invoice #555 subtotal tax total due' + }); + const { analyzeTextWithLlama } = require('../src/main/analysis/documentLlm'); + analyzeTextWithLlama.mockResolvedValueOnce({ + category: 'Financial', + keywords: ['invoice', 'total'], + confidence: 82, + suggestedName: 'invoice_555' + }); + }; + + afterEach(() => { + mockCacheInstance.set.mockReset(); + }); + + test('after an error OCR is the last resort for (the breaker of the vision runtime is open)', async () => { + mockLlamaService.analyzeImage.mockRejectedValue( + new Error('Circuit breaker is OPEN for llama-vision') + ); + ocrReadsAnInvoice(); + + const result = await analyzeImageFile('/path/to/IMG_0412.png'); + + // The fresh request was made before OCR stood in. + expect(mockLlamaService.analyzeImage).toHaveBeenCalledTimes(2); + expect(result.category).toBe('Financial'); + expect(result.analysisWarning).toMatch(/circuit breaker is open/i); + expect(mockCacheInstance.set).not.toHaveBeenCalled(); + }); + + test('when the vision model cannot take images right now', async () => { + mockLlamaService.supportsVisionInput.mockResolvedValue(false); + ocrReadsAnInvoice(); + + const result = await analyzeImageFile('/path/to/IMG_0412.png'); + + expect(mockLlamaService.analyzeImage).not.toHaveBeenCalled(); + expect(result.category).toBe('Financial'); + expect(mockCacheInstance.set).not.toHaveBeenCalled(); + }); + + test('so the next analysis of the image asks the vision model again', async () => { + const remembered = new Map(); + mockCacheInstance.set.mockImplementation((key, value) => remembered.set(key, value)); + mockCacheInstance.get.mockImplementation((key) => remembered.get(key) ?? null); + mockLlamaService.analyzeImage + .mockRejectedValueOnce(new Error('Circuit breaker is OPEN for llama-vision')) + .mockRejectedValueOnce(new Error('Circuit breaker is OPEN for llama-vision')) + .mockResolvedValue(visionAnswer); + ocrReadsAnInvoice(); + + const first = await analyzeImageFile('/path/to/IMG_0412.png'); + const second = await analyzeImageFile('/path/to/IMG_0412.png'); + + expect(first.category).toBe('Financial'); + expect(mockLlamaService.analyzeImage).toHaveBeenCalledTimes(3); + expect(second.category).toBe('Photos'); + expect(second.analysisWarning).toBeUndefined(); + // What the vision model said is what later analyses get back. + expect([...remembered.values()].map((entry) => entry.category)).toEqual(['Photos']); + }); + }); + describe('hand-off to the watchers once the queue accepts the image vector', () => { const visionResponse = { response: JSON.stringify({ category: 'Docs', keywords: ['a', 'b'], confidence: 80 }) diff --git a/test/integration/analyzeNameOrganize.e2e.test.js b/test/integration/analyzeNameOrganize.e2e.test.js index fdba5f1..3b7c7d2 100644 --- a/test/integration/analyzeNameOrganize.e2e.test.js +++ b/test/integration/analyzeNameOrganize.e2e.test.js @@ -60,6 +60,7 @@ jest.mock('../../src/main/ipc/files/batchRollback', () => ({ jest.mock('../../src/main/ipc/files/batchProgressReporter', () => ({ sendFileOperationBatchComplete: jest.fn(), + flushOperationProgress: jest.fn(), sendOperationProgress: jest.fn(), sendChunkedResults: jest.fn().mockResolvedValue({ sent: true, totalChunks: 0 }) })); diff --git a/test/integration/imageAnalysisPipeline.integration.test.js b/test/integration/imageAnalysisPipeline.integration.test.js index 1d5f176..2a0c895 100644 --- a/test/integration/imageAnalysisPipeline.integration.test.js +++ b/test/integration/imageAnalysisPipeline.integration.test.js @@ -27,6 +27,7 @@ jest.mock('fs', () => ({ jest.mock('sharp', () => { const mockSharp = jest.fn(() => ({ metadata: jest.fn().mockResolvedValue({ width: 800, height: 600, format: 'png' }), + rotate: jest.fn().mockReturnThis(), resize: jest.fn().mockReturnThis(), png: jest.fn().mockReturnThis(), toBuffer: jest.fn().mockResolvedValue(Buffer.from('processed-image-data')) diff --git a/test/ipcMiddleware.progressWithoutAnalysis.test.js b/test/ipcMiddleware.progressWithoutAnalysis.test.js new file mode 100644 index 0000000..f551a44 --- /dev/null +++ b/test/ipcMiddleware.progressWithoutAnalysis.test.js @@ -0,0 +1,112 @@ +/** + * @jest-environment jsdom + */ +/** + * Stop clears the counts of an analysis and tells main. A report main sent + * just before it heard of the Stop arrives after that. Written to the store, + * it put counts back with no analysis running, and Discover reads those as + * "Analysis paused. Click to resume." Real analysis reducer, real middleware. + */ +import { configureStore } from '@reduxjs/toolkit'; + +jest.mock('../src/shared/logger', () => { + const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() }; + return { logger, createLogger: jest.fn(() => logger) }; +}); + +describe('a batch report that arrives with no analysis running', () => { + let store; + let fromMain; + let slice; + let cleanupIpcListeners; + let domEvents; + const onDomEvent = (event) => domEvents.push(event.detail); + + beforeEach(() => { + jest.useFakeTimers(); + jest.resetModules(); + window.electronAPI = { + events: { + onOperationProgress: jest.fn((handler) => { + fromMain = handler; + return jest.fn(); + }) + } + }; + slice = require('../src/renderer/store/slices/analysisSlice'); + const middleware = require('../src/renderer/store/middleware/ipcMiddleware'); + cleanupIpcListeners = middleware.cleanupIpcListeners; + store = configureStore({ + reducer: { analysis: slice.default }, + middleware: (getDefault) => + getDefault({ serializableCheck: false, immutableCheck: false }).concat(middleware.default) + }); + middleware.markStoreReady(); + domEvents = []; + window.addEventListener('operation-progress', onDomEvent); + }); + + afterEach(() => { + window.removeEventListener('operation-progress', onDomEvent); + cleanupIpcListeners(true); + jest.useRealTimers(); + delete window.electronAPI; + }); + + const counts = () => { + const { current, total } = store.getState().analysis.analysisProgress; + return { current, total }; + }; + + test('after Stop, a report that was on its way is not written', () => { + store.dispatch(slice.startAnalysis({ total: 7 })); + fromMain({ type: 'batch_analyze', completed: 1, total: 7 }); + expect(counts()).toEqual({ current: 1, total: 7 }); + // What Stop dispatches. + store.dispatch(slice.stopAnalysis()); + store.dispatch(slice.updateProgress({ current: 0, total: 0, lastActivity: 0 })); + jest.advanceTimersByTime(200); + + fromMain({ type: 'batch_analyze', completed: 2, total: 7 }); + jest.advanceTimersByTime(200); + + expect(counts()).toEqual({ current: 0, total: 0 }); + expect(store.getState().analysis.isAnalyzing).toBe(false); + }); + + test('before any analysis, a report of a batch nobody here started is not written', () => { + fromMain({ type: 'batch_analyze', completed: 3, total: 9 }); + jest.advanceTimersByTime(200); + + expect(counts()).toEqual({ current: 0, total: 0 }); + }); + + test('the report still reaches the listeners of the page', () => { + fromMain({ type: 'batch_analyze', completed: 3, total: 9 }); + + expect(domEvents).toEqual([expect.objectContaining({ type: 'batch_analyze', completed: 3 })]); + }); + + test('with an analysis running, a report is written as before', () => { + store.dispatch(slice.startAnalysis({ total: 7 })); + + fromMain({ type: 'batch_analyze', completed: 4, total: 7 }); + jest.advanceTimersByTime(200); + + expect(counts()).toEqual({ current: 4, total: 7 }); + }); + + test('the next analysis shows its own reports', () => { + store.dispatch(slice.startAnalysis({ total: 7 })); + store.dispatch(slice.stopAnalysis()); + store.dispatch(slice.updateProgress({ current: 0, total: 0, lastActivity: 0 })); + fromMain({ type: 'batch_analyze', completed: 6, total: 7 }); + jest.advanceTimersByTime(200); + + store.dispatch(slice.startAnalysis({ total: 3 })); + fromMain({ type: 'batch_analyze', completed: 1, total: 3 }); + jest.advanceTimersByTime(200); + + expect(counts()).toEqual({ current: 1, total: 3 }); + }); +}); diff --git a/test/mediaAnalysis.test.js b/test/mediaAnalysis.test.js index 6b30282..8374348 100644 --- a/test/mediaAnalysis.test.js +++ b/test/mediaAnalysis.test.js @@ -38,6 +38,7 @@ const { VIDEO_EXTENSIONS } = require('../src/main/analysis/mediaAnalysis'); const { ERROR_CODES } = require('../src/shared/errorCodes'); +const { isFallbackAnalysis, isCapabilityFallback } = require('../src/shared/analysisProvenance'); describe('classifyMediaFile', () => { test.each([ @@ -414,6 +415,117 @@ describe('analyzeMediaFile — audio path', () => { }); }); +// The text model reports a failure it survived by returning `{ error }`, not +// by throwing. Spread into the result, that object was stored as a finished +// 'whisper-transcription' analysis with confidence 0: never retried, and +// embedded with no keywords. +describe('analyzeMediaFile — the text model gives no answer for a transcript', () => { + const podcast = () => + fakeWhisper({ + text: 'a podcast episode', + segments: [{ start: 0, end: 1, text: 'a podcast episode' }], + language: 'en', + durationSeconds: 1.0 + }); + const analyze = (analyzeTextWithLlama) => + analyzeMediaFile('/mock/podcast.mp3', { whisperService: podcast(), analyzeTextWithLlama }); + + test('a failure it returns is recorded as provisional, not as a finished analysis', async () => { + const result = await analyze(async () => ({ + error: 'AI engine error for document: llama_decode failed', + keywords: [], + confidence: 0, + failureMode: 'llm-engine-error' + })); + + expect(isFallbackAnalysis(result)).toBe(true); + expect(isCapabilityFallback(result)).toBe(true); + expect(result.error).toMatch(/llama_decode failed/); + expect(result.category).toBe('audio'); + expect(result.confidence).toBe(60); + }); + + // The watcher decides on the history row, and the row keeps neither + // `isFallback` flag: only `provisional` and the reason survive. + test('the row history stores is still one the watcher retries', async () => { + const { recordAnalysisResult } = require('../src/main/ipc/analysisUtils'); + const result = await analyze(async () => ({ error: 'LLM unavailable', keywords: [] })); + const recordAnalysis = jest.fn().mockResolvedValue(undefined); + + await recordAnalysisResult({ + filePath: '/mock/podcast.mp3', + result, + processingTime: 1, + modelType: 'llm', + analysisHistory: { recordAnalysis }, + logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() }, + fileStats: /** @type {any} */ ({ size: 10, mtimeMs: 1000 }) + }); + + const row = recordAnalysis.mock.calls[0][1]; + expect(row).toMatchObject({ provisional: true, fallbackReason: 'ai_analysis_failed' }); + expect(row.extractionMethod).toBe('whisper-transcription'); + expect(isCapabilityFallback(row)).toBe(true); + }); + + test('the transcript is kept', async () => { + const result = await analyze(async () => ({ + error: 'AI engine error for document: llama_decode failed', + keywords: [], + confidence: 0 + })); + + expect(result.transcript).toBe('a podcast episode'); + expect(result.extractedText).toContain('a podcast episode'); + expect(result.extractionMethod).toBe('whisper-transcription'); + }); + + test('a failure it throws is provisional too', async () => { + const result = await analyze(async () => { + throw new Error('LLM unavailable'); + }); + + expect(isFallbackAnalysis(result)).toBe(true); + expect(result.error).toBe('LLM unavailable'); + }); + + test('a memory budget refusal it returns is rethrown, as one it throws', async () => { + await expect( + analyze(async () => ({ + error: 'AI engine error for document: Model memory budget exceeded', + keywords: [], + confidence: 0 + })) + ).rejects.toMatchObject({ code: 'MODEL_MEMORY_BUDGET_EXCEEDED' }); + }); + + test('an answer is not provisional', async () => { + const result = await analyze(async () => ({ + category: 'Podcasts', + keywords: ['episode'], + confidence: 80 + })); + + expect(isFallbackAnalysis(result)).toBe(false); + expect(result.error).toBeUndefined(); + expect(result.category).toBe('Podcasts'); + }); + + test('a file with no speech is not sent to the model and is not a model failure', async () => { + const whisperService = fakeWhisper({ text: '', segments: [], language: null }); + const analyzeTextWithLlama = jest.fn(); + + const result = await analyzeMediaFile('/mock/silence.wav', { + whisperService, + analyzeTextWithLlama + }); + + expect(analyzeTextWithLlama).not.toHaveBeenCalled(); + expect(result.error).toBeUndefined(); + expect(result.fallbackReason).toBeUndefined(); + }); +}); + describe('analyzeMediaFile — video path', () => { test('extracts keyframes alongside transcript when captioning is on', async () => { const whisperService = fakeWhisper({ diff --git a/test/suggestionRanker.test.js b/test/suggestionRanker.test.js index 4c47f8b..ff0927c 100644 --- a/test/suggestionRanker.test.js +++ b/test/suggestionRanker.test.js @@ -151,6 +151,14 @@ describe('Suggestion Ranker', () => { expect(calculateConfidence({ confidence: 0, score: 0.4 })).toBe(0.4); }); + // The cluster boost multiplies `score` by 1.3 for ranking, so a strong + // match arrives here above 1. Organize reads anything above 1 as a + // percentage, which turned 1.24 into "1% confidence" on the card. + test('never reports more than 1 for a score a ranking boost pushed past it', () => { + expect(calculateConfidence({ confidence: 0.75, score: 0.95 * 1.3 })).toBe(1); + expect(calculateConfidence({ score: 1.01 })).toBe(1); + }); + test('does not boost confidence for multiple sources alone', () => { const confidence = calculateConfidence({ confidence: 0.7, diff --git a/test/useAnalysis.test.js b/test/useAnalysis.test.js index 55988f4..a4f40ba 100644 --- a/test/useAnalysis.test.js +++ b/test/useAnalysis.test.js @@ -852,6 +852,28 @@ describe('useAnalysis', () => { ]); }); + test('a slow file on the per-file path fails alone; the run goes on', async () => { + // A file gets 5 minutes, the same as the no-progress limit, and the + // run's clock started a moment before the file's. The run was stopped + // just before the file would have failed and made room for the next. + const { hook, finish } = await startPerFileRun('/slow'); + + for (let minute = 0; minute < 6; minute += 1) { + await act(async () => { + await jest.advanceTimersByTimeAsync(60 * 1000); + }); + } + + expect( + mockAddNotification.mock.calls.filter((call) => call[3] === 'analysis-timeout') + ).toEqual([]); + + act(() => { + hook.result.current.cancelAnalysis(); + }); + await finish(); + }); + test('fallback pool skips files whose results already streamed in [F-154]', async () => { const { result } = renderHook(() => useAnalysis(createMockOptions())); const files = Array.from({ length: 40 }, (_, index) => ({ @@ -891,6 +913,105 @@ describe('useAnalysis', () => { expect(analyzedPaths).toContain(files[1].path); }); + describe('a run that stops making progress', () => { + // Two checks watched the same clock: one after 5 minutes that reset the + // run and said nothing, one after 10 that would have said why. The + // first always won, so the progress bar went away with no word. + const stalledFiles = Array.from({ length: 40 }, (_, index) => ({ + path: '/stalled/file-' + index + '.txt', + name: 'file-' + index + '.txt' + })); + const timeoutNotices = () => + mockAddNotification.mock.calls.filter((call) => call[3] === 'analysis-timeout'); + const startRun = async () => { + mockElectronAPI.analysis.cancelBatch = jest.fn().mockResolvedValue({ cancelled: true }); + // Main never answers and never reports. + mockElectronAPI.analysis.batch.mockImplementation(() => new Promise(() => {})); + const hook = renderHook(() => + useAnalysis(createMockOptions({ selectedFiles: stalledFiles })) + ); + await act(async () => { + hook.result.current.analyzeFiles(stalledFiles); + await jest.advanceTimersByTimeAsync(50); + }); + return hook; + }; + const passMinutes = async (minutes, eachMinute = () => {}) => { + for (let minute = 0; minute < minutes; minute += 1) { + await act(async () => { + eachMinute(); + await jest.advanceTimersByTimeAsync(60 * 1000); + }); + } + }; + + afterEach(() => { + delete mockElectronAPI.analysis.cancelBatch; + mockElectronAPI.analysis.batch.mockReset(); + }); + + test('ends with a notice that says why', async () => { + await startRun(); + expect(mockElectronAPI.analysis.batch).toHaveBeenCalledTimes(1); + + await passMinutes(6); + + expect(mockSetIsAnalyzing).toHaveBeenLastCalledWith(false); + expect(timeoutNotices()).toHaveLength(1); + const [message, severity] = timeoutNotices()[0]; + // No duration: the check runs every 5 minutes, so the wait is + // anywhere between 5 and 10. + expect(message).toBe( + 'Analysis was stopped because it stopped making progress. Unfinished files are ready to analyze again.' + ); + expect(severity).toBe('warning'); + }); + + test('main is told to stop the batch', async () => { + await startRun(); + const { batchId } = mockElectronAPI.analysis.batch.mock.calls[0][0]; + + await passMinutes(6); + + expect(mockElectronAPI.analysis.cancelBatch).toHaveBeenCalledWith( + expect.objectContaining({ batchId }) + ); + }); + + test('the notice is shown once, however long the app stays open', async () => { + await startRun(); + + await passMinutes(25); + + expect(timeoutNotices()).toHaveLength(1); + }); + + test('a run that main keeps reporting on is not stopped', async () => { + await startRun(); + const { batchId } = mockElectronAPI.analysis.batch.mock.calls[0][0]; + mockSetIsAnalyzing.mockClear(); + + // A long file: main re-sends its report while it works on it. + await passMinutes(25, () => { + window.dispatchEvent( + new CustomEvent('operation-progress', { + detail: { + type: 'batch_analyze', + batchId, + completed: 0, + total: stalledFiles.length, + currentFile: stalledFiles[0].path + } + }) + ); + }); + + expect(timeoutNotices()).toHaveLength(0); + expect(mockSetIsAnalyzing).not.toHaveBeenCalledWith(false); + expect(mockElectronAPI.analysis.cancelBatch).not.toHaveBeenCalled(); + }); + }); + // O-3: an analysis run is a multi-invoke user action — it must run inside // a preload trace session so all its main-process logs share one id. describe('correlation trace session (O-3)', () => { diff --git a/test/visionErrorClassification.test.js b/test/visionErrorClassification.test.js index 34597e6..e145657 100644 --- a/test/visionErrorClassification.test.js +++ b/test/visionErrorClassification.test.js @@ -1,4 +1,5 @@ const { + isVisionRuntimeDecodePressure, classifyVisionError, isVisionDecodePressureError, isVisionInputDataError @@ -13,6 +14,16 @@ describe('visionErrorClassification', () => { expect(classification.isInputData).toBe(false); }); + // The runtime's stderr travels beside the message, not in it. + test('reads decode pressure from the stderr hint an error carries', () => { + const error = Object.assign(new Error('Vision runtime error'), { + visionRuntimeHint: ' [vision-runtime: decode: failed to find a memory slot for batch]' + }); + expect(isVisionRuntimeDecodePressure(error)).toBe(true); + expect(isVisionRuntimeDecodePressure(new Error('Vision runtime error'))).toBe(false); + expect(isVisionRuntimeDecodePressure(new Error('failed to process image'))).toBe(true); + }); + test('treats unsupported format as input-data error', () => { const message = 'unsupported image format'; expect(isVisionInputDataError(message)).toBe(true); diff --git a/test/visionRequest.callerAbort.test.js b/test/visionRequest.callerAbort.test.js new file mode 100644 index 0000000..39b3e81 --- /dev/null +++ b/test/visionRequest.callerAbort.test.js @@ -0,0 +1,210 @@ +/** + * @jest-environment node + * + * A request to the vision runtime is aborted while it runs for one of two + * reasons: its caller gave up (Stop, a closed window), or the analysis ran out + * of time. Both rejected with the same plain error, which the vision breaker + * counts. Five Stops during slow inferences opened it, and for five minutes + * every image got an OCR result in place of the vision model. Only running + * out of time says anything about the runtime. + * + * Real request, real breaker, real timeout wrapper; the runtime is a local + * server that never answers. + */ +jest.mock('electron', () => ({ + app: { getPath: jest.fn(() => '/mock/userData') } +})); +jest.mock('../src/shared/logger', () => { + const logger = { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + debug: jest.fn(), + setContext: jest.fn() + }; + return { logger, createLogger: () => logger }; +}); + +const http = require('http'); +const { _requestJson } = require('../src/main/services/VisionService'); +const promiseUtils = require('../src/shared/promiseUtils'); +const { + withLlamaResilience, + cleanupLlamaCircuits, + _getCircuitBreaker +} = require('../src/main/services/LlamaResilience'); + +const { withAbortableTimeout } = promiseUtils; + +describe('a vision request that is aborted while the runtime works on it', () => { + let server; + let port; + let onArrival; + let sendRequest; + + beforeEach(async () => { + onArrival = null; + server = http.createServer(() => { + // Never answered, as an inference that is still running. + if (onArrival) onArrival(); + }); + await new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); + port = server.address().port; + sendRequest = jest.fn((signal) => + _requestJson({ + method: 'POST', + port, + path: '/v1/chat/completions', + body: { a: 1 }, + signal + }) + ); + }); + + afterEach(async () => { + cleanupLlamaCircuits(); + server.closeAllConnections(); + await new Promise((resolve) => server.close(resolve)); + }); + + const nextArrival = () => + new Promise((resolve) => { + onArrival = resolve; + }); + + /** + * The layers an image analysis puts around the request: the timeout wrapper + * hands its own signal to the guarded call. `guarded()` is the promise the + * breaker settles, which outlives the rejection the caller gets. + */ + function analyze({ callerSignal, timeoutMs = 60000 } = {}) { + let guarded; + const outcome = withAbortableTimeout( + (inner) => { + guarded = withLlamaResilience(() => sendRequest(inner.signal), { modelType: 'vision' }); + return guarded; + }, + timeoutMs, + 'Image analysis', + { signal: callerSignal } + ); + return { outcome, guarded: () => guarded.catch((error) => error) }; + } + + async function stopDuringInference() { + const caller = new AbortController(); + const arrived = nextArrival(); + const run = analyze({ callerSignal: caller.signal }); + await arrived; + caller.abort(); + await expect(run.outcome).rejects.toMatchObject({ code: 'OPERATION_CANCELLED' }); + return run.guarded(); + } + + async function runOutOfTime() { + const run = analyze({ timeoutMs: 150 }); + await expect(run.outcome).rejects.toThrow(/timed out after 150ms/); + return run.guarded(); + } + + test('five Stops in a row leave the vision breaker closed', async () => { + for (let stop = 0; stop < 5; stop += 1) { + await stopDuringInference(); + } + + expect(_getCircuitBreaker('vision').getState()).toBe('CLOSED'); + // The next image is sent to the runtime. + await stopDuringInference(); + expect(sendRequest).toHaveBeenCalledTimes(6); + }); + + // The renderer's own limit on the invoke: main aborts the handler's signal + // with this reason. The runtime did not answer in time, as above. + async function invokeTimesOut() { + const caller = new AbortController(); + const arrived = nextArrival(); + const run = analyze({ callerSignal: caller.signal }); + await arrived; + caller.abort('ipc-timeout'); + await expect(run.outcome).rejects.toMatchObject({ code: 'OPERATION_CANCELLED' }); + return run.guarded(); + } + + test('five invokes that timed out in the renderer open it too', async () => { + for (let attempt = 0; attempt < 5; attempt += 1) { + const error = await invokeTimesOut(); + expect(error.originalError || error).toMatchObject({ name: 'Error' }); + } + + expect(_getCircuitBreaker('vision').getState()).toBe('OPEN'); + }); + + test('a Stop rejects the request as an abort', async () => { + const error = await stopDuringInference(); + + expect(error.message).toMatch(/Vision request aborted/); + expect(error.originalError || error).toMatchObject({ name: 'AbortError' }); + }); + + test('five analyses that ran out of time still open it', async () => { + for (let attempt = 0; attempt < 5; attempt += 1) { + const error = await runOutOfTime(); + expect(error.originalError || error).toMatchObject({ name: 'Error' }); + } + + expect(_getCircuitBreaker('vision').getState()).toBe('OPEN'); + await expect(analyze().outcome).rejects.toThrow(/Circuit breaker is OPEN for llama-vision/); + expect(sendRequest).toHaveBeenCalledTimes(5); + }); + + describe('how the request tells the two apart', () => { + const innerSignalOf = async ({ callerSignal, timeoutMs }) => { + let innerSignal; + await withAbortableTimeout( + (inner) => { + innerSignal = inner.signal; + return new Promise(() => {}); + }, + timeoutMs, + 'Image analysis', + { signal: callerSignal } + ).catch(() => {}); + return innerSignal; + }; + + test('the timeout wrapper marks the signal it aborts when the time ran out', async () => { + const signal = await innerSignalOf({ timeoutMs: 20 }); + + expect(signal.aborted).toBe(true); + expect(promiseUtils.isTimeoutAbort(signal)).toBe(true); + // Work that rethrows the reason is classified as it was before. + expect(signal.reason).toMatchObject({ + name: 'AbortError', + message: 'This operation was aborted' + }); + }); + + test('and does not mark it when the caller gave up', async () => { + const caller = new AbortController(); + setTimeout(() => caller.abort(), 10); + + const signal = await innerSignalOf({ callerSignal: caller.signal, timeoutMs: 60000 }); + + expect(signal.aborted).toBe(true); + expect(promiseUtils.isTimeoutAbort(signal)).toBe(false); + }); + + test('a signal of AbortSignal.timeout counts as running out of time', async () => { + const signal = AbortSignal.timeout(5); + await new Promise((resolve) => signal.addEventListener('abort', resolve, { once: true })); + + expect(promiseUtils.isTimeoutAbort(signal)).toBe(true); + }); + + test('a signal that was not aborted, or no signal, does not', () => { + expect(promiseUtils.isTimeoutAbort(new AbortController().signal)).toBe(false); + expect(promiseUtils.isTimeoutAbort(null)).toBe(false); + expect(promiseUtils.isTimeoutAbort(undefined)).toBe(false); + }); + }); +});