Update log handling for debugging

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

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 logMessage(LogLevel.INFO, "Mjolnir@startup", "Checking permissions...");
-                    await this.client.sendNotice(this.managementRoomId, "Checking permissions...");
-                }
                 await this.verifyPermissions(config.verboseLogging);
             }
         }).then(async () => {
             this.currentState = STATE_SYNCING;
             if (config.syncOnStartup) {
-                if (config.verboseLogging) {
+                await logMessage(LogLevel.INFO, "Mjolnir@startup", "Syncing lists...");
-                    await this.client.sendNotice(this.managementRoomId, "Syncing lists...");
-                }
                 await this.buildWatchedBanLists();
                 await this.syncLists(config.verboseLogging);
             }
         }).then(async () => {
             this.currentState = STATE_RUNNING;
-            if (config.verboseLogging) {
+            await logMessage(LogLevel.INFO, "Mjolnir@startup", "Startup complete. Now monitoring rooms.");
-                await this.client.sendNotice(this.managementRoomId, "Startup complete.");
-            }
         });
     }
 
@@ -181,7 +176,7 @@ export class Mjolnir {
         if (!hadErrors && verbose) {
             const html = `<font color="#00cc00">All permissions look OK.</font>`;
             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 = `<font color="#00cc00">Done updating rooms - no errors</font>`;
             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 = `<font color="#00cc00"><b>Done updating rooms - no errors</b></font>`;
             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 <a href="${url}">${roomId}</a> - 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 = `<font color="#00cc00">All permissions look OK.</font>`;
                     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;
     }
 }

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 logMessage(LogLevel.DEBUG, "ApplyAcl", `Checking ACLs for ${roomId}`);
-                await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Checking ACLs for ${roomId}`);
-            }
 
             try {
                 const currentAcl = await mjolnir.client.getRoomStateEvent(roomId, "m.room.server_acl", "");
                 if (acl.matches(currentAcl)) {
-                    if (config.verboseLogging) {
+                    await logMessage(LogLevel.DEBUG, "ApplyAcl", `Skipping ACLs for ${roomId} because they are already the right ones`);
-                        await mjolnir.client.sendNotice(mjolnir.managementRoomId, `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}`);
+            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 : '<no message>')});

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}`);
+            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}`);
+                            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 = `<font color="#00cc00"><b>Banned ${bansApplied} people</b></font>`;
         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",

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

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 <room ID> <shortcode>
 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'] || '<no 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 = "<no 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 = {

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 <user ID> [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 logMessage(LogLevel.DEBUG, "RedactCommand", `Fetching sent messages for ${userId} in ${targetRoomId} to redact...`);
-            await mjolnir.client.sendNotice(mjolnir.managementRoomId, `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 logMessage(LogLevel.DEBUG, "RedactCommand", `Redacting ${victimEvent['event_id']} in ${targetRoomId}`);
-                await mjolnir.client.sendNotice(mjolnir.managementRoomId, `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`);
             }
         }
     }

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 logMessage(LogLevel.DEBUG, "UnbanBanCommand", `Unbanning ${victim} in ${protectedRoomId}`);
-                        await mjolnir.client.sendNotice(mjolnir.managementRoomId, `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 logMessage(LogLevel.DEBUG, "UnbanBanCommand", `Syncing lists to ensure no users were accidentally unbanned`);
-                await mjolnir.client.sendNotice(mjolnir.managementRoomId, `Syncing lists to ensure no users were accidentally unbanned`);
-            }
             await mjolnir.syncLists(config.verboseLogging);
         }
     }

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 <IConfig>config;

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);
+    config.managementRoom = await client.joinRoom(config.managementRoom);
-    await client.sendNotice(managementRoomId, "Mjolnir is starting up. Use !mjolnir to query status.");
+    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();
 })();