From ed328ee06c01af990ba63cf0c628dec6861fd0aa Mon Sep 17 00:00:00 2001 From: Dmitri Date: Thu, 2 Jul 2026 07:38:38 +0200 Subject: [PATCH] improved logging --- backend/src/db/db-config.ts | 9 +- backend/src/helpers.ts | 13 ++- backend/src/index.ts | 22 ++-- backend/src/middlewares/check-permissions.ts | 34 ++---- backend/src/routes/sql.ts | 114 ------------------- backend/src/types/db-models.ts | 8 +- backend/src/types/index.ts | 13 --- backend/src/types/sql.ts | 43 ------- backend/src/utils/env-validation.ts | 5 +- backend/src/utils/index.ts | 8 +- backend/src/utils/logger.ts | 60 +++++++++- backend/src/utils/sqlValidator.ts | 47 -------- backend/tests/helpers.test.ts | 21 ++++ 13 files changed, 141 insertions(+), 256 deletions(-) delete mode 100644 backend/src/routes/sql.ts delete mode 100644 backend/src/types/sql.ts delete mode 100644 backend/src/utils/sqlValidator.ts diff --git a/backend/src/db/db-config.ts b/backend/src/db/db-config.ts index a0e00e6..252c1cf 100644 --- a/backend/src/db/db-config.ts +++ b/backend/src/db/db-config.ts @@ -1,10 +1,15 @@ import '../load-env.ts'; +import { logger } from '../utils/logger.ts'; import type { DatabaseConfigMap } from '../types/index.ts'; const sequelizeStorage = 'sequelize'; const migrationStorageTableName = 'SequelizeMeta'; type DatabaseLogging = NonNullable; +function logSql(message: string): void { + logger.debug({ sql: message }, 'Sequelize query'); +} + function readEnvPort(name: string): number | undefined { const value = process.env[name]; if (!value) return undefined; @@ -53,12 +58,12 @@ const dbConfig: DatabaseConfigMap = { password: '', database: 'db_tour_builder_platform', host: process.env.DB_HOST || 'localhost', - logging: console.log, + logging: logSql, seederStorage: sequelizeStorage, migrationStorage: sequelizeStorage, migrationStorageTableName, }, - dev_stage: createEnvDatabaseConfig(console.log), + dev_stage: createEnvDatabaseConfig(logSql), }; export default dbConfig; diff --git a/backend/src/helpers.ts b/backend/src/helpers.ts index 0270069..bf68262 100644 --- a/backend/src/helpers.ts +++ b/backend/src/helpers.ts @@ -18,6 +18,7 @@ import type { RouteIdRequestLike, } from './types/index.ts'; import { logger } from './utils/logger.ts'; +import { getRequestLogger } from './utils/request-context.ts'; import { assertBodyIdMatchesRouteId } from './utils/request-body.ts'; function wrapAsync< @@ -39,7 +40,7 @@ function wrapAsync< const commonErrorHandler: ErrorRequestHandler = ( error: RouteError, - _req: Request, + req: Request, res: Response, _next: NextFunction, ): Response => { @@ -59,7 +60,15 @@ const commonErrorHandler: ErrorRequestHandler = ( return res.status(statusCode).send(error.message); } - logger.error({ err: error }, 'Unhandled route error'); + const requestLog = getRequestLogger(req) ?? logger; + requestLog.error( + { + err: error, + method: req.method, + url: req.originalUrl || req.url, + }, + 'Route handler failed', + ); return res.status(500).send('Internal server error'); }; diff --git a/backend/src/index.ts b/backend/src/index.ts index 015a6bc..7bc60d8 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -46,7 +46,6 @@ import rolesRoutesModule from './routes/roles.ts'; import runtimeAccessRoutesModule from './routes/runtime-access.ts'; import runtimeContextRoutesModule from './routes/runtime-context.ts'; import searchRoutesModule from './routes/search.ts'; -import sqlRoutesModule from './routes/sql.ts'; import tourPagesRoutesModule from './routes/tour_pages.ts'; import usersRoutesModule from './routes/users.ts'; import RuntimePresentationAccessService from './services/runtime-presentation-access.ts'; @@ -60,8 +59,14 @@ import type { SwaggerHostMiddleware, SwaggerUiModuleWithHost, } from './types/index.ts'; -import { logger, requestLogger } from './utils/logger.ts'; import { + exitAfterLogging, + logger, + registerProcessErrorHandlers, + requestLogger, +} from './utils/logger.ts'; +import { + getRequestLogger, getRuntimeContext, setCurrentUser, setRuntimePublicRequest, @@ -70,6 +75,7 @@ import { const app = express(); const swaggerUiWithHost: SwaggerUiModuleWithHost = swaggerUI; +registerProcessErrorHandlers(); initializePermissionsMiddleware(); function isExpressRouter(value: unknown): value is ExpressRouter { @@ -140,7 +146,6 @@ const runtimeContextRoutes = getExpressRouter( runtimeContextRoutesModule, ); const searchRoutes = getExpressRouter('search', searchRoutesModule); -const sqlRoutes = getExpressRouter('sql', sqlRoutesModule); const tourPagesRoutes = getExpressRouter('tour_pages', tourPagesRoutesModule); const usersRoutes = getExpressRouter('users', usersRoutesModule); @@ -399,7 +404,6 @@ app.use('/api/project-ui-control-settings', projectUiControlSettingsRoutes); app.use('/api/publish', jwtAuth, publishRoutes); app.use('/api/search', jwtAuth, searchLimiter, searchRoutes); -app.use('/api/sql', jwtAuth, sqlRoutes); const publicDir = path.join(process.cwd(), 'public'); @@ -414,7 +418,11 @@ if (fs.existsSync(publicDir)) { // Generic error handler const appErrorHandler: AppErrorHandler = (err, req, res, _next) => { if (!res.headersSent) { - logger.error({ err, url: req.url, method: req.method }, 'Unhandled error'); + const requestLog = getRequestLogger(req) ?? logger; + requestLog.error( + { err, url: req.url, method: req.method }, + 'Express error middleware caught unhandled error', + ); res.status(500).json({ message: 'Internal server error' }); } }; @@ -443,9 +451,7 @@ server.on('error', (err: NodeJS.ErrnoException) => { { err, port: PORT, env: process.env.NODE_ENV || 'development' }, 'Server failed to start', ); - setImmediate(() => { - process.exit(1); - }); + exitAfterLogging(); }); export default app; diff --git a/backend/src/middlewares/check-permissions.ts b/backend/src/middlewares/check-permissions.ts index cd2fc68..6867442 100644 --- a/backend/src/middlewares/check-permissions.ts +++ b/backend/src/middlewares/check-permissions.ts @@ -16,36 +16,26 @@ let publicRoleCache: RoleWithPermissionLoader | null = null; // Function to asynchronously fetch and cache the 'Public' role async function fetchAndCachePublicRole(): Promise { - try { - // Use RolesDBApi to find the role by name 'Public' - publicRoleCache = await RolesDBApi.findBy({ name: 'Public' }); + // Use RolesDBApi to find the role by name 'Public' + publicRoleCache = await RolesDBApi.findBy({ name: 'Public' }); - if (!publicRoleCache) { - logger.warn( - { role: 'Public' }, - 'Role not found during permissions middleware startup', - ); - // The system might not function correctly without this role. May need to throw an error or use a fallback stub. - } else { - logger.info( - { role: 'Public', roleId: publicRoleCache.id }, - 'Role loaded and cached', - ); - } - } catch (error) { - logger.error( - { err: error, role: 'Public' }, - 'Error fetching role during permissions middleware startup', + if (!publicRoleCache) { + logger.warn( + { role: 'Public' }, + 'Role not found during permissions middleware startup', + ); + } else { + logger.info( + { role: 'Public', roleId: publicRoleCache.id }, + 'Role loaded and cached', ); - // Handle the error during startup fetch - throw error; // Important to know if the app can proceed without the Public role } } function initializePermissionsMiddleware(): void { fetchAndCachePublicRole().catch((error) => { logger.error( - { err: error }, + { err: error, role: 'Public' }, 'Critical error during permissions middleware initialization', ); }); diff --git a/backend/src/routes/sql.ts b/backend/src/routes/sql.ts deleted file mode 100644 index 24c39d3..0000000 --- a/backend/src/routes/sql.ts +++ /dev/null @@ -1,114 +0,0 @@ -import express from 'express'; - -import db from '../db/models/index.ts'; -import { wrapAsync } from '../helpers.ts'; -import type { - ExecuteSqlErrorResponse, - ExecuteSqlRequestBody, - ExecuteSqlSuccessResponse, - SqlQueryRow, -} from '../types/index.ts'; -import { getCurrentUser } from '../utils/request-context.ts'; -import { validateReadOnlySql } from '../utils/sqlValidator.ts'; - -const router = express.Router(); -const MAX_SQL_LENGTH = 5000; -const MAX_SQL_ROWS = 1000; -const SQL_TIMEOUT_MS = 5000; - -function isExecuteSqlRequestBody(body: unknown): body is ExecuteSqlRequestBody { - return ( - body !== null && - typeof body === 'object' && - 'sql' in body && - typeof body.sql === 'string' - ); -} - -/** - * @swagger - * /api/sql: - * post: - * security: - * - bearerAuth: [] - * summary: Execute a SELECT-only SQL query - * description: Executes a read-only SQL query and returns rows. - * requestBody: - * required: true - * content: - * application/json: - * schema: - * type: object - * properties: - * sql: - * type: string - * required: - * - sql - * responses: - * 200: - * description: Query result - * 400: - * description: Invalid SQL - * 401: - * $ref: "#/components/responses/UnauthorizedError" - * 500: - * description: Internal server error - */ -router.post( - '/', - wrapAsync(async (req, res) => { - const currentUser = getCurrentUser(req); - const isAdminUser = Boolean( - currentUser && - currentUser.app_role && - (currentUser.app_role.name === 'Administrator' || - currentUser.app_role.globalAccess === true), - ); - - if (!isAdminUser) { - const response: ExecuteSqlErrorResponse = { - error: 'Only administrators can execute SQL queries', - }; - return res.status(403).json(response); - } - - const body: unknown = req.body; - if (!isExecuteSqlRequestBody(body)) { - const response: ExecuteSqlErrorResponse = { - error: 'SQL query must be a non-empty string', - }; - return res.status(400).json(response); - } - - const validation = validateReadOnlySql(body.sql, { - maxLength: MAX_SQL_LENGTH, - }); - if (!validation.valid) { - const response: ExecuteSqlErrorResponse = { error: validation.error }; - return res.status(400).json(response); - } - - const wrappedSql = `SELECT * FROM (${validation.normalized}) AS query_result LIMIT ${MAX_SQL_ROWS}`; - - const rows = await db.sequelize.transaction(async (transaction) => { - await db.sequelize.query(`SET LOCAL statement_timeout = ${SQL_TIMEOUT_MS}`, { - transaction, - }); - return db.sequelize.query(wrappedSql, { - transaction, - type: db.Sequelize.QueryTypes.SELECT, - }); - }); - - const response: ExecuteSqlSuccessResponse = { - rows, - meta: { - maxRows: MAX_SQL_ROWS, - statementTimeoutMs: SQL_TIMEOUT_MS, - }, - }; - return res.status(200).json(response); - }), -); - -export default router; diff --git a/backend/src/types/db-models.ts b/backend/src/types/db-models.ts index dbbd56a..c91dc9f 100644 --- a/backend/src/types/db-models.ts +++ b/backend/src/types/db-models.ts @@ -34,7 +34,6 @@ import type { ProductionPresentationProject, PaginatedResult, QueryWhere, - SqlQueryRow, RuntimeProjectInclude, RuntimeEnvironment, TourPageRecord, @@ -53,6 +52,13 @@ import type { } from './index.ts'; import type { QueryTypes, SyncOptions, Transaction } from 'sequelize'; +export type SqlQueryScalar = string | number | boolean | Date | Buffer | null; +export type SqlQueryValue = + | SqlQueryScalar + | ReadonlyArray + | Readonly>; +export type SqlQueryRow = Record; + export interface SequelizeQueryOptions { transaction?: Transaction; type?: QueryTypes.SELECT; diff --git a/backend/src/types/index.ts b/backend/src/types/index.ts index 57a61a5..4decfc1 100644 --- a/backend/src/types/index.ts +++ b/backend/src/types/index.ts @@ -406,19 +406,6 @@ export type { RouteIdRequestBody, RouteIdRequestLike, } from './http.ts'; -export type { - ExecuteSqlErrorResponse, - ExecuteSqlRequestBody, - ExecuteSqlResponseMeta, - ExecuteSqlSuccessResponse, - InvalidSqlValidationResult, - ReadOnlySqlValidationOptions, - SqlQueryRow, - SqlQueryScalar, - SqlValidationResult, - SqlQueryValue, - ValidSqlValidationResult, -} from './sql.ts'; export type { NodeEnvironment, ValidatedEnvironment } from './env.ts'; export type { DbModels, diff --git a/backend/src/types/sql.ts b/backend/src/types/sql.ts deleted file mode 100644 index fc46ef2..0000000 --- a/backend/src/types/sql.ts +++ /dev/null @@ -1,43 +0,0 @@ -export interface ReadOnlySqlValidationOptions { - maxLength?: number; -} - -export interface ExecuteSqlRequestBody { - sql: string; -} - -export type SqlQueryScalar = string | number | boolean | Date | Buffer | null; -export type SqlQueryValue = - | SqlQueryScalar - | ReadonlyArray - | Readonly>; - -export type SqlQueryRow = Record; - -export interface ExecuteSqlResponseMeta { - maxRows: number; - statementTimeoutMs: number; -} - -export interface ExecuteSqlSuccessResponse { - rows: SqlQueryRow[]; - meta: ExecuteSqlResponseMeta; -} - -export interface ExecuteSqlErrorResponse { - error: string; -} - -export interface InvalidSqlValidationResult { - valid: false; - error: string; -} - -export interface ValidSqlValidationResult { - valid: true; - normalized: string; -} - -export type SqlValidationResult = - | InvalidSqlValidationResult - | ValidSqlValidationResult; diff --git a/backend/src/utils/env-validation.ts b/backend/src/utils/env-validation.ts index a4032f3..9257fe9 100644 --- a/backend/src/utils/env-validation.ts +++ b/backend/src/utils/env-validation.ts @@ -1,5 +1,6 @@ import Joi from 'joi'; +import { logger } from './logger.ts'; import type { NodeEnvironment, ValidatedEnvironment } from '../types/index.ts'; type EnvBooleanString = 'true' | 'false'; @@ -153,12 +154,12 @@ function validateEnv(): ValidatedEnvironment { const messages = result.error.details.map( (detail) => ` - ${detail.message}`, ); - console.error(`Environment validation failed:\n${messages.join('\n')}`); + logger.error({ errors: messages }, 'Environment validation failed'); if (process.env.NODE_ENV === 'production') { process.exit(1); } else { - console.warn('Continuing with default values in non-production mode'); + logger.warn('Continuing with default values in non-production mode'); } } diff --git a/backend/src/utils/index.ts b/backend/src/utils/index.ts index 7b3cd75..4c77870 100644 --- a/backend/src/utils/index.ts +++ b/backend/src/utils/index.ts @@ -6,5 +6,11 @@ export { UnauthorizedError, ValidationError, } from './errors.ts'; -export { logger, requestLogger } from './logger.ts'; +export { + exitAfterLogging, + logger, + normalizeLoggedError, + registerProcessErrorHandlers, + requestLogger, +} from './logger.ts'; export { envSchema, validateEnv } from './env-validation.ts'; diff --git a/backend/src/utils/logger.ts b/backend/src/utils/logger.ts index ebcfe44..c7aafed 100644 --- a/backend/src/utils/logger.ts +++ b/backend/src/utils/logger.ts @@ -38,6 +38,58 @@ const logger = pino( : baseLoggerOptions, ); +let processErrorHandlersRegistered = false; +let processExitScheduled = false; + +function normalizeLoggedError(reason: unknown): Error { + if (reason instanceof Error) return reason; + + const message = + typeof reason === 'string' + ? reason + : 'Non-Error value thrown or rejected'; + + return new Error(message, { cause: reason }); +} + +function exitAfterLogging(exitCode = 1): void { + if (processExitScheduled) return; + + processExitScheduled = true; + + const fallback = setTimeout(() => { + process.exit(exitCode); + }, 250); + fallback.unref(); + + logger.flush(() => { + clearTimeout(fallback); + process.exit(exitCode); + }); +} + +function registerProcessErrorHandlers(): void { + if (processErrorHandlersRegistered) return; + + processErrorHandlersRegistered = true; + + process.on('uncaughtException', (error) => { + logger.fatal( + { err: normalizeLoggedError(error) }, + 'Uncaught exception, shutting down process', + ); + exitAfterLogging(); + }); + + process.on('unhandledRejection', (reason) => { + logger.fatal( + { err: normalizeLoggedError(reason) }, + 'Unhandled promise rejection, shutting down process', + ); + exitAfterLogging(); + }); +} + const requestLogger: RequestHandler = (req, res, next) => { const headerRequestId = req.headers['x-request-id']; const requestId = @@ -72,4 +124,10 @@ const requestLogger: RequestHandler = (req, res, next) => { next(); }; -export { logger, requestLogger }; +export { + exitAfterLogging, + logger, + normalizeLoggedError, + registerProcessErrorHandlers, + requestLogger, +}; diff --git a/backend/src/utils/sqlValidator.ts b/backend/src/utils/sqlValidator.ts deleted file mode 100644 index 74cb9ef..0000000 --- a/backend/src/utils/sqlValidator.ts +++ /dev/null @@ -1,47 +0,0 @@ -import type { - ReadOnlySqlValidationOptions, - SqlValidationResult, -} from '../types/index.ts'; - -const DEFAULT_MAX_LENGTH = 5000; -const RESTRICTED_FUNCTIONS = /\b(pg_sleep|set_config|copy)\b/i; - -function validateReadOnlySql( - sql: unknown, - options: ReadOnlySqlValidationOptions = {}, -): SqlValidationResult { - const maxLength = options.maxLength ?? DEFAULT_MAX_LENGTH; - - if (typeof sql !== 'string' || !sql.trim()) { - return { valid: false, error: 'SQL query must be a non-empty string' }; - } - - if (sql.length > maxLength) { - return { - valid: false, - error: `SQL query is too long (max ${maxLength} characters)`, - }; - } - - const normalized = sql.trim().replace(/;+\s*$/, ''); - - if (!/^(select|with)\b/i.test(normalized)) { - return { valid: false, error: 'Only SELECT statements are allowed' }; - } - - if (normalized.includes(';')) { - return { valid: false, error: 'Only a single statement is allowed' }; - } - - if (/--|\/\*/.test(normalized)) { - return { valid: false, error: 'SQL comments are not allowed' }; - } - - if (RESTRICTED_FUNCTIONS.test(normalized)) { - return { valid: false, error: 'Restricted SQL function detected' }; - } - - return { valid: true, normalized }; -} - -export { validateReadOnlySql }; diff --git a/backend/tests/helpers.test.ts b/backend/tests/helpers.test.ts index 7d95b54..79a5037 100644 --- a/backend/tests/helpers.test.ts +++ b/backend/tests/helpers.test.ts @@ -2,6 +2,7 @@ import assert from 'node:assert/strict'; import test from 'node:test'; import { assertRouteIdMatchesBody } from '../src/helpers.ts'; +import { normalizeLoggedError } from '../src/utils/logger.ts'; void test('assertRouteIdMatchesBody allows matching top-level body id', () => { assert.doesNotThrow(() => @@ -31,3 +32,23 @@ void test('assertRouteIdMatchesBody rejects mismatched body id', () => { /Request body id does not match route id/, ); }); + +void test('normalizeLoggedError preserves Error instances', () => { + const error = new Error('Original failure'); + + assert.equal(normalizeLoggedError(error), error); +}); + +void test('normalizeLoggedError wraps non-Error values', () => { + const reason = { code: 'E_UNKNOWN' }; + const error = normalizeLoggedError(reason); + + assert.equal(error.message, 'Non-Error value thrown or rejected'); + assert.equal(error.cause, reason); +}); + +void test('normalizeLoggedError uses string reasons as messages', () => { + const error = normalizeLoggedError('plain rejection'); + + assert.equal(error.message, 'plain rejection'); +});