Improved logging in various modules. Customized log output. Resolves #2

for many modules.

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<bool, Error> {
     {
         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<bool, Error> {
     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<bool, Error> {
     {
         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?;
 

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!(
+                    "<url: {}>",
+                    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
+        )
+    }
+}

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<u64, ClientState>,
 }
@@ -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::<ClientState>())
+        )
+    }
+}

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?;

src/handlers/disconnect_handler.rs

@@ -8,21 +8,24 @@ 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<RwLock<ClientStateMap>>,
     pub(crate) manager: Arc<Songbird>,
     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<Event> {
-        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() {

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<Cache>,
@@ -19,13 +21,37 @@ pub(crate) struct InactivityHandler {
     pub(crate) manager: Arc<Songbird>,
 }
 
+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<Event> {
         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
     }
 }

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)
             });
 

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<Event> {
-        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 {

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
+}