diff --git a/backend/.env.example b/backend/.env.example index 7858ab1b..26a5e801 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -3,6 +3,12 @@ NODE_ENV=development PORT=3001 API_PREFIX=api/v1 +# Logging +# Log levels: fatal, error, warn, info, debug, trace, silent +LOG_LEVEL=info +# Enable JSON output for production (set to "true" for CloudWatch/Datadog) +LOG_JSON=false + # Database DB_HOST=localhost DB_PORT=5432 diff --git a/backend/package-lock.json b/backend/package-lock.json index 6bf4e344..cc478524 100644 --- a/backend/package-lock.json +++ b/backend/package-lock.json @@ -39,10 +39,13 @@ "ipfs-http-client": "^60.0.0", "jsonwebtoken": "^9.0.0", "multer": "^1.4.5-lts.1", + "nestjs-pino": "^4.6.1", "passport-custom": "^1.2.1", "passport-jwt": "^4.0.1", "pdf-parse": "^1.1.1", "pg": "^8.11.0", + "pino": "^10.3.1", + "pino-http": "^11.0.0", "redis": "^4.6.0", "reflect-metadata": "^0.1.13", "rxjs": "^7.8.1", @@ -69,6 +72,7 @@ "eslint-config-prettier": "^9.0.0", "eslint-plugin-prettier": "^5.0.0", "jest": "^29.5.0", + "pino-pretty": "^13.1.3", "prettier": "^3.0.0", "source-map-support": "^0.5.21", "ts-jest": "^29.1.0", @@ -2808,6 +2812,12 @@ "follow-redirects": "^1.14.0" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz", @@ -4256,6 +4266,15 @@ "integrity": "sha512-Oei9OH4tRh0YqU3GxhX79dM/mwVgvbZJaSNaRk+bshkj0S5cfHcgYakreBjrHwatXKbz+IoIdYLxrKim2MjW0Q==", "license": "MIT" }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/available-typed-arrays": { "version": "1.0.7", "resolved": "https://registry.npmjs.org/available-typed-arrays/-/available-typed-arrays-1.0.7.tgz", @@ -5405,6 +5424,13 @@ "color-support": "bin.js" } }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "dev": true, + "license": "MIT" + }, "node_modules/combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -5681,6 +5707,16 @@ "multiformats": "^11.0.0" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "dev": true, + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/dayjs": { "version": "1.11.21", "resolved": "https://registry.npmjs.org/dayjs/-/dayjs-1.11.21.tgz", @@ -6674,6 +6710,13 @@ "node": ">=4" } }, + "node_modules/fast-copy": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.0.4.tgz", + "integrity": "sha512-eVAiWVNPSEGIzDl5yPuLrx8fNMogScXvD9xp1Kzd41FjRIz2I3sSIcxsFeM5EzFfHAfobdvs8ZySffUopljvIA==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", @@ -7551,6 +7594,13 @@ "node": ">= 0.4" } }, + "node_modules/help-me": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", + "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==", + "dev": true, + "license": "MIT" + }, "node_modules/html-escaper": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/html-escaper/-/html-escaper-2.0.2.tgz", @@ -9236,6 +9286,16 @@ "url": "https://github.com/chalk/supports-color?sponsor=1" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -10238,6 +10298,21 @@ "dev": true, "license": "MIT" }, + "node_modules/nestjs-pino": { + "version": "4.6.1", + "resolved": "https://registry.npmjs.org/nestjs-pino/-/nestjs-pino-4.6.1.tgz", + "integrity": "sha512-nuARXa0xpdJ1lY2+fgycIQr6H3g0VgqAWNK3xMYjOFcj2DoPETNXj0lV3Y86nRuI7BUfQp5PGiVoZvT4dTWbpQ==", + "license": "MIT", + "engines": { + "node": ">= 14" + }, + "peerDependencies": { + "@nestjs/common": "^8.0.0 || ^9.0.0 || ^10.0.0 || ^11.0.0", + "pino": "^7.5.0 || ^8.0.0 || ^9.0.0 || ^10.0.0", + "pino-http": "^6.4.0 || ^7.0.0 || ^8.0.0 || ^9.0.0 || ^10.0.0 || ^11.0.0", + "rxjs": "^7.1.0" + } + }, "node_modules/node-abi": { "version": "3.94.0", "resolved": "https://registry.npmjs.org/node-abi/-/node-abi-3.94.0.tgz", @@ -10417,6 +10492,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -10936,6 +11020,93 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-http": { + "version": "11.0.0", + "resolved": "https://registry.npmjs.org/pino-http/-/pino-http-11.0.0.tgz", + "integrity": "sha512-wqg5XIAGRRIWtTk8qPGxkbrfiwEWz1lgedVLvhLALudKXvg1/L2lTFgTGPJ4Z2e3qcRmxoFxDuSdMdMGNM6I1g==", + "license": "MIT", + "dependencies": { + "get-caller-file": "^2.0.5", + "pino": "^10.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0" + } + }, + "node_modules/pino-pretty": { + "version": "13.1.3", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.1.3.tgz", + "integrity": "sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg==", + "dev": true, + "license": "MIT", + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^4.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^5.0.0", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.0", + "secure-json-parse": "^4.0.0", + "sonic-boom": "^4.0.1", + "strip-json-comments": "^5.0.2" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/strip-json-comments": { + "version": "5.0.3", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-5.0.3.tgz", + "integrity": "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=14.16" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/pirates": { "version": "4.0.7", "resolved": "https://registry.npmjs.org/pirates/-/pirates-4.0.7.tgz", @@ -11216,6 +11387,22 @@ "integrity": "sha512-3ouUOpQhtgrbOa17J7+uxOTpITYWaGP7/AhoR3+A+/1e9skrzelGi/dXzEYyvbxubEF6Wn2ypscTKiKJFFn1ag==", "license": "MIT" }, + "node_modules/process-warning": { + "version": "5.1.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.0.tgz", + "integrity": "sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/progress-events": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/progress-events/-/progress-events-1.1.0.tgz", @@ -11363,6 +11550,12 @@ ], "license": "MIT" }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.2.1.tgz", @@ -11476,6 +11669,15 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/receptacle": { "version": "1.3.2", "resolved": "https://registry.npmjs.org/receptacle/-/receptacle-1.3.2.tgz", @@ -11789,6 +11991,15 @@ ], "license": "MIT" }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -11838,6 +12049,23 @@ "dev": true, "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.0", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.0.tgz", + "integrity": "sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA==", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/semver": { "version": "7.8.5", "resolved": "https://registry.npmjs.org/semver/-/semver-7.8.5.tgz", @@ -12217,6 +12445,15 @@ "node": ">=10.0.0" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.7.4", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.7.4.tgz", @@ -12873,6 +13110,24 @@ "dev": true, "license": "MIT" }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, + "node_modules/thread-stream/node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/through": { "version": "2.3.8", "resolved": "https://registry.npmjs.org/through/-/through-2.3.8.tgz", diff --git a/backend/package.json b/backend/package.json index ccba020a..08f981d0 100644 --- a/backend/package.json +++ b/backend/package.json @@ -50,10 +50,13 @@ "ipfs-http-client": "^60.0.0", "jsonwebtoken": "^9.0.0", "multer": "^1.4.5-lts.1", + "nestjs-pino": "^4.6.1", "passport-custom": "^1.2.1", "passport-jwt": "^4.0.1", "pdf-parse": "^1.1.1", "pg": "^8.11.0", + "pino": "^10.3.1", + "pino-http": "^11.0.0", "redis": "^4.6.0", "reflect-metadata": "^0.1.13", "rxjs": "^7.8.1", @@ -80,6 +83,7 @@ "eslint-config-prettier": "^9.0.0", "eslint-plugin-prettier": "^5.0.0", "jest": "^29.5.0", + "pino-pretty": "^13.1.3", "prettier": "^3.0.0", "source-map-support": "^0.5.21", "ts-jest": "^29.1.0", diff --git a/backend/src/app.module.ts b/backend/src/app.module.ts index a1deed34..3dc8aa76 100644 --- a/backend/src/app.module.ts +++ b/backend/src/app.module.ts @@ -1,4 +1,4 @@ -import { Module } from '@nestjs/common'; +import { Module, MiddlewareConsumer, NestModule } from '@nestjs/common'; import { ConfigModule, ConfigService } from '@nestjs/config'; import { TypeOrmModule } from '@nestjs/typeorm'; import { CacheModule } from '@nestjs/cache-manager'; @@ -26,12 +26,15 @@ import { CredentialEventsModule } from './credentials/credential-events.module'; import { HealthAuthorityModule } from './health-authority/health-authority.module'; import { CredentialSharingHistoryModule } from './credential-sharing-history/credential-sharing-history.module'; import { CredentialExportModule } from './credential-export/credential-export.module'; +import { LoggerModule } from './common/logger/logger.module'; +import { RequestContextMiddleware } from './common/logger/logger.middleware'; @Module({ imports: [ ConfigModule.forRoot({ isGlobal: true, }), + LoggerModule, TypeOrmModule.forRootAsync({ imports: [ConfigModule], useFactory: (configService: ConfigService) => ({ @@ -97,4 +100,8 @@ import { CredentialExportModule } from './credential-export/credential-export.mo }, ], }) -export class AppModule {} +export class AppModule implements NestModule { + configure(consumer: MiddlewareConsumer) { + consumer.apply(RequestContextMiddleware).forRoutes('*'); + } +} diff --git a/backend/src/common/filters/http-exception.filter.ts b/backend/src/common/filters/http-exception.filter.ts index 6ecb32e4..3f10bf78 100644 --- a/backend/src/common/filters/http-exception.filter.ts +++ b/backend/src/common/filters/http-exception.filter.ts @@ -4,18 +4,19 @@ import { ArgumentsHost, HttpException, HttpStatus, - Logger, } from '@nestjs/common'; import { Request, Response } from 'express'; +import { StructuredLoggerService } from '../logger/logger.service'; +import { RequestWithContext } from '../logger/logger.middleware'; @Catch() export class AllExceptionsFilter implements ExceptionFilter { - private readonly logger = new Logger(AllExceptionsFilter.name); + constructor(private readonly logger: StructuredLoggerService) {} catch(exception: unknown, host: ArgumentsHost): void { const ctx = host.switchToHttp(); const response = ctx.getResponse(); - const request = ctx.getRequest(); + const request = ctx.getRequest(); let status = HttpStatus.INTERNAL_SERVER_ERROR; let message = 'Internal server error'; @@ -44,11 +45,24 @@ export class AllExceptionsFilter implements ExceptionFilter { ...(errors && { errors }), }; - // Log the error for debugging - this.logger.error( - `${request.method} ${request.url}`, - exception instanceof Error ? exception.stack : JSON.stringify(exception), - ); + const logContext = { + requestId: request.requestId, + correlationId: request.correlationId, + method: request.method, + url: request.url, + statusCode: status, + userId: request.userId, + }; + + if (status >= 500) { + this.logger.error( + `Server error: ${request.method} ${request.url}`, + exception instanceof Error ? exception.stack : undefined, + logContext, + ); + } else { + this.logger.warn(`Client error: ${request.method} ${request.url}`, logContext); + } response.status(status).json(errorResponse); } diff --git a/backend/src/common/logger/index.ts b/backend/src/common/logger/index.ts new file mode 100644 index 00000000..89e9f338 --- /dev/null +++ b/backend/src/common/logger/index.ts @@ -0,0 +1,3 @@ +export * from './logger.service'; +export * from './logger.middleware'; +export * from './logger.module'; diff --git a/backend/src/common/logger/logger.middleware.spec.ts b/backend/src/common/logger/logger.middleware.spec.ts new file mode 100644 index 00000000..2b270b29 --- /dev/null +++ b/backend/src/common/logger/logger.middleware.spec.ts @@ -0,0 +1,138 @@ +import { Test, TestingModule } from '@nestjs/testing'; +import { ConfigService } from '@nestjs/config'; +import { Request, Response, NextFunction } from 'express'; +import { RequestContextMiddleware, RequestWithContext } from './logger.middleware'; +import { StructuredLoggerService } from './logger.service'; + +describe('RequestContextMiddleware', () => { + let middleware: RequestContextMiddleware; + let logger: StructuredLoggerService; + let mockRequest: Partial; + let mockResponse: Partial; + let mockNext: NextFunction; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [ + RequestContextMiddleware, + StructuredLoggerService, + { + provide: ConfigService, + useValue: { + get: jest.fn((key: string) => { + if (key === 'LOG_LEVEL') return 'info'; + if (key === 'NODE_ENV') return 'test'; + return undefined; + }), + }, + }, + ], + }).compile(); + + middleware = module.get(RequestContextMiddleware); + logger = module.get(StructuredLoggerService); + + mockRequest = { + headers: {}, + method: 'GET', + originalUrl: '/api/v1/test', + ip: '127.0.0.1', + }; + + mockResponse = { + setHeader: jest.fn(), + statusCode: 200, + on: jest.fn(), + }; + + mockNext = jest.fn(); + }); + + it('should be defined', () => { + expect(middleware).toBeDefined(); + }); + + it('should generate request ID if not provided', () => { + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockRequest.requestId).toBeDefined(); + expect(mockRequest.requestId).toMatch( + /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/, + ); + }); + + it('should use provided request ID from header', () => { + mockRequest.headers = { 'x-request-id': 'custom-req-id' }; + + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockRequest.requestId).toBe('custom-req-id'); + }); + + it('should set correlation ID equal to request ID if not provided', () => { + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockRequest.correlationId).toBe(mockRequest.requestId); + }); + + it('should use provided correlation ID from header', () => { + mockRequest.headers = { 'x-correlation-id': 'custom-corr-id' }; + + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockRequest.correlationId).toBe('custom-corr-id'); + }); + + it('should set response headers', () => { + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockResponse.setHeader).toHaveBeenCalledWith( + 'X-Request-Id', + mockRequest.requestId, + ); + expect(mockResponse.setHeader).toHaveBeenCalledWith( + 'X-Correlation-Id', + mockRequest.correlationId, + ); + }); + + it('should call next()', () => { + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockNext).toHaveBeenCalled(); + }); + + it('should register finish event handler', () => { + middleware.use( + mockRequest as RequestWithContext, + mockResponse as Response, + mockNext, + ); + + expect(mockResponse.on).toHaveBeenCalledWith('finish', expect.any(Function)); + }); +}); diff --git a/backend/src/common/logger/logger.middleware.ts b/backend/src/common/logger/logger.middleware.ts new file mode 100644 index 00000000..3ade706b --- /dev/null +++ b/backend/src/common/logger/logger.middleware.ts @@ -0,0 +1,56 @@ +import { Injectable, NestMiddleware } from '@nestjs/common'; +import { Request, Response, NextFunction } from 'express'; +import { v4 as uuidv4 } from 'uuid'; +import { StructuredLoggerService } from './logger.service'; + +export interface RequestWithContext extends Request { + requestId: string; + correlationId: string; + userId?: string; +} + +@Injectable() +export class RequestContextMiddleware implements NestMiddleware { + private readonly logger: StructuredLoggerService; + + constructor(logger: StructuredLoggerService) { + this.logger = logger; + } + + use(req: RequestWithContext, res: Response, next: NextFunction): void { + const requestId = (req.headers['x-request-id'] as string) ?? uuidv4(); + const correlationId = (req.headers['x-correlation-id'] as string) ?? requestId; + + req.requestId = requestId; + req.correlationId = correlationId; + + res.setHeader('X-Request-Id', requestId); + res.setHeader('X-Correlation-Id', correlationId); + + const startTime = Date.now(); + + res.on('finish', () => { + const duration = Date.now() - startTime; + const logContext = { + requestId, + correlationId, + method: req.method, + url: req.originalUrl, + statusCode: res.statusCode, + duration, + userAgent: req.headers['user-agent'], + ip: req.ip, + }; + + if (res.statusCode >= 500) { + this.logger.error('Request completed with server error', undefined, logContext); + } else if (res.statusCode >= 400) { + this.logger.warn('Request completed with client error', logContext); + } else { + this.logger.log('Request completed', logContext); + } + }); + + next(); + } +} diff --git a/backend/src/common/logger/logger.module.ts b/backend/src/common/logger/logger.module.ts new file mode 100644 index 00000000..55260304 --- /dev/null +++ b/backend/src/common/logger/logger.module.ts @@ -0,0 +1,10 @@ +import { Module, Global } from '@nestjs/common'; +import { StructuredLoggerService } from './logger.service'; +import { RequestContextMiddleware } from './logger.middleware'; + +@Global() +@Module({ + providers: [StructuredLoggerService, RequestContextMiddleware], + exports: [StructuredLoggerService, RequestContextMiddleware], +}) +export class LoggerModule {} diff --git a/backend/src/common/logger/logger.service.spec.ts b/backend/src/common/logger/logger.service.spec.ts new file mode 100644 index 00000000..ec36b30a --- /dev/null +++ b/backend/src/common/logger/logger.service.spec.ts @@ -0,0 +1,72 @@ +import { Test, TestingModule } from '@nestjs/testing'; +import { ConfigService } from '@nestjs/config'; +import { StructuredLoggerService } from './logger.service'; + +describe('StructuredLoggerService', () => { + let service: StructuredLoggerService; + let configService: ConfigService; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [ + StructuredLoggerService, + { + provide: ConfigService, + useValue: { + get: jest.fn((key: string) => { + if (key === 'LOG_LEVEL') return 'info'; + if (key === 'NODE_ENV') return 'test'; + return undefined; + }), + }, + }, + ], + }).compile(); + + service = module.get(StructuredLoggerService); + configService = module.get(ConfigService); + }); + + it('should be defined', () => { + expect(service).toBeDefined(); + }); + + it('should log info messages', () => { + const spy = jest.spyOn(service.getPino(), 'info'); + service.log('Test message', { requestId: '123' }); + expect(spy).toHaveBeenCalledWith({ requestId: '123' }, 'Test message'); + }); + + it('should log error messages with trace', () => { + const spy = jest.spyOn(service.getPino(), 'error'); + service.error('Error message', 'stack trace', { requestId: '123' }); + expect(spy).toHaveBeenCalledWith( + expect.objectContaining({ requestId: '123' }), + 'Error message', + ); + }); + + it('should log warning messages', () => { + const spy = jest.spyOn(service.getPino(), 'warn'); + service.warn('Warning message', { userId: 'user-1' }); + expect(spy).toHaveBeenCalledWith({ userId: 'user-1' }, 'Warning message'); + }); + + it('should log debug messages', () => { + const spy = jest.spyOn(service.getPino(), 'debug'); + service.debug('Debug message'); + expect(spy).toHaveBeenCalledWith({}, 'Debug message'); + }); + + it('should create child logger with context', () => { + const child = service.child({ requestId: 'req-123', userId: 'user-456' }); + expect(child).toBeDefined(); + expect(child).toBeInstanceOf(StructuredLoggerService); + }); + + it('should return pino instance', () => { + const pino = service.getPino(); + expect(pino).toBeDefined(); + expect(typeof pino.info).toBe('function'); + }); +}); diff --git a/backend/src/common/logger/logger.service.ts b/backend/src/common/logger/logger.service.ts new file mode 100644 index 00000000..09a19905 --- /dev/null +++ b/backend/src/common/logger/logger.service.ts @@ -0,0 +1,91 @@ +import { Injectable, LoggerService } from '@nestjs/common'; +import { ConfigService } from '@nestjs/config'; +import pino from 'pino'; + +export interface LogContext { + requestId?: string; + userId?: string; + correlationId?: string; + [key: string]: unknown; +} + +@Injectable() +export class StructuredLoggerService implements LoggerService { + private readonly logger: pino.Logger; + + constructor(private readonly configService: ConfigService) { + const level = this.configService.get('LOG_LEVEL') ?? 'info'; + const isProduction = this.configService.get('NODE_ENV') === 'production'; + + this.logger = pino({ + level, + formatters: { + level(label: string) { + return { level: label }; + }, + }, + timestamp: pino.stdTimeFunctions.isoTime, + serializers: { + err: pino.stdSerializers.err, + req: pino.stdSerializers.req, + res: pino.stdSerializers.res, + }, + redact: { + paths: [ + 'req.headers.authorization', + 'req.headers.cookie', + 'password', + 'token', + 'secret', + 'encryptionKey', + 'healthData', + 'medicalRecord', + ], + remove: true, + }, + ...(isProduction + ? {} + : { + transport: { + target: 'pino-pretty', + options: { + colorize: true, + translateTime: 'SYS:standard', + ignore: 'pid,hostname', + }, + }, + }), + }); + } + + log(message: string, context?: LogContext): void { + this.logger.info(context ?? {}, message); + } + + error(message: string, trace?: string, context?: LogContext): void { + this.logger.error({ ...context, err: trace ? new Error(trace) : undefined }, message); + } + + warn(message: string, context?: LogContext): void { + this.logger.warn(context ?? {}, message); + } + + debug(message: string, context?: LogContext): void { + this.logger.debug(context ?? {}, message); + } + + verbose(message: string, context?: LogContext): void { + this.logger.trace(context ?? {}, message); + } + + child(context: LogContext): StructuredLoggerService { + const childLogger = Object.create(StructuredLoggerService.prototype); + childLogger.logger = this.logger.child(context); + childLogger.configService = this.configService; + return childLogger; + } + + getPino(): pino.Logger { + return this.logger; + } +} diff --git a/backend/src/main.ts b/backend/src/main.ts index 359bab56..16686523 100644 --- a/backend/src/main.ts +++ b/backend/src/main.ts @@ -4,11 +4,16 @@ import { ConfigService } from '@nestjs/config'; import { SwaggerModule, DocumentBuilder } from '@nestjs/swagger'; import { AppModule } from './app.module'; import { AllExceptionsFilter } from './common/filters/http-exception.filter'; +import { StructuredLoggerService } from './common/logger/logger.service'; async function bootstrap() { const app = await NestFactory.create(AppModule); const configService = app.get(ConfigService); + const logger = app.get(StructuredLoggerService); + + app.useLogger(logger); + const port = configService.get('PORT') ?? 3001; const apiPrefix = configService.get('API_PREFIX') ?? 'api/v1'; const nodeEnv = configService.get('NODE_ENV') ?? 'development'; @@ -54,9 +59,15 @@ async function bootstrap() { } await app.listen(port); - console.log(`API: http://localhost:${port}/${apiPrefix}`); + logger.log(`API server started`, { + port, + apiPrefix: `http://localhost:${port}/${apiPrefix}`, + environment: nodeEnv, + }); if (nodeEnv !== 'production') { - console.log(`Docs: http://localhost:${port}/docs`); + logger.log(`Swagger docs available`, { + docsUrl: `http://localhost:${port}/docs`, + }); } }