feat: add logging (#15)

* feat: add logging

* show confidence and delay when syncing

* log rpc errors

* fmt

Cargo.lock

@@ -33,6 +33,15 @@ dependencies = [
  "memchr",
 ]
 
+[[package]]
+name = "android_system_properties"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "819e7219dbd41043ac279b19830f2efc897156490d7fd6ea916720117ee66311"
+dependencies = [
+ "libc",
+]
+
 [[package]]
 name = "anyhow"
 version = "1.0.64"
@@ -354,8 +363,13 @@ version = "0.4.22"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "bfd4d1b31faaa3a89d7934dbded3111da0d2ef28e3ebccdb4f0179f5929d1ef1"
 dependencies = [
+ "iana-time-zone",
+ "js-sys",
  "num-integer",
  "num-traits",
+ "time",
+ "wasm-bindgen",
+ "winapi",
 ]
 
 [[package]]
@@ -422,6 +436,7 @@ dependencies = [
  "futures",
  "hex",
  "jsonrpsee",
+ "log",
  "reqwest",
  "revm",
  "serde",
@@ -519,6 +534,7 @@ dependencies = [
  "async-trait",
  "blst",
  "bytes",
+ "chrono",
  "common",
  "config",
  "ethers",
@@ -526,6 +542,7 @@ dependencies = [
  "futures",
  "hex",
  "jsonrpsee",
+ "log",
  "reqwest",
  "revm",
  "serde",
@@ -715,6 +732,19 @@ dependencies = [
  "cfg-if",
 ]
 
+[[package]]
+name = "env_logger"
+version = "0.9.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0b2cf0344971ee6c64c31be0d530793fba457d322dfec2810c453d0ef228f9c3"
+dependencies = [
+ "atty",
+ "humantime",
+ "log",
+ "regex",
+ "termcolor",
+]
+
 [[package]]
 name = "eth-keystore"
 version = "0.5.0"
@@ -1465,6 +1495,12 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421"
 
+[[package]]
+name = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
 [[package]]
 name = "hyper"
 version = "0.14.20"
@@ -1518,6 +1554,20 @@ dependencies = [
  "tokio-native-tls",
 ]
 
+[[package]]
+name = "iana-time-zone"
+version = "0.1.47"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4c495f162af0bf17656d0014a0eded5f3cd2f365fdd204548c2869db89359dc7"
+dependencies = [
+ "android_system_properties",
+ "core-foundation-sys",
+ "js-sys",
+ "once_cell",
+ "wasm-bindgen",
+ "winapi",
+]
+
 [[package]]
 name = "idna"
 version = "0.2.3"
@@ -1888,7 +1938,9 @@ dependencies = [
  "client",
  "config",
  "dirs",
+ "env_logger",
  "eyre",
+ "log",
  "tokio",
 ]
 
@@ -3220,6 +3272,17 @@ dependencies = [
  "num_cpus",
 ]
 
+[[package]]
+name = "time"
+version = "0.1.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6db9e6914ab8b1ae1c260a4ae7a49b6c5611b40328a735b21862567685e73255"
+dependencies = [
+ "libc",
+ "wasi 0.10.0+wasi-snapshot-preview1",
+ "winapi",
+]
+
 [[package]]
 name = "tiny-keccak"
 version = "1.5.0"
@@ -3537,6 +3600,12 @@ version = "0.9.0+wasi-snapshot-preview1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "cccddf32554fecc6acb585f82a32a72e28b48f8c4c1883ddfeeeaa96f7d8e519"
 
+[[package]]
+name = "wasi"
+version = "0.10.0+wasi-snapshot-preview1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f"
+
 [[package]]
 name = "wasi"
 version = "0.11.0+wasi-snapshot-preview1"

cli/Cargo.toml

@@ -8,6 +8,8 @@ tokio = { version = "1", features = ["full"] }
 clap = { version = "3.2.18", features = ["derive"] }
 eyre = "0.6.8"
 dirs = "4.0.0"
+env_logger = "0.9.0"
+log = "0.4.17"
 
 client = { path = "../client" }
 config = { path = "../config" }

cli/src/main.rs

@@ -2,6 +2,7 @@ use std::{sync::Arc, time::Duration};
 
 use clap::Parser;
 use dirs::home_dir;
+use env_logger::Env;
 use eyre::Result;
 use tokio::{sync::Mutex, time::sleep};
 
@@ -10,6 +11,8 @@ use config::{networks, Config};
 
 #[tokio::main]
 async fn main() -> Result<()> {
+    env_logger::Builder::from_env(Env::default().default_filter_or("info")).init();
+
     let cli = Cli::parse();
     let config = match cli.network.as_str() {
         "goerli" => networks::goerli(),
@@ -26,8 +29,7 @@ async fn main() -> Result<()> {
     let client = Arc::new(Mutex::new(client));
 
     let mut rpc = Rpc::new(client.clone(), cli.port.unwrap_or(8545));
-    let addr = rpc.start().await?;
+    rpc.start().await?;
-    println!("started rpc at: {}", addr);
 
     loop {
         sleep(Duration::from_secs(10)).await;

client/Cargo.toml

@@ -19,6 +19,7 @@ revm = "1.9.0"
 bytes = "1.2.1"
 futures = "0.3.23"
 toml = "0.5.9"
+log = "0.4.17"
 
 common = { path = "../common" }
 consensus = { path = "../consensus" }

client/src/rpc.rs

@@ -3,6 +3,7 @@ use ethers::{
     types::{Address, Transaction, TransactionReceipt, H256},
 };
 use eyre::Result;
+use log::{error, info};
 use std::{fmt::Display, net::SocketAddr, str::FromStr, sync::Arc};
 use tokio::sync::Mutex;
 
@@ -38,6 +39,9 @@ impl Rpc {
         };
         let (handle, addr) = start(rpc_inner).await?;
         self.handle = Some(handle);
+
+        info!("rpc server strated at {}", addr);
+
         Ok(addr)
     }
 }
@@ -232,7 +236,7 @@ async fn start(rpc: RpcInner) -> Result<(HttpServerHandle, SocketAddr)> {
 
 fn convert_err<T, E: Display>(res: Result<T, E>) -> Result<T, Error> {
     res.map_err(|err| {
-        println!("{}", err.to_string());
+        error!("{}", err);
         Error::Custom(err.to_string())
     })
 }

config/configs/goerli.toml

@@ -1,5 +1,6 @@
 [general]
 chain_id = 5
+genesis_time = 1616508000
 genesis_root = "0x043db0d9a83813551ee2f33450d23797757d430911a9320530ad8a0eabc43efb"
 checkpoint = "0x172128eadf1da46467f4d6a822206698e2d3f957af117dd650954780d680dc99"
 consensus_rpc = "http://testing.prater.beacon-api.nimbus.team"

config/src/lib.rs

@@ -16,6 +16,7 @@ pub struct Config {
 #[derive(Deserialize, Debug)]
 pub struct General {
     pub chain_id: u64,
+    pub genesis_time: u64,
     #[serde(deserialize_with = "bytes_deserialize")]
     pub genesis_root: Vec<u8>,
     #[serde(deserialize_with = "bytes_deserialize")]

config/src/networks.rs

@@ -6,6 +6,7 @@ pub fn goerli() -> Config {
     Config {
         general: General {
             chain_id: 5,
+            genesis_time: 1616508000,
             genesis_root: hex_str_to_bytes(
                 "0x043db0d9a83813551ee2f33450d23797757d430911a9320530ad8a0eabc43efb",
             )

consensus/Cargo.toml

@@ -21,6 +21,8 @@ bytes = "1.2.1"
 futures = "0.3.23"
 toml = "0.5.9"
 async-trait = "0.1.57"
+log = "0.4.17"
+chrono = "0.4.22"
 
 common = { path = "../common" }
 config = { path = "../config" }

consensus/src/consensus.rs

@@ -1,9 +1,12 @@
 use std::cmp;
 use std::sync::Arc;
+use std::time::UNIX_EPOCH;
 
 use blst::min_pk::{PublicKey, Signature};
 use blst::BLST_ERROR;
+use chrono::Duration;
 use eyre::Result;
+use log::info;
 use ssz_rs::prelude::*;
 
 use common::types::*;
@@ -283,9 +286,17 @@ impl<R: Rpc> ConsensusClient<R> {
             self.store.next_sync_committee = Some(update.next_sync_committee.clone());
         }
 
-        println!(
+        let participation =
-            "applying update for slot: {}",
+            get_bits(&update.sync_aggregate.sync_committee_bits) as f32 / 512_f32 * 100f32;
-            self.store.finalized_header.slot
+        let delay = self.get_delay(self.store.finalized_header.slot);
+
+        info!(
+            "applying update                slot={}  confidence={:.2}%  delay={:02}:{:02}:{:02}",
+            self.store.finalized_header.slot,
+            participation,
+            delay.num_hours(),
+            delay.num_minutes(),
+            delay.num_seconds(),
         );
     }
 
@@ -297,9 +308,17 @@ impl<R: Rpc> ConsensusClient<R> {
             self.store.current_max_active_participants =
                 get_bits(&update.sync_aggregate.sync_committee_bits);
 
-            println!(
+            let participation =
-                "applying finality update for slot: {}",
+                get_bits(&update.sync_aggregate.sync_committee_bits) as f32 / 512_f32 * 100f32;
-                self.store.finalized_header.slot
+            let delay = self.get_delay(self.store.finalized_header.slot);
+
+            info!(
+                "applying finality update       slot={}  confidence={:.2}%  delay={:02}:{:02}:{:02}",
+                self.store.finalized_header.slot,
+                participation,
+                delay.num_hours(),
+                delay.num_minutes(),
+                delay.num_seconds(),
             );
         }
 
@@ -324,9 +343,17 @@ impl<R: Rpc> ConsensusClient<R> {
         {
             self.store.optimistic_header = update.attested_header.clone();
 
-            println!(
+            let participation =
-                "applying optimistic update for slot: {}",
+                get_bits(&update.sync_aggregate.sync_committee_bits) as f32 / 512_f32 * 100f32;
-                self.store.optimistic_header.slot
+            let delay = self.get_delay(update.attested_header.slot);
+
+            info!(
+                "applying optimistic update     slot={}  confidence={:.2}%  delay={:02}:{:02}:{:02}",
+                self.store.optimistic_header.slot,
+                participation,
+                delay.num_hours(),
+                delay.num_minutes(),
+                delay.num_seconds(),
             );
         }
     }
@@ -345,6 +372,15 @@ impl<R: Rpc> ConsensusClient<R> {
         let domain = compute_domain(domain_type, fork_version, genesis_root)?;
         compute_signing_root(header, domain)
     }
+
+    fn get_delay(&self, slot: u64) -> Duration {
+        let expected_time = slot * 12 + self.config.general.genesis_time;
+        let now = std::time::SystemTime::now()
+            .duration_since(UNIX_EPOCH)
+            .unwrap();
+        let delay = now - std::time::Duration::from_secs(expected_time);
+        chrono::Duration::from_std(delay).unwrap()
+    }
 }
 
 fn get_participating_keys(

execution/src/execution.rs

@@ -175,7 +175,6 @@ impl<R: Rpc> ExecutionClient<R> {
 
         let expected_receipt_root = ordered_trie_root(receipts_encoded);
         let expected_receipt_root = H256::from_slice(&expected_receipt_root.to_fixed_bytes());
-        println!("{}", hex::encode(expected_receipt_root));
         let payload_receipt_root = H256::from_slice(&payload.receipts_root);
 
         if expected_receipt_root != payload_receipt_root || !receipts.contains(&receipt) {