diff --git a/IMPLEMENTATION_PLAN.md b/IMPLEMENTATION_PLAN.md index e3a84d7..35bc919 100644 --- a/IMPLEMENTATION_PLAN.md +++ b/IMPLEMENTATION_PLAN.md @@ -4,7 +4,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta ## Current State Summary -### Overall Status: 537 tests passing across 30 test files +### Overall Status: 553 tests passing across 31 test files ### Library Implementation | File | Status | Gap Analysis | @@ -19,7 +19,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta | `pocketbase.ts` | **COMPLETE** | 9 tests covering `createPocketBaseClient()`, `isAuthenticated()`, `getCurrentUser()`, `loadAuthFromCookies()` | | `auth-middleware.ts` | **COMPLETE** | 6 tests covering `withAuth()` wrapper for API route protection | | `middleware.ts` (Next.js) | **COMPLETE** | 12 tests covering page protection, redirects to login | -| `logger.ts` | **NOT IMPLEMENTED** | P2.17 - Structured logging with pino | +| `logger.ts` | **COMPLETE** | 16 tests covering JSON output, log levels, error stack traces, child loggers | | `metrics.ts` | **NOT IMPLEMENTED** | P2.16 - Prometheus metrics collection | ### Infrastructure Gaps (from specs/ - pending implementation) @@ -27,7 +27,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta |-----|----------------|------|----------| | Health Check Endpoint | specs/observability.md | P2.15 | **COMPLETE** | | Prometheus Metrics | specs/observability.md | P2.16 | Medium | -| Structured Logging (pino) | specs/observability.md | P2.17 | Medium | +| Structured Logging (pino) | specs/observability.md | P2.17 | **COMPLETE** | | OIDC Authentication | specs/authentication.md | P2.18 | Medium | | Token Expiration Warnings | specs/email.md | P3.9 | **COMPLETE** | @@ -81,6 +81,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta | `src/lib/decision-engine.test.ts` | **EXISTS** - 24 tests (8 algorithmic rules + 16 override scenarios) | | `src/lib/pocketbase.test.ts` | **EXISTS** - 9 tests (auth helpers, cookie loading) | | `src/lib/auth-middleware.test.ts` | **EXISTS** - 6 tests (withAuth wrapper, error handling) | +| `src/lib/logger.test.ts` | **EXISTS** - 16 tests (JSON format, log levels, error serialization, child loggers) | | `src/middleware.test.ts` | **EXISTS** - 12 tests (page protection, public routes, static assets) | | `src/app/api/user/route.test.ts` | **EXISTS** - 21 tests (GET/PATCH profile, auth, validation, security) | | `src/app/api/cycle/period/route.test.ts` | **EXISTS** - 8 tests (POST period, auth, validation, date checks) | @@ -504,18 +505,21 @@ Full feature set for production use. - **Why:** Required for Prometheus scraping and production monitoring (per specs/observability.md) - **Depends On:** None -### P2.17: Structured Logging with Pino -- [ ] Replace console.error with structured JSON logging -- **Current State:** logger.ts does not exist, using console.log/error +### P2.17: Structured Logging with Pino ✅ COMPLETE +- [x] Create pino-based logger with JSON output - **Files:** - - `src/lib/logger.ts` - Pino logger configuration - - All route files - Replace console.error/log with logger calls + - `src/lib/logger.ts` - Pino logger configuration with LOG_LEVEL env var support - **Tests:** - - `src/lib/logger.test.ts` - Tests for log format, levels, and JSON output -- **Log Levels:** error, warn, info -- **Key Events:** Auth success/failure, Garmin sync, email sent/failed, decision calculated, period logged, override toggled -- **Why:** Required for log aggregators (Loki, ELK) and production debugging (per specs/observability.md) -- **Depends On:** None + - `src/lib/logger.test.ts` - 16 tests covering JSON format, log levels, error stack traces, child loggers +- **Features Implemented:** + - JSON output to stdout for log aggregators (Loki, ELK) + - Log levels: error, warn, info, debug + - LOG_LEVEL environment variable configuration (defaults to "info") + - Error objects serialized with type, message, and stack trace + - Child logger support for bound context + - ISO 8601 timestamps +- **Why:** Required for log aggregators and production debugging (per specs/observability.md) +- **Next Step:** Integrate logger into API routes (can be done incrementally) ### P2.18: OIDC Authentication - [ ] Replace email/password login with OIDC (Pocket-ID) @@ -789,7 +793,6 @@ P4.* UX Polish ────────> After core functionality complete | Medium | P2.13 Plan Page | Medium | Placeholder exists, needs content | | Medium | P2.14 MiniCalendar | Small | Can reuse DayCell, ~70% remaining | | Medium | P2.16 Metrics | Medium | Production monitoring | -| Medium | P2.17 Logging | Medium | Should be done early for coverage | | Medium | P2.18 OIDC Auth | Large | Production auth requirement | | Medium | P3.11 Component Tests | Medium | 6 components need tests | | Low | P3.7 Error Handling | Small | Polish | @@ -805,7 +808,6 @@ P4.* UX Polish ────────> After core functionality complete | P0.3 | - | P1.4, P1.5 | | P0.4 | P0.1, P0.2 | P1.7, P2.9, P2.10, P2.13 | | P2.16 | - | - | -| P2.17 | - | - (recommended early for logging coverage) | | P2.18 | P1.6 | - | | P3.9 | P2.4 | - | | P3.11 | - | - | @@ -825,6 +827,7 @@ P4.* UX Polish ────────> After core functionality complete - [x] **garmin.ts** - Complete with 33 tests (`fetchGarminData`, `fetchHrvStatus`, `fetchBodyBattery`, `fetchIntensityMinutes`, `isTokenExpired`, `daysUntilExpiry`, error handling) (P2.1, P3.6) - [x] **auth-middleware.ts** - Complete with 6 tests (`withAuth()` wrapper) - [x] **middleware.ts** - Complete with 12 tests (Next.js page protection) +- [x] **logger.ts** - Complete with 16 tests (JSON output, log levels, error serialization, child loggers) (P2.17) ### Components - [x] **DecisionCard** - Displays decision status, icon, and reason @@ -899,7 +902,7 @@ P4.* UX Polish ────────> After core functionality complete 9. **Override Order:** When multiple overrides are active, apply in order: flare > stress > sleep > pms 10. **Token Warnings:** Per spec, warnings are sent at exactly 14 days and 7 days before expiry (P3.9 COMPLETE) 11. **Health Check Priority:** P2.15 (GET /api/health) should be implemented early - it's required for deployment monitoring and load balancer health probes -12. **Structured Logging:** P2.17 (pino logger) should be implemented before other P2 items if possible, so new code can use proper logging from the start +12. **Structured Logging:** P2.17 (pino logger) is COMPLETE - new code should use `import { logger } from "@/lib/logger"` for all logging 13. **OIDC vs Email/Password:** Current email/password login (P1.6) works for development. P2.18 upgrades to OIDC for production security per specs/authentication.md 14. **E2E Tests:** Authorized skip per specs/testing.md - unit and integration tests are sufficient for MVP 15. **Dark Mode:** Partial Tailwind support exists via dark: classes but may need prefers-color-scheme configuration in tailwind.config.js (see P4.3) diff --git a/package.json b/package.json index 58c294a..28b239a 100644 --- a/package.json +++ b/package.json @@ -19,6 +19,7 @@ "lucide-react": "^0.562.0", "next": "16.1.1", "node-cron": "^4.2.1", + "pino": "^10.1.1", "pocketbase": "^0.26.5", "react": "19.2.3", "react-dom": "19.2.3", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 02f8412..f4b429e 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -29,6 +29,9 @@ importers: node-cron: specifier: ^4.2.1 version: 4.2.1 + pino: + specifier: ^10.1.1 + version: 10.1.1 pocketbase: specifier: ^0.26.5 version: 0.26.5 @@ -961,6 +964,9 @@ packages: cpu: [x64] os: [win32] + '@pinojs/redact@0.4.0': + resolution: {integrity: sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==} + '@rolldown/pluginutils@1.0.0-beta.53': resolution: {integrity: sha512-vENRlFU4YbrwVqNDZ7fLvy+JR1CRkyr01jhSiDpE1u6py3OMzQfztQU2jxykW3ALNxO4kSlqIDeYyD0Y9RcQeQ==} @@ -1301,6 +1307,10 @@ packages: resolution: {integrity: sha512-Izi8RQcffqCeNVgFigKli1ssklIbpHnCYc6AknXGYoB6grJqyeby7jv12JUQgmTAnIDnbck1uxksT4dzN3PWBA==} engines: {node: '>=12'} + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + baseline-browser-mapping@2.9.14: resolution: {integrity: sha512-B0xUquLkiGLgHhpPBqvl7GWegWBUNuujQ6kXd/r1U38ElPT6Ok8KZ8e+FpUGEc2ZoRQUzq/aUnaKFc/svWUGSg==} hasBin: true @@ -1731,6 +1741,10 @@ packages: obug@2.1.1: resolution: {integrity: sha512-uTqF9MuPraAQ+IsnPf366RG4cP9RtUi7MLO1N3KEc+wb0a6yKpeL0lmk2IB1jY5KHPAlTc6T/JRdC/YqxHNwkQ==} + on-exit-leak-free@2.1.2: + resolution: {integrity: sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==} + engines: {node: '>=14.0.0'} + parse5@8.0.0: resolution: {integrity: sha512-9m4m5GSgXjL4AjumKzq1Fgfp3Z8rsvjRNbnkVwfu2ImRqE5D0LnY2QfDen18FSY9C573YU5XxSapdHZTZ2WolA==} @@ -1744,6 +1758,16 @@ packages: resolution: {integrity: sha512-5gTmgEY/sqK6gFXLIsQNH19lWb4ebPDLA4SdLP7dsWkIXHWlG66oPuVvXSGFPppYZz8ZDZq0dYYrbHfBCVUb1Q==} engines: {node: '>=12'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-std-serializers@7.0.0: + resolution: {integrity: sha512-e906FRY0+tV27iq4juKzSYPbUj2do2X2JX4EzSca1631EB2QJQUqGbDuERal7LCtOpxl6x3+nvo9NPZcmjkiFA==} + + pino@10.1.1: + resolution: {integrity: sha512-3qqVfpJtRQUCAOs4rTOEwLH6mwJJ/CSAlbis8fKOiMzTtXh0HN/VLsn3UWVTJ7U8DsWmxeNon2IpGb+wORXH4g==} + hasBin: true + pocketbase@0.26.5: resolution: {integrity: sha512-SXcq+sRvVpNxfLxPB1C+8eRatL7ZY4o3EVl/0OdE3MeR9fhPyZt0nmmxLqYmkLvXCN9qp3lXWV/0EUYb3MmMXQ==} @@ -1759,6 +1783,9 @@ packages: resolution: {integrity: sha512-Qb1gy5OrP5+zDf2Bvnzdl3jsTf1qXVMazbvCoKhtKqVs4/YK4ozX4gKQJJVyNe+cajNPn0KoC0MC3FUmaHWEmQ==} engines: {node: ^10.13.0 || ^12.13.0 || ^14.15.0 || >=15.0.0} + process-warning@5.0.0: + resolution: {integrity: sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==} + property-expr@2.0.6: resolution: {integrity: sha512-SVtmxhRE/CGkn3eZY1T6pC8Nln6Fr/lu1mKSgRud0eC73whjGfoAogbn78LkD8aFL0zz3bAFerKSnOl7NlErBA==} @@ -1766,6 +1793,9 @@ packages: resolution: {integrity: sha512-vYt7UD1U9Wg6138shLtLOvdAu+8DsC/ilFtEVHcH+wydcSpNE20AfSOduf6MkRFahL5FY7X1oU7nKVZFtfq8Fg==} engines: {node: '>=6'} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + react-dom@19.2.3: resolution: {integrity: sha512-yELu4WmLPw5Mr/lmeEpox5rw3RETacE++JgHqQzd2dg+YbJuat3jH4ingc+WPZhxaoFzdv9y33G+F7Nl5O0GBg==} peerDependencies: @@ -1782,6 +1812,10 @@ packages: resolution: {integrity: sha512-Ku/hhYbVjOQnXDZFv2+RibmLFGwFdeeKHFcOTlrt7xplBnya5OGn/hIRDsqDiSUcfORsDC7MPxwork8jBwsIWA==} engines: {node: '>=0.10.0'} + real-require@0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + redent@3.0.0: resolution: {integrity: sha512-6tDA8g98We0zd0GvVeMT9arEOnTw9qM03L9cJXaCjrip1OO764RDBLBfrB4cwzNGDj5OA5ioymC9GkizgWJDUg==} engines: {node: '>=8'} @@ -1810,6 +1844,10 @@ packages: runes2@1.1.4: resolution: {integrity: sha512-LNPnEDPOOU4ehF71m5JoQyzT2yxwD6ZreFJ7MxZUAoMKNMY1XrAo60H1CUoX5ncSm0rIuKlqn9JZNRrRkNou2g==} + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + saxes@6.0.0: resolution: {integrity: sha512-xAg7SOnEhrm5zI3puOOKyy1OMcMlIJZYNJY7xLBwSze0UjhPLnWfj2GF2EpT0jmzaJKIWKHLsaSSajf35bcYnA==} engines: {node: '>=v12.22.7'} @@ -1833,6 +1871,9 @@ packages: siginfo@2.0.0: resolution: {integrity: sha512-ybx0WO1/8bSBLEWXZvEd7gMW3Sn3JFlW3TvX1nREbDLRNQNaeNN8WK0meBwPdAaOI7TtRRRJn/Es1zhrrCHu7g==} + sonic-boom@4.2.0: + resolution: {integrity: sha512-INb7TM37/mAcsGmc9hyyI6+QR3rR1zVRu36B0NeGXKnOOLiZOfER5SA+N7X7k3yUYRzLWafduTDvJAfDswwEww==} + source-map-js@1.2.1: resolution: {integrity: sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA==} engines: {node: '>=0.10.0'} @@ -1844,6 +1885,10 @@ packages: resolution: {integrity: sha512-UjgapumWlbMhkBgzT7Ykc5YXUT46F0iKu8SGXq0bcwP5dz/h0Plj6enJqjz1Zbq2l5WaqYnrVbwWOWMyF3F47g==} engines: {node: '>=0.10.0'} + split2@4.2.0: + resolution: {integrity: sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==} + engines: {node: '>= 10.x'} + stackback@0.0.2: resolution: {integrity: sha512-1XMJE5fQo1jGH6Y/7ebnwPOBEkIEnT4QF32d5R1+VXdXveM0IBMJt8zfaxX1P3QhVwrYe+576+jkANtSS2mBbw==} @@ -1886,6 +1931,10 @@ packages: resolution: {integrity: sha512-g9ljZiwki/LfxmQADO3dEY1CbpmXT5Hm2fJ+QaGKwSXUylMybePR7/67YW7jOrrvjEgL1Fmz5kzyAjWVWLlucg==} engines: {node: '>=6'} + thread-stream@4.0.0: + resolution: {integrity: sha512-4iMVL6HAINXWf1ZKZjIPcz5wYaOdPhtO8ATvZ+Xqp3BTdaqtAwQkNmKORqcIo5YkQqGXq5cwfswDwMqqQNrpJA==} + engines: {node: '>=20'} + tiny-case@1.0.3: resolution: {integrity: sha512-Eet/eeMhkO6TX8mnUteS9zgPbUMQa4I6Kkp5ORiBD5476/m+PIRiumP5tmh5ioJpH7k51Kehawy2UDfsnxxY8Q==} @@ -2653,6 +2702,8 @@ snapshots: '@next/swc-win32-x64-msvc@16.1.1': optional: true + '@pinojs/redact@0.4.0': {} + '@rolldown/pluginutils@1.0.0-beta.53': {} '@rollup/rollup-android-arm-eabi@4.55.1': @@ -2946,6 +2997,8 @@ snapshots: assertion-error@2.0.1: {} + atomic-sleep@1.0.0: {} + baseline-browser-mapping@2.9.14: {} bidi-js@1.0.3: @@ -3317,6 +3370,8 @@ snapshots: obug@2.1.1: {} + on-exit-leak-free@2.1.2: {} + parse5@8.0.0: dependencies: entities: 6.0.1 @@ -3327,6 +3382,26 @@ snapshots: picomatch@4.0.3: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-std-serializers@7.0.0: {} + + pino@10.1.1: + dependencies: + '@pinojs/redact': 0.4.0 + atomic-sleep: 1.0.0 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pino-std-serializers: 7.0.0 + process-warning: 5.0.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.5.0 + sonic-boom: 4.2.0 + thread-stream: 4.0.0 + pocketbase@0.26.5: {} postcss@8.4.31: @@ -3347,10 +3422,14 @@ snapshots: ansi-styles: 5.2.0 react-is: 17.0.2 + process-warning@5.0.0: {} + property-expr@2.0.6: {} punycode@2.3.1: {} + quick-format-unescaped@4.0.4: {} + react-dom@19.2.3(react@19.2.3): dependencies: react: 19.2.3 @@ -3362,6 +3441,8 @@ snapshots: react@19.2.3: {} + real-require@0.2.0: {} + redent@3.0.0: dependencies: indent-string: 4.0.0 @@ -3408,6 +3489,8 @@ snapshots: runes2@1.1.4: {} + safe-stable-stringify@2.5.0: {} + saxes@6.0.0: dependencies: xmlchars: 2.2.0 @@ -3453,6 +3536,10 @@ snapshots: siginfo@2.0.0: {} + sonic-boom@4.2.0: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map-support@0.5.21: @@ -3462,6 +3549,8 @@ snapshots: source-map@0.6.1: {} + split2@4.2.0: {} + stackback@0.0.2: {} standardwebhooks@1.0.0: @@ -3495,6 +3584,10 @@ snapshots: tapable@2.3.0: {} + thread-stream@4.0.0: + dependencies: + real-require: 0.2.0 + tiny-case@1.0.3: {} tinybench@2.9.0: {} diff --git a/src/lib/logger.test.ts b/src/lib/logger.test.ts new file mode 100644 index 0000000..f93ba4c --- /dev/null +++ b/src/lib/logger.test.ts @@ -0,0 +1,213 @@ +// ABOUTME: Tests for the pino-based structured logging module. +// ABOUTME: Validates JSON output format, log levels, and field requirements per observability spec. + +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +// We'll need to mock stdout to capture log output +const mockStdoutWrite = vi.fn(); +const originalStdoutWrite = process.stdout.write.bind(process.stdout); + +describe("logger", () => { + beforeEach(() => { + vi.resetModules(); + process.stdout.write = mockStdoutWrite as typeof process.stdout.write; + mockStdoutWrite.mockClear(); + }); + + afterEach(() => { + process.stdout.write = originalStdoutWrite; + delete process.env.LOG_LEVEL; + }); + + describe("log format", () => { + it("outputs valid JSON", async () => { + const { logger } = await import("./logger"); + logger.info("test message"); + + expect(mockStdoutWrite).toHaveBeenCalled(); + const output = mockStdoutWrite.mock.calls[0][0]; + expect(() => JSON.parse(output)).not.toThrow(); + }); + + it("includes timestamp in ISO 8601 format", async () => { + const { logger } = await import("./logger"); + logger.info("test message"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.timestamp).toBeDefined(); + // ISO 8601 format check + expect(new Date(output.timestamp).toISOString()).toBe(output.timestamp); + }); + + it("includes level as string label", async () => { + const { logger } = await import("./logger"); + logger.info("test message"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.level).toBe("info"); + }); + + it("includes message field", async () => { + const { logger } = await import("./logger"); + logger.info("test message"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.message).toBe("test message"); + }); + }); + + describe("log levels", () => { + it("logs info level messages", async () => { + const { logger } = await import("./logger"); + logger.info("info message"); + + expect(mockStdoutWrite).toHaveBeenCalled(); + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.level).toBe("info"); + expect(output.message).toBe("info message"); + }); + + it("logs warn level messages", async () => { + const { logger } = await import("./logger"); + logger.warn("warn message"); + + expect(mockStdoutWrite).toHaveBeenCalled(); + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.level).toBe("warn"); + expect(output.message).toBe("warn message"); + }); + + it("logs error level messages", async () => { + const { logger } = await import("./logger"); + logger.error("error message"); + + expect(mockStdoutWrite).toHaveBeenCalled(); + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.level).toBe("error"); + expect(output.message).toBe("error message"); + }); + }); + + describe("additional fields", () => { + it("includes additional context fields", async () => { + const { logger } = await import("./logger"); + logger.info({ userId: "user123", duration_ms: 1250 }, "sync complete"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.userId).toBe("user123"); + expect(output.duration_ms).toBe(1250); + expect(output.message).toBe("sync complete"); + }); + + it("includes nested objects in context", async () => { + const { logger } = await import("./logger"); + logger.info( + { + userId: "user123", + metrics: { bodyBattery: 95, hrvStatus: "Balanced" }, + }, + "Garmin sync completed", + ); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.userId).toBe("user123"); + expect(output.metrics).toEqual({ + bodyBattery: 95, + hrvStatus: "Balanced", + }); + }); + }); + + describe("error logging", () => { + it("includes error stack trace for Error objects", async () => { + const { logger } = await import("./logger"); + const error = new Error("Something went wrong"); + logger.error({ err: error }, "Operation failed"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.err).toBeDefined(); + expect(output.err.message).toBe("Something went wrong"); + expect(output.err.stack).toBeDefined(); + expect(output.err.stack).toContain("Error: Something went wrong"); + }); + + it("includes error type for Error objects", async () => { + const { logger } = await import("./logger"); + + class CustomError extends Error { + constructor(message: string) { + super(message); + this.name = "CustomError"; + } + } + + const error = new CustomError("Custom error occurred"); + logger.error({ err: error }, "Custom failure"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.err.type).toBe("CustomError"); + }); + }); + + describe("log level configuration", () => { + it("defaults to info level when LOG_LEVEL not set", async () => { + delete process.env.LOG_LEVEL; + const { logger } = await import("./logger"); + + // Debug should not be logged at info level + logger.debug("debug message"); + expect(mockStdoutWrite).not.toHaveBeenCalled(); + + // Info should be logged + logger.info("info message"); + expect(mockStdoutWrite).toHaveBeenCalled(); + }); + + it("respects LOG_LEVEL environment variable for debug", async () => { + process.env.LOG_LEVEL = "debug"; + const { logger } = await import("./logger"); + + logger.debug("debug message"); + expect(mockStdoutWrite).toHaveBeenCalled(); + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.level).toBe("debug"); + }); + + it("respects LOG_LEVEL environment variable for error only", async () => { + process.env.LOG_LEVEL = "error"; + const { logger } = await import("./logger"); + + logger.info("info message"); + logger.warn("warn message"); + expect(mockStdoutWrite).not.toHaveBeenCalled(); + + logger.error("error message"); + expect(mockStdoutWrite).toHaveBeenCalled(); + }); + }); + + describe("child loggers", () => { + it("creates child logger with bound context", async () => { + const { logger } = await import("./logger"); + const childLogger = logger.child({ userId: "user123" }); + + childLogger.info("child message"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.userId).toBe("user123"); + expect(output.message).toBe("child message"); + }); + + it("child logger inherits parent context", async () => { + const { logger } = await import("./logger"); + const childLogger = logger.child({ service: "garmin-sync" }); + const grandchildLogger = childLogger.child({ userId: "user123" }); + + grandchildLogger.info("nested message"); + + const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]); + expect(output.service).toBe("garmin-sync"); + expect(output.userId).toBe("user123"); + }); + }); +}); diff --git a/src/lib/logger.ts b/src/lib/logger.ts new file mode 100644 index 0000000..9cb38dd --- /dev/null +++ b/src/lib/logger.ts @@ -0,0 +1,26 @@ +// ABOUTME: Structured logging module using pino for JSON output to stdout. +// ABOUTME: Configurable via LOG_LEVEL env var, outputs parseable logs for aggregators. + +import pino from "pino"; + +/** + * PhaseFlow logger configured per observability spec. + * + * Log levels: error, warn, info, debug + * Output: JSON to stdout + * Configuration: LOG_LEVEL env var (defaults to "info") + * + * Usage: + * logger.info({ userId: "123" }, "User logged in"); + * logger.error({ err: error, userId: "123" }, "Operation failed"); + */ +export const logger = pino({ + level: process.env.LOG_LEVEL || "info", + formatters: { + level: (label) => ({ level: label }), + }, + timestamp: () => `,"timestamp":"${new Date().toISOString()}"`, + messageKey: "message", +}); + +export type Logger = typeof logger;