From 5a50a57e479d6afd2717f94528357b17fcca243f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karol=20Bary=C5=82a?= Date: Thu, 2 May 2024 17:20:42 +0200 Subject: [PATCH 1/3] Remove `.with_current_subscriber()` calls Those calls were introduced in e5570956758503a8f0a7ed0ad1c649909f370a73, with message: ``` Now, when the driver spawns a task to run a new future on it, that future will use the same subscriber as the code that spawned the task in the first place. ``` There is unfortunately no explanation about when it is necessary. I don't see any problems after removing those - logs are still collected correctly using a tracing subscriber. Those calls however have a harmful side-effect: they prevent usage of `log` loggers to listen to driver logs using `log` feature in `tracing` crate. After reporting the problem to `tracing` crate: https://github.com/tokio-rs/tracing/issues/2913 one of maintainers said that using `.with_current_subscriber()` in a library is not necessary in general. As I don't see any issue caused by removing these calls, but their existence cause an issue, they are removed in this commit. --- scylla-proxy/examples/cmdline.rs | 3 +-- scylla-proxy/examples/identity_proxy.rs | 3 +-- .../examples/identity_shard_aware_proxy.rs | 3 +-- scylla/src/transport/cluster.rs | 5 ++--- scylla/src/transport/connection.rs | 5 ++--- scylla/src/transport/connection_pool.rs | 20 ++++++++----------- scylla/src/transport/iterator.rs | 3 +-- .../src/transport/load_balancing/default.rs | 4 ++-- scylla/tests/integration/utils.rs | 3 +-- 9 files changed, 19 insertions(+), 30 deletions(-) diff --git a/scylla-proxy/examples/cmdline.rs b/scylla-proxy/examples/cmdline.rs index 9ac8fd4c9b..193e3e2a6a 100644 --- a/scylla-proxy/examples/cmdline.rs +++ b/scylla-proxy/examples/cmdline.rs @@ -13,7 +13,6 @@ use std::{ }; use scylla_proxy::{Node, Proxy, ShardAwareness}; -use tracing::instrument::WithSubscriber; fn init_logger() { tracing_subscriber::fmt::fmt() @@ -53,7 +52,7 @@ async fn main() { None, None, )]); - let running_proxy = proxy.run().with_current_subscriber().await.unwrap(); + let running_proxy = proxy.run().await.unwrap(); pause().await; running_proxy.finish().await.unwrap(); diff --git a/scylla-proxy/examples/identity_proxy.rs b/scylla-proxy/examples/identity_proxy.rs index 33b6ea746e..7460e04c11 100644 --- a/scylla-proxy/examples/identity_proxy.rs +++ b/scylla-proxy/examples/identity_proxy.rs @@ -1,7 +1,6 @@ use std::{net::SocketAddr, str::FromStr}; use scylla_proxy::{Node, Proxy, ShardAwareness}; -use tracing::instrument::WithSubscriber; fn init_logger() { tracing_subscriber::fmt::fmt() @@ -30,7 +29,7 @@ async fn main() { .build(), ) .build(); - let running_proxy = proxy.run().with_current_subscriber().await.unwrap(); + let running_proxy = proxy.run().await.unwrap(); pause().await; running_proxy.finish().await.unwrap(); diff --git a/scylla-proxy/examples/identity_shard_aware_proxy.rs b/scylla-proxy/examples/identity_shard_aware_proxy.rs index 6f94ad214a..b94126e0ff 100644 --- a/scylla-proxy/examples/identity_shard_aware_proxy.rs +++ b/scylla-proxy/examples/identity_shard_aware_proxy.rs @@ -1,7 +1,6 @@ use std::{net::SocketAddr, str::FromStr}; use scylla_proxy::{Node, Proxy, ShardAwareness}; -use tracing::instrument::WithSubscriber; fn init_logger() { tracing_subscriber::fmt::fmt() @@ -27,7 +26,7 @@ async fn main() { None, None, )]); - let running_proxy = proxy.run().with_current_subscriber().await.unwrap(); + let running_proxy = proxy.run().await.unwrap(); pause().await; running_proxy.finish().await.unwrap(); diff --git a/scylla/src/transport/cluster.rs b/scylla/src/transport/cluster.rs index 2f576f33ea..29d9505e6b 100644 --- a/scylla/src/transport/cluster.rs +++ b/scylla/src/transport/cluster.rs @@ -24,7 +24,6 @@ use std::collections::{HashMap, HashSet}; use std::net::SocketAddr; use std::sync::Arc; use std::time::Duration; -use tracing::instrument::WithSubscriber; use tracing::{debug, warn}; use uuid::Uuid; @@ -206,7 +205,7 @@ impl Cluster { }; let (fut, worker_handle) = worker.work().remote_handle(); - tokio::spawn(fut.with_current_subscriber()); + tokio::spawn(fut); let result = Cluster { data: cluster_data, @@ -647,7 +646,7 @@ impl ClusterWorker { let cluster_data = self.cluster_data.load_full(); let use_keyspace_future = Self::handle_use_keyspace_request(cluster_data, request); - tokio::spawn(use_keyspace_future.with_current_subscriber()); + tokio::spawn(use_keyspace_future); }, None => return, // If use_keyspace_channel was closed then cluster was dropped, we can stop working } diff --git a/scylla/src/transport/connection.rs b/scylla/src/transport/connection.rs index c3f91ec6b4..d34824f97e 100644 --- a/scylla/src/transport/connection.rs +++ b/scylla/src/transport/connection.rs @@ -13,7 +13,6 @@ use tokio::io::{split, AsyncRead, AsyncWrite, AsyncWriteExt, BufReader, BufWrite use tokio::net::{TcpSocket, TcpStream}; use tokio::sync::{mpsc, oneshot}; use tokio::time::Instant; -use tracing::instrument::WithSubscriber; use tracing::{debug, error, trace, warn}; use uuid::Uuid; @@ -1090,7 +1089,7 @@ impl Connection { node_address, ) .remote_handle(); - tokio::task::spawn(task.with_current_subscriber()); + tokio::task::spawn(task); return Ok(handle); } @@ -1104,7 +1103,7 @@ impl Connection { node_address, ) .remote_handle(); - tokio::task::spawn(task.with_current_subscriber()); + tokio::task::spawn(task); Ok(handle) } diff --git a/scylla/src/transport/connection_pool.rs b/scylla/src/transport/connection_pool.rs index 84632a4078..bfad1de256 100644 --- a/scylla/src/transport/connection_pool.rs +++ b/scylla/src/transport/connection_pool.rs @@ -27,7 +27,6 @@ use std::sync::{Arc, RwLock, Weak}; use std::time::Duration; use tokio::sync::{broadcast, mpsc, Notify}; -use tracing::instrument::WithSubscriber; use tracing::{debug, error, trace, warn}; /// The target size of a per-node connection pool. @@ -212,7 +211,7 @@ impl NodeConnectionPool { let conns = refiller.get_shared_connections(); let (fut, refiller_handle) = refiller.run(use_keyspace_request_receiver).remote_handle(); - tokio::spawn(fut.with_current_subscriber()); + tokio::spawn(fut); Self { conns, @@ -1138,17 +1137,14 @@ impl PoolRefiller { Err(QueryError::IoError(io_error.unwrap())) }; - tokio::task::spawn( - async move { - let res = fut.await; - match &res { - Ok(()) => debug!("[{}] Successfully changed current keyspace", address), - Err(err) => warn!("[{}] Failed to change keyspace: {:?}", address, err), - } - let _ = response_sender.send(res); + tokio::task::spawn(async move { + let res = fut.await; + match &res { + Ok(()) => debug!("[{}] Successfully changed current keyspace", address), + Err(err) => warn!("[{}] Failed to change keyspace: {:?}", address, err), } - .with_current_subscriber(), - ); + let _ = response_sender.send(res); + }); } // Requires the keyspace to be set diff --git a/scylla/src/transport/iterator.rs b/scylla/src/transport/iterator.rs index 1167d6bdbb..6c340b3453 100644 --- a/scylla/src/transport/iterator.rs +++ b/scylla/src/transport/iterator.rs @@ -16,7 +16,6 @@ use scylla_cql::types::serialize::row::SerializedValues; use std::result::Result; use thiserror::Error; use tokio::sync::mpsc; -use tracing::instrument::WithSubscriber; use super::errors::QueryError; use super::execution_profile::ExecutionProfileInner; @@ -387,7 +386,7 @@ impl RowIterator { worker_task: impl Future + Send + 'static, mut receiver: mpsc::Receiver>, ) -> Result { - tokio::task::spawn(worker_task.with_current_subscriber()); + tokio::task::spawn(worker_task); // This unwrap is safe because: // - The future returned by worker.work sends at least one item diff --git a/scylla/src/transport/load_balancing/default.rs b/scylla/src/transport/load_balancing/default.rs index fe058a50e2..4280c855fa 100644 --- a/scylla/src/transport/load_balancing/default.rs +++ b/scylla/src/transport/load_balancing/default.rs @@ -2269,7 +2269,7 @@ mod latency_awareness { use itertools::Either; use scylla_cql::errors::{DbError, QueryError}; use tokio::time::{Duration, Instant}; - use tracing::{instrument::WithSubscriber, trace, warn}; + use tracing::{trace, warn}; use uuid::Uuid; use crate::{load_balancing::NodeRef, routing::Shard, transport::node::Node}; @@ -2454,7 +2454,7 @@ mod latency_awareness { } } .remote_handle(); - tokio::task::spawn(updater_fut.with_current_subscriber()); + tokio::task::spawn(updater_fut); Self { _updater_handle: Some(updater_handle), diff --git a/scylla/tests/integration/utils.rs b/scylla/tests/integration/utils.rs index 7839d772f3..4d5b10f7a4 100644 --- a/scylla/tests/integration/utils.rs +++ b/scylla/tests/integration/utils.rs @@ -3,7 +3,6 @@ use std::collections::HashMap; use std::env; use std::net::SocketAddr; use std::str::FromStr; -use tracing::instrument::WithSubscriber; use scylla_proxy::{Node, Proxy, ProxyError, RunningProxy, ShardAwareness}; @@ -53,7 +52,7 @@ where ); let translation_map = proxy.translation_map(); - let running_proxy = proxy.run().with_current_subscriber().await.unwrap(); + let running_proxy = proxy.run().await.unwrap(); let running_proxy = test( [proxy1_uri, proxy2_uri, proxy3_uri], From 01afc375409b23e0e9f62ea755b870561cfbccd7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karol=20Bary=C5=82a?= Date: Tue, 14 May 2024 11:58:45 +0200 Subject: [PATCH 2/3] Examples: add logging_log example This example demonstrates usage of `env_logger` to listen to driver logs. --- Cargo.lock.msrv | 31 +++++++++++++++++++++++++++++++ examples/Cargo.toml | 7 ++++++- examples/logging_log.rs | 27 +++++++++++++++++++++++++++ 3 files changed, 64 insertions(+), 1 deletion(-) create mode 100644 examples/logging_log.rs diff --git a/Cargo.lock.msrv b/Cargo.lock.msrv index 079fe63ef3..776cc09f56 100644 --- a/Cargo.lock.msrv +++ b/Cargo.lock.msrv @@ -457,6 +457,19 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c34f04666d835ff5d62e058c3995147c06f42fe86ff053337632bca83e42702d" +[[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.1" @@ -501,6 +514,7 @@ dependencies = [ "anyhow", "chrono", "clap", + "env_logger", "futures", "openssl", "rand", @@ -712,6 +726,12 @@ version = "0.6.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "12cb882ccb290b8646e554b157ab0b71e64e8d5bef775cd66b6531e52d302669" +[[package]] +name = "humantime" +version = "2.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" + [[package]] name = "iana-time-zone" version = "0.1.57" @@ -771,6 +791,17 @@ dependencies = [ "hashbrown 0.14.0", ] +[[package]] +name = "is-terminal" +version = "0.4.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f23ff5ef2b80d608d61efee834934d862cd92461afc0560dedf493e4c033738b" +dependencies = [ + "hermit-abi 0.3.2", + "libc", + "windows-sys 0.52.0", +] + [[package]] name = "itertools" version = "0.10.5" diff --git a/examples/Cargo.toml b/examples/Cargo.toml index 15e8f02074..edd817293d 100644 --- a/examples/Cargo.toml +++ b/examples/Cargo.toml @@ -12,7 +12,7 @@ rustyline = "9" rustyline-derive = "0.6" scylla = {path = "../scylla", features = ["ssl", "cloud", "chrono", "time", "num-bigint-03", "num-bigint-04", "bigdecimal-04"]} tokio = {version = "1.1.0", features = ["full"]} -tracing = "0.1.25" +tracing = { version = "0.1.25" , features = ["log"] } tracing-subscriber = { version = "0.3.14", features = ["env-filter"] } chrono = { version = "0.4", default-features = false } time = { version = "0.3.22" } @@ -21,6 +21,7 @@ tower = "0.4" stats_alloc = "0.1" clap = { version = "3.2.4", features = ["derive"] } rand = "0.8.5" +env_logger = "0.10" [[example]] name = "auth" @@ -34,6 +35,10 @@ path = "basic.rs" name = "logging" path = "logging.rs" +[[example]] +name = "logging_log" +path = "logging_log.rs" + [[example]] name = "tls" path = "tls.rs" diff --git a/examples/logging_log.rs b/examples/logging_log.rs new file mode 100644 index 0000000000..33a2b794c8 --- /dev/null +++ b/examples/logging_log.rs @@ -0,0 +1,27 @@ +use anyhow::Result; +use scylla::transport::session::Session; +use scylla::SessionBuilder; +use std::env; +use tracing::info; + +// To run this example, and view logged messages, RUST_LOG env var needs to be set +// This can be done using shell command presented below +// RUST_LOG=info cargo run --example logging_log +#[tokio::main] +async fn main() -> Result<()> { + // Driver uses `tracing` for logging purposes, but it's possible to use `log` + // ecosystem to view the messages. This requires adding `tracing` crate to + // dependencies and enabling its "log" feature. Then you will be able to use + // loggers like `env_logger` to see driver's messages. + env_logger::init(); + + let uri = env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string()); + info!("Connecting to {}", uri); + + let session: Session = SessionBuilder::new().known_node(uri).build().await?; + session.query("CREATE KEYSPACE IF NOT EXISTS examples_ks WITH REPLICATION = {'class' : 'NetworkTopologyStrategy', 'replication_factor' : 1}", &[]).await?; + + session.query("USE examples_ks", &[]).await?; + + Ok(()) +} From 370b00a9fda4f76149be02ffc006961928752960 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karol=20Bary=C5=82a?= Date: Thu, 2 May 2024 17:21:39 +0200 Subject: [PATCH 3/3] Docs: Info about logging with `log` ecosystem. --- docs/source/logging/logging.md | 52 ++++++++++++++++++++++++++++++++-- 1 file changed, 49 insertions(+), 3 deletions(-) diff --git a/docs/source/logging/logging.md b/docs/source/logging/logging.md index 198b3291f4..c99d1b1e0f 100644 --- a/docs/source/logging/logging.md +++ b/docs/source/logging/logging.md @@ -1,9 +1,15 @@ # Logging The driver uses the [tracing](https://github.com/tokio-rs/tracing) crate for all logs.\ -To view the logs you have to create a `tracing` subscriber to which all logs will be written. +There are two ways to view the logs: +- Create a `tracing` subscriber to which all logs will be written (recommended). +- Enable `log` feature on `tracing` crate and use some logger from `log` ecosystem. \ +Only do this if you can't use `tracing` subscriber for some reason. + +## Using tracing subscriber + +To print the logs you can use the default subscriber: -To just print the logs you can use the default subscriber: ```rust # extern crate scylla; # extern crate tokio; @@ -45,4 +51,44 @@ To start this example execute: RUST_LOG=info cargo run ``` -The full [example](https://github.com/scylladb/scylla-rust-driver/tree/main/examples/logging.rs) is available in the `examples` folder \ No newline at end of file +The full [example](https://github.com/scylladb/scylla-rust-driver/tree/main/examples/logging.rs) is available in the `examples` folder. +You can run it from main folder of driver repository using `RUST_LOG=trace SCYLLA_URI=:9042 cargo run --example logging`. + +## Using log + +To collect tracing events using log collector you first need to enable `log` feature on `tracing` crate. +You can use `cargo add tracing -F log` or edit `Cargo.toml`: +```toml +tracing = { version = "0.1.40" , features = ["log"] } +``` +then you can setup `env_logger` os some other logger and it will output logs from the driver: + +```rust +# extern crate scylla; +# extern crate tokio; +# extern crate tracing; +# extern crate env_logger; +# use std::error::Error; +# use scylla::{Session, SessionBuilder}; +use tracing::info; + +#[tokio::main] +async fn main() -> Result<(), Box> { + // Setup `log` collector that uses RUST_LOG env variable to configure + // verbosity. + env_logger::init(); + + let uri = std::env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string()); + info!("Connecting to {}", uri); + + let session: Session = SessionBuilder::new().known_node(uri).build().await?; + session.query("CREATE KEYSPACE IF NOT EXISTS examples_ks WITH REPLICATION = {'class' : 'NetworkTopologyStrategy', 'replication_factor' : 1}", &[]).await?; + + session.query("USE examples_ks", &[]).await?; + + Ok(()) +} +``` + +The full [example](https://github.com/scylladb/scylla-rust-driver/tree/main/examples/logging_log.rs) is available in the `examples` folder. +You can run it from main folder of driver repository using `RUST_LOG=trace SCYLLA_URI=:9042 cargo run --example logging_log`. \ No newline at end of file