Refactor Express module: streamline middleware logging, enhance sessi…

…on handling, and improve server startup logging
UKDanceBlue · Jan 17, 2025 · e000008 · e000008
1 parent 6017c87
commit e000008
Show file tree

Hide file tree

Showing 5 changed files with 88 additions and 47 deletions.
diff --git a/packages/server/src/entry/server/Express.ts b/packages/server/src/entry/server/Express.ts
@@ -9,12 +9,10 @@ import express from "express";
 
 import { formatError } from "#lib/formatError.js";
 import { logger } from "#lib/logging/standardLogging.js";
-import type { SyslogLevels } from "#lib/logging/SyslogLevels.js";
 import {
   applicationPortToken,
   cookieSecretToken,
   isDevelopmentToken,
-  loggingLevelToken,
 } from "#lib/typediTokens.js";
 import { SessionRepository } from "#repositories/Session.js";
 
@@ -25,7 +23,6 @@ import { SessionRepository } from "#repositories/Session.js";
   [
     SessionRepository,
     applicationPortToken,
-    loggingLevelToken,
     isDevelopmentToken,
     cookieSecretToken,
   ]
@@ -38,7 +35,6 @@ export class ExpressModule {
   constructor(
     private readonly sessionRepository: SessionRepository,
     private readonly applicationPort: number,
-    private readonly loggingLevel: SyslogLevels,
     private readonly isDevelopment: boolean,
     private readonly cookieSecret: string
   ) {}
@@ -51,19 +47,15 @@ export class ExpressModule {
   }
 
   public startMiddlewares() {
-    if (this.loggingLevel === "trace") {
-      this.app.use((req, _res, next) => {
-        logger.trace("request received", {
-          method: req.method,
-          url: req.url,
-        });
-        next();
+    this.app.use((req, _res, next) => {
+      logger.trace("request received", {
+        method: req.method,
+        url: req.url,
       });
-    }
-    this.app.use((req, _, next) => {
       req.getService = Container.get.bind(Container);
       next();
     });
+
     this.app.use(
       cors({
         credentials: true,
@@ -133,6 +125,19 @@ export class ExpressModule {
       this.httpServer.on("error", reject);
       this.httpServer.listen(this.applicationPort, () => {
         this.httpServer.off("error", reject);
+        const httpServerAddress = this.httpServer.address();
+        let httpServerUrl = "";
+        if (typeof httpServerAddress === "string") {
+          httpServerUrl = httpServerAddress;
+        } else if (httpServerAddress) {
+          httpServerUrl =
+            httpServerAddress.address === "::" ||
+            httpServerAddress.address === ""
+              ? `http://localhost:${httpServerAddress.port}`
+              : `http://${httpServerAddress.address}:${httpServerAddress.port}`;
+        }
+
+        logger.info(`HTTP server started at ${httpServerUrl}`);
         resolve();
       });
     });

diff --git a/packages/server/src/entry/server/Server.ts b/packages/server/src/entry/server/Server.ts
@@ -42,13 +42,19 @@ export class Server implements EntryPoint {
     );
 
     this.expressModule.init();
+    logger.debug("Express initialized");
+
     await this.apolloModule.init();
+    logger.debug("Apollo initialized");
 
     this.expressModule.startMiddlewares();
+    logger.debug("Express middlewares started");
 
     await this.apolloModule.start();
+    logger.debug("Apollo started");
 
     await this.expressModule.startRoutes();
+    logger.debug("Express routes started");
 
     if (process.env.SSR === "enable_unstable_ssr") {
       if (!this.isDevelopment) {
@@ -65,24 +71,16 @@ export class Server implements EntryPoint {
     } else {
       await this.portalModule.startSpa();
     }
+    logger.debug("Portal started");
 
     this.expressModule.startErrorHandlers();
+    logger.debug("Express error handlers started");
 
     await this.expressModule.start();
-
-    const httpServerAddress = this.expressModule.httpServer.address();
-    let httpServerUrl = "";
-    if (typeof httpServerAddress === "string") {
-      httpServerUrl = httpServerAddress;
-    } else if (httpServerAddress) {
-      httpServerUrl =
-        httpServerAddress.address === "::" || httpServerAddress.address === ""
-          ? `http://localhost:${httpServerAddress.port}`
-          : `http://${httpServerAddress.address}:${httpServerAddress.port}`;
-    }
-    logger.info(`HTTP server started at ${httpServerUrl}`);
+    logger.debug("Express started");
 
     await import("#jobs/index.js");
+    logger.debug("Jobs started");
 
     logger.info("DanceBlue Server Started");
   }

diff --git a/packages/server/src/lib/logging/standardLogging.ts b/packages/server/src/lib/logging/standardLogging.ts
@@ -1,6 +1,8 @@
 import { Container } from "@freshgum/typedi";
+import * as Sentry from "@sentry/node";
 import { debugStringify } from "@ukdanceblue/common";
 import { ConcreteError } from "@ukdanceblue/common/error";
+import { DateTime } from "luxon";
 import type winston from "winston";
 import type { Logform } from "winston";
 import { createLogger, format, transports } from "winston";
@@ -88,6 +90,20 @@ export const logger = createLogger({
   exitOnError: false,
 }) as StandardLogger;
 
+export function breadCrumbTrace(
+  message: string,
+  data?: Record<string, unknown>
+) {
+  logger.trace(message, data);
+  Sentry.addBreadcrumb({
+    message,
+    data,
+    category: "trace",
+    timestamp: DateTime.now().toSeconds(),
+    level: "debug",
+  });
+}
+
 /**
  * Log a fatal message to the logger
  *

diff --git a/packages/server/src/repositories/Session.ts b/packages/server/src/repositories/Session.ts
@@ -24,6 +24,8 @@ const { sign, verify } = jsonwebtoken;
 
 import * as Sentry from "@sentry/node";
 
+import { breadCrumbTrace, logger } from "#lib/logging/standardLogging.js";
+
 import { buildDefaultRepository } from "./Default.js";
 import {
   PersonRepository,
@@ -219,6 +221,11 @@ export class SessionRepository extends buildDefaultRepository("Session", {}) {
       res: express.Response,
       next: express.NextFunction
     ) => {
+      logger.trace("Session middleware", {
+        method: req.method,
+        url: req.url,
+      });
+
       let token = (req.cookies as Partial<Record<string, string>>)[
         SESSION_COOKIE_NAME
       ]
@@ -255,6 +262,11 @@ export class SessionRepository extends buildDefaultRepository("Session", {}) {
             ): AsyncRepositoryResult<SessionValue, UnauthenticatedError> => {
               req.session = session;
 
+              breadCrumbTrace("Session verified", {
+                sessionUuid: session.uuid,
+                personEmail: session.person?.email,
+              });
+
               Sentry.setUser({
                 email: session.person?.email,
                 id: session.person?.uuid,
@@ -269,28 +281,26 @@ export class SessionRepository extends buildDefaultRepository("Session", {}) {
               return this.refreshSession(session);
             }
           )
-          .andThen((session) => this.signSession(session))
-          .andThen<undefined, undefined>((token) => {
-            if (tokenFromCookie) {
-              res.cookie(SESSION_COOKIE_NAME, token, this.sessionCookieOptions);
-            }
+          .andThen((session) => this.signSession(session));
+        const awaited = await result.promise;
+        if (awaited.isOk()) {
+          if (tokenFromCookie) {
+            res.cookie(SESSION_COOKIE_NAME, token, this.sessionCookieOptions);
+          }
+          next();
+        } else {
+          req.session = null;
+          if (
+            awaited.error instanceof ConcreteError &&
+            awaited.error.tag === ErrorCode.Unauthenticated &&
+            tokenFromCookie
+          ) {
+            res.clearCookie(SESSION_COOKIE_NAME);
             next();
-            return Ok(undefined);
-          })
-          .orElse<undefined>((error) => {
-            req.session = null;
-            if (
-              error instanceof ConcreteError &&
-              error.tag === ErrorCode.Unauthenticated &&
-              tokenFromCookie
-            ) {
-              res.clearCookie(SESSION_COOKIE_NAME);
-            } else {
-              next(error);
-            }
-            return Ok(undefined);
-          }) satisfies AsyncResult<undefined, undefined>;
-        await result.promise;
+          } else {
+            next(awaited.error);
+          }
+        }
       }
     };
   }

diff --git a/packages/server/src/routes/RouteService.ts b/packages/server/src/routes/RouteService.ts
@@ -1,14 +1,26 @@
 import type { RequestHandler } from "express";
 import { Router } from "express";
 
+import { logger } from "#lib/logging/standardLogging.js";
+
 export abstract class RouterService {
   private readonly localRouter: Router;
   constructor(private path: string) {
     this.localRouter = Router();
   }
 
   public mount(parent: Router) {
-    parent.use(this.path, this.localRouter);
+    parent.use(
+      this.path,
+      (req, _res, next) => {
+        logger.trace(`Handling request with API path ${this.path}`, {
+          method: req.method,
+          url: req.url,
+        });
+        next();
+      },
+      this.localRouter
+    );
   }
 
   protected addGetRoute(path: string, ...middleware: RequestHandler[]) {