Replace env_logger with tracing (#2381)

* Replace `env_logger` with `tracing`/`tracing-subscriber`/`tracing-log`

TODO:
- Implement slog drain that would *properly* convert slog records into tracing events
  (`slog-stdlog` is fine for now, though)

* fixup! Replace `env_logger` with `tracing`/`tracing-subscriber`/`tracing-log`

Fix `consensus` test

* fixup! fixup! Replace `env_logger` with `tracing`/`tracing-subscriber`/`tracing-log`

Forget to `unwrap` the result 🙈

* fixup! fixup! Replace `env_logger` with `tracing`/`tracing-subscriber`/`tracing-log`

`tracing_subscriber::fmt::init` initializes `tracing_log::LogTracer`
automatically with default `tracing-subscriber` features enabled 💁‍♀️

* Update `DEVELOPMENT.md` documentation regarding `tracing`

* Update default log level for development to make it less noisy

---------

Co-authored-by: timvisee <tim@visee.me>

Author: 2 people

Cargo.lock

@@ -20,26 +20,15 @@ multiling-japanese = ["segment/multiling-japanese"]
 multiling-korean = ["segment/multiling-korean"]
 service_debug = ["parking_lot", "parking_lot/deadlock_detection"]
 tracing = [
-    "dep:tracing",
     "api/tracing",
     "collection/tracing",
     "segment/tracing",
     "storage/tracing",
 ]
-tracing-log = ["tracing/log"]
-tracing-log-always = ["tracing/log-always"]
-tracing-logger = [
-    "tracing",
-    "tracing-subscriber/ansi",
-    "tracing-subscriber/env-filter",
-    "tracing-subscriber/fmt",
-    "tracing-subscriber/tracing-log",
-    "dep:tracing-log",
-]
 console = ["console-subscriber"]
-console-subscriber = ["tracing", "tracing-subscriber", "dep:console-subscriber"]
+console-subscriber = ["tracing", "dep:console-subscriber"]
 tracy = ["tracing-tracy"]
-tracing-tracy = ["tracing", "tracing-subscriber", "dep:tracing-tracy"]
+tracing-tracy = ["tracing", "dep:tracing-tracy"]
 tokio-tracing = ["tokio/tracing"]
 
 [dev-dependencies]
@@ -57,7 +46,6 @@ parking_lot = { version = "0.12.1", features=["deadlock_detection"], optional =
 num_cpus = "1.16"
 thiserror = "1.0"
 log = "0.4"
-env_logger = "0.10.0"
 atty = "0.2"
 colored = "2"
 serde = { version = "~1.0", features = ["derive"] }
@@ -108,9 +96,9 @@ actix-multipart = "0.6.0"
 constant_time_eq = "0.3.0"
 
 # Profiling
-tracing = { version = "0.1", features = ["async-await"], optional = true }
-tracing-subscriber = { version = "0.3", default-features = false, features = ["registry", "std"], optional = true }
-tracing-log = { version = "0.1", default-features = false, features = ["log-tracer", "std"], optional = true }
+tracing = { version = "0.1", features = ["async-await"] }
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
+tracing-log = { version = "0.1", default-features = false, features = ["log-tracer", "std"] }
 console-subscriber = { version = "0.1", default-features = false, features = ["parking_lot"], optional = true }
 tracing-tracy = { version = "0.10.2", features = ["ondemand"], optional = true }
 

Cargo.toml

@@ -1,5 +1,5 @@
 debug: true
-log_level: DEBUG
+log_level: DEBUG,hyper=INFO,h2=INFO,tower=INFO,rustls=INFO,raft=INFO
 
 service:
   host: 127.0.0.1

config/development.yaml

@@ -140,17 +140,7 @@ Use [pprof](https://github.com/google/pprof) and the following command to genera
 Qdrant have basic [`tracing`] support with [`Tracy`] profiler and [`tokio-console`] integrations
 that can be enabled with optional features.
 
-- `tracing-log` and `tracing-log-always` features enable [`tracing/log` and `tracing/log-always`][tracing-log-features]
-  features of the `tracing` crate, which cause `tracing` crate to produce logs with the `log` crate
-  - if `tracing-log` feature enabled, the logs would only be produced if no other tracing subscriber is enabled
-    (e.g., if neither `tracy`, nor `console` feature is enabled)
-  - if `tracing-log-always` feature is enabled, the logs would _always_ be produced
-  - useful for "quick and dirty" `tracing`-enabled debugging, that does not require any additional setup
-- `tracing-logger` feature replaces default logger with an alternative "tracing-compatible" logger,
-  that also prints [tracing span] information for `tracing` logs (which is _super-useful_ in times)
-  - note, that `tracing-logger` only reads "filters" from default `RUST_LOG` env-var currently
-  - note, that if both `tracing-log-always` and `tracing-logger` features are enabled it will cause some logs
-    to be printed twice
+- [`tracing`] is an _optional_ dependency that can be enabled with `tracing` feature
 - `tracy` feature enables [`Tracy`] profiler integration
 - `console` feature enables [`tokio-console`] integration
   - note, that you'll also have to [pass `--cfg tokio_unstable` arguments to `rustc`][tokio-tracing] to enable this feature
@@ -162,15 +152,16 @@ that can be enabled with optional features.
   - note, that you'll also have to [pass `--cfg tokio_unstable` arguments to `rustc`][tokio-tracing] to enable this feature
   - this is required (and enabled automatically) by the `console` feature
   - but you can enable it explicitly with the `tracy` feature, to see Tokio traces in [`Tracy`] profiler
-- `tracing` feature simply enables optional [`tracing`] crate dependency (without any integrations)
-  - this is required (and enabled automatically) by all of the above features
 
 Qdrant code is **not** instrumented by default, so you'll have to manually add `#[tracing::instrument]` attributes
 on functions and methods that you want to profile.
 
+Qdrant uses [`tracing-log`] as the [`log`] backend, so `log` and `log-always` features of the [`tracing`] crate
+[should _not_ be enabled][tracing-log-warning]!
+
 ```rust
-// `tracing` crate is an *optional* dependency, so if you want the code to compile when `tracing`
-// feature is disabled, you have to use `#[cfg_attr(...)]`...
+// `tracing` crate is an *optional* dependency in `lib/*` crates, so if you want the code to compile
+// when `tracing` feature is disabled, you have to use `#[cfg_attr(...)]`...
 //
 // See https://doc.rust-lang.org/reference/conditional-compilation.html#the-cfg_attr-attribute
 #[cfg_attr(feature = "tracing", tracing::instrument)]
@@ -187,12 +178,13 @@ fn some_other_function() {
 }
 ```
 
-[tracing-log-features]: https://docs.rs/tracing/latest/tracing/#emitting-log-records
-[tracing span]: https://docs.rs/tracing/latest/tracing/index.html#spans
 [`tracing`]: https://docs.rs/tracing/latest/tracing/
 [`Tracy`]: https://github.com/wolfpld/tracy
 [`tokio-console`]: https://docs.rs/tokio-console/latest/tokio_console/
 [tokio-tracing]: https://docs.rs/tokio/latest/tokio/#unstable-features
+[`tracing-log`]: https://docs.rs/tracing-log/latest/tracing_log/
+[`log`]: https://docs.rs/log/latest/log/
+[tracing-log-warning]: https://docs.rs/tracing-log/latest/tracing_log/#caution-mixing-both-conversions
 
 ## API changes
 

docs/DEVELOPMENT.md

@@ -1139,7 +1139,7 @@ mod tests {
         let mut settings = crate::Settings::new(None).expect("Can't read config.");
         settings.storage.storage_path = storage_dir.path().to_str().unwrap().to_string();
         std::env::set_var("RUST_LOG", log::Level::Debug.as_str());
-        env_logger::init();
+        tracing_subscriber::fmt::init();
         let search_runtime =
             crate::create_search_runtime(settings.storage.performance.max_search_threads)
                 .expect("Can't create search runtime.");

src/consensus.rs

@@ -43,7 +43,7 @@ use crate::greeting::welcome;
 use crate::migrations::single_to_cluster::handle_existing_collections;
 use crate::settings::Settings;
 use crate::snapshots::{recover_full_snapshot, recover_snapshots};
-use crate::startup::{remove_started_file_indicator, setup_logger, touch_started_file_indicator};
+use crate::startup::{remove_started_file_indicator, touch_started_file_indicator};
 
 #[cfg(not(target_env = "msvc"))]
 #[global_allocator]
@@ -116,11 +116,7 @@ fn main() -> anyhow::Result<()> {
 
     let reporting_id = TelemetryCollector::generate_id();
 
-    if cfg!(feature = "tracing-logger") {
-        tracing::setup(&settings.log_level)?;
-    } else {
-        setup_logger(&settings.log_level);
-    }
+    tracing::setup(&settings.log_level)?;
 
     setup_panic_hook(reporting_enabled, reporting_id.to_string());
 

src/main.rs

@@ -4,8 +4,6 @@ use std::backtrace::Backtrace;
 use std::panic;
 use std::path::PathBuf;
 
-use log::LevelFilter;
-
 use crate::common::error_reporting::ErrorReporter;
 
 const DEFAULT_INITIALIZED_FILE: &str = ".qdrant-initialized";
@@ -16,30 +14,6 @@ fn get_init_file_path() -> PathBuf {
         .unwrap_or_else(|_| DEFAULT_INITIALIZED_FILE.into())
 }
 
-pub fn setup_logger(log_level: &str) {
-    let is_info = log_level.to_ascii_uppercase() == "INFO";
-    let mut log_builder = env_logger::Builder::new();
-
-    log_builder
-        // Timestamp in millis
-        .format_timestamp_millis()
-        // Parse user defined log level configuration
-        .parse_filters(log_level)
-        // h2 is very verbose and we have many network operations,
-        // so it is limited to only errors
-        .filter_module("h2", LevelFilter::Error)
-        .filter_module("tower", LevelFilter::Warn);
-
-    if is_info {
-        // Additionally filter verbose modules if no extended logging configuration is provided
-        log_builder
-            .filter_module("wal", LevelFilter::Warn)
-            .filter_module("raft::raft", LevelFilter::Warn);
-    };
-
-    log_builder.init();
-}
-
 pub fn setup_panic_hook(reporting_enabled: bool, reporting_id: String) {
     panic::set_hook(Box::new(move |panic_info| {
         let backtrace = Backtrace::force_capture().to_string();

src/startup.rs

@@ -1,55 +1,40 @@
-#[cfg_attr(not(feature = "tracing-logger"), allow(unused_variables))]
-pub fn setup(log_level: &str) -> anyhow::Result<()> {
-    // Use `console` and/or `tracy` features to enable both `tracing-subscriber` and the layer(s)
-    #[cfg(feature = "tracing-subscriber")]
-    {
-        use tracing_subscriber::prelude::*;
-
-        let reg = tracing_subscriber::registry();
-
-        // Use `console` feature to enable both `tracing-subscriber` and `console-subscriber`
-        #[cfg(feature = "console-subscriber")]
-        let reg = reg.with(console_subscriber::spawn());
-
-        // Note, that `console-subscriber` requires manually enabling
-        // `--cfg tokio_unstable` rust flags during compilation!
-        //
-        // Otherwise `console_subscriber::spawn` call panics!
-        //
-        // See https://docs.rs/tokio/latest/tokio/#unstable-features
-        #[cfg(all(feature = "console-subscriber", not(tokio_unstable)))]
-        eprintln!(
-            "`console-subscriber` requires manually enabling \
-             `--cfg tokio_unstable` rust flags during compilation!"
-        );
-
-        // Use `tracy` feature to enable both `tracing-subscriber` and `tracing-tracy`
-        #[cfg(feature = "tracing-tracy")]
-        let reg = reg.with(tracing_tracy::TracyLayer::new().with_filter(
-            tracing_subscriber::filter::filter_fn(|metadata| metadata.is_span()),
-        ));
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::{filter, fmt};
 
-        #[cfg(all(feature = "tracing-log-always", feature = "tracing-logger"))]
-        eprintln!(
-            "Both `tracing-log-always` and `tracing-logger` features are enabled at the same time. \
-             This will cause some logs to be printed twice!"
-        );
-
-        #[cfg(feature = "tracing-logger")]
-        let reg = reg.with(
-            tracing_subscriber::fmt::layer()
-                .with_ansi(true)
-                .with_span_events(tracing_subscriber::fmt::format::FmtSpan::NEW)
-                .with_filter(
-                    tracing_subscriber::filter::EnvFilter::builder().parse_lossy(log_level),
-                ),
-        );
-
-        #[cfg(feature = "tracing-logger")]
-        tracing_log::LogTracer::init()?;
-
-        tracing::subscriber::set_global_default(reg)?;
-    }
+pub fn setup(log_level: &str) -> anyhow::Result<()> {
+    tracing_log::LogTracer::init()?;
+
+    let reg = tracing_subscriber::registry().with(
+        fmt::layer()
+            .with_ansi(true)
+            .with_span_events(fmt::format::FmtSpan::NEW)
+            .with_filter(filter::EnvFilter::builder().parse_lossy(log_level)),
+    );
+
+    // Use `console` or `console-subscriber` feature to enable `console-subscriber`
+    //
+    // Note, that `console-subscriber` requires manually enabling
+    // `--cfg tokio_unstable` rust flags during compilation!
+    //
+    // Otherwise `console_subscriber::spawn` call panics!
+    //
+    // See https://docs.rs/tokio/latest/tokio/#unstable-features
+    #[cfg(all(feature = "console-subscriber", tokio_unstable))]
+    let reg = reg.with(console_subscriber::spawn());
+
+    #[cfg(all(feature = "console-subscriber", not(tokio_unstable)))]
+    eprintln!(
+        "`console-subscriber` requires manually enabling \
+         `--cfg tokio_unstable` rust flags during compilation!"
+    );
+
+    // Use `tracy` or `tracing-tracy` feature to enable `tracing-tracy`
+    #[cfg(feature = "tracing-tracy")]
+    let reg = reg.with(tracing_tracy::TracyLayer::new().with_filter(
+        tracing_subscriber::filter::filter_fn(|metadata| metadata.is_span()),
+    ));
+
+    tracing::subscriber::set_global_default(reg)?;
 
     Ok(())
 }