Implement structured logging for API routes (P3.7)

Replace console.error with pino structured logger across API routes
and add key event logging 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

Files updated:
- auth-middleware.ts: Added structured logging for auth failures
- cycle/period/route.ts: Added Period logged event + error logging
- calendar/[userId]/[token].ics/route.ts: Replaced console.error
- overrides/route.ts: Added Override toggled events
- today/route.ts: Added Decision calculated event

Tests: 720 passing (added 3 new structured logging tests)

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>

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
+### P3.7: Error Handling Improvements ✅ COMPLETE
-- [ ] Add consistent error responses across all API routes
+- [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
+  - `src/lib/auth-middleware.ts` - Replaced console.error with structured logger, added auth failure logging
-- **Why:** Better debugging and user experience
+  - `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)
 

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
+    logger.error({ err: error, userId }, "Calendar feed error");
-    console.error("Calendar feed error:", error);
     return NextResponse.json(
       { error: "Internal server error" },
       { status: 500 },

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 },

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 });
 });

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);
 

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<typeof vi.fn>;
+  error: ReturnType<typeof vi.fn>;
+  info: ReturnType<typeof vi.fn>;
+};
+
 const mockCookies = cookies as ReturnType<typeof vi.fn>;
 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"),
+      );
+    });
+  });
 });

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<T = unknown>(
 
       // 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 },