From ac7f6e728be64db0753dc5c16e444ad870525628 Mon Sep 17 00:00:00 2001
From: Dragory <2606411+Dragory@users.noreply.github.com>
Date: Thu, 2 May 2019 18:14:36 +0300
Subject: [PATCH] User resolving optimizations + debug logging

---
 src/plugins/Slowmode.ts       |  8 ++++----
 src/plugins/Tags.ts           |  2 ++
 src/plugins/Utility.ts        |  6 +++++-
 src/plugins/ZeppelinPlugin.ts | 24 +++++++++++++++++++++---
 src/utils.ts                  |  6 ++++++
 5 files changed, 38 insertions(+), 8 deletions(-)

diff --git a/src/plugins/Slowmode.ts b/src/plugins/Slowmode.ts
index eb2e8fb4..95ceac90 100644
--- a/src/plugins/Slowmode.ts
+++ b/src/plugins/Slowmode.ts
@@ -310,15 +310,15 @@ export class SlowmodePlugin extends ZeppelinPlugin<ISlowmodePluginConfig> {
     const thisMsgLock = await this.locks.acquire(`message-${msg.id}`);
     if (thisMsgLock.interrupted) return;
 
+    // Check if this channel even *has* a bot-maintained slowmode
+    const channelSlowmode = await this.slowmodes.getChannelSlowmode(channel.id);
+    if (!channelSlowmode) return thisMsgLock.unlock();
+
     // Make sure this user is affected by the slowmode
     const member = await this.getMember(msg.user_id);
     const isAffected = this.hasPermission("is_affected", { channelId: channel.id, userId: msg.user_id, member });
     if (!isAffected) return thisMsgLock.unlock();
 
-    // Check if this channel even *has* a bot-maintained slowmode
-    const channelSlowmode = await this.slowmodes.getChannelSlowmode(channel.id);
-    if (!channelSlowmode) return thisMsgLock.unlock();
-
     // Delete any extra messages sent after a slowmode was already applied
     const userHasSlowmode = await this.slowmodes.userHasSlowmode(channel.id, msg.user_id);
     if (userHasSlowmode) {
diff --git a/src/plugins/Tags.ts b/src/plugins/Tags.ts
index 4ec08d9a..3d0776b8 100644
--- a/src/plugins/Tags.ts
+++ b/src/plugins/Tags.ts
@@ -203,6 +203,8 @@ export class TagsPlugin extends ZeppelinPlugin<ITagsPluginConfig> {
   }
 
   async onMessageCreate(msg: SavedMessage) {
+    if (msg.is_bot) return;
+
     const member = await this.getMember(msg.user_id);
     if (!this.hasPermission("can_use", { member, channelId: msg.channel_id })) return;
 
diff --git a/src/plugins/Utility.ts b/src/plugins/Utility.ts
index 740d8f3c..e4b22f93 100644
--- a/src/plugins/Utility.ts
+++ b/src/plugins/Utility.ts
@@ -470,7 +470,11 @@ export class UtilityPlugin extends ZeppelinPlugin<IUtilityPluginConfig> {
   @d.permission("can_info")
   async infoCmd(msg: Message, args: { user?: User | UnknownUser }) {
     const user = args.user || msg.author;
-    const member = user && (await this.getMember(user.id));
+
+    let member;
+    if (!(user instanceof UnknownUser)) {
+      member = await this.getMember(user.id);
+    }
 
     const embed: EmbedOptions = {
       fields: [],
diff --git a/src/plugins/ZeppelinPlugin.ts b/src/plugins/ZeppelinPlugin.ts
index 03ac28cb..26892400 100644
--- a/src/plugins/ZeppelinPlugin.ts
+++ b/src/plugins/ZeppelinPlugin.ts
@@ -1,9 +1,13 @@
-import { IBasePluginConfig, IPluginOptions, Plugin } from "knub";
+import { IBasePluginConfig, IPluginOptions, logger, Plugin } from "knub";
 import { PluginRuntimeError } from "../PluginRuntimeError";
 import Ajv, { ErrorObject } from "ajv";
 import { isSnowflake, isUnicodeEmoji, resolveMember, resolveUser, UnknownUser } from "../utils";
 import { Member, User } from "eris";
 
+import { performance } from "perf_hooks";
+
+const SLOW_RESOLVE_THRESHOLD = 1500;
+
 export class ZeppelinPlugin<TConfig extends {} = IBasePluginConfig> extends Plugin<TConfig> {
   protected configSchema: any;
   protected permissionsSchema: any;
@@ -81,10 +85,24 @@ export class ZeppelinPlugin<TConfig extends {} = IBasePluginConfig> extends Plug
    * Resolves a user from the passed string. The passed string can be a user id, a user mention, a full username (with discrim), etc.
    */
   async resolveUser(userResolvable: string): Promise<User | UnknownUser> {
-    return resolveUser(this.bot, userResolvable);
+    const start = performance.now();
+    const user = await resolveUser(this.bot, userResolvable);
+    const time = performance.now() - start;
+    if (time >= SLOW_RESOLVE_THRESHOLD) {
+      const rounded = Math.round(time);
+      logger.warn(`Slow user resolve (${rounded}ms): ${userResolvable}`);
+    }
+    return user;
   }
 
   async getMember(memberResolvable: string): Promise<Member> {
-    return resolveMember(this.bot, this.guild, memberResolvable);
+    const start = performance.now();
+    const member = await resolveMember(this.bot, this.guild, memberResolvable);
+    const time = performance.now() - start;
+    if (time >= SLOW_RESOLVE_THRESHOLD) {
+      const rounded = Math.round(time);
+      logger.warn(`Slow member resolve (${rounded}ms): ${memberResolvable} in ${this.guild.name} (${this.guild.id})`);
+    }
+    return member;
   }
 }
diff --git a/src/utils.ts b/src/utils.ts
index 2672cf65..6422f9a4 100644
--- a/src/utils.ts
+++ b/src/utils.ts
@@ -566,6 +566,9 @@ export async function resolveUser(bot: Client, value: string): Promise<User | Un
   if (cachedUser) return cachedUser;
 
   try {
+    logger.info(`Resolving unknown user: ${value} / ${userId}`);
+    console.trace();
+
     const freshUser = await bot.getRESTUser(userId);
     bot.users.add(freshUser, bot);
     return freshUser;
@@ -585,6 +588,9 @@ export async function resolveMember(bot: Client, guild: Guild, value: string): P
   // If not, fetch it from the API
   if (!member) {
     try {
+      logger.info(`Resolving unknown member: ${value}`);
+      console.trace();
+
       member = await bot.getRESTGuildMember(guild.id, user.id);
       member.id = user.id;
       member.guild = guild;