diff --git a/src/discord/Core.ts b/src/discord/Core.ts index 7a57e6f..8eacaf5 100644 --- a/src/discord/Core.ts +++ b/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({ diff --git a/src/discord/InteractionManager.ts b/src/discord/InteractionManager.ts index 44d43e4..eb0ce3c 100644 --- a/src/discord/InteractionManager.ts +++ b/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, { diff --git a/src/discord/Ping.ts b/src/discord/Ping.ts index b0a94b7..c40317c 100644 --- a/src/discord/Ping.ts +++ b/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() })} ` + diff --git a/src/discord/VRChat/User.ts b/src/discord/VRChat/User.ts index b6e541f..3197957 100644 --- a/src/discord/VRChat/User.ts +++ b/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}**`, diff --git a/src/discord/VRChat/index.ts b/src/discord/VRChat/index.ts index 2f54664..f5a2fc1 100644 --- a/src/discord/VRChat/index.ts +++ b/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; - } - } } diff --git a/src/libs/ImageProxy.ts b/src/libs/ImageProxy.ts index 9489a0b..0161c8b 100644 --- a/src/libs/ImageProxy.ts +++ b/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; } } diff --git a/src/libs/Logger.ts b/src/libs/Logger.ts index ded0469..2a3ffb9 100644 --- a/src/libs/Logger.ts +++ b/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; diff --git a/src/providers/Cache.ts b/src/providers/Cache.ts index c7e2143..336bc69 100644 --- a/src/providers/Cache.ts +++ b/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 { - 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; } diff --git a/src/providers/Discord.ts b/src/providers/Discord.ts index 511abd4..39b4fee 100644 --- a/src/providers/Discord.ts +++ b/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(); @@ -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)) diff --git a/src/providers/DiscordMusicPlayer.ts b/src/providers/DiscordMusicPlayer.ts index 82e1977..37c0db8 100644 --- a/src/providers/DiscordMusicPlayer.ts +++ b/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; diff --git a/src/providers/Environment.ts b/src/providers/Environment.ts index 87e50bf..5db1ace 100644 --- a/src/providers/Environment.ts +++ b/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, diff --git a/src/providers/VRChatAPI.ts b/src/providers/VRChatAPI.ts index 8ce4f70..36297a0 100644 --- a/src/providers/VRChatAPI.ts +++ b/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; } diff --git a/src/utils/DiscordMessage.ts b/src/utils/DiscordMessage.ts index 02987b5..817e7ae 100644 --- a/src/utils/DiscordMessage.ts +++ b/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: '' }; @@ -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 { + 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 {