diff --git a/backend/config/logger.ts b/backend/config/logger.ts index 6eea5f1d..52f0c33e 100644 --- a/backend/config/logger.ts +++ b/backend/config/logger.ts @@ -17,6 +17,22 @@ import pino from 'pino' const isDev = process.env.NODE_ENV !== 'production' const level = process.env.LOG_LEVEL ?? (isDev ? 'debug' : 'info') +const SECRET_KEYS = ['password', 'currentPassword', 'newPassword', 'token', 'refreshToken'] + +// Redactar campos sensibles si aparecen accidentalmente. pino has no +// recursive wildcard: secrets are hidden at the first three levels. The SQL +// of a failed db.query carries its values interpolated (texts, plates, +// hashes); err.code and err.message stay +export const redact = { + paths: [ + ...SECRET_KEYS.flatMap((key) => [key, `*.${key}`, `*.*.${key}`]), + 'req.headers.authorization', + 'req.headers.cookie', + '*.sql', + ], + censor: '[REDACTED]', +} + export const logger = pino({ level, ...(isDev @@ -31,15 +47,5 @@ export const logger = pino({ }, } : {}), - // Redactar campos sensibles si aparecen accidentalmente - redact: { - paths: [ - '*.password', - '*.token', - '*.refreshToken', - 'req.headers.authorization', - 'req.headers.cookie', - ], - censor: '[REDACTED]', - }, + redact, }) diff --git a/backend/controllers/messages/conversation-controller.ts b/backend/controllers/messages/conversation-controller.ts index 656e9959..6c88cfec 100644 --- a/backend/controllers/messages/conversation-controller.ts +++ b/backend/controllers/messages/conversation-controller.ts @@ -9,6 +9,7 @@ import { } from '../../models/messages/index.js' import { ERROR_CODES, SUCCESS_CODES } from '../../config/error-codes.js' import { logger } from '../../config/logger.js' +import { logAdminOverride } from '../../middlewares/accessLog.js' import { createConversationSchema, addParticipantsSchema, @@ -86,6 +87,7 @@ export class ConversationController { code: ERROR_CODES.MESSAGES_NO_ACCESS, }) } + if (!isParticipant) logAdminOverride(req, 'read_conversation', { conversationId }) const conversation = await ConversationRepository.getByIdWithDetails(conversationId, userId) @@ -435,6 +437,7 @@ export class ConversationController { code: ERROR_CODES.MESSAGES_ADMIN_OR_SYSTEM_DELETE, }) } + if (!isConversationAdmin) logAdminOverride(req, 'delete_conversation', { conversationId }) // Eliminar conversacion completa (mensajes se eliminan por CASCADE) await ConversationRepository.deleteComplete(conversationId) @@ -760,6 +763,7 @@ export class ConversationController { } const { limit } = query.data const conversations = await ConversationRepository.getAll(limit) + logAdminOverride(req, 'list_all_conversations', { count: conversations.length }) return res.status(200).json({ success: true, diff --git a/backend/controllers/messages/message-controller.ts b/backend/controllers/messages/message-controller.ts index df51832d..8ee5bbeb 100644 --- a/backend/controllers/messages/message-controller.ts +++ b/backend/controllers/messages/message-controller.ts @@ -7,6 +7,7 @@ import { NotificationRepository } from '../../repositories/notifications/notific import { MESSAGE_CONSTANTS } from '../../models/messages/index.js' import { ERROR_CODES, SUCCESS_CODES } from '../../config/error-codes.js' import { logger } from '../../config/logger.js' +import { logAdminOverride } from '../../middlewares/accessLog.js' import { NotificationModule, NotificationRelatedTo, @@ -55,6 +56,7 @@ export class MessageController { code: ERROR_CODES.MESSAGES_NO_ACCESS, }) } + if (!isParticipant) logAdminOverride(req, 'read_messages', { conversationId }) // Parametros de paginacion const page = messagePageQuerySchema.safeParse(req.query) @@ -302,6 +304,7 @@ export class MessageController { code: ERROR_CODES.MESSAGES_ONLY_OWN_DELETE, }) } + if (!isSender) logAdminOverride(req, 'delete_message', { messageId }) const deleted = await MessageRepository.delete(messageId) if (!deleted) { diff --git a/backend/index.ts b/backend/index.ts index 0dafd4e9..ee8b27db 100644 --- a/backend/index.ts +++ b/backend/index.ts @@ -8,6 +8,7 @@ import { logServerInfo } from './config/startup-logger.js' import { logger } from './config/logger.js' import { apiLimiter } from './middlewares/rateLimiter.js' import { noStore } from './middlewares/noStore.js' +import { logAccessDenied } from './middlewares/accessLog.js' import { corsMiddleware } from './config/cors.js' import { CronService } from './services/cron/cron-service.js' @@ -66,6 +67,8 @@ app.use(cookieParser()) app.use('/api', apiLimiter) // Personal and financial data must not stay in browser or proxy caches app.use('/api', noStore) +// Every 403 leaves a trace in the log +app.use('/api', logAccessDenied) // ======================================== // RUTAS diff --git a/backend/middlewares/accessLog.ts b/backend/middlewares/accessLog.ts new file mode 100644 index 00000000..566c1e00 --- /dev/null +++ b/backend/middlewares/accessLog.ts @@ -0,0 +1,38 @@ +// middlewares/accessLog.ts +// Authorization decisions leave a trace in the log (ASVS 7.2): every 403 the +// API answers, and every time an admin reads or deletes messages of a +// conversation they are not in. + +import type { Request, Response, NextFunction } from 'express' +import { logger } from '../config/logger.js' + +// Goes before the routes: logs the 403 whichever middleware or handler sends it +export function logAccessDenied(req: Request, res: Response, next: NextFunction): void { + res.on('finish', () => { + if (res.statusCode !== 403) return + logger.warn( + { + event: 'access_denied', + userId: req.user?.id ?? null, + role: req.user?.role ?? null, + method: req.method, + // Without the query string, which may carry search terms + path: req.originalUrl.split('?')[0], + }, + '[SECURITY] access denied' + ) + }) + next() +} + +// An admin acting where only participants or owners can +export function logAdminOverride( + req: Request, + action: string, + target: Record +): void { + logger.info( + { event: 'admin_override', userId: req.user?.id ?? null, action, ...target }, + '[SECURITY] admin access to conversations of others' + ) +} diff --git a/backend/tests/security/access-log.test.ts b/backend/tests/security/access-log.test.ts new file mode 100644 index 00000000..8a5531b2 --- /dev/null +++ b/backend/tests/security/access-log.test.ts @@ -0,0 +1,133 @@ +// tests/security/access-log.test.ts +// Regression tests for the log (ASVS 7.1 and 7.2). The SQL of a failed +// db.query went to the log with its values interpolated (texts, plates, +// hashes), and `*.password` only hid the field one level down. No 403 left a +// trace, nor did an admin reading or deleting messages of a conversation they +// are not in. + +import { describe, it, expect, vi, beforeEach } from 'vitest' +import { EventEmitter } from 'node:events' +import { Writable } from 'node:stream' +import { readFileSync } from 'node:fs' +import { join, dirname } from 'node:path' +import { fileURLToPath } from 'node:url' +import pino from 'pino' +import type { Request, Response } from 'express' + +vi.mock('../../config/logger.js', async (importOriginal) => { + const actual = await importOriginal() + return { ...actual, logger: { warn: vi.fn(), info: vi.fn(), error: vi.fn(), debug: vi.fn() } } +}) + +const { logger, redact } = await import('../../config/logger.js') +const { logAccessDenied } = await import('../../middlewares/accessLog.js') + +const backend = join(dirname(fileURLToPath(import.meta.url)), '..', '..') +const read = (...p: string[]) => readFileSync(join(backend, ...p), 'utf8') + +// One line written by a pino logger with the app's redaction +function logged(obj: Record): Record { + let line = '' + const out = new Writable({ + write(chunk, _enc, done) { + line += chunk.toString() + done() + }, + }) + pino({ redact }, out).error(obj, 'test') + return JSON.parse(line) +} + +describe('log redaction', () => { + it('hides the SQL of a mysql2 error, which carries the values', () => { + const err = Object.assign(new Error("Duplicate entry '1234-ABC'"), { + code: 'ER_DUP_ENTRY', + sql: "INSERT INTO t VALUES ('1234-ABC', 'nota privada')", + }) + const line = JSON.stringify(logged({ err })) + expect(line).not.toContain('nota privada') + expect(line).toContain('ER_DUP_ENTRY') + }) + + it('hides passwords and tokens at any of the first three levels', () => { + const line = JSON.stringify( + logged({ + password: 'p0', + body: { newPassword: 'p1', token: 't1' }, + req: { body: { password: 'p2', currentPassword: 'p3', refreshToken: 't2' } }, + }) + ) + for (const secret of ['p0', 'p1', 'p2', 'p3', 't1', 't2']) { + expect(line, secret).not.toContain(`"${secret}"`) + } + }) +}) + +describe('403 responses are logged', () => { + beforeEach(() => vi.clearAllMocks()) + + function respond(status: number, user?: { id: string; role: string }) { + const res = Object.assign(new EventEmitter(), { statusCode: status }) + const req = { method: 'DELETE', originalUrl: '/api/cashier/daily/3?x=secret', user } + const next = vi.fn() + logAccessDenied(req as unknown as Request, res as unknown as Response, next) + expect(next).toHaveBeenCalledOnce() + res.emit('finish') + } + + it('logs who was refused what, without the query string', () => { + respond(403, { id: 'u1', role: 'recepcionista' }) + expect(logger.warn).toHaveBeenCalledWith( + { + event: 'access_denied', + userId: 'u1', + role: 'recepcionista', + method: 'DELETE', + path: '/api/cashier/daily/3', + }, + '[SECURITY] access denied' + ) + }) + + it('ignores every other status', () => { + for (const status of [200, 201, 400, 401, 404, 500]) respond(status) + expect(logger.warn).not.toHaveBeenCalled() + }) + + it('runs for the whole API, before the routes', () => { + const index = read('index.ts') + const at = index.indexOf("app.use('/api', logAccessDenied)") + expect(at).toBeGreaterThan(-1) + expect(at).toBeLessThan(index.indexOf("app.use('/api/auth', authRoutes)")) + }) +}) + +describe('admins acting on conversations they are not in are logged', () => { + const conversations = read('controllers', 'messages', 'conversation-controller.ts') + const messages = read('controllers', 'messages', 'message-controller.ts') + + // Body of `static async name(` up to the next static method + function method(source: string, name: string): string { + const start = source.indexOf(`static async ${name}(`) + expect(start, name).toBeGreaterThan(-1) + const next = source.indexOf('static async ', start + 1) + return source.slice(start, next === -1 ? undefined : next) + } + + it.each([ + [conversations, 'getConversation', 'isParticipant', 'read_conversation'], + [conversations, 'deleteConversation', 'isConversationAdmin', 'delete_conversation'], + [messages, 'getMessages', 'isParticipant', 'read_messages'], + [messages, 'deleteMessage', 'isSender', 'delete_message'], + ])('%#: %s logs the override', (source, name, own, action) => { + expect(method(source, name)).toMatch( + new RegExp(`if \\(!${own}\\) logAdminOverride\\(req, '${action}', \\{`) + ) + }) + + it('the moderation list of every conversation is logged', () => { + expect(method(conversations, 'getAllConversations')).toContain( + "logAdminOverride(req, 'list_all_conversations'" + ) + }) +}) diff --git a/docs/general/README.md b/docs/general/README.md index 1b2c9bc6..73bf4ead 100644 --- a/docs/general/README.md +++ b/docs/general/README.md @@ -93,6 +93,17 @@ if it does not match. server to server). - In production, unhandled errors return a generic message. +**Log** + +- Every `403` is logged (`access_denied`: user, role, method and path, without + the query string), and so is every time an `admin` reads, lists or deletes + conversations or messages they are not in (`admin_override`). +- Passwords and tokens are hidden at the first three levels of each entry, and + so is the SQL of a failed query (`err.sql`), which carries its values. +- Failed logins keep the username that was typed (decided on 2026-10-12, left + as is): it is what reveals a brute-force attack, although someone may type + their password in that field. + **Database** - Every schema change is a new, idempotent script in `backend/db-mysql/scripts/`