Compare commits

...

2 Commits

Author SHA1 Message Date
6b195d3014 feat: add comprehensive logging system with file output
- Add backend logging to logs/backend.log with file rotation support
- Add frontend logging to logs/frontend.log via /api/logs endpoint
- Add frontend logger utility with batching and user context
- Update .gitignore to exclude log files but preserve logs directory
- Update CLAUDE.md with logging documentation and usage examples

Co-Authored-By: Claude Sonnet 4.5 <noreply@anthropic.com>
2026-01-20 11:04:31 +01:00
ac0c8a39a9 fix: resolve Elysia framework and Vite URI error bugs
- Fix onResponse error by using onAfterHandle for Elysia framework
- Fix URI malformed errors from browser extensions in Vite dev server
- Update middleware plugin to run before SvelteKit with enforce: 'pre'
- Insert middleware at beginning of stack to catch malformed URIs early

Co-Authored-By: Claude Sonnet 4.5 <noreply@anthropic.com>
2026-01-20 11:03:43 +01:00
6 changed files with 398 additions and 26 deletions

2
.gitignore vendored
View File

@@ -15,9 +15,11 @@ coverage
*.lcov *.lcov
# logs # logs
logs/*.log
logs logs
_.log _.log
report.[0-9]_.[0-9]_.[0-9]_.[0-9]_.json report.[0-9]_.[0-9]_.[0-9]_.[0-9]_.json
!logs/.gitkeep
# dotenv environment variable files # dotenv environment variable files
.env .env

View File

@@ -21,11 +21,36 @@ Default to using Bun instead of Node.js.
## Logging ## Logging
The application uses a custom logger in `src/backend/config.js`: The application uses a custom logger that outputs to both files and console.
### Backend Logging
Backend logs are written to `logs/backend.log`:
- **Log levels**: `debug` (0), `info` (1), `warn` (2), `error` (3) - **Log levels**: `debug` (0), `info` (1), `warn` (2), `error` (3)
- **Default**: `debug` in development, `info` in production - **Default**: `debug` in development, `info` in production
- **Override**: Set `LOG_LEVEL` environment variable (e.g., `LOG_LEVEL=debug`) - **Override**: Set `LOG_LEVEL` environment variable (e.g., `LOG_LEVEL=debug`)
- **Output format**: `[timestamp] LEVEL: message` with JSON data - **Output format**: `[timestamp] LEVEL: message` with JSON data
- **Console**: Also outputs to console in development mode
- **File**: Always writes to `logs/backend.log`
### Frontend Logging
Frontend logs are sent to the backend and written to `logs/frontend.log`:
- **Logger**: `src/frontend/src/lib/logger.js`
- **Endpoint**: `POST /api/logs`
- **Batching**: Batches logs (up to 10 entries or 5 seconds) for performance
- **User context**: Automatically includes userId and user-agent
- **Levels**: Same as backend (debug, info, warn, error)
**Usage in frontend**:
```javascript
import { logger } from '$lib/logger';
logger.info('User action', { action: 'click', element: 'button' });
logger.error('API error', { error: err.message });
logger.warn('Deprecated feature used');
logger.debug('Component state', { state: componentState });
```
**Important**: The logger uses the nullish coalescing operator (`??`) to handle log levels. This ensures that `debug` (level 0) is not treated as falsy. **Important**: The logger uses the nullish coalescing operator (`??`) to handle log levels. This ensures that `debug` (level 0) is not treated as falsy.
@@ -35,6 +60,11 @@ NODE_ENV=development
LOG_LEVEL=debug LOG_LEVEL=debug
``` ```
**Log Files**:
- `logs/backend.log` - Backend server logs
- `logs/frontend.log` - Frontend client logs
- Logs are excluded from git via `.gitignore`
## Testing ## Testing
Use `bun test` to run tests. Use `bun test` to run tests.

View File

@@ -1,12 +1,18 @@
import Database from 'bun:sqlite'; import Database from 'bun:sqlite';
import { drizzle } from 'drizzle-orm/bun-sqlite'; import { drizzle } from 'drizzle-orm/bun-sqlite';
import * as schema from './db/schema/index.js'; import * as schema from './db/schema/index.js';
import { join } from 'path'; import { join, dirname } from 'path';
import { existsSync, mkdirSync } from 'fs';
import { fileURLToPath } from 'url';
// =================================================================== // ===================================================================
// Configuration // Configuration
// =================================================================== // ===================================================================
// ES module equivalent of __dirname
const __filename = fileURLToPath(import.meta.url);
const __dirname = dirname(__filename);
const isDevelopment = process.env.NODE_ENV !== 'production'; const isDevelopment = process.env.NODE_ENV !== 'production';
export const JWT_SECRET = process.env.JWT_SECRET || 'your-secret-key-change-in-production'; export const JWT_SECRET = process.env.JWT_SECRET || 'your-secret-key-change-in-production';
@@ -19,16 +25,46 @@ export const LOG_LEVEL = process.env.LOG_LEVEL || (isDevelopment ? 'debug' : 'in
const logLevels = { debug: 0, info: 1, warn: 2, error: 3 }; const logLevels = { debug: 0, info: 1, warn: 2, error: 3 };
const currentLogLevel = logLevels[LOG_LEVEL] ?? 1; const currentLogLevel = logLevels[LOG_LEVEL] ?? 1;
// Log file paths
const logsDir = join(__dirname, '../../logs');
const backendLogFile = join(logsDir, 'backend.log');
// Ensure log directory exists
if (!existsSync(logsDir)) {
mkdirSync(logsDir, { recursive: true });
}
function formatLogMessage(level, message, data) {
const timestamp = new Date().toISOString();
let logMessage = `[${timestamp}] ${level.toUpperCase()}: ${message}`;
if (data && Object.keys(data).length > 0) {
logMessage += ' ' + JSON.stringify(data, null, 2);
}
return logMessage + '\n';
}
function log(level, message, data) { function log(level, message, data) {
if (logLevels[level] < currentLogLevel) return; if (logLevels[level] < currentLogLevel) return;
const timestamp = new Date().toISOString(); const logMessage = formatLogMessage(level, message, data);
const logMessage = `[${timestamp}] ${level.toUpperCase()}: ${message}`;
if (data && Object.keys(data).length > 0) { // Write to file asynchronously (fire and forget for performance)
console.log(logMessage, JSON.stringify(data, null, 2)); Bun.write(backendLogFile, logMessage, { createPath: true }).catch(err => {
} else { console.error('Failed to write to log file:', err);
console.log(logMessage); });
// Also log to console in development
if (isDevelopment) {
const timestamp = new Date().toISOString();
const consoleMessage = `[${timestamp}] ${level.toUpperCase()}: ${message}`;
if (data && Object.keys(data).length > 0) {
console.log(consoleMessage, data);
} else {
console.log(consoleMessage);
}
} }
} }
@@ -39,6 +75,27 @@ export const logger = {
error: (message, data) => log('error', message, data), error: (message, data) => log('error', message, data),
}; };
// Frontend logger - writes to separate log file
const frontendLogFile = join(logsDir, 'frontend.log');
export function logToFrontend(level, message, data = null, context = {}) {
if (logLevels[level] < currentLogLevel) return;
const timestamp = new Date().toISOString();
let logMessage = `[${timestamp}] [${context.userAgent || 'unknown'}] [${context.userId || 'anonymous'}] ${level.toUpperCase()}: ${message}`;
if (data && Object.keys(data).length > 0) {
logMessage += ' ' + JSON.stringify(data, null, 2);
}
logMessage += '\n';
// Write to frontend log file
Bun.write(frontendLogFile, logMessage, { createPath: true }).catch(err => {
console.error('Failed to write to frontend log file:', err);
});
}
export default logger; export default logger;
// =================================================================== // ===================================================================
@@ -46,7 +103,6 @@ export default logger;
// =================================================================== // ===================================================================
// Get the directory containing this config file, then go to parent for db location // Get the directory containing this config file, then go to parent for db location
const __dirname = new URL('.', import.meta.url).pathname;
const dbPath = join(__dirname, 'award.db'); const dbPath = join(__dirname, 'award.db');
const sqlite = new Database(dbPath); const sqlite = new Database(dbPath);

View File

@@ -1,7 +1,7 @@
import { Elysia, t } from 'elysia'; import { Elysia, t } from 'elysia';
import { cors } from '@elysiajs/cors'; import { cors } from '@elysiajs/cors';
import { jwt } from '@elysiajs/jwt'; import { jwt } from '@elysiajs/jwt';
import { JWT_SECRET, logger, LOG_LEVEL } from './config.js'; import { JWT_SECRET, logger, LOG_LEVEL, logToFrontend } from './config.js';
import { import {
registerUser, registerUser,
authenticateUser, authenticateUser,
@@ -79,6 +79,44 @@ const app = new Elysia()
} }
}) })
// Request logging middleware
.onRequest(({ request, params }) => {
const url = new URL(request.url);
const method = request.method;
const path = url.pathname;
const query = url.search;
// Skip logging for health checks in development to reduce noise
if (path === '/api/health' && process.env.NODE_ENV === 'development') {
return;
}
logger.info('Incoming request', {
method,
path,
query: query || undefined,
ip: request.headers.get('x-forwarded-for') || 'unknown',
userAgent: request.headers.get('user-agent')?.substring(0, 100),
});
})
.onAfterHandle(({ request, set }) => {
const url = new URL(request.url);
const path = url.pathname;
// Skip logging for health checks in development
if (path === '/api/health' && process.env.NODE_ENV === 'development') {
return;
}
// Log error responses
if (set.status >= 400) {
logger.warn('Request failed', {
path,
status: set.status,
});
}
})
/** /**
* POST /api/auth/register * POST /api/auth/register
* Register a new user * Register a new user
@@ -706,6 +744,47 @@ const app = new Elysia()
timestamp: new Date().toISOString(), timestamp: new Date().toISOString(),
})) }))
/**
* POST /api/logs
* Receive frontend logs and write them to frontend.log file
*/
.post(
'/api/logs',
async ({ body, user, headers }) => {
// Extract context from headers (Elysia provides headers as a plain object)
const userAgent = headers['user-agent'] || 'unknown';
const context = {
userId: user?.id,
userAgent,
timestamp: new Date().toISOString(),
};
// Log each entry
const entries = Array.isArray(body) ? body : [body];
for (const entry of entries) {
logToFrontend(entry.level || 'info', entry.message || 'No message', entry.data || null, context);
}
return { success: true };
},
{
body: t.Union([
t.Object({
level: t.Optional(t.Union([t.Literal('debug'), t.Literal('info'), t.Literal('warn'), t.Literal('error')])),
message: t.String(),
data: t.Optional(t.Any()),
}),
t.Array(
t.Object({
level: t.Optional(t.Union([t.Literal('debug'), t.Literal('info'), t.Literal('warn'), t.Literal('error')])),
message: t.String(),
data: t.Optional(t.Any()),
})
),
]),
}
)
// Serve static files and SPA fallback for all non-API routes // Serve static files and SPA fallback for all non-API routes
.get('/*', ({ request }) => { .get('/*', ({ request }) => {
const url = new URL(request.url); const url = new URL(request.url);

View File

@@ -0,0 +1,192 @@
/**
* Frontend Logger
*
* Sends logs to backend endpoint which writes to logs/frontend.log
* Respects LOG_LEVEL environment variable from backend
*
* Usage:
* import { logger } from '$lib/logger';
* logger.info('User logged in', { userId: 123 });
* logger.error('Failed to fetch data', { error: err.message });
*/
// Log levels matching backend
const LOG_LEVELS = { debug: 0, info: 1, warn: 2, error: 3 };
// Get log level from backend or default to info
let currentLogLevel = LOG_LEVELS.info;
// Buffer for batching logs (sends when buffer reaches this size or after timeout)
const logBuffer = [];
const BUFFER_SIZE = 10;
const BUFFER_TIMEOUT = 5000; // 5 seconds
let bufferTimeout = null;
// Fetch current log level from backend on initialization
async function fetchLogLevel() {
try {
// Try to get log level from health endpoint or localStorage
const response = await fetch('/api/health');
if (response.ok) {
// For now, we'll assume the backend doesn't expose log level in health
// Could add it later. Default to info in production, debug in development
const isDev = import.meta.env.DEV;
currentLogLevel = isDev ? LOG_LEVELS.debug : LOG_LEVELS.info;
}
} catch (err) {
// Default to info if can't fetch
currentLogLevel = LOG_LEVELS.info;
}
}
// Initialize log level
fetchLogLevel();
/**
* Send logs to backend
*/
async function sendLogs(entries) {
try {
await fetch('/api/logs', {
method: 'POST',
headers: {
'Content-Type': 'application/json',
},
credentials: 'include', // Include cookies for authentication
body: JSON.stringify(entries),
});
} catch (err) {
// Silent fail - don't break the app if logging fails
console.error('Failed to send logs to backend:', err);
}
}
/**
* Flush log buffer
*/
function flushBuffer() {
if (logBuffer.length === 0) return;
const entries = [...logBuffer];
logBuffer.length = 0; // Clear buffer
if (bufferTimeout) {
clearTimeout(bufferTimeout);
bufferTimeout = null;
}
sendLogs(entries);
}
/**
* Add log entry to buffer
*/
function addToBuffer(level, message, data) {
// Check if we should log this level
if (LOG_LEVELS[level] < currentLogLevel) return;
logBuffer.push({
level,
message,
data: data || undefined,
timestamp: new Date().toISOString(),
});
// Flush if buffer is full
if (logBuffer.length >= BUFFER_SIZE) {
flushBuffer();
} else {
// Set timeout to flush after BUFFER_TIMEOUT
if (bufferTimeout) {
clearTimeout(bufferTimeout);
}
bufferTimeout = setTimeout(flushBuffer, BUFFER_TIMEOUT);
}
}
/**
* Logger API
*/
export const logger = {
/**
* Log debug message
*/
debug: (message, data) => {
if (import.meta.env.DEV) {
console.debug('[DEBUG]', message, data || '');
}
addToBuffer('debug', message, data);
},
/**
* Log info message
*/
info: (message, data) => {
if (import.meta.env.DEV) {
console.info('[INFO]', message, data || '');
}
addToBuffer('info', message, data);
},
/**
* Log warning message
*/
warn: (message, data) => {
if (import.meta.env.DEV) {
console.warn('[WARN]', message, data || '');
}
addToBuffer('warn', message, data);
},
/**
* Log error message
*/
error: (message, data) => {
if (import.meta.env.DEV) {
console.error('[ERROR]', message, data || '');
}
addToBuffer('error', message, data);
},
/**
* Immediately flush the log buffer
*/
flush: flushBuffer,
/**
* Set the log level (for testing purposes)
*/
setLogLevel: (level) => {
if (LOG_LEVELS[level] !== undefined) {
currentLogLevel = LOG_LEVELS[level];
}
},
};
/**
* SvelteKit action for automatic error logging
* Can be used in +page.svelte or +layout.svelte
*/
export function setupErrorLogging() {
// Log unhandled errors
if (typeof window !== 'undefined') {
window.addEventListener('error', (event) => {
logger.error('Unhandled error', {
message: event.message,
filename: event.filename,
lineno: event.lineno,
colno: event.colno,
error: event.error?.stack,
});
});
window.addEventListener('unhandledrejection', (event) => {
logger.error('Unhandled promise rejection', {
reason: event.reason,
promise: event.promise?.toString(),
});
});
}
}
export default logger;

View File

@@ -5,29 +5,42 @@ import { defineConfig } from 'vite';
function suppressURIErrorPlugin() { function suppressURIErrorPlugin() {
return { return {
name: 'suppress-uri-error', name: 'suppress-uri-error',
enforce: 'pre', // Run this plugin before others
configureServer(server) { configureServer(server) {
server.middlewares.use((req, res, next) => { // Return a function that will be called after all plugins are configured
// Intercept malformed requests before they reach Vite's middleware // This ensures our middleware is added at the correct time
try { return () => {
// Try to decode the URL to catch malformed URIs early // Add middleware BEFORE all other middlewares
if (req.url) { // We insert it at position 0 to ensure it runs first
decodeURI(req.url); server.middlewares.stack.unshift({
route: '',
handle: (req, res, next) => {
// Intercept malformed requests before they reach SvelteKit
try {
// Try to decode the URL to catch malformed URIs early
if (req.url) {
decodeURI(req.url);
// Also try the full URL construction that SvelteKit does
const base = `${server.config.server.https ? 'https' : 'http'}://${
req.headers[':authority'] || req.headers.host || 'localhost'
}`;
decodeURI(new URL(base + req.url).pathname);
}
} catch (e) {
// Silently ignore malformed URIs from browser extensions
res.writeHead(200, { 'Content-Type': 'text/plain' });
res.end('OK');
return;
} }
} catch (e) { next();
// Silently ignore malformed URIs from browser extensions }});
// Don't call next(), just end the response };
res.writeHead(200, { 'Content-Type': 'text/plain' });
res.end('OK');
return;
}
next();
});
} }
}; };
} }
export default defineConfig({ export default defineConfig({
plugins: [sveltekit(), suppressURIErrorPlugin()], plugins: [suppressURIErrorPlugin(), sveltekit()],
server: { server: {
host: 'localhost', host: 'localhost',
port: 5173, port: 5173,