From 8f17a835f9eceb77b4f556cf47c7b7bf1983ad8d Mon Sep 17 00:00:00 2001 From: Dragory <2606411+Dragory@users.noreply.github.com> Date: Wed, 27 Oct 2021 00:09:29 +0300 Subject: [PATCH] refactor: debounce and batch simultaneous audit log requests --- .../plugins/Logs/events/LogsGuildBanEvts.ts | 14 +--- .../plugins/Logs/events/LogsUserUpdateEvts.ts | 1 - .../events/CreateBanCaseOnManualBanEvt.ts | 8 +-- .../events/CreateKickCaseOnManualKickEvt.ts | 8 +-- .../events/CreateUnbanCaseOnManualUnbanEvt.ts | 8 +-- backend/src/utils.ts | 57 ---------------- .../src/utils/findMatchingAuditLogEntry.ts | 68 +++++++++++++++++++ .../utils/safeFindRelevantAuditLogEntry.ts | 30 -------- 8 files changed, 77 insertions(+), 117 deletions(-) create mode 100644 backend/src/utils/findMatchingAuditLogEntry.ts delete mode 100644 backend/src/utils/safeFindRelevantAuditLogEntry.ts diff --git a/backend/src/plugins/Logs/events/LogsGuildBanEvts.ts b/backend/src/plugins/Logs/events/LogsGuildBanEvts.ts index f9baa897..fcf84249 100644 --- a/backend/src/plugins/Logs/events/LogsGuildBanEvts.ts +++ b/backend/src/plugins/Logs/events/LogsGuildBanEvts.ts @@ -1,11 +1,11 @@ import { GuildAuditLogs } from "discord.js"; import { LogType } from "../../../data/LogType"; import { userToTemplateSafeUser } from "../../../utils/templateSafeObjects"; -import { safeFindRelevantAuditLogEntry } from "../../../utils/safeFindRelevantAuditLogEntry"; import { logsEvt } from "../types"; import { logMemberBan } from "../logFunctions/logMemberBan"; import { isLogIgnored } from "../util/isLogIgnored"; import { logMemberUnban } from "../logFunctions/logMemberUnban"; +import { findMatchingAuditLogEntry } from "../../../utils/findMatchingAuditLogEntry"; export const LogsGuildBanAddEvt = logsEvt({ event: "guildBanAdd", @@ -18,11 +18,7 @@ export const LogsGuildBanAddEvt = logsEvt({ return; } - const relevantAuditLogEntry = await safeFindRelevantAuditLogEntry( - pluginData, - GuildAuditLogs.Actions.MEMBER_BAN_ADD as number, - user.id, - ); + const relevantAuditLogEntry = await findMatchingAuditLogEntry(pluginData.guild, "MEMBER_BAN_ADD", user.id); const mod = relevantAuditLogEntry?.executor ?? null; logMemberBan(meta.pluginData, { mod, @@ -44,11 +40,7 @@ export const LogsGuildBanRemoveEvt = logsEvt({ return; } - const relevantAuditLogEntry = await safeFindRelevantAuditLogEntry( - pluginData, - GuildAuditLogs.Actions.MEMBER_BAN_REMOVE as number, - user.id, - ); + const relevantAuditLogEntry = await findMatchingAuditLogEntry(pluginData.guild, "MEMBER_BAN_REMOVE", user.id); const mod = relevantAuditLogEntry?.executor ?? null; logMemberUnban(pluginData, { diff --git a/backend/src/plugins/Logs/events/LogsUserUpdateEvts.ts b/backend/src/plugins/Logs/events/LogsUserUpdateEvts.ts index 061ab4fe..ac24a0fe 100644 --- a/backend/src/plugins/Logs/events/LogsUserUpdateEvts.ts +++ b/backend/src/plugins/Logs/events/LogsUserUpdateEvts.ts @@ -3,7 +3,6 @@ import diff from "lodash.difference"; import isEqual from "lodash.isequal"; import { memberToTemplateSafeMember, userToTemplateSafeUser } from "../../../utils/templateSafeObjects"; import { LogType } from "../../../data/LogType"; -import { safeFindRelevantAuditLogEntry } from "../../../utils/safeFindRelevantAuditLogEntry"; import { logsEvt } from "../types"; import { logMemberNickChange } from "../logFunctions/logMemberNickChange"; import { logMemberRoleChanges } from "../logFunctions/logMemberRoleChanges"; diff --git a/backend/src/plugins/ModActions/events/CreateBanCaseOnManualBanEvt.ts b/backend/src/plugins/ModActions/events/CreateBanCaseOnManualBanEvt.ts index 1afa0a01..148ebd5b 100644 --- a/backend/src/plugins/ModActions/events/CreateBanCaseOnManualBanEvt.ts +++ b/backend/src/plugins/ModActions/events/CreateBanCaseOnManualBanEvt.ts @@ -4,12 +4,12 @@ import { CaseTypes } from "../../../data/CaseTypes"; import { Case } from "../../../data/entities/Case"; import { LogType } from "../../../data/LogType"; import { resolveUser, UnknownUser } from "../../../utils"; -import { safeFindRelevantAuditLogEntry } from "../../../utils/safeFindRelevantAuditLogEntry"; import { CasesPlugin } from "../../Cases/CasesPlugin"; import { clearIgnoredEvents } from "../functions/clearIgnoredEvents"; import { isEventIgnored } from "../functions/isEventIgnored"; import { IgnoredEventType, modActionsEvt } from "../types"; import { LogsPlugin } from "../../Logs/LogsPlugin"; +import { findMatchingAuditLogEntry } from "../../../utils/findMatchingAuditLogEntry"; /** * Create a BAN case automatically when a user is banned manually. @@ -24,11 +24,7 @@ export const CreateBanCaseOnManualBanEvt = modActionsEvt({ return; } - const relevantAuditLogEntry = await safeFindRelevantAuditLogEntry( - pluginData, - GuildAuditLogs.Actions.MEMBER_BAN_ADD as number, - user.id, - ); + const relevantAuditLogEntry = await findMatchingAuditLogEntry(pluginData.guild, "MEMBER_BAN_ADD", user.id); const casesPlugin = pluginData.getPlugin(CasesPlugin); diff --git a/backend/src/plugins/ModActions/events/CreateKickCaseOnManualKickEvt.ts b/backend/src/plugins/ModActions/events/CreateKickCaseOnManualKickEvt.ts index 421c8681..b2a7f822 100644 --- a/backend/src/plugins/ModActions/events/CreateKickCaseOnManualKickEvt.ts +++ b/backend/src/plugins/ModActions/events/CreateKickCaseOnManualKickEvt.ts @@ -5,12 +5,12 @@ import { Case } from "../../../data/entities/Case"; import { LogType } from "../../../data/LogType"; import { logger } from "../../../logger"; import { resolveUser, UnknownUser } from "../../../utils"; -import { safeFindRelevantAuditLogEntry } from "../../../utils/safeFindRelevantAuditLogEntry"; import { CasesPlugin } from "../../Cases/CasesPlugin"; import { clearIgnoredEvents } from "../functions/clearIgnoredEvents"; import { isEventIgnored } from "../functions/isEventIgnored"; import { IgnoredEventType, modActionsEvt } from "../types"; import { LogsPlugin } from "../../Logs/LogsPlugin"; +import { findMatchingAuditLogEntry } from "../../../utils/findMatchingAuditLogEntry"; /** * Create a KICK case automatically when a user is kicked manually. @@ -24,11 +24,7 @@ export const CreateKickCaseOnManualKickEvt = modActionsEvt({ return; } - const kickAuditLogEntry = await safeFindRelevantAuditLogEntry( - pluginData, - GuildAuditLogs.Actions.MEMBER_KICK as number, - member.id, - ); + const kickAuditLogEntry = await findMatchingAuditLogEntry(pluginData.guild, "MEMBER_KICK", member.id); let mod: User | UnknownUser | null = null; let createdCase: Case | null = null; diff --git a/backend/src/plugins/ModActions/events/CreateUnbanCaseOnManualUnbanEvt.ts b/backend/src/plugins/ModActions/events/CreateUnbanCaseOnManualUnbanEvt.ts index de86e6e4..3498f834 100644 --- a/backend/src/plugins/ModActions/events/CreateUnbanCaseOnManualUnbanEvt.ts +++ b/backend/src/plugins/ModActions/events/CreateUnbanCaseOnManualUnbanEvt.ts @@ -4,12 +4,12 @@ import { CaseTypes } from "../../../data/CaseTypes"; import { Case } from "../../../data/entities/Case"; import { LogType } from "../../../data/LogType"; import { resolveUser, UnknownUser } from "../../../utils"; -import { safeFindRelevantAuditLogEntry } from "../../../utils/safeFindRelevantAuditLogEntry"; import { CasesPlugin } from "../../Cases/CasesPlugin"; import { clearIgnoredEvents } from "../functions/clearIgnoredEvents"; import { isEventIgnored } from "../functions/isEventIgnored"; import { IgnoredEventType, modActionsEvt } from "../types"; import { LogsPlugin } from "../../Logs/LogsPlugin"; +import { findMatchingAuditLogEntry } from "../../../utils/findMatchingAuditLogEntry"; /** * Create an UNBAN case automatically when a user is unbanned manually. @@ -24,11 +24,7 @@ export const CreateUnbanCaseOnManualUnbanEvt = modActionsEvt({ return; } - const relevantAuditLogEntry = await safeFindRelevantAuditLogEntry( - pluginData, - GuildAuditLogs.Actions.MEMBER_BAN_REMOVE as number, - user.id, - ); + const relevantAuditLogEntry = await findMatchingAuditLogEntry(pluginData.guild, "MEMBER_BAN_REMOVE", user.id); const casesPlugin = pluginData.getPlugin(CasesPlugin); diff --git a/backend/src/utils.ts b/backend/src/utils.ts index 32b7f548..9a37511e 100644 --- a/backend/src/utils.ts +++ b/backend/src/utils.ts @@ -635,63 +635,6 @@ export function sleep(ms: number): Promise { }); } -/** - * Attempts to find a relevant audit log entry for the given user and action - */ -const auditLogNextAttemptAfterFail: Map = new Map(); -const AUDIT_LOG_FAIL_COOLDOWN = 2 * MINUTES; - -export async function findRelevantAuditLogEntry( - guild: Guild, - actionType: number, - userId: string, - attempts: number = 3, - attemptDelay: number = 3000, -): Promise { - if (auditLogNextAttemptAfterFail.has(guild.id) && auditLogNextAttemptAfterFail.get(guild.id)! > Date.now()) { - return null; - } - - let auditLogs: GuildAuditLogs | null = null; - try { - auditLogs = await guild.fetchAuditLogs({ limit: 5, type: actionType }); - } catch (e) { - if (isDiscordAPIError(e) && e.code === 50013) { - // If we don't have permission to read audit log, set audit log requests on cooldown - auditLogNextAttemptAfterFail.set(guild.id, Date.now() + AUDIT_LOG_FAIL_COOLDOWN); - } else if (isDiscordHTTPError(e) && e.code === 500) { - // Ignore internal server errors which seem to be pretty common with audit log requests - } else if (e.message.startsWith("Request timed out")) { - // Ignore timeouts, try again next loop - } else { - throw e; - } - } - - const entries = auditLogs ? [...auditLogs.entries.values()] : []; - - entries.sort((a, b) => { - if (a.createdAt > b.createdAt) return -1; - if (a.createdAt > b.createdAt) return 1; - return 0; - }); - - const cutoffTS = Date.now() - 1000 * 60 * 2; - - const relevantEntry = entries.find((entry) => { - return (entry.target as { id }).id === userId && entry.createdTimestamp >= cutoffTS; - }); - - if (relevantEntry) { - return relevantEntry; - } else if (attempts > 0) { - await sleep(attemptDelay); - return findRelevantAuditLogEntry(guild, actionType, userId, attempts - 1, attemptDelay); - } else { - return null; - } -} - const realLinkRegex = /https?:\/\/\S+/; // http://anything or https://anything const plainLinkRegex = /((?!https?:\/\/)\S)+\.\S+/; // anything.anything, without http:// or https:// preceding it // Both of the above, with precedence on the first one diff --git a/backend/src/utils/findMatchingAuditLogEntry.ts b/backend/src/utils/findMatchingAuditLogEntry.ts new file mode 100644 index 00000000..fcce7a76 --- /dev/null +++ b/backend/src/utils/findMatchingAuditLogEntry.ts @@ -0,0 +1,68 @@ +import { Guild, GuildAuditLogsAction, GuildAuditLogsEntry } from "discord.js"; +import { SECONDS, sleep } from "../utils"; + +const BATCH_DEBOUNCE_TIME = 2 * SECONDS; +const BATCH_FETCH_COUNT_INCREMENT = 10; + +type Batch = { + _waitUntil: number; + _fetchCount: number; + _promise: Promise; + join: () => Promise; +}; + +const batches = new Map(); + +/** + * Find a recent audit log entry matching the given criteria. + * This function will debounce and batch simultaneous calls into one audit log request. + */ +export async function findMatchingAuditLogEntry( + guild: Guild, + action?: GuildAuditLogsAction, + targetId?: string, +): Promise { + let candidates: GuildAuditLogsEntry[]; + + if (batches.has(guild.id)) { + candidates = await batches.get(guild.id)!.join(); + } else { + const batch: Batch = { + _waitUntil: Date.now(), + _fetchCount: 0, + _promise: new Promise(async (resolve) => { + await sleep(BATCH_DEBOUNCE_TIME); + + do { + await sleep(Math.max(0, batch._waitUntil - Date.now())); + } while (Date.now() < batch._waitUntil); + + const result = await guild + .fetchAuditLogs({ + limit: batch._fetchCount, + }) + .catch((err) => { + // tslint:disable-next-line:no-console + console.warn(`[DEBUG] Audit log error in ${guild.id} (${guild.name}): ${err.message}`); + return null; + }); + const _candidates = Array.from(result?.entries.values() ?? []); + + batches.delete(guild.id); + resolve(_candidates); + }), + join() { + batch._waitUntil = Date.now() + BATCH_DEBOUNCE_TIME; + batch._fetchCount = Math.min(100, batch._fetchCount + BATCH_FETCH_COUNT_INCREMENT); + return batch._promise; + }, + }; + batches.set(guild.id, batch); + candidates = await batch.join(); + } + + return candidates.find( + (entry) => + (action == null || entry.action === action) && (targetId == null || (entry.target as any)?.id === targetId), + ); +} diff --git a/backend/src/utils/safeFindRelevantAuditLogEntry.ts b/backend/src/utils/safeFindRelevantAuditLogEntry.ts deleted file mode 100644 index 717c9923..00000000 --- a/backend/src/utils/safeFindRelevantAuditLogEntry.ts +++ /dev/null @@ -1,30 +0,0 @@ -import { GuildPluginData } from "knub"; -import { LogType } from "../data/LogType"; -import { LogsPlugin } from "../plugins/Logs/LogsPlugin"; -import { findRelevantAuditLogEntry, isDiscordAPIError } from "../utils"; - -/** - * Wrapper for findRelevantAuditLogEntry() that handles permission errors gracefully. - * Calling plugin must have LogsPlugin as a dependency (or be LogsPlugin itself). - */ -export async function safeFindRelevantAuditLogEntry( - pluginData: GuildPluginData, - actionType: number, - userId: string, - attempts?: number, - attemptDelay?: number, -) { - try { - return await findRelevantAuditLogEntry(pluginData.guild, actionType, userId, attempts, attemptDelay); - } catch (e) { - if (isDiscordAPIError(e) && e.code === 50013) { - const logs = pluginData.getPlugin(LogsPlugin); - logs.logBotAlert({ - body: "Missing permissions to read audit log", - }); - return; - } - - throw e; - } -}