From c5b06dd0b28f13bff3d2ffd294646a80d355c99f Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Mon, 18 Sep 2023 15:48:43 +0100 Subject: [PATCH] Improved logging in various modules. Customized log output. Resolves #2 for many modules. --- src/checks/shared_room_check.rs | 10 +++- src/client_state/client_state.rs | 26 ++++++++++ src/client_state/client_state_map.rs | 16 +++++- src/commands/track.rs | 11 ++++- src/handlers/disconnect_handler.rs | 13 +++-- src/handlers/inactivity_handler.rs | 39 +++++++++++++-- src/handlers/queue_handler.rs | 4 +- src/handlers/reconnect_handler.rs | 2 +- src/logging.rs | 74 ++++++++++++++++++++++++++++ src/main.rs | 56 +-------------------- src/utils/banish.rs | 2 +- 11 files changed, 181 insertions(+), 72 deletions(-) create mode 100644 src/logging.rs diff --git a/src/checks/shared_room_check.rs b/src/checks/shared_room_check.rs index cd06d1f..49dfc33 100644 --- a/src/checks/shared_room_check.rs +++ b/src/checks/shared_room_check.rs @@ -1,3 +1,5 @@ +use log::info; + use crate::config::{Context, Error}; /// Check if the command's author is in the same voice channel as the bot. @@ -15,6 +17,8 @@ pub async fn shared_room_check(ctx: Context<'_>) -> Result { { Some(vc) => vc, None => { + info!("User failed command check: Command author is not connected to a voice channel.",); + ctx.say("Whoops. It looks like you're not in a voice channel.") .await?; return Ok(false); @@ -26,6 +30,8 @@ pub async fn shared_room_check(ctx: Context<'_>) -> Result { let client_state = match client_map.get(guild_id.as_u64()) { Some(client_state) => client_state, None => { + info!("User failed command check: Bot is not connected to a voice channel."); + ctx.say("I'm sorry but I can't do that. I am currently not in voice channel.") .await?; return Ok(false); @@ -37,9 +43,11 @@ pub async fn shared_room_check(ctx: Context<'_>) -> Result { { Ok(true) } else { + info!("User failed command check: Bot in use in another voice channel."); + ctx.say( "Seems that you're in a different voice channel.\ - You can only issue commands if we are in the same voice channel.", + You can only issue commands if we are in the same voice channel.", ) .await?; diff --git a/src/client_state/client_state.rs b/src/client_state/client_state.rs index d3927de..614de4b 100644 --- a/src/client_state/client_state.rs +++ b/src/client_state/client_state.rs @@ -1,3 +1,5 @@ +use std::fmt::Display; + use songbird::tracks::TrackHandle; #[derive(Default, Debug, Clone)] @@ -23,3 +25,27 @@ pub struct QueueElement { pub(crate) url: String, pub(crate) id: String, } + +impl Display for ClientState { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let track_data = self.current_track.as_ref().map_or_else( + || "None".to_string(), + |t| { + format!( + "", + t.metadata().source_url.as_ref().clone().unwrap() + ) + }, + ); + + write!( + f, + "ClientState(channel: {}, est_alloc: {} B)::{{ is_playing: {}, current_track: {}, song_queue: {:?}}} ", + self.current_channel.map_or_else(|| "None".to_string(), |c| format!("{}", c)), + std::mem::size_of_val(self), + self.is_playing, + track_data, + self.song_queue + ) + } +} diff --git a/src/client_state/client_state_map.rs b/src/client_state/client_state_map.rs index 390e1f4..cd20edc 100644 --- a/src/client_state/client_state_map.rs +++ b/src/client_state/client_state_map.rs @@ -1,8 +1,8 @@ -use std::collections::HashMap; +use std::{collections::HashMap, fmt::Display}; use crate::client_state::{ClientState, ClientStateError}; -#[derive(Clone)] +#[derive(Clone, Debug)] pub struct ClientStateMap { map: HashMap, } @@ -59,3 +59,15 @@ impl ClientStateMap { } } } + +impl Display for ClientStateMap { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "ClientStateMap(size: {}, capacity: {}, est_alloc: {} B)", + self.map.len(), + self.map.capacity(), + (self.map.capacity() * std::mem::size_of::()) + ) + } +} diff --git a/src/commands/track.rs b/src/commands/track.rs index b33153b..4e7e9ad 100644 --- a/src/commands/track.rs +++ b/src/commands/track.rs @@ -1,4 +1,4 @@ -use log::error; +use log::{error, info}; use crate::{ checks::shared_room_check, @@ -36,15 +36,18 @@ pub async fn pause(context: Context<'_>) -> Result<(), Error> { context.say("Track paused.").await?; } (false, Some(_)) => { + info!("Pause failed: Pause called on paused track.\n{client_state:?}"); context.say("The track is already paused.").await?; } (_, None) => { + info!("Pause failed: Pause called without a queried track.\n{client_state:?}"); context .say("No tracks in the buffer. A track must be queried first") .await?; } }; } else { + error!("Pause failed: Client state could not be retrived."); context.say("Sorry. Something has gone wrong.").await?; } @@ -61,6 +64,7 @@ pub async fn resume(context: Context<'_>) -> Result<(), Error> { if let Some(client_state) = client_map.get(guild_id.as_u64()).cloned() { match (client_state.is_playing, &client_state.current_track) { (true, Some(_)) => { + info!("Resume failed: Resume called on an active track.\n{client_state:?}"); context.say("The track is not paused.").await?; } (false, Some(track)) => { @@ -79,12 +83,14 @@ pub async fn resume(context: Context<'_>) -> Result<(), Error> { context.say("Track resumed.").await?; } (_, None) => { + info!("Resume failed: Resume called without a queried track.\n{client_state:?}"); context .say("No tracks in the buffer. A track must be queried first") .await?; } }; } else { + error!("Resume failed: Client state could not be retrived."); context.say("Sorry. Something has gone wrong.").await?; } @@ -131,6 +137,7 @@ pub async fn info(context: Context<'_>) -> Result<(), Error> { Ok(()) } else { + error!("Resume failed: Client state could not be retrived."); context.say("Sorry. Something went wrong.").await?; Ok(()) } @@ -153,7 +160,7 @@ pub async fn skip(context: Context<'_>) -> Result<(), Error> { }; if let Err(err) = t_handle.stop() { - error!("An error occured stopping a track. Error: {err:?}"); + error!("Skip failed: An error occured stopping a track. Error: {err:?}"); context .say("Sorry something went wrong. Could not skip the current track.") .await?; diff --git a/src/handlers/disconnect_handler.rs b/src/handlers/disconnect_handler.rs index 9bd98c0..62dfe6f 100644 --- a/src/handlers/disconnect_handler.rs +++ b/src/handlers/disconnect_handler.rs @@ -8,9 +8,7 @@ use songbird::{ use std::sync::Arc; use tokio::sync::RwLock; -use log::debug; - -use crate::client_state::ClientStateMap; +use crate::{client_state::ClientStateMap, logging::Log}; pub(crate) struct DisconnectHandler { pub(crate) client_state_map: Arc>, @@ -18,11 +16,16 @@ pub(crate) struct DisconnectHandler { pub(crate) guild: Guild, } +impl Log for DisconnectHandler { + fn log(&self) { + use log::info; + info!("DisconnectHandler({}) event fired.", self.guild.id); + } +} + #[async_trait] impl EventHandler for DisconnectHandler { async fn act(&self, _: &EventContext<'_>) -> Option { - debug!("Disconnect Handler fired."); - let mut client_map = self.client_state_map.write().await; if client_map.get(self.guild.id.as_u64()).is_some() { diff --git a/src/handlers/inactivity_handler.rs b/src/handlers/inactivity_handler.rs index 7cd01f4..fcb5058 100644 --- a/src/handlers/inactivity_handler.rs +++ b/src/handlers/inactivity_handler.rs @@ -5,12 +5,14 @@ use songbird::{ Songbird, }; +use log::{debug, error}; use std::sync::Arc; use tokio::sync::RwLock; -use crate::client_state::ClientStateMap; - -use log::{debug, error}; +use crate::{ + client_state::ClientStateMap, + logging::{AsyncLog, Log}, +}; pub(crate) struct InactivityHandler { pub(crate) cache: Arc, @@ -19,13 +21,37 @@ pub(crate) struct InactivityHandler { pub(crate) manager: Arc, } +impl Log for InactivityHandler { + fn log(&self) { + use log::info; + info!("InactivityHandler({}) event fired.", self.guild.id); + } +} + +#[cfg(debug_assertions)] +#[async_trait] +impl AsyncLog for InactivityHandler { + async fn async_log(&self) { + debug!( + "InactivityHandler({})::{{ {} }}", + self.guild.id, + self.client_state_map.read().await + ); + } +} + #[async_trait] impl EventHandler for InactivityHandler { async fn act(&self, _: &EventContext<'_>) -> Option { let guild_id = self.guild.id; let mut client_map = self.client_state_map.write().await; - debug!("Inactivity hander acting"); + self.log(); + + #[cfg(debug_assertions)] + tokio::pin! { + let log_fut = self.async_log(); + } if let (Some(client_state), Some(guild)) = ( client_map.get(guild_id.as_u64()), @@ -54,6 +80,11 @@ impl EventHandler for InactivityHandler { } } } + std::mem::drop(client_map); + + #[cfg(debug_assertions)] + log_fut.await; + None } } diff --git a/src/handlers/queue_handler.rs b/src/handlers/queue_handler.rs index 29f84db..b9bbcc8 100644 --- a/src/handlers/queue_handler.rs +++ b/src/handlers/queue_handler.rs @@ -61,7 +61,7 @@ impl EventHandler for QueueHandler { .update(self.guild_id.as_u64(), &mut updated_state) .unwrap(); - t_handle + let _ = t_handle .add_event( Event::Track(TrackEvent::End), Self { @@ -71,7 +71,7 @@ impl EventHandler for QueueHandler { }, ) .or_else(|err| { - error!("Failed to add event listener for track end. Error: {err:?}"); + error!("Failed to add event listener for track end. Error: {err:?}\n{client_map:?}\n{client_state:?}"); Err(err) }); diff --git a/src/handlers/reconnect_handler.rs b/src/handlers/reconnect_handler.rs index 3439c75..ceea913 100644 --- a/src/handlers/reconnect_handler.rs +++ b/src/handlers/reconnect_handler.rs @@ -17,7 +17,7 @@ pub(crate) struct ReconnectHandler { #[async_trait] impl EventHandler for ReconnectHandler { async fn act(&self, ev: &EventContext<'_>) -> Option { - info!("Reconnect Handler fired."); + info!("ReconnectHandler({}) event fired.", self.guild.id); let mut client_state_map = self.client_state_map.write().await; let ev_data = match ev { diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 0000000..d3b70e1 --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,74 @@ +use poise::async_trait; + +pub(crate) trait Log { + fn log(&self); +} + +#[async_trait] +pub(crate) trait AsyncLog { + async fn async_log(&self); +} + +pub(crate) fn build_logger() -> env_logger::Builder { + use env_logger::fmt::Color; + + let mut log_builder = env_logger::builder(); + + if cfg!(debug_assertions) { + log_builder + .filter_module("poise", log::LevelFilter::Info) + .filter_module("songbird", log::LevelFilter::Info) + .filter_module(module_path!(), log::LevelFilter::Debug) + .filter_level(log::LevelFilter::Error) + } else { + log_builder + .filter_module(module_path!(), log::LevelFilter::Warn) + .filter_level(log::LevelFilter::Error) + }; + + log_builder.format(|buf, record| { + use chrono::Local; + use std::io::Write; + + let timestamp = Local::now().format("[%Y-%m-%d %H:%M:%S]"); + let level = record.level(); + + let level_color = match level { + log::Level::Error => Color::Red, + log::Level::Warn => Color::Yellow, + log::Level::Info => Color::Green, + log::Level::Debug => Color::Blue, + log::Level::Trace => Color::Magenta, + }; + + let mut timestamp_sty = buf.style(); + timestamp_sty + .set_bg(Color::Rgb(139, 0, 139)) + .set_color(Color::White); + + let mut level_sty = buf.style(); + level_sty + .set_color(level_color) + .set_intense(true) + .set_bold(true); + + let mut mod_sty = buf.style(); + mod_sty.set_color(Color::Blue).set_dimmed(true); + + write!( + buf, + "{} |{}| {} @{}:{}\n{}\n\n", + timestamp_sty.value(timestamp), + level_sty.value(level), + mod_sty.value(record.module_path().unwrap_or("unspecified mod")), + record + .file() + .and_then(|p| p.rsplit('/').next()) + .unwrap_or("unspecified file"), + record.line().unwrap_or(0), + record.args() + ) + }); + + log_builder +} diff --git a/src/main.rs b/src/main.rs index ae9bbc5..b3630fc 100644 --- a/src/main.rs +++ b/src/main.rs @@ -4,69 +4,17 @@ pub(crate) mod commands; pub(crate) mod config; pub(crate) mod framework; pub(crate) mod handlers; +pub(crate) mod logging; pub(crate) mod utils; use ::config::{Config, File, FileFormat}; -use env_logger::fmt::Color; use crate::config::Error; use poise::serenity_prelude::GatewayIntents; -fn build_logger() -> env_logger::Builder { - let mut log_builder = env_logger::builder(); - - if cfg!(debug_assertions) { - log_builder - .filter_module("poise", log::LevelFilter::Info) - .filter_module(module_path!(), log::LevelFilter::Debug) - .filter_level(log::LevelFilter::Error) - } else { - log_builder - .filter_module(module_path!(), log::LevelFilter::Warn) - .filter_level(log::LevelFilter::Error) - }; - - log_builder.format(|buf, record| { - use chrono::Local; - use std::io::Write; - - let timestamp = Local::now().format("[%Y-%m-%d %H:%M:%S]"); - let level = record.level(); - - let level_color = match level { - log::Level::Error => Color::Red, - log::Level::Warn => Color::Yellow, - log::Level::Info => Color::Green, - log::Level::Debug => Color::Blue, - log::Level::Trace => Color::Magenta, - }; - - let mut timestamp_sty = buf.style(); - timestamp_sty - .set_bg(Color::Rgb(2, 48, 32)) - .set_color(Color::White); - - let mut level_sty = buf.style(); - level_sty - .set_color(level_color) - .set_intense(true) - .set_bold(true); - - write!( - buf, - "{} |{}|: {}\n-\n", - timestamp_sty.value(timestamp), - level_sty.value(level), - record.args() - ) - }); - - log_builder -} - #[tokio::main] async fn main() -> Result<(), Error> { - build_logger().init(); + logging::build_logger().init(); let intents = GatewayIntents::non_privileged() | GatewayIntents::GUILD_VOICE_STATES diff --git a/src/utils/banish.rs b/src/utils/banish.rs index e1c77cf..308519d 100644 --- a/src/utils/banish.rs +++ b/src/utils/banish.rs @@ -11,7 +11,7 @@ pub async fn banish(ctx: &Context<'_>) -> Result<(), Error> { client_map.remove(gid.as_u64()).unwrap_or_else(|e| { error!( - "Error encountered: {} for gid: {} from ClientStateMap", + "Error encountered: {} for gid: {}.\n{client_map:?}", e, gid.to_string() )