0b886ed942
* fix(faces): defer on unreachable storage, and commit the import path first The two follow-ups left open by #1091, both consequences of external photos becoming scannable at all. **A dropped mount no longer burns the gallery.** ensurePreviewImage returns null for "this JPEG is corrupt" and "the NFS share is gone" alike, and faceProcessor marked both 'failed'. Nothing re-queues a failure automatically and the queue only ever claims 'pending', so a mount that blinked mid-scan cost the whole event a manual Re-scan — on external libraries, where network storage drops far more often than local disk, that is the common case rather than the corner one. faceProcessor now probes the containing DIRECTORY before failing, and throws TransientSourceError when it cannot be reached; faceQueue treats that exactly like SidecarUnavailableError — release to pending, back off, retry — with the warning rate-limited to one per five minutes, since an outage hits every photo in the event. The directory rather than the file is the whole point: a missing file inside a healthy directory is a broken photo and should still fail, and it still does. Anything that goes wrong deciding which case it is falls through to 'failed', because guessing 'transient' on an unknown condition would retry forever. **The import commits its path before inserting rows.** enqueueEvent accepts processing_status NULL (faceProcessor.js:243-246), which these inserts leave unset, so an admin hitting the toggle or Re-scan during a long import could queue partial rows while the event still resolved against the old directory — and burn them to 'failed'. Moving events.external_path ahead of the loop closes that, and fixes a pre-existing bug on the same line: an import that died at photo 500 of 1000 used to leave those 500 rows pointing into the new tree while the event still resolved against the old one, making every one of them unreadable. Safe to do first because the path is already validated above, and existing photos are unaffected — photo.source_origin takes precedence over event.source_mode in both resolvers and is NOT NULL defaulting to 'managed'. The #1090 test that asserted a missing source fails needed its setup corrected rather than its intent: it created no directory at all, which is now (correctly) a dropped mount. It now creates one, so it tests the case it always meant to — healthy storage, dead photo. Verified both fixes discriminate: removing the probe fails the defer test, and moving the event update back after the loop fails the ordering test. Face suite 59 passed across 8 suites; the full backend suite fails the same 10 pre-existing suites as unmodified main, no more. * fix(faces): stop a dead mount stalling the whole queue External review, and the first finding is one my own change created. Deferring by returning the row to 'pending' was a trap: claimNextPhoto orders by id ascending and the queue defaults to a single worker, so the same unreachable row becomes the oldest pending one after every backoff and the worker never reaches a higher id. One dead mount would have stalled face scanning for the entire install — unrelated events, fresh uploads, everything. Strictly worse than the permanent 'failed' this set out to replace. The row is now left parked in 'processing' with face_started_at intact. It is not claimable, so the worker moves straight on; the janitor that already exists returns it to 'pending' past STUCK_TIMEOUT_MS, which is the retry. No new column and no new timer. The sidecar branch still releases, because a down sidecar blocks every photo anyway — there is no other work to get on with. Second: probing existence was not enough. Unmounting an NFS or SMB share usually leaves the mountpoint behind as an ordinary empty directory, so fs.access succeeded on storage that was entirely gone and the photo was failed anyway — the exact case this was written for. An empty directory where the photo should live now counts as unreachable. The trade is deliberate and documented: a directory an admin genuinely emptied is retried rather than failed, which now costs one attempt per janitor sweep and nothing else. Third: a comment in adminExternalMedia claimed source_origin isolates existing photos from the early external_path update. That is true of managed rows and false of external ones — resolveExternalPath prefixes every external row with event.external_path, so importing folder B into an event referencing folder A rebases the A rows. Pre-existing rather than introduced here (the update always did this, just later), but the comment asserted otherwise, so it now says what actually happens and names the underlying single-base-path limitation. The deferral test initially passed against the blocking version too — database state alone cannot tell the fix from the bug. It now inspects the branch directly, the way the #596 contract tests do, and fails when releaseToPending is put back or the two branches are merged. * fix(faces): back off per event, and stop clobbering concurrent scans Round two of external review. Parking a row in 'processing' fixed the head-of-line block but not the cost: every janitor sweep handed the whole dead gallery back, and the worker walked all of it again — one stat per photo against storage that may be hard-mounted and slow to time out — before reaching any healthy event. Every one of those attempts also went through generatePreviewImage first, which logs an error per photo, so a down mount produced a recurring flood that the rate-limited warning did nothing about. So the backoff is now per EVENT and separate from the janitor: TransientSourceError carries the event id, the queue records a cooldown, and claimNextPhoto excludes those events while it lasts. The janitor keeps doing its own job, which is rescuing rows a crashed worker abandoned. Cooldown is in memory on purpose — a restart is usually what follows fixing a mount, so it should retry at once. Second: committing the event path before the loop means a toggle or Re-scan firing mid-import can now genuinely queue and finish some of those rows. The final bulk update was unconditional, so it dragged 'done' rows back to 'pending' for a duplicate sidecar scan and knocked 'processing' rows out from under the worker. It is now whereNull — only rows nothing has touched are ours to queue. Also corrected a comment of mine that had gone stale in the same file: it still described the enqueue as happening after the event path was written "below", which stopped being true when that update moved above the loop. * fix(faces): judge the mount, the path and the file separately Round three of external review. The probe was too coarse in both directions. It read any ENOENT on the photo's own directory as a mount-wide outage, so a deleted or renamed subfolder — individual/ gone while collages/ is healthy — deferred the entire event and starved every sibling folder, renewing the cooldown on each retry. It now judges the EVENT ROOT for that verdict: root missing, or present-but-empty, is an outage; anything below a populated root is a broken path and fails. And it read a listable directory as proof the photo was at fault, so EACCES on a reconnected share, EIO, or the classic NFS ESTALE handle were burnt as permanent failures. Only ENOENT now means genuinely gone; any other error opening the file defers. The event-wide backoff was also too broad. A reference event can hold managed uploads alongside imported external ones, and those live in local storage that is fine — excluding the whole event id left them unscanned for as long as external rows kept renewing the cooldown, which during a real outage is indefinitely. The exclusion is now scoped to external and reference rows. One of my own tests had modelled the unmount wrongly: it emptied the photo's subdirectory rather than the event root, which under the corrected logic is a populated mount with a missing folder — a failure, not an outage. It now empties the root, which is what an unmount actually leaves behind. Dropped the path require the first version of this probe needed; the event-root form does not. All three fixes mutation-checked: reverting each one fails the test written for it. Face suite 69 passed across 9 suites; full backend suite fails the same 10 pre-existing suites as main, no more. --------- Co-authored-by: Paul Nothaft <paul@MacStudio-von-Paul.local>
240 lines
10 KiB
JavaScript
240 lines
10 KiB
JavaScript
/**
|
|
* External imports are queued for face scanning, in the right order (#1090).
|
|
*
|
|
* Managed uploads are enqueued by photoProcessor, which writes face_status
|
|
* 'pending' once a photo is processed (photoProcessor.js:573 — "the only
|
|
* correct place to enqueue"). External media never goes through photoProcessor:
|
|
* adminExternalMedia inserts rows directly, so they stayed NULL and were only
|
|
* ever picked up by a manual Re-scan.
|
|
*
|
|
* The ordering matters as much as the enqueue. events.external_path is written
|
|
* only AFTER the whole import loop, so marking rows 'pending' as they are
|
|
* inserted publishes claimable work while the event still points at the old
|
|
* directory — or none at all, on a first import. The face worker polls
|
|
* continuously, would resolve those photos against the wrong path, and mark
|
|
* them permanently 'failed', a state only an explicit Re-scan clears.
|
|
*
|
|
* This drives the real route rather than re-implementing it, so removing the
|
|
* enqueue fails the first test and moving it back onto the insert fails the
|
|
* second.
|
|
*/
|
|
|
|
const fs = require('fs');
|
|
const path = require('path');
|
|
const os = require('os');
|
|
const express = require('express');
|
|
const request = require('supertest');
|
|
|
|
describe('external import queues faces (#1090)', () => {
|
|
let tmpDir; let db; let app; let mediaRoot;
|
|
// Recorded from inside the per-photo thumbnail call, i.e. mid-loop.
|
|
let pendingSeenDuringLoop = 0;
|
|
let externalPathDuringLoop;
|
|
// When set to an event id, the mocked thumbnail call turns detection on
|
|
// mid-loop, standing in for an admin flipping the toggle during an import.
|
|
let flipFacesOnDuringLoop = null;
|
|
// Stands in for a concurrent Re-scan completing a row mid-import.
|
|
let markDoneDuringLoop = false;
|
|
|
|
beforeAll(async () => {
|
|
tmpDir = await fs.promises.mkdtemp(path.join(os.tmpdir(), 'picpeak-extenq-'));
|
|
mediaRoot = path.join(tmpDir, 'media');
|
|
await fs.promises.mkdir(path.join(mediaRoot, 'nas', 'individual'), { recursive: true });
|
|
for (const name of ['a.jpg', 'b.jpg', 'c.jpg']) {
|
|
await fs.promises.writeFile(path.join(mediaRoot, 'nas', 'individual', name), 'not-a-real-jpeg');
|
|
}
|
|
|
|
process.env.NODE_ENV = 'test';
|
|
process.env.TEST_DATABASE_PATH = path.join(tmpDir, 'data', 'db.sqlite');
|
|
await fs.promises.mkdir(path.dirname(process.env.TEST_DATABASE_PATH), { recursive: true });
|
|
process.env.STORAGE_PATH = path.join(tmpDir, 'storage');
|
|
process.env.EXTERNAL_MEDIA_ROOT = mediaRoot;
|
|
process.env.JWT_SECRET = process.env.JWT_SECRET || 'extenq-secret';
|
|
|
|
jest.resetModules();
|
|
|
|
jest.doMock('../../src/middleware/auth', () => ({
|
|
adminAuth: (req, _res, next) => { req.admin = { id: 1, username: 'tester', roleName: 'admin' }; next(); },
|
|
}));
|
|
jest.doMock('../../src/middleware/permissions', () => ({
|
|
requirePermission: () => (_req, _res, next) => next(),
|
|
}));
|
|
jest.doMock('../../src/middleware/ownership', () => ({
|
|
requireEventOwnership: (_req, _res, next) => next(),
|
|
}));
|
|
|
|
// Runs once per photo, inside the import loop — the only hook that can
|
|
// observe the intermediate state the ordering bug would expose.
|
|
jest.doMock('../../src/services/imageProcessor', () => ({
|
|
generateThumbnail: jest.fn(async () => {
|
|
const { db: liveDb } = require('../../src/database/db');
|
|
const rows = await liveDb('photos').where({ face_status: 'pending' });
|
|
pendingSeenDuringLoop += rows.length;
|
|
const ev = await liveDb('events').first();
|
|
externalPathDuringLoop = ev ? ev.external_path : undefined;
|
|
if (markDoneDuringLoop) {
|
|
const rows = await liveDb('photos').orderBy('id', 'asc').limit(1);
|
|
if (rows.length) {
|
|
await liveDb('photos').where({ id: rows[0].id }).update({ face_status: 'done' });
|
|
}
|
|
}
|
|
if (flipFacesOnDuringLoop) {
|
|
await liveDb('events').where({ id: flipFacesOnDuringLoop })
|
|
.update({ face_recognition_enabled: true });
|
|
}
|
|
return 'thumbnails/mock.jpg';
|
|
}),
|
|
ensureThumbnail: jest.fn(),
|
|
}));
|
|
|
|
jest.doMock('../../src/utils/logger', () => ({
|
|
debug: jest.fn(), info: jest.fn(), warn: jest.fn(), error: jest.fn(),
|
|
}));
|
|
|
|
// bootCrmDb runs every migrations/core/*.up() directly — knex's Migrator
|
|
// deadlocks on 001_init's nested initializeDatabase() call.
|
|
({ db } = await require('./helpers/crmDb').bootCrmDb());
|
|
|
|
app = express();
|
|
app.use(express.json());
|
|
app.use('/api/admin/external-media', require('../../src/routes/adminExternalMedia'));
|
|
}, 180000);
|
|
|
|
afterAll(async () => {
|
|
if (db) await db.destroy?.();
|
|
await fs.promises.rm(tmpDir, { recursive: true, force: true }).catch(() => {});
|
|
});
|
|
|
|
async function seedEvent({ facesEnabled, flagOn }) {
|
|
await db('feature_flags').insert({ key: 'faces', value: flagOn })
|
|
.onConflict('key').merge()
|
|
.catch(async () => { await db('feature_flags').where({ key: 'faces' }).update({ value: flagOn }); });
|
|
// The flag read is TTL-cached (requireFeatureFlag.js:26-34); production
|
|
// invalidates after every write, and so must this.
|
|
require('../../src/middleware/requireFeatureFlag').invalidateFeatureFlagCache();
|
|
|
|
await db('photos').del();
|
|
await db('events').del();
|
|
const [e] = await db('events').insert({
|
|
slug: `extenq-${Math.random().toString(36).slice(2, 8)}`,
|
|
event_type: 'wedding',
|
|
event_name: 'extenq',
|
|
event_date: '2026-01-01',
|
|
host_email: 'h@example.com',
|
|
admin_email: 'a@example.com',
|
|
password_hash: 'x',
|
|
share_link: `extenq-${Math.random()}`,
|
|
expires_at: new Date().toISOString(),
|
|
face_recognition_enabled: facesEnabled,
|
|
source_mode: 'reference',
|
|
}).returning('id');
|
|
|
|
pendingSeenDuringLoop = 0;
|
|
externalPathDuringLoop = undefined;
|
|
markDoneDuringLoop = false;
|
|
return typeof e === 'object' ? e.id : e;
|
|
}
|
|
|
|
async function runImport(eventId) {
|
|
return request(app)
|
|
.post(`/api/admin/external-media/events/${eventId}/import-external`)
|
|
.send({ external_path: 'nas', recursive: true });
|
|
}
|
|
|
|
it('queues imported photos when detection is on', async () => {
|
|
const eventId = await seedEvent({ facesEnabled: true, flagOn: true });
|
|
|
|
const res = await runImport(eventId);
|
|
expect(res.status).toBe(200);
|
|
|
|
const photos = await db('photos').where({ event_id: eventId });
|
|
expect(photos.length).toBeGreaterThan(0);
|
|
// The regression: these stayed NULL and waited for a manual Re-scan.
|
|
expect(photos.every((p) => p.face_status === 'pending')).toBe(true);
|
|
});
|
|
|
|
it('does not publish claimable rows before events.external_path is written', async () => {
|
|
const eventId = await seedEvent({ facesEnabled: true, flagOn: true });
|
|
|
|
await runImport(eventId);
|
|
|
|
// Observed from inside the loop: nothing is claimable yet. The event path
|
|
// is already committed (see the test above), so this is no longer load
|
|
// bearing for correctness — but keeping the enqueue at the end is what lets
|
|
// the feature setting be read after the loop, so the invariant stays.
|
|
expect(pendingSeenDuringLoop).toBe(0);
|
|
|
|
// ...and afterwards both are in place.
|
|
const ev = await db('events').where({ id: eventId }).first();
|
|
expect(ev.external_path).toBe('nas');
|
|
expect((await db('photos').where({ event_id: eventId, face_status: 'pending' })).length)
|
|
.toBe((await db('photos').where({ event_id: eventId })).length);
|
|
});
|
|
|
|
it('honours a toggle flipped DURING the import', async () => {
|
|
// The setting is read after the loop, not before: on a large library the
|
|
// loop runs for minutes, and the toggle endpoint only queues rows that
|
|
// already existed when it fired. Reading it up front would strand every
|
|
// photo imported after that moment at NULL forever.
|
|
const eventId = await seedEvent({ facesEnabled: false, flagOn: true });
|
|
flipFacesOnDuringLoop = eventId;
|
|
|
|
await runImport(eventId);
|
|
flipFacesOnDuringLoop = null;
|
|
|
|
const photos = await db('photos').where({ event_id: eventId });
|
|
expect(photos.length).toBeGreaterThan(0);
|
|
expect(photos.every((p) => p.face_status === 'pending')).toBe(true);
|
|
});
|
|
|
|
it('commits events.external_path before the first row is inserted', async () => {
|
|
// enqueueEvent accepts processing_status NULL (faceProcessor.js:243-246),
|
|
// which these inserts leave unset — so a toggle or Re-scan firing mid-import
|
|
// can queue partial rows. If the event still pointed at the old directory
|
|
// they would resolve against it and burn to 'failed'. Setting the path
|
|
// first also means a half-finished import leaves rows that still resolve,
|
|
// instead of rows stranded against the previous path.
|
|
const eventId = await seedEvent({ facesEnabled: true, flagOn: true });
|
|
|
|
await runImport(eventId);
|
|
|
|
// Sampled from inside the per-photo thumbnail call, i.e. while rows are
|
|
// still being inserted.
|
|
expect(externalPathDuringLoop).toBe('nas');
|
|
});
|
|
|
|
it('does not re-queue rows a concurrent scan already handled', async () => {
|
|
// Committing the event path before the loop means a toggle or Re-scan
|
|
// firing mid-import can now genuinely queue and even finish some of these
|
|
// rows. A blanket update at the end would drag 'done' rows back to
|
|
// 'pending' for a duplicate sidecar scan and knock 'processing' rows out
|
|
// from under the worker.
|
|
const eventId = await seedEvent({ facesEnabled: true, flagOn: true });
|
|
markDoneDuringLoop = true;
|
|
|
|
await runImport(eventId);
|
|
markDoneDuringLoop = false;
|
|
|
|
const done = await db('photos').where({ event_id: eventId, face_status: 'done' });
|
|
expect(done.length).toBeGreaterThan(0); // the concurrent scan's work survived
|
|
});
|
|
|
|
it('leaves face_status untouched when the per-event toggle is off', async () => {
|
|
const eventId = await seedEvent({ facesEnabled: false, flagOn: true });
|
|
await runImport(eventId);
|
|
const photos = await db('photos').where({ event_id: eventId });
|
|
expect(photos.length).toBeGreaterThan(0);
|
|
expect(photos.every((p) => p.face_status === null)).toBe(true);
|
|
});
|
|
|
|
it('leaves face_status untouched when the global flag is off', async () => {
|
|
// Installs without the feature must never accumulate face_status rows —
|
|
// the same invariant photoProcessor's guard protects.
|
|
const eventId = await seedEvent({ facesEnabled: true, flagOn: false });
|
|
await runImport(eventId);
|
|
const photos = await db('photos').where({ event_id: eventId });
|
|
expect(photos.length).toBeGreaterThan(0);
|
|
expect(photos.every((p) => p.face_status === null)).toBe(true);
|
|
});
|
|
});
|