Add debug logging to executor

lib/executor.ts

@@ -1,16 +1,29 @@
+import { Debugger } from "debug";
 import { NextApiHandler, NextApiRequest, NextApiResponse } from "next";
 import { Middleware } from ".";
+import { logger } from "./logger";
 import { controlledPromise, isPromise } from "./promises";
 
+/**
+ * Basic means to count nested levels of middleware
+ */
+let counter = 0;
+
 // This gets invoked internally by `use` and `label`
 export function makeMiddlewareExecutor(middlewareFns: Middleware[]) {
+  logger("Registered %d middleware functions", middlewareFns.length);
+
   // This curried function receives an API route
   return function curryApiHandler(apiRouteFn: NextApiHandler): NextApiHandler {
+    logger("Registered Next API Handler");
+
     // The final function returned is a Next API handler that
     // is responsible for executing all the middleware provided,
     // as well as the API route handler
     return async function finalRouteHandler(req, res) {
+      logger("Starting middleware execution");
       await new Executor(middlewareFns, apiRouteFn, req, res).run();
+      counter = 0;
     };
   };
 }
@@ -46,6 +59,11 @@ export class Executor {
    */
   teardownPromise = controlledPromise();
 
+  /**
+   * Utility for logging debug messages
+   */
+  log: Debugger;
+
   constructor(
     [currentFn, ...remaining]: Middleware[],
     public apiRouteFn: NextApiHandler,
@@ -54,6 +72,7 @@ export class Executor {
   ) {
     this.currentFn = currentFn;
     this.remaining = remaining;
+    this.log = logger.extend(`fn-${++counter}`);
   }
 
   /**
@@ -65,10 +84,18 @@ export class Executor {
    * If it succeeds, an executor is created to handle
    * the remaining middleware.
    */
-  run(): Promise<void> {
+  async run(): Promise<void> {
+    const l = this.log;
+
     try {
+      const cleanupPromise = controlledPromise();
+
       // Call the current function
+      l(`Executing middleware "${this.currentFn.name}"`);
       this.result = this.currentFn(this.req, this.res, (error?: any) => {
+        cleanupPromise.resolve();
+        l("Finished cleanup");
+
         // Look for errors from synchronous middleware
         if (error) {
           // Throw errors to be caught in the try/catch block
@@ -85,15 +112,20 @@ export class Executor {
       if (isPromise(this.result)) {
         this.result.then(
           () => {
+            l("Async middleware succeeded");
             this.succeed();
           },
           (err) => {
+            l("Async middleware failed");
             asyncMiddlewareFailed = true;
+            cleanupPromise.resolve();
             this.fail(err);
           }
         );
       }
 
+      await cleanupPromise.promise;
+
       // Use a microtask to give async middleware a chance to fail
       queueMicrotask(() => {
         if (!asyncMiddlewareFailed) {
@@ -103,6 +135,7 @@ export class Executor {
       });
     } catch (err) {
       // Catches errors from synchronous middleware
+      l("Caught error from synchronous middleware");
       this.fail(err);
     }
 
@@ -114,10 +147,14 @@ export class Executor {
    * promise if it is available.
    */
   async runRemaining(): Promise<void> {
+    const l = this.log;
+
     try {
       if (this.remaining.length === 0) {
         // No more middleware, execute the API route handler
+        l("Executing API handler");
         await this.apiRouteFn(this.req, this.res);
+        l("Finished executing API handler");
       } else {
         // Recursively execute remaining middleware
         const remainingExecutor = new Executor(
@@ -127,6 +164,7 @@ export class Executor {
           this.res
         );
 
+        l("Running next executor");
         await remainingExecutor.run();
       }
 
@@ -144,24 +182,31 @@ export class Executor {
    * promise as a success.
    */
   finish(error?: any) {
+    const l = this.log;
+    l("Finishing...");
+
     if (isPromise(this.result)) {
       // Current middleware is async
       if (error) {
         // Let the result have a chance to handle the error
+        l("Passing nested error to async middleware");
         this.teardownPromise.reject(error);
       } else {
         // Let the result continue its teardown
+        l("Starting async middleware teardown");
         this.teardownPromise.resolve();
       }
     } else {
       // Current middleware is synchronous
       if (error) {
         // Synchronous middleware cannot handle errors,
         // trigger a failure
+        l("Failing executor and passing error up");
         this.fail(error);
       } else {
         // Synchronous middleware has no teardown phase,
         // trigger a success
+        l("Synchronous middleware succeeded");
         this.succeed();
       }
     }

lib/logger.ts

@@ -0,0 +1,3 @@
+import { debug } from "debug";
+
+export const logger = debug("middleware");

package.json

@@ -34,6 +34,7 @@
     "@babel/preset-env": "^7.13.15",
     "@babel/preset-typescript": "^7.13.0",
     "@types/cors": "^2.8.10",
+    "@types/debug": "^4.1.6",
     "@types/jest": "^26.0.24",
     "@types/node": "^15.0.1",
     "@types/react": "^17.0.3",
@@ -46,5 +47,7 @@
     "ts-node": "^10.0.0",
     "typescript": "^4.2.4"
   },
-  "dependencies": {}
+  "dependencies": {
+    "debug": "^4.3.2"
+  }
 }

yarn.lock

@@ -1308,6 +1308,11 @@
   resolved "https://registry.yarnpkg.com/@types/cors/-/cors-2.8.11.tgz#0bbd036cc6c8c63e0e5d64115fa9692eabb7eaa3"
   integrity sha512-64aQQZXPSo1fdLEE/utClOFVUqDUjyh5j3JorcCTlYQm4r5wsfggx6yhSY6hNudJLkbmIt+pO6xWyCnM0EQgPw==
 
+"@types/debug@^4.1.6":
+  version "4.1.6"
+  resolved "https://registry.yarnpkg.com/@types/debug/-/debug-4.1.6.tgz#0b7018723084918a865eff99249c490505df2163"
+  integrity sha512-7fDOJFA/x8B+sO1901BmHlf5dE1cxBU8mRXj8QOEDnn16hhGJv/IHxJtZhvsabZsIMn0eLIyeOKAeqSNJJYTpA==
+
 "@types/graceful-fs@^4.1.2":
   version "4.1.5"
   resolved "https://registry.yarnpkg.com/@types/graceful-fs/-/graceful-fs-4.1.5.tgz#21ffba0d98da4350db64891f92a9e5db3cdb4e15"
@@ -2271,7 +2276,7 @@ debug@2, debug@^2.2.0, debug@^2.3.3:
   dependencies:
     ms "2.0.0"
 
-debug@4, debug@^4.1.0, debug@^4.1.1:
+debug@4, debug@^4.1.0, debug@^4.1.1, debug@^4.3.2:
   version "4.3.2"
   resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.2.tgz#f0a49c18ac8779e31d4a0c6029dfb76873c7428b"
   integrity sha512-mOp8wKcvj7XxC78zLgw/ZA+6TSgkoE2C/ienthhRD298T7UNwAg9diBpLRxC0mOezLl4B0xV7M0cCO6P/O0Xhw==