feat(audit): implement audit logging for search requests and results
All checks were successful
Publish FaceAI Container / publish (push) Successful in 13m22s

- Added configuration options for audit database path and retention days in backend and processor.
- Integrated audit logging in server and worker processes to track search requests, completions, and failures.
- Created utility functions for reading and parsing audit logs in end-to-end tests.
- Updated Docker Compose files to include audit database configuration.
- Added new tests to verify audit log entries for successful and no-results searches.
This commit is contained in:
MaddoScientisto 2026-05-19 23:29:38 +02:00
commit 32db61c381
14 changed files with 1067 additions and 16 deletions

View file

@ -0,0 +1,472 @@
import fs from 'node:fs';
import path from 'node:path';
import { DatabaseSync } from 'node:sqlite';
const ONE_DAY_MS = 24 * 60 * 60 * 1000;
function textOrNull(value) {
if (value === undefined || value === null) {
return null;
}
const normalized = String(value).trim();
return normalized === '' ? null : normalized;
}
function jsonOrNull(value) {
if (value === undefined || value === null) {
return null;
}
return JSON.stringify(value);
}
function openDatabase(dbPath) {
fs.mkdirSync(path.dirname(dbPath), { recursive: true });
const db = new DatabaseSync(dbPath);
db.exec(`
PRAGMA foreign_keys = ON;
PRAGMA busy_timeout = 5000;
PRAGMA journal_mode = WAL;
CREATE TABLE IF NOT EXISTS faceai_audit_searches (
search_id TEXT PRIMARY KEY,
requested_at INTEGER NOT NULL,
updated_at INTEGER NOT NULL,
completed_at INTEGER,
redirect_issued_at INTEGER,
status TEXT NOT NULL,
completion_code TEXT,
error_code TEXT,
error_message TEXT,
user_id TEXT NOT NULL,
user_display_name TEXT,
user_membership_status TEXT,
race_id TEXT NOT NULL,
race_name TEXT,
race_storage TEXT,
lang TEXT,
request_ip TEXT,
request_user_agent TEXT,
return_url TEXT,
selfie_name TEXT,
selfie_sha256 TEXT,
selfie_size_bytes INTEGER,
upload_path TEXT,
result_id TEXT,
match_count INTEGER NOT NULL DEFAULT 0,
matches_json TEXT
);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_searches_requested_at
ON faceai_audit_searches (requested_at);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_searches_user_id
ON faceai_audit_searches (user_id, requested_at DESC);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_searches_race_id
ON faceai_audit_searches (race_id, requested_at DESC);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_searches_selfie_sha256
ON faceai_audit_searches (selfie_sha256, requested_at DESC);
CREATE TABLE IF NOT EXISTS faceai_audit_events (
id INTEGER PRIMARY KEY AUTOINCREMENT,
search_id TEXT REFERENCES faceai_audit_searches(search_id) ON DELETE CASCADE,
event_type TEXT NOT NULL,
happened_at INTEGER NOT NULL,
status TEXT,
user_id TEXT,
user_display_name TEXT,
race_id TEXT,
race_name TEXT,
race_storage TEXT,
request_ip TEXT,
request_user_agent TEXT,
selfie_sha256 TEXT,
result_id TEXT,
match_count INTEGER,
completion_code TEXT,
error_code TEXT,
payload_json TEXT
);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_events_search_id
ON faceai_audit_events (search_id, happened_at DESC);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_events_type
ON faceai_audit_events (event_type, happened_at DESC);
CREATE INDEX IF NOT EXISTS idx_faceai_audit_events_user_id
ON faceai_audit_events (user_id, happened_at DESC);
`);
return db;
}
export function createAuditStore({ dbPath, retentionDays }) {
const retentionMs = Math.max(1, Number(retentionDays || 730)) * ONE_DAY_MS;
const db = openDatabase(dbPath);
let lastPrunedAt = 0;
const upsertSearchRequestStatement = db.prepare(`
INSERT INTO faceai_audit_searches (
search_id,
requested_at,
updated_at,
status,
user_id,
user_display_name,
user_membership_status,
race_id,
race_name,
race_storage,
lang,
request_ip,
request_user_agent,
return_url,
selfie_name,
selfie_sha256,
selfie_size_bytes,
upload_path,
match_count
) VALUES (
@search_id,
@requested_at,
@updated_at,
@status,
@user_id,
@user_display_name,
@user_membership_status,
@race_id,
@race_name,
@race_storage,
@lang,
@request_ip,
@request_user_agent,
@return_url,
@selfie_name,
@selfie_sha256,
@selfie_size_bytes,
@upload_path,
@match_count
)
ON CONFLICT(search_id) DO UPDATE SET
updated_at = excluded.updated_at,
status = excluded.status,
user_id = excluded.user_id,
user_display_name = excluded.user_display_name,
user_membership_status = excluded.user_membership_status,
race_id = excluded.race_id,
race_name = excluded.race_name,
race_storage = excluded.race_storage,
lang = excluded.lang,
request_ip = excluded.request_ip,
request_user_agent = excluded.request_user_agent,
return_url = excluded.return_url,
selfie_name = excluded.selfie_name,
selfie_sha256 = excluded.selfie_sha256,
selfie_size_bytes = excluded.selfie_size_bytes,
upload_path = excluded.upload_path,
match_count = excluded.match_count
`);
const updateSearchOutcomeStatement = db.prepare(`
UPDATE faceai_audit_searches
SET
updated_at = @updated_at,
completed_at = COALESCE(@completed_at, completed_at),
redirect_issued_at = COALESCE(@redirect_issued_at, redirect_issued_at),
status = COALESCE(@status, status),
completion_code = COALESCE(@completion_code, completion_code),
error_code = CASE
WHEN @clear_error = 1 THEN NULL
ELSE COALESCE(@error_code, error_code)
END,
error_message = CASE
WHEN @clear_error = 1 THEN NULL
ELSE COALESCE(@error_message, error_message)
END,
result_id = COALESCE(@result_id, result_id),
match_count = COALESCE(@match_count, match_count),
matches_json = COALESCE(@matches_json, matches_json)
WHERE search_id = @search_id
`);
const insertEventStatement = db.prepare(`
INSERT INTO faceai_audit_events (
search_id,
event_type,
happened_at,
status,
user_id,
user_display_name,
race_id,
race_name,
race_storage,
request_ip,
request_user_agent,
selfie_sha256,
result_id,
match_count,
completion_code,
error_code,
payload_json
) VALUES (
@search_id,
@event_type,
@happened_at,
@status,
@user_id,
@user_display_name,
@race_id,
@race_name,
@race_storage,
@request_ip,
@request_user_agent,
@selfie_sha256,
@result_id,
@match_count,
@completion_code,
@error_code,
@payload_json
)
`);
const pruneSearchesStatement = db.prepare(`
DELETE FROM faceai_audit_searches
WHERE requested_at < @cutoff
`);
const pruneStandaloneEventsStatement = db.prepare(`
DELETE FROM faceai_audit_events
WHERE search_id IS NULL AND happened_at < @cutoff
`);
function maybePrune(now = Date.now()) {
if (now - lastPrunedAt < ONE_DAY_MS) {
return;
}
const cutoff = now - retentionMs;
pruneSearchesStatement.run({ cutoff });
pruneStandaloneEventsStatement.run({ cutoff });
lastPrunedAt = now;
}
function recordEvent({
eventType,
happenedAt = Date.now(),
searchId = null,
status = null,
user = null,
race = null,
request = null,
selfieFingerprint = null,
resultId = null,
matchCount = null,
completionCode = null,
errorCode = null,
payload = null
}) {
maybePrune(happenedAt);
insertEventStatement.run({
search_id: textOrNull(searchId),
event_type: eventType,
happened_at: happenedAt,
status: textOrNull(status),
user_id: textOrNull(user?.id),
user_display_name: textOrNull(user?.displayName),
race_id: textOrNull(race?.id),
race_name: textOrNull(race?.name),
race_storage: textOrNull(race?.storage),
request_ip: textOrNull(request?.ip),
request_user_agent: textOrNull(request?.userAgent),
selfie_sha256: textOrNull(selfieFingerprint?.hashHex),
result_id: textOrNull(resultId),
match_count: Number.isFinite(matchCount) ? matchCount : null,
completion_code: textOrNull(completionCode),
error_code: textOrNull(errorCode),
payload_json: jsonOrNull(payload)
});
}
function recordSearchRequested({ search, user, race, request, selfieFingerprint, payload = null }) {
const requestedAt = Number(search?.createdAt || Date.now());
maybePrune(requestedAt);
upsertSearchRequestStatement.run({
search_id: String(search.id),
requested_at: requestedAt,
updated_at: requestedAt,
status: textOrNull(search.status) || 'queued',
user_id: String(search.userId),
user_display_name: textOrNull(user?.displayName),
user_membership_status: textOrNull(user?.membershipStatus),
race_id: String(search.raceId),
race_name: textOrNull(race?.name || search.raceName),
race_storage: textOrNull(race?.storage || search.raceStorage),
lang: textOrNull(search.lang),
request_ip: textOrNull(request?.ip),
request_user_agent: textOrNull(request?.userAgent),
return_url: textOrNull(search.returnUrl),
selfie_name: textOrNull(search.selfieName),
selfie_sha256: textOrNull(selfieFingerprint?.hashHex),
selfie_size_bytes: Number.isFinite(selfieFingerprint?.sizeBytes) ? selfieFingerprint.sizeBytes : null,
upload_path: textOrNull(search.uploadPath || search.selfiePath),
match_count: Number(search.matchCount || 0)
});
recordEvent({
eventType: 'search_requested',
happenedAt: requestedAt,
searchId: search.id,
status: search.status || 'queued',
user,
race,
request,
selfieFingerprint,
payload
});
}
function markSearchCompleted({
searchId,
user = null,
race = null,
request = null,
resultId,
matchCount,
matches,
completionCode = null,
completedAt = Date.now(),
payload = null
}) {
maybePrune(completedAt);
updateSearchOutcomeStatement.run({
search_id: String(searchId),
updated_at: completedAt,
completed_at: completedAt,
redirect_issued_at: null,
status: 'completed',
completion_code: textOrNull(completionCode),
clear_error: 1,
error_code: null,
error_message: null,
result_id: textOrNull(resultId),
match_count: Number(matchCount || 0),
matches_json: jsonOrNull(matches)
});
recordEvent({
eventType: 'search_completed',
happenedAt: completedAt,
searchId,
status: 'completed',
user,
race,
request,
resultId,
matchCount,
completionCode,
payload
});
}
function markSearchFailed({
searchId,
user = null,
race = null,
request = null,
errorCode,
errorMessage,
completedAt = Date.now(),
payload = null
}) {
maybePrune(completedAt);
updateSearchOutcomeStatement.run({
search_id: String(searchId),
updated_at: completedAt,
completed_at: completedAt,
redirect_issued_at: null,
status: 'failed',
completion_code: null,
clear_error: 0,
error_code: textOrNull(errorCode),
error_message: textOrNull(errorMessage),
result_id: null,
match_count: null,
matches_json: null
});
recordEvent({
eventType: 'search_failed',
happenedAt: completedAt,
searchId,
status: 'failed',
user,
race,
request,
errorCode,
payload: {
errorMessage: textOrNull(errorMessage),
...payload
}
});
}
function markRedirectIssued({
searchId,
user = null,
race = null,
request = null,
resultId,
matchCount,
redirectUrl,
issuedAt = Date.now()
}) {
maybePrune(issuedAt);
updateSearchOutcomeStatement.run({
search_id: String(searchId),
updated_at: issuedAt,
completed_at: null,
redirect_issued_at: issuedAt,
status: null,
completion_code: null,
clear_error: 0,
error_code: null,
error_message: null,
result_id: textOrNull(resultId),
match_count: Number(matchCount || 0),
matches_json: null
});
recordEvent({
eventType: 'search_redirect_issued',
happenedAt: issuedAt,
searchId,
status: 'completed',
user,
race,
request,
resultId,
matchCount,
payload: {
redirectUrl: textOrNull(redirectUrl)
}
});
}
maybePrune();
return {
dbPath,
recordEvent,
recordSearchRequested,
markSearchCompleted,
markSearchFailed,
markRedirectIssued,
close() {
db.close();
}
};
}

