diff --git a/IMPLEMENTATION_PLAN.md b/IMPLEMENTATION_PLAN.md index 25db5da..107e019 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: 717 tests passing across 40 test files +### Overall Status: 720 tests passing across 40 test files ### Library Implementation | File | Status | Gap Analysis | @@ -17,7 +17,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta | `decision-engine.ts` | **COMPLETE** | 8 priority rules + override handling with `getDecisionWithOverrides()`, 24 tests | | `garmin.ts` | **COMPLETE** | 33 tests covering fetchGarminData, fetchHrvStatus, fetchBodyBattery, fetchIntensityMinutes, isTokenExpired, daysUntilExpiry, error handling, token validation | | `pocketbase.ts` | **COMPLETE** | 9 tests covering `createPocketBaseClient()`, `isAuthenticated()`, `getCurrentUser()`, `loadAuthFromCookies()` | -| `auth-middleware.ts` | **COMPLETE** | 6 tests covering `withAuth()` wrapper for API route protection | +| `auth-middleware.ts` | **COMPLETE** | 9 tests covering `withAuth()` wrapper for API route protection, structured logging for auth failures | | `middleware.ts` (Next.js) | **COMPLETE** | 12 tests covering page protection, redirects to login | | `logger.ts` | **COMPLETE** | 16 tests covering JSON output, log levels, error stack traces, child loggers | | `metrics.ts` | **COMPLETE** | 33 tests covering metrics collection, counters, gauges, histograms, Prometheus format | @@ -80,7 +80,7 @@ This file is maintained by Ralph. Run `./ralph-sandbox.sh plan 3` to generate ta | `src/lib/cycle.test.ts` | **EXISTS** - 9 tests | | `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/auth-middleware.test.ts` | **EXISTS** - 9 tests (withAuth wrapper, error handling, structured logging) | | `src/lib/logger.test.ts` | **EXISTS** - 16 tests (JSON format, log levels, error serialization, child loggers) | | `src/lib/metrics.test.ts` | **EXISTS** - 18 tests (metrics collection, counters, gauges, histograms, Prometheus format) | | `src/middleware.test.ts` | **EXISTS** - 12 tests (page protection, public routes, static assets) | @@ -625,11 +625,25 @@ Testing, error handling, and refinements. - Response parsing for biometric data structures - **Why:** External API integration robustness is now fully tested -### P3.7: Error Handling Improvements -- [ ] Add consistent error responses across all API routes +### P3.7: Error Handling Improvements ✅ COMPLETE +- [x] Add consistent error responses across all API routes +- [x] Replace console.error with structured pino logger +- [x] Add logging for key events per observability spec - **Files:** - - All route files - Standardize error format, add logging -- **Why:** Better debugging and user experience + - `src/lib/auth-middleware.ts` - Replaced console.error with structured logger, added auth failure logging + - `src/app/api/cycle/period/route.ts` - Added "Period logged" event logging, structured error logging + - `src/app/api/calendar/[userId]/[token].ics/route.ts` - Replaced console.error with structured logger + - `src/app/api/overrides/route.ts` - Added "Override toggled" event logging + - `src/app/api/today/route.ts` - Added "Decision calculated" event logging +- **Tests:** + - `src/lib/auth-middleware.test.ts` - Added 3 tests for structured logging (9 total) +- **Events Logged (per observability spec):** + - Auth failure (warn): reason + - Period logged (info): userId, date + - Override toggled (info): userId, override, enabled + - Decision calculated (info): userId, decision, reason + - Error events (error): err object with stack trace +- **Why:** Better debugging and user experience with structured JSON logs ### P3.8: Loading States - [ ] Add loading indicators to all pages @@ -798,7 +812,6 @@ P4.* UX Polish ────────> After core functionality complete | Priority | Task | Effort | Notes | |----------|------|--------|-------| -| Low | P3.7 Error Handling | Small | Polish | | Low | P3.8 Loading States | Small | Polish | | Low | P4.* UX Polish | Various | After core complete | @@ -877,6 +890,7 @@ P4.* UX Polish ────────> After core functionality complete - [x] **P3.4: ICS Tests** - Complete with 23 tests covering ICS format validation, 90-day event generation, timezone handling - [x] **P3.5: Encryption Tests** - Complete with 14 tests covering AES-256-GCM round-trip, error handling, key validation - [x] **P3.6: Garmin Tests** - Complete with 33 tests covering API interactions, token expiry, error handling +- [x] **P3.7: Error Handling Improvements** - Replaced console.error with structured pino logger across API routes, added key event logging (Period logged, Override toggled, Decision calculated, Auth failure), 3 new tests in auth-middleware.test.ts - [x] **P3.9: Token Expiration Warnings** - Complete with 10 new tests in email.test.ts, 10 new tests in garmin-sync/route.test.ts; sends warnings at 14 and 7 days before expiry - [x] **P3.11: Missing Component Tests** - Complete with 82 tests across 5 component test files (DecisionCard: 11, DataPanel: 18, NutritionPanel: 12, OverrideToggles: 18, DayCell: 23) diff --git a/src/app/api/calendar/[userId]/[token].ics/route.ts b/src/app/api/calendar/[userId]/[token].ics/route.ts index 4437959..a6c29f8 100644 --- a/src/app/api/calendar/[userId]/[token].ics/route.ts +++ b/src/app/api/calendar/[userId]/[token].ics/route.ts @@ -3,6 +3,7 @@ import { type NextRequest, NextResponse } from "next/server"; import { generateIcsFeed } from "@/lib/ics"; +import { logger } from "@/lib/logger"; import { createPocketBaseClient } from "@/lib/pocketbase"; interface RouteParams { @@ -61,8 +62,7 @@ export async function GET(_request: NextRequest, { params }: RouteParams) { return NextResponse.json({ error: "User not found" }, { status: 404 }); } - // Re-throw unexpected errors - console.error("Calendar feed error:", error); + logger.error({ err: error, userId }, "Calendar feed error"); return NextResponse.json( { error: "Internal server error" }, { status: 500 }, diff --git a/src/app/api/cycle/period/route.ts b/src/app/api/cycle/period/route.ts index 18fd27b..fca6eaf 100644 --- a/src/app/api/cycle/period/route.ts +++ b/src/app/api/cycle/period/route.ts @@ -5,6 +5,7 @@ import { NextResponse } from "next/server"; import { withAuth } from "@/lib/auth-middleware"; import { getCycleDay, getPhase } from "@/lib/cycle"; +import { logger } from "@/lib/logger"; import { createPocketBaseClient } from "@/lib/pocketbase"; interface PeriodLogRequest { @@ -80,6 +81,9 @@ export const POST = withAuth(async (request: NextRequest, user) => { const cycleDay = getCycleDay(lastPeriodDate, user.cycleLength, new Date()); const phase = getPhase(cycleDay); + // Log successful period logging per observability spec + logger.info({ userId: user.id, date: body.startDate }, "Period logged"); + return NextResponse.json({ message: "Period start date logged successfully", lastPeriodDate: body.startDate, @@ -87,7 +91,7 @@ export const POST = withAuth(async (request: NextRequest, user) => { phase, }); } catch (error) { - console.error("Period logging error:", error); + logger.error({ err: error, userId: user.id }, "Period logging error"); return NextResponse.json( { error: "Failed to update period date" }, { status: 500 }, diff --git a/src/app/api/overrides/route.ts b/src/app/api/overrides/route.ts index e12915f..0af9f49 100644 --- a/src/app/api/overrides/route.ts +++ b/src/app/api/overrides/route.ts @@ -4,6 +4,7 @@ import type { NextRequest } from "next/server"; import { NextResponse } from "next/server"; import { withAuth } from "@/lib/auth-middleware"; +import { logger } from "@/lib/logger"; import { createPocketBaseClient } from "@/lib/pocketbase"; import type { OverrideType } from "@/types"; @@ -59,6 +60,12 @@ export const POST = withAuth(async (request: NextRequest, user) => { .collection("users") .update(user.id, { activeOverrides: newOverrides }); + // Log override toggle per observability spec + logger.info( + { userId: user.id, override: overrideToAdd, enabled: true }, + "Override toggled", + ); + return NextResponse.json({ activeOverrides: newOverrides }); }); @@ -98,5 +105,11 @@ export const DELETE = withAuth(async (request: NextRequest, user) => { .collection("users") .update(user.id, { activeOverrides: newOverrides }); + // Log override toggle per observability spec + logger.info( + { userId: user.id, override: overrideToRemove, enabled: false }, + "Override toggled", + ); + return NextResponse.json({ activeOverrides: newOverrides }); }); diff --git a/src/app/api/today/route.ts b/src/app/api/today/route.ts index 0c05e0c..b37e0fe 100644 --- a/src/app/api/today/route.ts +++ b/src/app/api/today/route.ts @@ -11,6 +11,7 @@ import { PHASE_CONFIGS, } from "@/lib/cycle"; import { getDecisionWithOverrides } from "@/lib/decision-engine"; +import { logger } from "@/lib/logger"; import { getNutritionGuidance } from "@/lib/nutrition"; import { createPocketBaseClient } from "@/lib/pocketbase"; import type { DailyData, DailyLog, HrvStatus } from "@/types"; @@ -99,6 +100,12 @@ export const GET = withAuth(async (_request, user) => { // Get training decision with override handling const decision = getDecisionWithOverrides(dailyData, user.activeOverrides); + // Log decision calculation per observability spec + logger.info( + { userId: user.id, decision: decision.status, reason: decision.reason }, + "Decision calculated", + ); + // Get nutrition guidance const nutrition = getNutritionGuidance(cycleDay); diff --git a/src/lib/auth-middleware.test.ts b/src/lib/auth-middleware.test.ts index 3274040..7655a67 100644 --- a/src/lib/auth-middleware.test.ts +++ b/src/lib/auth-middleware.test.ts @@ -18,7 +18,17 @@ vi.mock("next/headers", () => ({ cookies: vi.fn(), })); +// Mock the logger module +vi.mock("./logger", () => ({ + logger: { + warn: vi.fn(), + error: vi.fn(), + info: vi.fn(), + }, +})); + import { cookies } from "next/headers"; +import { logger } from "./logger"; import { createPocketBaseClient, getCurrentUser, @@ -26,6 +36,12 @@ import { loadAuthFromCookies, } from "./pocketbase"; +const mockLogger = logger as { + warn: ReturnType; + error: ReturnType; + info: ReturnType; +}; + const mockCookies = cookies as ReturnType; const mockCreatePocketBaseClient = createPocketBaseClient as ReturnType< typeof vi.fn @@ -161,4 +177,59 @@ describe("withAuth", () => { const body = await response.json(); expect(body.error).toBe("Internal server error"); }); + + describe("structured logging", () => { + beforeEach(() => { + mockLogger.warn.mockClear(); + mockLogger.error.mockClear(); + mockLogger.info.mockClear(); + }); + + it("logs auth failure with warn level", async () => { + mockIsAuthenticated.mockReturnValue(false); + + const handler = vi.fn(); + const wrappedHandler = withAuth(handler); + + await wrappedHandler({} as NextRequest); + + expect(mockLogger.warn).toHaveBeenCalledWith( + expect.objectContaining({ reason: "not_authenticated" }), + expect.stringContaining("Auth failure"), + ); + }); + + it("logs auth failure when getCurrentUser returns null", async () => { + mockIsAuthenticated.mockReturnValue(true); + mockGetCurrentUser.mockReturnValue(null); + + const handler = vi.fn(); + const wrappedHandler = withAuth(handler); + + await wrappedHandler({} as NextRequest); + + expect(mockLogger.warn).toHaveBeenCalledWith( + expect.objectContaining({ reason: "user_not_found" }), + expect.stringContaining("Auth failure"), + ); + }); + + it("logs internal errors with error level and stack trace", async () => { + mockIsAuthenticated.mockReturnValue(true); + mockGetCurrentUser.mockReturnValue(mockUser); + + const testError = new Error("Handler error"); + const handler = vi.fn().mockRejectedValue(testError); + const wrappedHandler = withAuth(handler); + + await wrappedHandler({} as NextRequest); + + expect(mockLogger.error).toHaveBeenCalledWith( + expect.objectContaining({ + err: testError, + }), + expect.stringContaining("Auth middleware error"), + ); + }); + }); }); diff --git a/src/lib/auth-middleware.ts b/src/lib/auth-middleware.ts index 76e3b58..251af17 100644 --- a/src/lib/auth-middleware.ts +++ b/src/lib/auth-middleware.ts @@ -7,6 +7,7 @@ import { NextResponse } from "next/server"; import type { User } from "@/types"; +import { logger } from "./logger"; import { createPocketBaseClient, getCurrentUser, @@ -54,19 +55,21 @@ export function withAuth( // Check if the user is authenticated if (!isAuthenticated(pb)) { + logger.warn({ reason: "not_authenticated" }, "Auth failure"); return NextResponse.json({ error: "Unauthorized" }, { status: 401 }); } // Get the current user const user = getCurrentUser(pb); if (!user) { + logger.warn({ reason: "user_not_found" }, "Auth failure"); return NextResponse.json({ error: "Unauthorized" }, { status: 401 }); } // Call the original handler with the user context return await handler(request, user, context); } catch (error) { - console.error("Auth middleware error:", error); + logger.error({ err: error }, "Auth middleware error"); return NextResponse.json( { error: "Internal server error" }, { status: 500 },