From 41ee467e2dc951a08edd59a8f1706306e3f2bae2 Mon Sep 17 00:00:00 2001
From: Will Hunt <will@half-shot.uk>
Date: Tue, 2 Jan 2024 15:58:25 +0000
Subject: [PATCH] Fix logged errors not being properly formatted (and tone down
 the error verbosity a bit) (#874)

* Ensure we add the error handlers last

* Refactor error middleware to be less noisy

* changelog

* Add finalise
---
 changelog.d/874.bugfix      |  2 ++
 spec/util/e2e-test.ts       |  1 +
 src/App/BridgeApp.ts        |  3 ++-
 src/App/GithubWebhookApp.ts |  1 +
 src/App/MatrixSenderApp.ts  |  1 +
 src/ListenerService.ts      | 13 ++++++++-----
 src/api/error.ts            | 16 +++++++++-------
 7 files changed, 24 insertions(+), 13 deletions(-)
 create mode 100644 changelog.d/874.bugfix

diff --git a/changelog.d/874.bugfix b/changelog.d/874.bugfix
new file mode 100644
index 00000000..5e41fde9
--- /dev/null
+++ b/changelog.d/874.bugfix
@@ -0,0 +1,2 @@
+Fix hookshot failing to format API errors.
+Only log a stacktrace of API errors on debug level logging, log limited error on info.
diff --git a/spec/util/e2e-test.ts b/spec/util/e2e-test.ts
index 08a95a70..20cf38c2 100644
--- a/spec/util/e2e-test.ts
+++ b/spec/util/e2e-test.ts
@@ -233,6 +233,7 @@ export class E2ETestEnv {
             }
         };
         const app = await start(config, registration);
+        app.listener.finaliseListeners();
         
         return new E2ETestEnv(homeserver, app, opts, config, dir);
     }
diff --git a/src/App/BridgeApp.ts b/src/App/BridgeApp.ts
index c8073c62..a21049e4 100644
--- a/src/App/BridgeApp.ts
+++ b/src/App/BridgeApp.ts
@@ -73,8 +73,9 @@ async function startFromFile() {
     const registrationFile = process.argv[3] || "./registration.yml";
     const config = await BridgeConfig.parseConfig(configFile, process.env);
     const registration = await parseRegistrationFile(registrationFile);
-    const { bridgeApp } = await start(config, registration);
+    const { bridgeApp, listener } = await start(config, registration);
     await bridgeApp.start();
+    listener.finaliseListeners();
 }
 
 if (require.main === module) {
diff --git a/src/App/GithubWebhookApp.ts b/src/App/GithubWebhookApp.ts
index 6fe6f610..34d5aa7b 100644
--- a/src/App/GithubWebhookApp.ts
+++ b/src/App/GithubWebhookApp.ts
@@ -30,6 +30,7 @@ async function start() {
     }
     const webhookHandler = new Webhooks(config);
     listener.bindResource('webhooks', webhookHandler.expressRouter);
+    listener.finaliseListeners();
     const userWatcher = new UserNotificationWatcher(config);
     userWatcher.start();
     process.once("SIGTERM", () => {
diff --git a/src/App/MatrixSenderApp.ts b/src/App/MatrixSenderApp.ts
index f41d6451..9e7847f6 100644
--- a/src/App/MatrixSenderApp.ts
+++ b/src/App/MatrixSenderApp.ts
@@ -32,6 +32,7 @@ async function start() {
             listener.bindResource('metrics', Metrics.expressRouter);
         }
     }
+    listener.finaliseListeners();
     sender.listen();
     process.once("SIGTERM", () => {
         log.error("Got SIGTERM");
diff --git a/src/ListenerService.ts b/src/ListenerService.ts
index 6733b26b..32ef379f 100644
--- a/src/ListenerService.ts
+++ b/src/ListenerService.ts
@@ -51,6 +51,14 @@ export class ListenerService {
         }
     }
 
+    public finaliseListeners() {
+        for (const listener of this.listeners) {
+            // By default, Sentry only reports 500+ errors, which is what we want.
+            listener.app.use(Handlers.errorHandler());
+            listener.app.use((err: unknown, req: Request, res: Response, next: NextFunction) => errorMiddleware(log)(err, req, res, next));
+        }
+    }
+
     public getApplicationsForResource(resourceName: ResourceName): Application[] {
         const listeners = this.listeners.filter((l) => l.config.resources.includes(resourceName));
         if (listeners.length === 0) {
@@ -74,11 +82,6 @@ export class ListenerService {
             // Ensure each listener has a ready probe.
             listener.app.get("/live", (_, res) => res.send({ok: true}));
             listener.app.get("/ready", (_, res) => res.status(listener.resourcesBound ? 200 : 500).send({ready: listener.resourcesBound}));
-
-            // By default, Sentry only reports 500+ errors, which is what we want.
-            listener.app.use(Handlers.errorHandler());
-            // Always include the error handler
-            listener.app.use((err: unknown, req: Request, res: Response, next: NextFunction) => errorMiddleware(log)(err, req, res, next));
             log.info(`Listening on http://${addr}:${listener.config.port} for ${listener.config.resources.join(', ')}`)
         }
     }
diff --git a/src/api/error.ts b/src/api/error.ts
index f9bef2a6..4b4f7864 100644
--- a/src/api/error.ts
+++ b/src/api/error.ts
@@ -70,6 +70,8 @@ const ErrCodeToStatusCode: Record<ErrCode, StatusCodes> = {
 }
 
 export class ApiError extends Error implements IApiError {
+    static readonly GenericFailure = new ApiError("An internal error occurred");
+
     constructor(
         public readonly error: string,
         public readonly errcode = ErrCode.Unknown,
@@ -109,19 +111,19 @@ export class ValidatorApiError extends ApiError {
 
 
 export function errorMiddleware(log: Logger) {
-    return (err: unknown, _req: Request, res: Response, next: NextFunction) => {
+    return (err: unknown, req: Request, res: Response, next: NextFunction) => {
         if (!err) {
             next();
             return;
         }
-        log.warn(err);
+        const apiError = err instanceof ApiError ? err : ApiError.GenericFailure;
+        // Log a reduced error on info
+        log.info(`${req.method} ${req.path} ${apiError.statusCode} - ${apiError.errcode} - ${apiError.error}`);
+        // Only show full error on debug level.
+        log.debug(err);
         if (res.headersSent) {
             return;
         }
-        if (err instanceof ApiError) {
-            err.apply(res);
-        } else {
-            new ApiError("An internal error occurred").apply(res);
-        }
+        apiError.apply(res);
     }
 }
\ No newline at end of file