From 61866ec6a8c9ac13c29de0381347805f245b8eeb Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:01:13 -0500 Subject: [PATCH 01/18] fix: the watcher drops its own read echo, skips empty vision batches; folder descriptions keep their s The watcher's read of a file updates its NTFS last-access time, which chokidar 6 reports as a change for a file that was there at startup. The file was queued again while its analysis was still running. A change event for a file being analyzed is now dropped when its mtime and size are the ones the analysis started with. An image batch whose items the history already has no longer enters vision batch mode (text and embedding unloaded, vision runtime started, text loaded again) to analyze nothing. unquoteDescription's character class held a literal s where \s was meant, so Organize's target-folder cards cut the letter s off both ends of every description. --- src/main/services/SmartFolderWatcher.js | 83 ++++++++++- .../components/organize/TargetFolderList.jsx | 2 +- test/SmartFolderWatcher.readEcho.test.js | 130 ++++++++++++++++++ ...martFolderWatcher.visionBatchOwner.test.js | 73 ++++++++++ ...argetFolderList.unquoteDescription.test.js | 38 +++++ 5 files changed, 324 insertions(+), 2 deletions(-) create mode 100644 test/SmartFolderWatcher.readEcho.test.js create mode 100644 test/components/TargetFolderList.unquoteDescription.test.js diff --git a/src/main/services/SmartFolderWatcher.js b/src/main/services/SmartFolderWatcher.js index 72d4edf..9cc14d4 100644 --- a/src/main/services/SmartFolderWatcher.js +++ b/src/main/services/SmartFolderWatcher.js @@ -309,6 +309,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 = []; @@ -942,6 +947,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 +1402,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 +1446,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 @@ -2381,10 +2414,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; @@ -2543,6 +2590,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. @@ -2752,6 +2828,10 @@ class SmartFolderWatcher { // Verify file still exists and capture stats for reuse below const fileStats = await fs.stat(filePath); + this._analysisStartStats.set(processingKey, { + mtimeMs: fileStats.mtimeMs, + size: fileStats.size + }); // 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 @@ -3193,6 +3273,7 @@ class SmartFolderWatcher { } } finally { this.processingFiles.delete(processingKey); + this._analysisStartStats.delete(processingKey); } } 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/test/SmartFolderWatcher.readEcho.test.js b/test/SmartFolderWatcher.readEcho.test.js new file mode 100644 index 0000000..c5e0714 --- /dev/null +++ b/test/SmartFolderWatcher.readEcho.test.js @@ -0,0 +1,130 @@ +/** + * @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' }) + ]); + }); + + 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.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/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(''); + }); +}); From 401f4c3c30515e82558de54c7414a1bc8fd098d0 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:07:38 -0500 Subject: [PATCH 02/18] fix: content dates reject odd years, keep a day written with Z; search shows a document's day A written year of 0000-0099 was read as 1900-1999 and passed the plausibility window; a year of five or six digits passed on its first four. "2024-05-05Z" moved back a day west of Greenwich. Search results and cluster time ranges parsed a date-only document date as UTC midnight and showed the day before. Two tests depended on the zone they ran in. --- src/main/services/ClusteringService.js | 10 +-- src/renderer/components/search/ResultRow.jsx | 8 +- src/shared/contentDateSanity.js | 66 +++++++++++++---- test/ClusteringService.test.js | 30 ++++++++ test/analysisIpc.realZod.test.js | 6 +- test/calendarDayLocalTime.test.js | 74 ++++++++++++++++++- .../components/ResultRow.documentDate.test.js | 63 ++++++++++++++++ test/contentDateSanity.test.js | 9 +++ test/imageAnalysis.behavior.test.js | 4 +- 9 files changed, 245 insertions(+), 25 deletions(-) create mode 100644 test/components/ResultRow.documentDate.test.js 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/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/shared/contentDateSanity.js b/src/shared/contentDateSanity.js index 8594580..fa6ad45 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} */ @@ -81,13 +114,19 @@ function toWrittenCalendarDay(value) { } 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 +136,6 @@ module.exports = { isPlausibleContentDate, isIsoDateOnly, toLocalCalendarDay, + toLocalCalendarMs, toWrittenCalendarDay }; diff --git a/test/ClusteringService.test.js b/test/ClusteringService.test.js index 2d0881c..95a35f2 100644 --- a/test/ClusteringService.test.js +++ b/test/ClusteringService.test.js @@ -590,6 +590,36 @@ 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); + }); + test('derives member path and folder from metadata.filePath fallback', () => { service.clusters = [ { diff --git a/test/analysisIpc.realZod.test.js b/test/analysisIpc.realZod.test.js index 9d750d2..b70a969 100644 --- a/test/analysisIpc.realZod.test.js +++ b/test/analysisIpc.realZod.test.js @@ -269,10 +269,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/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..1192364 --- /dev/null +++ b/test/components/ResultRow.documentDate.test.js @@ -0,0 +1,63 @@ +/** + * @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'; + +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(); + }); + + 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/contentDateSanity.test.js b/test/contentDateSanity.test.js index 37efe68..f6dd8b4 100644 --- a/test/contentDateSanity.test.js +++ b/test/contentDateSanity.test.js @@ -26,6 +26,15 @@ 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('rejects non-strings and short/garbage input', () => { expect(isPlausibleContentDate(null, now)).toBe(false); expect(isPlausibleContentDate(undefined, now)).toBe(false); diff --git a/test/imageAnalysis.behavior.test.js b/test/imageAnalysis.behavior.test.js index 4b07e9b..644b51e 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' }]); From 0610c054bdad73cf9b76e665c54f091dd4f25fa1 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:19:01 -0500 Subject: [PATCH 03/18] fix(watcher): an embedding retry keeps a queued request; recordings get three hours; a vanished file is not recorded - An embedding retry no longer replaces a queued reanalysis or change event for the same file (the request was lost and the old result embedded again). - Queue, in-flight map and the analysis lock use one key, so an item pushed without a dedupKey (Reanalyze all) is not started beside itself and a handed-back vision batch merges with the item queued meanwhile. - A recording gets the three hours a Discover run allows, not ten minutes. - A file deleted or renamed during its analysis gets no history entry, notification or learning feedback. --- src/main/services/SmartFolderWatcher.js | 99 +++++++-- ...olderWatcher.embeddingRetryReplace.test.js | 207 ++++++++++++++++++ test/SmartFolderWatcher.mediaTimeout.test.js | 108 +++++++++ test/SmartFolderWatcher.vanishedFile.test.js | 142 ++++++++++++ 4 files changed, 542 insertions(+), 14 deletions(-) create mode 100644 test/SmartFolderWatcher.embeddingRetryReplace.test.js create mode 100644 test/SmartFolderWatcher.mediaTimeout.test.js create mode 100644 test/SmartFolderWatcher.vanishedFile.test.js diff --git a/src/main/services/SmartFolderWatcher.js b/src/main/services/SmartFolderWatcher.js index 9cc14d4..4816df4 100644 --- a/src/main/services/SmartFolderWatcher.js +++ b/src/main/services/SmartFolderWatcher.js @@ -141,15 +141,26 @@ 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. + * + * A model pass that was still to come stays to come. An embedding retry + * carries the result of the pass before it (`cachedAnalysis`) and only + * embeds that again: left on the item, the file was never read again. * @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 (!replaced.cachedAnalysis && replacement.cachedAnalysis) { + delete replacement.cachedAnalysis; + delete replacement._lastAnalysis; + } + if (replaced.eventType !== 'reanalyze' || replacement.eventType === 'reanalyze') return; replacement.eventType = 'reanalyze'; replacement.applyNaming = replaced.applyNaming; if (replaced.bulk) replacement.bulk = true; @@ -1488,7 +1499,15 @@ 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. + if (item.cachedAnalysis && !existing.cachedAnalysis) { + return; + } + keepAnalysisRequest(existing, item); this.analysisQueue[existingIndex] = item; this._scheduleQueuePersist(); return; @@ -2175,7 +2194,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) { @@ -2186,6 +2205,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 @@ -2354,9 +2411,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); @@ -2469,7 +2528,7 @@ class SmartFolderWatcher { const handedBack = []; for (const waiting of rest) { const newer = queuedByKey.get(procKey(waiting)); - if (newer) keepReanalysisRequest(waiting, newer); + if (newer) keepAnalysisRequest(waiting, newer); else handedBack.push(waiting); this._inFlightItems.delete(procKey(waiting)); } @@ -2627,8 +2686,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); } /** @@ -2921,6 +2979,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); diff --git a/test/SmartFolderWatcher.embeddingRetryReplace.test.js b/test/SmartFolderWatcher.embeddingRetryReplace.test.js new file mode 100644 index 0000000..9201ac8 --- /dev/null +++ b/test/SmartFolderWatcher.embeddingRetryReplace.test.js @@ -0,0 +1,207 @@ +/** + * @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); + expect(watcher.analysisQueue[0].filePath).toBe(second); + expect(watcher.analysisQueue[0].cachedAnalysis).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.vanishedFile.test.js b/test/SmartFolderWatcher.vanishedFile.test.js new file mode 100644 index 0000000..864b022 --- /dev/null +++ b/test/SmartFolderWatcher.vanishedFile.test.js @@ -0,0 +1,142 @@ +/** + * @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 is gone does nothing', async () => { + const watcher = makeWatcher(async () => {}); + fs.rmSync(file); + + await watcher._analyzeFile({ + filePath: file, + eventType: 'add', + retryCount: 1, + cachedAnalysis: RESULT + }); + + 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); + }); +}); From fdddbdb9dd635793dda65f4fa47aac58f762c52c Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:37:26 -0500 Subject: [PATCH 04/18] fix(analysis): a batch can be stopped while its paths are checked, ends with its renderer, and sends no progress after it ended - The run is registered before the path check, so a Stop that arrives during the check finds it. The check reads the disk for every file; a Stop in that time was answered 'unknown batch' and never sent again. - A batch is cancelled when the renderer that asked for it is destroyed, loses its process or loads the page again. It ran on with no owner before: the watcher waited behind it and a new Analyze ran the same files beside it. - A progress report held back by the throttle is dropped when its batch was cancelled or has ended by the time the window closes, and the renderer does not write a batch report to the store while no analysis is running. - The history keeps the size and date a file had before its analysis, not those of a version saved while the model worked. --- src/main/ipc/analysis.js | 352 ++++++++++------ src/main/ipc/files/batchProgressReporter.js | 25 +- .../store/middleware/ipcMiddleware.js | 19 +- test/analysisIpc.batchLifecycle.test.js | 386 ++++++++++++++++++ ...atchProgressReporter.trailingFlush.test.js | 102 +++++ ...Middleware.progressWithoutAnalysis.test.js | 112 +++++ 6 files changed, 862 insertions(+), 134 deletions(-) create mode 100644 test/analysisIpc.batchLifecycle.test.js create mode 100644 test/batchProgressReporter.trailingFlush.test.js create mode 100644 test/ipcMiddleware.progressWithoutAnalysis.test.js diff --git a/src/main/ipc/analysis.js b/src/main/ipc/analysis.js index aec3ecb..d127c8b 100644 --- a/src/main/ipc/analysis.js +++ b/src/main/ipc/analysis.js @@ -44,6 +44,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 +148,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 +156,8 @@ async function applyUserNamingFromSettings( settingsService, logger, logPrefix, - namingOverride = null + namingOverride = null, + fileStats = null ) { if (!result || typeof result !== 'object') { return result; @@ -120,7 +180,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 +546,7 @@ function registerAnalysisIpc(servicesOrParams) { getFolderNamesString(folderCategories) ); + const statsBefore = await statBeforeAnalysis(cleanPath); const result = await analyzeDocumentFile(cleanPath, folderCategories, { abortSignal }); await applyUserNamingFromSettings( cleanPath, @@ -493,7 +554,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -504,6 +566,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'llm', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -608,6 +671,7 @@ function registerAnalysisIpc(servicesOrParams) { getFolderNamesString(folderCategories) ); + const statsBefore = await statBeforeAnalysis(cleanPath); const result = await analyzeImageFile(cleanPath, folderCategories, { abortSignal }); await applyUserNamingFromSettings( cleanPath, @@ -615,7 +679,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, IMAGE_LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -626,6 +691,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'vision', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -736,6 +802,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 +810,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, MEDIA_LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const duration = performance.now() - startTime; systemAnalytics?.recordProcessingTime?.(duration); @@ -754,6 +822,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime: duration, modelType: 'whisper', + fileStats: await statsToRecord(cleanPath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -872,91 +941,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 +962,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 +985,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 +1129,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 +1197,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 +1207,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, LOG_PREFIX, - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1130,6 +1216,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'llm', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1148,6 +1235,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 +1245,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, '[IPC-IMAGE-ANALYSIS]', - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1165,6 +1254,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'vision', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1200,6 +1290,7 @@ function registerAnalysisIpc(servicesOrParams) { whisperService: safeGetWhisperService() }) ); + const statsBefore = await statBeforeAnalysis(filePath); const result = await adapter(filePath, smartFolders, { ...opts, abortSignal: batchAbortController.signal @@ -1210,7 +1301,8 @@ function registerAnalysisIpc(servicesOrParams) { settingsService, logger, '[IPC-MEDIA-ANALYSIS]', - namingOverride + namingOverride, + statsBefore ); const processingTime = performance.now() - started; await recordAnalysisResult({ @@ -1218,6 +1310,7 @@ function registerAnalysisIpc(servicesOrParams) { result, processingTime, modelType: 'media', + fileStats: await statsToRecord(filePath, statsBefore), analysisHistory: serviceIntegration?.analysisHistory, logger }); @@ -1262,9 +1355,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..c8e44fc 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,22 +59,29 @@ 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); } 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/test/analysisIpc.batchLifecycle.test.js b/test/analysisIpc.batchLifecycle.test.js new file mode 100644 index 0000000..daf7e80 --- /dev/null +++ b/test/analysisIpc.batchLifecycle.test.js @@ -0,0 +1,386 @@ +/** + * @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() +})); + +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 } = 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); + }); +}); + +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/batchProgressReporter.trailingFlush.test.js b/test/batchProgressReporter.trailingFlush.test.js new file mode 100644 index 0000000..9e66ad3 --- /dev/null +++ b/test/batchProgressReporter.trailingFlush.test.js @@ -0,0 +1,102 @@ +/** + * @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; + 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 } = 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('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/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 }); + }); +}); From 461c20609a072940103c5b011010aacc291e3474 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:53:04 -0500 Subject: [PATCH 05/18] fix: vision and media results that stood in for a model that did not answer - An OCR result that stands in for the vision model is never cached, whatever made the vision model unavailable (open breaker, model that cannot take images, a failed request), so the next analysis asks the vision model again. - A Stop while the vision runtime works on a request no longer counts against the vision breaker. Five of them opened it and every image got OCR only for five minutes. withAbortableTimeout now marks the signal it aborts when the time ran out, and the request tells the two apart; a timeout still counts. - A failure the text model returns for an audio or video transcript (engine error, model not installed, unparseable answer) is recorded as provisional, as for documents, instead of as a finished transcription with confidence 0. A memory budget refusal returned that way is rethrown. --- src/main/analysis/imageAnalysis.js | 7 +- src/main/analysis/mediaAnalysis.js | 35 ++++- src/main/services/VisionService.js | 12 +- src/shared/promiseUtils.js | 30 +++- test/imageAnalysis.behavior.test.js | 77 ++++++++++ test/mediaAnalysis.test.js | 90 ++++++++++++ test/visionRequest.callerAbort.test.js | 191 +++++++++++++++++++++++++ 7 files changed, 433 insertions(+), 9 deletions(-) create mode 100644 test/visionRequest.callerAbort.test.js diff --git a/src/main/analysis/imageAnalysis.js b/src/main/analysis/imageAnalysis.js index 1654d3a..f9c6059 100644 --- a/src/main/analysis/imageAnalysis.js +++ b/src/main/analysis/imageAnalysis.js @@ -1667,6 +1667,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; }; @@ -1791,9 +1795,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( 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/services/VisionService.js b/src/main/services/VisionService.js index 45a05f5..0c43cf2 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 }); } diff --git a/src/shared/promiseUtils.js b/src/shared/promiseUtils.js index 46e84d5..5c269b9 100644 --- a/src/shared/promiseUtils.js +++ b/src/shared/promiseUtils.js @@ -165,6 +165,33 @@ function withTimeout(fnOrPromise, timeoutMs, operationName = 'Operation') { * 'API fetch' * ); */ +/** + * 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 or AbortSignal.timeout), 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'; +} + /** * @param {(abortController: AbortController) => Promise} fn * @param {number} timeoutMs @@ -195,7 +222,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 @@ -913,6 +940,7 @@ module.exports = { throwIfAborted, withTimeout, withAbortableTimeout, + isTimeoutAbort, createTimeoutRace, // Retry diff --git a/test/imageAnalysis.behavior.test.js b/test/imageAnalysis.behavior.test.js index 644b51e..62a563d 100644 --- a/test/imageAnalysis.behavior.test.js +++ b/test/imageAnalysis.behavior.test.js @@ -986,6 +986,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/mediaAnalysis.test.js b/test/mediaAnalysis.test.js index 6b30282..c8d37e5 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,95 @@ 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); + // Retried by the watcher once the model answers again. + expect(isCapabilityFallback(result)).toBe(true); + expect(result.error).toMatch(/llama_decode failed/); + expect(result.category).toBe('audio'); + expect(result.confidence).toBe(60); + }); + + 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/visionRequest.callerAbort.test.js b/test/visionRequest.callerAbort.test.js new file mode 100644 index 0000000..88e60ef --- /dev/null +++ b/test/visionRequest.callerAbort.test.js @@ -0,0 +1,191 @@ +/** + * @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 arrived = nextArrival(); + const run = analyze({ timeoutMs: 150 }); + await arrived; + 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); + }); + + 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); + }); + }); +}); From f3eac43743a95305f5b3f44bcac25d472ecfc202 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 08:58:15 -0500 Subject: [PATCH 06/18] fix(discover): a run that stops making progress says why it ended Two checks watched the same clock: one after 5 minutes that reset the run and said nothing, one after 10 that would have told the user. The first always won and disarmed the second, so the progress bar went away with no word. The 5-minute check now shows the notice and is the only one; the global watchdog keeps the hard cap. The test for an abort during the batch-busy wait aborted before the wait was entered and passed whatever the wait did. It now aborts while the wait runs, and fails when the abort listener or the timer cleanup is removed. --- src/renderer/phases/discover/useAnalysis.js | 43 ++++------ test/discoverBatchBusy.test.js | 47 +++++++--- test/useAnalysis.test.js | 95 +++++++++++++++++++++ 3 files changed, 147 insertions(+), 38 deletions(-) diff --git a/src/renderer/phases/discover/useAnalysis.js b/src/renderer/phases/discover/useAnalysis.js index 9d55005..343bdac 100644 --- a/src/renderer/phases/discover/useAnalysis.js +++ b/src/renderer/phases/discover/useAnalysis.js @@ -1057,7 +1057,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 +1085,12 @@ export function useAnalysis(options = {}) { }); resetAnalysisState('Analysis lock timeout'); lockTimeoutRef.current = null; + addNotification( + `Analysis was stopped after no progress for ${Math.round(thresholdMs / 60000)} min. Unfinished files are ready to analyze again.`, + 'warning', + 5000, + 'analysis-timeout' + ); }, TIMEOUTS.ANALYSIS_LOCK); }; scheduleLockTimeoutCheck(); @@ -1154,22 +1162,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 +1192,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 +1211,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 +1224,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 +1321,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`); 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/useAnalysis.test.js b/test/useAnalysis.test.js index 55988f4..3e7b4b4 100644 --- a/test/useAnalysis.test.js +++ b/test/useAnalysis.test.js @@ -891,6 +891,101 @@ 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]; + expect(message).toMatch(/stopped after no progress for 5 min/); + 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)', () => { From dea1f6e0606f8c954e018a5217a421654c5bd6d3 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 09:02:49 -0500 Subject: [PATCH 07/18] fix(memory): a text model that is still loading counts as holding the GPU Two checks asked only whether the text model was in memory, while the budget already counted one that was being loaded. - An embedding load that started during the text load was offered no CPU option: it waited for the text model to go idle and then evicted it. - In a vision batch, an image that arrived during the text load respawned the vision runtime on top of it. ModelMemoryManager.isLoadedOrLoading answers for both states and does not count as using the model. --- src/main/services/LlamaService.js | 14 +-- src/main/services/ModelMemoryManager.js | 13 +++ test/LlamaService.inference.test.js | 29 ++++++- test/embeddingBesideText.test.js | 111 +++++++++++++++++++++++- 4 files changed, 159 insertions(+), 8 deletions(-) diff --git a/src/main/services/LlamaService.js b/src/main/services/LlamaService.js index 2ecb09b..b051678 100644 --- a/src/main/services/LlamaService.js +++ b/src/main/services/LlamaService.js @@ -4221,13 +4221,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 must wait for that + * load and free its memory before respawning the runtime. * @returns {boolean} * @private */ _textResidentWhileVisionDown() { - if (!this._visionBatchMode || !this._modelMemoryManager?.getLoadedContext?.('text')) { + if (!this._visionBatchMode || !this._modelMemoryManager?.isLoadedOrLoading?.('text')) { return false; } try { @@ -4238,8 +4239,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 +4254,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. diff --git a/src/main/services/ModelMemoryManager.js b/src/main/services/ModelMemoryManager.js index 02abeb4..5641567 100644 --- a/src/main/services/ModelMemoryManager.js +++ b/src/main/services/ModelMemoryManager.js @@ -210,6 +210,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 */ diff --git a/test/LlamaService.inference.test.js b/test/LlamaService.inference.test.js index 9245456..67c13b4 100644 --- a/test/LlamaService.inference.test.js +++ b/test/LlamaService.inference.test.js @@ -377,7 +377,7 @@ 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 }; @@ -387,6 +387,9 @@ describe('LlamaService – inference methods', () => { 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,6 +402,7 @@ describe('LlamaService – inference methods', () => { afterEach(() => { delete mockModelMemoryManager.getLoadedContext; + delete mockModelMemoryManager.isLoadedOrLoading; delete mockVisionService.isAlive; }); @@ -419,6 +423,29 @@ 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('waits out a text load still in progress before respawning vision', async () => { + const service = batchImageService({ + textResident: false, + textLoading: true, + visionAlive: false + }); + await service.analyzeImage({ imagePath: '/test.jpg', prompt: 'describe' }); + expect(service._releaseMemoryForVisionRuntime).toHaveBeenCalledWith('batch'); + }); + + 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/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); + }); }); From ed454e6baccb4810692c5129fe2f9a28d594820a Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 10:47:09 -0500 Subject: [PATCH 08/18] fix(organize): a boosted match no longer shows as 1% confidence The cluster boost multiplies a suggestion's score by 1.3 for ranking, and calculateConfidence returned the higher of confidence and score without a ceiling. Organize reads a confidence above 1 as a percentage, so 1.24 became 0.0124 and the card showed 1% for the strongest matches. --- src/main/services/organization/suggestionRanker.js | 4 ++++ test/suggestionRanker.test.js | 8 ++++++++ 2 files changed, 12 insertions(+) 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/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, From 6580ea6e874c7ed7751999fd68aca0abbd6b5151 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 10:49:42 -0500 Subject: [PATCH 09/18] fix(memory): an oversized text load stops waiting once nothing else holds memory The wait for room ran to its deadline when the model's own estimate was larger than the budget, though nothing else was left to release. Optional work may use a model that is the only one loaded, and is refused while the model is being disposed. A load in progress is counted at its refined size. --- src/main/ipc/semantic.js | 2 +- src/main/services/ModelMemoryManager.js | 23 ++++++-- test/ModelMemoryManager.pendingLoads.test.js | 58 ++++++++++++++++++++ test/ModelMemoryManager.test.js | 4 +- 4 files changed, 81 insertions(+), 6 deletions(-) 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/ModelMemoryManager.js b/src/main/services/ModelMemoryManager.js index 5641567..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), @@ -377,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. * @@ -387,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() @@ -488,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/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); From 827cebf5f2b3ca018faa92da23bcdb18878685f3 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 10:53:02 -0500 Subject: [PATCH 10/18] fix: review follow-ups (invoke timeouts, numeric dates, Whisper beside a loading text model, slow per-file runs) - An invoke the renderer timed out counts against the vision breaker again; only a caller that gave up is left out. - A numeric date from the model is a year or nothing, never milliseconds. - Whisper runs on the CPU while the text model is still being loaded onto a GPU that cannot hold both. - On the per-file path a slow file fails alone instead of ending the run. - The no-progress notice no longer states a duration it cannot know. - JSON repair and prose extraction timeouts read once, not twice. --- src/main/services/WhisperService.js | 11 ++-- src/main/utils/llmJsonRepair.js | 4 +- src/renderer/phases/discover/useAnalysis.js | 12 ++++- src/shared/contentDateSanity.js | 5 ++ src/shared/promiseUtils.js | 57 +++++++++++---------- test/WhisperService.test.js | 8 +++ test/contentDateSanity.test.js | 10 ++++ test/useAnalysis.test.js | 28 +++++++++- test/visionRequest.callerAbort.test.js | 23 ++++++++- 9 files changed, 122 insertions(+), 36 deletions(-) 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/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/phases/discover/useAnalysis.js b/src/renderer/phases/discover/useAnalysis.js index 343bdac..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 @@ -1086,7 +1090,7 @@ export function useAnalysis(options = {}) { resetAnalysisState('Analysis lock timeout'); lockTimeoutRef.current = null; addNotification( - `Analysis was stopped after no progress for ${Math.round(thresholdMs / 60000)} min. Unfinished files are ready to analyze again.`, + 'Analysis was stopped because it stopped making progress. Unfinished files are ready to analyze again.', 'warning', 5000, 'analysis-timeout' @@ -1615,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/shared/contentDateSanity.js b/src/shared/contentDateSanity.js index fa6ad45..8b31602 100644 --- a/src/shared/contentDateSanity.js +++ b/src/shared/contentDateSanity.js @@ -112,6 +112,11 @@ 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; const written = diff --git a/src/shared/promiseUtils.js b/src/shared/promiseUtils.js index 5c269b9..df6f606 100644 --- a/src/shared/promiseUtils.js +++ b/src/shared/promiseUtils.js @@ -147,24 +147,10 @@ function withTimeout(fnOrPromise, timeoutMs, operationName = 'Operation') { }; } -/** - * Execute a promise with timeout and AbortController support. - * Enhanced version of withTimeout that provides an AbortController signal - * to the promise factory, allowing the underlying operation to be cancelled. - * - * @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 - * @returns {Promise<*>} Result of the promise - * @throws {Error} If the operation times out or the promise rejects - * - * @example - * const result = await withAbortableTimeout( - * (abortController) => fetch(url, { signal: abortController.signal }), - * 5000, - * 'API fetch' - * ); - */ +// 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 @@ -182,22 +168,37 @@ function createTimeoutAbortReason() { /** * True when the signal was aborted because the time ran out (by - * withAbortableTimeout or AbortSignal.timeout), false when its caller gave up. + * 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'; + return ( + reason?.timedOut === true || reason?.name === 'TimeoutError' || reason === IPC_TIMEOUT_REASON + ); } /** - * @param {(abortController: AbortController) => Promise} fn - * @param {number} timeoutMs - * @param {string} [operationName] - * @param {{ signal?: AbortSignal }} [options] - * @returns {Promise} + * Execute a promise with timeout and AbortController support. + * Enhanced version of withTimeout that provides an AbortController signal + * to the promise factory, allowing the underlying operation to be cancelled. + * + * @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 + * + * @example + * const result = await withAbortableTimeout( + * (abortController) => fetch(url, { signal: abortController.signal }), + * 5000, + * 'API fetch' + * ); */ async function withAbortableTimeout(fn, timeoutMs, operationName = 'Operation', options = {}) { const externalSignal = options.signal || null; @@ -235,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 }); 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/contentDateSanity.test.js b/test/contentDateSanity.test.js index f6dd8b4..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'); @@ -35,6 +36,15 @@ describe('isPlausibleContentDate (F-158)', () => { 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/useAnalysis.test.js b/test/useAnalysis.test.js index 3e7b4b4..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) => ({ @@ -937,7 +959,11 @@ describe('useAnalysis', () => { expect(mockSetIsAnalyzing).toHaveBeenLastCalledWith(false); expect(timeoutNotices()).toHaveLength(1); const [message, severity] = timeoutNotices()[0]; - expect(message).toMatch(/stopped after no progress for 5 min/); + // 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'); }); diff --git a/test/visionRequest.callerAbort.test.js b/test/visionRequest.callerAbort.test.js index 88e60ef..39b3e81 100644 --- a/test/visionRequest.callerAbort.test.js +++ b/test/visionRequest.callerAbort.test.js @@ -102,9 +102,7 @@ describe('a vision request that is aborted while the runtime works on it', () => } async function runOutOfTime() { - const arrived = nextArrival(); const run = analyze({ timeoutMs: 150 }); - await arrived; await expect(run.outcome).rejects.toThrow(/timed out after 150ms/); return run.guarded(); } @@ -120,6 +118,27 @@ describe('a vision request that is aborted while the runtime works on it', () => 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(); From 6bb723fc8967a08a186b1c1434622dacfcec7bec Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 10:56:17 -0500 Subject: [PATCH 11/18] fix(analysis): a batch that ran to its end sends its closing progress report The report was held by the throttle and dropped once the run was unregistered, so the search and embedding counts that refresh on it did not. A cancelled run still sends nothing. --- src/main/ipc/analysis.js | 13 +++++++- src/main/ipc/files/batchProgressReporter.js | 21 ++++++++++++ test/analysis-ipc-handlers.test.js | 1 + ....classifyOutcome.formatUnsupported.test.js | 1 + test/analysisIpc.batchLifecycle.test.js | 33 +++++++++++++++++-- test/analysisIpc.realZod.test.js | 1 + test/analysisIpc.test.js | 1 + ...atchProgressReporter.trailingFlush.test.js | 22 ++++++++++++- .../analyzeNameOrganize.e2e.test.js | 1 + 9 files changed, 90 insertions(+), 4 deletions(-) diff --git a/src/main/ipc/analysis.js b/src/main/ipc/analysis.js index d127c8b..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'); @@ -1326,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. diff --git a/src/main/ipc/files/batchProgressReporter.js b/src/main/ipc/files/batchProgressReporter.js index c8e44fc..6c88d5e 100644 --- a/src/main/ipc/files/batchProgressReporter.js +++ b/src/main/ipc/files/batchProgressReporter.js @@ -87,6 +87,26 @@ function sendOperationProgress(getMainWindow, payload, { stillWanted } = {}) { } } +/** + * 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 @@ -179,6 +199,7 @@ function sendFileOperationBatchComplete(getMainWindow, { operation, files, desti module.exports = { sendOperationProgress, + flushOperationProgress, sendChunkedResults, sendFileComplete, sendFileOperationBatchComplete 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 index daf7e80..e8ac763 100644 --- a/test/analysisIpc.batchLifecycle.test.js +++ b/test/analysisIpc.batchLifecycle.test.js @@ -56,7 +56,8 @@ jest.mock('../src/main/services/BatchAnalysisService', () => ); jest.mock('../src/main/ipc/files/batchProgressReporter', () => ({ sendFileComplete: jest.fn(), - sendOperationProgress: jest.fn() + sendOperationProgress: jest.fn(), + flushOperationProgress: jest.fn() })); const mockMediaAnalyzer = jest.fn(); @@ -70,7 +71,10 @@ const { EventEmitter } = require('events'); const fsPromises = require('fs').promises; const registerAnalysisIpc = require('../src/main/ipc/analysis'); const { validateFileOperationPath } = require('../src/shared/pathSanitization'); -const { sendOperationProgress } = require('../src/main/ipc/files/batchProgressReporter'); +const { + sendOperationProgress, + flushOperationProgress +} = require('../src/main/ipc/files/batchProgressReporter'); const IPC_CHANNELS = { ANALYSIS: { @@ -311,6 +315,31 @@ describe('progress of a batch that is on its way when the batch ends', () => { 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', () => { diff --git a/test/analysisIpc.realZod.test.js b/test/analysisIpc.realZod.test.js index b70a969..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() })); 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/batchProgressReporter.trailingFlush.test.js b/test/batchProgressReporter.trailingFlush.test.js index 9e66ad3..8efba73 100644 --- a/test/batchProgressReporter.trailingFlush.test.js +++ b/test/batchProgressReporter.trailingFlush.test.js @@ -18,6 +18,7 @@ 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]); @@ -25,7 +26,10 @@ describe('a progress report held back by the throttle', () => { jest.useFakeTimers(); jest.resetModules(); ({ safeSend } = require('../src/main/ipc/ipcWrappers')); - ({ sendOperationProgress } = require('../src/main/ipc/files/batchProgressReporter')); + ({ + 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); @@ -56,6 +60,22 @@ describe('a progress report held back by the throttle', () => { 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 }); 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 }) })); From db9899c5b4795ce78ab6d42212d8e139176222cb Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 10:59:35 -0500 Subject: [PATCH 12/18] fix(watcher): a transcript the text model gave no answer for is retried The history row keeps `provisional` and the reason but not the isFallback flags, and the transcript keeps its real extraction method, so the stored row failed isFallbackAnalysis and the watcher never retried it; being provisional it was never embedded either. A provisional row is now a fallback, and for this case the watcher asks whether the text model is installed rather than Whisper, which is already there. --- src/main/services/SmartFolderWatcher.js | 12 ++++-- src/shared/analysisProvenance.js | 3 ++ test/SmartFolderWatcher.coverage.test.js | 49 +++++++++++++++++++++++- test/analysisProvenance.test.js | 11 ++++++ test/mediaAnalysis.test.js | 24 +++++++++++- 5 files changed, 94 insertions(+), 5 deletions(-) diff --git a/src/main/services/SmartFolderWatcher.js b/src/main/services/SmartFolderWatcher.js index 4816df4..835ff8b 100644 --- a/src/main/services/SmartFolderWatcher.js +++ b/src/main/services/SmartFolderWatcher.js @@ -2159,7 +2159,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; } @@ -2264,9 +2264,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; @@ -2302,7 +2303,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; } 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/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/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/mediaAnalysis.test.js b/test/mediaAnalysis.test.js index c8d37e5..8374348 100644 --- a/test/mediaAnalysis.test.js +++ b/test/mediaAnalysis.test.js @@ -439,13 +439,35 @@ describe('analyzeMediaFile — the text model gives no answer for a transcript', })); expect(isFallbackAnalysis(result)).toBe(true); - // Retried by the watcher once the model answers again. 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', From a475f33f28188ce9a2b97c694568d9012830a51e Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:05:44 -0500 Subject: [PATCH 13/18] fix(watcher): an embedding retry neither loses its file nor embeds stale content An embedding retry carries the result of a finished pass and only embeds it. - It gave way to an item already queued for the file; when that item was then skipped as already analyzed, nothing embedded the file. The item that stays now carries the result and embeds it in that case. - It embedded its result even when the file had changed since the pass. It now compares the file with what its pass saw and drops out. - It recorded start stats as if it read the file, so a real edit during it was dropped as the watcher's own read echo. - A batch hand-back that met a queued retry kept the retry (stripped of its result) instead of the waiting item, losing the event type and mtime. Also corrects the descriptions of ANALYSIS_LOCK and GLOBAL_ANALYSIS and the watcher comments that still named a single ten-minute timeout. --- docs/CONFIG.md | 4 +- src/main/services/SmartFolderWatcher.js | 89 ++++++++-- src/shared/performanceConstants.js | 11 +- ...derWatcher.embeddingRetryFreshness.test.js | 158 ++++++++++++++++++ ...olderWatcher.embeddingRetryReplace.test.js | 10 +- test/SmartFolderWatcher.readEcho.test.js | 21 +++ test/SmartFolderWatcher.vanishedFile.test.js | 17 +- 7 files changed, 286 insertions(+), 24 deletions(-) create mode 100644 test/SmartFolderWatcher.embeddingRetryFreshness.test.js 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/services/SmartFolderWatcher.js b/src/main/services/SmartFolderWatcher.js index 835ff8b..4f6c040 100644 --- a/src/main/services/SmartFolderWatcher.js +++ b/src/main/services/SmartFolderWatcher.js @@ -148,17 +148,15 @@ function analysisRetryDelayMs(retryCount) { * it would run as a content update (original name kept, folder kept) or be * skipped as already analyzed. * - * A model pass that was still to come stays to come. An embedding retry - * carries the result of the pass before it (`cachedAnalysis`) and only - * embeds that again: left on the item, the file was never read again. + * 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 keepAnalysisRequest(replaced, replacement) { if (!replaced) return; - if (!replaced.cachedAnalysis && replacement.cachedAnalysis) { - delete replacement.cachedAnalysis; - delete replacement._lastAnalysis; + 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'; @@ -166,6 +164,27 @@ function keepAnalysisRequest(replaced, replacement) { 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; @@ -344,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} */ @@ -1504,7 +1524,9 @@ class SmartFolderWatcher { // 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); @@ -2180,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). @@ -2534,8 +2556,17 @@ class SmartFolderWatcher { const handedBack = []; for (const waiting of rest) { const newer = queuedByKey.get(procKey(waiting)); - if (newer) keepAnalysisRequest(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); @@ -2892,10 +2923,14 @@ class SmartFolderWatcher { // Verify file still exists and capture stats for reuse below const fileStats = await fs.stat(filePath); - this._analysisStartStats.set(processingKey, { - mtimeMs: fileStats.mtimeMs, - size: fileStats.size - }); + // 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 @@ -2908,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, @@ -3015,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. 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/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 index 9201ac8..f29ae61 100644 --- a/test/SmartFolderWatcher.embeddingRetryReplace.test.js +++ b/test/SmartFolderWatcher.embeddingRetryReplace.test.js @@ -186,8 +186,14 @@ describe('an image batch handed back when a Discover analysis starts', () => { expect(watcher._analyzeFile).toHaveBeenCalledTimes(1); expect(watcher.analysisQueue).toHaveLength(1); - expect(watcher.analysisQueue[0].filePath).toBe(second); - expect(watcher.analysisQueue[0].cachedAnalysis).toBeUndefined(); + 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(); }); }); diff --git a/test/SmartFolderWatcher.readEcho.test.js b/test/SmartFolderWatcher.readEcho.test.js index c5e0714..7c30b1a 100644 --- a/test/SmartFolderWatcher.readEcho.test.js +++ b/test/SmartFolderWatcher.readEcho.test.js @@ -116,6 +116,27 @@ describe('SmartFolderWatcher and change events from its own read', () => { ]); }); + // 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 () => {}); diff --git a/test/SmartFolderWatcher.vanishedFile.test.js b/test/SmartFolderWatcher.vanishedFile.test.js index 864b022..b398b33 100644 --- a/test/SmartFolderWatcher.vanishedFile.test.js +++ b/test/SmartFolderWatcher.vanishedFile.test.js @@ -109,9 +109,21 @@ describe('SmartFolderWatcher and a file that vanishes during its analysis', () = expectNothingRecorded(watcher); }); - test('an embedding retry for a file that is gone does nothing', async () => { + test('an embedding retry for a file that goes during it embeds nothing', async () => { const watcher = makeWatcher(async () => {}); - fs.rmSync(file); + // 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, @@ -120,6 +132,7 @@ describe('SmartFolderWatcher and a file that vanishes during its analysis', () = cachedAnalysis: RESULT }); + expect(fs.existsSync(file)).toBe(false); expect(watcher._embedAnalyzedFile).not.toHaveBeenCalled(); expect(watcher.analysisQueue).toEqual([]); }); From 6cc451a3084809b1161ee7787dac9f74e113036a Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:12:52 -0500 Subject: [PATCH 14/18] fix(vision): an image that could not be decoded is not sent to the vision model Preprocessing failed on an SVG, a TIFF or a damaged WebP and the raw bytes went to the vision runtime labelled image/png. The runtime rejected them, the call was retried, and each rejection counted toward the breaker that turns vision off for the images after it. Bytes that are not PNG, JPEG, GIF or BMP by signature now skip the vision call and Tesseract; the file is analyzed from its text if it has any, else from its name, with a reason that names the file and not the model. 'failed to load image' no longer counts as a transient failure. The stderr excerpt of the vision runtime travels on the error as visionRuntimeHint and is no longer appended to its message, where it reached the UI and decided how unrelated errors were classified. --- src/main/analysis/imageAnalysis.js | 61 +++++++++++-- src/main/services/LlamaResilience.js | 3 + src/main/services/LlamaService.js | 4 +- src/main/services/VisionService.js | 13 ++- .../services/visionErrorClassification.js | 17 ++++ test/LlamaResilience.test.js | 19 ++++ test/VisionService.test.js | 42 +++++++++ test/imageAnalysis.behavior.test.js | 91 ++++++++++++++++++- .../imageAnalysisPipeline.integration.test.js | 1 + test/visionErrorClassification.test.js | 11 +++ 10 files changed, 249 insertions(+), 13 deletions(-) diff --git a/src/main/analysis/imageAnalysis.js b/src/main/analysis/imageAnalysis.js index f9c6059..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 @@ -1689,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; @@ -1701,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' @@ -2376,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/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 b051678..bb84d65 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'); @@ -707,7 +707,7 @@ class LlamaService extends EventEmitter { } _isVisionDecodePressureError(/** @type {any} */ errorLike) { - return isVisionDecodePressureError(errorLike); + return isVisionRuntimeDecodePressure(errorLike); } _getContextSequences(type = 'text') { diff --git a/src/main/services/VisionService.js b/src/main/services/VisionService.js index 0c43cf2..8ef48e9 100644 --- a/src/main/services/VisionService.js +++ b/src/main/services/VisionService.js @@ -2207,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/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/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/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/imageAnalysis.behavior.test.js b/test/imageAnalysis.behavior.test.js index 62a563d..719e13c 100644 --- a/test/imageAnalysis.behavior.test.js +++ b/test/imageAnalysis.behavior.test.js @@ -343,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 = { @@ -702,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(() => ({ @@ -742,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'); }); 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/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); From d6c252b2909358761bcf8f1491943eea96a0c938 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:16:07 -0500 Subject: [PATCH 15/18] fix(vision): an image in a batch waits for a text request to let go of the text model A text load inside a vision batch evicts the runtime. The next image tried to free the text model, found it pinned by the request that loaded it, and was refused the runtime: it lost its vision analysis for a text request that ends seconds later. The image now waits up to 45 s for that request, stops waiting when it is cancelled or the app shuts down, and tries once more. The refusal stands when the text model is still in use after that. --- src/main/services/LlamaService.js | 45 ++++++++++++++++-- test/LlamaService.inference.test.js | 72 ++++++++++++++++++++++++++++- 2 files changed, 113 insertions(+), 4 deletions(-) diff --git a/src/main/services/LlamaService.js b/src/main/services/LlamaService.js index bb84d65..f82324a 100644 --- a/src/main/services/LlamaService.js +++ b/src/main/services/LlamaService.js @@ -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; @@ -2146,6 +2151,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, @@ -4222,8 +4261,8 @@ class LlamaService extends EventEmitter { /** * True during a vision batch when the runtime is gone and the text model * sits in memory instead, or is still being loaded: a text load from - * inside the batch evicted the runtime. The next image must wait for that - * load and free its memory before respawning the runtime. + * inside the batch evicted the runtime. The next image frees that memory + * before it respawns the runtime (_releaseMemoryForBatchVisionRespawn). * @returns {boolean} * @private */ @@ -4407,7 +4446,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/test/LlamaService.inference.test.js b/test/LlamaService.inference.test.js index 67c13b4..e800650 100644 --- a/test/LlamaService.inference.test.js +++ b/test/LlamaService.inference.test.js @@ -383,6 +383,8 @@ describe('LlamaService – inference methods', () => { 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 @@ -404,6 +406,7 @@ describe('LlamaService – inference methods', () => { 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 () => { @@ -427,7 +430,7 @@ describe('LlamaService – inference methods', () => { // 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('waits out a text load still in progress before respawning vision', async () => { + test('makes room again once a text load in progress has ended', async () => { const service = batchImageService({ textResident: false, textLoading: true, @@ -437,6 +440,73 @@ describe('LlamaService – inference methods', () => { 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, From f07432b95e50e70f88b8fdcb29f4a1d60d64bf48 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:18:19 -0500 Subject: [PATCH 16/18] fix(embedding): an embedding load in a vision batch no longer evicts the text model that replaced the runtime The batch's CPU-only embedding load was declared beside the vision runtime for as long as the batch held its pin, also after a text load had evicted the runtime. With no runtime to sit beside, the load evicted the idle text model, or waited for a busy one, for a model that takes no VRAM. It is now declared beside the text model in that window and stays the batch's CPU model, unloaded when the batch ends. --- src/main/services/LlamaService.js | 26 ++++++++++++++++++++++-- test/LlamaService.visionBatchPin.test.js | 26 ++++++++++++++++++++++++ 2 files changed, 50 insertions(+), 2 deletions(-) diff --git a/src/main/services/LlamaService.js b/src/main/services/LlamaService.js index f82324a..ba66da1 100644 --- a/src/main/services/LlamaService.js +++ b/src/main/services/LlamaService.js @@ -1772,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; @@ -4304,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 }; } 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(); }); From cf3ef00459ae914349da06a13a35b35961813255 Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:19:27 -0500 Subject: [PATCH 17/18] test: the day a result and a cluster show is checked in every time zone The two tests for the stored-day fix compared against local midnight, which is what the old UTC parse also gives where the zone is UTC, as on CI. Each now has a case where the calendar-day helper returns an instant no parse of the stored value gives; with either call site reverted they fail under TZ=UTC. --- test/ClusteringService.test.js | 45 +++++++++++++++++++ .../components/ResultRow.documentDate.test.js | 20 +++++++++ 2 files changed, 65 insertions(+) diff --git a/test/ClusteringService.test.js b/test/ClusteringService.test.js index 95a35f2..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') })); @@ -620,6 +626,45 @@ describe('ClusteringService', () => { 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/components/ResultRow.documentDate.test.js b/test/components/ResultRow.documentDate.test.js index 1192364..ca7559d 100644 --- a/test/components/ResultRow.documentDate.test.js +++ b/test/components/ResultRow.documentDate.test.js @@ -11,6 +11,13 @@ 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 = () => {}; @@ -41,6 +48,19 @@ describe('the date on a search result', () => { 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' }); From 6040398ce35300b5c86fe9d95618d66a5640963c Mon Sep 17 00:00:00 2001 From: Levy Tate <78818969+iLevyTate@users.noreply.github.com> Date: Tue, 10 Nov 2026 11:25:05 -0500 Subject: [PATCH 18/18] docs(changelog): record the regression-hunt fixes --- CHANGELOG.md | 53 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 53 insertions(+) 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