From 84135c5ff57af2703929faa99a0f25fe43a771f2 Mon Sep 17 00:00:00 2001 From: Travis Ralston Date: Wed, 6 Nov 2019 18:46:49 -0700 Subject: [PATCH] Update log handling for debugging --- src/LogProxy.ts | 36 +++++++++++++++++++++++++++++++++ src/Mjolnir.ts | 31 ++++++++++++---------------- src/actions/ApplyAcl.ts | 20 +++++++++--------- src/actions/ApplyBan.ts | 18 ++++++++--------- src/commands/CommandHandler.ts | 2 +- src/commands/ImportCommand.ts | 5 +++-- src/commands/RedactCommand.ts | 12 +++++------ src/commands/UnbanBanCommand.ts | 17 ++++++++-------- src/config.ts | 9 +++++++++ src/index.ts | 11 +++++++--- 10 files changed, 103 insertions(+), 58 deletions(-) create mode 100644 src/LogProxy.ts diff --git a/src/LogProxy.ts b/src/LogProxy.ts new file mode 100644 index 0000000..1ca0006 --- /dev/null +++ b/src/LogProxy.ts @@ -0,0 +1,36 @@ +/* +Copyright 2019 The Matrix.org Foundation C.I.C. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +import { LogLevel, LogService } from "matrix-bot-sdk"; +import config from "./config"; + +const levelToFn = { + [LogLevel.DEBUG.toString()]: LogService.debug, + [LogLevel.INFO.toString()]: LogService.info, + [LogLevel.WARN.toString()]: LogService.warn, + [LogLevel.ERROR.toString()]: LogService.error, +}; + +export async function logMessage(level: LogLevel, module: string, message: string | any) { + if (config.RUNTIME.client && (config.verboseLogging || LogLevel.INFO.includes(level))) { + let clientMessage = message; + if (level === LogLevel.WARN) clientMessage = `⚠ | ${message}`; + if (level === LogLevel.ERROR) clientMessage = `‼ | ${message}`; + await config.RUNTIME.client.sendNotice(config.managementRoom, clientMessage); + } + + levelToFn[level.toString()](module, message); +} diff --git a/src/Mjolnir.ts b/src/Mjolnir.ts index 83df629..564b4e3 100644 --- a/src/Mjolnir.ts +++ b/src/Mjolnir.ts @@ -14,13 +14,14 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { LogService, MatrixClient, Permalinks } from "matrix-bot-sdk"; +import { LogLevel, LogService, MatrixClient, Permalinks } from "matrix-bot-sdk"; import BanList, { ALL_RULE_TYPES } from "./models/BanList"; import { applyServerAcls } from "./actions/ApplyAcl"; import { RoomUpdateError } from "./models/RoomUpdateError"; import { COMMAND_PREFIX, handleCommand } from "./commands/CommandHandler"; import { applyUserBans } from "./actions/ApplyBan"; import config from "./config"; +import { logMessage } from "./LogProxy"; export const STATE_NOT_STARTED = "not_started"; export const STATE_CHECKING_PERMISSIONS = "checking_permissions"; @@ -37,14 +38,13 @@ export class Mjolnir { constructor( public readonly client: MatrixClient, - public readonly managementRoomId: string, public readonly protectedRooms: { [roomId: string]: string }, private banLists: BanList[], ) { client.on("room.event", this.handleEvent.bind(this)); client.on("room.message", async (roomId, event) => { - if (roomId !== managementRoomId) return; + if (roomId !== config.managementRoom) return; if (!event['content']) return; const content = event['content']; @@ -55,6 +55,7 @@ export class Mjolnir { // rewrite the event body to make the prefix uniform (in case the bot has spaces in its display name) event['content']['body'] = COMMAND_PREFIX + content['body'].substring(prefixUsed.length); + LogService.info("Mjolnir", `Command being run by ${event['sender']}: ${event['content']['body']}`); await client.sendReadReceipt(roomId, event['event_id']); return handleCommand(roomId, event, this); @@ -83,25 +84,19 @@ export class Mjolnir { return this.client.start().then(async () => { this.currentState = STATE_CHECKING_PERMISSIONS; if (config.verifyPermissionsOnStartup) { - if (config.verboseLogging) { - await this.client.sendNotice(this.managementRoomId, "Checking permissions..."); - } + await logMessage(LogLevel.INFO, "Mjolnir@startup", "Checking permissions..."); await this.verifyPermissions(config.verboseLogging); } }).then(async () => { this.currentState = STATE_SYNCING; if (config.syncOnStartup) { - if (config.verboseLogging) { - await this.client.sendNotice(this.managementRoomId, "Syncing lists..."); - } + await logMessage(LogLevel.INFO, "Mjolnir@startup", "Syncing lists..."); await this.buildWatchedBanLists(); await this.syncLists(config.verboseLogging); } }).then(async () => { this.currentState = STATE_RUNNING; - if (config.verboseLogging) { - await this.client.sendNotice(this.managementRoomId, "Startup complete."); - } + await logMessage(LogLevel.INFO, "Mjolnir@startup", "Startup complete. Now monitoring rooms."); }); } @@ -181,7 +176,7 @@ export class Mjolnir { if (!hadErrors && verbose) { const html = `All permissions look OK.`; const text = "All permissions look OK."; - await this.client.sendMessage(this.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", @@ -257,7 +252,7 @@ export class Mjolnir { if (!hadErrors && verbose) { const html = `Done updating rooms - no errors`; const text = "Done updating rooms - no errors"; - await this.client.sendMessage(this.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", @@ -285,7 +280,7 @@ export class Mjolnir { if (!hadErrors) { const html = `Done updating rooms - no errors`; const text = "Done updating rooms - no errors"; - await this.client.sendMessage(this.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", @@ -302,7 +297,7 @@ export class Mjolnir { const url = this.protectedRooms[roomId]; let html = `Power levels changed in ${roomId} - checking permissions...`; let text = `Power levels changed in ${url} - checking permissions...`; - await this.client.sendMessage(this.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", @@ -313,7 +308,7 @@ export class Mjolnir { if (!hadErrors) { html = `All permissions look OK.`; text = "All permissions look OK."; - await this.client.sendMessage(this.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", @@ -358,7 +353,7 @@ export class Mjolnir { format: "org.matrix.custom.html", formatted_body: html, }; - await this.client.sendMessage(this.managementRoomId, message); + await this.client.sendMessage(config.managementRoom, message); return true; } } diff --git a/src/actions/ApplyAcl.ts b/src/actions/ApplyAcl.ts index dda4927..232daf8 100644 --- a/src/actions/ApplyAcl.ts +++ b/src/actions/ApplyAcl.ts @@ -19,6 +19,8 @@ import { ServerAcl } from "../models/ServerAcl"; import { RoomUpdateError } from "../models/RoomUpdateError"; import { Mjolnir } from "../Mjolnir"; import config from "../config"; +import { LogLevel } from "matrix-bot-sdk"; +import { logMessage } from "../LogProxy"; /** * Applies the server ACLs represented by the ban lists to the provided rooms, returning the @@ -40,35 +42,31 @@ export async function applyServerAcls(lists: BanList[], roomIds: string[], mjoln if (config.verboseLogging) { // We specifically use sendNotice to avoid having to escape HTML - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Constructed server ACL:\n${JSON.stringify(finalAcl, null, 2)}`); + await mjolnir.client.sendNotice(config.managementRoom, `Constructed server ACL:\n${JSON.stringify(finalAcl, null, 2)}`); } const errors: RoomUpdateError[] = []; for (const roomId of roomIds) { try { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Checking ACLs for ${roomId}`); - } + await logMessage(LogLevel.DEBUG, "ApplyAcl", `Checking ACLs for ${roomId}`); try { const currentAcl = await mjolnir.client.getRoomStateEvent(roomId, "m.room.server_acl", ""); if (acl.matches(currentAcl)) { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Skipping ACLs for ${roomId} because they are already the right ones`); - } + await logMessage(LogLevel.DEBUG, "ApplyAcl", `Skipping ACLs for ${roomId} because they are already the right ones`); continue; } } catch (e) { // ignore - assume no ACL } - if (config.verboseLogging) { - // We specifically use sendNotice to avoid having to escape HTML - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Applying ACL in ${roomId}`); - } + // We specifically use sendNotice to avoid having to escape HTML + await logMessage(LogLevel.DEBUG, "ApplyAcl", `Applying ACL in ${roomId}`); if (!config.noop) { await mjolnir.client.sendStateEvent(roomId, "m.room.server_acl", "", finalAcl); + } else { + await logMessage(LogLevel.WARN, "ApplyAcl", `Tried to apply ACL in ${roomId} but Mjolnir is running in no-op mode`); } } catch (e) { errors.push({roomId, errorMessage: e.message || (e.body ? e.body.error : '')}); diff --git a/src/actions/ApplyBan.ts b/src/actions/ApplyBan.ts index a80fda9..6d4b991 100644 --- a/src/actions/ApplyBan.ts +++ b/src/actions/ApplyBan.ts @@ -18,6 +18,8 @@ import BanList from "../models/BanList"; import { RoomUpdateError } from "../models/RoomUpdateError"; import { Mjolnir } from "../Mjolnir"; import config from "../config"; +import { logMessage } from "../LogProxy"; +import { LogLevel } from "matrix-bot-sdk"; /** * Applies the member bans represented by the ban lists to the provided rooms, returning the @@ -32,10 +34,8 @@ export async function applyUserBans(lists: BanList[], roomIds: string[], mjolnir let bansApplied = 0; for (const roomId of roomIds) { try { - if (config.verboseLogging) { - // We specifically use sendNotice to avoid having to escape HTML - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Updating member bans in ${roomId}`); - } + // We specifically use sendNotice to avoid having to escape HTML + await logMessage(LogLevel.DEBUG, "ApplyBan", `Updating member bans in ${roomId}`); const state = await mjolnir.client.getRoomState(roomId); const members = state.filter(s => s['type'] === 'm.room.member' && !!s['state_key']); @@ -54,13 +54,13 @@ export async function applyUserBans(lists: BanList[], roomIds: string[], mjolnir if (userRule.isMatch(member['state_key'])) { // User needs to be banned - if (config.verboseLogging) { - // We specifically use sendNotice to avoid having to escape HTML - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Banning ${member['state_key']} in ${roomId} for: ${userRule.reason}`); - } + // We specifically use sendNotice to avoid having to escape HTML + await logMessage(LogLevel.DEBUG, "ApplyBan", `Banning ${member['state_key']} in ${roomId} for: ${userRule.reason}`); if (!config.noop) { await mjolnir.client.banUser(member['state_key'], roomId, userRule.reason); + } else { + await logMessage(LogLevel.WARN, "ApplyBan", `Tried to ban ${member['state_key']} in ${roomId} but Mjolnir is running in no-op mode`); } bansApplied++; @@ -79,7 +79,7 @@ export async function applyUserBans(lists: BanList[], roomIds: string[], mjolnir if (bansApplied > 0) { const html = `Banned ${bansApplied} people`; const text = `Banned ${bansApplied} people`; - await this.client.sendMessage(mjolnir.managementRoomId, { + await this.client.sendMessage(config.managementRoom, { msgtype: "m.notice", body: text, format: "org.matrix.custom.html", diff --git a/src/commands/CommandHandler.ts b/src/commands/CommandHandler.ts index 3e338c7..5bc43a9 100644 --- a/src/commands/CommandHandler.ts +++ b/src/commands/CommandHandler.ts @@ -83,6 +83,6 @@ export async function handleCommand(roomId: string, event: any, mjolnir: Mjolnir 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"; - return mjolnir.client.sendMessage(roomId, reply); + return await mjolnir.client.sendMessage(roomId, reply); } } diff --git a/src/commands/ImportCommand.ts b/src/commands/ImportCommand.ts index 784102a..d7e67c3 100644 --- a/src/commands/ImportCommand.ts +++ b/src/commands/ImportCommand.ts @@ -18,6 +18,7 @@ import { Mjolnir } from "../Mjolnir"; import { RichReply } from "matrix-bot-sdk"; import { RECOMMENDATION_BAN, recommendationToStable } from "../models/ListRule"; import { RULE_SERVER, RULE_USER, ruleTypeToStable } from "../models/BanList"; +import config from "../config"; // !mjolnir import export async function execImportCommand(roomId: string, event: any, mjolnir: Mjolnir, parts: string[]) { @@ -42,7 +43,7 @@ export async function execImportCommand(roomId: string, event: any, mjolnir: Mjo if (content['membership'] === 'ban') { const reason = content['reason'] || ''; - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Adding user ${stateEvent['state_key']} to ban list`); + await mjolnir.client.sendNotice(config.managementRoom, `Adding user ${stateEvent['state_key']} to ban list`); const recommendation = recommendationToStable(RECOMMENDATION_BAN); const ruleContent = { @@ -60,7 +61,7 @@ export async function execImportCommand(roomId: string, event: any, mjolnir: Mjo for (const server of content['deny']) { const reason = ""; - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Adding server ${server} to ban list`); + await mjolnir.client.sendNotice(config.managementRoom, `Adding server ${server} to ban list`); const recommendation = recommendationToStable(RECOMMENDATION_BAN); const ruleContent = { diff --git a/src/commands/RedactCommand.ts b/src/commands/RedactCommand.ts index aa13c6b..a5dbe33 100644 --- a/src/commands/RedactCommand.ts +++ b/src/commands/RedactCommand.ts @@ -17,6 +17,8 @@ limitations under the License. import { Mjolnir } from "../Mjolnir"; import { getMessagesByUserSinceLastJoin } from "../utils"; import config from "../config"; +import { logMessage } from "../LogProxy"; +import { LogLevel } from "matrix-bot-sdk"; // !mjolnir redact [room alias] export async function execRedactCommand(roomId: string, event: any, mjolnir: Mjolnir, parts: string[]) { @@ -28,17 +30,15 @@ export async function execRedactCommand(roomId: string, event: any, mjolnir: Mjo const targetRoomIds = roomAlias ? [roomAlias] : Object.keys(mjolnir.protectedRooms); for (const targetRoomId of targetRoomIds) { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Fetching sent messages for ${userId} in ${targetRoomId} to redact...`); - } + await logMessage(LogLevel.DEBUG, "RedactCommand", `Fetching sent messages for ${userId} in ${targetRoomId} to redact...`); const eventsToRedact = await getMessagesByUserSinceLastJoin(mjolnir.client, userId, targetRoomId); for (const victimEvent of eventsToRedact) { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Redacting ${victimEvent['event_id']} in ${targetRoomId}`); - } + await logMessage(LogLevel.DEBUG, "RedactCommand", `Redacting ${victimEvent['event_id']} in ${targetRoomId}`); if (!config.noop) { await mjolnir.client.redactEvent(targetRoomId, victimEvent['event_id']); + } else { + await logMessage(LogLevel.WARN, "RedactCommand", `Tried to redact ${victimEvent['event_id']} in ${targetRoomId} but Mjolnir is running in no-op mode`); } } } diff --git a/src/commands/UnbanBanCommand.ts b/src/commands/UnbanBanCommand.ts index ea0d69e..85f81b8 100644 --- a/src/commands/UnbanBanCommand.ts +++ b/src/commands/UnbanBanCommand.ts @@ -16,10 +16,11 @@ limitations under the License. import { Mjolnir } from "../Mjolnir"; import { RULE_ROOM, RULE_SERVER, RULE_USER, ruleTypeToStable, USER_RULE_TYPES } from "../models/BanList"; -import { RichReply } from "matrix-bot-sdk"; +import { LogLevel, RichReply } from "matrix-bot-sdk"; import { RECOMMENDATION_BAN, recommendationToStable } from "../models/ListRule"; import { MatrixGlob } from "matrix-bot-sdk/lib/MatrixGlob"; import config from "../config"; +import { logMessage } from "../LogProxy"; function parseBits(parts: string[]): { listShortcode: string, entityType: string, ruleType: string, glob: string, reason: string } { const shortcode = parts[2].toLowerCase(); @@ -98,7 +99,7 @@ export async function execUnbanCommand(roomId: string, event: any, mjolnir: Mjol if (USER_RULE_TYPES.includes(bits.ruleType) && parts.length > 5 && parts[5] === 'true') { const rule = new MatrixGlob(bits.glob); - await mjolnir.client.sendNotice(mjolnir.managementRoomId, "Unbanning users that match glob: " + bits.glob); + await logMessage(LogLevel.INFO, "UnbanBanCommand", "Unbanning users that match glob: " + bits.glob); let unbannedSomeone = false; for (const protectedRoomId of Object.keys(mjolnir.protectedRooms)) { const members = await mjolnir.client.getMembers(protectedRoomId, null, ['ban'], null); @@ -106,21 +107,21 @@ export async function execUnbanCommand(roomId: string, event: any, mjolnir: Mjol const victim = member['state_key']; if (!member['content'] || member['content']['membership'] !== 'ban') continue; if (rule.test(victim)) { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Unbanning ${victim} in ${protectedRoomId}`); - } + await logMessage(LogLevel.DEBUG, "UnbanBanCommand", `Unbanning ${victim} in ${protectedRoomId}`); + if (!config.noop) { await mjolnir.client.unbanUser(victim, protectedRoomId); + } else { + await logMessage(LogLevel.WARN, "UnbanBanCommand", `Attempted to unban ${victim} in ${protectedRoomId} but Mjolnir is running in no-op mode`); } + unbannedSomeone = true; } } } if (unbannedSomeone) { - if (config.verboseLogging) { - await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Syncing lists to ensure no users were accidentally unbanned`); - } + await logMessage(LogLevel.DEBUG, "UnbanBanCommand", `Syncing lists to ensure no users were accidentally unbanned`); await mjolnir.syncLists(config.verboseLogging); } } diff --git a/src/config.ts b/src/config.ts index 32ce24b..50a6b2e 100644 --- a/src/config.ts +++ b/src/config.ts @@ -15,6 +15,7 @@ limitations under the License. */ import * as config from "config"; +import { MatrixClient } from "matrix-bot-sdk"; interface IConfig { homeserverUrl: string; @@ -33,6 +34,14 @@ interface IConfig { verifyPermissionsOnStartup: boolean; noop: boolean; protectedRooms: string[]; // matrix.to urls + + /** + * Config options only set at runtime. Try to avoid using the objects + * here as much as possible. + */ + RUNTIME: { + client: MatrixClient; + }; } export default config; diff --git a/src/index.ts b/src/index.ts index 6ff9685..d1be023 100644 --- a/src/index.ts +++ b/src/index.ts @@ -28,6 +28,9 @@ import { import config from "./config"; import BanList from "./models/BanList"; import { Mjolnir } from "./Mjolnir"; +import { logMessage } from "./LogProxy"; + +config.RUNTIME = {client: null}; LogService.setLogger(new RichConsoleLogger()); LogService.setLevel(LogLevel.fromString(config.logLevel, LogLevel.DEBUG)); @@ -45,6 +48,8 @@ LogService.info("index", "Starting bot..."); client = new MatrixClient(config.homeserverUrl, config.accessToken, storage); } + config.RUNTIME.client = client; + if (config.autojoin) { AutojoinRoomsMixin.setupOnClient(client); } @@ -68,9 +73,9 @@ LogService.info("index", "Starting bot..."); } // Ensure we're also in the management room - const managementRoomId = await client.joinRoom(config.managementRoom); - await client.sendNotice(managementRoomId, "Mjolnir is starting up. Use !mjolnir to query status."); + config.managementRoom = await client.joinRoom(config.managementRoom); + await logMessage(LogLevel.INFO, "index", "Mjolnir is starting up. Use !mjolnir to query status."); - const bot = new Mjolnir(client, managementRoomId, protectedRooms, banLists); + const bot = new Mjolnir(client, protectedRooms, banLists); await bot.start(); })();