View file

@ -27,6 +27,8 @@ export const config = {
queueName: process.env.FACEAI_QUEUE_NAME || 'faceai-searches',
runtimeRoot: process.env.FACEAI_RUNTIME_ROOT || '/data/runtime',
uploadRoot: process.env.FACEAI_UPLOAD_ROOT || path.join(process.env.FACEAI_RUNTIME_ROOT || '/data/runtime', 'uploads'),
auditDbPath: process.env.FACEAI_AUDIT_DB_PATH || path.join(process.env.FACEAI_LOG_ROOT || '/data/logs', 'faceai-audit.sqlite'),
auditRetentionDays: Number(process.env.FACEAI_AUDIT_RETENTION_DAYS || 730),
searchTtlSeconds: Number(process.env.FACEAI_SEARCH_TTL_SECONDS || 24 * 60 * 60),
resultTtlSeconds: Number(process.env.FACEAI_RESULT_TTL_SECONDS || 24 * 60 * 60),
processorHeartbeatGraceMs: Number(process.env.FACEAI_PROCESSOR_HEARTBEAT_GRACE_MS || 60 * 1000),

View file

@ -2,11 +2,13 @@ import express from 'express';
import cors from 'cors';
import cookieParser from 'cookie-parser';
import multer from 'multer';
import crypto from 'node:crypto';
import fs from 'node:fs';
import fsp from 'node:fs/promises';
import path from 'node:path';
import { fileURLToPath } from 'node:url';
import { config } from './config.js';
import { createAuditStore } from './audit-store.js';
import { signPayload, verifySignedPayload } from './auth.js';
import { createSession, getSession, mockCatalog } from './store.js';
import { buildRaceStorage, resolveRacePklAvailability } from './race-storage.js';
@ -31,6 +33,7 @@ const frontendDist = path.resolve(__dirname, '../../frontend/dist');
const app = express();
const redis = createRedisConnection(config.redisUrl);
const searchQueue = getSearchQueue({ queueName: config.queueName, connection: redis });
const auditStore = createAuditStore({ dbPath: config.auditDbPath, retentionDays: config.auditRetentionDays });
let lastHealthFailureSignature = null;
await fsp.mkdir(config.uploadRoot, { recursive: true });
@ -85,6 +88,34 @@ function clientIp(req) {
return forwardedFor || req.ip || req.socket?.remoteAddress || null;
}
function requestAuditContext(req) {
return {
ip: clientIp(req),
userAgent: req.headers['user-agent'] || null
};
}
async function fingerprintUpload(filePath) {
const hash = crypto.createHash('sha256');
let sizeBytes = 0;
await new Promise((resolve, reject) => {
const stream = fs.createReadStream(filePath);
stream.on('data', (chunk) => {
hash.update(chunk);
sizeBytes += chunk.length;
});
stream.on('end', resolve);
stream.on('error', reject);
});
return {
algorithm: 'sha256',
hashHex: hash.digest('hex'),
sizeBytes
};
}
function logFaceAiAccess(event, req, details = {}) {
console.log(`[FaceAI] ${event} ${JSON.stringify({
ip: clientIp(req),
@ -118,13 +149,34 @@ async function failSearchIfProcessorUnavailable(search) {
return search;
}
return markSearchFailed(
const failedSearch = await markSearchFailed(
redis,
search.id,
'PROCESSOR_UNAVAILABLE',
processor.message,
config.searchTtlSeconds
);
if (failedSearch) {
auditStore.markSearchFailed({
searchId: failedSearch.id,
user: { id: failedSearch.userId },
race: {
id: failedSearch.raceId,
name: failedSearch.raceName,
storage: failedSearch.raceStorage
},
errorCode: 'PROCESSOR_UNAVAILABLE',
errorMessage: processor.message,
completedAt: failedSearch.completedAt || Date.now(),
payload: {
processorAgeMs: processor.ageMs,
processorHeartbeat: processor.heartbeat
}
});
}
return failedSearch;
}
async function resolveBlockingActiveSearch(userId) {
@ -534,6 +586,18 @@ app.post('/api/searches', requireSession, enforceSearchRateLimit, upload.single(
const processor = await getProcessorAvailability();
if (!processor.available) {
auditStore.recordEvent({
eventType: 'search_blocked_processor_unavailable',
user: summarizeUser(req.faceaiSession.user),
race: summarizeRace(race),
request: requestAuditContext(req),
errorCode: 'PROCESSOR_UNAVAILABLE',
payload: {
processorAgeMs: processor.ageMs,
processorHeartbeat: processor.heartbeat
}
});
logFaceAiAccess('Identification blocked: processor unavailable', req, {
user: summarizeUser(req.faceaiSession.user),
race: summarizeRace(race),
@ -596,6 +660,7 @@ app.post('/api/searches', requireSession, enforceSearchRateLimit, upload.single(
await fsp.mkdir(finalUploadDir, { recursive: true });
const finalUploadPath = path.join(finalUploadDir, path.basename(req.file.path));
await fsp.rename(req.file.path, finalUploadPath);
const selfieFingerprint = await fingerprintUpload(finalUploadPath);
const updatedSearch = await saveSearchRecord(redis, {
...search,
@ -603,6 +668,17 @@ app.post('/api/searches', requireSession, enforceSearchRateLimit, upload.single(
uploadPath: finalUploadPath
}, config.searchTtlSeconds);
auditStore.recordSearchRequested({
search: updatedSearch,
user: req.faceaiSession.user,
race,
request: requestAuditContext(req),
selfieFingerprint,
payload: {
availability
}
});
await searchQueue.add('run-search', {
searchId: search.id
}, {
@ -690,6 +766,16 @@ app.get('/api/searches/:id/redirect', requireSession, async (req, res) => {
redirectUrl
});
auditStore.markRedirectIssued({
searchId: search.id,
user: req.faceaiSession.user,
race: req.faceaiSession.race,
request: requestAuditContext(req),
resultId: result.id,
matchCount: result.matches?.length || 0,
redirectUrl
});
res.json({
url: redirectUrl
});

View file

@ -26,6 +26,8 @@ export const config = {
workerTimeoutMs: Number(process.env.FACEAI_WORKER_TIMEOUT_MS || 5 * 60 * 1000),
runtimeRoot: process.env.FACEAI_RUNTIME_ROOT || '/data/runtime',
logRoot: process.env.FACEAI_LOG_ROOT || path.join(process.env.FACEAI_RUNTIME_ROOT || '/data/runtime', 'logs'),
auditDbPath: process.env.FACEAI_AUDIT_DB_PATH || path.join(process.env.FACEAI_LOG_ROOT || '/data/logs', 'faceai-audit.sqlite'),
auditRetentionDays: Number(process.env.FACEAI_AUDIT_RETENTION_DAYS || 730),
pklRoot: process.env.FACEAI_PKL_ROOT || '/data/pkl',
matcherBinary: process.env.FACEAI_MATCHER_BINARY || '/app/bin/face_matcher',
matcherTolerance,

View file

@ -32,7 +32,7 @@ export async function runFaceMatcher({ matcherBinary, matcherTolerance, selfiePa
];
if (matcherTolerance !== null && matcherTolerance !== undefined) {
matcherArgs.push('--tollerance', String(matcherTolerance));
matcherArgs.push('--tolerance', String(matcherTolerance));
}
const child = spawn(matcherBinary, matcherArgs, {

View file

@ -3,6 +3,7 @@ import fs from 'node:fs/promises';
import path from 'node:path';
import { Worker } from 'bullmq';
import { config } from './config.js';
import { createAuditStore } from '../../backend/src/audit-store.js';
import {
createRedisConnection,
getSearchRecord,
@ -16,6 +17,7 @@ import {
import { parseMatcherCsv, resolvePklPath, runFaceMatcher } from './worker-utils.js';
const connection = createRedisConnection(config.redisUrl);
const auditStore = createAuditStore({ dbPath: config.auditDbPath, retentionDays: config.auditRetentionDays });
async function ensureMatcherBinaryAvailable() {
try {
@ -93,9 +95,23 @@ async function completeSearch(search, searchId, searchLogPath, matchCount, match
completionCode
});
await markSearchCompleted(connection, searchId, result.id, matchCount, config.searchTtlSeconds, {
const completedSearch = await markSearchCompleted(connection, searchId, result.id, matchCount, config.searchTtlSeconds, {
completionCode
});
auditStore.markSearchCompleted({
searchId,
user: { id: search.userId },
race: {
id: search.raceId,
name: search.raceName,
storage: search.raceStorage
},
resultId: result.id,
matchCount,
matches,
completionCode,
completedAt: completedSearch?.completedAt || Date.now()
});
await releaseActiveSearchLock(connection, search.userId, searchId);
}
@ -178,7 +194,22 @@ async function processJob(job) {
message: error.message,
stack: error.stack || null
});
await markSearchFailed(connection, searchId, 'PROCESSOR_ERROR', error.message, config.searchTtlSeconds);
const failedSearch = await markSearchFailed(connection, searchId, 'PROCESSOR_ERROR', error.message, config.searchTtlSeconds);
auditStore.markSearchFailed({
searchId,
user: { id: search.userId },
race: {
id: search.raceId,
name: search.raceName,
storage: search.raceStorage
},
errorCode: 'PROCESSOR_ERROR',
errorMessage: error.message,
completedAt: failedSearch?.completedAt || Date.now(),
payload: {
stack: error.stack || null
}
});
await releaseActiveSearchLock(connection, search.userId, searchId);
throw error;
}