From 4d6ec7924bac809debc4d9cab92c1651c7304cfc Mon Sep 17 00:00:00 2001 From: YoursFunny Date: Thu, 24 Sep 2026 15:02:31 +0800 Subject: [PATCH] fix(handlers): escape user-supplied text in log lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A Telegram display name, callback payload or channel handle is attacker-controlled text, and it went straight into info/error lines: one embedded newline forged a second log entry, and control characters could hide inside a line (log injection, audit SEC-006). handlers::log_escape replaces newlines, carriage returns and other control characters with visible escapes — clean input borrows, so logging allocates nothing extra — and every site that prints such a value uses it: the callback arrival line, the set-forward-channel info line (name + handle) and both get_chat error lines. The test pins that no raw newline can survive; AGENTS' logging convention names the helper. --- AGENTS.md | 2 +- crates/xmedia-bot/src/handlers/callback.rs | 5 +++- crates/xmedia-bot/src/handlers/commands.rs | 16 +++++++--- crates/xmedia-bot/src/handlers/mod.rs | 35 ++++++++++++++++++++++ 4 files changed, 52 insertions(+), 6 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 26caaf2..5041b40 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, `1 << attempt` backoff, 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, 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 (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. ## Important Files diff --git a/crates/xmedia-bot/src/handlers/callback.rs b/crates/xmedia-bot/src/handlers/callback.rs index 5a69bfe..7f41c2d 100644 --- a/crates/xmedia-bot/src/handlers/callback.rs +++ b/crates/xmedia-bot/src/handlers/callback.rs @@ -71,7 +71,10 @@ async fn handle_callback( return; } - log::info!("callback from {chat_id} on prompt {prompt_message_id}: {data}"); + log::info!( + "callback from {chat_id} on prompt {prompt_message_id}: {}", + super::log_escape(data) + ); if data == SKIP { // Skip works with or without a forward channel: it is the explicit // "do not forward this" answer, and it drops the record so the forward diff --git a/crates/xmedia-bot/src/handlers/commands.rs b/crates/xmedia-bot/src/handlers/commands.rs index 23370bf..65c334e 100644 --- a/crates/xmedia-bot/src/handlers/commands.rs +++ b/crates/xmedia-bot/src/handlers/commands.rs @@ -205,14 +205,18 @@ async fn set_forward_channel_handler( if let Some(from) = &message.from { log::info!( "Set forward channel for {} ({}) to {}", - from.full_name(), + super::log_escape(&from.full_name()), message.chat.id, - channel + super::log_escape(&channel.to_string()) ); } let chat = match bot.get_chat(channel.clone()).await { Err(e) => { - log::error!("Failed to get channel {}: {}", channel, e); + log::error!( + "Failed to get channel {}: {}", + super::log_escape(&channel.to_string()), + e + ); return Err(SetForwardChannelError::NotBotAdmin(e)); } Ok(chat) => chat, @@ -229,7 +233,11 @@ async fn set_forward_channel_handler( }; match bot.get_chat_administrators(channel.clone()).await { Err(e) => { - log::error!("Failed to get channel administrators {}: {}", channel, e); + log::error!( + "Failed to get channel administrators {}: {}", + super::log_escape(&channel.to_string()), + e + ); return Err(SetForwardChannelError::NotBotAdmin(e)); } Ok(admins) => { diff --git a/crates/xmedia-bot/src/handlers/mod.rs b/crates/xmedia-bot/src/handlers/mod.rs index dde1044..d6eb37f 100644 --- a/crates/xmedia-bot/src/handlers/mod.rs +++ b/crates/xmedia-bot/src/handlers/mod.rs @@ -56,6 +56,26 @@ pub fn log_key(url: &str) -> String { x_media::site::cache_key(url).unwrap_or_else(|| "".to_string()) } +/// Makes user-supplied text (a display name, callback data, a channel handle) +/// fit one log line: newlines and other control characters are escaped, so a +/// crafted value cannot forge a second log entry or hide inside one. Tab is +/// kept — it cannot break the line. +pub(crate) fn log_escape(s: &str) -> std::borrow::Cow<'_, str> { + if !s.chars().any(|c| c.is_control() && c != '\t') { + return std::borrow::Cow::Borrowed(s); + } + let mut out = String::with_capacity(s.len()); + for c in s.chars() { + match c { + '\n' => out.push_str("\\n"), + '\r' => out.push_str("\\r"), + c if c != '\t' && c.is_control() => out.push_str(&format!("\\u{:04x}", c as u32)), + c => out.push(c), + } + } + std::borrow::Cow::Owned(out) +} + /// How long a caption edit may sleep before it gives up on retrying: the reply /// (or button press) that carried the text is already consumed, so the update /// must not stall the chat's queue behind a long flood-control wait — the user @@ -282,6 +302,21 @@ mod tests { /// edit (the prompt was deleted). const API_ERROR: &str = "Bad Request: message not found"; + #[test] + fn log_escape_cannot_forge_a_second_log_line() { + let forged = log_escape("alice\nINFO injected entry"); + assert!(!forged.contains('\n'), "no raw newline may survive"); + assert!( + forged.contains("\\n"), + "the break stays visible as an escape" + ); + // The common case (clean input) borrows — logging must not allocate. + assert!(matches!( + log_escape("plain text"), + std::borrow::Cow::Borrowed(_) + )); + } + #[tokio::test] async fn reply_to_a_prompt_swaps_the_caption_through_its_template() { let sender = MockSender::scripted(vec![Outcome::EditOk], || api_error(API_ERROR));