Add diagnostic logging to NSFW review flow

NSFW reports posted via the website-side GraphQL mutation aren't
triggering reviews when moderators react in Discord, but the bot-command
path (!review) works. Adds structured logging to disambiguate the two
paths and pinpoint which step in the path-B (graphql) flow is failing:

- DiscordEventHandler: client lifecycle events (ready, error, disconnect,
  reconnecting, shardError), login failures, top-level
  messageReactionAdd listener so we can see whether the Next.js-side
  gateway receives reactions at all
- DiscordEventHandler.handle: entry log + try/catch so swallowed errors
  surface (notify is fire-and-forget)
- requestReview: entry, resolved tweetStatus, explicit "skipping
  already-reviewed" log
- postSkin: new optional source param so logs can distinguish the bot
  command from the graphql mutation; logs at entry, after send, on bot
  reaction success/failure, awaiting reactions, awaitReactions resolved
- loggingFilter wrapping the awaitReactions filter to log every observed
  reaction with pass/fail and any filter errors

Author: captbaritone

packages/skin-database/api/DiscordEventHandler.ts

@@ -4,15 +4,57 @@ import * as Config from "../config";
 import SkinModel from "../data/SkinModel";
 import * as DiscordUtils from "../discord-bot/utils";
 import UserContext from "../data/UserContext";
