Merge pull request #959 from wprzytula/show-tracing-logs-iff-test-failed

Show tracing output only for failed tests

.github/workflows/authenticate_test.yml

@@ -28,4 +28,4 @@ jobs:
     steps:
     - uses: actions/checkout@v3
     - name: Run tests
-      run: cargo test --verbose authenticate_superuser -- custom_authentication --ignored
+      run: RUST_LOG=trace cargo test --verbose authenticate_superuser -- custom_authentication --ignored

.github/workflows/cassandra.yml

@@ -29,7 +29,7 @@ jobs:
       run: cargo build --verbose --tests --features "full-serialization"
     - name: Run tests on cassandra
       run: |
-        CDC='disabled' SCYLLA_URI=172.42.0.2:9042 SCYLLA_URI2=172.42.0.3:9042 SCYLLA_URI3=172.42.0.4:9042 cargo test --verbose --features "full-serialization" -- --skip test_views_in_schema_info --skip test_large_batch_statements
+        CDC='disabled' RUST_LOG=trace SCYLLA_URI=172.42.0.2:9042 SCYLLA_URI2=172.42.0.3:9042 SCYLLA_URI3=172.42.0.4:9042 cargo test --verbose --features "full-serialization" -- --skip test_views_in_schema_info --skip test_large_batch_statements
     - name: Stop the cluster
       if: ${{ always() }}
       run: docker compose -f test/cluster/cassandra/docker-compose.yml stop

.github/workflows/rust.yml

@@ -53,7 +53,7 @@ jobs:
     - name: Run tests
       run: |
         cargo clean
-        SCYLLA_URI=172.42.0.2:9042 SCYLLA_URI2=172.42.0.3:9042 SCYLLA_URI3=172.42.0.4:9042 cargo test --verbose --features "full-serialization"
+        RUST_LOG=trace SCYLLA_URI=172.42.0.2:9042 SCYLLA_URI2=172.42.0.3:9042 SCYLLA_URI3=172.42.0.4:9042 cargo test --verbose --features "full-serialization"
     - name: Stop the cluster
       if: ${{ always() }}
       run: docker compose -f test/cluster/docker-compose.yml stop

.github/workflows/serverless.yaml

@@ -35,7 +35,7 @@ jobs:
       - name: Run cloud example
         run: cargo run --example cloud -- $HOME/.ccm/serverless/config_data.yaml
       - name: Run cloud tests
-        run: CLOUD_CONFIG_PATH=$HOME/.ccm/serverless/config_data.yaml RUSTFLAGS="--cfg scylla_cloud_tests" cargo test --verbose
+        run: CLOUD_CONFIG_PATH=$HOME/.ccm/serverless/config_data.yaml RUSTFLAGS="--cfg scylla_cloud_tests" RUST_LOG=trace cargo test --verbose
 
       - name: Remove serverless cluster
         run: ccm remove serverless

CONTRIBUTING.md

@@ -49,6 +49,18 @@ The above commands will leave a running ScyllaDB cluster in the background.
 To stop it, use `make down`.\
 Starting a cluster without running any test is possible with `make up`.
 
+### Tracing in tests
+
+By default cargo captures `print!` macro's output from tests and prints them for failed tests.
+This is a bit problematic for us in case of `tracing` crate logs, because traces are not printed
+unless a subscriber is set. That's why we have a helper function for tests: `setup_tracing`.
+It sets up a tracing subscriber with env filter (so you can filter traces using env variables)
+and with a Writer that is compatible with test framework's output capturing.
+
+Most of the tests already call this function, and any new tests should too.
+If you want to see tracing output from a failing test and it doesn't call this function,
+simply add the call at the beginning of the test.
+
 ## CI
 
 Before sending a pull request, it is a good idea to run `make ci` locally (or `make dockerized-ci` if on macOS).

scylla-proxy/src/actions.rs

@@ -4,6 +4,9 @@ use bytes::Bytes;
 use rand::{Rng, RngCore};
 use tokio::sync::mpsc;
 
