From 5e265f24138602e2f60446aa55880340beed2e11 Mon Sep 17 00:00:00 2001 From: YoursFunny Date: Thu, 24 Sep 2026 15:38:25 +0800 Subject: [PATCH] chore(log): align levels with the documented convention MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three places disagreed with AGENTS' own level rules: get_chat/get_chat_administrators failures during /set_channel printed at error even though the usual cause is a mistyped channel name the user fixes on the spot (error is reserved for dead letters and the like — now warn, same as other user-served degradations); the edit-before-forward callback arrival line logged at info while the sibling arrival lines for commands and inline queries log at debug (now debug, still carries the escaped payload); and the two upload-fallback lines logged at info while photo.rs's parallel degradations log at warn (now warn both — Telegram failing to fetch our media is a degradation that leaves the user served). AGENTS' convention sentence is now explicit about all three instead of the ambiguous '(fallback, retry enqueue, dead-letter is error)'. --- AGENTS.md | 2 +- crates/xmedia-bot/src/handlers/callback.rs | 2 +- crates/xmedia-bot/src/handlers/commands.rs | 6 +++--- crates/xmedia-bot/src/send/mod.rs | 4 ++-- 4 files changed, 7 insertions(+), 7 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 3a8c4f9..2fa421e 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -74,7 +74,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, a doubling backoff widened by a random slice of itself so workers that failed together do not recover together, with a 429's `Retry-After` honored up to `MAX_RETRY_AFTER_SECS` = 60 s, over HTTP errors only); `site::fetch_once` is the same code path with a single attempt, used by inline queries whose answer window is shorter than the backoff. A status a site answers with is classified by what a *retry* can change: 404/410 are `NotFound` and 401/403 are `Blocked` (permanent, reported at once), 429/5xx are `Transient` and retried. Queue retries are explicit `QueueError::Retryable` with computed delay (`retry_delay_seconds`), scaled per attempt by `scaled_retry_delay` — which only ever scales **up**, so a delay the server asked for (Telegram `retry_after`) is never shortened. `send::classify_request_error` is the send-side counterpart: `RetryAfter` and `Network` are retryable, and so is a 5xx — teloxide sleeps 10 s on a server error and then parses the body, so by then the HTTP status is gone and the condition is recognised by shape instead (a JSON server-error description, or an `InvalidJson` whose raw body is not JSON, i.e. a proxy/error page). -- Logging via `log` macros (`pretty_env_logger`, level from `RUST_LOG`). `main.rs` initializes the **timed** builder with a default filter of `info,hyper_util=warn,reqwest=warn` when `RUST_LOG` is unset: the plain `init` had no timestamps and fell back to `error`, so a deployment that forgot the variable logged nothing at all, and at `debug` the HTTP client's own lines outnumbered the bot's two to one. An explicit `RUST_LOG` overrides the default wholesale. Level convention: `info` = lifecycle + per-post business results (`sent`/`forwarded`/`copied`, with `chat=` and the total `ms`), admin/operator actions and anomalies (fallback, retry enqueue, dead-letter is `error`); `debug` = per-request detail (URL extraction, `fetching`/`fetched` with the fetch duration, batch sends, queue processing with the row's `chat=`/`key=` and per-attempt `ms`, photo processing, inline queries); `trace` = user data (the full URL, the message text, the inline query). At `debug` and above links are printed via the normalized cache key (`handlers::log_key`, e.g. `[key=twitter:123...]`), so a `debug` log can be shared without echoing what users pasted; user-supplied text that does reach a line (display names, callback data, channel handles) goes through `handlers::log_escape`, whose escapes keep a crafted value from splitting or forging a log entry, and degradations that leave the user served (a failed cache read/write, a failed chat action) are `warn`, not `error`. The only queue/sweep aggregate is the 300 s sweep's queue line, and it speaks only when the queue is non-empty. +- Logging via `log` macros (`pretty_env_logger`, level from `RUST_LOG`). `main.rs` initializes the **timed** builder with a default filter of `info,hyper_util=warn,reqwest=warn` when `RUST_LOG` is unset: the plain `init` had no timestamps and fell back to `error`, so a deployment that forgot the variable logged nothing at all, and at `debug` the HTTP client's own lines outnumbered the bot's two to one. An explicit `RUST_LOG` overrides the default wholesale. Level convention: `info` = lifecycle + per-post business results (`sent`/`forwarded`/`copied`, with `chat=` and the total `ms`), admin/operator actions and anomalies (the upload fallback and other user-served degradations are `warn`; retry enqueue and dead-letter are `error`); `debug` = per-request detail (URL extraction, `fetching`/`fetched` with the fetch duration, batch sends, queue processing with the row's `chat=`/`key=` and per-attempt `ms`, photo processing, inline queries); `trace` = user data (the full URL, the message text, the inline query). At `debug` and above links are printed via the normalized cache key (`handlers::log_key`, e.g. `[key=twitter:123...]`), so a `debug` log can be shared without echoing what users pasted; user-supplied text that does reach a line (display names, callback data, channel handles) goes through `handlers::log_escape`, whose escapes keep a crafted value from splitting or forging a log entry, and degradations that leave the user served (a failed cache read/write, a failed chat action) are `warn`, not `error`. The only queue/sweep aggregate is the 300 s sweep's queue line, and it speaks only when the queue is non-empty. ## Important Files diff --git a/crates/xmedia-bot/src/handlers/callback.rs b/crates/xmedia-bot/src/handlers/callback.rs index 7f41c2d..b6f913e 100644 --- a/crates/xmedia-bot/src/handlers/callback.rs +++ b/crates/xmedia-bot/src/handlers/callback.rs @@ -71,7 +71,7 @@ async fn handle_callback( return; } - log::info!( + log::debug!( "callback from {chat_id} on prompt {prompt_message_id}: {}", super::log_escape(data) ); diff --git a/crates/xmedia-bot/src/handlers/commands.rs b/crates/xmedia-bot/src/handlers/commands.rs index d984319..49846e0 100644 --- a/crates/xmedia-bot/src/handlers/commands.rs +++ b/crates/xmedia-bot/src/handlers/commands.rs @@ -212,7 +212,7 @@ async fn set_forward_channel_handler( } let chat = match bot.get_chat(channel.clone()).await { Err(e) => { - log::error!( + log::warn!( "Failed to get channel {}: {}", super::log_escape(&channel.to_string()), e @@ -227,13 +227,13 @@ async fn set_forward_channel_handler( let channel_id = chat.id.0; // The sender must be a channel administrator. Compare against the // sender's user id, NOT the chat id (they only coincide in private - // chats, so the old check broke group usage). + // chats), so the old check broke group usage). let Some(sender) = message.from.as_ref() else { return Err(SetForwardChannelError::NotAdmin); }; match bot.get_chat_administrators(channel.clone()).await { Err(e) => { - log::error!( + log::warn!( "Failed to get channel administrators {}: {}", super::log_escape(&channel.to_string()), e diff --git a/crates/xmedia-bot/src/send/mod.rs b/crates/xmedia-bot/src/send/mod.rs index 0f07a0d..c41c8d7 100644 --- a/crates/xmedia-bot/src/send/mod.rs +++ b/crates/xmedia-bot/src/send/mod.rs @@ -511,7 +511,7 @@ pub async fn send_media_sequence(ctx: &AppContext<'_>, task: &Task) -> Result { - log::info!( + log::warn!( "Telegram could not fetch media for batch {idx} ({}), downloading and reuploading", batch .first() @@ -604,7 +604,7 @@ pub async fn send_animation(ctx: &AppContext<'_>, task: &Task) -> Result { - log::info!( + log::warn!( "Telegram could not fetch animation URL, downloading and reuploading: [key={}]", log_key(media_url) );