From 72f554ef2e1f9354949fb9258e4f556ea03dae97 Mon Sep 17 00:00:00 2001 From: gnuxie Date: Tue, 31 Jan 2023 17:58:17 +0000 Subject: [PATCH] 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 | 4 +- src/Mjolnir.ts | 17 ++++-- src/ProtectedRoomsConfig.ts | 6 +-- .../AddRemoveProtectedRoomsCommand.ts | 4 +- src/commands/CommandHandler.ts | 9 ++-- src/commands/ProtectionsCommands.ts | 4 +- src/commands/SetPowerLevelCommand.ts | 4 +- src/commands/UnbanBanCommand.ts | 6 +-- src/config.ts | 2 + src/models/PolicyList.ts | 11 +--- src/protections/ProtectionManager.ts | 12 +++-- src/queues/ThrottlingQueue.ts | 4 +- src/queues/UnlistedUserRedactionQueue.ts | 4 +- src/utils.ts | 52 +++++++++++-------- 14 files changed, 76 insertions(+), 63 deletions(-) diff --git a/src/ManagementRoomOutput.ts b/src/ManagementRoomOutput.ts index 3db1f82e..a0eabd18 100644 --- a/src/ManagementRoomOutput.ts +++ b/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); diff --git a/src/Mjolnir.ts b/src/Mjolnir.ts index 2ed247a6..b6d78742 100644 --- a/src/Mjolnir.ts +++ b/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; } diff --git a/src/ProtectedRoomsConfig.ts b/src/ProtectedRoomsConfig.ts index 39441c7d..4211e1a8 100644 --- a/src/ProtectedRoomsConfig.ts +++ b/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); diff --git a/src/commands/AddRemoveProtectedRoomsCommand.ts b/src/commands/AddRemoveProtectedRoomsCommand.ts index b060a3b1..d8221cba 100644 --- a/src/commands/AddRemoveProtectedRoomsCommand.ts +++ b/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 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'], '✅'); diff --git a/src/commands/CommandHandler.ts b/src/commands/CommandHandler.ts index 86cd87d0..fa865135 100644 --- a/src/commands/CommandHandler.ts +++ b/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>; 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"; diff --git a/src/commands/ProtectionsCommands.ts b/src/commands/ProtectionsCommands.ts index 52e88c43..2dd910a7 100644 --- a/src/commands/ProtectionsCommands.ts +++ b/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 @@ -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); diff --git a/src/commands/SetPowerLevelCommand.ts b/src/commands/SetPowerLevelCommand.ts index 6edc4ba6..759258e3 100644 --- a/src/commands/SetPowerLevelCommand.ts +++ b/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 [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 : ''); + 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)); } } diff --git a/src/commands/UnbanBanCommand.ts b/src/commands/UnbanBanCommand.ts index 7ad03324..39bec5d3 100644 --- a/src/commands/UnbanBanCommand.ts +++ b/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. } diff --git a/src/config.ts b/src/config.ts index c22f1e4e..c6daf75b 100644 --- a/src/config.ts +++ b/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, diff --git a/src/models/PolicyList.ts b/src/models/PolicyList.ts index 27d638a2..e22e9371 100644 --- a/src/models/PolicyList.ts +++ b/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); } diff --git a/src/protections/ProtectionManager.ts b/src/protections/ProtectionManager.ts index 5c1d3d19..866d5e30 100644 --- a/src/protections/ProtectionManager.ts +++ b/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 : ''), diff --git a/src/queues/ThrottlingQueue.ts b/src/queues/ThrottlingQueue.ts index a3b91a96..ce526469 100644 --- a/src/queues/ThrottlingQueue.ts +++ b/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 = (queue: ThrottlingQueue) => Promise; @@ -192,7 +192,7 @@ export class ThrottlingQueue { await this.mjolnir.managementRoomOutput.logMessage( LogLevel.WARN, 'Error while executing task', - extractRequestError(ex) + ex ); } finally { this.stop(); diff --git a/src/queues/UnlistedUserRedactionQueue.ts b/src/queues/UnlistedUserRedactionQueue.ts index 3c2c91df..62e011bb 100644 --- a/src/queues/UnlistedUserRedactionQueue.ts +++ b/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); } } } diff --git a/src/utils.ts b/src/utils.ts index 328990ea..c526fe79 100644 --- a/src/utils.ts +++ b/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) {