From b4e874ae078534096e466fce5a4f25834de7b7ca Mon Sep 17 00:00:00 2001 From: trivernis Date: Thu, 8 Apr 2021 17:39:53 +0200 Subject: [PATCH] Add logging with fern Signed-off-by: trivernis --- .gitignore | 3 +- Cargo.lock | 35 ++++++++++++ Cargo.toml | 6 +- src/client.rs | 18 ++---- src/commands/minecraft/enchantment.rs | 5 +- src/commands/minecraft/item.rs | 2 + src/commands/misc/help.rs | 5 +- src/commands/music/clear.rs | 3 +- src/commands/music/current.rs | 4 +- src/commands/music/join.rs | 1 + src/commands/music/leave.rs | 6 +- src/commands/music/mod.rs | 19 +++++++ src/commands/music/play.rs | 5 ++ src/commands/music/play_next.rs | 3 + src/commands/music/queue.rs | 7 ++- src/commands/music/shuffle.rs | 1 + src/commands/music/skip.rs | 3 +- src/commands/settings/get.rs | 5 +- src/database/mod.rs | 24 ++++++-- src/handler.rs | 21 +++++++ src/main.rs | 11 ++-- src/providers/music/mod.rs | 5 ++ src/providers/music/queue.rs | 1 + src/providers/music/spotify.rs | 31 ++++++++-- src/utils/logging.rs | 82 +++++++++++++++++++++++++++ src/utils/mod.rs | 5 +- 26 files changed, 270 insertions(+), 41 deletions(-) create mode 100644 src/handler.rs create mode 100644 src/utils/logging.rs diff --git a/.gitignore b/.gitignore index 09386ae..12508d9 100644 --- a/.gitignore +++ b/.gitignore @@ -1,4 +1,5 @@ /target bot.db .env -*.env \ No newline at end of file +*.env +logs \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index f8f5d6f..4a77dfc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -100,6 +100,17 @@ dependencies = [ "webpki-roots 0.21.1", ] +[[package]] +name = "atty" +version = "0.2.14" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8" +dependencies = [ + "hermit-abi", + "libc", + "winapi 0.3.9", +] + [[package]] name = "audiopus" version = "0.2.0" @@ -223,6 +234,17 @@ dependencies = [ "generic-array", ] +[[package]] +name = "colored" +version = "2.0.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b3616f750b84d8f0de8a58bda93e08e2a81ad3f523089b05f1dffecab48c6cbd" +dependencies = [ + "atty", + "lazy_static", + "winapi 0.3.9", +] + [[package]] name = "command_attr" version = "0.3.5" @@ -354,6 +376,15 @@ version = "0.1.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7360491ce676a36bf9bb3c56c1aa791658183a54d2744120f27285738d90465a" +[[package]] +name = "fern" +version = "0.6.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8c9a4820f0ccc8a7afd67c39a0f1a0f4b07ca1725164271a64939d7aeb9af065" +dependencies = [ + "log 0.4.14", +] + [[package]] name = "flate2" version = "1.0.20" @@ -1868,9 +1899,13 @@ name = "tobi-rs" version = "0.1.0" dependencies = [ "aspotify", + "chrono", + "colored", "dotenv", + "fern", "futures", "lazy_static", + "log 0.4.14", "minecraft-data-rs", "rand 0.8.3", "regex", diff --git a/Cargo.toml b/Cargo.toml index 8cfe376..29ec9f3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,4 +22,8 @@ rand = "0.8.3" regex = "1.4.5" aspotify = "0.7.0" lazy_static = "1.4.0" -futures = "0.3.13" \ No newline at end of file +futures = "0.3.13" +log = "0.4.14" +fern = "0.6.0" +chrono = "0.4.19" +colored = "2.0.0" \ No newline at end of file diff --git a/src/client.rs b/src/client.rs index 43cdd7e..7b5b3f7 100644 --- a/src/client.rs +++ b/src/client.rs @@ -1,5 +1,4 @@ -use serenity::async_trait; -use serenity::client::{Context, EventHandler}; +use serenity::client::Context; use serenity::framework::standard::macros::hook; use serenity::framework::standard::{CommandResult, DispatchError}; use serenity::framework::StandardFramework; @@ -9,19 +8,16 @@ use songbird::SerenityInit; use crate::commands::*; use crate::database::get_database; +use crate::handler::Handler; use crate::utils::error::{BotError, BotResult}; use crate::utils::store::{Store, StoreData}; -struct Handler; - -#[async_trait] -impl EventHandler for Handler {} - pub async fn get_client() -> BotResult { let token = dotenv::var("BOT_TOKEN").map_err(|_| BotError::MissingToken)?; let database = get_database()?; let client = Client::builder(token) + .event_handler(Handler) .framework(get_framework()) .register_songbird() .await?; @@ -61,18 +57,16 @@ async fn after_hook(ctx: &Context, msg: &Message, cmd_name: &str, error: Command let _ = msg .channel_id .send_message(ctx, |m| { - m.embed(|e| { - e.title("Error occurred") - .description(format!("```\n{}\n```", why)) - }) + m.embed(|e| e.title("Error occurred").description(format!("{}", why))) }) .await; - println!("Error in {}: {:?}", cmd_name, why); + log::warn!("Error in {}: {:?}", cmd_name, why); } } #[hook] async fn before_hook(ctx: &Context, msg: &Message, _: &str) -> bool { + log::trace!("Got command message {}", msg.content); let _ = msg.channel_id.broadcast_typing(ctx).await; true } diff --git a/src/commands/minecraft/enchantment.rs b/src/commands/minecraft/enchantment.rs index e05db59..1ddf7bc 100644 --- a/src/commands/minecraft/enchantment.rs +++ b/src/commands/minecraft/enchantment.rs @@ -1,5 +1,5 @@ use serenity::client::Context; -use serenity::framework::standard::{Args, CommandError, CommandResult, macros::command}; +use serenity::framework::standard::{macros::command, Args, CommandError, CommandResult}; use serenity::model::channel::Message; use crate::utils::store::Store; @@ -14,6 +14,8 @@ pub(crate) async fn enchantment(ctx: &Context, msg: &Message, args: Args) -> Com let data = ctx.data.read().await; let store = data.get::().expect("Failed to get store"); let enchantment_name = args.message().to_lowercase(); + log::debug!("Searching for enchantment {}", enchantment_name); + let enchantments_by_name = store .minecraft_data_api .enchantments @@ -25,6 +27,7 @@ pub(crate) async fn enchantment(ctx: &Context, msg: &Message, args: Args) -> Com enchantment_name )))? .clone(); + log::trace!("Enchantment is {:?}", enchantment); msg.channel_id .send_message(ctx, |m| { diff --git a/src/commands/minecraft/item.rs b/src/commands/minecraft/item.rs index 380d5bb..95c0183 100644 --- a/src/commands/minecraft/item.rs +++ b/src/commands/minecraft/item.rs @@ -15,6 +15,7 @@ pub(crate) async fn item(ctx: &Context, msg: &Message, args: Args) -> CommandRes let store = data.get::().expect("Failed to get store"); let item_name = args.message().to_lowercase(); + log::debug!("Searching for item '{}'", item_name); let items_by_name = store.minecraft_data_api.items.items_by_name()?; let item = items_by_name .get(&item_name) @@ -26,6 +27,7 @@ pub(crate) async fn item(ctx: &Context, msg: &Message, args: Args) -> CommandRes .minecraft_data_api .enchantments .enchantments_by_category()?; + log::trace!("Item is {:?}", item); msg.channel_id .send_message(ctx, |m| { diff --git a/src/commands/misc/help.rs b/src/commands/misc/help.rs index 9896e3c..5483532 100644 --- a/src/commands/misc/help.rs +++ b/src/commands/misc/help.rs @@ -1,13 +1,14 @@ use std::collections::HashSet; use serenity::client::Context; -use serenity::framework::standard::{Args, help_commands}; -use serenity::framework::standard::{CommandGroup, CommandResult, HelpOptions}; use serenity::framework::standard::macros::help; +use serenity::framework::standard::{help_commands, Args}; +use serenity::framework::standard::{CommandGroup, CommandResult, HelpOptions}; use serenity::model::channel::Message; use serenity::model::id::UserId; #[help] +#[max_levenshtein_distance(2)] pub async fn help( ctx: &Context, msg: &Message, diff --git a/src/commands/music/clear.rs b/src/commands/music/clear.rs index 8d3c819..e031cdd 100644 --- a/src/commands/music/clear.rs +++ b/src/commands/music/clear.rs @@ -1,6 +1,6 @@ use serenity::client::Context; -use serenity::framework::standard::CommandResult; use serenity::framework::standard::macros::command; +use serenity::framework::standard::CommandResult; use serenity::model::channel::Message; use crate::commands::music::get_queue_for_guild; @@ -13,6 +13,7 @@ use crate::commands::music::get_queue_for_guild; #[allowed_roles("DJ")] async fn clear(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Clearing queue for guild {}", guild.id); let queue = get_queue_for_guild(ctx, &guild.id).await?; { diff --git a/src/commands/music/current.rs b/src/commands/music/current.rs index 91c3768..5d078b3 100644 --- a/src/commands/music/current.rs +++ b/src/commands/music/current.rs @@ -1,6 +1,6 @@ use serenity::client::Context; -use serenity::framework::standard::CommandResult; use serenity::framework::standard::macros::command; +use serenity::framework::standard::CommandResult; use serenity::model::channel::Message; use crate::commands::music::get_queue_for_guild; @@ -13,11 +13,13 @@ use crate::commands::music::get_queue_for_guild; async fn current(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Displaying current song for queue in {}", guild.id); let queue = get_queue_for_guild(ctx, &guild.id).await?; let queue_lock = queue.lock().await; if let Some(current) = queue_lock.current() { let metadata = current.metadata().clone(); + log::trace!("Metadata is {:?}", metadata); msg.channel_id .send_message(ctx, |m| { m.embed(|mut e| { diff --git a/src/commands/music/join.rs b/src/commands/music/join.rs index ce0b5ae..b4a5a9d 100644 --- a/src/commands/music/join.rs +++ b/src/commands/music/join.rs @@ -12,6 +12,7 @@ use crate::commands::music::{get_channel_for_author, join_channel}; async fn join(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); let channel_id = get_channel_for_author(&msg.author.id, &guild)?; + log::debug!("Joining channel {} for guild {}", channel_id, guild.id); join_channel(ctx, channel_id, guild.id).await; Ok(()) diff --git a/src/commands/music/leave.rs b/src/commands/music/leave.rs index efcfb1e..53f9210 100644 --- a/src/commands/music/leave.rs +++ b/src/commands/music/leave.rs @@ -1,6 +1,6 @@ use serenity::client::Context; -use serenity::framework::standard::CommandResult; use serenity::framework::standard::macros::command; +use serenity::framework::standard::CommandResult; use serenity::model::channel::Message; use crate::commands::music::{get_queue_for_guild, get_voice_manager}; @@ -14,9 +14,11 @@ use crate::commands::music::{get_queue_for_guild, get_voice_manager}; async fn leave(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Leave request received for guild {}", guild.id); let manager = get_voice_manager(ctx).await; let queue = get_queue_for_guild(ctx, &guild.id).await?; let queue_lock = queue.lock().await; + log::trace!("Queue is {:?}", queue_lock); let handler = manager.get(guild.id); if let Some(handler) = handler { @@ -30,8 +32,10 @@ async fn leave(ctx: &Context, msg: &Message) -> CommandResult { if manager.get(guild.id).is_some() { manager.remove(guild.id).await?; msg.channel_id.say(ctx, "Left the voice channel").await?; + log::debug!("Left the voice channel"); } else { msg.channel_id.say(ctx, "Not in a voice channel").await?; + log::debug!("Not in a voice channel"); } Ok(()) diff --git a/src/commands/music/mod.rs b/src/commands/music/mod.rs index 04b8bb7..0b57ae1 100644 --- a/src/commands/music/mod.rs +++ b/src/commands/music/mod.rs @@ -48,6 +48,11 @@ pub struct Music; /// Joins a voice channel async fn join_channel(ctx: &Context, channel_id: ChannelId, guild_id: GuildId) -> Arc> { + log::debug!( + "Attempting to join channel {} in guild {}", + channel_id, + guild_id + ); let manager = songbird::get(ctx) .await .expect("Songbird Voice client placed in at initialisation.") @@ -56,12 +61,14 @@ async fn join_channel(ctx: &Context, channel_id: ChannelId, guild_id: GuildId) - let (handler, _) = manager.join(guild_id, channel_id).await; let mut data = ctx.data.write().await; let store = data.get_mut::().unwrap(); + log::debug!("Creating new queue"); let queue = Arc::new(Mutex::new(MusicQueue::new())); store.music_queues.insert(guild_id, queue.clone()); { let mut handler_lock = handler.lock().await; + log::debug!("Registering track end handler"); handler_lock.add_global_event( Event::Track(TrackEvent::End), SongEndNotifier { @@ -119,6 +126,7 @@ struct SongEndNotifier { #[async_trait] impl VoiceEventHandler for SongEndNotifier { async fn act(&self, _ctx: &EventContext<'_>) -> Option { + log::debug!("Song ended in {}. Playing next one", self.channel_id); while !play_next_in_queue(&self.http, &self.channel_id, &self.queue, &self.handler).await { tokio::time::sleep(Duration::from_millis(100)).await; } @@ -146,6 +154,7 @@ async fn play_next_in_queue( return false; } }; + log::debug!("Getting source for song '{}'", url); let source = match songbird::ytdl(&url).await { Ok(s) => s, Err(e) => { @@ -160,6 +169,7 @@ async fn play_next_in_queue( }; let mut handler_lock = handler.lock().await; let track = handler_lock.play_only_source(source); + log::trace!("Track is {:?}", track); queue_lock.set_current(track); } else { queue_lock.clear_current(); @@ -180,7 +190,9 @@ async fn get_songs_for_query(ctx: &Context, msg: &Message, query: &str) -> BotRe let data = ctx.data.read().await; let store = data.get::().unwrap(); + log::debug!("Querying play input {}", query); if YOUTUBE_URL_REGEX.is_match(query) { + log::debug!("Query is youtube video or playlist"); // try fetching the url as a playlist songs = get_videos_for_playlist(query) .await? @@ -190,30 +202,37 @@ async fn get_songs_for_query(ctx: &Context, msg: &Message, query: &str) -> BotRe // if no songs were found fetch the song as a video if songs.len() == 0 { + log::debug!("Query is youtube video"); let mut song: Song = get_video_information(query).await?.into(); added_one_msg(&ctx, msg, &mut song).await?; songs.push(song); } else { + log::debug!("Query is playlist with {} songs", songs.len()); added_multiple_msg(&ctx, msg, &mut songs).await?; } } else if SPOTIFY_PLAYLIST_REGEX.is_match(query) { // search for all songs in the playlist and search for them on youtube + log::debug!("Query is spotify playlist"); songs = store.spotify_api.get_songs_in_playlist(query).await?; added_multiple_msg(&ctx, msg, &mut songs).await?; } else if SPOTIFY_ALBUM_REGEX.is_match(query) { // fetch all songs in the album and search for them on youtube + log::debug!("Query is spotify album"); songs = store.spotify_api.get_songs_in_album(query).await?; added_multiple_msg(&ctx, msg, &mut songs).await?; } else if SPOTIFY_SONG_REGEX.is_match(query) { // fetch the song name and search it on youtube + log::debug!("Query is a spotify song"); let mut song = store.spotify_api.get_song_name(query).await?; added_one_msg(ctx, msg, &mut song).await?; songs.push(song); } else { + log::debug!("Query is a youtube search"); let mut song: Song = search_video_information(query.to_string()) .await? .ok_or(BotError::Msg(format!("Noting found for {}", query)))? .into(); + log::trace!("Search result is {:?}", song); added_one_msg(&ctx, msg, &mut song).await?; songs.push(song); diff --git a/src/commands/music/play.rs b/src/commands/music/play.rs index 90668e9..785902d 100644 --- a/src/commands/music/play.rs +++ b/src/commands/music/play.rs @@ -20,11 +20,13 @@ async fn play(ctx: &Context, msg: &Message, args: Args) -> CommandResult { let query = args.message(); let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Play request received for guild {}", guild.id); let manager = get_voice_manager(ctx).await; let mut handler = manager.get(guild.id); if handler.is_none() { + log::debug!("Not in a channel. Joining authors channel..."); msg.guild(&ctx.cache).await.unwrap(); let channel_id = get_channel_for_author(&msg.author.id, &guild)?; handler = Some(join_channel(ctx, channel_id, guild.id).await); @@ -37,6 +39,7 @@ async fn play(ctx: &Context, msg: &Message, args: Args) -> CommandResult { let queue = get_queue_for_guild(ctx, &guild.id).await?; let play_first = { + log::debug!("Adding song to queue"); let mut queue_lock = queue.lock().await; for song in songs { queue_lock.add(song); @@ -47,12 +50,14 @@ async fn play(ctx: &Context, msg: &Message, args: Args) -> CommandResult { .get_guild_setting(&guild.id, SETTING_AUTOSHUFFLE) .unwrap_or(false); if autoshuffle { + log::debug!("Autoshuffeling"); queue_lock.shuffle(); } queue_lock.current().is_none() }; if play_first { + log::debug!("Playing first song in queue"); play_next_in_queue(&ctx.http, &msg.channel_id, &queue, &handler_lock).await; } diff --git a/src/commands/music/play_next.rs b/src/commands/music/play_next.rs index 74a5f36..1e288a7 100644 --- a/src/commands/music/play_next.rs +++ b/src/commands/music/play_next.rs @@ -19,11 +19,13 @@ async fn play_next(ctx: &Context, msg: &Message, args: Args) -> CommandResult { let query = args.message(); let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Playing song as next song for guild {}", guild.id); let manager = get_voice_manager(ctx).await; let mut handler = manager.get(guild.id); if handler.is_none() { + log::debug!("Not in a voice channel. Joining authors channel"); msg.guild(&ctx.cache).await.unwrap(); let channel_id = get_channel_for_author(&msg.author.id, &guild)?; handler = Some(join_channel(ctx, channel_id, guild.id).await); @@ -37,6 +39,7 @@ async fn play_next(ctx: &Context, msg: &Message, args: Args) -> CommandResult { let play_first = { let mut queue_lock = queue.lock().await; songs.reverse(); + log::debug!("Enqueueing songs as next songs in the queue"); for song in songs { queue_lock.add_next(song); diff --git a/src/commands/music/queue.rs b/src/commands/music/queue.rs index 6a04c6d..b42ba5b 100644 --- a/src/commands/music/queue.rs +++ b/src/commands/music/queue.rs @@ -14,6 +14,7 @@ use crate::commands::music::get_queue_for_guild; #[aliases("q")] async fn queue(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::trace!("Displaying queue for guild {}", guild.id); let queue = get_queue_for_guild(ctx, &guild.id).await?; let queue_lock = queue.lock().await; @@ -23,6 +24,7 @@ async fn queue(ctx: &Context, msg: &Message) -> CommandResult { .map(|s| s.title().clone()) .enumerate() .collect(); + log::trace!("Songs are {:?}", songs); if songs.len() == 0 { msg.channel_id @@ -37,13 +39,14 @@ async fn queue(ctx: &Context, msg: &Message) -> CommandResult { let mut song_list = Vec::new(); for i in 0..min(10, songs.len() - 1) { - song_list.push(format!("{:0>3} - {}", songs[i].0, songs[i].1)) + song_list.push(format!("{:0>3} - {}", songs[i].0 + 1, songs[i].1)) } if songs.len() > 10 { song_list.push("...".to_string()); let last = songs.last().unwrap(); - song_list.push(format!("{:0>3} - {}", last.0, last.1)) + song_list.push(format!("{:0>3} - {}", last.0 + 1, last.1)) } + log::trace!("Song list is {:?}", song_list); msg.channel_id .send_message(ctx, |m| { m.embed(|e| { diff --git a/src/commands/music/shuffle.rs b/src/commands/music/shuffle.rs index 18ef15a..6e58caf 100644 --- a/src/commands/music/shuffle.rs +++ b/src/commands/music/shuffle.rs @@ -14,6 +14,7 @@ use crate::commands::music::get_queue_for_guild; async fn shuffle(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Shuffling queue for guild {}", guild.id); let queue = get_queue_for_guild(ctx, &guild.id).await?; { let mut queue_lock = queue.lock().await; diff --git a/src/commands/music/skip.rs b/src/commands/music/skip.rs index cbd2a48..bca3dcf 100644 --- a/src/commands/music/skip.rs +++ b/src/commands/music/skip.rs @@ -1,6 +1,6 @@ use serenity::client::Context; -use serenity::framework::standard::CommandResult; use serenity::framework::standard::macros::command; +use serenity::framework::standard::CommandResult; use serenity::model::channel::Message; use crate::commands::music::get_queue_for_guild; @@ -14,6 +14,7 @@ use crate::commands::music::get_queue_for_guild; async fn skip(ctx: &Context, msg: &Message) -> CommandResult { let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Skipping song for guild {}", guild.id); let queue = get_queue_for_guild(ctx, &guild.id).await?; let queue_lock = queue.lock().await; diff --git a/src/commands/settings/get.rs b/src/commands/settings/get.rs index 8ec708e..a037a56 100644 --- a/src/commands/settings/get.rs +++ b/src/commands/settings/get.rs @@ -1,6 +1,6 @@ use serenity::client::Context; -use serenity::framework::standard::{Args, CommandResult}; use serenity::framework::standard::macros::command; +use serenity::framework::standard::{Args, CommandResult}; use serenity::model::channel::Message; use crate::database::get_database_from_context; @@ -17,8 +17,10 @@ use crate::database::guild::GUILD_SETTINGS; async fn get(ctx: &Context, msg: &Message, mut args: Args) -> CommandResult { let database = get_database_from_context(ctx).await; let guild = msg.guild(&ctx.cache).await.unwrap(); + log::debug!("Displaying guild setting for guild {}", guild.id); if let Some(key) = args.single::().ok() { + log::debug!("Displaying guild setting of '{}'", key); let database_lock = database.lock().await; let setting = database_lock.get_guild_setting::(&guild.id, &key); @@ -36,6 +38,7 @@ async fn get(ctx: &Context, msg: &Message, mut args: Args) -> CommandResult { } } } else { + log::debug!("Displaying all guild settings"); for key in GUILD_SETTINGS { let mut kv_pairs = Vec::new(); { diff --git a/src/database/mod.rs b/src/database/mod.rs index 1e103bd..40872b2 100644 --- a/src/database/mod.rs +++ b/src/database/mod.rs @@ -1,7 +1,7 @@ use std::str::FromStr; use std::sync::Arc; -use rusqlite::{Connection, NO_PARAMS, params}; +use rusqlite::{params, Connection, NO_PARAMS}; use serenity::client::Context; use serenity::model::id::GuildId; use tokio::sync::Mutex; @@ -10,6 +10,7 @@ use crate::database::guild::GuildSettings; use crate::database::scripts::{CREATE_SCRIPT, UPDATE_SCRIPT}; use crate::utils::error::{BotError, BotResult}; use crate::utils::store::Store; +use std::fmt::Debug; pub mod guild; pub mod scripts; @@ -28,15 +29,21 @@ impl Database { pub fn init(&self) -> BotResult<()> { self.connection.execute(CREATE_SCRIPT, NO_PARAMS)?; self.connection.execute(UPDATE_SCRIPT, NO_PARAMS)?; + log::info!("Database initialized"); Ok(()) } /// Returns a guild setting pub fn get_guild_setting(&self, guild_id: &GuildId, key: &str) -> BotResult - where - T: Clone + FromStr, + where + T: Clone + FromStr + Debug, { + log::trace!( + "Fetching value of guild setting '{}' for guild {}", + key, + guild_id + ); self.connection .query_row( "SELECT guild_id, setting_key, setting_value FROM guild_settings WHERE guild_id = ?1 AND setting_key = ?2", @@ -53,10 +60,11 @@ impl Database { /// Sets a guild setting and overrides it if it already exists pub fn set_guild_setting(&self, guild_id: &GuildId, key: &str, value: T) -> BotResult<()> - where - T: ToString + FromStr + Clone, + where + T: ToString + FromStr + Clone + Debug, { if self.get_guild_setting::(guild_id, key).is_ok() { + log::trace!("Clearing previous guild setting"); self.connection.execute( "DELETE FROM guild_settings WHERE guild_id = ?1 AND setting_key = ?2", params![guild_id.to_string(), key], @@ -66,6 +74,12 @@ impl Database { "INSERT INTO guild_settings (guild_id, setting_key, setting_value) VALUES (?1, ?2, ?3)", params![guild_id.to_string(), key, value.to_string()], )?; + log::debug!( + "Setting '{}' set to '{:?}' for guild {}", + key, + value, + guild_id + ); Ok(()) } diff --git a/src/handler.rs b/src/handler.rs new file mode 100644 index 0000000..f3fad26 --- /dev/null +++ b/src/handler.rs @@ -0,0 +1,21 @@ +use serenity::async_trait; +use serenity::client::Context; +use serenity::model::event::ResumedEvent; +use serenity::model::gateway::{Activity, Ready}; +use serenity::prelude::*; + +pub(crate) struct Handler; + +#[async_trait] +impl EventHandler for Handler { + async fn ready(&self, ctx: Context, ready: Ready) { + log::info!("Connected as {}", ready.user.name); + let prefix = dotenv::var("BOT_PREFIX").unwrap_or("~!".to_string()); + ctx.set_activity(Activity::listening(format!("{}help", prefix).as_str())) + .await; + } + + async fn resume(&self, _: Context, _: ResumedEvent) { + log::info!("Reconnected to gateway") + } +} diff --git a/src/main.rs b/src/main.rs index 50f2eca..d33ee10 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,17 +1,20 @@ use crate::client::get_client; +use crate::utils::logging::init_logger; -pub(crate) mod client; +pub mod client; mod commands; -pub(crate) mod database; +pub mod database; +pub mod handler; mod providers; -pub(crate) mod utils; +pub mod utils; #[tokio::main] async fn main() { + init_logger(); let mut client = get_client().await.unwrap(); // start listening for events by starting a single shard if let Err(why) = client.start().await { - println!("An error occurred while running the client: {:?}", why); + log::error!("An error occurred while running the client: {:?}", why); } } diff --git a/src/providers/music/mod.rs b/src/providers/music/mod.rs index 97a3d87..dd604c4 100644 --- a/src/providers/music/mod.rs +++ b/src/providers/music/mod.rs @@ -18,6 +18,7 @@ static THREAD_LIMIT: u8 = 64; /// Returns a list of youtube videos for a given url pub(crate) async fn get_videos_for_playlist(url: &str) -> BotResult> { + log::debug!("Getting playlist information for {}", url); let output = youtube_dl(&["--no-warnings", "--flat-playlist", "--dump-json", "-i", url]).await?; @@ -31,6 +32,7 @@ pub(crate) async fn get_videos_for_playlist(url: &str) -> BotResult BotResult { + log::debug!("Fetching information for '{}'", url); let output = youtube_dl(&["--no-warnings", "--dump-json", "-i", url]).await?; let information = serde_json::from_str(&*output)?; @@ -40,6 +42,7 @@ pub(crate) async fn get_video_information(url: &str) -> BotResult BotResult> { + log::debug!("Searching for video '{}'", query); let output = youtube_dl(&[ "--no-warnings", "--dump-json", @@ -72,6 +75,7 @@ async fn parallel_search_youtube(song_names: Vec) -> Vec { /// to avoid using too much memory async fn youtube_dl(args: &[&str]) -> BotResult { lazy_static::lazy_static! { static ref THREAD_LOCK: Arc = Arc::new(AtomicU8::new(0)); } + log::trace!("Running youtube-dl with args {:?}", args); while THREAD_LOCK.load(Ordering::SeqCst) >= THREAD_LIMIT { tokio::time::sleep(Duration::from_millis(100)).await; @@ -95,6 +99,7 @@ async fn youtube_dl(args: &[&str]) -> BotResult { THREAD_LOCK.fetch_sub(1, Ordering::Relaxed); e })?; + log::trace!("youtube-dl response is {}", output); THREAD_LOCK.fetch_sub(1, Ordering::Relaxed); Ok(output) diff --git a/src/providers/music/queue.rs b/src/providers/music/queue.rs index 5044d02..b78021c 100644 --- a/src/providers/music/queue.rs +++ b/src/providers/music/queue.rs @@ -82,6 +82,7 @@ impl Song { if let Some(url) = self.url.clone() { Some(url) } else { + log::debug!("Lazy fetching video for title"); let information = search_video_information(format!("{} - {}", self.author, self.title)) .await .ok() diff --git a/src/providers/music/spotify.rs b/src/providers/music/spotify.rs index 46a83c4..4cbb16b 100644 --- a/src/providers/music/spotify.rs +++ b/src/providers/music/spotify.rs @@ -15,12 +15,14 @@ impl SpotifyApi { secret: dotenv::var("SPOTIFY_CLIENT_SECRET").expect("Missing Spotify Credentials"), }; let client = Client::new(credentials); + log::info!("Spotify API initialized."); Self { client } } - /// Returns the song names for a playlist + /// Returns the songs for a playlist pub async fn get_songs_in_playlist(&self, url: &str) -> BotResult> { + log::debug!("Fetching spotify songs from playlist '{}'", url); let id = self.get_id_for_url(url)?; let mut playlist_tracks = Vec::new(); let mut offset = 0; @@ -33,8 +35,13 @@ impl SpotifyApi { playlist_tracks.append(&mut tracks); offset += 100; } + log::debug!( + "{} Songs found in spotify playlist '{}'", + playlist_tracks.len(), + url + ); - let song_names = playlist_tracks + let songs = playlist_tracks .into_iter() .filter_map(|item| item.item) .filter_map(|t| match t { @@ -42,8 +49,9 @@ impl SpotifyApi { PlaylistItemType::Episode(_) => None, }) .collect(); + log::trace!("Songs are {:?}", songs); - Ok(song_names) + Ok(songs) } /// Returns the tracks of a playlist with pagination @@ -53,29 +61,40 @@ impl SpotifyApi { limit: usize, offset: usize, ) -> BotResult> { + log::trace!( + "Fetching songs from spotify playlist: limit {}, offset {}", + limit, + offset + ); let tracks = self .client .playlists() .get_playlists_items(id, limit, offset, None) .await? .data; + log::trace!("Tracks are {:?}", tracks); Ok(tracks.items) } - /// Returns all song names for a given album + /// Returns all songs for a given album pub async fn get_songs_in_album(&self, url: &str) -> BotResult> { + log::debug!("Fetching songs for spotify album '{}'", url); let id = self.get_id_for_url(url)?; let album = self.client.albums().get_album(&*id, None).await?.data; - let song_names = album.tracks.items.into_iter().map(Song::from).collect(); + log::trace!("Album is {:?}", album); + let song_names: Vec = album.tracks.items.into_iter().map(Song::from).collect(); + log::debug!("{} songs found in album '{}'", song_names.len(), url); Ok(song_names) } - /// Returns the name for a spotify song url + /// Returns song entity for a given spotify url pub async fn get_song_name(&self, url: &str) -> BotResult { + log::debug!("Getting song for {}", url); let id = self.get_id_for_url(url)?; let track = self.client.tracks().get_track(&*id, None).await?.data; + log::trace!("Track info is {:?}", track); Ok(track.into()) } diff --git a/src/utils/logging.rs b/src/utils/logging.rs new file mode 100644 index 0000000..4dda7cf --- /dev/null +++ b/src/utils/logging.rs @@ -0,0 +1,82 @@ +/* + * snekcloud node based network + * Copyright (C) 2020 trivernis + * See LICENSE for more information + */ + +use chrono::Local; +use colored::*; +use log::{Level, LevelFilter}; +use std::fs; +use std::path::PathBuf; +use std::str::FromStr; + +/// Initializes the env_logger with a custom format +/// that also logs the thread names +pub fn init_logger() { + let log_dir = PathBuf::from(dotenv::var("LOG_DIR").unwrap_or("logs".to_string())); + + if !log_dir.exists() { + fs::create_dir(&log_dir).expect("failed to create log dir"); + } + fern::Dispatch::new() + .format(|out, message, record| { + let color = get_level_style(record.level()); + let mut target = record.target().to_string(); + target.truncate(39); + + out.finish(format_args!( + "{:<40}| {} {}: {}", + target.dimmed().italic(), + Local::now().format("%Y-%m-%dT%H:%M:%S"), + record + .level() + .to_string() + .to_lowercase() + .as_str() + .color(color), + message + )) + }) + .level( + log::LevelFilter::from_str( + std::env::var("RUST_LOG") + .unwrap_or("info".to_string()) + .as_str(), + ) + .unwrap_or(LevelFilter::Info), + ) + .level_for("tokio", log::LevelFilter::Info) + .level_for("tracing", log::LevelFilter::Warn) + .level_for("serenity", log::LevelFilter::Warn) + .level_for("rustls", log::LevelFilter::Warn) + .level_for("h2", log::LevelFilter::Warn) + .level_for("reqwest", log::LevelFilter::Warn) + .level_for("tungstenite", log::LevelFilter::Warn) + .level_for("hyper", log::LevelFilter::Warn) + .level_for("async_tungstenite", log::LevelFilter::Warn) + .level_for("tokio_util", log::LevelFilter::Warn) + .level_for("want", log::LevelFilter::Warn) + .level_for("mio", log::LevelFilter::Warn) + .level_for("songbird", log::LevelFilter::Warn) + .chain(std::io::stdout()) + .chain( + fern::log_file(log_dir.join(PathBuf::from(format!( + "{}.log", + Local::now().format("%Y-%m-%d"), + )))) + .expect("failed to create log file"), + ) + .apply() + .expect("failed to init logger"); +} + +fn get_level_style(level: Level) -> colored::Color { + match level { + Level::Trace => colored::Color::Magenta, + Level::Debug => colored::Color::Blue, + Level::Info => colored::Color::Green, + Level::Warn => colored::Color::Yellow, + Level::Error => colored::Color::Red, + } +} diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 05274c6..9295b30 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -2,8 +2,9 @@ use std::collections::VecDeque; use rand::Rng; -pub mod error; -pub mod store; +pub(crate) mod error; +pub(crate) mod logging; +pub(crate) mod store; /// Fisher-Yates shuffle for VecDeque pub fn shuffle_vec_deque(deque: &mut VecDeque) {