Replace log with tracing and record extrinsic info (paritytech#535)

* Replace log with tracing for integration tests

* Replace log with tracing

* Use correct tracing lib

* Log extrinsic hash and signature

* Debug extrinsic params

* Replace env_logger

* Replace more env_logger init

* Replace new logs with tracing

* Fix final env_logger

examples/Cargo.toml

@@ -15,7 +15,7 @@ description = "Subxt example usage"
 subxt = { path = "../subxt" }
 tokio = { version = "1.8", features = ["rt-multi-thread", "macros", "time"] }
 sp-keyring = "6.0.0"
-env_logger = "0.9.0"
 futures = "0.3.13"
 codec = { package = "parity-scale-codec", version = "3.0.0", default-features = false, features = ["derive", "full", "bit-vec"] }
 hex = "0.4.3"
+tracing-subscriber = "0.3.11"

examples/examples/balance_transfer.rs

@@ -35,7 +35,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let signer = PairSigner::new(AccountKeyring::Alice.pair());
     let dest = AccountKeyring::Bob.to_account_id().into();

examples/examples/balance_transfer_with_params.rs

@@ -40,7 +40,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let signer = PairSigner::new(AccountKeyring::Alice.pair());
     let dest = AccountKeyring::Bob.to_account_id().into();

examples/examples/fetch_all_accounts.rs

@@ -33,7 +33,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .build()

examples/examples/fetch_staking_details.rs

@@ -39,7 +39,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .build()

examples/examples/metadata_compatibility.rs

@@ -33,7 +33,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .build()

examples/examples/rpc_call.rs

@@ -33,7 +33,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .set_url("wss://rpc.polkadot.io:443")

examples/examples/submit_and_watch.rs

@@ -36,7 +36,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     simple_transfer().await?;
     simple_transfer_separate_events().await?;

examples/examples/subscribe_all_events.rs

@@ -39,7 +39,7 @@ pub mod polkadot {}
 /// pluck out the events that we care about.
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .build()

examples/examples/subscribe_one_event.rs

@@ -39,7 +39,7 @@ pub mod polkadot {}
 /// pluck out the events that we care about.
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     // Subscribe to any events that occur:
     let api = ClientBuilder::new()

examples/examples/subscribe_runtime_updates.rs

@@ -36,7 +36,7 @@ pub mod polkadot {}
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     let api = ClientBuilder::new()
         .build()

examples/examples/subscribe_some_events.rs

@@ -39,7 +39,7 @@ pub mod polkadot {}
 /// pluck out the events that we care about.
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    env_logger::init();
+    tracing_subscriber::fmt::init();
 
     // Subscribe to any events that occur:
     let api = ClientBuilder::new()

integration-tests/Cargo.toml

@@ -18,17 +18,17 @@ default = ["subxt/integration-tests"]
 assert_matches = "1.5.0"
 async-trait = "0.1.49"
 codec = { package = "parity-scale-codec", version = "3.0.0", default-features = false, features = ["derive", "full", "bit-vec"] }
-env_logger = "0.9.0"
 frame-metadata = "15.0.0"
 futures = "0.3.13"
 hex = "0.4.3"
-log = "0.4.14"
 scale-info = { version = "2.0.0", features = ["bit-vec"] }
 sp-core = { version = "6.0.0", default-features = false  }
 sp-keyring = "6.0.0"
 sp-runtime = "6.0.0"
 subxt = { version = "0.21.0", path = "../subxt" }
 test-runtime = { path = "../test-runtime" }
 tokio = { version = "1.8", features = ["macros", "time"] }
+tracing = "0.1.34"
+tracing-subscriber = "0.3.11"
 wabt = "0.10.0"
 which = "4.0.2"

integration-tests/src/events/mod.rs

@@ -28,7 +28,7 @@ use sp_keyring::AccountKeyring;
 // Check that we can subscribe to non-finalized block events.
 #[tokio::test]
 async fn non_finalized_block_subscription() -> Result<(), subxt::BasicError> {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let ctx = test_context().await;
 
     let mut event_sub = ctx.api.events().subscribe().await?;
@@ -46,7 +46,7 @@ async fn non_finalized_block_subscription() -> Result<(), subxt::BasicError> {
 // Check that we can subscribe to finalized block events.
 #[tokio::test]
 async fn finalized_block_subscription() -> Result<(), subxt::BasicError> {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let ctx = test_context().await;
 
     let mut event_sub = ctx.api.events().subscribe_finalized().await?;
@@ -66,7 +66,7 @@ async fn finalized_block_subscription() -> Result<(), subxt::BasicError> {
 // a few blocks.
 #[tokio::test]
 async fn subscription_produces_events_each_block() -> Result<(), subxt::BasicError> {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let ctx = test_context().await;
 
     let mut event_sub = ctx.api.events().subscribe().await?;
@@ -95,7 +95,7 @@ async fn subscription_produces_events_each_block() -> Result<(), subxt::BasicErr
 // it's Stream impl, and ultimately see the event we expect.
 #[tokio::test]
 async fn balance_transfer_subscription() -> Result<(), subxt::BasicError> {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let ctx = test_context().await;
 
     // Subscribe to balance transfer events, ignoring all else.

integration-tests/src/frame/balances.rs

@@ -189,7 +189,7 @@ async fn storage_balance_lock() -> Result<(), subxt::Error<DispatchError>> {
 
 #[tokio::test]
 async fn transfer_error() {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let alice = pair_signer(AccountKeyring::Alice.pair());
     let alice_addr = alice.account_id().clone().into();
     let hans = pair_signer(Pair::generate().0);
@@ -230,7 +230,7 @@ async fn transfer_error() {
 
 #[tokio::test]
 async fn transfer_implicit_subscription() {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let alice = pair_signer(AccountKeyring::Alice.pair());
     let bob = AccountKeyring::Bob.to_account_id();
     let bob_addr = bob.clone().into();

integration-tests/src/frame/contracts.rs

@@ -52,6 +52,7 @@ type AccountId = <DefaultConfig as Config>::AccountId;
 
 impl ContractsTestContext {
     async fn init() -> Self {
+        tracing_subscriber::fmt::try_init().ok();
         let cxt = test_context().await;
         let signer = PairSigner::new(AccountKeyring::Alice.pair());
 
@@ -69,7 +70,7 @@ impl ContractsTestContext {
     async fn instantiate_with_code(
         &self,
     ) -> Result<(Hash, AccountId), Error<DispatchError>> {
-        log::info!("instantiate_with_code:");
+        tracing::info!("instantiate_with_code:");
         const CONTRACT: &str = r#"
                 (module
                     (func (export "call"))
@@ -108,9 +109,9 @@ impl ContractsTestContext {
                 Error::Other("Failed to find a ExtrinsicSuccess event".into())
             })?;
 
-        log::info!("  Block hash: {:?}", events.block_hash());
-        log::info!("  Code hash: {:?}", code_stored.code_hash);
-        log::info!("  Contract address: {:?}", instantiated.contract);
+        tracing::info!("  Block hash: {:?}", events.block_hash());
+        tracing::info!("  Code hash: {:?}", code_stored.code_hash);
+        tracing::info!("  Contract address: {:?}", instantiated.contract);
         Ok((code_stored.code_hash, instantiated.contract))
     }
 
@@ -136,7 +137,7 @@ impl ContractsTestContext {
             .wait_for_finalized_success()
             .await?;
 
-        log::info!("Instantiate result: {:?}", result);
+        tracing::info!("Instantiate result: {:?}", result);
         let instantiated = result
             .find_first::<events::Instantiated>()?
             .ok_or_else(|| Error::Other("Failed to find a Instantiated event".into()))?;
@@ -152,7 +153,7 @@ impl ContractsTestContext {
         TransactionProgress<'_, DefaultConfig, DispatchError, node_runtime::Event>,
         Error<DispatchError>,
     > {
-        log::info!("call: {:?}", contract);
+        tracing::info!("call: {:?}", contract);
         let result = self
             .contracts_tx()
             .call(
@@ -165,7 +166,7 @@ impl ContractsTestContext {
             .sign_and_submit_then_watch_default(&self.signer)
             .await?;
 
-        log::info!("Call result: {:?}", result);
+        tracing::info!("Call result: {:?}", result);
         Ok(result)
     }
 }

integration-tests/src/utils/context.rs

@@ -67,7 +67,7 @@ impl TestContext {
 }
 
 pub async fn test_context() -> TestContext {
-    env_logger::try_init().ok();
+    tracing_subscriber::fmt::try_init().ok();
     let node_proc = test_node_process_with(AccountKeyring::Alice).await;
     let api = node_proc.client().clone().to_runtime_api();
     TestContext { node_proc, api }

integration-tests/src/utils/node_proc.rs

@@ -63,10 +63,10 @@ where
 
     /// Attempt to kill the running substrate process.
     pub fn kill(&mut self) -> Result<(), String> {
-        log::info!("Killing node process {}", self.proc.id());
+        tracing::info!("Killing node process {}", self.proc.id());
         if let Err(err) = self.proc.kill() {
             let err = format!("Error killing node process {}: {}", self.proc.id(), err);
-            log::error!("{}", err);
+            tracing::error!("{}", err);
             return Err(err)
         }
         Ok(())
@@ -152,7 +152,7 @@ impl TestNodeProcessBuilder {
             }
             Err(err) => {
                 let err = format!("Failed to connect to node rpc at {}: {}", ws_url, err);
-                log::error!("{}", err);
+                tracing::error!("{}", err);
                 proc.kill().map_err(|e| {
                     format!("Error killing substrate process '{}': {}", proc.id(), e)
                 })?;

subxt/Cargo.toml

@@ -25,10 +25,10 @@ scale-info = { version = "2.0.0", features = ["bit-vec"] }
 futures = "0.3.13"
 hex = "0.4.3"
 jsonrpsee = { version = "0.12.0", features = ["async-client", "client-ws-transport"] }
-log = "0.4.14"
 serde = { version = "1.0.124", features = ["derive"] }
 serde_json = "1.0.64"
 thiserror = "1.0.24"
+tracing = "0.1.34"
 parking_lot = "0.12.0"
 
 subxt-macro = { version = "0.21.0", path = "../macro" }
@@ -44,7 +44,6 @@ derivative = "2.2.0"
 sp-arithmetic = { version = "5.0.0", default-features = false }
 assert_matches = "1.5.0"
 tokio = { version = "1.8", features = ["macros", "time"] }
-env_logger = "0.9.0"
 tempdir = "0.3.7"
 wabt = "0.10.0"
 which = "4.0.2"

subxt/src/client.rs

@@ -267,6 +267,8 @@ where
         // Get a hash of the extrinsic (we'll need this later).
         let ext_hash = T::Hashing::hash_of(&extrinsic);
 
+        tracing::info!("xt hash: {}", hex::encode(ext_hash.encode()));
+
         // Submit and watch for transaction progress.
         let sub = self.client.rpc().watch_extrinsic(extrinsic).await?;
 
@@ -352,6 +354,11 @@ where
             )
         };
 
+        tracing::debug!(
+            "additional_and_extra_params: {:?}",
+            additional_and_extra_params
+        );
+
         // 4. Construct signature. This is compatible with the Encode impl
         //    for SignedPayload (which is this payload of bytes that we'd like)
         //    to sign. See:
@@ -368,6 +375,8 @@ where
             }
         };
 
+        tracing::info!("xt signature: {}", hex::encode(signature.encode()));
+
         // 5. Encode extrinsic, now that we have the parts we need. This is compatible
         //    with the Encode impl for UncheckedExtrinsic (protocol version 4).
         let extrinsic = {

subxt/src/config.rs

@@ -34,7 +34,7 @@ use sp_runtime::traits::{
 // Note: the 'static bound isn't strictly required, but currently deriving TypeInfo
 // automatically applies a 'static bound to all generic types (including this one),
 // and so until that is resolved, we'll keep the (easy to satisfy) constraint here.
-pub trait Config: 'static {
+pub trait Config: Debug + 'static {
     /// Account index (aka nonce) type. This stores the number of previous
     /// transactions associated with a sender account.
     type Index: Parameter
@@ -95,6 +95,7 @@ impl<T> Parameter for T where T: Codec + EncodeLike + Clone + Eq + Debug {}
 /// Default set of commonly used types by Substrate runtimes.
 // Note: We only use this at the type level, so it should be impossible to
 // create an instance of it.
+#[derive(Debug)]
 pub enum DefaultConfig {}
 
 impl Config for DefaultConfig {

subxt/src/events/events_type.rs

@@ -351,17 +351,17 @@ fn decode_raw_event_details<T: Config>(
     let phase = Phase::decode(input)?;
     let pallet_index = input.read_byte()?;
     let variant_index = input.read_byte()?;
-    log::debug!(
+    tracing::debug!(
         "phase {:?}, pallet_index {}, event_variant: {}",
         phase,
         pallet_index,
         variant_index
     );
-    log::debug!("remaining input: {}", hex::encode(&input));
+    tracing::debug!("remaining input: {}", hex::encode(&input));
 
     // Get metadata for the event:
     let event_metadata = metadata.event(pallet_index, variant_index)?;
-    log::debug!(
+    tracing::debug!(
         "Decoding Event '{}::{}'",
         event_metadata.pallet(),
         event_metadata.event()
@@ -387,7 +387,7 @@ fn decode_raw_event_details<T: Config>(
     // topics come after the event data in EventRecord. They aren't used for
     // anything at the moment, so just decode and throw them away.
     let topics = Vec::<T::Hash>::decode(input)?;
-    log::debug!("topics: {:?}", topics);
+    tracing::debug!("topics: {:?}", topics);
 
     Ok(RawEventDetails {
         phase,