Replace env_logger with tracing in tests (#505)

* Remove `log` crate dependency

We don't use this anymore

* Remove `env_logger` from tests

* Replace `println!` in server with `tracing::info!`

* First go at initializing global logger in tests

* Use `lazy_static` instead of `once_cell`

We already have this as a dependency and it's not very different in terms of characteristics.

* Move logger init code out of `testing-utils`

I think it's fine to have it in the server test helpers.

* Manually initialize logger in `user` tests

* Initialize logger in the rest of the tests

* By default filter out logs that aren't `ERROR` level

* Initialize logger before cleaning `kvdb`

* Add missing logger initilization

crypto/server/Cargo.toml

@@ -46,7 +46,6 @@ entropy-protocol={ path="../protocol", features=["server"] }
 ec-runtime={ git="ssh://[email protected]/entropyxyz/constraints.git", tag="v0.3.0" }
 
 # Logging
-log               ="0.4.17"                                              # todo: remove, overlaps tracing
 tracing           ="0.1.37"
 tracing-subscriber={ version="0.3.17", features=["env-filter", "json"] }
 tower-http        ={ version="0.3.4", features=["trace", "cors"] }
@@ -73,6 +72,7 @@ project-root      ="0.2.2"
 sp-keyring        ="24.0.0"
 more-asserts      ="0.3.1"
 template-barebones={ git="ssh://[email protected]/entropyxyz/constraints.git", tag="v0.2.0" }
+lazy_static       ="1.4.0"
 
 [features]
 default=['std']

crypto/server/src/health/tests.rs

@@ -2,14 +2,18 @@ use axum::http::StatusCode;
 use kvdb::clean_tests;
 use serial_test::serial;
 
-use crate::helpers::tests::setup_client;
+use crate::helpers::tests::{initialize_test_logger, setup_client};
+
 #[tokio::test]
 #[serial]
 async fn health() {
+    initialize_test_logger();
     clean_tests();
     setup_client().await;
+
     let client = reqwest::Client::new();
     let response = client.get("http://127.0.0.1:3001/healthz").send().await.unwrap();
     assert_eq!(response.status(), StatusCode::OK);
+
     clean_tests();
 }

crypto/server/src/helpers/launch.rs

@@ -147,7 +147,7 @@ pub async fn setup_mnemonic(
         }
 
         let phrase = mnemonic.phrase();
-        println!("[server-config]");
+        tracing::info!("[server-config]");
         let pair = mnemonic_to_pair(&mnemonic).expect("Issue deriving Mnemonic");
         let static_secret = derive_static_secret(&pair);
         let dh_public = x25519_dalek::PublicKey::from(&static_secret);
@@ -173,7 +173,7 @@ pub async fn setup_mnemonic(
             .put(dh_reservation, converted_dh_public.clone())
             .await
             .expect("failed to update dh");
-        println!("dh_public_key={dh_public:?}");
+        tracing::info!("dh_public_key={dh_public:?}");
 
         let formatted_dh_public = format!("{converted_dh_public:?}").replace('"', "");
         fs::write(".entropy/public_key", formatted_dh_public)
@@ -182,7 +182,7 @@ pub async fn setup_mnemonic(
         let p = <sr25519::Pair as Pair>::from_phrase(phrase, None)
             .expect("Issue getting pair from mnemonic");
         let id = AccountId32::new(p.0.public().0);
-        println!("account_id={id}");
+        tracing::info!("account_id={id}");
         fs::write(".entropy/account_id", format!("{id}")).expect("Failed to write account_id file");
 
         // Update the value in the kvdb

crypto/server/src/helpers/tests.rs

@@ -36,6 +36,27 @@ use crate::{
     AppState,
 };
 
+lazy_static::lazy_static! {
+    /// A shared reference to the logger used for tests.
+    ///
+    /// Since this only needs to be initialized once for the whole test suite we define it as a lazy
+    /// static.
+    pub static ref LOGGER: () = {
+        // We set up the tests to only print out logs of `ERROR` or higher by default, otherwise we
+        // fall back to the user's `RUST_LOG` settings.
+        tracing_subscriber::fmt()
+            .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+            .init();
+    };
+}
+
+/// Initialize the global loger used in tests.
+///
+/// The logger will only be initialized once, even if this function is called multiple times.
+pub fn initialize_test_logger() {
+    lazy_static::initialize(&LOGGER);
+}
+
 pub async fn setup_client() -> KvManager {
     let kv_store =
         KvManager::new(get_db_path(true).into(), PasswordMethod::NoPassword.execute().unwrap())
@@ -200,6 +221,7 @@ pub async fn run_to_block(rpc: &LegacyRpcMethods<EntropyConfig>, block_run: u32)
 #[tokio::test]
 #[serial]
 async fn test_get_signing_group() {
+    initialize_test_logger();
     clean_tests();
     let cxt = testing_context().await;
     setup_client().await;

crypto/server/src/signing_client/tests.rs

@@ -3,7 +3,7 @@ use crate::{
     chain_api::{get_api, get_rpc},
     helpers::{
         launch::LATEST_BLOCK_NUMBER_PROACTIVE_REFRESH,
-        tests::{run_to_block, setup_client, spawn_testing_validators},
+        tests::{initialize_test_logger, run_to_block, setup_client, spawn_testing_validators},
     },
     r#unsafe::api::UnsafeQuery,
 };
@@ -22,6 +22,7 @@ use testing_utils::{
 #[tokio::test]
 #[serial]
 async fn test_proactive_refresh() {
+    initialize_test_logger();
     clean_tests();
     let eve = AccountKeyring::Eve;
     let dave = AccountKeyring::Dave;
@@ -160,7 +161,9 @@ pub async fn submit_transaction_requests(
 #[tokio::test]
 #[serial]
 async fn test_proactive_refresh_validation_fail() {
+    initialize_test_logger();
     clean_tests();
+
     let cxt = test_context_stationary().await;
     let api = get_api(&cxt.node_proc.ws_url).await.unwrap();
     let rpc = get_rpc(&cxt.node_proc.ws_url).await.unwrap();

crypto/server/src/unsafe/tests.rs

@@ -3,11 +3,12 @@ use kvdb::clean_tests;
 use serial_test::serial;
 
 use super::api::UnsafeQuery;
-use crate::helpers::tests::setup_client;
+use crate::helpers::tests::{initialize_test_logger, setup_client};
 
 #[tokio::test]
 #[serial]
 async fn test_unsafe_get_endpoint() {
+    initialize_test_logger();
     setup_client().await;
     let client = reqwest::Client::new();
 

crypto/server/src/user/api.rs

@@ -24,7 +24,6 @@ use kvdb::kv_manager::{
     value::PartyInfo,
     KvManager,
 };
-use log::info;
 use num::{bigint::BigInt, FromPrimitive, Num, ToPrimitive};
 use parity_scale_codec::{Decode, DecodeAll, Encode};
 use serde::{Deserialize, Serialize};

crypto/server/src/user/tests.rs

@@ -73,8 +73,9 @@ use crate::{
         signing::{create_unique_tx_id, Hasher},
         substrate::{get_subgroup, make_register, return_all_addresses_of_subgroup},
         tests::{
-            check_if_confirmation, create_clients, keyring_to_subxt_signer_and_x25519,
-            run_to_block, setup_client, spawn_testing_validators, update_programs,
+            check_if_confirmation, create_clients, initialize_test_logger,
+            keyring_to_subxt_signer_and_x25519, run_to_block, setup_client,
+            spawn_testing_validators, update_programs,
         },
         user::send_key,
     },
@@ -89,7 +90,9 @@ use crate::{
 #[tokio::test]
 #[serial]
 async fn test_get_signer_does_not_throw_err() {
+    initialize_test_logger();
     clean_tests();
+
     let kv_store = load_kv_store(&None, false).await;
     let mnemonic = setup_mnemonic(&kv_store, &None).await;
     assert!(mnemonic.is_ok());
@@ -99,7 +102,9 @@ async fn test_get_signer_does_not_throw_err() {
 #[tokio::test]
 #[serial]
 async fn test_sign_tx_no_chain() {
+    initialize_test_logger();
     clean_tests();
+
     let one = AccountKeyring::Dave;
     let two = AccountKeyring::Two;
 
@@ -357,7 +362,9 @@ async fn test_sign_tx_no_chain() {
 #[tokio::test]
 #[serial]
 async fn test_fail_signing_group() {
+    initialize_test_logger();
     clean_tests();
+
     let dave = AccountKeyring::Dave;
     let _ = spawn_testing_validators(None, false).await;
 
@@ -410,7 +417,9 @@ async fn test_fail_signing_group() {
 #[tokio::test]
 #[serial]
 async fn test_store_share() {
+    initialize_test_logger();
     clean_tests();
+
     let alice = AccountKeyring::Alice;
     let alice_program = AccountKeyring::Charlie;
     let signing_address = alice.to_account_id().to_ss58check();
@@ -563,6 +572,8 @@ async fn test_store_share() {
 #[tokio::test]
 #[serial]
 async fn test_return_addresses_of_subgroup() {
+    initialize_test_logger();
+
     let cxt = test_context_stationary().await;
     let api = get_api(&cxt.node_proc.ws_url).await.unwrap();
     let rpc = get_rpc(&cxt.node_proc.ws_url).await.unwrap();
@@ -574,7 +585,9 @@ async fn test_return_addresses_of_subgroup() {
 #[tokio::test]
 #[serial]
 async fn test_send_and_receive_keys() {
+    initialize_test_logger();
     clean_tests();
+
     let alice = AccountKeyring::Alice;
 
     let cxt = test_context_stationary().await;
@@ -667,7 +680,9 @@ async fn test_send_and_receive_keys() {
 #[tokio::test]
 #[serial]
 async fn test_recover_key() {
+    initialize_test_logger();
     clean_tests();
+
     let cxt = test_node_process_testing_state(false).await;
     setup_client().await;
     let (_, bob_kv) =
@@ -725,7 +740,9 @@ pub async fn put_register_request_on_chain(
 #[tokio::test]
 #[serial]
 async fn test_sign_tx_user_participates() {
+    initialize_test_logger();
     clean_tests();
+
     let one = AccountKeyring::Eve;
     let two = AccountKeyring::Two;
 
@@ -1143,6 +1160,7 @@ async fn test_wasm_sign_tx_user_participates() {
 #[tokio::test]
 #[serial]
 async fn test_register_with_private_key_visibility() {
+    initialize_test_logger();
     clean_tests();
 
     let one = AccountKeyring::One;

crypto/server/src/validator/api.rs

@@ -58,7 +58,7 @@ pub async fn sync_validator(sync: bool, dev: bool, endpoint: &str, kv_store: &Kv
             let health = rpc.system_health().await.expect("Issue checking chain health");
             is_syncing = health.is_syncing;
             if is_syncing {
-                println!("chain syncing, retrying {is_syncing:?}");
+                tracing::info!("chain syncing, retrying {is_syncing:?}");
                 thread::sleep(sleep_time);
             }
         }
@@ -72,7 +72,7 @@ pub async fn sync_validator(sync: bool, dev: bool, endpoint: &str, kv_store: &Kv
         // if not in subgroup retry until you are
         let mut my_subgroup = get_subgroup(&api, &rpc, &signer).await;
         while my_subgroup.is_err() {
-            println!("you are not currently a validator, retrying");
+            tracing::info!("you are not currently a validator, retrying");
             thread::sleep(sleep_time);
             my_subgroup =
                 Ok(get_subgroup(&api, &rpc, &signer).await.expect("Failed to get subgroup."));