diff --git a/corpwiki/docs/people-portal-dev-guide/deployment/environment-variables.md b/corpwiki/docs/people-portal-dev-guide/deployment/environment-variables.md index 4fa8fd5..a69f171 100644 --- a/corpwiki/docs/people-portal-dev-guide/deployment/environment-variables.md +++ b/corpwiki/docs/people-portal-dev-guide/deployment/environment-variables.md @@ -39,6 +39,7 @@ A present-but-empty value counts as missing. |---|---| | `NODE_ENV` | `development`, `test` or `production`. Anything else throws. Default `development` | | `PORT` | Listen port. Default `3000` | +| `LOG_LEVEL` | `trace`, `debug`, `info`, `warn`, `error`, `fatal` or `silent`. Default `info` (`silent` under `NODE_ENV=test`). Production logs one JSON object per line; other environments get readable output. Every line written during a request carries its `requestId` and `userId` | | `PEOPLEPORTAL_BASE_URL` | Public origin. Builds the OIDC redirect and post-logout URLs | | `PEOPLEPORTAL_WEBHOOK_URL` | Origin Gitea calls back on. Usually the same as above | | `PEOPLEPORTAL_MONGO_URL` | MongoDB connection string | diff --git a/peopleportal/server/.env.example b/peopleportal/server/.env.example index cfa0d92..6127be3 100644 --- a/peopleportal/server/.env.example +++ b/peopleportal/server/.env.example @@ -56,3 +56,6 @@ PEOPLEPORTAL_WEBHOOK_URL=http://localhost:3000 # that container is actually running, or every upload is waved through. PHOTO_CHECK_ENABLED=false PHOTO_CHECK_URL=http://localhost:8001 + +# Log verbosity: trace, debug, info (default), warn, error, fatal or silent. +# LOG_LEVEL=info diff --git a/peopleportal/server/package-lock.json b/peopleportal/server/package-lock.json index 0b7a73b..1fcd9e8 100644 --- a/peopleportal/server/package-lock.json +++ b/peopleportal/server/package-lock.json @@ -43,6 +43,7 @@ "nodemailer": "^9.0.3", "nodemailer-express-handlebars": "^7.0.0", "openid-client": "^6.7.1", + "pino": "^9.14.0", "redis": "^6.0.1", "tsoa": "^6.6.0", "zxcvbn": "^4.4.2" @@ -58,6 +59,7 @@ "cpx": "^1.5.0", "mongodb-memory-server": "^11.2.0", "nodemon": "^3.1.10", + "pino-pretty": "^13.2.0", "supertest": "^7.2.2", "ts-node": "^10.9.2", "tsx": "^4.23.13", @@ -1818,6 +1820,12 @@ "@noble/hashes": "^1.1.5" } }, + "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", @@ -3121,6 +3129,15 @@ "node": ">= 4.5.0" } }, + "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/axios": { "version": "1.16.1", "resolved": "https://registry.npmjs.org/axios/-/axios-1.16.1.tgz", @@ -3702,6 +3719,13 @@ "integrity": "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==", "license": "MIT" }, + "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", @@ -4327,6 +4351,18 @@ "node": ">= 8" } }, + "node_modules/data-uri-to-buffer": { + "version": "4.0.1", + "resolved": "https://registry.npmjs.org/data-uri-to-buffer/-/data-uri-to-buffer-4.0.1.tgz", + "integrity": "sha512-0R9ikRb668HB7QDxT1vkpuUBtqc53YyAwMwGeUFKRojY/NWKvdZ+9UYtRfGmhqNbRkTSVpMbmyhXipFFv2cb/A==", + "dev": true, + "license": "MIT", + "optional": true, + "peer": true, + "engines": { + "node": ">= 12" + } + }, "node_modules/date.js": { "version": "0.3.3", "resolved": "https://registry.npmjs.org/date.js/-/date.js-0.3.3.tgz", @@ -4351,6 +4387,16 @@ "integrity": "sha512-Tpp60P6IUJDTuOq/5Z8cdskzJujfwqfOTkrwIwj7IRISpnkJnT6SyJ4PCPnGMoFjC9ddhal5KVIYtAt97ix05A==", "license": "MIT" }, + "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/debug": { "version": "4.4.3", "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", @@ -4553,6 +4599,16 @@ "node": ">= 0.8" } }, + "node_modules/end-of-stream": { + "version": "1.4.5", + "resolved": "https://registry.npmjs.org/end-of-stream/-/end-of-stream-1.4.5.tgz", + "integrity": "sha512-ooEGc6HP26xXq/N+GCGOT0JKCLDGrq2bQUZrQ7gyrJiZANJ/8YDTxTpQBXGMn+WbIQXNVpyWymm7KYVICQnyOg==", + "dev": true, + "license": "MIT", + "dependencies": { + "once": "^1.4.0" + } + }, "node_modules/entities": { "version": "4.5.0", "resolved": "https://registry.npmjs.org/entities/-/entities-4.5.0.tgz", @@ -5008,6 +5064,13 @@ "node": ">=0.10.0" } }, + "node_modules/fast-copy": { + "version": "4.3.1", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.3.1.tgz", + "integrity": "sha512-CRzQaTFOFUs6PuhsAq7lk9Zqr995soJBcFNZlfJS/5keTSl1awREV9dZW4xS2nX4pWbhIIR0xp4h+J8PQxCkvg==", + "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", @@ -5071,6 +5134,32 @@ "fxparser": "src/cli/cli.js" } }, + "node_modules/fetch-blob": { + "version": "3.2.0", + "resolved": "https://registry.npmjs.org/fetch-blob/-/fetch-blob-3.2.0.tgz", + "integrity": "sha512-7yAQpD2UMJzLi1Dqv7qFYnPbaPx7ZfFK6PiIxQ4PfkGPyNyl2Ugx+a/umUonmKqjhM4DnfbMvdX6otXq83soQQ==", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/jimmywarting" + }, + { + "type": "paypal", + "url": "https://paypal.me/jimmywarting" + } + ], + "license": "MIT", + "optional": true, + "peer": true, + "dependencies": { + "node-domexception": "^1.0.0", + "web-streams-polyfill": "^3.0.3" + }, + "engines": { + "node": "^12.20 || >= 14.13" + } + }, "node_modules/file-uri-to-path": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/file-uri-to-path/-/file-uri-to-path-1.0.0.tgz", @@ -5254,6 +5343,21 @@ "node": ">= 0.6" } }, + "node_modules/formdata-polyfill": { + "version": "4.0.10", + "resolved": "https://registry.npmjs.org/formdata-polyfill/-/formdata-polyfill-4.0.10.tgz", + "integrity": "sha512-buewHzMvYL29jdeQTVILecSaZKnt/RJWjoZCF5OW60Z67/GmSLBkOFM7qh1PI3zFNtJbaZL5eQu1vLfazOwj4g==", + "dev": true, + "license": "MIT", + "optional": true, + "peer": true, + "dependencies": { + "fetch-blob": "^3.1.2" + }, + "engines": { + "node": ">=12.20.0" + } + }, "node_modules/formidable": { "version": "3.5.4", "resolved": "https://registry.npmjs.org/formidable/-/formidable-3.5.4.tgz", @@ -5602,6 +5706,18 @@ "node": ">=10" } }, + "node_modules/google-logging-utils": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/google-logging-utils/-/google-logging-utils-1.2.0.tgz", + "integrity": "sha512-WE9av4wKDZgRjBwgVUabocx8T6/7o3Ca1Fat46FXDhXVAFibzNadedcOXrdgd1Kzmk8tsk/9ZH89Wyf/SqeZ3A==", + "dev": true, + "license": "Apache-2.0", + "optional": true, + "peer": true, + "engines": { + "node": ">=18" + } + }, "node_modules/google-p12-pem": { "version": "4.0.1", "resolved": "https://registry.npmjs.org/google-p12-pem/-/google-p12-pem-4.0.1.tgz", @@ -5849,6 +5965,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/http-errors": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/http-errors/-/http-errors-2.0.0.tgz", @@ -6263,6 +6386,16 @@ "url": "https://github.com/sponsors/panva" } }, + "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/json-bigint": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/json-bigint/-/json-bigint-1.0.0.tgz", @@ -6993,6 +7126,40 @@ "node": ">=20.19.0" } }, + "node_modules/mongodb-memory-server-core/node_modules/gaxios": { + "version": "7.3.1", + "resolved": "https://registry.npmjs.org/gaxios/-/gaxios-7.3.1.tgz", + "integrity": "sha512-kB3rzJV7d9juLZh8/56QTXCwQfxyhdOMdyYk1HdQKFtF8TJTDTZQJtixWIwXdE9Jji91mC41DUNpjleo4L4eAQ==", + "dev": true, + "license": "Apache-2.0", + "optional": true, + "peer": true, + "dependencies": { + "extend": "^3.0.2", + "https-proxy-agent": "^7.0.1", + "node-fetch": "^3.3.2" + }, + "engines": { + "node": ">=18" + } + }, + "node_modules/mongodb-memory-server-core/node_modules/gcp-metadata": { + "version": "7.0.1", + "resolved": "https://registry.npmjs.org/gcp-metadata/-/gcp-metadata-7.0.1.tgz", + "integrity": "sha512-UcO3kefx6dCcZkgcTGgVOTFb7b1LlQ02hY1omMjjrrBzkajRMCFgYOjs7J71WqnuG1k2b+9ppGL7FsOfhZMQKQ==", + "dev": true, + "license": "Apache-2.0", + "optional": true, + "peer": true, + "dependencies": { + "gaxios": "^7.0.0", + "google-logging-utils": "^1.0.0", + "json-bigint": "^1.0.0" + }, + "engines": { + "node": ">=18" + } + }, "node_modules/mongodb-memory-server-core/node_modules/https-proxy-agent": { "version": "7.0.6", "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-7.0.6.tgz", @@ -7068,6 +7235,27 @@ "node": ">=20.19.0" } }, + "node_modules/mongodb-memory-server-core/node_modules/node-fetch": { + "version": "3.3.2", + "resolved": "https://registry.npmjs.org/node-fetch/-/node-fetch-3.3.2.tgz", + "integrity": "sha512-dRB78srN/l6gqWulah9SrxeYnxeddIG30+GOqK/9OlLVyLg3HPnr6SqOWTWOXKRwC2eGYCkZ59NNuSgvSrpgOA==", + "dev": true, + "license": "MIT", + "optional": true, + "peer": true, + "dependencies": { + "data-uri-to-buffer": "^4.0.0", + "fetch-blob": "^3.1.4", + "formdata-polyfill": "^4.0.10" + }, + "engines": { + "node": "^12.20.0 || ^14.13.1 || >=16.0.0" + }, + "funding": { + "type": "opencollective", + "url": "https://opencollective.com/node-fetch" + } + }, "node_modules/mongoose": { "version": "8.24.0", "resolved": "https://registry.npmjs.org/mongoose/-/mongoose-8.24.0.tgz", @@ -7233,6 +7421,29 @@ "node": ">=20" } }, + "node_modules/node-domexception": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/node-domexception/-/node-domexception-1.0.0.tgz", + "integrity": "sha512-/jKZoMpw0F8GRwl4/eLROPA3cfcXtLApP0QzLmUT/HuPCZWyB7IY9ZrMeKw2O/nFIqPQB3PVM9aYm0F312AXDQ==", + "deprecated": "Use your platform's native DOMException instead", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/jimmywarting" + }, + { + "type": "github", + "url": "https://paypal.me/jimmywarting" + } + ], + "license": "MIT", + "optional": true, + "peer": true, + "engines": { + "node": ">=10.5.0" + } + }, "node_modules/node-fetch": { "version": "2.7.0", "resolved": "https://registry.npmjs.org/node-fetch/-/node-fetch-2.7.0.tgz", @@ -7483,6 +7694,15 @@ "node": ">=0.10.0" } }, + "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", @@ -7798,6 +8018,88 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-9.14.0.tgz", + "integrity": "sha512-8OEwKp5juEvb/MjpIc4hjqfgCNysrS94RIOMXYvpYCdm/jglrKEiAYmiumbmGhCvs+IcInsphYDFwqrjr7398w==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^2.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": "^3.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-2.0.0.tgz", + "integrity": "sha512-F63x5tizV6WCh4R6RHyi2Ml+M70DNRXt/+HANowMflpgGFMAym/VKm6G7ZOQRjqN7XbGxK1Lg9t6ZrtzOaivMw==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-pretty": { + "version": "13.2.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.2.0.tgz", + "integrity": "sha512-jjghD1ML+Di/WxjJDz6j6Y4FT7hIXOlb8h27AyJ+ohtAXJXH4PS/xkv7si+RCCIW59HMgZsMKTDgzdr0RhuRrg==", + "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.2", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.3", + "secure-json-parse": "^4.1.0", + "sonic-boom": "^5.0.0", + "strip-json-comments": "^5.0.3" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/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==", + "dev": true, + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-pretty/node_modules/sonic-boom": { + "version": "5.0.2", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-5.0.2.tgz", + "integrity": "sha512-/JEruzo6yhNVhsLblTRchgTQHIt7SsdJP0YyrfWaNKjIOQDfrdZv9gwYraYCAsmKV39/LAdV31FLL5NCDpoL/A==", + "dev": true, + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "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/pkg-dir": { "version": "4.2.0", "resolved": "https://registry.npmjs.org/pkg-dir/-/pkg-dir-4.2.0.tgz", @@ -7838,6 +8140,22 @@ "dev": true, "license": "MIT" }, + "node_modules/process-warning": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.1.tgz", + "integrity": "sha512-oCkNVj4OKnKEcocVBcDfiIugN1/cE6rgfT3nCtzeqZPA8+rIxMaQ0xXzIkGP8Gj2qUaP1UR7uhJ1VD8lUCpzCg==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/proxy-addr": { "version": "2.0.7", "resolved": "https://registry.npmjs.org/proxy-addr/-/proxy-addr-2.0.7.tgz", @@ -7867,6 +8185,17 @@ "dev": true, "license": "MIT" }, + "node_modules/pump": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.4.tgz", + "integrity": "sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==", + "dev": true, + "license": "MIT", + "dependencies": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "node_modules/punycode": { "version": "2.3.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.3.1.tgz", @@ -7900,6 +8229,12 @@ "url": "https://github.com/sponsors/ljharb" } }, + "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/random-bytes": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/random-bytes/-/random-bytes-1.0.0.tgz", @@ -8024,6 +8359,15 @@ "node": ">=8.10.0" } }, + "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/redis": { "version": "6.2.1", "resolved": "https://registry.npmjs.org/redis/-/redis-6.2.1.tgz", @@ -8210,12 +8554,38 @@ "ret": "~0.1.10" } }, + "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", "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.1", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.1.tgz", + "integrity": "sha512-lnd81MQEZKjhW/Gd2TQqdd4XP6QYNdDW/EP+I7nTrFHP9y2LmaGPIHk9xsnzcOiEr1c39c/e84xFgGviQKBTRw==", + "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", @@ -8581,6 +8951,15 @@ "node": ">=0.10.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.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", @@ -8635,6 +9014,15 @@ "node": ">=0.10.0" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/static-extend": { "version": "0.1.2", "resolved": "https://registry.npmjs.org/static-extend/-/static-extend-0.1.2.tgz", @@ -8810,6 +9198,19 @@ "node": ">=8" } }, + "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/strnum": { "version": "2.3.0", "resolved": "https://registry.npmjs.org/strnum/-/strnum-2.3.0.tgz", @@ -8952,6 +9353,15 @@ "b4a": "^1.6.4" } }, + "node_modules/thread-stream": { + "version": "3.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-3.2.0.tgz", + "integrity": "sha512-zLBvqpwr4Esa0kRjcrzGU6zL25lePWaCLMx0RQFrmteozIfeNdaMLpG5U7PeHzvlFkAWaRKA9/KVW4F60iB+qw==", + "license": "MIT", + "dependencies": { + "real-require": "^0.2.0" + } + }, "node_modules/to-object-path": { "version": "0.3.0", "resolved": "https://registry.npmjs.org/to-object-path/-/to-object-path-0.3.0.tgz", @@ -9396,6 +9806,18 @@ "node": ">= 0.8" } }, + "node_modules/web-streams-polyfill": { + "version": "3.3.3", + "resolved": "https://registry.npmjs.org/web-streams-polyfill/-/web-streams-polyfill-3.3.3.tgz", + "integrity": "sha512-d2JWLCivmZYTSIoge9MsgFCZrt571BikcWGYkjC1khllbTeDlGqZ2D8vD8E/lJa8WGWbb7Plm8/XJYV7IJHZZw==", + "dev": true, + "license": "MIT", + "optional": true, + "peer": true, + "engines": { + "node": ">= 8" + } + }, "node_modules/webidl-conversions": { "version": "7.0.0", "resolved": "https://registry.npmjs.org/webidl-conversions/-/webidl-conversions-7.0.0.tgz", diff --git a/peopleportal/server/package.json b/peopleportal/server/package.json index b58d67b..926b7fd 100644 --- a/peopleportal/server/package.json +++ b/peopleportal/server/package.json @@ -41,6 +41,7 @@ "nodemailer": "^9.0.3", "nodemailer-express-handlebars": "^7.0.0", "openid-client": "^6.7.1", + "pino": "^9.14.0", "redis": "^6.0.1", "tsoa": "^6.6.0", "zxcvbn": "^4.4.2" @@ -56,9 +57,10 @@ "cpx": "^1.5.0", "mongodb-memory-server": "^11.2.0", "nodemon": "^3.1.10", + "pino-pretty": "^13.2.0", "supertest": "^7.2.2", "ts-node": "^10.9.2", "tsx": "^4.23.13", "typescript": "^5.9.2" } -} \ No newline at end of file +} diff --git a/peopleportal/server/src/app.ts b/peopleportal/server/src/app.ts index 9873d5d..a7e1aac 100644 --- a/peopleportal/server/src/app.ts +++ b/peopleportal/server/src/app.ts @@ -41,15 +41,13 @@ import { AuthentikClient } from "./clients/AuthentikClient"; import { RedisClient } from "./clients/RedisClient"; import { CustomValidationError, ResourceAccessError } from "./utils/errors"; import { ENABLED_SHARED_RESOURCES } from "./config"; -import log from "loglevel"; +import { logger, requestLogger } from "./utils/logger"; import { agendaClient } from "./clients/AgendaClient"; import { authenticateGiteaWebhook } from "./utils/gitea-webhook-auth"; import { describeUnknownError } from "./utils/errors"; -log.setLevel("info"); - assertRequiredEnvironment(); -log.info( +logger.info( `Environment: ${ENVIRONMENT}${loadedEnvFiles.length ? ` (loaded ${loadedEnvFiles.join(", ")})` : ""}`, ); @@ -60,7 +58,7 @@ if (!process.env.PEOPLEPORTAL_TOKEN_SECRET) { throw new Error("PEOPLEPORTAL_TOKEN_SECRET must be set in production"); process.env.PEOPLEPORTAL_TOKEN_SECRET = generateSecureRandomString(16); - log.warn( + logger.warn( "PEOPLEPORTAL_TOKEN_SECRET is unset; generated an ephemeral one. Sessions will not survive a restart.", ); } @@ -68,6 +66,9 @@ if (!process.env.PEOPLEPORTAL_TOKEN_SECRET) { const app = express(); const PORT = envInt("PORT", 3000); +/* First, so request timing and the request id cover every other middleware. */ +app.use(requestLogger); + app.use(express.urlencoded({ extended: true })); app.use(express.json()); @@ -163,7 +164,20 @@ app.use(function errorHandler( } if (err instanceof ValidateError) { - console.warn(`Caught Validation Error for ${req.path}:`, err.fields); + /* Log which fields failed and why, never the submitted values: a + rejected login or signup body would otherwise put passwords in logs. */ + logger.warn( + { + route: req.path, + fields: Object.fromEntries( + Object.entries(err.fields).map(([name, f]) => [ + name, + f.message, + ]), + ), + }, + "Request validation failed", + ); return res.status(422).json({ message: "Validation Failed", details: err?.fields, @@ -180,7 +194,7 @@ app.use(function errorHandler( } if (err instanceof Error) { - console.error(err); + logger.error({ err, route: req.path }, "Unhandled error in request"); return res.status(500).json({ message: err.message ?? "Unknown Internal Server Error", }); @@ -220,30 +234,30 @@ async function startup(): Promise { try { await authentikClient.validateServiceExistance(); } catch (e: unknown) { - log.error( - "Service team validation failed; executive and events features may be unavailable:", - describeUnknownError(e), + logger.error( + { err: describeUnknownError(e) }, + "Service team validation failed; executive and events features may be unavailable", ); } /* Initialize Shared Resource Clients. One integration failing to start must not stop the server from serving, so each is isolated. */ for (const client in ENABLED_SHARED_RESOURCES) { - log.info(`Initializing Shared Resource Client: ${client}`); + logger.info({ client }, "Initializing shared resource client"); const clientInstance = ENABLED_SHARED_RESOURCES[client]!; try { await clientInstance.init(); } catch (e: unknown) { - log.error( - `Failed to initialize shared resource client "${client}", continuing without it:`, - describeUnknownError(e), + logger.error( + { client, err: describeUnknownError(e) }, + "Failed to initialize shared resource client, continuing without it", ); } } /* Validate Database Connection */ await mongoose.connect(process.env.PEOPLEPORTAL_MONGO_URL!); - log.info(`Server running at http://localhost:${PORT}`); + logger.info({ port: PORT }, "Server running"); // Agenda Client Singleton await agendaClient.initialize(); @@ -255,8 +269,10 @@ app.listen(PORT, () => { discovery, Redis, Mongo, the job scheduler) did not come up. Exit deliberately with a readable reason rather than dying on an unhandled rejection halfway through boot. */ - log.error("Fatal error during startup:", describeUnknownError(e)); - if (e instanceof Error && e.stack) log.error(e.stack); + logger.fatal( + { err: e instanceof Error ? e : describeUnknownError(e) }, + "Fatal error during startup", + ); process.exit(1); }); }); diff --git a/peopleportal/server/src/auth.ts b/peopleportal/server/src/auth.ts index e139d39..74fa21e 100644 --- a/peopleportal/server/src/auth.ts +++ b/peopleportal/server/src/auth.ts @@ -27,6 +27,10 @@ import { formatBindleAccessError } from "./utils/strings"; import { ConstraintViolationException } from "@aws-sdk/client-organizations"; import { hasAdminAuthority } from "./config"; +import { logger } from "./utils/logger"; + +const log = logger.child({ module: "auth" }); + export async function NativeExpressOIDCAuthPort( req: express.Request, res: express.Response, @@ -124,7 +128,7 @@ async function oidcAuthVerify( request.session.refreshToken ) { try { - console.log("Access Token Expired. Attempting Refresh..."); + log.debug("Access token expired; attempting refresh"); const newTokens = await OpenIdClient.refreshAccessToken( request.session.refreshToken, ); @@ -139,7 +143,7 @@ async function oidcAuthVerify( return Promise.resolve(true); } catch (refreshError) { - console.error("Token Refresh Failed:", refreshError); + log.error({ err: refreshError }, "Token Refresh Failed"); } } @@ -473,7 +477,7 @@ async function bindlesAuthVerify( ), ); } catch (e) { - console.error("Bindle Permission Check Failed", e); + log.error({ err: e }, "Bindle Permission Check Failed"); if (e instanceof ResourceAccessError) return Promise.reject(e); return Promise.reject( new ResourceAccessError(403, "Bindle Permission Check Failed"), diff --git a/peopleportal/server/src/controllers/ATSController.ts b/peopleportal/server/src/controllers/ATSController.ts index babbb46..1d3a090 100644 --- a/peopleportal/server/src/controllers/ATSController.ts +++ b/peopleportal/server/src/controllers/ATSController.ts @@ -78,6 +78,10 @@ import { wrapCacheValue, } from "../utils/cache-envelope"; +import { logger } from "../utils/logger"; + +const log = logger.child({ module: "ATSController" }); + // ==================== // Type Definitions // ==================== @@ -320,7 +324,7 @@ export class ATSController extends Controller { this.setHeader("Location", downloadUrl); return; } catch (error) { - console.error("Error generating download URL:", error); + log.error({ err: error }, "Error generating download URL"); this.setStatus(404); // Or 500 return { error: "NotFound", @@ -502,8 +506,9 @@ export class ATSController extends Controller { here would take the process down for a stale cache entry. */ void this.buildAndCacheOpenTeams() .catch((e: any) => - console.error( - `Background refresh of the open-teams cache failed: ${e?.message ?? e}`, + log.error( + { err: e }, + "Background refresh of the open-teams cache failed", ), ) .finally(() => { @@ -625,8 +630,9 @@ export class ATSController extends Controller { * one query rather than one delete per team inside the render loop. */ if (missingTeamPks.length > 0) { - console.warn( - `Recruiting Teams with PKs ${missingTeamPks.join(", ")} not found in Authentik. Cleaning up.`, + log.warn( + { teamPks: missingTeamPks }, + "Recruiting teams not found in Authentik; cleaning up", ); await TeamRecruitingStatus.deleteMany({ teamPk: { $in: missingTeamPks }, @@ -783,7 +789,7 @@ export class ATSController extends Controller { return kanbanData; } catch (err) { - console.error("Error fetching applications:", err); + log.error({ err: err }, "Error fetching applications"); this.setStatus(500); throw new Error("Failed to fetch applications"); } @@ -842,7 +848,7 @@ export class ATSController extends Controller { : {}), }; } catch (err) { - console.error("Error fetching application details:", err); + log.error({ err: err }, "Error fetching application details"); this.setStatus(500); return { error: "ServerError", @@ -1030,7 +1036,7 @@ export class ATSController extends Controller { ); // 15 mins } } catch (s3Error) { - console.error("Error signing S3 URL:", s3Error); + log.error({ err: s3Error }, "Error signing S3 URL"); // Fallback or just ignore, maybe client can deal with the raw key or empty string? // We'll leave it undefined if signing fails. } @@ -1040,7 +1046,7 @@ export class ATSController extends Controller { resumeUrl: resumeDownloadUrl, }; } catch (err) { - console.error("Error fetching applicant URLs:", err); + log.error({ err: err }, "Error fetching applicant URLs"); this.setStatus(500); return { error: "ServerError", @@ -1297,7 +1303,7 @@ export class ATSController extends Controller { }, }; } catch (err) { - console.error("Error updating application stage:", err); + log.error({ err: err }, "Error updating application stage"); this.setStatus(500); return { error: "ServerError", @@ -1360,9 +1366,9 @@ export class ATSController extends Controller { teamName = teamInfo.name; } } catch (e) { - console.error( - `Failed to fetch team info for ${app.teamPk}`, - e, + log.error( + { err: e, teamPk: app.teamPk }, + "Failed to fetch team info", ); } @@ -1379,9 +1385,9 @@ export class ATSController extends Controller { subteamInfo.attributes?.friendlyName || subteamInfo.name; } catch (e) { - console.error( - `Failed to fetch subteam info for ${pref.subteamPk}`, - e, + log.error( + { err: e, subteamPk: pref.subteamPk }, + "Failed to fetch subteam info", ); } return { ...pref, subteamName }; @@ -1402,7 +1408,7 @@ export class ATSController extends Controller { return results; } catch (err) { - console.error("Error fetching applicant applications:", err); + log.error({ err: err }, "Error fetching applicant applications"); this.setStatus(500); return { error: "ServerError", @@ -1695,7 +1701,7 @@ export class ATSController extends Controller { }; } } catch (e) { - console.error("Failed to validate resume", e); + log.error({ err: e }, "Failed to validate resume"); this.setStatus(500); return { error: "FileProcessingError", @@ -1761,7 +1767,7 @@ export class ATSController extends Controller { id: application._id, }; } catch (err) { - console.error("Application submission error:", err); + log.error({ err: err }, "Application submission error"); this.setStatus(500); return { error: "ServerError", @@ -1848,7 +1854,7 @@ export class ATSController extends Controller { return { message: "Profile updated successfully" }; } catch (err) { - console.error("Error updating profile:", err); + log.error({ err: err }, "Error updating profile"); this.setStatus(500); return { error: "ServerError", diff --git a/peopleportal/server/src/controllers/AuthController.ts b/peopleportal/server/src/controllers/AuthController.ts index 395c67c..b22113f 100644 --- a/peopleportal/server/src/controllers/AuthController.ts +++ b/peopleportal/server/src/controllers/AuthController.ts @@ -43,6 +43,10 @@ import { signAvatarUrl } from "../utils/avatars"; import { executiveAuthVerify } from "../auth"; import { describeUnknownError } from "../utils/errors"; +import { logger } from "../utils/logger"; + +const log = logger.child({ module: "AuthController" }); + export interface CorpUserInfoResponse extends UserInfoResponse { avatar: string; isExecutive: boolean; @@ -255,7 +259,7 @@ export class AuthController extends Controller { /* Case 3: Default */ return res.redirect(302, "/"); } catch (e) { - console.log(e); + log.error({ err: e }, "handleRedirect failed"); throw e; } } @@ -443,9 +447,9 @@ export class AuthController extends Controller { teamName = teamInfo.attributes?.friendlyName || teamInfo.name; } catch (e) { - console.error( - `Failed to fetch team info for ${app.teamPk}`, - e, + log.error( + { err: e, teamPk: app.teamPk }, + "Failed to fetch team info", ); } @@ -462,9 +466,9 @@ export class AuthController extends Controller { subteamInfo.attributes?.friendlyName || subteamInfo.name; } catch (e) { - console.error( - `Failed to fetch subteam info for ${pref.subteamPk}`, - e, + log.error( + { err: e, subteamPk: pref.subteamPk }, + "Failed to fetch subteam info", ); } return { ...pref, subteamName }; @@ -529,9 +533,9 @@ export class AuthController extends Controller { } catch (e: unknown) { /* A provider problem must not strand the user in a logged-in session: fall through to the local logout below. */ - console.error( - "Failed building provider logout URL:", - describeUnknownError(e), + log.error( + { err: describeUnknownError(e) }, + "Failed building provider logout URL", ); } diff --git a/peopleportal/server/src/controllers/EventController.ts b/peopleportal/server/src/controllers/EventController.ts index 59ed209..afd5aa4 100644 --- a/peopleportal/server/src/controllers/EventController.ts +++ b/peopleportal/server/src/controllers/EventController.ts @@ -45,6 +45,10 @@ import { DiscordClient } from "../clients/DiscordClient"; import type { DocumentJSON } from "../utils/types"; +import { logger } from "../utils/logger"; + +const log = logger.child({ module: "EventController" }); + export interface GetEventListOptions { before?: Date; after?: Date; @@ -264,10 +268,7 @@ export class EventController extends Controller { } return { status: "Success", data: event }; } catch (error) { - console.error( - `Failed to get event data for event ${eventId}:`, - error, - ); + log.error({ err: error, eventId }, "Failed to get event data"); throw new ResourceAccessError(500, "Failed to fetch event data"); } } @@ -347,7 +348,10 @@ export class EventController extends Controller { }, }); } catch (error) { - console.error("Failed to send email to event invitees:", error); + log.error( + { err: error }, + "Failed to send email to event invitees", + ); issues.push("Failed to send email."); } } @@ -398,9 +402,9 @@ export class EventController extends Controller { }); } catch (error) { issues.push("Failed to schedule 2 hour reminder."); - console.error( - `Failed to schedule 2 hour reminder for event ${event._id}:`, - error, + log.error( + { err: error, eventId: event._id }, + "Failed to schedule 2 hour reminder", ); } @@ -434,10 +438,7 @@ export class EventController extends Controller { try { event = await Event.findOne({ _id: eventId }).exec(); } catch (error) { - console.error( - `Failed to get event data for event ${eventId}: `, - error, - ); + log.error({ err: error, eventId }, "Failed to get event data"); throw new ResourceAccessError( 500, `Failed to fetch event ${eventId}`, @@ -494,7 +495,7 @@ export class EventController extends Controller { }, }); } catch (error) { - console.error(`Failed to get email recipients:`, error); + log.error({ err: error }, "Failed to get email recipients"); issues.push("Failed to send emails."); } } @@ -651,7 +652,7 @@ export class EventController extends Controller { }); } catch (error) { issues.push("Failed to replace notification job."); - console.error("Failed to re-schedule notification:", error); + log.error({ err: error }, "Failed to re-schedule notification"); } } @@ -730,7 +731,7 @@ export class EventController extends Controller { }, }); } catch (error) { - console.error("Failed to send email:", error); + log.error({ err: error }, "Failed to send email"); issues.push("Failed to send emails."); } @@ -783,7 +784,7 @@ export class EventController extends Controller { }, }; } catch (error) { - console.error(`Failed to get RSVPs for event ${eventId}:`, error); + log.error({ err: error, eventId }, "Failed to get RSVPs"); throw new ResourceAccessError(500, "Failed to fetch RSVPs"); } } @@ -915,7 +916,7 @@ export class EventController extends Controller { }, }); } catch (error) { - console.error("Failed to send confirmation email for RSVP."); + log.error("Failed to send confirmation email for RSVP."); issues.push("Failed to send confirmation email."); } @@ -983,12 +984,12 @@ export class EventController extends Controller { message, ); if (!success) { - console.error("Failed to send slack message."); + log.error("Failed to send slack message."); return false; } return success; } else { - console.error("Slack announcements channel not found."); + log.error("Slack announcements channel not found."); return false; } } @@ -1008,7 +1009,7 @@ export class EventController extends Controller { } return true; } catch (error) { - console.error("Failed to send discord announcement:", error); + log.error({ err: error }, "Failed to send discord announcement"); return false; } } diff --git a/peopleportal/server/src/controllers/HooksController.ts b/peopleportal/server/src/controllers/HooksController.ts index bb68d35..a3b8613 100644 --- a/peopleportal/server/src/controllers/HooksController.ts +++ b/peopleportal/server/src/controllers/HooksController.ts @@ -32,6 +32,10 @@ import { import { GiteaClient } from "../clients/GiteaClient"; import { AuthentikClient } from "../clients/AuthentikClient"; +import { logger } from "../utils/logger"; + +const log = logger.child({ module: "HooksController" }); + @Route("/api/webhook") export class HooksController extends Controller { /* How recently a personal repository must have been created for its @@ -101,8 +105,9 @@ export class HooksController extends Controller { ]); } catch (e: any) { /* Potential Group Not Found Error! We're good, not mission critical. */ - console.error( - `Failed applying branch protection for ${commitEvent.repository.full_name}: ${e.message}`, + log.error( + { err: e, repository: commitEvent.repository.full_name }, + "Failed applying branch protection", ); } @@ -118,8 +123,9 @@ export class HooksController extends Controller { repoEvent.repository.owner.username, ); } catch (e: any) { - console.error( - `Failed resolving the owner of ${repoEvent.repository.full_name}: ${e.message}`, + log.error( + { err: e, repository: repoEvent.repository.full_name }, + "Failed resolving the repository owner", ); return "OK (Actions Failed)"; } @@ -154,8 +160,9 @@ export class HooksController extends Controller { }); } catch (e: any) { /* Processing failed; leave the repository untouched for an authorized operator to review. */ - console.error( - `Failed provisioning repository ${repoEvent.repository.full_name}: ${e.message}`, + log.error( + { err: e, repository: repoEvent.repository.full_name }, + "Failed provisioning repository", ); return "OK (Actions Failed)"; } @@ -195,13 +202,15 @@ export class HooksController extends Controller { } await this.giteaClient.deleteRepository(ownerName, repository.name); - console.warn( - `Deleted personal repository ${repository.full_name}: team code belongs in a team organization`, + log.warn( + { repository: repository.full_name }, + "Deleted personal repository: team code belongs in a team organization", ); return "OK (Personal Repository Deleted)"; } catch (e: any) { - console.error( - `Not deleting personal repository ${repoEvent.repository.full_name}: ${e.message}`, + log.error( + { err: e, repository: repoEvent.repository.full_name }, + "Not deleting personal repository", ); return "OK (Actions Failed)"; } diff --git a/peopleportal/server/src/controllers/OrgController.ts b/peopleportal/server/src/controllers/OrgController.ts index f622565..4527d2f 100644 --- a/peopleportal/server/src/controllers/OrgController.ts +++ b/peopleportal/server/src/controllers/OrgController.ts @@ -118,6 +118,10 @@ import { IUserReview, UserReview } from "../models/UserReview"; import type { DocumentJSON } from "../utils/types"; +import { logger, errorMap } from "../utils/logger"; + +const log = logger.child({ module: "OrgController" }); + export interface EnabledRootSettings { [key: string]: boolean; } @@ -505,7 +509,7 @@ export class OrgController extends Controller { userInfo.username, ); } catch (e) { - console.error(e); + log.error({ err: e }, "getReview failed"); throw new ResourceAccessError( 500, "Failed to get user team membership", @@ -528,7 +532,7 @@ export class OrgController extends Controller { .exec(); return { review: review }; } catch (e) { - console.error(e); + log.error({ err: e }, "getReview failed"); throw new ResourceAccessError(500, "Failed to fetch review"); } } @@ -721,7 +725,7 @@ export class OrgController extends Controller { userInfo.username, ); } catch (e) { - console.error(e); + log.error({ err: e }, "writeReview failed"); throw new ResourceAccessError( 500, "Failed to get user team membership", @@ -748,7 +752,7 @@ export class OrgController extends Controller { throw new CustomValidationError(400, "Review already created."); } } catch (e) { - console.error(e); + log.error({ err: e }, "writeReview failed"); if (e instanceof CustomValidationError) { throw e; } @@ -767,7 +771,7 @@ export class OrgController extends Controller { if (e instanceof Error.ValidationError) { throw new CustomValidationError(400, `Invalid Review: ${e}`); } - console.error(e); + log.error({ err: e }, "writeReview failed"); throw new ResourceAccessError(500, "Failed to create review"); } @@ -1112,7 +1116,7 @@ export class OrgController extends Controller { }), ); } catch (e) { - console.error("Failed to delete old avatar", e); + log.error({ err: e }, "Failed to delete old avatar"); } } @@ -1124,14 +1128,14 @@ export class OrgController extends Controller { }), ); } catch (e) { - console.error( + log.error( + { err: e }, "Failed to delete temp avatar after commit", - e, ); } } catch (e) { if (e instanceof CustomValidationError) throw e; - console.error("Failed to process avatar update", e); + log.error({ err: e }, "Failed to process avatar update"); throw new CustomValidationError( 500, "Failed to update avatar.", @@ -1509,7 +1513,7 @@ export class OrgController extends Controller { return ownerNode; } } catch (e) { - // console.error(`Failed to process team ${team.name}`, e); + // log.error({ err: e, team: team.name }, "Failed to process team"); } }), ); @@ -2068,7 +2072,7 @@ export class OrgController extends Controller { allowedAvatars, ); if (!isValid) { - console.error( + log.error( "Profile picture was not valid. Account created anyway.", ); await deleteTempAvatar(req.avatarKey); @@ -2078,7 +2082,7 @@ export class OrgController extends Controller { const imageBytes = await getS3ObjectBytes(req.avatarKey); if (!imageBytes) { - console.error( + log.error( "Failed to fetch avatar bytes. Account created anyway.", ); await deleteTempAvatar(req.avatarKey); @@ -2088,7 +2092,7 @@ export class OrgController extends Controller { const faceCheckResult = await checkPhotoHasFace(imageBytes); if (faceCheckResult.passed === false) { - console.error( + log.error( "Avatar failed face check. Account created anyway.", ); await deleteTempAvatar(req.avatarKey); @@ -2123,7 +2127,7 @@ export class OrgController extends Controller { ); } catch (e) { // Don't fail the whole request, just log error. User is created. - console.error("Failed to process avatar", e); + log.error({ err: e }, "Failed to process avatar"); } } @@ -2828,7 +2832,11 @@ export class OrgController extends Controller { } /* Write All the Errors during the Process... */ - console.log(errors); + if (errors.size > 0) + log.warn( + { errors: errorMap(errors) }, + "Shared resource sync finished with errors", + ); res.end(); } @@ -2993,9 +3001,9 @@ export class OrgController extends Controller { } if (errors.size > 0) - console.error( - "[OrgController] Archive completed with errors:", - errors, + log.error( + { errors: errorMap(errors) }, + "Archive completed with errors", ); /* 3. Stamp the team as archived */ diff --git a/peopleportal/server/src/controllers/PlatformController.ts b/peopleportal/server/src/controllers/PlatformController.ts index 9d806be..99268ce 100644 --- a/peopleportal/server/src/controllers/PlatformController.ts +++ b/peopleportal/server/src/controllers/PlatformController.ts @@ -21,6 +21,10 @@ import fs from "fs"; import path from "path"; import { getGPLv3License } from "../utils/strings"; +import { logger } from "../utils/logger"; + +const log = logger.child({ module: "PlatformController" }); + interface PlatformLicenseResponse { licenseText: string; dependencies: { name: string; version: string }[]; @@ -53,7 +57,7 @@ export class PlatformController extends Controller { } } } catch (e) { - console.error("Failed to read package.json", e); + log.error({ err: e }, "Failed to read package.json"); } return { diff --git a/peopleportal/server/src/utils/logger.ts b/peopleportal/server/src/utils/logger.ts new file mode 100644 index 0000000..f57509b --- /dev/null +++ b/peopleportal/server/src/utils/logger.ts @@ -0,0 +1,194 @@ +/** + People Portal Server + Copyright (C) 2026 Atheesh Thirumalairajan + + This program is free software: you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation, either version 3 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program. If not, see . +*/ + +import { AsyncLocalStorage } from "async_hooks"; +import { randomUUID } from "crypto"; +import type { NextFunction, Request, Response } from "express"; +import loglevel from "loglevel"; +import pino, { type DestinationStream, type Logger } from "pino"; +import { + ENVIRONMENT, + isProduction, + isTest, + loadEnvironmentFiles, +} from "../config/environment"; + +/* Imports are hoisted above app.ts's own env loading, so make sure LOG_LEVEL + from the .env files is visible before we read it. Loading is idempotent. */ +loadEnvironmentFiles(); + +const LEVELS = ["trace", "debug", "info", "warn", "error", "fatal", "silent"]; + +/** + * LOG_LEVEL picks how chatty the server is. Unset means "info", except under + * test where the default is "silent" so test output stays readable. + */ +export function resolveLogLevel(raw = process.env.LOG_LEVEL): string { + const wanted = raw?.trim().toLowerCase(); + if (wanted && LEVELS.includes(wanted)) return wanted; + return isTest ? "silent" : "info"; +} + +/** + * Production writes one JSON object per line so logs can be searched and + * filtered by field. Everywhere else gets readable, colourised output through + * pino-pretty (a devDependency, so it is simply skipped if absent). + */ +function createDestination(): DestinationStream | undefined { + if (isProduction || isTest) return undefined; + try { + // eslint-disable-next-line @typescript-eslint/no-require-imports + const pretty = require("pino-pretty"); + return pretty({ colorize: true, ignore: "pid,hostname" }); + } catch { + return undefined; + } +} + +/** + * Errors are logged as type, message, stack and (for HTTP failures) the status. + * Axios and similar errors also carry the whole request - headers with bearer + * tokens, bodies with passwords - so those properties are dropped, not logged. + */ +export function serializeError(err: unknown): unknown { + const base = pino.stdSerializers.err(err as Error) as Record< + string, + unknown + >; + if (!base || typeof base !== "object") return base; + for (const key of ["config", "request", "response", "headers", "toJSON"]) + delete base[key]; + const status = (err as { response?: { status?: number } })?.response + ?.status; + if (typeof status === "number") base.status = status; + return base; +} + +/* Each key is covered at the top level and one level down: pino's "*.x" only + matches nested keys, so a bare { password } would otherwise slip through. */ +const SENSITIVE_KEYS = [ + "token", + "accessToken", + "refreshToken", + "secret", + "password", +]; +export const REDACT = { + paths: [ + "req.headers.authorization", + "req.headers.cookie", + ...SENSITIVE_KEYS, + ...SENSITIVE_KEYS.map((key) => `*.${key}`), + ], + censor: "[redacted]", +}; + +const level = resolveLogLevel(); + +/** The request currently being served, so any log line can be tied back to it. */ +const requestContext = new AsyncLocalStorage<{ id: string; req: Request }>(); + +export const logger: Logger = pino( + { + level, + base: { env: ENVIRONMENT }, + /* Anything logged while a request is in flight (controllers, clients, + the error handler) automatically carries its request id and user. */ + mixin() { + const ctx = requestContext.getStore(); + if (!ctx) return {}; + return { + requestId: ctx.id, + userId: ctx.req.session?.authorizedUser?.pk, + }; + }, + /* Errors passed as { err } are expanded into type, message and stack. */ + serializers: { err: serializeError }, + /* Never let credentials reach a log line, whatever gets logged. */ + redact: REDACT, + }, + createDestination(), +); + +/* A few clients still log through loglevel. Drive it from the same LOG_LEVEL so + there is a single knob, instead of a hardcoded level in app.ts. */ +loglevel.setLevel( + (level === "fatal" + ? "error" + : level) as loglevel.LogLevelDesc /* pino and loglevel share names */, +); + +/** Request augmentation: every request carries an id. */ +declare module "express-serve-static-core" { + interface Request { + id: string; + } +} + +/** + * Logs one line per request when it finishes: method, route, status, duration + * and user id. The route is the matched pattern (/teams/:teamId), not the raw + * URL, so query strings and ids never end up in the message and the field + * stays searchable. The request id is returned in X-Request-Id and is added to + * every log line written while the request is in flight, which ties error lines + * to the request that produced them. + * + * Register this before every other middleware so timing covers all of them. + */ +export function requestLogger( + req: Request, + res: Response, + next: NextFunction, +): void { + const start = process.hrtime.bigint(); + req.id = randomUUID(); + res.setHeader("X-Request-Id", req.id); + + res.on("finish", () => { + const route = req.route?.path + ? `${req.baseUrl}${req.route.path}` + : undefined; + const fields = { + requestId: req.id, + method: req.method, + route: route ?? "(unmatched)", + status: res.statusCode, + durationMs: Number(process.hrtime.bigint() - start) / 1e6, + userId: req.session?.authorizedUser?.pk, + }; + + /* Static assets and the SPA fallback match no API route; keep their + successful hits out of the way at debug. */ + if (res.statusCode >= 500) logger.error(fields, "request failed"); + else if (res.statusCode >= 400) logger.warn(fields, "request rejected"); + else if (!route) logger.debug(fields, "request completed"); + else logger.info(fields, "request completed"); + }); + + requestContext.run({ id: req.id, req }, next); +} + +/** + * Flattens a Map of named failures into { name: message } so it logs as + * structured fields rather than an opaque Map dump. + */ +export function errorMap(errors: Map): Record { + return Object.fromEntries( + [...errors].map(([name, error]) => [name, error.message]), + ); +} diff --git a/peopleportal/server/test/unit/logger.test.js b/peopleportal/server/test/unit/logger.test.js new file mode 100644 index 0000000..bf608cf --- /dev/null +++ b/peopleportal/server/test/unit/logger.test.js @@ -0,0 +1,76 @@ +/** + * The logger is the one place every server log line goes through, so these pin + * the behaviours the rest of the codebase relies on: LOG_LEVEL is honoured, + * errors are serialised without leaking request secrets, and each request logs + * one structured line carrying its id. + */ +const assert = require("node:assert/strict"); +const test = require("node:test"); +const pino = require("pino"); +const { EventEmitter } = require("node:events"); +const { + resolveLogLevel, + serializeError, + errorMap, + requestLogger, + REDACT, +} = require("../../dist/utils/logger.js"); + +test("LOG_LEVEL is honoured, case-insensitively, and bad values fall back", () => { + assert.equal(resolveLogLevel("debug"), "debug"); + assert.equal(resolveLogLevel(" WARN "), "warn"); + /* NODE_ENV is "test" here, where the default is silent. */ + assert.equal(resolveLogLevel(undefined), "silent"); + assert.equal(resolveLogLevel("loud"), "silent"); +}); + +test("serialised errors keep message and stack but drop the request", () => { + const err = new Error("Request failed with status code 401"); + err.config = { headers: { Authorization: "Bearer super-secret" } }; + err.request = { _header: "Authorization: Bearer super-secret" }; + err.response = { status: 401, data: { token: "super-secret" } }; + + const out = serializeError(err); + assert.equal(out.message, "Request failed with status code 401"); + assert.ok(out.stack); + assert.equal(out.status, 401); + assert.equal(out.config, undefined); + assert.equal(out.request, undefined); + assert.equal(out.response, undefined); + assert.doesNotMatch(JSON.stringify(out), /super-secret/); +}); + +test("errorMap flattens named failures to messages", () => { + const errors = new Map([ + ["aws", new Error("denied")], + ["slack", new Error("rate limited")], + ]); + assert.deepEqual(errorMap(errors), { aws: "denied", slack: "rate limited" }); +}); + +test("a request gets an id header, and the id is passed along", () => { + const req = { method: "GET", baseUrl: "/api", route: { path: "/teams/:teamId" }, session: {} }; + const res = new EventEmitter(); + res.statusCode = 200; + const headers = {}; + res.setHeader = (k, v) => (headers[k] = v); + + let called = false; + requestLogger(req, res, () => { + called = true; + }); + assert.ok(called, "next() must be called"); + assert.match(req.id, /^[0-9a-f-]{36}$/); + assert.equal(headers["X-Request-Id"], req.id); + + /* Finishing must not throw even with no session user. */ + res.emit("finish"); +}); + +test("credentials are redacted at the top level and one level down", () => { + let line = ""; + const log = pino({ redact: REDACT }, { write: (chunk) => (line += chunk) }); + log.info({ password: "hunter2", token: "t0p", user: { secret: "s3", refreshToken: "r3" } }); + assert.doesNotMatch(line, /hunter2|t0p|s3|r3/); + assert.match(line, /\[redacted\]/); +});