Logging

6 files changed, 87 insertions, 38 deletions

diff --git a/Cargo.lock b/Cargo.lock
index 56121f9..7f65bd7 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -247,6 +247,19 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
 [[package]]
+name = "chrono"
+version = "0.4.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73"
+dependencies = [
+ "libc",
+ "num-integer",
+ "num-traits",
+ "time",
+ "winapi 0.3.9",
+]
+
+[[package]]
 name = "clap"
 version = "2.33.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -297,9 +310,9 @@ dependencies = [
 
 [[package]]
 name = "env_logger"
-version = "0.7.1"
+version = "0.8.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
+checksum = "f26ecb66b4bdca6c1409b40fb255eefc2bd4f6d135dab3c3124f80ffa2a9661e"
 dependencies = [
  "atty",
  "humantime",
@@ -535,12 +548,9 @@ checksum = "644f9158b2f133fd50f5fb3242878846d9eb792e445c893805ff0e3824006e35"
 
 [[package]]
 name = "humantime"
-version = "1.3.0"
+version = "2.0.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
-dependencies = [
- "quick-error",
-]
+checksum = "3c1ad908cc71012b7bea4d0c53ba96a8cba9962f048fa68d143376143d863b7a"
 
 [[package]]
 name = "instant"
@@ -757,13 +767,13 @@ dependencies = [
  "async-trait",
  "base64",
  "bytes 0.6.0",
+ "chrono",
  "env_logger",
  "err-derive",
  "hex",
  "kuska-handshake",
  "log",
  "lru",
- "pretty_env_logger",
  "rand",
  "rmp-serde",
  "serde",
@@ -773,6 +783,16 @@ dependencies = [
 ]
 
 [[package]]
+name = "num-integer"
+version = "0.1.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d2cc698a63b549a70bc047073d2949cce27cd1c7b0a4a862d08a8031bc2801db"
+dependencies = [
+ "autocfg",
+ "num-traits",
+]
+
+[[package]]
 name = "num-traits"
 version = "0.2.14"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -855,16 +875,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "pretty_env_logger"
-version = "0.4.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
-dependencies = [
- "env_logger",
- "log",
-]
-
-[[package]]
 name = "proc-macro-error"
 version = "1.0.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -910,12 +920,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "quick-error"
-version = "1.2.3"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
-
-[[package]]
 name = "quote"
 version = "1.0.7"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1179,6 +1183,17 @@ dependencies = [
 ]
 
 [[package]]
+name = "time"
+version = "0.1.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6db9e6914ab8b1ae1c260a4ae7a49b6c5611b40328a735b21862567685e73255"
+dependencies = [
+ "libc",
+ "wasi",
+ "winapi 0.3.9",
+]
+
+[[package]]
 name = "tokio"
 version = "0.2.23"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1256,6 +1271,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9d5b2c62b4012a3e1eca5a7e077d13b3bf498c4073e33ccd58626607748ceeca"
 
 [[package]]
+name = "wasi"
+version = "0.10.0+wasi-snapshot-preview1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f"
+
+[[package]]
 name = "wasm-bindgen"
 version = "0.2.69"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/Cargo.toml b/Cargo.toml
index 4877b79..e018af7 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -17,10 +17,10 @@ base64 = "0.12.1"
 
 structopt = { version = "0.3", default-features = false }
 rand = "0.5.5"
+chrono = "0.4"
 
 log = "0.4.8"
-pretty_env_logger = "0.4"
-env_logger = "0.7.1"
+env_logger = "0.8"
 arc-swap = "1.0"
 async-trait = "0.1.7"
 err-derive = "0.2.3"
@@ -30,3 +30,4 @@ lru = "0.6"
 sodiumoxide = { git = "https://github.com/Dhole/sodiumoxidez", branch = "extra" }
 #kuska-handshake = { path = "../handshake", features = ["default", "tokio_compat"] }
 kuska-handshake = { git = "https://github.com/kuska-ssb/handshake", branch = "master", features = ["default", "tokio_compat"] }
+
diff --git a/Dockerfile b/Dockerfile
index a179597..ea676ac 100644
--- a/Dockerfile
+++ b/Dockerfile
@@ -4,6 +4,6 @@ COPY target/release/examples/basalt /root/basalt
 
 CMD /root/basalt
 ENV RUST_BACKTRACE=1
-ENV RUST_LOG=netapp=debug,basalt=debug
+ENV RUST_LOG=netapp=info,netapp::peering=debug,basalt=info
 
 CMD /garage/garage server -c /garage/config.toml
diff --git a/examples/basalt.rs b/examples/basalt.rs
index e09f627..141069a 100644
--- a/examples/basalt.rs
+++ b/examples/basalt.rs
@@ -1,8 +1,9 @@
 use std::net::SocketAddr;
 use std::sync::Arc;
 use std::time::Duration;
+use std::io::Write;
 
-use log::{info, warn};
+use log::{debug, info, warn};
 
 use structopt::StructOpt;
 use serde::{Deserialize, Serialize};
@@ -48,7 +49,18 @@ pub struct Opt {
 
 #[tokio::main]
 async fn main() {
-	pretty_env_logger::init();
+	env_logger::Builder::new()
+		.parse_env("RUST_LOG")
+		.format(|buf, record| {
+			writeln!(buf,
+					 "{} {} {}",
+					 chrono::Local::now().format("%s%.6f"),
+					 record.level(),
+					 record.args()
+					)
+		})
+		.init();
+
 
 	let opt = Opt::from_args();
 
@@ -56,7 +68,7 @@ async fn main() {
 		Some(k) => auth::Key::from_slice(&hex::decode(k).unwrap()).unwrap(),
 		None => auth::gen_key(),
 	};
-	info!("Network key: {}", hex::encode(&netid));
+	info!("KYEV NK {}", hex::encode(&netid));
 
 	let privkey = match &opt.private_key {
 		Some(k) => ed25519::SecretKey::from_slice(&hex::decode(k).unwrap()).unwrap(),
@@ -66,8 +78,8 @@ async fn main() {
 		}
 	};
 
-	info!("Node private key: {}", hex::encode(&privkey));
-	info!("Node public key: {}", hex::encode(&privkey.public_key()));
+	info!("KYEV SK {}", hex::encode(&privkey));
+	info!("KYEV PK {}", hex::encode(&privkey.public_key()));
 
 	let listen_addr = opt.listen_addr.parse().unwrap();
 	let netapp = NetApp::new(listen_addr, netid, privkey);
@@ -93,7 +105,7 @@ async fn main() {
 
 	netapp.add_msg_handler::<ExampleMessage, _, _>(
 		|_from: ed25519::PublicKey, msg: ExampleMessage| {
-			info!("Got example message: {:?}, sending example response", msg);
+			debug!("Got example message: {:?}, sending example response", msg);
 			async {
 				ExampleResponse{example_field: false}
 			}
@@ -115,14 +127,14 @@ async fn sampling_loop(netapp: Arc<NetApp>, basalt: Arc<Basalt>) {
 
 		let peers = basalt.sample(10);
 		for p in peers {
-			info!("Sampled: {}", hex::encode(p));
+			info!("KYEV S {}", hex::encode(p));
 
 			let netapp2 = netapp.clone();
 			tokio::spawn(async move {
 				match netapp2.request(&p, ExampleMessage{
 					example_field: 42,
 				}, PRIO_NORMAL).await {
-					Ok(resp) => info!("Got example response: {:?}", resp),
+					Ok(resp) => debug!("Got example response: {:?}", resp),
 					Err(e) => warn!("Error with example request: {}", e),
 				}
 			});
diff --git a/examples/fullmesh.rs b/examples/fullmesh.rs
index af315fb..a61ab3d 100644
--- a/examples/fullmesh.rs
+++ b/examples/fullmesh.rs
@@ -28,7 +28,17 @@ pub struct Opt {
 
 #[tokio::main]
 async fn main() {
-	pretty_env_logger::init();
+	env_logger::Builder::new()
+		.parse_env("RUST_LOG")
+		.format(|buf, record| {
+			writeln!(buf,
+					 "{} {} {}",
+					 chrono::Local::now().format("%s%.6f"),
+					 record.level(),
+					 record.args()
+					)
+		})
+		.init();
 
 	let opt = Opt::from_args();
 
diff --git a/src/peering/basalt.rs b/src/peering/basalt.rs
index 5da65e0..00cfd60 100644
--- a/src/peering/basalt.rs
+++ b/src/peering/basalt.rs
@@ -3,7 +3,7 @@ use std::net::SocketAddr;
 use std::sync::{Arc, RwLock};
 use std::time::Duration;
 
-use log::{debug, warn};
+use log::{debug, info, warn};
 use lru::LruCache;
 use rand::{thread_rng, Rng};
 use serde::{Deserialize, Serialize};
@@ -302,7 +302,10 @@ impl Basalt {
 			.unwrap()
 			.sample(count)
 			.iter()
-			.map(|p| p.id)
+			.map(|p| {
+				info!("KYEV S {}", hex::encode(p.id));
+				p.id
+			})
 			.collect::<Vec<_>>()
 	}
 
@@ -421,6 +424,7 @@ impl Basalt {
 		if is_incoming {
 			self.handle_peer_list(&[Peer { id: pk, addr }][..]);
 		} else {
+			info!("KYEV C {}", hex::encode(pk));
 			let peer = Peer { id: pk, addr };
 
 			let mut backlog = self.backlog.write().unwrap();
@@ -443,6 +447,7 @@ impl Basalt {
 
 	fn on_disconnected(&self, pk: ed25519::PublicKey, is_incoming: bool) {
 		if !is_incoming {
+			info!("KYEV D {}", hex::encode(pk));
 			self.view.write().unwrap().disconnected(pk);
 		}
 	}