VIA-824 TS Logging improvements, adds logs of unauthenticated routes, adds HTTP method to middleware

src/app/api/auth/[...nextauth]/route.test.ts

@@ -1,6 +1,6 @@
 import { handlers } from "@project/auth";
 import { extractRequestContextFromHeadersAndCookies } from "@project/src/utils/requestScopedStorageWrapper";
-import { GET } from "@src/app/api/auth/[...nextauth]/route";
+import { GET, POST } from "@src/app/api/auth/[...nextauth]/route";
 import { logger } from "@src/utils/logger";
 import { NextRequest } from "next/server";
 
@@ -11,10 +11,6 @@ jest.mock("@project/auth", () => ({
   },
 }));
 
-jest.mock("@src/app/api/auth/[...nextauth]/provider", () => ({
-  NHS_LOGIN_PROVIDER_ID: "nhs-login",
-}));
-
 jest.mock("@src/utils/logger", () => ({
   logger: {
     child: jest.fn().mockReturnValue({
@@ -32,112 +28,160 @@ jest.mock("@project/src/utils/requestContext", () => ({
 
 jest.mock("@project/src/utils/requestScopedStorageWrapper");
 
-jest.mock("next/server", () => ({
-  NextRequest: jest.fn().mockImplementation((url: string, init?: RequestInit) => ({
-    url,
-    headers: init?.headers ?? new Headers(),
-  })),
+jest.mock("@src/utils/getHeadersForLogging", () => ({
+  getHeadersForLogging: jest.fn().mockReturnValue({ "mock-header": "mock-value" }),
 }));
 
-const buildMockRequest = (pathname: string, params?: Record<string, string>): NextRequest =>
+const buildMockGetRequest = (
+  pathname: string,
+  params?: Record<string, string>,
+  headers: Headers = new Headers(),
+): NextRequest =>
   ({
     method: "GET",
     nextUrl: {
       pathname,
       searchParams: new URLSearchParams(params),
     },
+    headers,
   }) as unknown as NextRequest;
 
-describe("GET", () => {
+describe("NextAuth API Route", () => {
   const mockLogError = (logger.child as jest.Mock).mock.results[0].value.error as jest.Mock;
   const mockLogInfo = (logger.child as jest.Mock).mock.results[0].value.info as jest.Mock;
   const mockResponse = { status: 200 } as Response;
-
   const mockContext = { sessionId: "test-session-id", traceId: "test-trace-id", nextUrl: "" };
 
   beforeEach(() => {
     (handlers.GET as jest.Mock).mockResolvedValue(mockResponse);
+    (handlers.POST as jest.Mock).mockResolvedValue(mockResponse);
     (extractRequestContextFromHeadersAndCookies as jest.Mock).mockReturnValueOnce(mockContext);
   });
 
-  it("should log the pathname on GET request with correct context", async () => {
-    const req = buildMockRequest("/api/auth/signin") as unknown as NextRequest;
-
-    await GET(req);
-
-    expect(mockLogInfo).toHaveBeenCalledWith(
-      {
-        context: { pathname: "/api/auth/signin" },
-        sessionId: "test-session-id",
-        traceId: "test-trace-id",
-        nextUrl: "/api/auth/signin",
-      },
-      "GET NextAuth route",
-    );
-  });
-
-  it("should delegate to nextAuth handlers.GET with the original request", async () => {
-    const req = buildMockRequest("/api/auth/callback/nhs-login") as unknown as NextRequest;
-
-    await GET(req);
-
-    expect(handlers.GET).toHaveBeenCalledWith(req);
-  });
-
-  describe("when the callback URL contains an OAuth error", () => {
-    it("should log the error and error_description", async () => {
-      const req = buildMockRequest("/api/auth/callback/nhs-login", {
-        error: "access_denied",
-        error_description: "User cancelled login",
-      }) as unknown as NextRequest;
+  describe("GET", () => {
+    it("should log the pathname on GET request with correct context", async () => {
+      const req = buildMockGetRequest("/api/auth/signin") as unknown as NextRequest;
 
       await GET(req);
 
-      expect(mockLogError).toHaveBeenCalledWith(
-        { error: "access_denied", error_description: "User cancelled login" },
-        "OAuth provider returned error in callback",
+      expect(mockLogInfo).toHaveBeenCalledWith(
         {
+          context: {
+            method: "GET",
+            pathname: "/api/auth/signin",
+            headers: { "mock-header": "mock-value" },
+          },
           sessionId: "test-session-id",
           traceId: "test-trace-id",
-          nextUrl: "/api/auth/callback/nhs-login",
+          nextUrl: "/api/auth/signin",
         },
+        "NextAuth route",
       );
     });
 
-    it("should log null when error_description is absent", async () => {
-      const req = buildMockRequest("/api/auth/callback/nhs-login", { error: "server_error" }) as unknown as NextRequest;
+    it("should delegate the request to nextAuth handlers.GET", async () => {
+      const req = buildMockGetRequest("/api/auth/callback/nhs-login") as unknown as NextRequest;
 
       await GET(req);
 
-      expect(mockLogError).toHaveBeenCalledWith(
-        { error: "server_error", error_description: null },
-        "OAuth provider returned error in callback",
+      expect(handlers.GET as jest.Mock).toHaveBeenCalledWith(req);
+    });
+
+    describe("when the callback URL is called", () => {
+      it("should log the error and error_description when present", async () => {
+        const req = buildMockGetRequest("/api/auth/callback/nhs-login", {
+          error: "access_denied",
+          error_description: "User cancelled login",
+        }) as unknown as NextRequest;
+
+        await GET(req);
+
+        expect(mockLogError).toHaveBeenCalledWith(
+          { error: "access_denied", error_description: "User cancelled login" },
+          "OAuth provider returned error in callback",
+          {
+            sessionId: "test-session-id",
+            traceId: "test-trace-id",
+            nextUrl: "/api/auth/callback/nhs-login",
+          },
+        );
+      });
+
+      it("should log null when error_description is absent", async () => {
+        const req = buildMockGetRequest("/api/auth/callback/nhs-login", {
+          error: "access_denied",
+        }) as unknown as NextRequest;
+
+        await GET(req);
+
+        expect(mockLogError).toHaveBeenCalledWith(
+          { error: "access_denied", error_description: null },
+          "OAuth provider returned error in callback",
+          {
+            sessionId: "test-session-id",
+            traceId: "test-trace-id",
+            nextUrl: "/api/auth/callback/nhs-login",
+          },
+        );
+      });
+
+      it("should carry on and delegate to handlers.GET when error not present", async () => {
+        const req = buildMockGetRequest("/api/auth/callback/nhs-login") as unknown as NextRequest;
+
+        await GET(req);
+
+        expect(handlers.GET as jest.Mock).toHaveBeenCalledWith(req);
+      });
+    });
+
+    describe("when a non-callback url is called", () => {
+      it("should not log an error even if an error param is present", async () => {
+        const req = buildMockGetRequest("/api/auth/signin", { error: "OAuthCallbackError" }) as unknown as NextRequest;
+
+        await GET(req);
+
+        expect(mockLogError).not.toHaveBeenCalled();
+      });
+    });
+  });
+
+  describe("POST", () => {
+    it("should log the pathname and method on POST request with correct context", async () => {
+      const req = {
+        method: "POST",
+        nextUrl: { pathname: "/api/auth/callback/nhs-login" },
+        headers: new Headers(),
+      } as unknown as NextRequest;
+
+      await POST(req);
+
+      expect(mockLogInfo).toHaveBeenCalledWith(
         {
+          context: {
+            method: "POST",
+            pathname: "/api/auth/callback/nhs-login",
+            headers: { "mock-header": "mock-value" },
+          },
           sessionId: "test-session-id",
           traceId: "test-trace-id",
           nextUrl: "/api/auth/callback/nhs-login",
         },
+        "NextAuth route",
       );
     });
-  });
 
-  describe("when the callback URL has no error", () => {
-    it("should not log an error", async () => {
-      const req = buildMockRequest("/api/auth/callback/nhs-login") as unknown as NextRequest;
+    it("should delegate the request to nextAuth handlers.POST", async () => {
+      const req = {
+        method: "POST",
+        nextUrl: { pathname: "/api/auth/callback/nhs-login" },
+        headers: new Headers(),
+      } as unknown as NextRequest;
 
-      await GET(req);
+      (extractRequestContextFromHeadersAndCookies as jest.Mock).mockReturnValueOnce(mockContext);
 
-      expect(mockLogError).not.toHaveBeenCalled();
-    });
-  });
-
-  describe("when the path is not the OAuth callback", () => {
-    it("should not log an error even if an error param is present", async () => {
-      const req = buildMockRequest("/api/auth/signin", { error: "OAuthCallbackError" }) as unknown as NextRequest;
-
-      await GET(req);
+      await POST(req);
 
-      expect(mockLogError).not.toHaveBeenCalled();
+      expect(handlers.POST as jest.Mock).toHaveBeenCalledWith(req);
     });
   });
 });

src/app/api/auth/[...nextauth]/route.ts

@@ -2,6 +2,7 @@ import { handlers } from "@project/auth";
 import { RequestContext, asyncLocalStorage } from "@project/src/utils/requestContext";
 import { extractRequestContextFromHeadersAndCookies } from "@project/src/utils/requestScopedStorageWrapper";
 import { NHS_LOGIN_PROVIDER_ID } from "@src/app/api/auth/[...nextauth]/provider";
+import { getHeadersForLogging } from "@src/utils/getHeadersForLogging";
 import { logger } from "@src/utils/logger";
 import { NextRequest } from "next/server";
 
@@ -16,7 +17,10 @@ export const GET = async (req: NextRequest) => {
   requestContext.nextUrl = pathname;
 
   return await asyncLocalStorage.run(requestContext, async () => {
-    log.info({ context: { pathname }, ...requestContext }, "GET NextAuth route");
+    log.info(
+      { context: { method: req.method, pathname, headers: getHeadersForLogging(req) }, ...requestContext },
+      "NextAuth route",
+    );
 
     const error = searchParams.get("error");
     if (pathname.includes(NHS_LOGIN_CALLBACK_PATH) && error) {
@@ -33,4 +37,17 @@ export const GET = async (req: NextRequest) => {
   });
 };
 
-export const { POST } = handlers;
+export const POST = async (req: NextRequest) => {
+  const { pathname } = req.nextUrl;
+
+  const requestContext: RequestContext = extractRequestContextFromHeadersAndCookies(req.headers, req?.cookies);
+  requestContext.nextUrl = pathname;
+
+  return await asyncLocalStorage.run(requestContext, async () => {
+    log.info(
+      { context: { method: req.method, pathname, headers: getHeadersForLogging(req) }, ...requestContext },
+      "NextAuth route",
+    );
+    return await handlers.POST(req);
+  });
+};

src/app/api/sso/route.test.ts

@@ -2,6 +2,7 @@ import { signIn } from "@project/auth";
 import { GET } from "@src/app/api/sso/route";
 import config from "@src/utils/config";
 import { SESSION_ID_COOKIE_NAME } from "@src/utils/constants";
+import { logger } from "@src/utils/logger";
 import { ConfigMock, configBuilder } from "@test-data/config/builders";
 import { ResponseCookie, ResponseCookies } from "next/dist/compiled/@edge-runtime/cookies";
 import { ReadonlyHeaders } from "next/dist/server/web/spec-extension/adapters/headers";
@@ -15,7 +16,20 @@ jest.mock("@project/auth", () => ({
 jest.mock("next/navigation", () => ({
   redirect: jest.fn(),
 }));
-jest.mock("sanitize-data", () => ({ sanitize: jest.fn() }));
+jest.mock("@src/utils/getHeadersForLogging", () => ({
+  getHeadersForLogging: jest.fn().mockReturnValue({ "mock-header": "mock-value" }),
+}));
+jest.mock("@src/utils/logger", () => ({
+  logger: {
+    child: jest.fn().mockReturnValue({
+      info: jest.fn(),
+      warn: jest.fn(),
+      error: jest.fn(),
+      debug: jest.fn(),
+    }),
+  },
+  extractRootTraceIdFromAmznTraceId: jest.fn().mockReturnValue("mock-trace-id"),
+}));
 
 jest.mock("next/headers", () => ({
   headers: jest.fn(),
@@ -34,20 +48,25 @@ const getMockRequest = (testUrl: string, params?: Record<string, string>) => {
     ["X-Clacks-Overhead", "GNU Terry Pratchett"],
     ["referer", "testing"],
   ]);
+  const url = new URL(testUrl);
 
   return {
     nextUrl: {
       searchParams: new URLSearchParams(params),
-      origin: new URL(testUrl).origin,
+      origin: url.origin,
       href: testUrl,
+      pathname: url.pathname,
     },
+    method: "GET",
     headers: headers,
   } as NextRequest;
 };
 
 let responseCookies: ResponseCookies;
 
 describe("GET handler", () => {
+  const mockLogInfo = (logger.child as jest.Mock).mock.results[0].value.info as jest.Mock;
+
   beforeEach(() => {
     jest.clearAllMocks();
     jest.useFakeTimers().setSystemTime(mockNowTimeInSeconds * 1000);
@@ -68,6 +87,26 @@ describe("GET handler", () => {
     jest.useRealTimers();
   });
 
+  it("logs method, pathname and headers when the route is invoked", async () => {
+    const testUrl = "https://testurl/api/sso";
+    const mockRequest = getMockRequest(testUrl, { assertedLoginIdentity: "test-identity" });
+
+    (signIn as jest.Mock).mockResolvedValue("/some-url");
+
+    await GET(mockRequest);
+
+    expect(mockLogInfo).toHaveBeenCalledWith(
+      expect.objectContaining({
+        context: expect.objectContaining({
+          method: "GET",
+          pathname: "/api/sso",
+          headers: { "mock-header": "mock-value" },
+        }),
+      }),
+      "SSO route invoked",
+    );
+  });
+
   it("redirects to sso-failure if assertedLoginIdentity parameter is missing", async () => {
     const testUrl = "https://testurl";
     const mockRequest = getMockRequest(testUrl);

src/app/api/sso/route.ts

@@ -2,6 +2,7 @@ import { signIn } from "@project/auth";
 import { NHS_LOGIN_PROVIDER_ID } from "@src/app/api/auth/[...nextauth]/provider";
 import { SSO_FAILURE_ROUTE } from "@src/app/sso-failure/constants";
 import config from "@src/utils/config";
+import { getHeadersForLogging } from "@src/utils/getHeadersForLogging";
 import { logger } from "@src/utils/logger";
 import { profilePerformanceEnd, profilePerformanceStart } from "@src/utils/performance";
 import { RequestContext, asyncLocalStorage } from "@src/utils/requestContext";
@@ -22,7 +23,12 @@ export const GET = async (request: NextRequest) => {
   requestContext.nextUrl = request.nextUrl.pathname;
 
   await asyncLocalStorage.run(requestContext, async () => {
-    log.info("SSO route invoked");
+    log.info(
+      {
+        context: { method: request.method, pathname: request.nextUrl.pathname, headers: getHeadersForLogging(request) },
+      },
+      "SSO route invoked",
+    );
     const assertedLoginIdentity: string | null = request.nextUrl.searchParams.get(ASSERTED_LOGIN_IDENTITY_PARAM);
 
     const MAX_SESSION_AGE_MILLISECONDS: number = (await config.MAX_SESSION_AGE_MINUTES) * 60 * 1000;