Refactor logging to be much more flexible and less noisy (#229)

* Add new logging config options

* Reduce logging noise

* Identify more sources of noise

* Add new colourize and json options for logging

* Update documentation

* changelog

changelog.d/229.feature

@@ -0,0 +1 @@
+Logging now supports `json` format outputs and colourized logs. Startup logging should now be less noisy on non-debug levels.

config.sample.yml

@@ -95,6 +95,9 @@ logging:
   # (Optional) Logging settings. You can have a severity debug,info,warn,error
   #
   level: info
+  colorize: true
+  json: false
+  timestampFormat: HH:mm:ss:SSS
 permissions:
   # (Optional) Permissions for using the bridge. See docs/setup.md#permissions for help
   #

docs/setup.md

@@ -205,3 +205,19 @@ You will need to configure some services. Each service has it's own documentatio
 - [GitLab](./setup/gitlab.md)
 - [Jira](./setup/jira.md)
 - [Webhooks](./setup/webhooks.md)
+
+### Logging
+
+The bridge supports some basic logging options. The section is optional, and by default will log at an `info` level.
+
+```yaml
+logging:
+  # Level of information to report to the logs. Can be `debug`, `info`, `warn` or `error.
+  level: info
+  # Should the logs output in human readable format or JSON. If you are using a third-party ingestion service like logstash, use this.
+  json: false
+  # Ignored if `json` is enabled. Should the logs print the levels in color. This will print extra characters around the logs which may not be suitable for some systems.
+  colorize: true
+  #  Ignored if `json` is enabled. The timestamp format to use in log lines. See https://github.com/taylorhakes/fecha#formatting-tokens for help on formatting tokens.
+  timestampFormat: HH:mm:ss:SSS
+```

src/App/BridgeApp.ts

@@ -7,7 +7,7 @@ import { MatrixSender } from "../MatrixSender";
 import { UserNotificationWatcher } from "../Notifications/UserNotificationWatcher";
 import { ListenerService } from "../ListenerService";
 
-LogWrapper.configureLogging("debug");
+LogWrapper.configureLogging("info");
 const log = new LogWrapper("App");
 
 async function start() {
@@ -16,7 +16,7 @@ async function start() {
     const config = await BridgeConfig.parseConfig(configFile, process.env);
     const registration = await parseRegistrationFile(registrationFile);
     const listener = new ListenerService(config.listeners);
-    LogWrapper.configureLogging(config.logging.level);
+    LogWrapper.configureLogging(config.logging);
 
     if (config.queue.monolithic) {
         const webhookHandler = new Webhooks(config);

src/App/GithubWebhookApp.ts

@@ -11,7 +11,7 @@ const log = new LogWrapper("App");
 async function start() {
     const configFile = process.argv[2] || "./config.yml";
     const config = await BridgeConfig.parseConfig(configFile, process.env);
-    LogWrapper.configureLogging(config.logging.level);
+    LogWrapper.configureLogging(config.logging);
     const listener = new ListenerService(config.listeners);
     if (config.metrics) {
         if (!config.metrics.port) {

src/App/MatrixSenderApp.ts

@@ -12,7 +12,7 @@ async function start() {
     const registrationFile = process.argv[3] || "./registration.yml";
     const config = await BridgeConfig.parseConfig(configFile, process.env);
     const registration = await parseRegistrationFile(registrationFile);
-    LogWrapper.configureLogging(config.logging.level);
+    LogWrapper.configureLogging(config.logging);
     const listener = new ListenerService(config.listeners);
     const sender = new MatrixSender(config, registration);
     if (config.metrics) {

src/Bridge.ts

@@ -92,7 +92,7 @@ export class Bridge {
             try {
                 log.info("Connecting to homeserver and fetching joined rooms..");
                 joinedRooms = await this.as.botIntent.underlyingClient.getJoinedRooms();
-                log.info(`Found ${joinedRooms.length} rooms`);
+                log.debug(`Bridge bot is joined to ${joinedRooms.length} rooms`);
             } catch (ex) {
                 // This is our first interaction with the homeserver, so wait if it's not ready yet.
                 log.warn("Failed to connect to homeserver:", ex, "retrying in 5s");
@@ -583,7 +583,7 @@ export class Bridge {
                 const adminRoom = await this.setupAdminRoom(roomId, accountData, notifContent || NotifFilter.getDefaultContent());
                 // Call this on startup to set the state
                 await this.onAdminRoomSettingsChanged(adminRoom, accountData, { admin_user: accountData.admin_user });
-                log.info(`Room ${roomId} is connected to: ${adminRoom.toString()}`);
+                log.debug(`Room ${roomId} is connected to: ${adminRoom.toString()}`);
             } catch (ex) {
                 log.error(`Failed to setup admin room ${roomId}:`, ex);
             }
@@ -607,7 +607,7 @@ export class Bridge {
             this.listener.bindResource('metrics', Metrics.expressRouter);
         }
         await this.as.begin();
-        log.info("Started bridge");
+        log.info(`Bridge is now ready. Found ${this.connectionManager.size} connections`);
         this.ready = true;
     }
 
@@ -981,7 +981,7 @@ export class Bridge {
         if (this.config.widgets?.addToAdminRooms && this.config.widgets.publicUrl) {
             await adminRoom.setupWidget();
         }
-        log.info(`Setup ${roomId} as an admin room for ${adminRoom.userId}`);
+        log.debug(`Setup ${roomId} as an admin room for ${adminRoom.userId}`);
         return adminRoom;
     }
 }

src/Config/Config.ts

@@ -201,8 +201,11 @@ interface BridgeConfigQueue {
     host?: string;
 }
 
-interface BridgeConfigLogging {
+export interface BridgeConfigLogging {
     level: string;
+    json?: boolean;
+    colorize?: boolean;
+    timestampFormat?: string;
 }
 
 interface BridgeConfigBot {
@@ -376,7 +379,7 @@ export class BridgeConfig {
         for(const roomEntry of permissionRooms) {
             const membership = await client.getJoinedRoomMembers(await client.resolveRoom(roomEntry));
             membership.forEach(userId => this.bridgePermissions.addMemberToCache(roomEntry, userId));
-            log.info(`Found ${membership.length} users for ${roomEntry}`);
+            log.debug(`Found ${membership.length} users for ${roomEntry}`);
         } 
     }
 

src/Config/Defaults.ts

@@ -19,6 +19,9 @@ export const DefaultConfig = new BridgeConfig({
     },
     logging: {
         level: "info",
+        colorize: true,
+        json: false,
+        timestampFormat: "HH:mm:ss:SSS",
     },
     permissions: [{
         actor: "example.com",

src/ConnectionManager.ts

@@ -26,6 +26,10 @@ export class ConnectionManager {
     private connections: IConnection[] = [];
     public readonly enabledForProvisioning: Record<string, GetConnectionTypeResponseItem> = {};
 
+    public get size() {
+        return this.connections.length;
+    }
+
     constructor(
         private readonly as: Appservice,
         private readonly config: BridgeConfig,
@@ -265,8 +269,10 @@ export class ConnectionManager {
         for (const event of state) {
             try {
                 const conn = await this.createConnectionForState(roomId, new StateEvent(event));
-                log.info(`Room ${roomId} is connected to: ${conn}`);
-                if (conn) { this.push(conn);  }
+                if (conn) {
+                    log.debug(`Room ${roomId} is connected to: ${conn}`);
+                    this.push(conn);
+                }
             } catch (ex) {
                 log.warn(`Failed to create connection for ${roomId}:`, ex);
             }

src/Connections/FigmaFileConnection.ts

@@ -105,4 +105,8 @@ export class FigmaFileConnection extends BaseConnection implements IConnection {
         log.info(`New figma comment ${payload.comment_id} -> ${this.roomId}/${eventId}`)
         await this.storage.setFigmaCommentEventId(this.roomId, payload.comment_id, eventId);
     }
+
+    public toString() {
+        return `FigmaFileConnection ${this.instanceName}/${this.fileId || "*"}`;
+    }
 }

src/ListenerService.ts

@@ -39,7 +39,7 @@ export class ListenerService {
 
     public bindResource(resourceName: ResourceName, router: Router) {
         for (const listener of this.listeners.filter((l) => l.config.resources.includes(resourceName))) {
-            log.info(`Registering ${listener.config.bindAddress || "127.0.0.1"}:${listener.config.port} for ${resourceName}`);
+            log.debug(`Registering ${listener.config.bindAddress || "127.0.0.1"}:${listener.config.port} for ${resourceName}`);
             listener.app.use(router);
             listener.resourcesBound = true;
         }
@@ -55,7 +55,7 @@ export class ListenerService {
             }
             const addr = listener.config.bindAddress || "127.0.0.1";
             listener.server = listener.app.listen(listener.config.port, addr);
-            log.info(`Listening on ${addr}:${listener.config.port} for ${listener.config.resources.join(', ')}`)
+            log.info(`Listening on http://${addr}:${listener.config.port} for ${listener.config.resources.join(', ')}`)
         }
     }
 

