diff --git a/Cargo.lock b/Cargo.lock --- a/Cargo.lock +++ b/Cargo.lock @@ -92,7 +92,7 @@ "regex", "serde", "serde_bytes", "serde_json", - "thiserror", + "thiserror 1.0.69", "tokio", "trait-variant", ] @@ -106,7 +106,7 @@ dependencies = [ "dashmap", "lru", "moka", - "thiserror", + "thiserror 1.0.69", "tokio", "trait-variant", "web-time", @@ -122,7 +122,7 @@ "http", "serde", "serde_html_form", "serde_json", - "thiserror", + "thiserror 1.0.69", "trait-variant", ] @@ -147,10 +147,16 @@ "futures", "glob", "grep", "kameo", + "opentelemetry", + "opentelemetry_sdk", "rand", "redis", "tokio", "tokio-cron-scheduler", + "tracing", + "tracing-log", + "tracing-opentelemetry", + "tracing-subscriber", ] [[package]] @@ -210,7 +216,7 @@ "psl", "regex", "serde", "serde_json", - "thiserror", + "thiserror 1.0.69", "trait-variant", "unicode-segmentation", ] @@ -1231,6 +1237,12 @@ "serde", ] [[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + +[[package]] name = "leb128fmt" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1386,6 +1398,15 @@ "tempfile", ] [[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + +[[package]] name = "num-bigint" version = "0.4.6" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1475,6 +1496,35 @@ "vcpkg", ] [[package]] +name = "opentelemetry" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b84bcd6ae87133e903af7ef497404dda70c60d0ea14895fc8a5e6722754fc2a0" +dependencies = [ + "futures-core", + "futures-sink", + "js-sys", + "pin-project-lite", + "thiserror 2.0.18", + "tracing", +] + +[[package]] +name = "opentelemetry_sdk" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e14ae4f5991976fd48df6d843de219ca6d31b01daaab2dad5af2badeded372bd" +dependencies = [ + "futures-channel", + "futures-executor", + "futures-util", + "opentelemetry", + "percent-encoding", + "rand", + "thiserror 2.0.18", +] + +[[package]] name = "parking" version = "2.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1934,6 +1984,15 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bbfa15b3dddfee50a0fff136974b3e1bde555604ba463834a7eb7deb6417705d" [[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + +[[package]] name = "shlex" version = "1.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -2091,7 +2150,16 @@ version = "1.0.69" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b6aaf5339b578ea85b50e080feb250a3e8ae8cfcdff9a461c9ec2904bc923f52" dependencies = [ - "thiserror-impl", + "thiserror-impl 1.0.69", +] + +[[package]] +name = "thiserror" +version = "2.0.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4288b5bcbc7920c07a1149a35cf9590a2aa808e0bc1eafaade0b80947865fbc4" +dependencies = [ + "thiserror-impl 2.0.18", ] [[package]] @@ -2103,6 +2171,26 @@ dependencies = [ "proc-macro2", "quote", "syn", +] + +[[package]] +name = "thiserror-impl" +version = "2.0.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ebc4ee7f67670e9b64d05fa4253e753e016c6c95ff35b89b7941d6b856dec1d5" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", ] [[package]] @@ -2262,6 +2350,48 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-opentelemetry" +version = "0.32.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ac28f2d093c6c477eaa76b23525478f38de514fa9aeb1285738d4b97a9552fc" +dependencies = [ + "js-sys", + "opentelemetry", + "smallvec", + "tracing", + "tracing-core", + "tracing-log", + "tracing-subscriber", + "web-time", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", ] [[package]] @@ -2333,6 +2463,12 @@ "getrandom 0.4.2", "js-sys", "wasm-bindgen", ] + +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" [[package]] name = "vcpkg" diff --git a/Cargo.toml b/Cargo.toml --- a/Cargo.toml +++ b/Cargo.toml @@ -12,7 +12,13 @@ futures = "0.3.31" glob = "0.3.2" grep = "0.3.2" kameo = "0.17.2" +opentelemetry = "0.31.0" +opentelemetry_sdk = "0.31.0" rand = "0.9.0" redis = { version = "0.29.1", features = ["aio", "connection-manager", "tokio-comp"] } tokio = { version = "1.44.0", features = ["full"] } tokio-cron-scheduler = "0.15.1" +tracing = { version = "0.1.44" } +tracing-log = "0.2.0" +tracing-opentelemetry = "0.32.1" +tracing-subscriber = "0.3.23" diff --git a/src/lib.rs b/src/lib.rs --- a/src/lib.rs +++ b/src/lib.rs @@ -98,9 +98,14 @@ ); continue; } + use tracing::Instrument; + let post_span = + tracing::debug_span!("post_cycle", time = chrono::Utc::now().to_string()); + // We store the code to perform the next posting iteration as one atomic future which we wrap with a timeout. // This means that, if we miss a posting window due to the timeout, we will not get multiple consecutive or late posts. let next_post_iteration = async || -> Result<(), Box> { + tracing::debug!("Fetching next quote"); let next_quote = cycle .ask(FetchQuote) .await @@ -109,16 +114,22 @@ // Note: By using `tell`, we don't know when each sink's code will have completed. // If any sink uses, say, a file or stdout, that resource may well be contested between // consecutive iterations of this loop. + tracing::debug!( + quote = next_quote.get().to_string(), + "Forwarding quote to sink" + ); sink.tell(PostQuote(next_quote)).await?; println!(); Ok(()) }; - if let Err(e) = timeout(POSTING_TIMEOUT, next_post_iteration()).await { - eprintln!( - "Could not submit post in time to all sinks. Timeout error: {}", - e + if let Err(e) = + timeout(POSTING_TIMEOUT, next_post_iteration().instrument(post_span)).await + { + tracing::error!( + error = e.to_string(), + "Could not submit post in time to all sinks.", ); } } diff --git a/src/main.rs b/src/main.rs --- a/src/main.rs +++ b/src/main.rs @@ -1,4 +1,23 @@ +use tracing::Level; + #[tokio::main] async fn main() -> Result<(), Box> { + // Start configuring a `fmt` subscriber + let subscriber = tracing_subscriber::fmt() + // Display source code file paths + .with_file(true) + // Display source code line numbers + .with_line_number(true) + // Display the thread ID an event was recorded on + .with_thread_ids(true) + // Don't display the event's target (module path) + .with_target(true) + .with_max_level(Level::DEBUG) + // Build the subscriber + .finish(); + + tracing::subscriber::set_global_default(subscriber)?; + tracing_log::LogTracer::init()?; + audquotes::run::entrypoint().await } diff --git a/src/sink.rs b/src/sink.rs --- a/src/sink.rs +++ b/src/sink.rs @@ -43,11 +43,13 @@ impl Message for StdoutSink { type Reply = PostResult; + #[tracing::instrument(name = "stdout::post", skip(self, _ctx))] async fn handle( &mut self, PostQuote(quote): PostQuote, _ctx: &mut Context, ) -> Self::Reply { + tracing::debug!(quote = quote.get()); println!("{}", quote.get()); Ok(()) } @@ -61,10 +63,17 @@ bsky_session: Object, } impl BskySink { + #[tracing::instrument(name = "bsky::new_session", skip(password))] pub async fn new_session(username: String, password: String) -> Result { + tracing::debug!("Logging in to Bluesky..."); + let agent = BskyAgent::builder().build().await.map_err(|_| ())?; - let session = agent.login(username, password).await.map_err(|_| ())?; + let session = agent.login(username, password).await.map_err(|e| { + tracing::error!(error = e.to_string(), "Could not log-in to Bluesky"); + () + })?; + tracing::debug!("Logged in to Bluesky successfully."); Ok(Self { bsky_agent: agent, bsky_session: session, @@ -81,7 +90,10 @@ ) .await } + #[tracing::instrument(name = "bsky::post", skip(self))] async fn submit_post(&mut self, quote: Quote) -> Result<(), ()> { + tracing::debug!("Submitting post to Bluesky..."); + let post = bsky_sdk::api::app::bsky::feed::post::RecordData { text: quote.into(), created_at: bsky_sdk::api::types::string::Datetime::now(), @@ -107,8 +119,11 @@ // If no error occurred, we simply proceed as normal. let Err(e) = resume_result else { break }; // Otherwise, we log the failed attempt... - eprintln!( - "[{idx}/{MAX_RETRIES}] Failed to resume sessions due to following error: {e}" + tracing::error!( + error = e.to_string(), + attempt = idx, + max_retries = MAX_RETRIES, + "Failed to resume session", ); // ...and then try to log in again. @@ -116,9 +131,15 @@ *self = Self::new_from_env().await? } match self.bsky_agent.create_record(post.clone()).await { - Ok(_) => Ok(()), + Ok(_) => { + tracing::debug!("Submitted post successfully."); + Ok(()) + } Err(e) => { - eprintln!("Could not submit post to Bluesky sink: {e:?}"); + tracing::error!( + error = e.to_string(), + "Could not submit post to Bluesky sink", + ); Err(()) } } @@ -172,6 +193,7 @@ impl Message for SinkManager { type Reply = SinkReplies; + #[tracing::instrument(name = "sink::post", skip(self, _ctx))] async fn handle( &mut self, msg: PostQuote, diff --git a/src/storage.rs b/src/storage.rs --- a/src/storage.rs +++ b/src/storage.rs @@ -195,9 +195,11 @@ use super::*; // Messages to interact with the quote queue + #[derive(Debug)] pub struct DequeueQuote; pub type DequeueReply = Result, ()>; + #[derive(Debug)] pub struct EnqueueQuotes(pub Vec); /// In case of a successful enqueue, no further data is required; @@ -301,11 +303,18 @@ R: redis::aio::ConnectionLike + redis::AsyncCommands + 'static, { type Reply = EnqueueReply; + #[tracing::instrument(name = "redis::enqueue_many", skip(self, _ctx, msg))] async fn handle( &mut self, msg: EnqueueQuotes, _ctx: &mut Context, ) -> Self::Reply { + tracing::debug!( + to_enqueue = msg.0.len(), + "Enqueuing {} quotes...", + msg.0.len() + ); + for (idx, q) in msg.0.iter().enumerate() { let _: () = self .con @@ -313,7 +322,15 @@ .rpush(&self.queue_key, q.get()) .await // If something goes wrong, we return the number of quotes // **already successfully queued** as part of our error message. - .map_err(|_| idx)?; + .map_err(|e| { + tracing::error!( + error = e.to_string(), + queued_so_far = idx, + total_to_queue = msg.0.len(), + "Could not enqueue all quotes to redis" + ); + idx + })?; } Ok(()) @@ -326,13 +343,18 @@ R: redis::aio::ConnectionLike + redis::AsyncCommands + 'static, { type Reply = DequeueReply; + #[tracing::instrument(name = "redis::dequeue_one", skip(self, _ctx, _msg))] async fn handle( &mut self, _msg: DequeueQuote, _ctx: &mut Context, ) -> Self::Reply { + tracing::debug!("Dequeuing quote..."); let quote: Result, ()> = - self.con.lpop(&self.queue_key, None).await.map_err(|_| ()); + self.con.lpop(&self.queue_key, None).await.map_err(|e| { + tracing::error!(error = e.to_string(), "Could not dequeue quote from Redis"); + () + }); match quote { Ok(Some(quote)) => Ok(Some(Quote::from(quote))), @@ -377,6 +399,7 @@ } } /// A message to [QuoteCycle] to fetch one more quote from its storage. +#[derive(Debug)] pub struct FetchQuote; impl Message for QuoteCycle @@ -386,34 +409,45 @@ Q: queue::QueueManager, { type Reply = Result; + #[tracing::instrument(name = "quote_cycle::fetch", skip(self, _ctx))] async fn handle( &mut self, _msg: FetchQuote, _ctx: &mut Context, ) -> Self::Reply { // 1. We query our queue storage for the next quote + tracing::debug!("Fetching new quotes..."); if let Some(next_quote) = self.queue_manager.ask(DequeueQuote).await.map_err(|_| ())? { // if there is a quote, we simply return it and move on + tracing::debug!( + quote = next_quote.get().to_string(), + "Quote dequeued immediately." + ); return Ok(next_quote); } // 2. Otherwise, we must repopulate the queue through our source - let mut refreshed_quotes = self - .source_manager - .ask(SourceQuotes) - .await - .map_err(|_| ())?; + let mut refreshed_quotes = self.source_manager.ask(SourceQuotes).await.map_err(|_| { + tracing::error!("Could not retrieve new quotes from source"); + () + })?; + tracing::debug!("Retrieved {} quotes.", refreshed_quotes.len()); // 3. We shuffle the newly-sourced quotes + tracing::debug!("Shuffling quotes..."); self.rng.shuffle_slice(&mut refreshed_quotes); let refreshed_quotes = refreshed_quotes; // No longer mutable // TODO: Perhaps we should assert that the new quotes are non-empty? // 4. We enqueue the newly-sourced quotes... + tracing::debug!("Enqueuing quotes..."); self.queue_manager .ask(EnqueueQuotes(refreshed_quotes)) .await - .map_err(|_| ())?; + .map_err(|_| { + tracing::error!("Could not enqueue quotes to storage"); + () + })?; // 5. and, finally, we return the first among them. match self.queue_manager.ask(DequeueQuote).await {