Skip to content

Commit

Permalink
Replace env_logger with tracing (#2381)
Browse files Browse the repository at this point in the history
* 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 <[email protected]>
  • Loading branch information
2 people authored and generall committed Aug 15, 2023
1 parent 98e6f44 commit 7a85ac3
Show file tree
Hide file tree
Showing 8 changed files with 54 additions and 120 deletions.
1 change: 0 additions & 1 deletion Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

22 changes: 5 additions & 17 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand All @@ -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"] }
Expand Down Expand Up @@ -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 }

Expand Down
2 changes: 1 addition & 1 deletion config/development.yaml
Original file line number Diff line number Diff line change
@@ -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
Expand Down
26 changes: 9 additions & 17 deletions docs/DEVELOPMENT.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)]
Expand All @@ -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
Expand Down
2 changes: 1 addition & 1 deletion src/consensus.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.");
Expand Down
8 changes: 2 additions & 6 deletions src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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());

Expand Down
26 changes: 0 additions & 26 deletions src/startup.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand All @@ -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();
Expand Down
87 changes: 36 additions & 51 deletions src/tracing.rs
Original file line number Diff line number Diff line change
@@ -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(())
}

0 comments on commit 7a85ac3

Please sign in to comment.