src/LogWrapper.ts

@@ -1,25 +1,67 @@
 import { LogLevel, LogService } from "matrix-bot-sdk";
 import util from "util";
-import winston from "winston";
+import winston, { format } from "winston";
+import { BridgeConfigLogging } from "./Config/Config";
 
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
 type MsgType = string|Error|any|{error?: string};
+
+function isMessageNoise(messageOrObject: MsgType[]) {
+    const error = messageOrObject[0]?.error || messageOrObject[1]?.error ||messageOrObject[1]?.body?.error;
+    const errcode = messageOrObject[0]?.errcode || messageOrObject[1]?.errcode;
+    if (errcode === "M_NOT_FOUND" && error === "Room account data not found") {
+        return true;
+    }
+    if (errcode === "M_NOT_FOUND" && error === "Event not found.") {
+        return true;
+    }
+    if (errcode === "M_USER_IN_USE") {
+        return true;
+    }
+    return false;
+}
 export default class LogWrapper {
 
-    public static configureLogging(level: string) {
+    public static configureLogging(cfg: BridgeConfigLogging|string) {
+
+        if (typeof cfg === "string") {
+            cfg = { level: cfg };
+        }
+
+        const formatters = [
+            winston.format.timestamp({
+                format: cfg.timestampFormat || "HH:mm:ss:SSS",
+            }),
+            (format((info) => {
+                info.level = info.level.toUpperCase();
+                return info;
+            }))(),
+        ]
+
+        if (!cfg.json && cfg.colorize) {
+            formatters.push(
+                winston.format.colorize({
+                    level: true,
+                })
+            );
+        }
+
+        if (cfg.json) {
+            formatters.push(winston.format.json());
+        } else {
+            formatters.push(winston.format.printf(
+                (info) => {
+                    return `${info.level} ${info.timestamp} [${info.module}] ${info.message}`;
+                },
+            ));
+        }
+
+
         const log = winston.createLogger({
-            level,
+            level: cfg.level,
             transports: [
                 new winston.transports.Console({
-                    format: winston.format.combine(
-                        winston.format.timestamp({
-                            format: "HH:mm:ss:SSS",
-                        }),
-                        winston.format.printf(
-                        (info) => {
-                            return `${info.level.toUpperCase()} ${info.timestamp} [${info.module}] ${info.message}`;
-                        },
-                    )),
+                    format: winston.format.combine(...formatters),
                 }),
             ],
         });
@@ -45,16 +87,14 @@ export default class LogWrapper {
                 log.info(getMessageString(messageOrObject), { module });
             },
             warn: (module: string, ...messageOrObject: MsgType[]) => {
-                const error = messageOrObject[0].error || messageOrObject[1]?.body?.error;
-                if (error === "Room account data not found") {
+                if (isMessageNoise(messageOrObject)) {
                     log.debug(getMessageString(messageOrObject), { module });
                     return; // This is just noise :|
                 }
                 log.warn(getMessageString(messageOrObject), { module });
             },
             error: (module: string, ...messageOrObject: MsgType[]) => {
-                const error = messageOrObject[0].error || messageOrObject[1]?.body?.error;
-                if (error === "Room account data not found") {
+                if (isMessageNoise(messageOrObject)) {
                     log.debug(getMessageString(messageOrObject), { module });
                     return; // This is just noise :|
                 }
@@ -67,8 +107,8 @@ export default class LogWrapper {
                 log.verbose(getMessageString(messageOrObject), { module });
             },
         });
-        LogService.setLevel(LogLevel.fromString(level));
-        LogService.info("LogWrapper", "Reconfigured logging");
+        LogService.setLevel(LogLevel.fromString(cfg.level));
+        LogService.debug("LogWrapper", "Reconfigured logging");
     }
 
     constructor(private module: string) { }