From b91d0be8e56969643d66b40f34ffbd0d9ec9302d Mon Sep 17 00:00:00 2001 From: Markus Wiegand Date: Mon, 19 Jun 2023 19:44:37 +0200 Subject: [PATCH] Improve logging (#117) * add log formats and ansi handling * update readme * fix help indentation * add `no-color` option * rename default formatter * add verbose option * make fields depend on debug mode * update help message * improve control of color output * improve log messages --- Cargo.lock | 74 +++++++++++++++++--- Cargo.toml | 11 ++- README.md | 9 ++- src/feed/mod.rs | 26 ++++++- src/main.rs | 163 ++++++++++++++++++++++++++++++++++++++------ src/sink/custom.rs | 43 +++++++++--- src/sink/discord.rs | 20 ++++++ src/sink/slack.rs | 20 ++++++ src/watcher.rs | 74 ++++++++++++++------ 9 files changed, 378 insertions(+), 62 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 87d3a4b..f25b1a7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -696,6 +696,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.10" @@ -1028,6 +1037,36 @@ dependencies = [ "bitflags", ] +[[package]] +name = "regex" +version = "1.8.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d0ab3ca65655bb1e41f2a8c8cd662eb4fb035e67c3f78da1d61dffe89d07300f" +dependencies = [ + "regex-syntax 0.7.2", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", +] + +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + +[[package]] +name = "regex-syntax" +version = "0.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "436b050e76ed2903236f032a59761c1eb99e1b0aead2c257922771dab1fc8c78" + [[package]] name = "reqwest" version = "0.11.18" @@ -1147,9 +1186,9 @@ dependencies = [ [[package]] name = "rustls" -version = "0.21.1" +version = "0.21.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c911ba11bc8433e811ce56fde130ccf32f5127cab0e0194e9c68c5a5b671791e" +checksum = "e32ca28af694bc1bbf399c33a516dbdf1c90090b8ab23c2bc24f834aa2247f5f" dependencies = [ "log", "ring", @@ -1252,9 +1291,9 @@ dependencies = [ [[package]] name = "serde_json" -version = "1.0.96" +version = "1.0.97" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "057d394a50403bcac12672b2b18fb387ab6d289d957dab67dd201875391e52f1" +checksum = "bdf3bf93142acad5821c99197022e170842cdbc1c30482b98750c688c640842a" dependencies = [ "itoa", "ryu", @@ -1634,18 +1673,36 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "parking_lot", + "regex", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", + "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] @@ -1763,11 +1820,10 @@ checksum = "accd4ea62f7bb7a82fe23066fb0957d48ef677f6eeb8215f372f52e48bb32426" [[package]] name = "want" -version = "0.3.0" +version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1ce8a968cb1cd110d136ff8b819a556d6fb6d919363c61534f6860c7eb172ba0" +checksum = "bfa7760aed19e106de2c7c0b581b509f2f25d3dacaf737cb82ac61bc6d760b0e" dependencies = [ - "log", "try-lock", ] @@ -2025,9 +2081,9 @@ checksum = "1a515f5799fe4961cb532f983ce2b23082366b898e52ffbce459c86f67c8378a" [[package]] name = "winnow" -version = "0.4.6" +version = "0.4.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "61de7bac303dc551fe038e2b3cef0f571087a47571ea6e79a87692ac99b99699" +checksum = "ca0ace3845f0d96209f0375e6d367e3eb87eb65d27d445bdc9f1843a26f39448" dependencies = [ "memchr", ] diff --git a/Cargo.toml b/Cargo.toml index 5d93f0d..55929ac 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -43,7 +43,16 @@ rss = { version = "2", default-features = false } atom_syndication = { version = "0.12", default-features = false } chrono = { version = "0.4", features = ["serde"], default-features = false } tracing = "0.1" -tracing-subscriber = "0.3" +tracing-subscriber = { version = "0.3", features = [ + "std", + "fmt", + "tracing-log", + "smallvec", + "parking_lot", + "env-filter", + "ansi", + "json", +], default-features = false } thiserror = "1" humantime-serde = "1" toml = "0.7" diff --git a/README.md b/README.md index 507b637..966115b 100644 --- a/README.md +++ b/README.md @@ -46,9 +46,12 @@ See [GitHub container package](https://github.com/morphy2k/rss-forwarder/pkgs/co USAGE: rss-forwarder [OPTIONS] OPTIONS: ---debug Enables debug mode --h, --help Show help information --v, --version Show version info + -f, --format Log format: full, pretty, compact, json (default: full) + --color Colorize output: auto, always, never (default: auto) + --debug Enables debug mode + --verbose Enables verbose mode + -h, --help Show this help message + -v, --version Show version information ``` [Examples](example) diff --git a/src/feed/mod.rs b/src/feed/mod.rs index e0e5437..622e50c 100644 --- a/src/feed/mod.rs +++ b/src/feed/mod.rs @@ -6,6 +6,8 @@ use self::item::{FeedItem, Item, Source}; use std::{cmp::Reverse, io::BufRead}; +use tracing::debug; + #[derive(Debug)] pub enum Feed { Rss(rss::Channel), @@ -24,10 +26,16 @@ impl<'a> Feed { let feed = atom_syndication::Feed::read_from(reader)?; Self::Atom(feed) } - _ => return Err(e.into()), + _ => return Err(e)?, }, }; + debug!( + format = %if feed.is_rss() { "RSS" } else { "Atom" }, + items = feed.items().len(), + "parsed feed" + ); + Ok(feed) } @@ -72,4 +80,20 @@ impl<'a> Feed { items } + + /// Returns `true` if the feed is [`Rss`]. + /// + /// [`Rss`]: Feed::Rss + #[must_use] + pub fn is_rss(&self) -> bool { + matches!(self, Self::Rss(..)) + } + + /// Returns `true` if the feed is [`Atom`]. + /// + /// [`Atom`]: Feed::Atom + #[must_use] + pub fn is_atom(&self) -> bool { + matches!(self, Self::Atom(..)) + } } diff --git a/src/main.rs b/src/main.rs index 13d4953..4342028 100644 --- a/src/main.rs +++ b/src/main.rs @@ -9,7 +9,15 @@ use crate::{ watcher::Watcher, }; -use std::{collections::HashMap, env, path::PathBuf, process, time::Duration}; +use std::{ + collections::HashMap, + env, + io::{stdout, IsTerminal}, + path::PathBuf, + process, + str::FromStr, + time::Duration, +}; use error::Error; use pico_args::Arguments; @@ -19,7 +27,8 @@ use tokio::{ sync::broadcast, task::JoinSet, }; -use tracing::{error, info}; +use tracing::{debug, error, info}; +use tracing_subscriber::EnvFilter; #[cfg(feature = "mimalloc")] #[global_allocator] @@ -30,7 +39,84 @@ pub type Result = std::result::Result; #[derive(Debug)] struct Args { config: PathBuf, + format: LogFormat, + color: AnsiOutput, debug: bool, + verbose: bool, +} + +#[derive(Debug, Default)] +enum LogFormat { + #[default] + Full, + Pretty, + Compact, + Json, +} + +struct InvalidLogFormat; + +impl std::fmt::Display for InvalidLogFormat { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "invalid log format") + } +} + +impl FromStr for LogFormat { + type Err = InvalidLogFormat; + + fn from_str(s: &str) -> std::result::Result { + let value = match s { + "full" => LogFormat::Full, + "pretty" => LogFormat::Pretty, + "compact" => LogFormat::Compact, + "json" => LogFormat::Json, + _ => return Err(InvalidLogFormat), + }; + + Ok(value) + } +} + +#[derive(Debug, Default)] +enum AnsiOutput { + #[default] + Auto, + Always, + Never, +} + +impl AnsiOutput { + fn is_enabled(&self) -> bool { + match self { + AnsiOutput::Auto => stdout().is_terminal(), + AnsiOutput::Always => true, + AnsiOutput::Never => false, + } + } +} + +struct InvalidAnsiOutput; + +impl std::fmt::Display for InvalidAnsiOutput { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "invalid ansi output") + } +} + +impl FromStr for AnsiOutput { + type Err = InvalidAnsiOutput; + + fn from_str(s: &str) -> std::result::Result { + let value = match s { + "auto" => AnsiOutput::Auto, + "always" => AnsiOutput::Always, + "never" => AnsiOutput::Never, + _ => return Err(InvalidAnsiOutput), + }; + + Ok(value) + } } #[tokio::main] @@ -38,19 +124,24 @@ async fn main() -> Result<()> { let args = match parse_args() { Ok(v) => v, Err(e) => { - eprintln!("Argument error: {e}"); + eprintln!("Error while parsing arguments: {e}\nUse --help for more information"); process::exit(1); } }; - if env::var("RUST_LOG").is_err() { - if args.debug { - env::set_var("RUST_LOG", "rss_forwarder=debug,reqwest=debug"); - } else { - env::set_var("RUST_LOG", "rss_forwarder=info"); - } - } - tracing_subscriber::fmt::init(); + let subscriber = tracing_subscriber::fmt() + .with_line_number(args.debug) + .with_thread_ids(args.debug) + .with_target(args.debug) + .with_env_filter(parse_env_filter(args.debug, args.verbose)) + .with_ansi(args.color.is_enabled()); + + match args.format { + LogFormat::Full => subscriber.init(), + LogFormat::Pretty => subscriber.pretty().init(), + LogFormat::Compact => subscriber.compact().init(), + LogFormat::Json => subscriber.json().init(), + }; let config = match Config::from_file(args.config).await { Ok(c) => c, @@ -73,7 +164,7 @@ async fn main() -> Result<()> { } if task_failed { - error!("Terminate due to a faulty watcher"); + eprintln!("Terminate due to a faulty watcher"); process::exit(1); } @@ -100,9 +191,12 @@ const DESCRIPTION: &str = env!("CARGO_PKG_DESCRIPTION"); const OPTIONS: &str = "\ OPTIONS: - --debug Enables debug mode - -h, --help Show help information - -v, --version Show version info + -f, --format Log format: full, pretty, compact, json (default: full) + --color Colorize output: auto, always, never (default: auto) + --debug Enables debug mode + --verbose Enables verbose mode + -h, --help Show this help message + -v, --version Show version information "; fn print_help() { @@ -133,6 +227,11 @@ fn parse_args() -> Result { let args = Args { debug: pargs.contains("--debug"), + verbose: pargs.contains("--verbose"), + format: pargs + .opt_value_from_str(["-f", "--format"])? + .unwrap_or_default(), + color: pargs.opt_value_from_str("--color")?.unwrap_or_default(), config: pargs.free_from_str()?, }; @@ -141,6 +240,24 @@ fn parse_args() -> Result { Ok(args) } +fn parse_env_filter(debug: bool, verbose: bool) -> EnvFilter { + match (env::var("RUST_LOG").is_err(), debug, verbose) { + (true, true, true) => EnvFilter::builder() + .parse("debug") + .expect("should be a valid directive"), + (true, false, true) => EnvFilter::builder() + .parse("info") + .expect("should be a valid directive"), + (true, true, false) => EnvFilter::builder() + .parse("rss_forwarder=debug") + .expect("should be a valid directive"), + (true, false, false) => EnvFilter::builder() + .parse("rss_forwarder=info") + .expect("should be a valid directive"), + (false, _, _) => EnvFilter::from_default_env(), + } +} + fn watch_feeds(feeds: HashMap, client: Client) -> Result>> { let mut tasks = JoinSet::new(); @@ -159,11 +276,15 @@ fn watch_feeds(feeds: HashMap, client: Client) -> Result, client: Client) -> Result {}, }; + debug!("received termination signal"); + tx.send(()).unwrap(); }); diff --git a/src/sink/custom.rs b/src/sink/custom.rs index 14c1cd5..0a144a6 100644 --- a/src/sink/custom.rs +++ b/src/sink/custom.rs @@ -17,9 +17,12 @@ use tokio::{ sync::mpsc::{self, Sender}, task::JoinHandle, }; +use tracing::debug; #[derive(Debug)] pub struct Custom { + command: String, + arguments: Vec, process: Child, stdin_task: JoinHandle>, kill_tx: Sender<()>, @@ -27,18 +30,14 @@ pub struct Custom { } impl Custom { - pub fn new(cmd: C, args: A) -> Result - where - C: AsRef, - A: IntoIterator, - { - let mut cmd = Command::new(cmd.as_ref()) - .args(args) + pub fn new(cmd: String, args: Vec) -> Result { + let mut process = Command::new(&cmd) + .args(&args) .stdin(Stdio::piped()) .kill_on_drop(true) .spawn()?; - let mut stdin = cmd + let mut stdin = process .stdin .take() .ok_or_else(|| Error::Sink("stdin not captured".to_string()))?; @@ -64,7 +63,9 @@ impl Custom { }); Ok(Self { - process: cmd, + command: cmd, + arguments: args, + process, stdin_task: task, kill_tx, data_tx, @@ -74,10 +75,22 @@ impl Custom { #[async_trait] impl Sink for Custom { + #[tracing::instrument( + name = "push", + skip(self, items), + fields( + pid = self.process.id(), + command = %self.command, + arguments = %self.arguments.join(" "), + ), + level = "debug" + )] async fn push<'a, T>(&self, items: &'a [T]) -> Result<()> where T: FeedItem<'a>, { + debug!(count = items.len(), "pushing items"); + for item in items { let obj = Object::try_from_item(item)?; let mut json = serde_json::to_vec(&obj)?; @@ -91,7 +104,19 @@ impl Sink for Custom { Ok(()) } + #[tracing::instrument( + name = "shutdown", + skip(self), + fields( + pid = self.process.id(), + commad = %self.command, + arguments = %self.arguments.join(" "), + ), + level = "debug" + )] async fn shutdown(mut self) -> Result<()> { + debug!("shutting down"); + if !self.kill_tx.is_closed() { self.kill_tx.send(()).await.unwrap(); } diff --git a/src/sink/discord.rs b/src/sink/discord.rs index 7d26529..93d4ed1 100644 --- a/src/sink/discord.rs +++ b/src/sink/discord.rs @@ -10,6 +10,7 @@ use async_trait::async_trait; use chrono::{DateTime, FixedOffset}; use reqwest::{Client, IntoUrl, Url}; use serde::Serialize; +use tracing::debug; const PROVIDER: EmbedProvider<'static> = EmbedProvider { name: env!("CARGO_PKG_NAME"), @@ -33,6 +34,14 @@ impl Discord { #[async_trait] impl Sink for Discord { + #[tracing::instrument( + name = "push", + skip(self, items), + fields( + url = %self.url, + ) + level = "debug" + )] async fn push<'a, T>(&self, items: &'a [T]) -> Result<()> where T: FeedItem<'a>, @@ -41,6 +50,8 @@ impl Sink for Discord { let limit = 10_usize; let chunk_count = (length as f64 / limit as f64).ceil() as usize; + debug!(count = length, chunks = chunk_count, "pushing items"); + let mut chunks: Vec = Vec::with_capacity(chunk_count); for i in 0..chunk_count { let pos = i * limit; @@ -64,7 +75,16 @@ impl Sink for Discord { Ok(()) } + #[tracing::instrument( + name = "shutdown", + skip(self), + fields( + url = %self.url, + ) + level = "debug" + )] async fn shutdown(self) -> Result<()> { + debug!("shutting down"); Ok(()) } } diff --git a/src/sink/slack.rs b/src/sink/slack.rs index 7405019..9593e8e 100644 --- a/src/sink/slack.rs +++ b/src/sink/slack.rs @@ -15,6 +15,7 @@ use slack_bk::{ elements::{Button, Element}, }; use tokio::time::{self, Duration}; +use tracing::debug; #[derive(Debug)] pub struct Slack { @@ -33,6 +34,14 @@ impl Slack { #[async_trait] impl Sink for Slack { + #[tracing::instrument( + name = "push", + skip(self, items), + fields( + url = %self.url, + ) + level = "debug" + )] async fn push<'a, T>(&self, items: &'a [T]) -> Result<()> where T: FeedItem<'a>, @@ -41,6 +50,8 @@ impl Sink for Slack { let limit = 10_usize; let chunk_count = (length as f64 / limit as f64).ceil() as usize; + debug!(count = length, chunks = chunk_count, "pushing items"); + let mut chunks: Vec = Vec::with_capacity(chunk_count); for i in 0..chunk_count { let pos = i * limit; @@ -71,7 +82,16 @@ impl Sink for Slack { Ok(()) } + #[tracing::instrument( + name = "shutdown", + skip(self), + fields( + url = %self.url, + ) + level = "debug" + )] async fn shutdown(self) -> Result<()> { + debug!("shutting down"); Ok(()) } } diff --git a/src/watcher.rs b/src/watcher.rs index 6991b04..5103e1c 100644 --- a/src/watcher.rs +++ b/src/watcher.rs @@ -22,7 +22,7 @@ pub struct Watcher { client: Client, retry_limit: usize, retries_left: usize, - last_date: Option>, + last_date: DateTime, } impl Watcher { @@ -40,10 +40,20 @@ impl Watcher { client, retry_limit, retries_left: retry_limit, - last_date: None, + last_date: DateTime::default(), }) } + #[tracing::instrument( + name = "watch", + skip(self, kill), + fields( + url = %self.url, + interval = ?self.interval, + retry_limit = self.retry_limit, + ) + level = "debug" + )] pub async fn watch(mut self, mut kill: Receiver<()>) -> Result<()> { let mut interval = tokio::time::interval(self.interval); @@ -56,54 +66,79 @@ impl Watcher { let feed = match self.fetch().await { Ok(c) => c, - Err(e) => { - if is_retriable(&e) && self.retries_left > 0 { - error!(error =? e, "error while getting items"); + Err(err) => { + if is_retriable(&err) && self.retries_left > 0 { self.retries_left -= 1; + error!( + error = %err, + retries_left = self.retries_left, + "error while fetching feed", + ); continue; } else { - return Err(e); + return Err(err); } } }; let items = feed.items(); - if items.is_empty() { + let Some(last) = items.first() else { + debug!("no items in feed"); continue; - } - - let last = items.first().unwrap(); + }; - if self.last_date.is_none() { - self.last_date = last.date().into(); + if self.last_date.timestamp() == 0 { + debug!( + date = %last.date(), + "no date set, setting to last item date", + ); + self.last_date = last.date(); + continue; } - let Some(news) = self.get_new_items(&items) else { continue }; + let Some(news) = self.get_new_items(&items) else { + debug!( + since = %self.last_date, + "found no new items", + ); + continue; + }; debug!( - feed = feed.title(), count = news.len(), - "pushing items from feed" + since = %self.last_date, + "found new items", ); if let Err(err) = self.sink.push(news).await { if is_retriable(&err) && self.retries_left > 0 { - error!(error =? err, "error while pushing items"); self.retries_left -= 1; + error!( + error = %err, + retries_left = self.retries_left, + "error while pushing items to sink", + ); continue; } else { return Err(err); } } - self.last_date = last.date().into(); + debug!( + date = %last.date(), + "updating last date", + ); + self.last_date = last.date(); if self.retries_left != self.retry_limit { + debug!("resetting retries"); self.retries_left = self.retry_limit; } } + debug!("shutting down"); + self.sink.shutdown().await?; Ok(()) @@ -114,9 +149,8 @@ impl Watcher { I: FeedItem<'a>, { let mut idx = 0; - for (i, item) in items.iter().enumerate() { - if item.date().gt(&self.last_date.unwrap()) { + if item.date().gt(&self.last_date) { idx = i; } else { if i == 0 { @@ -130,6 +164,8 @@ impl Watcher { } async fn fetch(&self) -> Result { + debug!("fetching feed"); + let res = self.client.get(self.url.as_ref()).send().await?; let body = res.error_for_status()?.bytes().await?;