diff --git a/AGENTS.md b/AGENTS.md index 2ea52ff..b3830b4 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -60,7 +60,7 @@ Docker: `docker build -t tgxmb .` then `docker run --rm -d --name tgxmb --env-fi - **Serde**: per-site `model.rs` are pure `Deserialize` DTOs mirroring API JSON; site structs in `interface.rs` have private fields, a `caption()` builder, and `impl From for Fetched`. Persisted payloads use internally-tagged enums (`#[serde(tag = "kind")]` / `type`). - **Naming**: module-per-concern, snake_case files, `CamelCase` types, `snake_case` fns. `//!` module docs and `///` docs on non-obvious logic (syndication token, ugoira encoding, `display_text_range`). - **Retries**: only `x-media::site::fetch` retries (3 attempts, `1 << attempt` backoff, HTTP errors only). Queue retries are explicit `QueueError::Retryable` with computed delay (`retry_delay_seconds`). -- Logging via `log` macros (`pretty_env_logger`, level from `RUST_LOG`). +- Logging via `log` macros (`pretty_env_logger`, level from `RUST_LOG`). Level convention: `info` = lifecycle + per-post business results (`sent`/`forwarded`/`copied`), admin/operator actions and anomalies (fallback, retry enqueue, dead-letter is `error`); `debug` = per-request detail (message/command/URL extraction, `fetching`/`fetched`, batch sends, queue processing, photo processing, inline queries). Full user-submitted URLs and message text only appear at `debug`; at `info` and above links are printed via the normalized cache key (`handlers::log_key`, e.g. `[key=twitter:123...]`) so logs stay short and do not echo user data. ## Important Files diff --git a/crates/x-media/src/site/mod.rs b/crates/x-media/src/site/mod.rs index d2bd96d..cf67d8d 100644 --- a/crates/x-media/src/site/mod.rs +++ b/crates/x-media/src/site/mod.rs @@ -329,8 +329,10 @@ pub async fn fetch(url: &str) -> Result, FetchError> { for attempt in 0..3u32 { match fetch_once(url).await { Ok(Some(fetched)) => { - log::info!( - "fetched {url}: site {} returned {} media", + // Per-request detail: debug only, keyed by the post id. + log::debug!( + "fetched [key={}]: site {} returned {} media", + cache_key(url).unwrap_or_else(|| "?".into()), fetched.site_name(), fetched.media.len() ); diff --git a/crates/x-media/src/site/twitter/interface.rs b/crates/x-media/src/site/twitter/interface.rs index f4bccf8..60becfc 100644 --- a/crates/x-media/src/site/twitter/interface.rs +++ b/crates/x-media/src/site/twitter/interface.rs @@ -35,7 +35,7 @@ pub async fn fetch_from_url(url: &str) -> Result { } } } else { - log::info!("tweet {id} is sensitive; set TWITTER_AUTH_TOKEN to fetch NSFW media"); + log::debug!("tweet {id} is sensitive; set TWITTER_AUTH_TOKEN to fetch NSFW media"); Ok(empty_fetched(url)) } } diff --git a/crates/xmedia-bot/src/handlers.rs b/crates/xmedia-bot/src/handlers.rs index 071b82b..a0431b1 100644 --- a/crates/xmedia-bot/src/handlers.rs +++ b/crates/xmedia-bot/src/handlers.rs @@ -131,6 +131,14 @@ where .await } +/// Log prefix tying the whole lifecycle of one link (fetch → send → cache → +/// forward) together: the normalized cache key (`twitter:123…`, `pixiv:123`, +/// `bsky:handle/rkey`) instead of the raw URL, so logs stay short and do not +/// echo full user-submitted URLs at info level. +pub fn log_key(url: &str) -> String { + x_media::site::cache_key(url).unwrap_or_else(|| "".to_string()) +} + /// Extracts URL and text-link entities (text + caption), deduped in order. pub fn extract_urls(message: &Message) -> Vec { let mut urls = Vec::new(); @@ -534,7 +542,11 @@ async fn dispatch_send(bot: Bot, message: &Message, task: &Task, url: &str) { }; match result { Ok(message_ids) => { - log::info!("sent {} message(s) for {url}", message_ids.len()); + log::info!( + "sent {} message(s) for [key={}]", + message_ids.len(), + log_key(url) + ); send::post_send_actions(&bot, task, message_ids).await; // The task settled: drop any keep-alive temp media. send::release_keep_alive(task); @@ -543,7 +555,10 @@ async fn dispatch_send(bot: Bot, message: &Message, task: &Task, url: &str) { delay_seconds, task, }) => { - log::info!("send for {url} failed, queued for retry in {delay_seconds:.1}s"); + log::info!( + "send for [key={}] failed, queued for retry in {delay_seconds:.1}s", + log_key(url) + ); enqueue_retry(task, delay_seconds).await; let _ = reply(bot, message.clone(), "Send failed. Task queued for retry.").await; } @@ -619,7 +634,7 @@ async fn url_media(bot: Bot, message: &Message, url: &str) { if let Some(key) = x_media::site::cache_key(url) && let Some(cached) = LINK_CACHE.get(&key, CONFIG.link_cache_ttl).await { - log::info!("link cache hit for {url}"); + log::debug!("link cache hit for {key}"); let chat_data = CHAT_STORE.get(chat_id).await; let site = key.split(':').next().unwrap_or("unknown"); let format = chat_data @@ -676,11 +691,11 @@ async fn url_media(bot: Bot, message: &Message, url: &str) { return; } - log::info!("fetching {url}"); + log::debug!("fetching {url} [key={}]", log_key(url)); match x_media::site::fetch(url).await { // Unsupported links are ignored silently (Python parity). Ok(None) => { - log::info!("no site pattern matches {url}; ignoring"); + log::debug!("no site pattern matches {url}; ignoring"); } // Retries exhausted: notify the user (Rust-only requirement 3). Err(e) => { @@ -763,7 +778,8 @@ pub async fn message_handler(bot: Bot, message: Message) -> Result<(), RequestEr &t[..end] }) .unwrap_or(""); - log::info!( + // Per-request detail: debug only (message text is user data). + log::debug!( "message from {sender} in {} (private={is_private}): {text_preview}", message.chat.id ); @@ -774,14 +790,16 @@ pub async fn message_handler(bot: Bot, message: Message) -> Result<(), RequestEr if let Some(text) = message.text() && let Ok(command) = Command::parse(text, "") { - log::info!("command from {}: {text_preview}", message.chat.id); + log::debug!("command from {}: {text_preview}", message.chat.id); execute_command(&bot, &message, command).await?; return respond(()); } if is_private { let urls = extract_urls(&message); if !urls.is_empty() { - log::info!("extracted {} URL(s): {urls:?}", urls.len()); + // Debug only, and echo the normalized keys instead of the raw URLs. + let keys: Vec = urls.iter().map(|u| log_key(u)).collect(); + log::debug!("extracted {} URL(s): {keys:?}", urls.len()); } for url in urls { // Clone out of the lock: the parking_lot guard is !Send and must @@ -875,7 +893,11 @@ pub async fn inline_query_handler(bot: Bot, query: InlineQuery) -> Result<(), Re /// Fetches the post behind an inline query and answers it. The caller has /// already applied the debounce. Returns `true` when an answer was sent. async fn answer_inline_query(bot: Bot, query: InlineQuery) -> Result { - log::info!("inline query: {}", query.query); + log::debug!( + "inline query: {} [key={}]", + query.query, + log_key(&query.query) + ); match x_media::site::fetch(&query.query).await { Ok(Some(fetched)) => { let mut results: Vec = Vec::new(); @@ -952,7 +974,7 @@ pub async fn callback_query_handler(bot: Bot, query: CallbackQuery) -> Result<() let chat_data = CHAT_STORE.get(chat_id).await; let edit = chat_data.edit_message.get(&prompt_message_id).cloned(); let Some(edit) = edit else { - log::info!( + log::debug!( "callback from {}: no edit record for prompt {prompt_message_id}", chat_id ); @@ -1028,7 +1050,7 @@ pub async fn callback_query_handler(bot: Bot, query: CallbackQuery) -> Result<() } } None => { - log::info!("forward callback without a forward channel set"); + log::debug!("forward callback without a forward channel set"); bot.answer_callback_query(callback_query_id) .text("No forward channel set.") .await?; diff --git a/crates/xmedia-bot/src/photo.rs b/crates/xmedia-bot/src/photo.rs index bdc35bf..e9844c8 100644 --- a/crates/xmedia-bot/src/photo.rs +++ b/crates/xmedia-bot/src/photo.rs @@ -223,7 +223,7 @@ fn prepare_png(file: NamedTempFile, bytes: &[u8]) -> Result { if w + h <= PHOTO_MAX_DIMENSION_SUM && !size_over { return Ok(PhotoPrep::Upload(file)); } - log::info!( + log::debug!( "photo {w}x{h} ({_bit_depth:?} {color_type:?}, {} bytes) needs processing", bytes.len() ); @@ -269,7 +269,7 @@ fn prepare_png(file: NamedTempFile, bytes: &[u8]) -> Result { let (nw, nh) = target_dims(w, h); pix = resize_pix(pix, w, h, nw, nh)?; (w, h) = (nw, nh); - log::info!("downscaled photo to {w}x{h} (Lanczos3)"); + log::debug!("downscaled photo to {w}x{h} (Lanczos3)"); } let mut png_bytes = Vec::new(); @@ -277,7 +277,7 @@ fn prepare_png(file: NamedTempFile, bytes: &[u8]) -> Result { if png_bytes.len() as u64 <= MAX_UPLOAD_BYTES { return Ok(PhotoPrep::Upload(write_temp(&png_bytes, "png")?)); } - log::info!("PNG still over the upload cap after processing; transcoding to JPEG"); + log::debug!("PNG still over the upload cap after processing; transcoding to JPEG"); let jpeg_bytes = encode_jpeg(&pix, w, h)?; if jpeg_bytes.len() as u64 <= MAX_UPLOAD_BYTES { return Ok(PhotoPrep::Upload(write_temp(&jpeg_bytes, "jpg")?)); @@ -311,7 +311,7 @@ fn prepare_jpeg(file: NamedTempFile, bytes: &[u8]) -> Result let (nw, nh) = target_dims(w, h); pix = resize_pix(pix, w, h, nw, nh)?; (w, h) = (nw, nh); - log::info!("downscaled jpeg to {w}x{h} (Lanczos3)"); + log::debug!("downscaled jpeg to {w}x{h} (Lanczos3)"); } let jpeg_bytes = encode_jpeg(&pix, w, h)?; if jpeg_bytes.len() as u64 <= MAX_UPLOAD_BYTES { diff --git a/crates/xmedia-bot/src/queue.rs b/crates/xmedia-bot/src/queue.rs index c9e7591..b1b925e 100644 --- a/crates/xmedia-bot/src/queue.rs +++ b/crates/xmedia-bot/src/queue.rs @@ -188,7 +188,7 @@ impl PersistentTaskQueue { self.counter.fetch_add(1, Ordering::Relaxed) ); let payload = payload.to_string(); - log::info!("enqueued {id} (run_after {run_after:.1})"); + log::debug!("enqueued {id} (run_after {run_after:.1})"); self.pool.with_conn(move |conn| { conn.execute( "INSERT OR REPLACE INTO tasks (id, payload, run_after, attempts, status, locked_until, created_at) \ @@ -339,10 +339,10 @@ impl QueueWorker { return; } }; - log::info!("processing {} (attempt {})", row.id, row.attempts + 1); + log::debug!("processing {} (attempt {})", row.id, row.attempts + 1); match (self.handler)(payload).await { Ok(()) => { - log::info!("task {} completed", row.id); + log::debug!("task {} completed", row.id); self.delete_row(&row.id).await; } Err(QueueError::Retryable { @@ -356,7 +356,7 @@ impl QueueWorker { (self.dead_letter)(payload, message).await; } else { let delay = scaled_retry_delay(delay_seconds, row.attempts); - log::info!( + log::debug!( "task {} rescheduled in {delay:.1}s (attempt {})", row.id, row.attempts + 1 diff --git a/crates/xmedia-bot/src/send.rs b/crates/xmedia-bot/src/send.rs index 857ceb6..c49bb88 100644 --- a/crates/xmedia-bot/src/send.rs +++ b/crates/xmedia-bot/src/send.rs @@ -3,7 +3,7 @@ //! URL is blocked by hotlink protection; the bot downloads the file itself //! and uploads it via multipart). -use crate::handlers::{CHAT_STORE, LINK_CACHE, TASK_QUEUE}; +use crate::handlers::{CHAT_STORE, LINK_CACHE, TASK_QUEUE, log_key}; use crate::link_cache::{CachedMedia, CachedMediaKind, CachedPost}; use crate::photo::{self, MAX_UPLOAD_BYTES, PhotoPrep}; use crate::queue::QueueError; @@ -232,7 +232,7 @@ async fn cache_sent_task(task: &Task, media: Vec) { post.media = media; if let Some(key) = x_media::site::cache_key(&post.url) { LINK_CACHE.put(&key, &post).await; - log::info!("cached send for {}", post.url); + log::debug!("cached send for [key={}]", log_key(&post.url)); } } @@ -257,7 +257,7 @@ pub async fn invalidate_cache(task: &Task) { && let Some(url) = task.source_url() && let Some(key) = x_media::site::cache_key(url) { - log::info!("removing stale link cache entry for {url}"); + log::debug!("removing stale link cache entry for [key={}]", log_key(url)); LINK_CACHE.remove(&key).await; } } @@ -941,7 +941,7 @@ pub async fn send_media_sequence(bot: &Bot, task: &Task) -> Result, Sen .await { Ok(messages) => { - log::info!( + log::debug!( "media group batch {idx}/{} sent ({} item(s))", media_batches.len(), batch.len() @@ -952,7 +952,11 @@ pub async fn send_media_sequence(bot: &Bot, task: &Task) -> Result, Sen Err(RequestError::Api(api)) if is_media_fetch_failure(&api) || is_size_error(&api) => { log::info!( "Telegram could not fetch media for batch {idx} ({}), downloading and reuploading", - batch.first().map(item_url).unwrap_or("?") + batch + .first() + .map(item_url) + .map(log_key) + .unwrap_or_else(|| "?".into()) ); match send_batch_via_upload(bot, chat_id, reply_to, batch, caption).await { Ok(messages) => { @@ -1048,8 +1052,8 @@ pub async fn send_animation(bot: &Bot, task: &Task) -> Result, SendErro } Err(RequestError::Api(api)) if is_media_fetch_failure(&api) || is_size_error(&api) => { log::info!( - "Telegram could not fetch animation URL, downloading and reuploading: {}", - media_url + "Telegram could not fetch animation URL, downloading and reuploading: [key={}]", + log_key(media_url) ); match download_to_temp(animation).await { Ok((file, _bytes)) => {