Implement centralized logging with RMABLogger

Replaces scattered console statements with a unified RMABLogger across backend API routes and services. Adds LOG_LEVEL-based filtering, job-aware database persistence, and context-based logging. Updates documentation to describe the new logging system and usage patterns. Also documents qBittorrent CSRF header fix
This commit is contained in:
kikootwo
2026-01-12 12:45:48 -05:00
parent ba5f5cf7d6
commit 682836237b
118 changed files with 1623 additions and 1079 deletions
+44 -62
View File
@@ -9,9 +9,10 @@
import { prisma } from '@/lib/db';
import { compareTwoStrings } from 'string-similarity';
import { LibraryItem } from '@/lib/services/library';
import { RMABLogger } from './logger';
// Debug logging controlled by LOG_LEVEL environment variable
const DEBUG_ENABLED = process.env.LOG_LEVEL === 'debug';
// Module-level logger
const logger = RMABLogger.create('AudiobookMatcher');
export interface AudiobookMatchInput {
asin: string;
@@ -109,7 +110,7 @@ export async function findPlexMatch(
// If no candidates found, log and return null
if (plexBooks.length === 0) {
matchResult.matchType = 'no_candidates';
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return null;
}
@@ -125,7 +126,7 @@ export async function findPlexMatch(
asin: plexBook.asin,
confidence: 100,
};
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return plexBook;
}
}
@@ -141,7 +142,7 @@ export async function findPlexMatch(
plexAuthor: plexBook.author,
confidence: 100,
};
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return plexBook;
}
}
@@ -182,7 +183,7 @@ export async function findPlexMatch(
if (validCandidates.length === 0) {
matchResult.matchType = 'asin_filtered_all';
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return null;
}
@@ -250,13 +251,13 @@ export async function findPlexMatch(
plexAuthor: bestMatch.plexBook.author,
confidence: Math.round(bestMatch.score * 100),
};
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return bestMatch.plexBook;
}
// No match found
matchResult.matchType = 'fuzzy_below_threshold';
if (DEBUG_ENABLED) console.log(JSON.stringify({ MATCHER: matchResult }));
logger.debug('Matcher result', { MATCHER: matchResult });
return null;
}
@@ -362,15 +363,12 @@ export async function enrichAudiobooksWithMatches(
}
}
if (DEBUG_ENABLED) {
const summary = {
total: results.length,
available: results.filter(r => r.isAvailable).length,
notAvailable: results.filter(r => !r.isAvailable).length,
requested: userId ? results.filter(r => (r as any).isRequested).length : 'N/A',
};
console.log(JSON.stringify({ MATCHER_BATCH_SUMMARY: summary }));
}
logger.debug('Batch summary', {
total: results.length,
available: results.filter(r => r.isAvailable).length,
notAvailable: results.filter(r => !r.isAvailable).length,
requested: userId ? results.filter(r => (r as any).isRequested).length : 'N/A',
});
return results;
}
@@ -405,16 +403,12 @@ export function matchAudiobook(
item.asin?.toLowerCase() === request.asin?.toLowerCase()
);
if (asinMatch) {
if (DEBUG_ENABLED) {
console.log(JSON.stringify({
GENERIC_MATCHER: {
matchType: 'asin_exact',
input: { title: request.title, asin: request.asin },
matched: { title: asinMatch.title, asin: asinMatch.asin },
confidence: 100
}
}));
}
logger.debug('Generic matcher result', {
matchType: 'asin_exact',
input: { title: request.title, asin: request.asin },
matched: { title: asinMatch.title, asin: asinMatch.asin },
confidence: 100
});
return asinMatch;
}
}
@@ -426,16 +420,12 @@ export function matchAudiobook(
item.isbn && normalizeISBN(item.isbn) === normalizedRequestISBN
);
if (isbnMatch) {
if (DEBUG_ENABLED) {
console.log(JSON.stringify({
GENERIC_MATCHER: {
matchType: 'isbn_exact',
input: { title: request.title, isbn: request.isbn },
matched: { title: isbnMatch.title, isbn: isbnMatch.isbn },
confidence: 95
}
}));
}
logger.debug('Generic matcher result', {
matchType: 'isbn_exact',
input: { title: request.title, isbn: request.isbn },
matched: { title: isbnMatch.title, isbn: isbnMatch.isbn },
confidence: 95
});
return isbnMatch;
}
}
@@ -463,35 +453,27 @@ export function matchAudiobook(
// Accept if score >= 70%
if (bestMatch && bestMatch.score >= 0.7) {
if (DEBUG_ENABLED) {
console.log(JSON.stringify({
GENERIC_MATCHER: {
matchType: 'fuzzy',
input: { title: request.title, author: request.author },
matched: { title: bestMatch.item.title, author: bestMatch.item.author },
scores: {
title: Math.round(bestMatch.titleScore * 100),
author: Math.round(bestMatch.authorScore * 100),
overall: Math.round(bestMatch.score * 100)
},
confidence: Math.round(bestMatch.score * 100)
}
}));
}
logger.debug('Generic matcher result', {
matchType: 'fuzzy',
input: { title: request.title, author: request.author },
matched: { title: bestMatch.item.title, author: bestMatch.item.author },
scores: {
title: Math.round(bestMatch.titleScore * 100),
author: Math.round(bestMatch.authorScore * 100),
overall: Math.round(bestMatch.score * 100)
},
confidence: Math.round(bestMatch.score * 100)
});
return bestMatch.item;
}
// No match found
if (DEBUG_ENABLED) {
console.log(JSON.stringify({
GENERIC_MATCHER: {
matchType: 'no_match',
input: { title: request.title, author: request.author },
bestScore: bestMatch ? Math.round(bestMatch.score * 100) : 0,
threshold: 70
}
}));
}
logger.debug('Generic matcher result', {
matchType: 'no_match',
input: { title: request.title, author: request.author },
bestScore: bestMatch ? Math.round(bestMatch.score * 100) : 0,
threshold: 70
});
return null;
}
+12 -9
View File
@@ -8,6 +8,9 @@ import path from 'path';
import axios from 'axios';
import { createJobLogger, JobLogger } from './job-logger';
import { tagMultipleFiles, checkFfmpegAvailable } from './metadata-tagger';
import { RMABLogger } from './logger';
const moduleLogger = RMABLogger.create('FileOrganizer');
import {
detectChapterFiles,
analyzeChapterFiles,
@@ -296,7 +299,7 @@ export class FileOrganizer {
try {
await fs.access(sourcePath, fs.constants.R_OK);
} catch {
console.warn(`[FileOrganizer] Source file not found or not readable: ${sourcePath}`);
moduleLogger.warn(`Source file not found or not readable: ${sourcePath}`);
result.errors.push(`Source file not found: ${audioFile}`);
continue;
}
@@ -304,7 +307,7 @@ export class FileOrganizer {
// Check if target already exists (skip if already copied)
try {
await fs.access(targetFilePath);
console.log(`[FileOrganizer] File already exists, skipping: ${filename}`);
moduleLogger.debug(`File already exists, skipping: ${filename}`);
result.audioFiles.push(targetFilePath);
// Clean up tagged temp file if it exists
@@ -504,7 +507,7 @@ export class FileOrganizer {
}
}
} catch (error) {
console.error('[FileOrganizer] Error reading directory:', error);
moduleLogger.error('Error reading directory', { error: error instanceof Error ? error.message : String(error) });
throw error;
}
@@ -532,7 +535,7 @@ export class FileOrganizer {
}
}
} catch (error) {
console.error(`[FileOrganizer] Error reading directory ${dir}:`, error);
moduleLogger.error(`Error reading directory ${dir}`, { error: error instanceof Error ? error.message : String(error) });
}
return files;
@@ -601,7 +604,7 @@ export class FileOrganizer {
// Copy from local cache instead of downloading
await fs.copyFile(cachedPath, targetPath);
await fs.chmod(targetPath, 0o644);
console.log(`[FileOrganizer] Copied cover art from cache: ${filename}`);
moduleLogger.debug(`Copied cover art from cache: ${filename}`);
} else {
// Download from external URL (e.g., Audible CDN)
const response = await axios.get(url, {
@@ -610,10 +613,10 @@ export class FileOrganizer {
});
await fs.writeFile(targetPath, response.data);
console.log(`[FileOrganizer] Downloaded cover art from URL`);
moduleLogger.debug(`Downloaded cover art from URL`);
}
} catch (error) {
console.error('[FileOrganizer] Failed to download cover art:', error);
moduleLogger.error('Failed to download cover art', { error: error instanceof Error ? error.message : String(error) });
throw error;
}
}
@@ -625,9 +628,9 @@ export class FileOrganizer {
try {
// Remove download directory and all remaining files
await fs.rm(downloadPath, { recursive: true, force: true });
console.log(`[FileOrganizer] Cleaned up: ${downloadPath}`);
moduleLogger.debug(`Cleaned up: ${downloadPath}`);
} catch (error) {
console.error(`[FileOrganizer] Cleanup failed for ${downloadPath}:`, error);
moduleLogger.error(`Cleanup failed for ${downloadPath}`, { error: error instanceof Error ? error.message : String(error) });
// Don't throw - cleanup is non-critical
}
}
+26 -57
View File
@@ -1,96 +1,65 @@
/**
* Component: Job Logger Utility
* Component: Job Logger Utility (Backward Compatibility)
* Documentation: documentation/backend/services/jobs.md
*
* Provides structured logging for job processors with database persistence
* @deprecated Use RMABLogger.forJob() directly for new code.
* This file provides backward compatibility for existing processors.
*
* Migration example:
* ```typescript
* // Before (deprecated)
* const logger = jobId ? createJobLogger(jobId, 'Context') : null;
* await logger?.info('message');
*
* // After (preferred)
* import { RMABLogger } from './logger';
* const logger = RMABLogger.forJob(jobId, 'Context');
* logger.info('message'); // No await needed!
* ```
*/
import { prisma } from '../db';
import { RMABLogger, LogMetadata } from './logger';
export type LogLevel = 'info' | 'warn' | 'error';
export interface LogMetadata {
[key: string]: any;
}
/**
* Job Logger - Logs events to both console and database
* @deprecated Use RMABLogger.forJob() directly
*/
export class JobLogger {
private jobId: string;
private context: string;
private logger: RMABLogger;
constructor(jobId: string, context: string) {
this.jobId = jobId;
this.context = context;
this.logger = RMABLogger.forJob(jobId, context);
}
/**
* Log info message
* @deprecated Returns Promise for backward compat but is actually synchronous
*/
async info(message: string, metadata?: LogMetadata): Promise<void> {
await this.log('info', message, metadata);
this.logger.info(message, metadata);
}
/**
* Log warning message
* @deprecated Returns Promise for backward compat but is actually synchronous
*/
async warn(message: string, metadata?: LogMetadata): Promise<void> {
await this.log('warn', message, metadata);
this.logger.warn(message, metadata);
}
/**
* Log error message
* @deprecated Returns Promise for backward compat but is actually synchronous
*/
async error(message: string, metadata?: LogMetadata): Promise<void> {
await this.log('error', message, metadata);
}
/**
* Internal logging method
*/
private async log(level: LogLevel, message: string, metadata?: LogMetadata): Promise<void> {
// Log to console with timestamp (for Docker logs)
const timestamp = new Date().toISOString().split('T')[1].split('.')[0];
const consoleMessage = `[${this.context}] ${message}`;
switch (level) {
case 'info':
console.log(consoleMessage);
break;
case 'warn':
console.warn(consoleMessage);
break;
case 'error':
console.error(consoleMessage);
break;
}
// Log metadata if provided
if (metadata && Object.keys(metadata).length > 0) {
console.log(timestamp, JSON.stringify(metadata, null, 2));
}
// Persist to database (non-blocking, ignore errors to not break job execution)
try {
await prisma.jobEvent.create({
data: {
jobId: this.jobId,
level,
context: this.context,
message,
metadata: metadata ? JSON.parse(JSON.stringify(metadata)) : null,
},
});
} catch (error) {
console.error('[JobLogger] Failed to persist log to database:', error);
// Don't throw - logging failure should not break job execution
}
this.logger.error(message, metadata);
}
}
/**
* Create a job logger instance
* @deprecated Use RMABLogger.forJob() directly
*/
export function createJobLogger(jobId: string, context: string): JobLogger {
return new JobLogger(jobId, context);
+5 -1
View File
@@ -3,6 +3,10 @@
* Documentation: documentation/frontend/routing-auth.md
*/
import { RMABLogger } from './logger';
const logger = RMABLogger.create('JWTClient');
interface JWTPayload {
sub: string;
plexId: string;
@@ -27,7 +31,7 @@ export function decodeJWT(token: string): JWTPayload | null {
const decoded = JSON.parse(atob(payload.replace(/-/g, '+').replace(/_/g, '/')));
return decoded as JWTPayload;
} catch (error) {
console.error('Failed to decode JWT:', error);
logger.error('Failed to decode JWT', { error: error instanceof Error ? error.message : String(error) });
return null;
}
}
+5 -5
View File
@@ -4,6 +4,9 @@
*/
import jwt from 'jsonwebtoken';
import { RMABLogger } from './logger';
const logger = RMABLogger.create('JWT');
const JWT_SECRET = process.env.JWT_SECRET || 'change-this-to-a-random-secret-key';
const JWT_REFRESH_SECRET = process.env.JWT_REFRESH_SECRET || 'change-this-to-another-random-secret-key';
@@ -54,10 +57,7 @@ export function verifyAccessToken(token: string): TokenPayload | null {
const decoded = jwt.verify(token, JWT_SECRET) as TokenPayload;
return decoded;
} catch (error) {
console.error('[JWT] Access token verification failed:', error);
if (error instanceof Error) {
console.error('[JWT] Error details:', error.message);
}
logger.error('Access token verification failed', { error: error instanceof Error ? error.message : String(error) });
return null;
}
}
@@ -73,7 +73,7 @@ export function verifyRefreshToken(token: string): RefreshTokenPayload | null {
}
return decoded;
} catch (error) {
console.error('Refresh token verification failed:', error);
logger.error('Refresh token verification failed', { error: error instanceof Error ? error.message : String(error) });
return null;
}
}
+213
View File
@@ -0,0 +1,213 @@
/**
* Component: Centralized Logging System (RMABLogger)
* Documentation: documentation/backend/services/logging.md
*
* Single logging infrastructure for all console and database logging.
* All logs in the application should go through RMABLogger.
*/
import { prisma } from '../db';
export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'quiet';
export interface LogMetadata {
[key: string]: unknown;
}
// Log level hierarchy (lower number = more verbose)
const LEVEL_PRIORITY: Record<LogLevel, number> = {
debug: 0,
info: 1,
warn: 2,
error: 3,
quiet: 4,
};
/**
* Get configured log level from environment (single source of truth)
*/
function getConfiguredLogLevel(): LogLevel {
const envLevel = process.env.LOG_LEVEL?.toLowerCase();
if (envLevel && envLevel in LEVEL_PRIORITY) {
return envLevel as LogLevel;
}
return 'info'; // Default
}
// Cached log level (computed once at module load)
const CONFIGURED_LOG_LEVEL = getConfiguredLogLevel();
const CONFIGURED_LOG_PRIORITY = LEVEL_PRIORITY[CONFIGURED_LOG_LEVEL];
/**
* RMABLogger - Centralized Logger for ReadMeABook
*
* Features:
* - Context namespacing (e.g., RMABLogger.create('QBittorrent'))
* - Job-aware database persistence (e.g., RMABLogger.forJob(jobId, 'Context'))
* - Single LOG_LEVEL env var check point
* - Consistent formatting: [LEVEL] [Context] Message
* - Synchronous API - no await needed
*
* Usage:
* ```typescript
* // Standard logging
* const logger = RMABLogger.create('QBittorrent');
* logger.info('Connected successfully');
* logger.debug('Cookie value', { cookie: '...' });
*
* // Job-aware logging (persists to database)
* const logger = RMABLogger.forJob(jobId, 'SearchIndexers');
* logger.info('Processing request'); // Logs to console AND database
* ```
*/
export class RMABLogger {
private context: string;
private jobId: string | undefined;
private constructor(context: string, jobId?: string) {
this.context = context;
this.jobId = jobId;
}
/**
* Create a new logger with context namespace
* @param context - Logger context (e.g., 'QBittorrent', 'Plex', 'API.Auth')
*/
static create(context: string): RMABLogger {
return new RMABLogger(context);
}
/**
* Create a job-aware logger that persists to database
* @param jobId - Job ID for database persistence (if undefined, logs to console only)
* @param context - Logger context (e.g., 'SearchIndexers', 'MonitorDownload')
*/
static forJob(jobId: string | undefined, context: string): RMABLogger {
return new RMABLogger(context, jobId);
}
/**
* Create a child logger with extended context
* @param subContext - Additional context to append
*/
child(subContext: string): RMABLogger {
return new RMABLogger(`${this.context}.${subContext}`, this.jobId);
}
/**
* Debug level logging (most verbose)
* Only logged when LOG_LEVEL=debug
* Never persisted to database
*/
debug(message: string, metadata?: LogMetadata): void {
this.log('debug', message, metadata);
}
/**
* Info level logging (default level)
* Logged unless LOG_LEVEL=warn, error, or quiet
*/
info(message: string, metadata?: LogMetadata): void {
this.log('info', message, metadata);
}
/**
* Warning level logging
* Logged unless LOG_LEVEL=error or quiet
*/
warn(message: string, metadata?: LogMetadata): void {
this.log('warn', message, metadata);
}
/**
* Error level logging
* Always logged unless LOG_LEVEL=quiet
*/
error(message: string, metadata?: LogMetadata): void {
this.log('error', message, metadata);
}
/**
* Internal logging method - single point of LOG_LEVEL checking
*/
private log(
level: Exclude<LogLevel, 'quiet'>,
message: string,
metadata?: LogMetadata
): void {
const levelPriority = LEVEL_PRIORITY[level];
// Check if this level should be logged (single check point)
if (levelPriority < CONFIGURED_LOG_PRIORITY) {
return;
}
// Format: [LEVEL] [Context] Message
const formattedMessage = `[${level.toUpperCase()}] [${this.context}] ${message}`;
// Console output using appropriate method
switch (level) {
case 'debug':
console.debug(formattedMessage);
break;
case 'info':
console.log(formattedMessage);
break;
case 'warn':
console.warn(formattedMessage);
break;
case 'error':
console.error(formattedMessage);
break;
}
// Log metadata if provided
if (metadata && Object.keys(metadata).length > 0) {
console.log(JSON.stringify(metadata, null, 2));
}
// Persist to database for job-aware loggers (fire-and-forget)
// Debug logs are NEVER persisted to keep job_events clean
if (this.jobId && level !== 'debug') {
this.persistToDatabase(level, message, metadata);
}
}
/**
* Persist log to database (non-blocking, fire-and-forget)
* Errors are silently caught - logging should never break job execution
*/
private persistToDatabase(
level: Exclude<LogLevel, 'quiet' | 'debug'>,
message: string,
metadata?: LogMetadata
): void {
prisma.jobEvent
.create({
data: {
jobId: this.jobId!,
level,
context: this.context,
message,
metadata: metadata ? JSON.parse(JSON.stringify(metadata)) : null,
},
})
.catch(() => {
// Silently fail - logging should never break job execution
});
}
}
/**
* Convenience function to get the current log level
*/
export function getLogLevel(): LogLevel {
return CONFIGURED_LOG_LEVEL;
}
/**
* Check if debug logging is enabled
*/
export function isDebugEnabled(): boolean {
return CONFIGURED_LOG_LEVEL === 'debug';
}
+8 -5
View File
@@ -7,6 +7,9 @@
*/
import path from 'path';
import { RMABLogger } from './logger';
const logger = RMABLogger.create('PathMapper');
export interface PathMappingConfig {
enabled: boolean;
@@ -35,7 +38,7 @@ export class PathMapper {
// 2. Handle empty paths
if (!qbittorrentPath || !config.remotePath || !config.localPath) {
console.warn('PathMapper: Empty path or config, returning original');
logger.warn('Empty path or config, returning original');
return qbittorrentPath;
}
@@ -47,8 +50,8 @@ export class PathMapper {
// 4. Check if qBittorrent path starts with remote path
if (!normalizedQbPath.startsWith(normalizedRemote)) {
console.warn(
`PathMapper: Path "${qbittorrentPath}" does not start with remote path "${config.remotePath}". ` +
logger.warn(
`Path "${qbittorrentPath}" does not start with remote path "${config.remotePath}". ` +
`Returning original path unchanged.`
);
return qbittorrentPath;
@@ -60,7 +63,7 @@ export class PathMapper {
// Join local path with relative path, ensuring proper path separators
const transformedPath = path.join(normalizedLocal, relativePath);
console.log(`PathMapper: Transformed "${qbittorrentPath}" "${transformedPath}"`);
logger.info(`Transformed "${qbittorrentPath}" to "${transformedPath}"`);
return transformedPath;
}
@@ -95,7 +98,7 @@ export class PathMapper {
// Warn if paths look suspicious (but don't throw)
if (config.remotePath === config.localPath) {
console.warn('PathMapper: Remote and local paths are identical - path mapping will have no effect');
logger.warn('Remote and local paths are identical - path mapping will have no effect');
}
}
+11 -9
View File
@@ -3,6 +3,10 @@
* Documentation: documentation/backend/services/environment.md
*/
import { RMABLogger } from './logger';
const logger = RMABLogger.create('URL');
/**
* Get application base URL for OAuth callbacks and redirects
*
@@ -35,22 +39,20 @@ export function getBaseUrl(): string {
// Validate URL format
if (!url.startsWith('http://') && !url.startsWith('https://')) {
console.warn(`[URL Utility] Invalid base URL format: ${url}. URLs must start with http:// or https://`);
logger.warn(`Invalid base URL format: ${url}. URLs must start with http:// or https://`);
}
// Production warning if using localhost
if (process.env.NODE_ENV === 'production' && url.includes('localhost')) {
console.warn('[URL Utility] ⚠️ WARNING: Using localhost URL in production. OAuth callbacks may fail. Set PUBLIC_URL environment variable.');
logger.warn('Using localhost URL in production. OAuth callbacks may fail. Set PUBLIC_URL environment variable.');
}
// Log which variable is being used (debug only)
if (process.env.LOG_LEVEL === 'debug') {
const source = publicUrl ? 'PUBLIC_URL' :
nextAuthUrl ? 'NEXTAUTH_URL' :
baseUrl ? 'BASE_URL' :
'default (localhost)';
console.debug(`[URL Utility] Using base URL from ${source}: ${url}`);
}
const source = publicUrl ? 'PUBLIC_URL' :
nextAuthUrl ? 'NEXTAUTH_URL' :
baseUrl ? 'BASE_URL' :
'default (localhost)';
logger.debug(`Using base URL from ${source}: ${url}`);
return url;
}