Merge pull request #73 from kirameki-cafe/debug-logs

Added more debug logs

src/discord/Core.ts

@@ -7,6 +7,8 @@ import Logger from '../libs/Logger';
 import Cache from '../providers/Cache';
 import Prisma from '../providers/Prisma';
 
+const LOGGING_TAG = '[DiscordCore]';
+
 export default class Core extends DiscordModule {
     public id: string = 'Discord_Core';
 
@@ -28,13 +30,15 @@ export default class Core extends DiscordModule {
 
         this.setActivity();
         setInterval(() => {
+            Logger.verbose(LOGGING_TAG, 'Updating activity');
             this.setActivity();
         }, 5 * 60 * 1000);
 
-        Logger.info('Core started successfully');
+        Logger.info(LOGGING_TAG, 'Core started successfully');
     }
 
     async GuildCreate(guild: Guild) {
+        Logger.info(LOGGING_TAG, `Joined guild ${guild.name} (${guild.id})`);
         if (await Prisma.client.guild.findFirst({ where: { id: guild.id } })) return;
 
         await Prisma.client.guild.create({

src/discord/InteractionManager.ts

@@ -16,6 +16,9 @@ import {
     unregisterAllGuildsCommands,
     unregisterAllGlobalCommands
 } from '../utils/DiscordInteraction';
+import Logger from '../libs/Logger';
+
+const LOGGING_TAG = '[InteractionManager]';
 
 const EMBEDS = {
     INTERACTION_INFO: (data: HybridInteractionMessage) => {
@@ -97,6 +100,7 @@ export default class InteractionManager extends DiscordModule {
 
         const funct = {
             unloadAll: async (data: HybridInteractionMessage) => {
+                Logger.info(LOGGING_TAG, 'Unloading all interaction');
                 let placeholder: HybridInteractionMessage | undefined;
 
                 let _placeholder = await sendHybridInteractionMessageResponse(data, {
@@ -127,6 +131,7 @@ export default class InteractionManager extends DiscordModule {
                 }
             },
             unloadGlobal: async (data: HybridInteractionMessage) => {
+                Logger.info(LOGGING_TAG, 'Unloading all global interaction');
                 let placeholder: HybridInteractionMessage | undefined;
 
                 let _placeholder = await sendHybridInteractionMessageResponse(data, {
@@ -157,6 +162,7 @@ export default class InteractionManager extends DiscordModule {
                 }
             },
             reloadGlobal: async (data: HybridInteractionMessage) => {
+                Logger.info(LOGGING_TAG, 'Reloading all global interaction');
                 let placeholder: HybridInteractionMessage | undefined;
 
                 let _placeholder = await sendHybridInteractionMessageResponse(data, {
@@ -188,6 +194,7 @@ export default class InteractionManager extends DiscordModule {
                 }
             },
             reloadAll: async (data: HybridInteractionMessage) => {
+                Logger.info(LOGGING_TAG, 'Reloading all interaction');
                 let placeholder: HybridInteractionMessage | undefined;
 
                 let _placeholder = await sendHybridInteractionMessageResponse(data, {

src/discord/Ping.ts

@@ -11,6 +11,9 @@ import Locale from '../services/Locale';
 
 import DiscordModule, { HybridInteractionMessage } from '../utils/DiscordModule';
 import { makeSuccessEmbed, makeProcessingEmbed, sendHybridInteractionMessageResponse } from '../utils/DiscordMessage';
+import Logger from '../libs/Logger';
+
+const LOGGING_TAG = '[Ping]';
 
 enum MeasureType {
     Ping = 'ping',
@@ -75,26 +78,36 @@ export default class Ping extends DiscordModule {
                     let stringCurrent = `${entry.title}`;
 
                     if (entry.type === MeasureType.Ping) {
+                        Logger.debug(LOGGING_TAG, `Pinging ${entry.host}`);
                         const res = await NodePing.promise.probe(entry.host!, { min_reply: 4 });
 
                         if (!res.alive) {
+                            Logger.debug(LOGGING_TAG, `Ping failed for ${entry.host} (not alive)`);
                             stringCurrent += 'Failed';
                             return finalString.push(stringCurrent);
                         }
 
                         if (res.avg === 'unknown' || res.min === 'unknown' || res.max === 'unknown') {
+                            Logger.debug(LOGGING_TAG, `Ping failed for ${entry.host} (unknown)`);
                             stringCurrent += 'Failed';
                             return finalString.push(stringCurrent);
                         }
 
+                        Logger.debug(
+                            LOGGING_TAG,
+                            `Ping result for ${entry.host}: Avg: ${res.avg}ms, Min: ${res.min}ms, Max: ${res.max}ms`
+                        );
+
                         stringCurrent += `${parseFloat(res.avg).toFixed(1)}ms (${parseFloat(res.min).toFixed(
                             1
                         )}ms - ${parseFloat(res.max).toFixed(1)}ms)`;
                         finalString.push(stringCurrent);
                     } else if (entry.type === MeasureType.DiscordWebsocket) {
+                        Logger.debug(LOGGING_TAG, `Pinging DiscordWebsocket`);
                         stringCurrent += `${Math.round(DiscordProvider.client.ws.ping).toFixed(1)}ms`;
                         finalString.push(stringCurrent);
                     } else if (entry.type === MeasureType.DiscordHTTPPing) {
+                        Logger.debug(LOGGING_TAG, `Pinging DiscordHTTPPing`);
                         stringCurrent += `${Math.abs(afterEditDate - beforeEditDate).toFixed(1)}ms`;
                         finalString.push(stringCurrent);
                     }
@@ -105,6 +118,8 @@ export default class Ping extends DiscordModule {
             { concurrency: 5 }
         );
 
+        Logger.debug(LOGGING_TAG, `All pings done, sending message`);
+
         finalString.push('');
         finalString.push(
             `💻 ${locale.__('ping.running_on', { HOST: os.hostname() })} ` +

src/discord/VRChat/User.ts

@@ -7,6 +7,9 @@ import DiscordModule, { HybridInteractionMessage } from '../../utils/DiscordModu
 import { makeInfoEmbed, makeErrorEmbed, sendHybridInteractionMessageResponse } from '../../utils/DiscordMessage';
 import Environment from '../../providers/Environment';
 import ImagePorxy from '../../libs/ImageProxy';
+import Logger from '../../libs/Logger';
+
+const LOGGING_TAG = '[VRChatUser]';
 
 const EMBEDS = {
     NO_USER_FOUND: (data: HybridInteractionMessage) => {
@@ -84,6 +87,8 @@ export default class VRChatUser {
             await data.getSlashCommand().deferReply();
         }
 
+        Logger.verbose(LOGGING_TAG, `Showing user ${user.displayName} (${user.id})`, JSON.stringify(user));
+
         const embed = makeInfoEmbed({
             icon: null,
             title: `**${user.displayName}**`,

src/discord/VRChat/index.ts

@@ -90,12 +90,4 @@ export default class VRChat extends DiscordModule {
                 return await VRChatWorld.run(data, args);
         }
     }
-
-    private numberWithCommas(x: Number) {
-        try {
-            return x.toString().replace(/\B(?=(\d{3})+(?!\d))/g, ',');
-        } catch (err) {
-            return x;
-        }
-    }
 }

src/libs/ImageProxy.ts

@@ -1,5 +1,8 @@
 import { createHmac } from 'crypto';
 import Environment from '../providers/Environment';
+import Logger from './Logger';
+
+const LOGGING_TAG = '[ImageProxy]';
 
 export default class ImagePorxy {
     public static signImageProxyURL(url: string, modifiers: string | undefined = undefined) {
@@ -22,6 +25,8 @@ export default class ImagePorxy {
 
         const signature = sign(Environment.get().IMGPROXY_SALT, path, Environment.get().IMGPROXY_KEY);
         const result = `${Environment.get().IMGPROXY_HOST}${signature}${path}`;
+
+        Logger.verbose(LOGGING_TAG, `Signed URL ${result}`);
         return result;
     }
 }

src/libs/Logger.ts

@@ -1,4 +1,4 @@
-import winston from 'winston';
+import winston, { verbose } from 'winston';
 
 const levels = {
     critical: 0,
@@ -7,12 +7,16 @@ const levels = {
     warn: 3,
     info: 4,
     http: 5,
-    debug: 6
+    debug: 6,
+    verbose: 7
 };
 
 const level = () => {
     const env = process.env.NODE_ENV || 'development';
     const isDevelopment = env === 'development';
+    const isVerbose = process.env.VERBOSE ? process.env.VERBOSE.toLowerCase() === 'true' && isDevelopment : false;
+    if (isVerbose) return 'verbose';
+
     return isDevelopment ? 'debug' : 'info';
 };
 
@@ -23,7 +27,8 @@ const colors = {
     warn: 'yellow',
     info: 'green',
     http: 'magenta',
-    debug: 'white'
+    debug: 'white',
+    verbose: 'gray'
 };
 
 winston.addColors(colors);
@@ -59,4 +64,15 @@ const Logger = winston.createLogger({
     transports
 });
 
+const wrapper = (original: winston.LeveledLogMethod) => {
+    return (...args: any) => original(args.join(' '));
+};
+
+Logger.error = wrapper(Logger.error);
+Logger.warn = wrapper(Logger.warn);
+Logger.info = wrapper(Logger.info);
+Logger.verbose = wrapper(Logger.verbose);
+Logger.debug = wrapper(Logger.debug);
+Logger.silly = wrapper(Logger.silly);
+
 export default Logger;

src/providers/Cache.ts

@@ -1,6 +1,9 @@
 import { User, Guild } from '@prisma/client';
 import { Snowflake } from 'discord-api-types/v10';
 import Prisma from './Prisma';
+import Logger from '../libs/Logger';
+
+const LOGGING_TAG = '[PrismaCache]';
 
 class Cache {
     private cache: {
@@ -16,6 +19,7 @@ class Cache {
     }
 
     public async updateGuildsCache() {
+        Logger.debug(LOGGING_TAG, 'Updating guilds cache');
         const Guilds = await Prisma.client.guild.findMany();
         for (let guild of Guilds) {
             this.setGuildCache(guild.id, guild);
@@ -23,6 +27,7 @@ class Cache {
     }
 
     public async updateGuildCache(id: Snowflake) {
+        Logger.debug(LOGGING_TAG, `Updating guild cache for ${id}`);
         const DBGuild = await Prisma.client.guild.findFirst({ where: { id: id } });
 
         // TODO: Try to fetch guild, create if not found or throw error
@@ -31,6 +36,7 @@ class Cache {
     }
 
     public async updateUserCache(id: Snowflake) {
+        Logger.debug(LOGGING_TAG, `Updating user cache for ${id}`);
         let user = await Prisma.client.user.findUnique({ where: { id } });
         if (!user) {
             user = await Prisma.client.user.create({
@@ -58,8 +64,12 @@ class Cache {
     }
 
     public async getCachedUser(id: Snowflake): Promise<User | undefined> {
-        if (typeof this.cache.Users[id] !== 'undefined') return this.cache.Users[id];
+        if (typeof this.cache.Users[id] !== 'undefined') {
+            Logger.debug(LOGGING_TAG, `Cache hit for user ${id}`);
+            return this.cache.Users[id];
+        }
 
+        Logger.debug(LOGGING_TAG, `Looking up user ${id} in Prisma`);
         const user = await Prisma.client.user.findUnique({
             where: {
                 id: id
@@ -73,10 +83,12 @@ class Cache {
     }
 
     public setGuildCache(id: Snowflake, data: Guild): void {
+        Logger.debug(LOGGING_TAG, `Caching guild ${id}`);
         this.cache.Guilds[id] = data;
     }
 
     public setUserCache(id: Snowflake, data: User): void {
+        Logger.debug(LOGGING_TAG, `Caching user ${id}`);
         this.cache.Users[id] = data;
     }
 

src/providers/Discord.ts

@@ -49,6 +49,8 @@ import Discord_Developer_Debug from '../discord/Developer/Debug';
 import Cache from './Cache';
 import DiscordModule from '../utils/DiscordModule';
 
+const LOGGING_TAG = '[DiscordProvider]';
+
 class Discord {
     public client: Client;
     private loaded_module = new Map<string, DiscordModule>();
@@ -111,7 +113,10 @@ class Discord {
                             _module.id
                         }. ${this.loaded_module.get(_module.id)!.constructor.name} is already assigned to this id.`
                     );
-                else this.loaded_module.set(_module.id, _module);
+                else {
+                    Logger.verbose(LOGGING_TAG, `Loaded module ${_module.constructor.name}`);
+                    this.loaded_module.set(_module.id, _module);
+                }
             } else Logger.error(`Invalid module ${_module.constructor.name}. The module does not have an id.`);
         }
 
@@ -119,6 +124,7 @@ class Discord {
 
         for (const module of this.loaded_module) {
             let thisModule: DiscordModule = module[1];
+            Logger.verbose(LOGGING_TAG, `Initializing module ${thisModule.constructor.name}`);
             thisModule.Init();
         }
 
@@ -126,6 +132,7 @@ class Discord {
         this.client.on('ready', () => {
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
+                Logger.verbose(LOGGING_TAG, `Triggering 'ready' event for module ${thisModule.constructor.name}`);
                 thisModule.Ready();
             }
         });
@@ -134,6 +141,10 @@ class Discord {
         this.client.on('guildMemberAdd', (member: GuildMember) => {
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
+                Logger.verbose(
+                    LOGGING_TAG,
+                    `Triggering 'guildMemberAdd' event for module ${thisModule.constructor.name}`
+                );
                 thisModule.GuildMemberAdd(member);
             }
         });
@@ -154,11 +165,24 @@ class Discord {
                         thisModule.commandInteractionName
                     ) {
                         thisModule.GuildCommandInteractionCreate(interaction);
-                        if (interaction.commandName.toLowerCase() === thisModule.commandInteractionName)
+                        if (interaction.commandName.toLowerCase() === thisModule.commandInteractionName) {
+                            Logger.verbose(
+                                LOGGING_TAG,
+                                `Triggering 'GuildModuleCommandInteractionCreate' event for module ${thisModule.constructor.name}`
+                            );
                             thisModule.GuildModuleCommandInteractionCreate(interaction);
+                        }
                     } else if (interaction.isButton()) {
+                        Logger.verbose(
+                            LOGGING_TAG,
+                            `Triggering 'GuildButtonInteractionCreate' event for module ${thisModule.constructor.name}`
+                        );
                         thisModule.GuildButtonInteractionCreate(interaction);
                     } else if (interaction.isSelectMenu()) {
+                        Logger.verbose(
+                            LOGGING_TAG,
+                            `Triggering 'GuildSelectMenuInteractionCreate' event for module ${thisModule.constructor.name}`
+                        );
                         thisModule.GuildSelectMenuInteractionCreate(interaction);
                     }
                 }
@@ -171,6 +195,11 @@ class Discord {
         this.client.on('messageCreate', (message: Message) => {
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
+                // This spamms too much logs
+                //Logger.verbose(
+                //    LOGGING_TAG,
+                //    `Triggering 'messageCreate' event for module ${thisModule.constructor.name}`
+                //);
                 thisModule.GuildMessageCreate(message);
             }
         });
@@ -179,6 +208,7 @@ class Discord {
         this.client.on('guildCreate', (guild: Guild) => {
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
+                Logger.verbose(LOGGING_TAG, `Triggering 'guildCreate' event for module ${thisModule.constructor.name}`);
                 thisModule.GuildCreate(guild);
             }
         });
@@ -275,6 +305,11 @@ class Discord {
 
             if (!Cache.isUserCached(message.author.id)) await Cache.updateUserCache(message.author.id);
 
+            Logger.verbose(
+                LOGGING_TAG,
+                `Triggering 'GuildOnCommand (Message)' event to loaded modules for command ${command} by ${message.author.username} (${message.author.id}) in ${message.guild.name} (${message.guild.id})`
+            );
+
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
                 thisModule.GuildOnCommand(command, args, message);
@@ -314,6 +349,10 @@ class Discord {
 
             for (const module of this.loaded_module) {
                 let thisModule: DiscordModule = module[1];
+                Logger.verbose(
+                    LOGGING_TAG,
+                    `Triggering 'GuildOnCommand (Mention)' event for module ${thisModule.constructor.name}`
+                );
                 thisModule.GuildOnCommand(command, args, message);
 
                 if (thisModule.commands && thisModule.commands.includes(command))

src/providers/DiscordMusicPlayer.ts

@@ -27,6 +27,8 @@ import DiscordProvider from './Discord';
 import Environment from './Environment';
 import Logger from '../libs/Logger';
 
+const LOGGING_TAG = '[DiscordMusicPlayer]';
+
 export type ValidTracks = YouTubeVideo | SpotifyTrack;
 declare class YouTubeThumbnail {
     url: string;
@@ -65,6 +67,7 @@ interface TokenOptions {
 let tokenObject: TokenOptions = {};
 
 if (Environment.get().YOUTUBE_COOKIE_BASE64) {
+    Logger.debug(LOGGING_TAG, 'Setting YouTube cookie');
     tokenObject.youtube = {
         cookie: Buffer.from(Environment.get().YOUTUBE_COOKIE_BASE64, 'base64').toString()
     };
@@ -76,6 +79,7 @@ if (
     Environment.get().SPOTIFY_REFRESH_TOKEN &&
     Environment.get().SPOTIFY_CLIENT_MARKET
 ) {
+    Logger.debug(LOGGING_TAG, 'Setting Spotify token');
     tokenObject.spotify = {
         client_id: Environment.get().SPOTIFY_CLIENT_ID,
         client_secret: Environment.get().SPOTIFY_CLIENT_SECRET,
@@ -180,6 +184,7 @@ export enum DiscordMusicPlayerLoopMode {
     None = 'none',
     Current = 'current'
 }
+
 export class DiscordMusicPlayerInstance {
     public queue: Queue;
     public player: AudioPlayer;
@@ -322,6 +327,12 @@ export class DiscordMusicPlayerInstance {
             let resource;
             if (track instanceof YouTubeVideo) {
                 const stream = await playdl.stream(track.url);
+
+                Logger.verbose(
+                    LOGGING_TAG,
+                    `New stream created, type: ${stream.type}, url: ${track.url}, Guild: ${this.voiceChannel.guild.id}, VoiceChannel: ${this.voiceChannel.id}`
+                );
+
                 resource = createAudioResource(stream.stream, {
                     inputType: stream.type
                 });
@@ -331,6 +342,12 @@ export class DiscordMusicPlayerInstance {
                 if (!search) throw new Error('Unable to find Spotify track on YouTube');
 
                 const stream = await playdl.stream(search.url);
+
+                Logger.verbose(
+                    LOGGING_TAG,
+                    `New stream created, type: ${stream.type}, url: ${track.url}, Guild: ${this.voiceChannel.guild.id}, VoiceChannel: ${this.voiceChannel.id}`
+                );
+
                 resource = createAudioResource(stream.stream, {
                     inputType: stream.type
                 });
@@ -473,6 +490,12 @@ class DiscordMusicPlayer {
         const searched: YouTubeVideo[] = await playdl.search(query, {
             source: { youtube: 'video' }
         });
+
+        Logger.verbose(
+            LOGGING_TAG,
+            `Search YouTube by query: ${query}, Total result: ${searched.length}, ${JSON.stringify(searched)}`
+        );
+
         if (searched.length == 0) return null;
         return searched;
     }
@@ -491,7 +514,10 @@ class DiscordMusicPlayer {
     }
 
     public async searchSpotifyBySpotifyLink(spotifyLink: SpotifyLink) {
-        if (playdl.is_expired()) await playdl.refreshToken();
+        if (playdl.is_expired()) {
+            Logger.debug(LOGGING_TAG, 'Spotify token expired, refreshing...');
+            await playdl.refreshToken();
+        }
 
         if (spotifyLink.type != 'track') return;
 
@@ -502,6 +528,9 @@ class DiscordMusicPlayer {
                 Logger.error(err.message);
                 throw new Error('Error while searching on Spotify');
             });
+
+        Logger.verbose(LOGGING_TAG, `Search Spotify by link: ${spotifyLink.id}, ${JSON.stringify(searched)}`);
+
         if (!(searched instanceof SpotifyTrack)) return;
 
         if (!searched) return null;
@@ -514,6 +543,14 @@ class DiscordMusicPlayer {
         const searched: YouTubeVideo[] = await playdl.search('https://www.youtube.com/watch?v=' + youtubeLink.videoId, {
             source: { youtube: 'video' }
         });
+
+        Logger.verbose(
+            LOGGING_TAG,
+            `Search YouTube by link (Pass 1): ${youtubeLink.videoId}, Total result: ${
+                searched.length
+            }, ${JSON.stringify(searched)}`
+        );
+
         for (let video of searched) {
             if (video.id === youtubeLink.videoId) return video;
         }
@@ -522,6 +559,14 @@ class DiscordMusicPlayer {
         const searched2: YouTubeVideo[] = await playdl.search(youtubeLink.videoId, {
             source: { youtube: 'video' }
         });
+
+        Logger.verbose(
+            LOGGING_TAG,
+            `Seach YouTube by video ID (Pass 2): ${youtubeLink.videoId}, Total result: ${
+                searched2.length
+            }, ${JSON.stringify(searched2)}`
+        );
+
         for (let video of searched2) {
             if (video.id === youtubeLink.videoId) return video;
         }
@@ -532,12 +577,21 @@ class DiscordMusicPlayer {
             const searched: YouTubeVideo[] = await playdl.search(videoInfo.video_details.title, {
                 source: { youtube: 'video' }
             });
+
+            Logger.verbose(
+                LOGGING_TAG,
+                `Search YouTube by title (Pass 3): ${videoInfo.video_details.title}, Total result: ${
+                    searched.length
+                }, ${JSON.stringify(searched)}`
+            );
+
             for (let video of searched) {
                 if (video.id === youtubeLink.videoId) return video;
             }
         }
 
         let yt_info = await playdl.video_info('https://www.youtube.com/watch?v=' + youtubeLink.videoId);
+
         if (yt_info) {
             return new YouTubeVideo({
                 id: yt_info.video_details.id,
@@ -566,19 +620,26 @@ class DiscordMusicPlayer {
     }
 
     public async getYouTubeSongsInPlayList(youtubeLink: string) {
-        return await playdl.playlist_info(youtubeLink, {
+        const result = await playdl.playlist_info(youtubeLink, {
             incomplete: true
         });
+        Logger.verbose(LOGGING_TAG, `Get YouTube songs in playlist: ${youtubeLink}, ${JSON.stringify(result)}`);
+        return result;
     }
 
     public async getSpotifySongsInPlayList(spotifyLink: string) {
-        if (playdl.is_expired()) await playdl.refreshToken();
+        if (playdl.is_expired()) {
+            Logger.debug(LOGGING_TAG, 'Spotify token expired, refreshing...');
+            await playdl.refreshToken();
+        }
 
         const result = await playdl.spotify(spotifyLink).catch((err) => {
             Logger.error(err.message);
             throw new Error('Error while searching on Spotify');
         });
 
+        Logger.verbose(LOGGING_TAG, `Get Spotify songs in playlist: ${spotifyLink}, ${JSON.stringify(result)}`);
+
         if (!(result.type == 'playlist' || result.type == 'album')) throw new Error('Not a spotify playlist');
 
         return result as unknown as SpotifyPlaylist;

src/providers/Environment.ts

@@ -63,6 +63,7 @@ class Environment {
 
     public get(): any {
         const NODE_ENV = process.env.NODE_ENV;
+        const VERBOSE = process.env.VERBOSE;
 
         const DISCORD_TOKEN = process.env.DISCORD_TOKEN;
         const DEVELOPER_IDS = process.env.DEVELOPER_IDS;
@@ -90,6 +91,7 @@ class Environment {
 
         return {
             NODE_ENV,
+            VERBOSE,
 
             DISCORD_TOKEN,
             DEVELOPER_IDS,

src/providers/VRChatAPI.ts

@@ -3,6 +3,7 @@ import Environment from './Environment';
 import Logger from '../libs/Logger';
 import App from './App';
 
+const LOGGING_TAG = '[VRChatAPI]';
 const VRC_CACHE_DURATION = 5 * 60 * 1000; // 5 minutes
 
 interface VRChatAPIs {
@@ -29,6 +30,7 @@ interface Cache {
 class VRChatAPI {
     public client: VRChatAPIs | null;
     public configuration: VRChat.Configuration | null;
+
     private ready = false;
     private cache: Cache;
     private useragent: string | null = null;
@@ -46,7 +48,8 @@ class VRChatAPI {
         this.useragent = `Yumi/${App.version.replaceAll('/', '').replaceAll(' ', '-').replaceAll('--', '-')} ${
             Environment.get().VRC_CONTACT_EMAIL
         }`;
-        Logger.debug(`[VRChat] Using user agent ${this.useragent}`);
+
+        Logger.debug(LOGGING_TAG, `Using user agent ${this.useragent}`);
         this.configuration = new VRChat.Configuration({
             //username: Environment.get().VRC_USERNAME,
             //;password: Environment.get().VRC_PASSWORD,
@@ -66,31 +69,41 @@ class VRChatAPI {
             WorldsApi: new VRChat.WorldsApi(this.configuration)
         };
 
-        Logger.info('Logging in to VRChat');
+        Logger.info(LOGGING_TAG, 'Logging in to VRChat');
 
         let res;
         try {
             res = await this.client.AuthenticationApi.getCurrentUser();
         } catch (err: any) {
             if (err.response?.status === 401) {
-                Logger.error('Unable to log in to VRChat, check your credentials');
+                Logger.error(LOGGING_TAG, 'Unable to log in, check your credentials');
                 return;
             } else throw err;
         }
 
+        if ((res.data as any).requiresTwoFactorAuth) {
+            Logger.error(
+                LOGGING_TAG,
+                'Two factor authentication is required, please authenticate',
+                (res.data as any).requiresTwoFactorAuth
+            );
+            Logger.info(LOGGING_TAG, `Auth Cookie: ${this.configuration.baseOptions.headers.Cookie}`);
+            return;
+        }
+
         this.ready = true;
-        Logger.info('Logged in to VRChat as ' + res.data.displayName);
+        Logger.info(LOGGING_TAG, 'Logged in to VRChat as ' + res.data.displayName);
 
         setInterval(() => {
             for (let key in this.cache.Users) {
                 if (this.cache.Users[key].expires < new Date()) {
-                    Logger.debug('[VRChat] [Cache] Removing user ' + key + ' from cache');
+                    Logger.debug(LOGGING_TAG, `Removing user ${key} from cache (expired)`);
                     delete this.cache.Users[key];
                 }
             }
             for (let key in this.cache.Worlds) {
                 if (this.cache.Worlds[key].expires < new Date()) {
-                    Logger.debug('[VRChat] [Cache] Removing world ' + key + ' from cache');
+                    Logger.debug(LOGGING_TAG, `Removing world ${key} from cache (expired)`);
                     delete this.cache.Worlds[key];
                 }
             }
@@ -129,13 +142,15 @@ class VRChatAPI {
 
     public async getCachedUserById(id: string) {
         if (typeof this.cache.Users[id] !== 'undefined') {
-            Logger.debug('[VRChat] [Cache] Cache hit for user ' + id);
             if (this.cache.Users[id].expires > new Date()) {
+                Logger.debug(LOGGING_TAG, `Cache hit for user ${id}`);
+                Logger.verbose(LOGGING_TAG, `Cache hit for user ${id}, ${JSON.stringify(this.cache.Users[id].user)}}`);
                 return this.cache.Users[id].user;
             }
+            Logger.debug(LOGGING_TAG, `Cache hit for user ${id} but expired, refreshing`);
         }
 
-        Logger.debug('[VRChat] [Cache] Cache miss for ' + id);
+        Logger.debug(LOGGING_TAG, `Looking up user ${id} in VRChat API`);
         let user;
         try {
             user = await this.client!.UsersApi.getUser(id);
@@ -148,7 +163,7 @@ class VRChatAPI {
             return null;
         }
 
-        Logger.debug('[VRChat] [Cache] Caching user ' + id);
+        Logger.debug(LOGGING_TAG, `Caching user ${id}`);
         this.cache.Users[id] = {
             user: user.data,
             expires: new Date(Date.now() + VRC_CACHE_DURATION)
@@ -158,13 +173,18 @@ class VRChatAPI {
 
     public async getCachedWorldById(id: string) {
         if (typeof this.cache.Worlds[id] !== 'undefined') {
-            Logger.debug('[VRChat] [Cache] Cache hit for world ' + id);
             if (this.cache.Worlds[id].expires > new Date()) {
+                Logger.debug(LOGGING_TAG, `Cache hit for world ${id}`);
+                Logger.verbose(
+                    LOGGING_TAG,
+                    `Cache hit for world ${id}, ${JSON.stringify(this.cache.Worlds[id].world)}}`
+                );
                 return this.cache.Worlds[id].world;
             }
+            Logger.debug(LOGGING_TAG, `Cache hit for world ${id} but expired, refreshing`);
         }
 
-        Logger.debug('[VRChat] [Cache] Cache miss for ' + id);
+        Logger.debug(LOGGING_TAG, `Looking up world ${id} in VRChat API`);
         let world;
         try {
             world = await this.client!.WorldsApi.getWorld(id);
@@ -177,12 +197,12 @@ class VRChatAPI {
             return null;
         }
 
-        Logger.debug('[VRChat] [Cache] Caching world ' + id);
+        Logger.debug(LOGGING_TAG, `Caching world ${id}`);
+        Logger.verbose(LOGGING_TAG, `Caching world ${id}, ${JSON.stringify(world.data)}}`);
         this.cache.Worlds[id] = {
             world: world.data,
             expires: new Date(Date.now() + VRC_CACHE_DURATION)
         };
-
         return world.data;
     }
 

src/utils/DiscordMessage.ts

@@ -20,6 +20,8 @@ import App from '..';
 import { HybridInteractionMessage } from './DiscordModule';
 import Logger from '../libs/Logger';
 
+const LOGGING_TAG = '[DiscordMessage]';
+
 const emotes = {
     yumiloading: '<a:yumiloading:983269480085983262>'
 };
@@ -142,6 +144,7 @@ export async function sendMessage(
     user: User | undefined,
     options: string | MessagePayload | BaseMessageOptions
 ) {
+    Logger.verbose(LOGGING_TAG, `Sending message, ${JSON.stringify(options)})}`);
     let message;
 
     try {
@@ -171,6 +174,8 @@ export async function sendHybridInteractionMessageResponse(
     payload: BaseMessageOptions | InteractionReplyOptions,
     replace = false
 ): Promise<Message | BaseInteraction | undefined> {
+    Logger.verbose(LOGGING_TAG, `Sending hybrid interaction message response, ${JSON.stringify(payload)})}`);
+
     if (data.isApplicationCommand() || data.isButton() || data.isSelectMenu()) {
         const messageComponent = data.getMessageComponentInteraction();
 
@@ -218,6 +223,7 @@ export function getEmotes() {
 }
 
 async function sendReply(rMessage: Message, options: string | MessagePayload | BaseMessageOptions) {
+    Logger.verbose(LOGGING_TAG, `Sending reply, ${JSON.stringify(options)})}`);
     let message;
 
     try {