From b95f058a66b59c2b57763e3985648c75afe25554 Mon Sep 17 00:00:00 2001 From: Darkraise Date: Tue, 10 Feb 2026 16:55:54 +0700 Subject: [PATCH] fix: reduce log noise, harden DB reload, and tune caches - Demote per-request game service logs to debug level - Add reentrant guard to DatabaseService.syncAndReload - Enable WAL mode + PRAGMA tuning for user.db - Align CachedSystemSettingsService cleanup to 90s interval - Extract CACHE_TTL constant in GameSearchCache - Add PerformanceMetrics hourly cleanup with .unref() - Fix migration timing to measure exec only, type result - Add parseInt NaN fallback for OTEL metrics interval - Make config object readonly with `as const` --- backend/src/config.ts | 2 +- backend/src/game/gamezipserver.ts | 4 ++-- backend/src/game/legacy-server.ts | 3 +-- backend/src/game/proxy-request-handler.ts | 2 +- backend/src/game/zip-manager.ts | 4 ---- backend/src/server.ts | 13 ++++++++++- .../services/CachedSystemSettingsService.ts | 4 ++-- backend/src/services/DatabaseService.ts | 15 ++++++++++--- backend/src/services/GameSearchCache.ts | 6 +++-- backend/src/services/UserDatabaseService.ts | 22 +++++++++++-------- backend/src/telemetry/otel.ts | 3 ++- 11 files changed, 50 insertions(+), 28 deletions(-) diff --git a/backend/src/config.ts b/backend/src/config.ts index 199f8c7..dc689d7 100644 --- a/backend/src/config.ts +++ b/backend/src/config.ts @@ -107,7 +107,7 @@ export const config = { // Auto-detected from version.txt; affects metadata sync and image path availability flashpointEdition: flashpointVersion.edition, flashpointVersionString: flashpointVersion.versionString, -}; +} as const; /** Resolves external image CDN URLs from Flashpoint preferences, with hardcoded fallbacks. */ export async function getExternalImageUrls(): Promise { diff --git a/backend/src/game/gamezipserver.ts b/backend/src/game/gamezipserver.ts index 8d5e1d8..d6f4eac 100644 --- a/backend/src/game/gamezipserver.ts +++ b/backend/src/game/gamezipserver.ts @@ -280,10 +280,10 @@ export class GameZipServer { let fileData = result.data; if (ext === 'html' || ext === 'htm') { fileData = injectPolyfills(result.data); - logger.info(`[GameZipServer] Injected polyfills into HTML file: ${relPath}`); + logger.debug(`[GameZipServer] Injected polyfills into HTML file: ${relPath}`); } - logger.info( + logger.debug( `[GameZipServer] ✓ Serving from ZIP ${result.mountId}: ${relPath} (${fileData.length} bytes)` ); diff --git a/backend/src/game/legacy-server.ts b/backend/src/game/legacy-server.ts index da9fd65..3f9543e 100644 --- a/backend/src/game/legacy-server.ts +++ b/backend/src/game/legacy-server.ts @@ -162,8 +162,7 @@ export class LegacyServer { const host = hostname.split(':')[0]; const relPath = path.posix.join(host, urlPath); - logger.debug(`[LegacyServer] Serving: ${host}${urlPath}`); - logger.debug(`[LegacyServer] Relative path: ${relPath}`); + logger.debug(`[LegacyServer] Serving: ${host}${urlPath} (relPath: ${relPath})`); const pathCandidates = this.buildPathCandidates(relPath, urlPath, settings); diff --git a/backend/src/game/proxy-request-handler.ts b/backend/src/game/proxy-request-handler.ts index 81498c2..ec8980d 100644 --- a/backend/src/game/proxy-request-handler.ts +++ b/backend/src/game/proxy-request-handler.ts @@ -36,7 +36,7 @@ export class ProxyRequestHandler { /** Replicates the request processing flow from Go's goproxy */ async handleRequest(req: IncomingMessage, res: ServerResponse): Promise { try { - logger.info(`[ProxyHandler] ${req.method} ${req.url}`); + logger.debug(`[ProxyHandler] ${req.method} ${req.url}`); if (!req.url) { this.sendError(res, 400, 'Bad Request: No URL'); diff --git a/backend/src/game/zip-manager.ts b/backend/src/game/zip-manager.ts index 9f5c265..e77165d 100644 --- a/backend/src/game/zip-manager.ts +++ b/backend/src/game/zip-manager.ts @@ -175,12 +175,8 @@ export class ZipManager { return null; } - logger.debug(`[ZipManager] Reading from ZIP ${id}: ${normalizedPath}`); - const data = await mounted.zip.entryData(normalizedPath); - logger.debug(`[ZipManager] ✓ Read ${data.length} bytes from ${id}:${normalizedPath}`); - return data; } catch (error) { // File not found in ZIP diff --git a/backend/src/server.ts b/backend/src/server.ts index 89dc904..b43afd8 100644 --- a/backend/src/server.ts +++ b/backend/src/server.ts @@ -26,6 +26,7 @@ import { MetadataSyncJob } from './jobs/MetadataSyncJob'; import { RuffleUpdateJob } from './jobs/RuffleUpdateJob'; import { CachedSystemSettingsService } from './services/CachedSystemSettingsService'; import { PermissionCache } from './services/PermissionCache'; +import { PerformanceMetrics } from './services/PerformanceMetrics'; import { RuffleService } from './services/RuffleService'; import { ConfigManager } from './game/config'; import { PreferencesService } from './game/services/PreferencesService'; @@ -259,7 +260,7 @@ async function startServer() { } else { logger.warn('File logging verification failed - check permissions'); } - }, 1000); + }, 1000).unref(); } else if (loggingStatus.fileError) { logger.warn(`File logging unavailable: ${loggingStatus.fileError}`); } @@ -321,6 +322,15 @@ async function startServer() { logger.error('Failed to cleanup old activity logs:', error); }); + // Cleanup old performance metrics every hour + const metricsCleanupInterval = setInterval( + () => { + PerformanceMetrics.cleanupOldMetrics(); + }, + 60 * 60 * 1000 + ); + metricsCleanupInterval.unref(); + const jobExecutionService = new JobExecutionService(); const jobLogCleanupInterval = setInterval( () => { @@ -343,6 +353,7 @@ async function startServer() { clearInterval(loginAttemptsCleanupInterval); clearInterval(activityLogsCleanupInterval); clearInterval(jobLogCleanupInterval); + clearInterval(metricsCleanupInterval); try { gameZipServer.dispose(); diff --git a/backend/src/services/CachedSystemSettingsService.ts b/backend/src/services/CachedSystemSettingsService.ts index 57a0cc2..295a5fd 100644 --- a/backend/src/services/CachedSystemSettingsService.ts +++ b/backend/src/services/CachedSystemSettingsService.ts @@ -50,8 +50,8 @@ export class CachedSystemSettingsService extends SystemSettingsService { super(); this.cacheTTL = cacheTTL; - // Start cache cleanup interval (every 5 minutes) - this.cleanupIntervalId = setInterval(() => this.cleanup(), 5 * 60 * 1000).unref(); + // Start cache cleanup interval — aligned to cache TTL (90s vs 60s TTL) + this.cleanupIntervalId = setInterval(() => this.cleanup(), 90 * 1000).unref(); } /** diff --git a/backend/src/services/DatabaseService.ts b/backend/src/services/DatabaseService.ts index ca18d09..c41aaff 100644 --- a/backend/src/services/DatabaseService.ts +++ b/backend/src/services/DatabaseService.ts @@ -33,6 +33,7 @@ export class DatabaseService { private static sourceDbPath: string = ''; // Original path (may be network) private static activeDbPath: string = ''; // Path actually used (local or network) private static isUsingLocalCopy: boolean = false; + private static isReloading: boolean = false; static async initialize(): Promise { try { @@ -299,6 +300,11 @@ export class DatabaseService { * Called when source database file changes */ private static async syncAndReload(): Promise { + if (this.isReloading) { + logger.debug('syncAndReload already in progress, skipping'); + return; + } + this.isReloading = true; try { // Check if file was actually modified const stats = fs.statSync(this.sourceDbPath); @@ -345,12 +351,15 @@ export class DatabaseService { logger.error('Failed to sync and reload database:', error); // Log but don't retry — calling initialize() here risks rapid retry loops // since it re-registers the file watcher which could trigger another syncAndReload + } finally { + this.isReloading = false; } } /** * Legacy method for backward compatibility * @deprecated Use syncAndReload instead + * @see syncAndReload */ private static async reloadFromDisk(): Promise { return this.syncAndReload(); @@ -542,9 +551,9 @@ export class DatabaseService { ); } - // Save database changes to disk - // Note: With better-sqlite3 in DELETE journal mode, changes are automatically written to disk - // This method exists for compatibility but is essentially a no-op + /** + * @deprecated No-op — changes are automatically flushed in DELETE journal mode. + */ static save(): void { // No action needed in DELETE journal mode // Changes are automatically flushed to disk diff --git a/backend/src/services/GameSearchCache.ts b/backend/src/services/GameSearchCache.ts index 55b9135..abccff6 100644 --- a/backend/src/services/GameSearchCache.ts +++ b/backend/src/services/GameSearchCache.ts @@ -17,13 +17,15 @@ import { config } from '../config'; * since Flashpoint database is read-only and changes are rare) */ export class GameSearchCache { + private static readonly CACHE_TTL = 1000 * 60 * 5; // 5 minutes + // In-flight request tracking for cache stampede prevention private static inFlightRequests = new Map>>(); private static cache = new LRUCache>({ max: 1000, // Maximum 1000 cached search queries maxSize: 10000, // Maximum total items across all cached results (10k games) - ttl: 1000 * 60 * 5, // 5 minutes TTL + ttl: GameSearchCache.CACHE_TTL, updateAgeOnGet: true, // Reset TTL on cache hit allowStale: false, // Never return stale data @@ -197,7 +199,7 @@ export class GameSearchCache { primary: { size: this.cache.size, max: this.cache.max, - ttl: 1000 * 60 * 5, // 5 minutes + ttl: GameSearchCache.CACHE_TTL, }, fallback: this.fallbackCache.getStats(), }; diff --git a/backend/src/services/UserDatabaseService.ts b/backend/src/services/UserDatabaseService.ts index 83695cf..0ad5f27 100644 --- a/backend/src/services/UserDatabaseService.ts +++ b/backend/src/services/UserDatabaseService.ts @@ -22,8 +22,11 @@ export class UserDatabaseService { this.db = new BetterSqlite3(config.userDbPath); logger.info(`[UserDB] Opened database at: ${config.userDbPath}`); - // Enable foreign keys + // Apply PRAGMA optimizations (WAL mode for better concurrent read/write) + this.db.pragma('journal_mode = WAL'); this.db.pragma('foreign_keys = ON'); + this.db.pragma('cache_size = -8000'); // 8MB cache + this.db.pragma('mmap_size = 67108864'); // 64MB mmap // Bootstrap migration registry await this.bootstrapMigrationRegistry(); @@ -153,21 +156,21 @@ export class UserDatabaseService { // Read migration SQL const sql = fs.readFileSync(migrationPath, 'utf-8'); const checksum = this.computeChecksum(sql); - const start = Date.now(); // Wrap migration execution and registry insert in a single transaction const runMigration = this.db!.transaction(() => { + const start = Date.now(); this.db!.exec(sql); - const executionTime = Date.now() - start; + this.db!.prepare( 'INSERT INTO migrations (name, applied_at, checksum, execution_time_ms) VALUES (?, ?, ?, ?)' ).run(name, new Date().toISOString(), checksum, executionTime); + + return executionTime; }); - runMigration(); - - const executionTime = Date.now() - start; + const executionTime = runMigration(); logger.info(`[UserDB] Migration completed: ${name} (${executionTime}ms)`); } else { logger.debug(`[UserDB] Migration already applied: ${name}`); @@ -186,8 +189,9 @@ export class UserDatabaseService { */ static needsInitialSetup(): boolean { try { - const userCount = this.get('SELECT COUNT(*) as count FROM users', []); - const needsSetup = userCount?.count === 0; + const userCount = this.get<{ count: number }>('SELECT COUNT(*) as count FROM users', []); + const count = userCount?.count ?? 0; + const needsSetup = count === 0; if (needsSetup) { logger.info('╔═══════════════════════════════════════════════════════════════╗'); @@ -196,7 +200,7 @@ export class UserDatabaseService { logger.info('║ The first registered user will become an administrator. ║'); logger.info('╚═══════════════════════════════════════════════════════════════╝'); } else { - logger.debug(`[UserDB] Found ${userCount.count} existing user(s)`); + logger.debug(`[UserDB] Found ${count} existing user(s)`); } return needsSetup; diff --git a/backend/src/telemetry/otel.ts b/backend/src/telemetry/otel.ts index 5dec183..978d788 100644 --- a/backend/src/telemetry/otel.ts +++ b/backend/src/telemetry/otel.ts @@ -44,7 +44,8 @@ function getOtelConfig() { serviceVersion: process.env.npm_package_version || '1.0.0', tracesEnabled: process.env.OTEL_TRACES_ENABLED !== 'false', metricsEnabled: process.env.OTEL_METRICS_ENABLED !== 'false', - metricsExportInterval: parseInt(process.env.OTEL_METRICS_EXPORT_INTERVAL || '60000', 10), + metricsExportInterval: + parseInt(process.env.OTEL_METRICS_EXPORT_INTERVAL || '60000', 10) || 60000, logLevel: process.env.OTEL_LOG_LEVEL || 'info', }; }