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

@@ -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.

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);
     }

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) {

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", () => {

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");

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(', ')}`)
         }
     }

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) {
+        apiError.apply(res);
-            err.apply(res);
-        } else {
-            new ApiError("An internal error occurred").apply(res);
-        }
     }
 }