diff --git a/Cargo.lock b/Cargo.lock index c7042e3aa8b417d317da6ed97b5f64666e03a9df..b3f708e138509e92d4f69a03a3a4e4f132c4260f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -617,7 +617,7 @@ dependencies = [ "memchr", "num", "regex", - "regex-syntax", + "regex-syntax 0.8.2", ] [[package]] @@ -634,7 +634,7 @@ dependencies = [ "memchr", "num", "regex", - "regex-syntax", + "regex-syntax 0.8.2", ] [[package]] @@ -2676,6 +2676,15 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7e88c3cbe8288f77f293e48a28b3232e3defd203a6d839fa7f68ea4329e83464" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matchit" version = "0.7.3" @@ -2883,6 +2892,16 @@ dependencies = [ "winapi", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num" version = "0.4.1" @@ -3097,6 +3116,12 @@ version = "0.5.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4030760ffd992bef45b0ae3f10ce1aba99e33464c90d14dd7c039884963ddc7a" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -3439,7 +3464,7 @@ dependencies = [ "rand", "rand_chacha", "rand_xorshift", - "regex-syntax", + "regex-syntax 0.8.2", "unarray", ] @@ -3734,8 +3759,17 @@ checksum = "380b951a9c5e80ddfd6136919eef32310721aa4aacd4889a8d39124b026ab343" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.3", + "regex-syntax 0.8.2", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -3746,9 +3780,15 @@ checksum = "5f804c7828047e88b2d32e2d7fe5a105da8ee3264f01902f796c8e067dc2483f" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.2", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.2" @@ -3942,7 +3982,6 @@ dependencies = [ "sentry-contexts", "sentry-core", "sentry-debug-images", - "sentry-log", "sentry-panic", "sentry-tower", "sentry-tracing", @@ -4011,16 +4050,6 @@ dependencies = [ "sentry-core", ] -[[package]] -name = "sentry-log" -version = "0.32.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e74b7261245ff17a8c48e8f3e1e96fb6b84146870121af880d53aef6a5b4f784" -dependencies = [ - "log", - "sentry-core", -] - [[package]] name = "sentry-panic" version = "0.32.3" @@ -4140,6 +4169,15 @@ dependencies = [ "digest", ] +[[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" @@ -4345,7 +4383,6 @@ dependencies = [ "cadence", "chrono", "clap", - "env_logger 0.11.5", "futures", "http-body", "itertools 0.11.0", @@ -4354,6 +4391,7 @@ dependencies = [ "prost 0.13.2", "prost-types 0.13.2", "sentry", + "sentry-tracing", "serde", "serde_derive", "serde_json", @@ -4365,6 +4403,8 @@ dependencies = [ "tonic-health", "tonic-middleware", "tonic-reflection", + "tracing", + "tracing-subscriber", ] [[package]] @@ -4912,13 +4952,33 @@ dependencies = [ "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-subscriber" version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", "tracing-core", + "tracing-log", ] [[package]] diff --git a/grpc-server/Cargo.toml b/grpc-server/Cargo.toml index 491bdb154eb89e3db5e731514ea1f750ebb3b094..ee4f8ed8d06ea540f457d3cd56886eb1092cadd0 100644 --- a/grpc-server/Cargo.toml +++ b/grpc-server/Cargo.toml @@ -19,9 +19,11 @@ java-properties = "1.4.1" cadence = "1.4.0" clap.workspace = true chrono = { version = "0.4.31", features = ["serde"] } -env_logger.workspace = true log.workspace = true -sentry = { version = "0.32.1", features = ["anyhow", "log", "tower"], optional = true } +sentry = { version = "0.32.1", features = ["anyhow", "tower", "tracing"], optional = true } +sentry-tracing = "0.32.1" +tracing = "0.1.40" +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } # gRPC prost = "0.13" diff --git a/grpc-server/README.md b/grpc-server/README.md index 4e9f688b09fd9dde29f5fd1703e8d3a70b0c4268..390bed9f7ef6dbe72955aadb3ebcd80992bc8be3 100644 --- a/grpc-server/README.md +++ b/grpc-server/README.md @@ -5,8 +5,9 @@ using a compressed in-memory representation ## Environment variables -`RUST_LOG` to set the log level, eg. `RUST_LOG=debug,h2=info`. -See the [env_logger](https://docs.rs/env_logger) documentation for details. +`RUST_LOG` to set the log level, eg. `RUST_LOG=debug,h2=info`. See the +[tracing_subscriber::filter::EnvFilter](https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html) +documentation for details. `SWH_SENTRY_DSN` and `SWH_SENTRY_ENVIRONMENT`: [Sentry](https://sentry.io/) configuration, see [Sentry Data Source Name](https://docs.sentry.io/concepts/key-terms/dsn-explainer/) and diff --git a/grpc-server/src/lib.rs b/grpc-server/src/lib.rs index 8bbdcd1d9a9246c43ee36d88c6b979da4c6f45ab..87083c6c6fab635c3b1a7c758e7940ff0da60f74 100644 --- a/grpc-server/src/lib.rs +++ b/grpc-server/src/lib.rs @@ -8,6 +8,7 @@ use std::io::Read; use std::path::Path; use std::pin::Pin; use std::str::FromStr; +use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::Arc; use std::task::{Context, Poll}; @@ -18,6 +19,7 @@ use tonic::body::BoxBody; use tonic::transport::{Body, Server}; use tonic::{Request, Response}; use tonic_middleware::{Middleware, MiddlewareFor, ServiceBound}; +use tracing::{instrument, span, Instrument, Level, Span}; use swh_graph::graph::SwhFullGraph; use swh_graph::properties::NodeIdFromSwhidError; @@ -129,55 +131,67 @@ impl<G: SwhFullGraph + Send + Sync + Clone + 'static> } type TraverseStream = ReceiverStream<Result<proto::Node, tonic::Status>>; + #[instrument(skip(self, request), err(level = Level::INFO))] async fn traverse( &self, request: Request<proto::TraversalRequest>, ) -> TonicResult<Self::TraverseStream> { + tracing::info!("{:?}", request.get_ref()); traversal::SimpleTraversal { service: self } .traverse(request) .await } + #[instrument(skip(self, request), err(level = Level::INFO))] async fn find_path_to( &self, request: Request<proto::FindPathToRequest>, ) -> TonicResult<proto::Path> { + tracing::info!("{:?}", request.get_ref()); find_path::FindPath { service: self } .find_path_to(request) .await } + #[instrument(skip(self, request), err(level = Level::INFO))] async fn find_path_between( &self, request: Request<proto::FindPathBetweenRequest>, ) -> TonicResult<proto::Path> { + tracing::info!("{:?}", request.get_ref()); find_path::FindPath { service: self } .find_path_between(request) .await } + #[instrument(skip(self, request), err(level = Level::INFO))] async fn count_nodes( &self, request: Request<proto::TraversalRequest>, ) -> TonicResult<proto::CountResponse> { + tracing::info!("{:?}", request.get_ref()); traversal::SimpleTraversal { service: self } .count_nodes(request) .await } + #[instrument(skip(self, request), err(level = Level::INFO))] async fn count_edges( &self, request: Request<proto::TraversalRequest>, ) -> TonicResult<proto::CountResponse> { + tracing::info!("{:?}", request.get_ref()); traversal::SimpleTraversal { service: self } .count_edges(request) .await } + #[instrument(skip(self, request))] async fn stats( &self, - _request: Request<proto::StatsRequest>, + request: Request<proto::StatsRequest>, ) -> TonicResult<proto::StatsResponse> { + tracing::info!("{:?}", request.get_ref()); // Load properties let properties_path = suffix_path(self.0.path(), ".properties"); let properties_path = properties_path.as_path(); @@ -334,12 +348,15 @@ pub async fn serve<G: SwhFullGraph + Sync + Send + 'static>( #[derive(Clone)] pub struct MetricsMiddleware { statsd_client: Arc<StatsdClient>, + /// Uniquely identifies the span associated with a request + request_id: Arc<AtomicU64>, } impl MetricsMiddleware { pub fn new(statsd_client: StatsdClient) -> Self { Self { statsd_client: Arc::new(statsd_client), + request_id: Arc::new(AtomicU64::new(0)), } } } @@ -357,21 +374,10 @@ where ) -> Result<tonic::codegen::http::Response<BoxBody>, S::Error> { let incoming_request_time = Instant::now(); let uri = req.uri().clone(); + let request_id = self.request_id.fetch_add(1, Ordering::Relaxed); + let span = span!(Level::INFO, "request", id = request_id,); - #[cfg(feature = "sentry")] - ::sentry::add_breadcrumb(::sentry::protocol::Breadcrumb { - ty: "http".into(), - category: Some("request".into()), - data: { - let mut map = ::sentry::protocol::Map::new(); - map.insert("method".into(), req.method().to_string().into()); - map.insert("path".into(), uri.path().into()); - map - }, - ..Default::default() - }); - - match service.call(req).await { + match service.call(req).instrument(span.clone()).await { Ok(resp) => { let status = resp.status(); let (parts, body) = resp.into_parts(); @@ -383,6 +389,7 @@ where incoming_request_time, start_streaming_time: Instant::now(), num_frames: 0, + span, }; let resp = tonic::codegen::http::Response::from_parts(parts, BoxBody::new(body)); Ok(resp) @@ -406,10 +413,14 @@ struct TimedBody<B: Body + Unpin> { incoming_request_time: Instant, start_streaming_time: Instant, num_frames: u64, + span: Span, } impl<B: Body + Unpin> TimedBody<B> { fn publish_metrics(&self) { + // runs the log statement within the same tracing span as the rest of the request + let _guard = self.span.enter(); + let end_streaming_time = Instant::now(); let response_duration = self.start_streaming_time - self.incoming_request_time; let streaming_duration = end_streaming_time - self.start_streaming_time; diff --git a/grpc-server/src/main.rs b/grpc-server/src/main.rs index 97e9520921bd4c5c0de677484550edc3e7cfc58b..a57683cafd6fe7be2d88ac12323a6acdfc958c7d 100644 --- a/grpc-server/src/main.rs +++ b/grpc-server/src/main.rs @@ -10,6 +10,9 @@ use std::fs::File; use std::io::{BufRead, BufReader}; use std::path::PathBuf; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; + use swh_graph::graph::*; use swh_graph::views::Subgraph; @@ -31,15 +34,24 @@ struct Args { pub fn main() -> Result<()> { let args = Args::parse(); - let logger = - env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info")).build(); - let max_level = logger.filter(); + let fmt_layer = tracing_subscriber::fmt::layer(); + let filter_layer = tracing_subscriber::EnvFilter::try_from_default_env() + .or_else(|_| tracing_subscriber::EnvFilter::try_new("info")) + .unwrap(); + + let logger = tracing_subscriber::registry(); + + #[cfg(feature = "sentry")] + let (_guard, sentry_layer) = swh_graph_grpc_server::sentry::setup(); #[cfg(feature = "sentry")] - let (_guard, logger) = swh_graph_grpc_server::sentry::setup(Box::new(logger)); - log::set_boxed_logger(Box::new(logger)).context("Could not setup logger")?; + let logger = logger.with(sentry_layer); - log::set_max_level(max_level); + logger + .with(filter_layer) + .with(fmt_layer) + .try_init() + .context("Could not initialize logging")?; let statsd_client = swh_graph_grpc_server::statsd::statsd_client(args.statsd_host)?; diff --git a/grpc-server/src/sentry.rs b/grpc-server/src/sentry.rs index 7bf8749d123173ef61e6356ba125d7ddefe0c826..d712b111169679ce650f3a536f418d7a6e573ec9 100644 --- a/grpc-server/src/sentry.rs +++ b/grpc-server/src/sentry.rs @@ -6,8 +6,9 @@ use std::env::VarError; use anyhow::Result; -use sentry::integrations::log::LogFilter; use sentry::ClientInitGuard; +use sentry_tracing::EventFilter; +use tracing::{Level, Subscriber}; /// Parses an environment variable as a boolean, like `swh.core.sentry.override_with_bool_envvar` fn parse_bool_env_var(var_name: &'static str, default: bool) -> bool { @@ -35,7 +36,10 @@ fn _parse_bool_env_var( } } -pub fn setup(logger: Box<dyn log::Log>) -> (Result<ClientInitGuard, VarError>, Box<dyn log::Log>) { +pub fn setup<S: Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>>() -> ( + Result<ClientInitGuard, VarError>, + impl tracing_subscriber::layer::Layer<S>, +) { let guard = std::env::var("SWH_SENTRY_DSN").map(|sentry_dsn| { sentry::init(( sentry_dsn, @@ -51,16 +55,16 @@ pub fn setup(logger: Box<dyn log::Log>) -> (Result<ClientInitGuard, VarError>, B log::error!("Could not initialize Sentry: {e}"); } - let mut logger = sentry::integrations::log::SentryLogger::with_dest(logger); + let mut sentry_layer = sentry_tracing::layer(); if parse_bool_env_var("SWH_SENTRY_DISABLE_LOGGING_EVENTS", false) { - logger = logger.filter(|md| match md.level() { - log::Level::Error => LogFilter::Breadcrumb, // replaces the default (LogFilter::Exception) - log::Level::Warn | log::Level::Info => LogFilter::Breadcrumb, - log::Level::Debug | log::Level::Trace => LogFilter::Ignore, + sentry_layer = sentry_layer.event_filter(|md| match *md.level() { + Level::ERROR => EventFilter::Breadcrumb, // replaces the default (LogFilter::Exception) + Level::WARN | Level::INFO => EventFilter::Breadcrumb, + Level::DEBUG | Level::TRACE => EventFilter::Ignore, }); } - (guard, Box::new(logger)) + (guard, sentry_layer) } #[test]