Merge pull request #45 from saleor/add-more-debug-messages

Add debug messages to middlewares

docs/debugging.md

@@ -15,7 +15,7 @@ To enable logs, use the following:
 
 ### Enabling in Node context
 
-Add `DEBUG={namespaces}` env variable.
+Add `DEBUG=app-sdk:{namespaces}` env variable.
 
 #### Example
 
@@ -27,7 +27,7 @@ For more details check [debug package](https://github.com/debug-js/debug#usage).
 
 ### Enabling in Browser context
 
-Set `localStorage.debug = '{namepsaces}'` in your frontend code. For more details see [debug package](https://github.com/debug-js/debug#browser-support).
+Set `localStorage.debug = 'app-sdk:{namepsaces}'` in your frontend code. For more details see [debug package](https://github.com/debug-js/debug#browser-support).
 
 #### Debug in iframe
 
@@ -45,7 +45,8 @@ localStorage.debug = "*";
 
 Use the namespace name to enable debug logs for each module.
 
-| Namespace name | Description                                        |
-| -------------- | -------------------------------------------------- |
-| \*             | Enable all                                         |
-| AppBridge      | Enable [AppBridge](./app-bridge.md) (browser only) |
+| Namespace name        | Description                                        |
+| --------------------- | -------------------------------------------------- |
+| \app-sdk:\*           | Enable all                                         |
+| app-sdk:AppBridge     | Enable [AppBridge](./app-bridge.md) (browser only) |
+| app-sdk:Middleware:\* | Enable all middlewares (node only)                 |

src/app-bridge/app-bridge.ts

@@ -12,7 +12,7 @@ type SubscribeMap = {
   [type in EventType]: Record<symbol, EventCallback<PayloadOfEvent<type>>>;
 };
 
-const debug = debugPkg.debug("AppBridge");
+const debug = debugPkg.debug("app-sdk:AppBridge");
 
 function eventStateReducer(state: AppBridgeState, event: Events) {
   debug("Event reducer received event: %j", event);

src/debug.ts

@@ -0,0 +1,3 @@
+import debugPkg from "debug";
+
+export const createDebug = (namespace: string) => debugPkg.debug(`app-sdk:${namespace}`);

src/middleware/index.ts

@@ -1,3 +1,4 @@
+export { withReqResDebugging } from "./middleware-debug";
 export * from "./with-auth-token-required";
 export * from "./with-base-url";
 export * from "./with-jwt-verified";

src/middleware/middleware-debug.test.ts

@@ -0,0 +1,27 @@
+import { Handler, Request } from "retes";
+import { Response } from "retes/response";
+import { describe, expect, it, vi } from "vitest";
+
+import { withReqResDebugging } from "./middleware-debug";
+
+describe("withReqResDebugging", () => {
+  it("Logs request and response to debug", async () => {
+    const mockDebug = vi.fn();
+    const handler: Handler = async () => Response.OK("Tested handler is ok");
+    const wrappedHandler = withReqResDebugging(() => mockDebug)(handler);
+
+    const mockReqBody = JSON.stringify({ foo: "bar" });
+
+    await wrappedHandler({ rawBody: mockReqBody } as Request);
+
+    expect(mockDebug).toHaveBeenNthCalledWith(1, "Called with request %j", {
+      rawBody: mockReqBody,
+    });
+
+    expect(mockDebug).toHaveBeenNthCalledWith(2, "Responded with response %j", {
+      body: "Tested handler is ok",
+      headers: {},
+      status: 200,
+    });
+  });
+});

src/middleware/middleware-debug.ts

@@ -0,0 +1,26 @@
+import { Middleware } from "retes";
+
+import { createDebug } from "../debug";
+
+export const createMiddlewareDebug = (middleware: string) =>
+  createDebug(`Middleware:${middleware}`);
+
+type DebugFactory = (handlerName: string) => (msg: string, ...args: any[]) => void;
+
+/**
+ * Experimental. Needs to be tested and evaluated on security
+ */
+export const withReqResDebugging =
+  (debugFactory: DebugFactory = createMiddlewareDebug): Middleware =>
+  (handler) =>
+  async (request) => {
+    const debug = debugFactory(handler.name);
+
+    debug("Called with request %j", request);
+
+    const response = await handler(request);
+
+    debug("Responded with response %j", response);
+
+    return response;
+  };

src/middleware/with-auth-token-required.ts

@@ -1,9 +1,18 @@
 import { Middleware } from "retes";
 import { Response } from "retes/response";
 
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withAuthTokenRequired");
+
 export const withAuthTokenRequired: Middleware = (handler) => async (request) => {
+  debug("Middleware called");
+
   const authToken = request.params.auth_token;
+
   if (!authToken) {
+    debug("Found missing authToken param");
+
     return Response.BadRequest({
       success: false,
       message: "Missing auth token.",

src/middleware/with-base-url.ts

@@ -1,9 +1,17 @@
 import { Middleware } from "retes";
 
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withBaseURL");
+
 export const withBaseURL: Middleware = (handler) => async (request) => {
   const { host, "x-forwarded-proto": protocol = "http" } = request.headers;
 
+  debug("Middleware called with host: %s, protocol %s", host, request.headers["x-forwarded-proto"]);
+
   request.context.baseURL = `${protocol}://${host}`;
 
+  debug("context.baseURL resolved to be: \"%s\"", request.context.baseURL);
+
   return handler(request);
 };

src/middleware/with-jwt-verified.ts

@@ -5,25 +5,35 @@ import { Response } from "retes/response";
 import { SALEOR_AUTHORIZATION_BEARER_HEADER, SALEOR_DOMAIN_HEADER } from "../const";
 import { getSaleorHeaders } from "../headers";
 import { getJwksUrl } from "../urls";
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withJWTVerified");
 
 export interface DashboardTokenPayload extends jose.JWTPayload {
   app: string;
 }
 
+const ERROR_MESSAGE = "JWT verification failed:";
+
 export const withJWTVerified =
   (getAppId: (request: Request) => Promise<string | undefined>): Middleware =>
   (handler) =>
   async (request) => {
     const { domain, authorizationBearer: token } = getSaleorHeaders(request.headers);
-    const ERROR_MESSAGE = "JWT verification failed:";
 
-    if (token === undefined) {
+    debug("Middleware called with domain: \"%s\"", domain);
+
+    if (typeof token !== "string") {
+      debug("Middleware with empty token, will response with Bad Request", token);
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} Missing ${SALEOR_AUTHORIZATION_BEARER_HEADER} header.`,
       });
     }
 
+    debug("Middleware called with token starting with: \"%s\"", token.substring(0, 4));
+
     if (domain === undefined) {
       return Response.BadRequest({
         success: false,
@@ -32,9 +42,13 @@ export const withJWTVerified =
     }
 
     let tokenClaims: DashboardTokenPayload;
+
     try {
       tokenClaims = jose.decodeJwt(token as string) as DashboardTokenPayload;
+      debug("Token Claims decoded from jwt");
     } catch (e) {
+      debug("Token Claims could not be decoded from JWT, will respond with Bad Request");
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} Could not decode authorization token.`,
@@ -42,6 +56,8 @@ export const withJWTVerified =
     }
 
     if (tokenClaims.iss !== domain) {
+      debug("Token iss doesn't match domain, will response with Bad Request");
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} Token iss property is different than domain header.`,
@@ -49,9 +65,14 @@ export const withJWTVerified =
     }
 
     let appId: string | undefined;
+
     try {
       appId = await getAppId(request);
+
+      debug("Resolved App ID from request to be: %s", appId);
     } catch (error) {
+      debug("App ID could not be resolved from request, will respond with Internal Server Error");
+
       return Response.InternalServerError({
         success: false,
         message: `${ERROR_MESSAGE} Could not obtain the app ID.`,
@@ -59,6 +80,8 @@ export const withJWTVerified =
     }
 
     if (!appId) {
+      debug("Resolved App ID to be empty value");
+
       return Response.InternalServerError({
         success: false,
         message: `${ERROR_MESSAGE} No value for app ID.`,
@@ -66,6 +89,10 @@ export const withJWTVerified =
     }
 
     if (tokenClaims.app !== appId) {
+      debug(
+        "Resolved App ID value from token to be different than in request, will respond with Bad Request"
+      );
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} Token's app property is different than app ID.`,
@@ -73,10 +100,17 @@ export const withJWTVerified =
     }
 
     try {
+      debug("Trying to create JWKS");
+
       const JWKS = jose.createRemoteJWKSet(new URL(getJwksUrl(domain)));
+      debug("Trying to compare JWKS with token");
       await jose.jwtVerify(token, JWKS);
     } catch (e) {
+      debug("Failure: %s", e);
+      debug("Will return with Bad Request");
+
       console.error(e);
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} JWT signature verification failed.`,

src/middleware/with-registered-saleor-domain-header.ts

@@ -3,20 +3,30 @@ import { Response } from "retes/response";
 
 import { APL } from "../APL";
 import { getSaleorHeaders } from "../headers";
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withRegisteredSaleorDomainHeader");
 
 export const withRegisteredSaleorDomainHeader =
   ({ apl }: { apl: APL }): Middleware =>
   (handler) =>
   async (request) => {
     const { domain: saleorDomain } = getSaleorHeaders(request.headers);
+
     if (!saleorDomain) {
       return Response.BadRequest({
         success: false,
         message: "Domain header missing.",
       });
     }
+
+    debug("Middleware called with domain: \"%s\"", saleorDomain);
+
     const authData = await apl.get(saleorDomain);
+
     if (!authData) {
+      debug("Auth was not found in APL, will respond with Forbidden status");
+
       return Response.Forbidden({
         success: false,
         message: `Domain ${saleorDomain} not registered.`,

src/middleware/with-saleor-domain-present.ts

@@ -2,11 +2,18 @@ import { Middleware } from "retes";
 import { Response } from "retes/response";
 
 import { getSaleorHeaders } from "../headers";
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withSaleorDomainPresent");
 
 export const withSaleorDomainPresent: Middleware = (handler) => async (request) => {
   const { domain } = getSaleorHeaders(request.headers);
 
+  debug("Middleware called with domain in header: %s", domain);
+
   if (!domain) {
+    debug("Domain not found in header, will respond with Bad Request");
+
     return Response.BadRequest({
       success: false,
       message: "Missing Saleor domain header.",

src/middleware/with-saleor-event-match.ts

@@ -2,6 +2,9 @@ import { Middleware } from "retes";
 import { Response } from "retes/response";
 
 import { getSaleorHeaders } from "../headers";
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withSaleorEventMatch");
 
 export const withSaleorEventMatch =
   <E extends string>(expectedEvent: `${Lowercase<E>}`): Middleware =>
@@ -9,7 +12,15 @@ export const withSaleorEventMatch =
   async (request) => {
     const { event } = getSaleorHeaders(request.headers);
 
+    debug("Middleware called with even header: \"%s\"", event);
+
     if (event !== expectedEvent) {
+      debug(
+        "Event from header (%s) doesnt match expected (%s). Will respond with Bad Request",
+        event,
+        expectedEvent
+      );
+
       return Response.BadRequest({
         success: false,
         message: `Invalid Saleor event. Expecting ${expectedEvent}.`,

src/middleware/with-webhook-signature-verified.ts

@@ -6,14 +6,21 @@ import { Response } from "retes/response";
 import { SALEOR_DOMAIN_HEADER, SALEOR_SIGNATURE_HEADER } from "../const";
 import { getSaleorHeaders } from "../headers";
 import { getJwksUrl } from "../urls";
+import { createMiddlewareDebug } from "./middleware-debug";
+
+const debug = createMiddlewareDebug("withWebhookSignatureVerified");
+
+const ERROR_MESSAGE = "Webhook signature verification failed:";
 
 export const withWebhookSignatureVerified =
   (secretKey: string | undefined = undefined): Middleware =>
   (handler) =>
   async (request) => {
-    const ERROR_MESSAGE = "Webhook signature verification failed:";
+    debug("Middleware executing start");
 
     if (request.rawBody === undefined) {
+      debug("Request rawBody was not found, will return Internal Server Error");
+
       return Response.InternalServerError({
         success: false,
         message: `${ERROR_MESSAGE} Request payload already parsed.`,
@@ -23,6 +30,8 @@ export const withWebhookSignatureVerified =
     const { domain: saleorDomain, signature: payloadSignature } = getSaleorHeaders(request.headers);
 
     if (!payloadSignature) {
+      debug("Signature header was not found");
+
       return Response.BadRequest({
         success: false,
         message: `${ERROR_MESSAGE} Missing ${SALEOR_SIGNATURE_HEADER} header.`,
@@ -42,7 +51,11 @@ export const withWebhookSignatureVerified =
         .update(request.rawBody)
         .digest("hex");
 
+      debug("Signature was calculated");
+
       if (calculatedSignature !== payloadSignature) {
+        debug("Calculated signature doesn't match payload signature, will return Bad Request");
+
         return Response.BadRequest({
           success: false,
           message: `${ERROR_MESSAGE} Verification using secret key has failed.`,
@@ -60,9 +73,15 @@ export const withWebhookSignatureVerified =
         new URL(getJwksUrl(saleorDomain))
       ) as jose.FlattenedVerifyGetKey;
 
+      debug("Created remote JWKS");
+
       try {
         await jose.flattenedVerify(jws, remoteJwks);
+
+        debug("JWKS verified");
       } catch {
+        debug("JWKS verification failed");
+
         return Response.BadRequest({
           success: false,
           message: `${ERROR_MESSAGE} Verification using public key has failed.`,