From bbc4b4ad58518c4ba6990d93e9965086098ef670 Mon Sep 17 00:00:00 2001 From: Leonid Kozarin Date: Wed, 18 Mar 2026 14:34:38 +0300 Subject: [PATCH 1/2] Add distributed tracing via OpenTelemetry OTLP - Add src/observability.rs: init_tracing() wires tracing-log bridge, optional OTLP/gRPC exporter (disabled when OTEL_EXPORTER_OTLP_ENDPOINT is unset), and console fmt layer; replaces pretty_env_logger - Instrument inline_handler, cmd_loc_handler, resolve_locations, SearchChain::find, and all loc finders (Google, OSM, Yandex) with #[tracing::instrument]; replace log:: with tracing:: throughout - Add OtelAxumLayer + OtelInResponseLayer to axum router in both webhook and polling branches - Add otel test helper and two span tests: creates_span and hierarchy - Passthrough OTEL_EXPORTER_OTLP_ENDPOINT in docker-compose.yaml Co-Authored-By: Claude Sonnet 4.6 --- .env.example | 2 + Cargo.lock | 215 +++++++++++++++++++++++++++-------- Cargo.toml | 10 +- docker-compose.yaml | 1 + src/handlers/limiter_test.rs | 2 +- src/handlers/mod.rs | 17 +-- src/handlers/test.rs | 67 ++++++++++- src/loc/google.rs | 10 +- src/loc/mod.rs | 11 +- src/loc/osm.rs | 7 +- src/loc/yandex.rs | 12 +- src/main.rs | 37 +++--- src/observability.rs | 60 ++++++++++ 13 files changed, 360 insertions(+), 91 deletions(-) create mode 100644 src/observability.rs diff --git a/.env.example b/.env.example index 43bee83..f42a172 100644 --- a/.env.example +++ b/.env.example @@ -24,6 +24,8 @@ REQUESTS_LIMITER_TIMEFRAME=60 QUERY_CHECK_MODE=regex +# Optional: if unset, OTLP export is disabled (console-only logging) +#OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 ### envars for user-service diff --git a/Cargo.lock b/Cargo.lock index 816e048..fb8304a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -225,6 +225,25 @@ dependencies = [ "tower-http", ] +[[package]] +name = "axum-tracing-opentelemetry" +version = "0.33.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4bedd2c385488b22a3a35b664fbc7f8e755d3ec6720848bc106b80cb5ae18fd7" +dependencies = [ + "axum", + "futures-core", + "futures-util", + "http", + "opentelemetry", + "opentelemetry-semantic-conventions", + "pin-project-lite", + "tower", + "tracing", + "tracing-opentelemetry", + "tracing-opentelemetry-instrumentation-sdk", +] + [[package]] name = "base62" version = "2.2.3" @@ -744,19 +763,6 @@ version = "1.15.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "48c757948c5ede0e46177b7add2e67155f70e33c07fea8284df6576da70b3719" -[[package]] -name = "env_logger" -version = "0.10.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4cd405aab171cb85d6735e5c8d9db038c17d3ca007a4d2c25f337935c3d90580" -dependencies = [ - "humantime", - "is-terminal", - "log", - "regex", - "termcolor", -] - [[package]] name = "equivalent" version = "1.0.2" @@ -1235,12 +1241,6 @@ version = "1.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9" -[[package]] -name = "humantime" -version = "2.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "135b12329e5e3ce057a9f972339ea52bc954fe1e9358ef27f95e89716fbc5424" - [[package]] name = "hyper" version = "1.8.1" @@ -1568,17 +1568,6 @@ dependencies = [ "serde", ] -[[package]] -name = "is-terminal" -version = "0.4.17" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3640c1c38b8e4e43584d8df18be5fc6b0aa314ce6ebf51b53313d4306cca8e46" -dependencies = [ - "hermit-abi", - "libc", - "windows-sys 0.61.2", -] - [[package]] name = "itertools" version = "0.10.5" @@ -1704,6 +1693,7 @@ dependencies = [ "async-trait", "axum", "axum-prometheus", + "axum-tracing-opentelemetry", "bincode", "chashmap", "derive_more 2.1.1", @@ -1719,7 +1709,9 @@ dependencies = [ "mobc", "mobc-redis", "once_cell", - "pretty_env_logger", + "opentelemetry", + "opentelemetry-otlp", + "opentelemetry_sdk", "prometheus", "prost", "prost-types", @@ -1740,6 +1732,10 @@ dependencies = [ "tonic", "tonic-prost", "tonic-prost-build", + "tracing", + "tracing-log", + "tracing-opentelemetry", + "tracing-subscriber", "uuid", ] @@ -1764,6 +1760,15 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "112b39cec0b298b6c1999fee3e31427f74f676e4cb9879ed1a121b43661a4154" +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.8.4" @@ -2012,6 +2017,88 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7c87def4c32ab89d880effc9e097653c8da5d6ef28e6b539d313baaacfbafcbe" +[[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-http" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d7a6d09a73194e6b66df7c8f1b680f156d916a1a942abf2de06823dd02b7855d" +dependencies = [ + "async-trait", + "bytes", + "http", + "opentelemetry", + "reqwest 0.12.28", +] + +[[package]] +name = "opentelemetry-otlp" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7a2366db2dca4d2ad033cad11e6ee42844fd727007af5ad04a1730f4cb8163bf" +dependencies = [ + "http", + "opentelemetry", + "opentelemetry-http", + "opentelemetry-proto", + "opentelemetry_sdk", + "prost", + "reqwest 0.12.28", + "thiserror 2.0.18", + "tokio", + "tonic", + "tracing", +] + +[[package]] +name = "opentelemetry-proto" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7175df06de5eaee9909d4805a3d07e28bb752c34cab57fa9cff549da596b30f" +dependencies = [ + "opentelemetry", + "opentelemetry_sdk", + "prost", + "tonic", + "tonic-prost", +] + +[[package]] +name = "opentelemetry-semantic-conventions" +version = "0.31.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e62e29dfe041afb8ed2a6c9737ab57db4907285d999ef8ad3a59092a36bdc846" + +[[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 0.9.2", + "thiserror 2.0.18", + "tokio", + "tokio-stream", +] + [[package]] name = "owning_ref" version = "0.3.3" @@ -2176,16 +2263,6 @@ dependencies = [ "zerocopy", ] -[[package]] -name = "pretty_env_logger" -version = "0.5.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "865724d4dbe39d9f3dd3b52b88d859d66bcb2d6a0acfd5ea68a65fb66d4bdc1c" -dependencies = [ - "env_logger", - "log", -] - [[package]] name = "prettyplease" version = "0.2.37" @@ -2740,6 +2817,7 @@ checksum = "eddd3ca559203180a307f12d114c268abf583f59b03cb906fd0b3ff8646c1147" dependencies = [ "base64 0.22.1", "bytes", + "futures-channel", "futures-core", "futures-util", "http", @@ -3541,15 +3619,6 @@ dependencies = [ "windows-sys 0.61.2", ] -[[package]] -name = "termcolor" -version = "1.4.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "06794f8f6c5c898b3275aebefa6b8a1cb24cd2c6c79397ab15774837a0bc5755" -dependencies = [ - "winapi-util", -] - [[package]] name = "testcontainers" version = "0.27.1" @@ -3950,18 +4019,64 @@ dependencies = [ "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 1.15.1", + "tracing", + "tracing-core", + "tracing-log", + "tracing-subscriber", + "web-time", +] + +[[package]] +name = "tracing-opentelemetry-instrumentation-sdk" +version = "0.32.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc2a7ad7b8bd011f482d1fdf95be20377cdd19f45aa9d1f9f902d746eddc3cad" +dependencies = [ + "http", + "opentelemetry", + "opentelemetry-semantic-conventions", + "tracing", + "tracing-opentelemetry", +] + +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec 1.15.1", "thread_local", + "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 0a77d9e..ede7e66 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,7 +17,14 @@ prometheus = "0.14.0" hyper = "1.8.1" # Logging and envs log = "0.4.29" -pretty_env_logger = "0.5.0" +tracing = "0.1.44" +tracing-subscriber = { version = "0.3.22", features = ["env-filter", "fmt", "json"] } +tracing-opentelemetry = "0.32.1" +tracing-log = "0.2" +opentelemetry = "0.31.0" +opentelemetry_sdk = { version = "0.31.0", features = ["rt-tokio"] } +opentelemetry-otlp = { version = "0.31.0", features = ["grpc-tonic"] } +axum-tracing-opentelemetry = "0.33.0" dotenvy = "0.15.7" # HTTP client with caching reqwest = { version = "0.13.2", default-features = false, features = ["rustls", "json"] } @@ -58,6 +65,7 @@ async-trait = "0.1.89" [dev-dependencies] testcontainers = "0.27.1" +opentelemetry_sdk = { version = "0.31.0", features = ["testing"] } [build-dependencies] tonic-prost-build = "0.14.5" diff --git a/docker-compose.yaml b/docker-compose.yaml index 0ca4a08..f05b9d2 100644 --- a/docker-compose.yaml +++ b/docker-compose.yaml @@ -26,6 +26,7 @@ services: - CACHE_CLEAN_UP_INTERVAL_SECS - SEARCH_RADIUS_METERS - QUERY_CHECK_MODE + - OTEL_EXPORTER_OTLP_ENDPOINT expose: - 8080 networks: diff --git a/src/handlers/limiter_test.rs b/src/handlers/limiter_test.rs index 657adc1..232acb0 100644 --- a/src/handlers/limiter_test.rs +++ b/src/handlers/limiter_test.rs @@ -4,7 +4,7 @@ use crate::testutils::start_redis; #[tokio::test] async fn test_rate_limiter() { - pretty_env_logger::init(); + let _ = tracing_subscriber::fmt::try_init(); let (_redis_container, redis_client) = start_redis().await; let limiter = RequestsLimiter::new(redis_client, 2, 60); diff --git a/src/handlers/mod.rs b/src/handlers/mod.rs index 08ed6ed..a93e869 100644 --- a/src/handlers/mod.rs +++ b/src/handlers/mod.rs @@ -78,13 +78,14 @@ pub fn preload_env_vars() { let _ = *INLINE_REQUESTS_LIMITER; } +#[tracing::instrument(skip(bot, usr_client), fields(query = %q.query))] pub async fn inline_handler(bot: Bot, q: InlineQuery, usr_client: UserService) -> HandlerResult { if !is_query_correct(&q.query) || rate_limit_exceeded(&q).await { bot.answer_inline_query(q.id, vec![]).await?; return Ok(()); } - log::info!("Got an inline query: {}", q.query); + tracing::info!("Got an inline query: {}", q.query); metrics::INLINE_COUNTER.inc_allowed(); let lang_code = &ensure_lang_code(q.from.id, q.from.language_code.clone(), &usr_client).await; @@ -101,7 +102,7 @@ fn is_query_correct(query: &str) -> bool { *QUERY_CHECK_MODE != QueryCheckMode::Regex ); if !allowed { - log::info!("Invalid query: {}", query); + tracing::info!("Invalid query: {}", query); metrics::INLINE_COUNTER.inc_bad_query(); } allowed @@ -110,7 +111,7 @@ fn is_query_correct(query: &str) -> bool { async fn rate_limit_exceeded(q: &InlineQuery) -> bool { let forbidden = !INLINE_REQUESTS_LIMITER.is_req_allowed(q).await; if forbidden { - log::info!("Requests limit was exceeded for {}", q.from.id); + tracing::info!("Requests limit was exceeded for {}", q.from.id); metrics::INLINE_COUNTER.inc_forbidden(); } forbidden @@ -134,7 +135,7 @@ pub async fn command_handler(bot: Bot, msg: Message, cmd: Command, me: Me, usr_c help::get_start_message(msg.from.as_ref().unwrap(), me, usr_client).await.into() }, Command::Start => { - log::warn!("The /start command was invoked without a FROM field for a message: {msg:?}"); + tracing::warn!("The /start command was invoked without a FROM field for a message: {msg:?}"); let lang_code = &determine_lang_code(&msg, &usr_client).await?; help::get_help_message(me, lang_code).into() } @@ -155,7 +156,7 @@ pub async fn command_handler(bot: Bot, msg: Message, cmd: Command, me: Me, usr_c } _ if usr_client.disabled() => { let lang_code = &determine_lang_code(&msg, &usr_client).await?; - log::error!("user-service is disabled but a command was invoked by {:?}", msg.from); + tracing::error!("user-service is disabled but a command was invoked by {:?}", msg.from); t!("error.service.user.disabled", locale = lang_code).to_string().into() }, _ if msg.from.is_none() => Err(anyhow!("some command was invoked without a FROM field for a message: {msg:?}"))?, @@ -175,7 +176,7 @@ pub async fn message_handler(bot: Bot, msg: Message, usr_client: UserService HandlerResult { - log::info!("Got a callback query for {}: {}", + tracing::info!("Got a callback query for {}: {}", q.from.id, q.data.clone().unwrap_or("".to_string())); @@ -197,6 +198,7 @@ pub async fn callback_handler(bot: Bot, q: CallbackQuery) -> HandlerResult { Ok(()) } +#[tracing::instrument(skip(bot, usr_client))] async fn cmd_loc_handler(bot: Bot, msg: Message, usr_client: UserService) -> HandlerResult { let from = msg.from.as_ref().ok_or("no from")?; let lang_code = &ensure_lang_code(from.id, from.language_code.clone(), &usr_client).await; @@ -205,7 +207,7 @@ async fn cmd_loc_handler(bot: Bot, msg: Message, usr_client: UserService return send_error(bot, msg, "error.query.empty", lang_code).await, Some(text) => text.to_string() }; - log::info!("Got a message query: {}", text); + tracing::info!("Got a message query: {}", text); let location = try_determine_location(from.id, &usr_client).await; let locations = resolve_locations(text, lang_code, location).await?; @@ -213,6 +215,7 @@ async fn cmd_loc_handler(bot: Bot, msg: Message, usr_client: UserService) -> Result, Box> { let query = query.as_str(); let locations = if let Some(coords) = COORDS_REGEXP.captures(query) { diff --git a/src/handlers/test.rs b/src/handlers/test.rs index 450ba2f..bb127d7 100644 --- a/src/handlers/test.rs +++ b/src/handlers/test.rs @@ -1,5 +1,23 @@ use super::{is_query_correct, COORDS_REGEXP, QUERY_REGEX}; +mod otel { + use opentelemetry_sdk::trace::InMemorySpanExporter; + use opentelemetry_sdk::trace::{SdkTracerProvider, SimpleSpanProcessor}; + use tracing::Subscriber; + use tracing_subscriber::{layer::SubscriberExt, Registry}; + + pub fn setup_otel_test() -> (InMemorySpanExporter, SdkTracerProvider, impl Subscriber + Send + Sync) { + let exporter = InMemorySpanExporter::default(); + let provider = SdkTracerProvider::builder() + .with_span_processor(SimpleSpanProcessor::new(exporter.clone())) + .build(); + let tracer = opentelemetry::trace::TracerProvider::tracer(&provider, "test"); + let subscriber = Registry::default() + .with(tracing_opentelemetry::layer().with_tracer(tracer)); + (exporter, provider, subscriber) + } +} + #[test] fn test_coords_regex() { let false_cases = [ @@ -52,7 +70,7 @@ fn test_query_regex() { "中国北京", "دبي مارينا، دبي، الإمارات العربية المتحدة", ]; - + run_test(false_cases, true_cases, |case| QUERY_REGEX.is_match(case)) } @@ -82,10 +100,55 @@ fn test_is_query_correct() { "中国北京", "دبي مارينا، دبي، الإمارات العربية المتحدة", ]; - + run_test(false_cases, true_cases, is_query_correct) } +#[tokio::test] +async fn test_resolve_locations_creates_span() { + let (exporter, _provider, subscriber) = otel::setup_otel_test(); + let _guard = tracing::subscriber::set_default(subscriber); + + let result = super::resolve_locations("55.7 37.6".to_string(), "en", None).await; + assert!(result.is_ok()); + + let spans = exporter.get_finished_spans().unwrap(); + assert!( + spans.iter().any(|s| s.name == "resolve_locations"), + "Expected span 'resolve_locations', got: {:?}", + spans.iter().map(|s| s.name.as_ref()).collect::>() + ); +} + +#[tokio::test] +async fn test_span_hierarchy() { + use tracing::Instrument; + + let (exporter, _provider, subscriber) = otel::setup_otel_test(); + let _guard = tracing::subscriber::set_default(subscriber); + + let root_span = tracing::info_span!("root"); + super::resolve_locations("55.7 37.6".to_string(), "en", None) + .instrument(root_span) + .await + .unwrap(); + + let spans = exporter.get_finished_spans().unwrap(); + let root = spans.iter().find(|s| s.name == "root").expect("root span not found"); + let child = spans.iter().find(|s| s.name == "resolve_locations").expect("child span not found"); + + assert_eq!( + child.span_context.trace_id(), + root.span_context.trace_id(), + "child and root must share the same trace_id" + ); + assert_eq!( + child.parent_span_id, + root.span_context.span_id(), + "child's parent_span_id must equal root's span_id" + ); +} + fn run_test( false_cases: [&str; N1], true_cases: [&str; N2], diff --git a/src/loc/google.rs b/src/loc/google.rs index 3a28beb..7817863 100644 --- a/src/loc/google.rs +++ b/src/loc/google.rs @@ -14,7 +14,7 @@ const FINDER_ENV_API_KEY: &str = "GOOGLE_MAPS_API_KEY"; static GAPI_MODE: Lazy = Lazy::new(|| { let val = std::env::var("GAPI_MODE").expect("GAPI_MODE must be set!"); - log::info!("GAPI_MODE is {val}"); + tracing::info!("GAPI_MODE is {val}"); GoogleAPIMode::from_str(val.as_str()).expect("Invalid value of GAPI_MODE") }); @@ -93,6 +93,7 @@ impl GoogleLocFinder { Self::init(api_key.as_str()) } + #[tracing::instrument(skip(self))] async fn find(&self, address: &str, params: SearchParams<'_>) -> LocResult { let mut results = self.find_geo(address, params).await?; if results.is_empty() { @@ -101,6 +102,7 @@ impl GoogleLocFinder { Ok(results) } + #[tracing::instrument(skip(self))] async fn find_geo(&self, address: &str, params: SearchParams<'_>) -> LocResult { self.geocode_req_counter.inc(); let bounds_part = params.location @@ -113,7 +115,7 @@ impl GoogleLocFinder { self.inc_resp_counter(&resp); let json = resp.json::().await?; - log::info!("Response from Google Maps Geocoding API: {json}"); + tracing::info!("Response from Google Maps Geocoding API: {json}"); let results = iter_over_array(&json["results"]) .filter_map(map_resp_geo) @@ -121,6 +123,7 @@ impl GoogleLocFinder { Ok(results) } + #[tracing::instrument(skip(self))] async fn find_text(&self, address: &str, params: SearchParams<'_>) -> LocResult { self.text_req_counter.inc(); let resp = self.client.post("https://places.googleapis.com/v1/places:searchText") @@ -132,7 +135,7 @@ impl GoogleLocFinder { self.inc_resp_counter(&resp); let json = resp.json::().await?; - log::info!("Response from Google Maps Text Search API: {json}"); + tracing::info!("Response from Google Maps Text Search API: {json}"); let results: Vec = iter_over_array(&json["places"]) .filter_map(map_resp_place) @@ -144,6 +147,7 @@ impl GoogleLocFinder { #[async_trait] impl LocFinder for GoogleLocFinder { + #[tracing::instrument(skip(self))] async fn find(&self, query: &str, lang_code: &str, location: Option<(f64, f64)>) -> LocResult { let params = SearchParams { lang_code, location }; match *GAPI_MODE { diff --git a/src/loc/mod.rs b/src/loc/mod.rs index 8219bcd..3947b7a 100644 --- a/src/loc/mod.rs +++ b/src/loc/mod.rs @@ -18,9 +18,9 @@ const DISABLE_ENV_PREFIX: &str = "DISABLE_FINDER_"; static SEARCH_RADIUS: Lazy = Lazy::new(|| { let val: u32 = std::env::var("SEARCH_RADIUS_METERS") .ok() - .and_then(|v| v.parse().map_err(|e| log::error!("couldn't parse SEARCH_RADIUS_METERS: {e}")).ok()) + .and_then(|v| v.parse().map_err(|e| tracing::error!("couldn't parse SEARCH_RADIUS_METERS: {e}")).ok()) .unwrap_or(1000); - log::info!("SEARCH_RADIUS_METERS is {val}"); + tracing::info!("SEARCH_RADIUS_METERS is {val}"); f64::from(val) / 10_000.0 // 6 digits after a comma have accuracy in 0.1 m, so we need to shift the dot at 5 digits }); @@ -84,6 +84,7 @@ impl SearchChain { self } + #[tracing::instrument(skip(self), fields(query, lang_code))] pub async fn find(&self, query: &str, lang_code: &str, location: Option<(f64, f64)>) -> Vec { let futures = self.regional_finders.get(lang_code) .unwrap_or(&self.global_finders) @@ -94,7 +95,7 @@ impl SearchChain { match fut.await { Ok(res) if !res.is_empty() => return res, Ok(_) => continue, - Err(err) => log::error!("couldn't fetch loc data: {err}"), + Err(err) => tracing::error!("couldn't fetch loc data: {err}"), } }; @@ -125,7 +126,7 @@ impl LocFinderChainWrapper { .map(|v| v == "true" || v == "1" || v == "yes" || v == "y") .unwrap_or(false); if disabled { - log::warn!("The {} finder is disabled!", self.env_suffix); + tracing::warn!("The {} finder is disabled!", self.env_suffix); None } else { Some(self.finder) @@ -133,7 +134,7 @@ impl LocFinderChainWrapper { } } -#[derive(Copy, Clone)] +#[derive(Debug, Copy, Clone)] struct SearchParams<'a> { lang_code: &'a str, location: Option<(f64, f64)> diff --git a/src/loc/osm.rs b/src/loc/osm.rs index a7ad98b..23c6ead 100644 --- a/src/loc/osm.rs +++ b/src/loc/osm.rs @@ -35,6 +35,7 @@ impl OpenStreetMapLocFinder { #[async_trait] impl LocFinder for OpenStreetMapLocFinder { + #[tracing::instrument(skip(self))] async fn find(&self, query: &str, lang_code: &str, location: Option<(f64, f64)>) -> LocResult { self.api_req_counter.inc(); let viewbox_part = location @@ -42,7 +43,7 @@ impl LocFinder for OpenStreetMapLocFinder { .map(|(p1, p2)| format!("&viewbox={},{},{},{}", p1.1, p1.0, p2.1, p2.0)) .unwrap_or_default(); let url = format!("https://nominatim.openstreetmap.org/search?q={query}&format=json{viewbox_part}"); - log::debug!("Request: {url}"); + tracing::debug!("Request: {url}"); let resp = self.client.get(url) .header(USER_AGENT, "kozalosev/LocPlaceBot") .header(ACCEPT_LANGUAGE, lang_code) @@ -50,7 +51,7 @@ impl LocFinder for OpenStreetMapLocFinder { self.inc_resp_counter(&resp); let json = resp.json::().await?; - log::info!("Response from Open Street Map Nominatim API: {json}"); + tracing::info!("Response from Open Street Map Nominatim API: {json}"); let results = json.as_array().unwrap().iter() .filter_map(map_resp) @@ -78,4 +79,4 @@ fn map_resp(v: &serde_json::Value) -> Option { Some(Location { address, latitude, longitude }) -} \ No newline at end of file +} diff --git a/src/loc/yandex.rs b/src/loc/yandex.rs index ac142ca..20f70b9 100644 --- a/src/loc/yandex.rs +++ b/src/loc/yandex.rs @@ -14,7 +14,7 @@ const PLACES_ENV_API_KEY: &str = "YANDEX_MAPS_PLACES_API_KEY"; pub static YAPI_MODE: Lazy = Lazy::new(|| { let val = std::env::var("YAPI_MODE").expect("YAPI_MODE must be set!"); - log::info!("YAPI_MODE is {val}"); + tracing::info!("YAPI_MODE is {val}"); YandexAPIMode::from_str(val.as_str()).expect("Invalid value of YAPI_MODE") }); @@ -77,6 +77,7 @@ impl YandexLocFinder { Self::init(geocode_api_key, places_api_key) } + #[tracing::instrument(skip(self))] async fn find_geo_place(&self, address: &str, params: SearchParams<'_>) -> LocResult { let mut results = self.find_geo(address, params).await?; if results.is_empty() { @@ -85,6 +86,7 @@ impl YandexLocFinder { Ok(results) } + #[tracing::instrument(skip(self))] async fn find_geo(&self, address: &str, params: SearchParams<'_>) -> LocResult { self.geocode_req_counter.inc(); @@ -94,7 +96,7 @@ impl YandexLocFinder { self.inc_resp_counter(&resp); let json = resp.json::().await?; - log::info!("Response from Yandex Maps Geocoder: {json}"); + tracing::info!("Response from Yandex Maps Geocoder: {json}"); let empty: Vec = Vec::new(); let result = json["response"]["GeoObjectCollection"]["featureMember"] @@ -106,6 +108,7 @@ impl YandexLocFinder { Ok(result) } + #[tracing::instrument(skip(self))] async fn find_place(&self, address: &str, params: SearchParams<'_>) -> LocResult { self.place_req_counter.inc(); @@ -118,7 +121,7 @@ impl YandexLocFinder { self.inc_resp_counter(&resp); let json = resp.json::().await?; - log::info!("Response from Yandex Maps Places API: {json}"); + tracing::info!("Response from Yandex Maps Places API: {json}"); let empty: Vec = Vec::new(); let result = json["features"] @@ -133,6 +136,7 @@ impl YandexLocFinder { #[async_trait] impl LocFinder for YandexLocFinder { + #[tracing::instrument(skip(self))] async fn find(&self, query: &str, lang_code: &str, location: Option<(f64, f64)>) -> LocResult { let params = SearchParams { lang_code, location }; match *YAPI_MODE { @@ -162,7 +166,7 @@ fn geocode_elem_mapper(v: &serde_json::Value) -> Option { .split(' ') .collect::>(); if pos.len() < 2 { - log::error!("pos length < 2: {pos:?}"); + tracing::error!("pos length < 2: {pos:?}"); return None } let longitude: f64 = pos[0].parse().ok()?; diff --git a/src/main.rs b/src/main.rs index 84223fb..8f81488 100644 --- a/src/main.rs +++ b/src/main.rs @@ -10,6 +10,7 @@ mod users; mod eula; mod commands; mod redis; +mod observability; #[cfg(test)] mod testutils; @@ -17,6 +18,7 @@ mod testutils; use std::env::VarError; use std::net::SocketAddr; use std::time::Duration; +use axum_tracing_opentelemetry::middleware::{OtelAxumLayer, OtelInResponseLayer}; use futures::future::join_all; use reqwest::Url; use rust_i18n::i18n; @@ -41,8 +43,8 @@ i18n!(fallback = "en"); // load localizations with default parameters async fn main() -> Result<(), Box> { #[cfg(debug_assertions)] dotenvy::dotenv()?; - - pretty_env_logger::init(); + + let tracer_provider = observability::init_tracing()?; handlers::preload_env_vars(); let handler = dptree::entry() @@ -71,7 +73,7 @@ async fn main() -> Result<(), Box> { if set_my_commands_failed { Err("couldn't set the bot's commands")? } else { - log::info!("The commands has been updated successfully!") + tracing::info!("The commands has been updated successfully!") } let webhook_url: Option = match std::env::var(ENV_WEBHOOK_URL) { @@ -101,7 +103,7 @@ async fn main() -> Result<(), Box> { UserService::Connected(grpc) }, Err(e) => { - log::error!("couldn't connect to user-service: {e}"); + tracing::error!("couldn't connect to user-service: {e}"); UserService::Disabled } }; @@ -110,9 +112,9 @@ async fn main() -> Result<(), Box> { RedisStorage::open(&REDIS.connection_url, Json).await? ]; - match webhook_url { + let result = match webhook_url { Some(url) => { - log::info!("Setting a webhook: {url}"); + tracing::info!("Setting a webhook: {url}"); let (mut listener, stop_flag, bot_router) = axum_to_router(bot.clone(), Options::new(addr, url)).await?; let stop_token = listener.stop_token(); @@ -126,13 +128,12 @@ async fn main() -> Result<(), Box> { let srv = tokio::spawn(async move { let tcp_listener = tokio::net::TcpListener::bind(addr) .await - .map_err(|err| { - stop_token.stop(); - err - })?; + .inspect_err(|_| stop_token.stop())?; let app = axum::Router::new() .merge(metrics_router) - .merge(bot_router); + .merge(bot_router) + .layer(OtelInResponseLayer) + .layer(OtelAxumLayer::default()); axum::serve(tcp_listener, app) .with_graceful_shutdown(stop_flag) .await @@ -143,7 +144,7 @@ async fn main() -> Result<(), Box> { res?.map_err(Into::into) } None => { - log::info!("The polling dispatcher is activating..."); + tracing::info!("The polling dispatcher is activating..."); let bot_fut = tokio::spawn(async move { Dispatcher::builder(bot, handler) @@ -156,12 +157,15 @@ async fn main() -> Result<(), Box> { let srv = tokio::spawn(async move { let tcp_listener = tokio::net::TcpListener::bind(addr).await?; - axum::serve(tcp_listener, metrics_router) + let app = metrics_router + .layer(OtelInResponseLayer) + .layer(OtelAxumLayer::default()); + axum::serve(tcp_listener, app) .with_graceful_shutdown(async { tokio::signal::ctrl_c() .await .expect("failed to install CTRL+C signal handler"); - log::info!("Shutdown of the metrics server") + tracing::info!("Shutdown of the metrics server") }) .await }); @@ -169,5 +173,8 @@ async fn main() -> Result<(), Box> { let (res, _) = futures::join!(srv, bot_fut); res?.map_err(Into::into) } - } + }; + + tracer_provider.shutdown()?; + result } diff --git a/src/observability.rs b/src/observability.rs new file mode 100644 index 0000000..a8cecaf --- /dev/null +++ b/src/observability.rs @@ -0,0 +1,60 @@ +use opentelemetry::global; +use opentelemetry::trace::TracerProvider; +use opentelemetry_sdk::Resource; +use opentelemetry_otlp::{SpanExporter, WithExportConfig}; +use opentelemetry_sdk::trace::SdkTracerProvider; +use tracing_subscriber::{Layer, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; + +const SERVICE_NAME: &str = env!("CARGO_PKG_NAME"); + +/// Initialize tracing subscriber, optionally with OpenTelemetry OTLP export. +/// +/// Bridges existing `log::*` calls from libraries into the tracing pipeline +/// via `tracing_log::LogTracer`. +/// +/// Configuration via environment variables: +/// - `OTEL_EXPORTER_OTLP_ENDPOINT`: OTLP endpoint. If unset, OTLP export is +/// disabled and only console output is produced (useful for local development). +/// - `RUST_LOG`: console log level filter +pub fn init_tracing() -> Result> { + tracing_log::LogTracer::init()?; + + let provider = build_provider()?; + global::set_tracer_provider(provider.clone()); + + // Suppress noisy internals at the OTel level; console verbosity is controlled by RUST_LOG + let otel_filter = EnvFilter::new("trace,h2=off,hyper=off,tower=off,teloxide=off,reqwest=off"); + let telemetry_layer = tracing_opentelemetry::layer() + .with_tracer(provider.tracer(SERVICE_NAME)) + .with_filter(otel_filter); + let fmt_layer = tracing_subscriber::fmt::layer() + .with_target(true) + .with_line_number(true) + .with_filter(EnvFilter::from_default_env()); + tracing_subscriber::registry() + .with(telemetry_layer) + .with(fmt_layer) + .try_init()?; + + tracing::info!(service_name = %SERVICE_NAME, "Tracing initialized"); + Ok(provider) +} + +fn build_provider() -> Result> { + let Some(endpoint) = std::env::var("OTEL_EXPORTER_OTLP_ENDPOINT").ok() else { + tracing::warn!("OTEL_EXPORTER_OTLP_ENDPOINT is not set — OTLP export disabled"); + return Ok(SdkTracerProvider::builder().build()); + }; + + let otlp_exporter = SpanExporter::builder() + .with_tonic() + .with_endpoint(endpoint) + .build()?; + let resource = Resource::builder() + .with_service_name(SERVICE_NAME.to_owned()) + .build(); + Ok(SdkTracerProvider::builder() + .with_batch_exporter(otlp_exporter) + .with_resource(resource) + .build()) +} \ No newline at end of file From 02e45f6220c38c07f41cc56edd4b38f5be32b1e7 Mon Sep 17 00:00:00 2001 From: Leonid Kozarin Date: Mon, 23 Mar 2026 05:04:19 +0300 Subject: [PATCH 2/2] Fix SetLoggerError: remove redundant LogTracer::init() call tracing_subscriber's try_init() already initializes the log bridge internally via its built-in tracing-log feature, making the explicit LogTracer::init() call a double-init that fails on startup. Co-Authored-By: Claude Sonnet 4.6 --- Cargo.lock | 1 - Cargo.toml | 1 - src/observability.rs | 4 +--- 3 files changed, 1 insertion(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b625618..131de9e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1800,7 +1800,6 @@ dependencies = [ "tonic-prost", "tonic-prost-build", "tracing", - "tracing-log", "tracing-opentelemetry", "tracing-subscriber", "urlencoding", diff --git a/Cargo.toml b/Cargo.toml index 51a2e29..bf57a02 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -20,7 +20,6 @@ log = "0.4.29" tracing = "0.1.44" tracing-subscriber = { version = "0.3.22", features = ["env-filter", "fmt", "json"] } tracing-opentelemetry = "0.32.1" -tracing-log = "0.2" opentelemetry = "0.31.0" opentelemetry_sdk = { version = "0.31.0", features = ["rt-tokio"] } opentelemetry-otlp = { version = "0.31.0", features = ["grpc-tonic"] } diff --git a/src/observability.rs b/src/observability.rs index a8cecaf..ff46d0b 100644 --- a/src/observability.rs +++ b/src/observability.rs @@ -10,15 +10,13 @@ const SERVICE_NAME: &str = env!("CARGO_PKG_NAME"); /// Initialize tracing subscriber, optionally with OpenTelemetry OTLP export. /// /// Bridges existing `log::*` calls from libraries into the tracing pipeline -/// via `tracing_log::LogTracer`. +/// via `tracing_subscriber`'s built-in `tracing-log` feature (called inside `try_init`). /// /// Configuration via environment variables: /// - `OTEL_EXPORTER_OTLP_ENDPOINT`: OTLP endpoint. If unset, OTLP export is /// disabled and only console output is produced (useful for local development). /// - `RUST_LOG`: console log level filter pub fn init_tracing() -> Result> { - tracing_log::LogTracer::init()?; - let provider = build_provider()?; global::set_tracer_provider(provider.clone());