+#[cfg(test)]
+use crate::setup_tracing;
+
 use crate::{
     frame::{FrameOpcode, FrameParams, RequestFrame, RequestOpcode, ResponseFrame, ResponseOpcode},
     TargetShard,
@@ -725,6 +728,7 @@ pub struct ResponseRule(pub Condition, pub ResponseReaction);
 
 #[test]
 fn condition_case_insensitive_matching() {
+    setup_tracing();
     let mut condition_matching =
         Condition::BodyContainsCaseInsensitive(Box::new(*b"cassandra'sInefficiency"));
     let mut condition_nonmatching =

scylla-proxy/src/lib.rs

@@ -14,3 +14,11 @@ pub use frame::{RequestFrame, RequestOpcode, ResponseFrame, ResponseOpcode};
 pub use proxy::{Node, Proxy, RunningProxy, ShardAwareness};
 
 pub use proxy::get_exclusive_local_address;
+
+#[cfg(test)]
+pub(crate) fn setup_tracing() {
+    let _ = tracing_subscriber::fmt::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_writer(tracing_subscriber::fmt::TestWriter::new())
+        .try_init();
+}

scylla-proxy/src/proxy.rs

@@ -1294,7 +1294,9 @@ pub fn get_exclusive_local_address() -> IpAddr {
 mod tests {
     use super::*;
     use crate::frame::{read_frame, read_request_frame, FrameType};
-    use crate::{Condition, Reaction as _, RequestReaction, ResponseOpcode, ResponseReaction};
+    use crate::{
+        setup_tracing, Condition, Reaction as _, RequestReaction, ResponseOpcode, ResponseReaction,
+    };
     use assert_matches::assert_matches;
     use bytes::{BufMut, BytesMut};
     use futures::future::{join, join3};
@@ -1308,15 +1310,6 @@ mod tests {
     use tokio::io::{AsyncReadExt as _, AsyncWriteExt as _};
     use tokio::sync::oneshot;
 
-    // This is for convenient logs from failing tests. Just call it at the beginning of a test.
-    #[allow(unused)]
-    fn init_logger() {
-        let _ = tracing_subscriber::fmt::fmt()
-            .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
-            .without_time()
-            .try_init();
-    }
-
     fn random_body() -> Bytes {
         let body_len = (rand::random::<u32>() % 1000) as usize;
         let mut body = BytesMut::zeroed(body_len);
@@ -1437,19 +1430,21 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn identity_shard_unaware_proxy_does_not_mutate_frames() {
+        setup_tracing();
         identity_proxy_does_not_mutate_frames(ShardAwareness::Unaware).await
     }
 
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn identity_shard_aware_proxy_does_not_mutate_frames() {
-        init_logger();
+        setup_tracing();
         identity_proxy_does_not_mutate_frames(ShardAwareness::QueryNode).await
     }
 
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn shard_aware_proxy_is_transparent_for_connection_to_shards() {
+        setup_tracing();
         async fn test_for_shards_num(shards_num: u16) {
             let node1_real_addr = next_local_address_with_port(9876);
             let node1_proxy_addr = next_local_address_with_port(9876);
@@ -1499,6 +1494,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn shard_aware_proxy_queries_shards_number() {
+        setup_tracing();
         async fn test_for_shards_num(shards_num: u16) {
             for shard_num in 0..shards_num {
                 let node1_real_addr = next_local_address_with_port(9876);
@@ -1554,6 +1550,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn forger_proxy_forges_response() {
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
 
@@ -1685,6 +1682,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn ad_hoc_rules_changing() {
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
         let proxy = Proxy::new([Node::new(
@@ -1779,6 +1777,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(2000)]
     async fn limited_times_condition_expires() {
+        setup_tracing();
         const FAILING_TRIES: usize = 4;
         const PASSING_TRIES: usize = 5;
 
@@ -1880,6 +1879,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn proxy_reports_requests_and_responses_as_feedback() {
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
 
@@ -1952,6 +1952,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn sanity_check_reports_errors() {
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
         let proxy = Proxy::new([Node::new(
@@ -2002,7 +2003,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn proxy_processes_requests_concurrently() {
-        init_logger();
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
 
@@ -2076,6 +2077,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn dry_mode_proxy_drops_incoming_frames() {
+        setup_tracing();
         let node1_proxy_addr = next_local_address_with_port(9876);
         let proxy = Proxy::new([Node::new_dry_mode(node1_proxy_addr, None)]);
         let running_proxy = proxy.run().await.unwrap();
@@ -2100,6 +2102,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn dry_mode_forger_proxy_forges_response() {
+        setup_tracing();
         let node1_proxy_addr = next_local_address_with_port(9876);
 
         let this_shall_pass = b"This.Shall.Pass.";
@@ -2207,7 +2210,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn proxy_reports_target_shard_as_feedback() {
-        init_logger();
+        setup_tracing();
 
         let node_port = 10101;
         let node_real_addr = next_local_address_with_port(node_port);
@@ -2355,6 +2358,7 @@ mod tests {
     #[tokio::test]
     #[ntest::timeout(1000)]
     async fn proxy_ignores_control_connection_messages() {
+        setup_tracing();
         let node1_real_addr = next_local_address_with_port(9876);
         let node1_proxy_addr = next_local_address_with_port(9876);
 

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();