Improve HTTP Error handling.

So as a history lesson.
The Matrix Bot SDK uses the npm library "requests".
When there was a http error, matrix-bot-sdk
would literally throw the response object.
This would be a horrible 1000+line long thing to accidentally
be logged to the console via node's inspect.
Though it was inevitable since you can't be sure every catch
was handling the error correctly. Irregardless, the solution
developed at Element was to create an error object
that had concise details.
This was great, however, within the matrix-bot-sdk there is
[this](https://github.com/Half-Shot/matrix-bot-sdk/blob/f58d7ea6e24d1db8b9b8009dea4cd97cbff54d0c/src/http.ts#L66)
awful line of code which logs every http error as error using the
matrix-bot-sdk logger.
This wastes so much log space and causes alarm fatigue,
rather than muting the module, the action instead taken
was to redact stack traces from http errors.
This was not a good idea.
Eventually matrix-bot-sdk was updated to have a MatrixError type
when a request was performed via the client-server api that had an
error.
matrix-appservice-bridge depends upon this and so Mjolnir now needs
to be updated to throw MatrixError's.
We have gone a step further in this commit and also muted
the matrix-bot-sdk http module, to stop the alarm fatigue problem
https://github.com/turt2live/matrix-bot-sdk/pull/158

src/ManagementRoomOutput.ts

@@ -26,7 +26,7 @@ limitations under the License.
  */
 
 import * as Sentry from "@sentry/node";
-import { extractRequestError, LogLevel, LogService, MessageType, Permalinks, TextualMessageEventContent, UserID } from "matrix-bot-sdk";
+import { LogLevel, LogService, MessageType, Permalinks, TextualMessageEventContent, UserID } from "matrix-bot-sdk";
 import { IConfig } from "./config";
 import { MatrixSendClient } from "./MatrixEmitter";
 import { htmlEscape } from "./utils";
@@ -84,7 +84,7 @@ export default class ManagementRoomOutput {
             } catch (e) {
                 // This is a recursive call, so tell the function not to try and call us
                 await this.logMessage(LogLevel.WARN, "utils", `Failed to resolve room alias for ${roomId} - see console for details`, null, true);
-                LogService.warn("utils", extractRequestError(e));
+                LogService.warn("ManagementRoomOutput", "Failed resolving room alias when formatting a message", e);
             }
             const regexRoomId = new RegExp(escapeRegex(roomId), "g");
             content.body = content.body.replace(regexRoomId, alias);

src/Mjolnir.ts

@@ -26,7 +26,6 @@ limitations under the License.
  */
 
 import {
-    extractRequestError,
     LogLevel,
     LogService,
     MembershipEvent,
@@ -185,6 +184,15 @@ export class Mjolnir {
     ) {
         this.protectedRoomsConfig = new ProtectedRoomsConfig(client);
 
+        const mutedModules = (LogService as any).mutedModules;
+        if (!Array.isArray(mutedModules)) {
+            throw new TypeError("MatrixBotSdk has changed their hacky handling of muted modules, praise be");
+        }
+        for (const module of config.logMutedModules) {
+            if (!mutedModules.includes(module)) {
+                LogService.muteModule(module);
+            }
+        }
         // Setup bot.
 
         matrixEmitter.on("room.event", this.handleEvent.bind(this));
@@ -332,12 +340,11 @@ export class Mjolnir {
             await this.managementRoomOutput.logMessage(LogLevel.INFO, "Mjolnir@startup", "Startup complete. Now monitoring rooms.");
         } catch (err) {
             try {
-                LogService.error("Mjolnir", "Error during startup:");
-                LogService.error("Mjolnir", extractRequestError(err));
+                LogService.error("Mjolnir", "Error during startup:", err);
                 this.stop();
                 await this.managementRoomOutput.logMessage(LogLevel.ERROR, "Mjolnir@startup", "Startup failed due to error - see console");
             } catch (e) {
-                LogService.error("Mjolnir", `Failed to report startup error to the management room: ${e}`);
+                LogService.error("Mjolnir", `Failed to report startup error to the management room:`, e);
             }
             throw err;
         }
@@ -527,7 +534,7 @@ export class Mjolnir {
             watchedListsEvent = await this.client.getAccountData(WATCHED_LISTS_EVENT_TYPE);
         } catch (e) {
             if (e.statusCode === 404) {
-                LogService.warn('Mjolnir', "Couldn't find account data for Mjolnir's watched lists, assuming first start.", extractRequestError(e));
+                LogService.warn('Mjolnir', "Couldn't find account data for Mjolnir's watched lists, assuming first start.", e);
             } else {
                 throw e;
             }

src/ProtectedRoomsConfig.ts

@@ -26,7 +26,7 @@ limitations under the License.
  */
 
 import AwaitLock from 'await-lock';
-import { extractRequestError, LogService, Permalinks } from "matrix-bot-sdk";
+import { LogService, Permalinks } from "matrix-bot-sdk";
 import { IConfig } from "./config";
 import { MatrixSendClient } from './MatrixEmitter';
 const PROTECTED_ROOMS_EVENT_TYPE = "org.matrix.mjolnir.protected_rooms";
@@ -84,7 +84,7 @@ export default class ProtectedRoomsConfig {
             }
         } catch (e) {
             if (e.statusCode === 404) {
-                LogService.warn("ProtectedRoomsConfig", "Couldn't find any explicitly protected rooms from Mjolnir's account data, assuming first start.", extractRequestError(e));
+                LogService.warn("ProtectedRoomsConfig", "Couldn't find any explicitly protected rooms from Mjolnir's account data, assuming first start.", e);
             } else {
                 throw e;
             }
@@ -129,7 +129,7 @@ export default class ProtectedRoomsConfig {
         try {
             const additionalProtectedRooms: string[] = await this.client.getAccountData(PROTECTED_ROOMS_EVENT_TYPE)
                 .then((rooms: {rooms?: string[]}) => Array.isArray(rooms?.rooms) ? rooms.rooms : [])
-                .catch(e => (LogService.warn("ProtectedRoomsConfig", "Could not load protected rooms from account data", extractRequestError(e)), []));
+                .catch(e => (LogService.warn("ProtectedRoomsConfig", "Could not load protected rooms from account data", e), []));
 
             const roomsToSave = new Set([...this.explicitlyProtectedRooms.keys(), ...additionalProtectedRooms]);
             excludeRooms.forEach(roomsToSave.delete, roomsToSave);

src/commands/AddRemoveProtectedRoomsCommand.ts

@@ -26,7 +26,7 @@ limitations under the License.
  */
 
 import { Mjolnir } from "../Mjolnir";
-import { extractRequestError, LogLevel, LogService } from "matrix-bot-sdk";
+import { LogLevel, LogService } from "matrix-bot-sdk";
 
 // !mjolnir rooms add <room alias/ID>
 export async function execAddProtectedRoom(roomId: string, event: any, mjolnir: Mjolnir, parts: string[]) {
@@ -42,7 +42,7 @@ export async function execRemoveProtectedRoom(roomId: string, event: any, mjolni
     try {
         await mjolnir.client.leaveRoom(protectedRoomId);
     } catch (e) {
-        LogService.warn("AddRemoveProtectedRoomsCommand", extractRequestError(e));
+        LogService.warn("AddRemoveProtectedRoomsCommand", e);
         await mjolnir.managementRoomOutput.logMessage(LogLevel.WARN, "AddRemoveProtectedRoomsCommand", `Failed to leave ${protectedRoomId} - the room is no longer being protected, but the bot could not leave`, protectedRoomId);
     }
     await mjolnir.client.unstableApis.addReactionToEvent(roomId, event['event_id'], '✅');

src/commands/CommandHandler.ts

@@ -29,7 +29,7 @@ import { Mjolnir } from "../Mjolnir";
 import { execStatusCommand } from "./StatusCommand";
 import "./UnbanBanCommand";
 import { execDumpRulesCommand, execRulesMatchingCommand } from "./DumpRulesCommand";
-import { extractRequestError, LogService, RichReply } from "matrix-bot-sdk";
+import { LogService, RichReply } from "matrix-bot-sdk";
 import { htmlEscape } from "../utils";
 import { execSyncCommand } from "./SyncCommand";
 import { execPermissionCheckCommand } from "./PermissionCheckCommand";
@@ -58,6 +58,8 @@ import { findMatrixInterfaceAdaptor, MatrixContext } from "./interface-manager/M
 import { ArgumentStream } from "./interface-manager/ParamaterParsing";
 import { execBanCommand, execUnbanCommand } from "./UnbanBanCommand";
 import { CommandResult } from "./interface-manager/Validation";
+import { CommandException } from "./interface-manager/CommandException";
+import { tickCrossRenderer } from "./interface-manager/MatrixHelpRenderer";
 
 export interface MjolnirContext extends MatrixContext {
     mjolnir: Mjolnir,
@@ -66,9 +68,8 @@ export interface MjolnirContext extends MatrixContext {
 export type MjolnirBaseExecutor = (this: MjolnirContext, ...args: any[]) => Promise<CommandResult<any>>;
 
 defineCommandTable("mjolnir");
+import "./interface-manager/MatrixPresentations";
 import "./MakeRoomAdminCommand";
-import { CommandException } from "./interface-manager/CommandException";
-import { tickCrossRenderer } from "./interface-manager/MatrixHelpRenderer";
 
 export const COMMAND_PREFIX = "!mjolnir";
 
@@ -214,7 +215,7 @@ export async function handleCommand(roomId: string, event: { content: { body: st
             return await mjolnir.client.sendMessage(roomId, reply);
         }
     } catch (e) {
-        LogService.error("CommandHandler", extractRequestError(e));
+        LogService.error("CommandHandler", e);
         const text = "There was an error processing your command - see console/log for details";
         const reply = RichReply.createFor(roomId, event, text, text);
         reply["msgtype"] = "m.notice";

src/commands/ProtectionsCommands.ts

@@ -27,7 +27,7 @@ limitations under the License.
 
 import { htmlEscape } from "../utils";
 import { Mjolnir } from "../Mjolnir";
-import { extractRequestError, LogService, RichReply } from "matrix-bot-sdk";
+import { LogService, RichReply } from "matrix-bot-sdk";
 import { isListSetting } from "../protections/ProtectionSettings";
 
 // !mjolnir enable <protection>
@@ -36,7 +36,7 @@ export async function execEnableProtection(roomId: string, event: any, mjolnir:
         await mjolnir.protectionManager.enableProtection(parts[2]);
         await mjolnir.client.unstableApis.addReactionToEvent(roomId, event['event_id'], '✅');
     } catch (e) {
-        LogService.error("ProtectionsCommands", extractRequestError(e));
+        LogService.error("ProtectionsCommands", e);
 
         const message = `Error enabling protection '${parts[0]}' - check the name and try again.`;
         const reply = RichReply.createFor(roomId, event, message, message);

src/commands/SetPowerLevelCommand.ts

@@ -26,7 +26,7 @@ limitations under the License.
  */
 
 import { Mjolnir } from "../Mjolnir";
-import { extractRequestError, LogLevel, LogService } from "matrix-bot-sdk";
+import { LogLevel, LogService } from "matrix-bot-sdk";
 
 // !mjolnir powerlevel <user ID> <level> [room]
 export async function execSetPowerLevelCommand(roomId: string, event: any, mjolnir: Mjolnir, parts: string[]) {
@@ -41,8 +41,8 @@ export async function execSetPowerLevelCommand(roomId: string, event: any, mjoln
             await mjolnir.client.setUserPowerLevel(victim, targetRoomId, level);
         } catch (e) {
             const message = e.message || (e.body ? e.body.error : '<no message>');
+            LogService.error("SetPowerLevelCommand", e);
             await mjolnir.managementRoomOutput.logMessage(LogLevel.ERROR, "SetPowerLevelCommand", `Failed to set power level of ${victim} to ${level} in ${targetRoomId}: ${message}`, targetRoomId);
-            LogService.error("SetPowerLevelCommand", extractRequestError(e));
         }
     }
 

src/commands/UnbanBanCommand.ts

@@ -27,7 +27,7 @@ limitations under the License.
 
 import { Mjolnir } from "../Mjolnir";
 import PolicyList from "../models/PolicyList";
-import { extractRequestError, LogLevel, LogService, MatrixGlob, RichReply } from "matrix-bot-sdk";
+import { LogLevel, LogService, MatrixGlob, RichReply } from "matrix-bot-sdk";
 import { RULE_ROOM, RULE_SERVER, RULE_USER, USER_RULE_TYPES } from "../models/ListRule";
 import { DEFAULT_LIST_EVENT_TYPE } from "./SetDefaultBanListCommand";
 
@@ -45,9 +45,7 @@ export async function parseArguments(roomId: string, event: any, mjolnir: Mjolni
         const data: { shortcode: string } = await mjolnir.client.getAccountData(DEFAULT_LIST_EVENT_TYPE);
         defaultShortcode = data['shortcode'];
     } catch (e) {
-        LogService.warn("UnbanBanCommand", "Non-fatal error getting default ban list");
-        LogService.warn("UnbanBanCommand", extractRequestError(e));
-
+        LogService.warn("UnbanBanCommand", "Non-fatal error getting default ban list:", e);
         // Assume no default.
     }
 

src/config.ts

@@ -59,6 +59,7 @@ export interface IConfig {
     managementRoom: string;
     verboseLogging: boolean;
     logLevel: "DEBUG" | "INFO" | "WARN" | "ERROR";
+    logMutedModules: string[],
     syncOnStartup: boolean;
     verifyPermissionsOnStartup: boolean;
     noop: boolean;
@@ -149,6 +150,7 @@ const defaultConfig: IConfig = {
     managementRoom: "!noop:example.org",
     verboseLogging: false,
     logLevel: "INFO",
+    logMutedModules: ['MatrixHttpClient', 'MatrixClientLite'],
     syncOnStartup: true,
     verifyPermissionsOnStartup: true,
     noop: false,

src/models/PolicyList.ts

@@ -25,7 +25,7 @@ limitations under the License.
  * are NOT distributed, contributed, committed, or licensed under the Apache License.
  */
 
-import { extractRequestError, LogService, RoomCreateOptions, UserID } from "matrix-bot-sdk";
+import { LogService, RoomCreateOptions, UserID } from "matrix-bot-sdk";
 import { EventEmitter } from "events";
 import { ALL_RULE_TYPES, EntityType, ListRule, Recommendation, ROOM_RULE_TYPES, RULE_ROOM, RULE_SERVER, RULE_USER, SERVER_RULE_TYPES, USER_RULE_TYPES } from "./ListRule";
 import { MatrixSendClient } from "../MatrixEmitter";
@@ -250,15 +250,6 @@ class PolicyList extends EventEmitter {
         return rules;
     }
 
-    public set listShortcode(newShortcode: string) {
-        const currentShortcode = this.shortcode;
-        this.shortcode = newShortcode;
-        this.client.sendStateEvent(this.roomId, SHORTCODE_EVENT_TYPE, '', { shortcode: this.shortcode }).catch(err => {
-            LogService.error("PolicyList", extractRequestError(err));
-            if (this.shortcode === newShortcode) this.shortcode = currentShortcode;
-        });
-    }
-
     public get serverRules(): ListRule[] {
         return this.rulesOfKind(RULE_SERVER);
     }

src/protections/ProtectionManager.ts

@@ -35,7 +35,7 @@ import { MessageIsMedia } from "./MessageIsMedia";
 import { TrustedReporters } from "./TrustedReporters";
 import { JoinWaveShortCircuit } from "./JoinWaveShortCircuit";
 import { Mjolnir } from "../Mjolnir";
-import { extractRequestError, LogLevel, LogService, Permalinks } from "matrix-bot-sdk";
+import { LogLevel, LogService, Permalinks } from "matrix-bot-sdk";
 import { ProtectionSettingValidationError } from "./ProtectionSettings";
 import { Consequence } from "./consequence";
 import { htmlEscape } from "../utils";
@@ -80,7 +80,11 @@ export class ProtectionManager {
             try {
                 await this.registerProtection(protection);
             } catch (e) {
-                this.mjolnir.managementRoomOutput.logMessage(LogLevel.WARN, "ProtectionManager", extractRequestError(e));
+                LogService.error("ProtectionManager", `Unable to start protection ${protection.name}`, e);
+                this.mjolnir.managementRoomOutput.logMessage(
+                    LogLevel.WARN, "ProtectionManager", `Unable to start protection ${protection.name}`
+                );
+
             }
         }
     }
@@ -292,7 +296,7 @@ export class ProtectionManager {
                     const eventPermalink = Permalinks.forEvent(roomId, event['event_id']);
                     LogService.error("ProtectionManager", "Error handling protection: " + protection.name);
                     LogService.error("ProtectionManager", "Failed event: " + eventPermalink);
-                    LogService.error("ProtectionManager", extractRequestError(e));
+                    LogService.error("ProtectionManager", e);
                     await this.mjolnir.client.sendNotice(this.mjolnir.managementRoomId, "There was an error processing an event through a protection - see log for details. Event: " + eventPermalink);
                     continue;
                 }
@@ -389,7 +393,7 @@ export class ProtectionManager {
 
             // Otherwise OK
         } catch (e) {
-            LogService.error("Mjolnir", extractRequestError(e));
+            LogService.error("Mjolnir", e);
             errors.push({
                 roomId,
                 errorMessage: e.message || (e.body ? e.body.error : '<no message>'),

src/queues/ThrottlingQueue.ts

@@ -25,7 +25,7 @@ limitations under the License.
  * are NOT distributed, contributed, committed, or licensed under the Apache License.
  */
 
-import { extractRequestError, LogLevel } from "matrix-bot-sdk";
+import { LogLevel } from "matrix-bot-sdk";
 import { Mjolnir } from "../Mjolnir";
 
 export type Task<T> = (queue: ThrottlingQueue) => Promise<T>;
@@ -192,7 +192,7 @@ export class ThrottlingQueue {
             await this.mjolnir.managementRoomOutput.logMessage(
                 LogLevel.WARN,
                 'Error while executing task',
-                extractRequestError(ex)
+                ex
             );
         } finally {
             this.stop();

src/queues/UnlistedUserRedactionQueue.ts

@@ -24,7 +24,7 @@ limitations under the License.
  * However, this file is modified and the modifications in this file
  * are NOT distributed, contributed, committed, or licensed under the Apache License.
  */
-import { extractRequestError, LogLevel, LogService, Permalinks } from "matrix-bot-sdk";
+import { LogLevel, LogService, Permalinks } from "matrix-bot-sdk";
 import { Mjolnir } from "../Mjolnir";
 
 /**
@@ -64,7 +64,7 @@ export class UnlistedUserRedactionQueue {
                 }
             } catch (e) {
                 mjolnir.managementRoomOutput.logMessage(LogLevel.WARN, "AutomaticRedactionQueue", `Unable to redact message: ${permalink}`);
-                LogService.warn("AutomaticRedactionQueue", extractRequestError(e));
+                LogService.warn("AutomaticRedactionQueue", e);
             }
         }
     }

src/utils.ts

@@ -31,6 +31,7 @@ import {
     MatrixGlob,
     getRequestFn,
     setRequestFn,
+    MatrixError,
 } from "matrix-bot-sdk";
 import { ClientRequest, IncomingMessage } from "http";
 import { default as parseDuration } from "parse-duration";
@@ -213,6 +214,15 @@ export async function getMessagesByUserIn(client: MatrixSendClient, sender: stri
 
 let isMatrixClientPatchedForConciseExceptions = false;
 
+// The fact that MatrixHttpClient logs every http error as error
+// is unacceptable really.
+// We will provide our own utility for logging outgoing requests as debug.
+LogService.muteModule("MatrixHttpClient");
+
+function isMatrixError(path: string): boolean {
+    return /^\/_matrix/.test(path)
+}
+
 /**
  * Patch `MatrixClient` into something that throws concise exceptions.
  *
@@ -270,23 +280,17 @@ function patchMatrixClientForConciseExceptions() {
             // of `Error`. The former take ~800 lines of log and
             // provide no stack trace, which makes them typically
             // useless.
-            let method: string | null = null;
-            let path = '';
+            const method: string | undefined = err.method
+                ? err.method
+                : "req" in err && err.req instanceof ClientRequest
+                ? err.req.method
+                : params.method;
+            const path: string = err.url
+                ? err.url
+                : "req" in err && err.req instanceof ClientRequest
+                ? err.req.path
+                : params.uri ?? '';
             let body: unknown = null;
-            if (err.method) {
-                method = err.method;
-            }
-            if (err.url) {
-                path = err.url;
-            }
-            if ("req" in err && err.req instanceof ClientRequest) {
-                if (!method) {
-                    method = err.req.method;
-                }
-                if (!path) {
-                    path = err.req.path;
-                }
-            }
             if ("body" in err) {
                 body = err.body;
             }
@@ -317,11 +321,17 @@ function patchMatrixClientForConciseExceptions() {
                     enumerable: false,
                 });
             }
-            if (!LogService.level.includes(LogLevel.TRACE)) {
-                // Remove stack trace to reduce impact on logs.
-                error.stack = "";
+            // matrix-appservice-bridge depends on errors being matrix-bot-sdk's MatrixError.
+            // Since https://github.com/turt2live/matrix-bot-sdk/blob/836c2da7145668b20af7e0d75094b6162164f3dc/src/http.ts#L109
+            // we wrote this, matrix-bot-sdk has updated so that there is now a MatrixError that is thrown
+            // when there are errors in the response.
+            if (isMatrixError(path)) {
+                const matrixError = new MatrixError(body as any, err.statusCode as any);
+                matrixError.stack = error.stack;
+                return cb(matrixError, response, resBody)
+            } else {
+                return cb(error, response, resBody);
             }
-            return cb(error, response, resBody);
         })
     });
     isMatrixClientPatchedForConciseExceptions = true;
@@ -434,7 +444,7 @@ function patchMatrixClientForPrototypePollution() {
                 }
             }
 
-            if (typeof response.body === 'string') {
+            if (typeof response?.body === 'string') {
                 try {
                     response.body = JSON.parse(response.body, jsonReviver);
                 } catch (e) {