scylla unit tests: introduce setup_tracing()

Before, tracing crate's prints weren't captured during tests. Those with
error level used to bloat tests' output, which was especially painful in
CI. OTOH, we wanted to have traces visible in failed tests in order to
easier spot the cause of a failure.
By using tracing_subscriber's TestWriter, tracing's prints are now
captured and only shown if a test fails. This enables efficient
troubleshooting especially in case of flaky tests, as those are common
in CI only and hard to be reproduced locally.
For all tests to easily use the captured tracing, a function
setup_tracing() is introduced. This commit adds it to scylla crate unit
tests. Integration tests and proxy tests are covered in next commits.

Author: wprzytula

scylla/src/cloud/config.rs

@@ -551,6 +551,7 @@ mod deserialize {
     #[cfg(test)]
     mod tests {
         use crate::cloud::config::deserialize::Parameters;
+        use crate::test_utils::setup_tracing;
 
         use super::super::CloudConfig;
         use super::RawCloudConfig;
@@ -599,6 +600,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_no_cert_provided() {
+            setup_tracing();
             let dc_no_cert = super::Datacenter {
                 certificateAuthorityPath: None,
                 certificateAuthorityData: None,
@@ -609,6 +611,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_cert_not_found() {
+            setup_tracing();
             let dc_cert_nonfound = super::Datacenter {
                 certificateAuthorityPath: Some(NO_PEM_PATH.into()),
                 certificateAuthorityData: None,
@@ -619,6 +622,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_invalid_cert() {
+            setup_tracing();
             let dc_invalid_cert = super::Datacenter {
                 certificateAuthorityData: Some("INVALID CERFITICATE".into()),
                 ..dc_valid()
@@ -628,6 +632,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_cert_found_bad() {
+            setup_tracing();
             let dc_cert_found_bad = super::Datacenter {
                 certificateAuthorityPath: Some(BAD_PEM_PATH.into()),
                 certificateAuthorityData: None,
@@ -638,6 +643,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_cert_found_good() {
+            setup_tracing();
             let dc_cert_found_good = super::Datacenter {
                 certificateAuthorityPath: Some(GOOD_PEM_PATH.into()),
                 certificateAuthorityData: None,
@@ -648,6 +654,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_domain_empty() {
+            setup_tracing();
             let dc_bad_domain_empty = super::Datacenter {
                 nodeDomain: "".into(),
                 ..dc_valid()
@@ -657,6 +664,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_domain_trailing_minus() {
+            setup_tracing();
             let dc_bad_domain_trailing_minus = super::Datacenter {
                 nodeDomain: "cql.scylla-.com".into(),
                 ..dc_valid()
@@ -666,6 +674,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_domain_interior_minus() {
+            setup_tracing();
             let dc_good_domain_interior_minus = super::Datacenter {
                 nodeDomain: "cql.scylla-cloud.com".into(),
                 ..dc_valid()
@@ -675,6 +684,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_domain_special_sign() {
+            setup_tracing();
             let dc_bad_domain_special_sign = super::Datacenter {
                 nodeDomain: "cql.$cylla-cloud.com".into(),
                 ..dc_valid()
@@ -684,6 +694,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_dc_validation_bad_server_url() {
+            setup_tracing();
             let dc_bad_server_not_url = super::Datacenter {
                 server: "NotAUrl".into(),
                 ..dc_valid()
@@ -699,6 +710,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_unsupported_api_version() {
+            setup_tracing();
             let mut config = RawCloudConfig::try_from(CCM_CONFIG).unwrap();
             config.apiVersion = Some("1.0".into());
             // The mere unknown api version should not be considered an erroneous input, but a warning will be logged.
@@ -707,6 +719,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_deserialisation() {
+            setup_tracing();
             {
                 // CCM standard config
                 let config = RawCloudConfig::try_from(CCM_CONFIG).unwrap();
@@ -786,6 +799,7 @@ mod deserialize {
 
         #[test]
         fn test_cloud_config_validation() {
+            setup_tracing();
             {
                 // CCM standard config
                 let config = RawCloudConfig::try_from(CCM_CONFIG).unwrap();

scylla/src/history.rs

@@ -456,7 +456,8 @@ mod tests {
     };
 
     use crate::{
-        query::Query, retry_policy::RetryDecision, utils::test_utils::unique_keyspace_name,
+        query::Query, retry_policy::RetryDecision, test_utils::setup_tracing,
+        utils::test_utils::unique_keyspace_name,
     };
 
     use super::{
@@ -589,6 +590,7 @@ mod tests {
 
     #[test]
     fn empty_history() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
         let history: StructuredHistory = history_collector.clone_structured_history();
 
@@ -601,6 +603,7 @@ mod tests {
 
     #[test]
     fn empty_query() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let _query_id: QueryId = history_collector.log_query_start();
@@ -625,6 +628,7 @@ mod tests {
 
     #[test]
     fn one_attempt() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let query_id: QueryId = history_collector.log_query_start();
@@ -659,6 +663,7 @@ mod tests {
 
     #[test]
     fn two_error_atempts() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let query_id: QueryId = history_collector.log_query_start();
@@ -709,6 +714,7 @@ mod tests {
 
     #[test]
     fn empty_fibers() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let query_id: QueryId = history_collector.log_query_start();
@@ -750,6 +756,7 @@ mod tests {
 
     #[test]
     fn complex() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let query_id: QueryId = history_collector.log_query_start();
@@ -854,6 +861,7 @@ mod tests {
 
     #[test]
     fn multiple_queries() {
+        setup_tracing();
         let history_collector = HistoryCollector::new();
 
         let query1_id: QueryId = history_collector.log_query_start();
@@ -908,6 +916,7 @@ mod tests {
 
     #[tokio::test]
     async fn successful_query_history() {
+        setup_tracing();
         let session = create_new_session_builder().build().await.unwrap();
 
         let mut query = Query::new("SELECT * FROM system.local");
@@ -974,6 +983,7 @@ mod tests {
 
     #[tokio::test]
     async fn failed_query_history() {
+        setup_tracing();
         let session = create_new_session_builder().build().await.unwrap();
 
         let mut query = Query::new("This isnt even CQL");
@@ -1010,6 +1020,7 @@ mod tests {
 
     #[tokio::test]
     async fn iterator_query_history() {
+        setup_tracing();
         let session = create_new_session_builder().build().await.unwrap();
         let ks = unique_keyspace_name();
         session

scylla/src/routing.rs

@@ -135,12 +135,15 @@ impl<'a> TryFrom<&'a HashMap<String, Vec<String>>> for ShardInfo {
 
 #[cfg(test)]
 mod tests {
+    use crate::test_utils::setup_tracing;
+
     use super::Token;
     use super::{ShardCount, Sharder};
     use std::collections::HashSet;
 
     #[test]
     fn test_shard_of() {
+        setup_tracing();
         /* Test values taken from the gocql driver.  */
         let sharder = Sharder::new(ShardCount::new(4).unwrap(), 12);
         assert_eq!(
@@ -159,6 +162,7 @@ mod tests {
 
     #[test]
     fn test_iter_source_ports_for_shard() {
+        setup_tracing();
         let nr_shards = 4;
         let max_port_num = 65535;
         let min_port_num = (49152 + nr_shards - 1) / nr_shards * nr_shards;

scylla/src/statement/prepared_statement.rs

@@ -534,7 +534,7 @@ mod tests {
         types::serialize::row::SerializedValues,
     };
 
-    use crate::prepared_statement::PartitionKey;
+    use crate::{prepared_statement::PartitionKey, test_utils::setup_tracing};
 
     fn make_meta(
         cols: impl IntoIterator<Item = ColumnType>,
@@ -572,6 +572,7 @@ mod tests {
 
     #[test]
     fn test_partition_key_multiple_columns_shuffled() {
+        setup_tracing();
         let meta = make_meta(
             [
                 ColumnType::TinyInt,

scylla/src/transport/authenticate_test.rs

@@ -1,4 +1,5 @@
 use crate::authentication::{AuthError, AuthenticatorProvider, AuthenticatorSession};
+use crate::test_utils::setup_tracing;
 use crate::utils::test_utils::unique_keyspace_name;
 use async_trait::async_trait;
 use bytes::{BufMut, BytesMut};
@@ -7,6 +8,7 @@ use std::sync::Arc;
 #[tokio::test]
 #[ignore]
 async fn authenticate_superuser() {
+    setup_tracing();
     let uri = std::env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string());
 
     println!("Connecting to {} with cassandra superuser ...", uri);
@@ -62,6 +64,7 @@ impl AuthenticatorProvider for CustomAuthenticatorProvider {
 #[tokio::test]
 #[ignore]
 async fn custom_authentication() {
+    setup_tracing();
     let uri = std::env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string());
 
     println!("Connecting to {} with cassandra superuser ...", uri);

scylla/src/transport/caching_session.rs

@@ -218,7 +218,7 @@ where
 #[cfg(test)]
 mod tests {
     use crate::query::Query;
-    use crate::test_utils::create_new_session_builder;
+    use crate::test_utils::{create_new_session_builder, setup_tracing};
     use crate::transport::partitioner::PartitionerName;
     use crate::utils::test_utils::unique_keyspace_name;
     use crate::{
@@ -281,6 +281,7 @@ mod tests {
     /// to the cache and a random query is removed
     #[tokio::test]
     async fn test_full() {
+        setup_tracing();
         let session = create_caching_session().await;
 
         let first_query = "select * from test_table";
@@ -315,6 +316,7 @@ mod tests {
     /// Checks that the same prepared statement is reused when executing the same query twice
     #[tokio::test]
     async fn test_execute_cached() {
+        setup_tracing();
         let session = create_caching_session().await;
         let result = session
             .execute("select * from test_table", &[])
@@ -336,6 +338,7 @@ mod tests {
     /// Checks that caching works with execute_iter
     #[tokio::test]
     async fn test_execute_iter_cached() {
+        setup_tracing();
         let session = create_caching_session().await;
 
         assert!(session.cache.is_empty());
@@ -354,6 +357,7 @@ mod tests {
     /// Checks that caching works with execute_paged
     #[tokio::test]
     async fn test_execute_paged_cached() {
+        setup_tracing();
         let session = create_caching_session().await;
 
         assert!(session.cache.is_empty());
@@ -392,6 +396,7 @@ mod tests {
     /// This test checks that we can construct a CachingSession with custom HashBuilder implementations
     #[tokio::test]
     async fn test_custom_hasher() {
+        setup_tracing();
         #[derive(Default, Clone)]
         struct CustomBuildHasher;
         impl std::hash::BuildHasher for CustomBuildHasher {
@@ -423,6 +428,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_batch() {
+        setup_tracing();
         let session: CachingSession = create_caching_session().await;
 
         session
@@ -545,6 +551,7 @@ mod tests {
     // Reproduces #597
     #[tokio::test]
     async fn test_parameters_caching() {
+        setup_tracing();
         let session: CachingSession = CachingSession::from(new_for_test().await, 100);
 
         session
@@ -592,6 +599,7 @@ mod tests {
     // Checks whether the PartitionerName is cached properly.
     #[tokio::test]
     async fn test_partitioner_name_caching() {
+        setup_tracing();
         if option_env!("CDC") == Some("disabled") {
             return;
         }

scylla/src/transport/connection.rs

@@ -1877,6 +1877,7 @@ mod tests {
 
     use super::ConnectionConfig;
     use crate::query::Query;
+    use crate::test_utils::setup_tracing;
     use crate::transport::connection::open_connection;
     use crate::transport::node::ResolvedContactPoint;
     use crate::transport::topology::UntranslatedEndpoint;
@@ -1910,6 +1911,7 @@ mod tests {
     #[tokio::test]
     #[cfg(not(scylla_cloud_tests))]
     async fn connection_query_iter_test() {
+        setup_tracing();
         let uri = std::env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string());
         let addr: SocketAddr = resolve_hostname(&uri).await;
 
@@ -2009,6 +2011,7 @@ mod tests {
     #[tokio::test]
     #[cfg(not(scylla_cloud_tests))]
     async fn test_coalescing() {
+        setup_tracing();
         // It's difficult to write a reliable test that checks whether coalescing
         // works like intended or not. Instead, this is a smoke test which is supposed
         // to trigger the coalescing logic and check that everything works fine
@@ -2124,6 +2127,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_lwt_optimisation_mark_negotiation() {
+        setup_tracing();
         const MASK: &str = "2137";
 
         let lwt_optimisation_entry = format!("{}={}", LWT_OPTIMIZATION_META_BIT_MASK_KEY, MASK);
@@ -2204,6 +2208,7 @@ mod tests {
     #[ntest::timeout(20000)]
     #[cfg(not(scylla_cloud_tests))]
     async fn connection_is_closed_on_no_response_to_keepalives() {
+        setup_tracing();
         let proxy_addr = SocketAddr::new(scylla_proxy::get_exclusive_local_address(), 9042);
         let uri = std::env::var("SCYLLA_URI").unwrap_or_else(|_| "127.0.0.1:9042".to_string());
         let node_addr: SocketAddr = resolve_hostname(&uri).await;

scylla/src/transport/connection_pool.rs

@@ -1262,6 +1262,7 @@ async fn open_connection_to_shard_aware_port(
 mod tests {
     use super::open_connection_to_shard_aware_port;
     use crate::routing::{ShardCount, Sharder};
+    use crate::test_utils::setup_tracing;
     use crate::transport::connection::ConnectionConfig;
     use crate::transport::node::ResolvedContactPoint;
     use crate::transport::topology::UntranslatedEndpoint;
@@ -1273,6 +1274,7 @@ mod tests {
     #[tokio::test]
     #[cfg(not(scylla_cloud_tests))]
     async fn many_connections() {
+        setup_tracing();
         let connections_number = 512;
 
         let connect_address: SocketAddr = std::env::var("SCYLLA_URI")