+import logger from "../logger";
 
 export default class DiscordEventHandler {
   _clientPromise: Promise<Discord.Client>;
 
   constructor() {
+    logger.info("DiscordEventHandler: constructing");
     const _client = new Discord.Client();
+    _client.on("ready", () => {
+      logger.info("DiscordEventHandler: client ready", {
+        user: _client.user?.tag,
+      });
+    });
+    _client.on("error", (err: any) => {
+      logger.error("DiscordEventHandler: client error", {
+        err: err?.message,
+        stack: err?.stack,
+      });
+    });
+    _client.on("disconnect", (event: any) => {
+      logger.warn("DiscordEventHandler: client disconnect", { event });
+    });
+    _client.on("reconnecting", () => {
+      logger.warn("DiscordEventHandler: client reconnecting");
+    });
+    _client.on("shardError", (err: any) => {
+      logger.error("DiscordEventHandler: shard error", {
+        err: err?.message,
+        stack: err?.stack,
+      });
+    });
+    _client.on("messageReactionAdd", (reaction: any, user: any) => {
+      logger.info("DiscordEventHandler: messageReactionAdd", {
+        emoji: reaction?.emoji?.name,
+        msgId: reaction?.message?.id,
+        channelId: reaction?.message?.channel?.id,
+        userId: user?.id,
+        username: user?.username,
+        userIsBot: user?.bot,
+      });
+    });
     this._clientPromise = _client
       .login(Config.discordToken)
-      .then(() => _client);
+      .then(() => _client)
+      .catch((err) => {
+        logger.error("DiscordEventHandler: login failed", {
+          err: err?.message,
+          stack: err?.stack,
+        });
+        throw err;
+      });
   }
 
   async dispose() {
@@ -34,6 +76,24 @@ export default class DiscordEventHandler {
   }
 
   async handle(action: ApiAction): Promise<void> {
+    const actionMd5 = "md5" in action ? action.md5 : undefined;
+    logger.info("DiscordEventHandler.handle: entry", {
+      type: action.type,
+      md5: actionMd5,
+    });
+    try {
+      await this._handle(action);
+    } catch (err: any) {
+      logger.error("DiscordEventHandler.handle: failed", {
+        type: action.type,
+        md5: actionMd5,
+        err: err?.message,
+        stack: err?.stack,
+      });
+    }
+  }
+
+  private async _handle(action: ApiAction): Promise<void> {
     const ctx = new UserContext();
     switch (action.type) {
       case "REVIEW_REQUESTED":
@@ -159,19 +219,31 @@ export default class DiscordEventHandler {
   }
 
   private async requestReview(md5: string, ctx: UserContext) {
+    logger.info("requestReview: entry", { md5 });
     const skin = await SkinModel.fromMd5(ctx, md5);
     if (skin == null) {
+      logger.warn("requestReview: skin not found", { md5 });
       return;
     }
     const dest = await this.getChannel(Config.NSFW_SKIN_CHANNEL_ID);
     const tweetStatus = await skin.getTweetStatus();
+    logger.info("requestReview: resolved", {
+      md5,
+      tweetStatus,
+      channelId: Config.NSFW_SKIN_CHANNEL_ID,
+    });
     if (tweetStatus === "UNREVIEWED") {
       await DiscordUtils.postSkin({
         md5,
         title: (filename) => `Review: ${filename}`,
         dest,
+        source: "graphql:request_nsfw_review_for_skin",
       });
     } else {
+      logger.info("requestReview: skipping post, already reviewed", {
+        md5,
+        tweetStatus,
+      });
       // Too much nosie
       // await DiscordUtils.sendAlreadyReviewed({ md5, dest });
     }

packages/skin-database/discord-bot/commands/review.ts

@@ -15,6 +15,7 @@ async function reviewSkin(message: Message): Promise<void> {
     md5,
     title: (filename) => `Review: ${filename}`,
     dest: message.channel,
+    source: "bot:!review",
   });
 }
 

packages/skin-database/discord-bot/utils.ts

@@ -29,18 +29,21 @@ export async function postSkin({
   md5,
   title: _title,
   dest,
+  source = "unknown",
 }: {
   md5: string;
   title?: (filename: string | null) => string;
   dest: TextChannel | DMChannel;
+  source?: string;
 }) {
   const ctx = new UserContext();
 
-  console.log("postSkin...");
+  const destName = "name" in dest ? dest.name : "DM";
+  logger.info("postSkin: entry", { md5, source, dest: destName });
   const skin = await SkinModel.fromMd5(ctx, md5);
   if (skin == null) {
     console.warn("Could not find skin for md5", { md5, alert: true });
-    logger.warn("Could not find skin for md5", { md5, alert: true });
+    logger.warn("Could not find skin for md5", { md5, alert: true, source });
     return;
   }
   const readmeText = await skin.getReadme();
@@ -108,14 +111,62 @@ export async function postSkin({
 
   // @ts-ignore WAT?
   const msg = await dest.send(embed);
+  const msgId = Array.isArray(msg) ? msg.map((m) => m.id).join(",") : msg.id;
+  logger.info("postSkin: sent message", { md5, source, msgId, isArray: Array.isArray(msg) });
   if (tweetStatus !== "UNREVIEWED") {
+    logger.info("postSkin: skipping reactions, not UNREVIEWED", { md5, source, msgId, tweetStatus });
     return;
   }
 
   // Don't await
-  Promise.all([msg.react("👍"), msg.react("👎"), msg.react("🔞")]);
+  Promise.all([msg.react("👍"), msg.react("👎"), msg.react("🔞")])
+    .then(() => logger.info("postSkin: bot reactions added", { md5, source, msgId }))
+    .catch((err) =>
+      logger.error("postSkin: bot reactions failed", {
+        md5,
+        source,
+        msgId,
+        err: err?.message,
+        stack: err?.stack,
+      })
+    );
+
+  const loggingFilter = async (
+    reaction: MessageReaction,
+    user: User
+  ): Promise<boolean> => {
+    let passes = false;
+    let err: string | undefined;
+    try {
+      passes = await filter(reaction);
+    } catch (e: any) {
+      err = e?.message ?? String(e);
+    }
+    logger.info("postSkin: reaction observed", {
+      md5,
+      source,
+      msgId,
+      emoji: reaction.emoji.name,
+      userId: user?.id,
+      username: user?.username,
+      userIsBot: user?.bot,
+      passes,
+      filterErr: err,
+    });
+    return passes;
+  };
+
+  logger.info("postSkin: awaiting reactions", { md5, source, msgId });
   // TODO: Timeout at some point
-  await msg.awaitReactions(filter, { max: 1 }).then(async (collected) => {
+  await msg
+    .awaitReactions(loggingFilter, { max: 1 })
+    .then(async (collected) => {
+    logger.info("postSkin: awaitReactions resolved", {
+      md5,
+      source,
+      msgId,
+      collectedSize: collected.size,
+    });
     const vote = collected.first();
     if (vote == null) {
       throw new Error("Did not expect vote to be empty");