diff --git a/README.md b/README.md index bb8c38bf..b98ee36b 100644 --- a/README.md +++ b/README.md @@ -80,6 +80,10 @@ docker build -t halfshot/matrix-appservice-discord . # Run the container docker run -v /matrix-appservice-discord:/data -p 9005:9005 halfshot/matrix-appservice-discord ``` +#### Metrics + +The bridge supports reporting metrics via Prometheus. You can configure metrics support in the config +file. The metrics will be reported under the URL provided in the registration file, on the `/metrics` endpoint. #### 3PID Protocol Support diff --git a/package.json b/package.json index e79ab464..60894a21 100644 --- a/package.json +++ b/package.json @@ -47,6 +47,7 @@ "node-html-parser": "^1.1.11", "p-queue": "^6.0.1", "pg-promise": "^8.5.1", + "prom-client": "^11.3.0", "tslint": "^5.11.0", "typescript": "^3.1.3", "winston": "^3.0.0", diff --git a/src/bot.ts b/src/bot.ts index d88c10bf..8051c0b3 100644 --- a/src/bot.ts +++ b/src/bot.ts @@ -37,6 +37,7 @@ import * as Discord from "discord.js"; import * as mime from "mime"; import { IMatrixEvent, IMatrixMediaInfo } from "./matrixtypes"; import { DiscordCommandHandler } from "./discordcommandhandler"; +import { MetricPeg } from "./metrics"; const log = new Log("DiscordBot"); @@ -240,6 +241,7 @@ export class DiscordBot { client.on("messageDelete", async (msg: Discord.Message) => { try { await this.waitUnlock(msg.channel); + this.clientFactory.bindMetricsToChannel(msg.channel as Discord.TextChannel); this.discordMessageQueue[msg.channel.id] = (async () => { await (this.discordMessageQueue[msg.channel.id] || Promise.resolve()); try { @@ -260,6 +262,7 @@ export class DiscordBot { promiseArr.push(async () => { try { await this.waitUnlock(msg.channel); + this.clientFactory.bindMetricsToChannel(msg.channel as Discord.TextChannel); await this.DeleteDiscordMessage(msg); } catch (err) { log.error("Caught while handling 'messageDeleteBulk'", err); @@ -274,6 +277,7 @@ export class DiscordBot { client.on("messageUpdate", async (oldMessage: Discord.Message, newMessage: Discord.Message) => { try { await this.waitUnlock(newMessage.channel); + this.clientFactory.bindMetricsToChannel(newMessage.channel as Discord.TextChannel); this.discordMessageQueue[newMessage.channel.id] = (async () => { await (this.discordMessageQueue[newMessage.channel.id] || Promise.resolve()); try { @@ -288,12 +292,15 @@ export class DiscordBot { }); client.on("message", async (msg: Discord.Message) => { try { + MetricPeg.get.registerRequest(msg.id); await this.waitUnlock(msg.channel); + this.clientFactory.bindMetricsToChannel(msg.channel as Discord.TextChannel); this.discordMessageQueue[msg.channel.id] = (async () => { await (this.discordMessageQueue[msg.channel.id] || Promise.resolve()); try { await this.OnMessage(msg); } catch (err) { + MetricPeg.get.requestOutcome(msg.id, true, "fail"); log.error("Caught while handing 'message'", err); } })(); @@ -389,6 +396,7 @@ export class DiscordBot { } const channel = guild.channels.get(room); if (channel && channel.type === "text") { + this.ClientFactory.bindMetricsToChannel(channel as Discord.TextChannel); const lookupResult = new ChannelLookupResult(); lookupResult.channel = channel as Discord.TextChannel; lookupResult.botUser = this.bot.user.id === client.user.id; @@ -448,6 +456,7 @@ export class DiscordBot { // NOTE: Don't send replies to discord if we are a puppet. msg = await chan.send(embed.description, opts); } else if (hook) { + MetricPeg.get.remoteCall("hook.send"); msg = await hook.send(embed.description, { avatarURL: embed!.author!.icon_url, embeds: embedSet.replyEmbed ? [embedSet.replyEmbed] : undefined, @@ -539,6 +548,7 @@ export class DiscordBot { if (guild) { const channel = client.channels.get(entry.remote!.get("discord_channel") as string); if (channel) { + this.ClientFactory.bindMetricsToChannel(channel as Discord.TextChannel); return channel; } throw Error("Channel given in room entry not found"); @@ -738,11 +748,13 @@ export class DiscordBot { if (indexOfMsg !== -1) { log.verbose("Got repeated message, ignoring."); delete this.sentMessages[indexOfMsg]; + MetricPeg.get.requestOutcome(msg.id, true, "dropped"); return; // Skip *our* messages } const chan = msg.channel as Discord.TextChannel; if (msg.author.id === this.bot.user.id) { // We don't support double bridging. + MetricPeg.get.requestOutcome(msg.id, true, "dropped"); return; } // Test for webhooks @@ -751,6 +763,7 @@ export class DiscordBot { .filterArray((h) => h.name === "_matrix").pop(); if (webhook && msg.webhookID === webhook.id) { // Filter out our own webhook messages. + MetricPeg.get.requestOutcome(msg.id, true, "dropped"); return; } } @@ -758,6 +771,7 @@ export class DiscordBot { // check if it is a command to process by the bot itself if (msg.content.startsWith("!matrix")) { await this.discordCommandHandler.Process(msg); + MetricPeg.get.requestOutcome(msg.id, true, "success"); return; } @@ -766,14 +780,15 @@ export class DiscordBot { let rooms; try { rooms = await this.channelSync.GetRoomIdsFromChannel(msg.channel); + if (rooms === null) { + throw Error(); + } } catch (err) { log.verbose("No bridged rooms to send message to. Oh well."); + MetricPeg.get.requestOutcome(msg.id, true, "dropped"); return null; } try { - if (rooms === null) { - return null; - } const intent = this.GetIntentFromDiscordMember(msg.author, msg.webhookID); // Check Attachements await Util.AsyncForEach(msg.attachments.array(), async (attachment) => { @@ -854,7 +869,9 @@ export class DiscordBot { await afterSend(res); } }); + MetricPeg.get.requestOutcome(msg.id, true, "success"); } catch (err) { + MetricPeg.get.requestOutcome(msg.id, true, "fail"); log.verbose("Failed to send message into room.", err); } } diff --git a/src/clientfactory.ts b/src/clientfactory.ts index 54e2694c..1b2adcfb 100644 --- a/src/clientfactory.ts +++ b/src/clientfactory.ts @@ -16,14 +16,12 @@ limitations under the License. import { DiscordBridgeConfigAuth } from "./config"; import { DiscordStore } from "./store"; -import { Client as DiscordClient } from "discord.js"; +import { Client as DiscordClient, TextChannel } from "discord.js"; import { Log } from "./log"; -import { Util } from "./util"; +import { MetricPeg } from "./metrics"; const log = new Log("ClientFactory"); -const READY_TIMEOUT = 30000; - export class DiscordClientFactory { private config: DiscordBridgeConfigAuth; private store: DiscordStore; @@ -110,4 +108,19 @@ export class DiscordClientFactory { return this.botClient; } } + + public bindMetricsToChannel(channel: TextChannel) { + // tslint:disable-next-line:no-any + const flexChan = channel as any; + if (flexChan._xmet_send !== undefined) { + return; + } + // Prefix the real functions with _xmet_ + flexChan._xmet_send = channel.send; + // tslint:disable-next-line:only-arrow-functions + channel.send = function() { + MetricPeg.get.remoteCall("channel.send"); + return flexChan._xmet_send.apply(channel, arguments); + }; + } } diff --git a/src/config.ts b/src/config.ts index 2f0eb762..2da5b773 100644 --- a/src/config.ts +++ b/src/config.ts @@ -90,6 +90,7 @@ class DiscordBridgeConfigBridge { public disableEveryoneMention: boolean = false; public disableHereMention: boolean = false; public disableJoinLeaveNotifications: boolean = false; + public enableMetrics: boolean = false; } export class DiscordBridgeConfigDatabase { diff --git a/src/db/roomstore.ts b/src/db/roomstore.ts index c04230e0..2cb9d9f0 100644 --- a/src/db/roomstore.ts +++ b/src/db/roomstore.ts @@ -19,6 +19,7 @@ import { Util } from "../util"; import * as uuid from "uuid/v4"; import { Postgres } from "./postgres"; +import { MetricPeg } from "../metrics"; const log = new Log("DbRoomStore"); @@ -155,8 +156,10 @@ export class DbRoomStore { public async getEntriesByMatrixId(matrixId: string): Promise { const cached = this.entriesMatrixIdCache.get(matrixId); if (cached && cached.ts + ENTRY_CACHE_LIMETIME > Date.now()) { + MetricPeg.get.storeCall("RoomStore.getEntriesByMatrixId", true); return cached.e; } + MetricPeg.get.storeCall("RoomStore.getEntriesByMatrixId", false); const entries = await this.db.All( "SELECT * FROM room_entries WHERE matrix_id = $id", {id: matrixId}, ); @@ -190,6 +193,7 @@ export class DbRoomStore { } public async getEntriesByMatrixIds(matrixIds: string[]): Promise { + MetricPeg.get.storeCall("RoomStore.getEntriesByMatrixIds", false); const mxIdMap = { }; matrixIds.forEach((mxId, i) => mxIdMap[i] = mxId); const sql = `SELECT * FROM room_entries WHERE matrix_id IN (${matrixIds.map((_, id) => `\$${id}`).join(", ")})`; @@ -222,6 +226,7 @@ export class DbRoomStore { } public async linkRooms(matrixRoom: MatrixStoreRoom, remoteRoom: RemoteStoreRoom) { + MetricPeg.get.storeCall("RoomStore.linkRooms", false); await this.upsertRoom(remoteRoom); const values = { @@ -244,6 +249,7 @@ export class DbRoomStore { } public async getEntriesByRemoteRoomData(data: IRemoteRoomDataLazy): Promise { + MetricPeg.get.storeCall("RoomStore.getEntriesByRemoteRoomData", false); Object.keys(data).filter((k) => typeof(data[k]) === "boolean").forEach((k) => { data[k] = Number(data[k]); }); @@ -270,11 +276,13 @@ export class DbRoomStore { } public async removeEntriesByRemoteRoomId(remoteId: string) { + MetricPeg.get.storeCall("RoomStore.removeEntriesByRemoteRoomId", false); await this.db.Run(`DELETE FROM room_entries WHERE remote_id = $remoteId`, {remoteId}); await this.db.Run(`DELETE FROM remote_room_data WHERE room_id = $remoteId`, {remoteId}); } public async removeEntriesByMatrixRoomId(matrixId: string) { + MetricPeg.get.storeCall("RoomStore.removeEntriesByMatrixRoomId", false); const entries = (await this.db.All(`SELECT * FROM room_entries WHERE matrix_id = $matrixId`, {matrixId})) || []; await Util.AsyncForEach(entries, async (entry) => { if (entry.remote_id) { @@ -286,6 +294,7 @@ export class DbRoomStore { } private async upsertRoom(room: RemoteStoreRoom) { + MetricPeg.get.storeCall("RoomStore.upsertRoom", false); if (!room.data) { throw new Error("Tried to upsert a room with undefined data"); } diff --git a/src/db/userstore.ts b/src/db/userstore.ts index cb1251e2..0f307d61 100644 --- a/src/db/userstore.ts +++ b/src/db/userstore.ts @@ -15,8 +15,8 @@ limitations under the License. */ import { IDatabaseConnector } from "./connector"; -import * as uuid from "uuid/v4"; import { Log } from "../log"; +import { MetricPeg } from "../metrics"; /** * A UserStore compatible with @@ -54,8 +54,11 @@ export class DbUserStore { public async getRemoteUser(remoteId: string): Promise { const cached = this.remoteUserCache.get(remoteId); if (cached && cached.ts + ENTRY_CACHE_LIMETIME > Date.now()) { + MetricPeg.get.storeCall("UserStore.getRemoteUser", true); return cached.e; } + MetricPeg.get.storeCall("UserStore.getRemoteUser", false); + const row = await this.db.Get( "SELECT * FROM user_entries WHERE remote_id = $id", {id: remoteId}, ); @@ -86,6 +89,7 @@ export class DbUserStore { } public async setRemoteUser(user: RemoteUser) { + MetricPeg.get.storeCall("UserStore.setRemoteUser", false); this.remoteUserCache.delete(user.id); const existingData = await this.db.Get( "SELECT * FROM remote_user_data WHERE remote_id = $remoteId", @@ -156,6 +160,7 @@ AND guild_id = $guild_id`, } public async linkUsers(matrixId: string, remoteId: string) { + MetricPeg.get.storeCall("UserStore.linkUsers", false); // This is used ONCE in the bridge to link two IDs, so do not UPSURT data. try { await this.db.Run(`INSERT INTO user_entries VALUES ($matrixId, $remoteId)`, { diff --git a/src/discordas.ts b/src/discordas.ts index 1f350c38..2e989cea 100644 --- a/src/discordas.ts +++ b/src/discordas.ts @@ -22,6 +22,7 @@ import { DiscordBot } from "./bot"; import { DiscordStore } from "./store"; import { Log } from "./log"; import "source-map-support/register"; +import { MetricPeg, PrometheusBridgeMetrics } from "./metrics"; const log = new Log("DiscordAS"); @@ -94,13 +95,16 @@ async function run(port: number, fileConfig: DiscordBridgeConfig) { } catch (err) { log.error("Exception thrown while handling \"onAliasQuery\" event", err); } }, onEvent: async (request) => { + const data = request.getData(); try { + MetricPeg.get.registerRequest(data.event_id); // Build our own context. if (!store.roomStore) { log.warn("Discord store not ready yet, dropping message"); + MetricPeg.get.requestOutcome(data.event_id, false, "dropped"); return; } - const roomId = request.getData().room_id; + const roomId = data.room_id; const context: BridgeContext = { rooms: {}, @@ -112,7 +116,9 @@ async function run(port: number, fileConfig: DiscordBridgeConfig) { } await request.outcomeFrom(callbacks.onEvent(request, context)); + MetricPeg.get.requestOutcome(data.event_id, false, "success"); } catch (err) { + MetricPeg.get.requestOutcome(data.event_id, false, "fail"); log.error("Exception thrown while handling \"onEvent\" event", err); await request.outcomeFrom(Promise.reject("Failed to handle")); } @@ -160,6 +166,11 @@ async function run(port: number, fileConfig: DiscordBridgeConfig) { await bridge.run(port, config); log.info(`Started listening on port ${port}`); + if (config.bridge.enableMetrics) { + log.info("Enabled metrics"); + MetricPeg.set(new PrometheusBridgeMetrics().init(bridge)); + } + try { await store.init(undefined, bridge.getRoomStore(), bridge.getUserStore()); } catch (ex) { diff --git a/src/metrics.ts b/src/metrics.ts new file mode 100644 index 00000000..db1556f3 --- /dev/null +++ b/src/metrics.ts @@ -0,0 +1,156 @@ +/* +Copyright 2019 matrix-appservice-discord + +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 { PrometheusMetrics, Bridge } from "matrix-appservice-bridge"; +import { Gauge, Counter, Histogram } from "prom-client"; +import { Log } from "./log"; + +const AgeCounters = PrometheusMetrics.AgeCounters; +const log = new Log("BridgeMetrics"); +const REQUEST_EXPIRE_TIME_MS = 30000; + +interface IAgeCounter { + setGauge(gauge: Gauge, morelabels: string[]); + bump(age: number); +} + +interface IBridgeGauges { + matrixRoomConfigs: number; + remoteRoomConfigs: number; + matrixGhosts: number; + remoteGhosts: number; + matrixRoomsByAge: IAgeCounter; + remoteRoomsByAge: IAgeCounter; + matrixUsersByAge: IAgeCounter; + remoteUsersByAge: IAgeCounter; +} + +export interface IBridgeMetrics { + registerRequest(id: string); + requestOutcome(id: string, isRemote: boolean, outcome: string); + remoteCall(method: string); + setPresenceCount(count: number); + storeCall(method: string, cached: boolean); +} + +export class DummyBridgeMetrics implements IBridgeMetrics { + public registerRequest() {} + public requestOutcome() {} + public remoteCall() {} + public setPresenceCount() {} + public storeCall() {} +} + +export class MetricPeg { + public static get get(): IBridgeMetrics { + return this.metrics; + } + + public static set(metrics: IBridgeMetrics) { + this.metrics = metrics; + } + + private static metrics: IBridgeMetrics = new DummyBridgeMetrics(); +} + +export class PrometheusBridgeMetrics implements IBridgeMetrics { + private metrics; + private remoteCallCounter: Counter; + private storeCallCounter: Counter; + private presenceGauge: Gauge; + private remoteRequest: Histogram; + private matrixRequest: Histogram; + private requestsInFlight: Map; + private bridgeGauges: IBridgeGauges = { + matrixGhosts: 0, + matrixRoomConfigs: 0, + matrixRoomsByAge: new AgeCounters(), + matrixUsersByAge: new AgeCounters(), + remoteGhosts: 0, + remoteRoomConfigs: 0, + remoteRoomsByAge: new AgeCounters(), + remoteUsersByAge: new AgeCounters(), + }; + + public init(bridge: Bridge) { + this.metrics = new PrometheusMetrics(); + this.metrics.registerMatrixSdkMetrics(); + this.metrics.registerBridgeGauges(() => this.bridgeGauges); + this.metrics.addAppServicePath(bridge); + this.remoteCallCounter = this.metrics.addCounter({ + help: "Count of remote API calls made", + labels: ["method"], + name: "remote_api_calls", + }); + this.storeCallCounter = this.metrics.addCounter({ + help: "Count of store function calls made", + labels: ["method", "cached"], + name: "store_calls", + }); + this.presenceGauge = this.metrics.addGauge({ + help: "Count of users in the presence queue", + labels: [], + + name: "active_presence_users", + }); + this.matrixRequest = this.metrics.addTimer({ + help: "Histogram of processing durations of received Matrix messages", + labels: ["outcome"], + name: "matrix_request_seconds", + }); + this.remoteRequest = this.metrics.addTimer({ + help: "Histogram of processing durations of received remote messages", + labels: ["outcome"], + name: "remote_request_seconds", + }); + this.requestsInFlight = new Map(); + setInterval(() => { + this.requestsInFlight.forEach((time, id) => { + if (Date.now() - time) { + this.requestsInFlight.delete(id); + } + }); + }, REQUEST_EXPIRE_TIME_MS); + return this; + } + + public registerRequest(id: string) { + this.requestsInFlight.set(id, Date.now()); + } + + public requestOutcome(id: string, isRemote: boolean, outcome: string) { + const startTime = this.requestsInFlight.get(id); + this.requestsInFlight.delete(id); + if (!startTime) { + log.verbose(`Got "requestOutcome" for ${id}, but this request was never started`); + return; + } + const duration = Date.now() - startTime; + (isRemote ? this.remoteRequest : this.matrixRequest).observe({outcome}, duration / 1000); + } + + public setPresenceCount(count: number) { + this.presenceGauge.set(count); + } + + public remoteCall(method: string) { + this.remoteCallCounter.inc({method}); + } + + public storeCall(method: string, cached: boolean) { + this.storeCallCounter.inc({method, cached: cached ? "yes" : "no"}); + } +} diff --git a/src/presencehandler.ts b/src/presencehandler.ts index 16fa4a97..91343e60 100644 --- a/src/presencehandler.ts +++ b/src/presencehandler.ts @@ -17,6 +17,7 @@ limitations under the License. import { User, Presence } from "discord.js"; import { DiscordBot } from "./bot"; import { Log } from "./log"; +import { MetricPeg } from "./metrics"; const log = new Log("PresenceHandler"); export class PresenceHandlerStatus { @@ -66,6 +67,7 @@ export class PresenceHandler { if (user.id !== this.bot.GetBotId() && this.presenceQueue.find((u) => u.id === user.id) === undefined) { log.info(`Adding ${user.id} (${user.username}) to the presence queue`); this.presenceQueue.push(user); + MetricPeg.get.setPresenceCount(this.presenceQueue.length); } } @@ -75,6 +77,7 @@ export class PresenceHandler { }); if (index !== -1) { this.presenceQueue.splice(index, 1); + MetricPeg.get.setPresenceCount(this.presenceQueue.length); } else { log.warn( `Tried to remove ${user.id} from the presence queue but it could not be found`, @@ -96,6 +99,7 @@ export class PresenceHandler { this.presenceQueue.push(user); } else { log.info(`Dropping ${user.id} from the presence queue.`); + MetricPeg.get.setPresenceCount(this.presenceQueue.length); } } } diff --git a/test/mocks/discordclientfactory.ts b/test/mocks/discordclientfactory.ts index 803dedc1..b174f3d5 100644 --- a/test/mocks/discordclientfactory.ts +++ b/test/mocks/discordclientfactory.ts @@ -31,4 +31,6 @@ export class DiscordClientFactory { } return this.botClient; } + + public bindMetricsToChannel() {} } diff --git a/test/test_discordbot.ts b/test/test_discordbot.ts index f6208be1..918ff468 100644 --- a/test/test_discordbot.ts +++ b/test/test_discordbot.ts @@ -434,6 +434,7 @@ describe("DiscordBot", () => { it("should lock and unlock a channel early, if unlocked", async () => { const discordSendDelay = 500; const SHORTDELAY = 100; + const MINEXPECTEDDELAY = 95; const bot = new modDiscordBot.DiscordBot( "", { @@ -453,7 +454,8 @@ describe("DiscordBot", () => { bot.lockChannel(chan); await bot.waitUnlock(chan); const diff = Date.now() - t; - expect(diff).to.be.greaterThan(SHORTDELAY - 1); + // Date accuracy can be off by a few ms sometimes. + expect(diff).to.be.greaterThan(MINEXPECTEDDELAY); }); }); // }); diff --git a/tslint.json b/tslint.json index cd7de561..ff80b039 100644 --- a/tslint.json +++ b/tslint.json @@ -9,7 +9,7 @@ "object-literal-sort-keys": "off", "no-any": true, "arrow-return-shorthand": true, - "no-magic-numbers": true, + "no-magic-numbers": [true, -1, 0, 1, 1000], "prefer-for-of": true, "typedef": { "severity": "warning"