Pretty logging

Cargo.lock

@@ -1,5 +1,13 @@
 # This file is automatically @generated by Cargo.
 # It is not intended for manual editing.
+[[package]]
+name = "aho-corasick"
+version = "0.7.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "memchr 2.3.3 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "arc-swap"
 version = "0.4.5"
@@ -15,6 +23,16 @@ dependencies = [
  "syn 1.0.17 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "atty"
+version = "0.2.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "hermit-abi 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)",
+ "libc 0.2.68 (registry+https://github.com/rust-lang/crates.io-index)",
+ "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "autocfg"
 version = "1.0.0"
@@ -25,15 +43,6 @@ name = "base64"
 version = "0.11.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
-[[package]]
-name = "bincode"
-version = "1.2.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-dependencies = [
- "byteorder 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)",
- "serde 1.0.106 (registry+https://github.com/rust-lang/crates.io-index)",
-]
-
 [[package]]
 name = "bitflags"
 version = "1.2.1"
@@ -155,6 +164,18 @@ dependencies = [
  "generic-array 0.12.3 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "env_logger"
+version = "0.7.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "atty 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)",
+ "humantime 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)",
+ "regex 1.3.7 (registry+https://github.com/rust-lang/crates.io-index)",
+ "termcolor 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "err-derive"
 version = "0.2.3"
@@ -297,7 +318,6 @@ version = "0.1.0"
 dependencies = [
  "arc-swap 0.4.5 (registry+https://github.com/rust-lang/crates.io-index)",
  "async-trait 0.1.30 (registry+https://github.com/rust-lang/crates.io-index)",
- "bincode 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)",
  "err-derive 0.2.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "futures 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -309,8 +329,9 @@ dependencies = [
  "http 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "hyper 0.13.4 (registry+https://github.com/rust-lang/crates.io-index)",
  "hyper-rustls 0.20.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)",
+ "pretty_env_logger 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "rand 0.7.3 (registry+https://github.com/rust-lang/crates.io-index)",
- "reduce 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)",
  "rmp-serde 0.14.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "rustls 0.17.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "serde 1.0.106 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -415,6 +436,14 @@ name = "httparse"
 version = "1.3.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
+[[package]]
+name = "humantime"
+version = "1.3.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "quick-error 1.2.3 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "hyper"
 version = "0.13.4"
@@ -681,6 +710,15 @@ name = "ppv-lite86"
 version = "0.2.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
+[[package]]
+name = "pretty_env_logger"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "env_logger 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "proc-macro-error"
 version = "0.4.12"
@@ -723,6 +761,11 @@ dependencies = [
  "unicode-xid 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "quick-error"
+version = "1.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+
 [[package]]
 name = "quote"
 version = "1.0.3"
@@ -774,8 +817,19 @@ version = "0.1.56"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
-name = "reduce"
+name = "regex"
-version = "0.1.2"
+version = "1.3.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "aho-corasick 0.7.10 (registry+https://github.com/rust-lang/crates.io-index)",
+ "memchr 2.3.3 (registry+https://github.com/rust-lang/crates.io-index)",
+ "regex-syntax 0.6.17 (registry+https://github.com/rust-lang/crates.io-index)",
+ "thread_local 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.17"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
@@ -1002,6 +1056,14 @@ dependencies = [
  "unicode-xid 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "termcolor"
+version = "1.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "winapi-util 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "textwrap"
 version = "0.11.0"
@@ -1010,6 +1072,14 @@ dependencies = [
  "unicode-width 0.1.7 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.0.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "lazy_static 1.4.0 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "time"
 version = "0.1.42"
@@ -1230,6 +1300,14 @@ name = "winapi-i686-pc-windows-gnu"
 version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
+[[package]]
+name = "winapi-util"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "winapi-x86_64-pc-windows-gnu"
 version = "0.4.0"
@@ -1245,11 +1323,12 @@ dependencies = [
 ]
 
 [metadata]
+"checksum aho-corasick 0.7.10 (registry+https://github.com/rust-lang/crates.io-index)" = "8716408b8bc624ed7f65d223ddb9ac2d044c0547b6fa4b0d554f3a9540496ada"
 "checksum arc-swap 0.4.5 (registry+https://github.com/rust-lang/crates.io-index)" = "d663a8e9a99154b5fb793032533f6328da35e23aac63d5c152279aa8ba356825"
 "checksum async-trait 0.1.30 (registry+https://github.com/rust-lang/crates.io-index)" = "da71fef07bc806586090247e971229289f64c210a278ee5ae419314eb386b31d"
+"checksum atty 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)" = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
 "checksum autocfg 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "f8aac770f1885fd7e387acedd76065302551364496e46b3dd00860b2f8359b9d"
 "checksum base64 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)" = "b41b7ea54a0c9d92199de89e20e58d49f02f8e699814ef3fdf266f6f748d15c7"
-"checksum bincode 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "5753e2a71534719bf3f4e57006c3a4f0d2c672a4b676eec84161f763eca87dbf"
 "checksum bitflags 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "cf1de2fe8c75bc145a2f577add951f8134889b4795d47466a54a5c846d691693"
 "checksum block-buffer 0.7.3 (registry+https://github.com/rust-lang/crates.io-index)" = "c0940dc441f31689269e10ac70eb1002a3a1d3ad1390e030043662eb7fe4688b"
 "checksum block-padding 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "fa79dedbb091f449f1f39e53edf88d5dbe95f895dae6135a8d7b881fb5af73f5"
@@ -1266,6 +1345,7 @@ dependencies = [
 "checksum crossbeam-epoch 0.8.2 (registry+https://github.com/rust-lang/crates.io-index)" = "058ed274caafc1f60c4997b5fc07bf7dc7cca454af7c6e81edffe5f33f70dace"
 "checksum crossbeam-utils 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)" = "c3c7c73a2d1e9fc0886a08b93e98eb643461230d5f1925e4036204d5f2e261a8"
 "checksum digest 0.8.1 (registry+https://github.com/rust-lang/crates.io-index)" = "f3d0c8c8752312f9713efd397ff63acb9f85585afbf179282e720e7704954dd5"
+"checksum env_logger 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)" = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
 "checksum err-derive 0.2.3 (registry+https://github.com/rust-lang/crates.io-index)" = "82f46c91bbed409ee74495549acbfcc7fae856e712e1df15afe75d0775eedc6c"
 "checksum fake-simd 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "e88a8acf291dafb59c2d96e8f59828f3838bb1a70398823ade51a84de6a6deed"
 "checksum fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)" = "2fad85553e09a6f881f739c29f0b00b0f01357c743266d478b68951ce23285f3"
@@ -1292,6 +1372,7 @@ dependencies = [
 "checksum http 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "28d569972648b2c512421b5f2a405ad6ac9666547189d0c5477a3f200f3e02f9"
 "checksum http-body 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)" = "13d5ff830006f7646652e057693569bfe0d51760c0085a071769d142a205111b"
 "checksum httparse 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)" = "cd179ae861f0c2e53da70d892f5f3029f9594be0c41dc5269cd371691b1dc2f9"
+"checksum humantime 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)" = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
 "checksum hyper 0.13.4 (registry+https://github.com/rust-lang/crates.io-index)" = "ed6081100e960d9d74734659ffc9cc91daf1c0fc7aceb8eaa94ee1a3f5046f2e"
 "checksum hyper-rustls 0.20.0 (registry+https://github.com/rust-lang/crates.io-index)" = "ac965ea399ec3a25ac7d13b8affd4b8f39325cca00858ddf5eb29b79e6b14b08"
 "checksum indexmap 1.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "076f042c5b7b98f31d205f1249267e12a6518c1481e9dae9764af19b707d2292"
@@ -1322,18 +1403,21 @@ dependencies = [
 "checksum pin-project-lite 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)" = "237844750cfbb86f67afe27eee600dfbbcb6188d734139b534cbfbf4f96792ae"
 "checksum pin-utils 0.1.0-alpha.4 (registry+https://github.com/rust-lang/crates.io-index)" = "5894c618ce612a3fa23881b152b608bafb8c56cfc22f434a3ba3120b40f7b587"
 "checksum ppv-lite86 0.2.6 (registry+https://github.com/rust-lang/crates.io-index)" = "74490b50b9fbe561ac330df47c08f3f33073d2d00c150f719147d7c54522fa1b"
+"checksum pretty_env_logger 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
 "checksum proc-macro-error 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)" = "18f33027081eba0a6d8aba6d1b1c3a3be58cbb12106341c2d5759fcd9b5277e7"
 "checksum proc-macro-error-attr 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)" = "8a5b4b77fdb63c1eca72173d68d24501c54ab1269409f6b672c85deb18af69de"
 "checksum proc-macro-hack 0.5.15 (registry+https://github.com/rust-lang/crates.io-index)" = "0d659fe7c6d27f25e9d80a1a094c223f5246f6a6596453e09d7229bf42750b63"
 "checksum proc-macro-nested 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)" = "8e946095f9d3ed29ec38de908c22f95d9ac008e424c7bcae54c75a79c527c694"
 "checksum proc-macro2 1.0.10 (registry+https://github.com/rust-lang/crates.io-index)" = "df246d292ff63439fea9bc8c0a270bed0e390d5ebd4db4ba15aba81111b5abe3"
+"checksum quick-error 1.2.3 (registry+https://github.com/rust-lang/crates.io-index)" = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
 "checksum quote 1.0.3 (registry+https://github.com/rust-lang/crates.io-index)" = "2bdc6c187c65bca4260c9011c9e3132efe4909da44726bad24cf7572ae338d7f"
 "checksum rand 0.7.3 (registry+https://github.com/rust-lang/crates.io-index)" = "6a6b1679d49b24bbfe0c803429aa1874472f50d9b363131f0e89fc356b544d03"
 "checksum rand_chacha 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "f4c8ed856279c9737206bf725bf36935d8666ead7aa69b52be55af369d193402"
 "checksum rand_core 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)" = "90bde5296fc891b0cef12a6d03ddccc162ce7b2aff54160af9338f8d40df6d19"
 "checksum rand_hc 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "ca3129af7b92a17112d59ad498c6f81eaf463253766b90396d39ea7a39d6613c"
 "checksum redox_syscall 0.1.56 (registry+https://github.com/rust-lang/crates.io-index)" = "2439c63f3f6139d1b57529d16bc3b8bb855230c8efcc5d3a896c8bea7c3b1e84"
-"checksum reduce 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "75b1fa5668b02f2a69746bba558f8f98cc087b123a587fd959122872ad9a3f3c"
+"checksum regex 1.3.7 (registry+https://github.com/rust-lang/crates.io-index)" = "a6020f034922e3194c711b82a627453881bc4682166cabb07134a10c26ba7692"
+"checksum regex-syntax 0.6.17 (registry+https://github.com/rust-lang/crates.io-index)" = "7fe5bd57d1d7414c6b5ed48563a2c855d995ff777729dcd91c369ec7fea395ae"
 "checksum ring 0.16.12 (registry+https://github.com/rust-lang/crates.io-index)" = "1ba5a8ec64ee89a76c98c549af81ff14813df09c3e6dc4766c3856da48597a0c"
 "checksum rmp 0.8.9 (registry+https://github.com/rust-lang/crates.io-index)" = "0f10b46df14cf1ee1ac7baa4d2fbc2c52c0622a4b82fa8740e37bc452ac0184f"
 "checksum rmp-serde 0.14.3 (registry+https://github.com/rust-lang/crates.io-index)" = "4c1ee98f14fe8b8e9c5ea13d25da7b2a1796169202c57a09d7288de90d56222b"
@@ -1358,7 +1442,9 @@ dependencies = [
 "checksum syn 1.0.17 (registry+https://github.com/rust-lang/crates.io-index)" = "0df0eb663f387145cab623dea85b09c2c5b4b0aef44e945d928e682fce71bb03"
 "checksum syn-mid 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7be3539f6c128a931cf19dcee741c1af532c7fd387baa739c03dd2e96479338a"
 "checksum synstructure 0.12.3 (registry+https://github.com/rust-lang/crates.io-index)" = "67656ea1dc1b41b1451851562ea232ec2e5a80242139f7e679ceccfb5d61f545"
+"checksum termcolor 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f"
 "checksum textwrap 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)" = "d326610f408c7a4eb6f51c37c330e496b08506c9457c9d34287ecc38809fb060"
+"checksum thread_local 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)" = "d40c6d1b69745a6ec6fb1ca717914848da4b44ae29d9b3080cbee91d72a69b14"
 "checksum time 0.1.42 (registry+https://github.com/rust-lang/crates.io-index)" = "db8dcfca086c1143c9270ac42a2bbd8a7ee477b78ac8e45b19abfb0cbede4b6f"
 "checksum tokio 0.2.16 (registry+https://github.com/rust-lang/crates.io-index)" = "ee5a0dd887e37d37390c13ff8ac830f992307fe30a1fff0ab8427af67211ba28"
 "checksum tokio-macros 0.2.5 (registry+https://github.com/rust-lang/crates.io-index)" = "f0c3acc6aa564495a0f2e1d59fab677cd7f81a19994cfc7f3ad0e64301560389"
@@ -1386,5 +1472,6 @@ dependencies = [
 "checksum winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)" = "8093091eeb260906a183e6ae1abdba2ef5ef2257a21801128899c3fc699229c6"
 "checksum winapi-build 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "2d315eee3b34aca4797b2da6b13ed88266e6d612562a0c46390af8299fc699bc"
 "checksum winapi-i686-pc-windows-gnu 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
+"checksum winapi-util 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178"
 "checksum winapi-x86_64-pc-windows-gnu 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f"
 "checksum ws2_32-sys 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "d59cefebd0c892fa2dd6de581e937301d8552cb44489cdff035c6187cb63fa5e"

Cargo.toml

@@ -8,35 +8,39 @@ edition = "2018"
 
 [dependencies]
 bytes = "0.4"
-http = "0.2"
+rand = "0.7"
-hyper = "0.13"
+hex = "0.3"
+sha2 = "0.8"
+arc-swap = "0.4"
+gethostname = "0.2"
+err-derive = "0.2.3"
+log = "0.4"
+pretty_env_logger = "0.4"
+
 sled = "0.31"
+
+structopt = { version = "0.3", default-features = false }
+toml = "0.5"
+rmp-serde = "0.14.3"
+serde = { version = "1.0", features = ["derive", "rc"] }
+serde_bytes = "0.11"
+serde_json = "1.0"
+
+async-trait = "0.1.30"
 futures = "0.3"
 futures-core = "0.3"
 futures-channel = "0.3"
 futures-util = "0.3"
 tokio = { version = "0.2", features = ["full"] }
-serde = { version = "1.0", features = ["derive", "rc"] }
-serde_bytes = "0.11"
-bincode = "1.2.1"
-err-derive = "0.2.3"
-rmp-serde = "0.14.3"
-toml = "0.5"
-structopt = { version = "0.3", default-features = false }
-rand = "0.7"
-hex = "0.3"
-sha2 = "0.8"
-async-trait = "0.1.30"
-reduce = "0.1.2"
-serde_json = "1.0"
-arc-swap = "0.4"
-gethostname = "0.2"
 
+http = "0.2"
+hyper = "0.13"
 rustls = "0.17"
 tokio-rustls = "0.13"
 hyper-rustls = { version = "0.20", default-features = false }
 webpki = "0.21"
 
+
 [profile.dev]
 lto = "off"
 

README.md

@@ -3,3 +3,9 @@
 THIS IS ALL WORK IN PROGRESS. NOTHING TO SEE YET BUT THANKS FOR YOUR INTEREST.
 
 Garage implements an S3-compatible object store with high resiliency to network failures, machine failure, and sysadmin failure.
+
+## To log:
+
+```
+RUST_LOG=garage=debug cargo run --release -- server -c config_file.toml
+```

src/admin_rpc.rs

@@ -222,12 +222,15 @@ impl AdminRpcHandler {
 			let version_exists = match object {
 				Some(o) => o.versions.iter().any(|x| x.uuid == version.uuid),
 				None => {
-					eprintln!("No object entry found for version {:?}", version);
+					warn!(
+						"Repair versions: object for version {:?} not found",
+						version
+					);
 					false
 				}
 			};
 			if !version_exists {
-				eprintln!("Marking deleted version: {:?}", version);
+				info!("Repair versions: marking version as deleted: {:?}", version);
 				self.garage
 					.version_table
 					.insert(&Version {
@@ -265,12 +268,18 @@ impl AdminRpcHandler {
 			let ref_exists = match version {
 				Some(v) => !v.deleted,
 				None => {
-					eprintln!("No version found for block ref {:?}", block_ref);
+					warn!(
+						"Block ref repair: version for block ref {:?} not found",
+						block_ref
+					);
 					false
 				}
 			};
 			if !ref_exists {
-				eprintln!("Marking deleted block_ref: {:?}", block_ref);
+				info!(
+					"Repair block ref: marking block_ref as deleted: {:?}",
+					block_ref
+				);
 				self.garage
 					.block_ref_table
 					.insert(&BlockRef {

src/api_server.rs

@@ -42,7 +42,7 @@ pub async fn run_api_server(
 	let server = Server::bind(&addr).serve(service);
 
 	let graceful = server.with_graceful_shutdown(shutdown_signal);
-	println!("API server listening on http://{}", addr);
+	info!("API server listening on http://{}", addr);
 
 	graceful.await?;
 	Ok(())
@@ -69,7 +69,7 @@ async fn handler_inner(
 	req: Request<Body>,
 	addr: SocketAddr,
 ) -> Result<Response<BodyType>, Error> {
-	eprintln!("{} {} {}", addr, req.method(), req.uri());
+	info!("{} {} {}", addr, req.method(), req.uri());
 
 	let bucket = req
 		.headers()
@@ -231,7 +231,7 @@ impl BodyChunker {
 		while !self.read_all && self.buf.len() < self.block_size {
 			if let Some(block) = self.body.next().await {
 				let bytes = block?;
-				eprintln!("Body next: {} bytes", bytes.len());
+				trace!("Body next: {} bytes", bytes.len());
 				self.buf.extend(&bytes[..]);
 			} else {
 				self.read_all = true;

src/background.rs

@@ -77,9 +77,9 @@ impl BackgroundRunner {
 		let stop_signal = self.stop_signal.clone();
 		workers.push(tokio::spawn(async move {
 			if let Err(e) = worker(stop_signal).await {
-				eprintln!("Worker stopped with error: {}, error: {}", name, e);
+				error!("Worker stopped with error: {}, error: {}", name, e);
 			} else {
-				println!("Worker exited successfully: {}", name);
+				info!("Worker exited successfully: {}", name);
 			}
 		}));
 	}
@@ -90,11 +90,11 @@ impl BackgroundRunner {
 			let must_exit: bool = *stop_signal.borrow();
 			if let Some(job) = self.dequeue_job(must_exit).await {
 				if let Err(e) = job.await {
-					eprintln!("Job failed: {}", e)
+					error!("Job failed: {}", e)
 				}
 			} else {
 				if must_exit {
-					eprintln!("Background runner {} exiting", i);
+					info!("Background runner {} exiting", i);
 					return;
 				}
 				tokio::time::delay_for(Duration::from_secs(1)).await;

src/block.rs

@@ -153,7 +153,7 @@ impl BlockManager {
 
 		if data::hash(&data[..]) != *hash {
 			let _lock = self.lock.lock().await;
-			eprintln!("Block {:?} is corrupted. Deleting and resyncing.", hash);
+			warn!("Block {:?} is corrupted. Deleting and resyncing.", hash);
 			fs::remove_file(path).await?;
 			self.put_to_resync(&hash, 0)?;
 			return Err(Error::CorruptData(hash.clone()));
@@ -211,7 +211,7 @@ impl BlockManager {
 
 	fn put_to_resync(&self, hash: &Hash, delay_millis: u64) -> Result<(), Error> {
 		let when = now_msec() + delay_millis;
-		eprintln!("Put resync_queue: {} {:?}", when, hash);
+		trace!("Put resync_queue: {} {:?}", when, hash);
 		let mut key = u64::to_be_bytes(when).to_vec();
 		key.extend(hash.as_ref());
 		self.resync_queue.insert(key, hash.as_ref())?;
@@ -222,7 +222,7 @@ impl BlockManager {
 		while !*must_exit.borrow() {
 			if let Some((time_bytes, hash_bytes)) = self.resync_queue.pop_min()? {
 				let time_msec = u64_from_bytes(&time_bytes[0..8]);
-				eprintln!(
+				trace!(
 					"First in resync queue: {} (now = {})",
 					time_msec,
 					now_msec()
@@ -233,7 +233,7 @@ impl BlockManager {
 					let hash = Hash::from(hash);
 
 					if let Err(e) = self.resync_iter(&hash).await {
-						eprintln!("Failed to resync block {:?}, retrying later: {}", hash, e);
+						warn!("Failed to resync block {:?}, retrying later: {}", hash, e);
 						self.put_to_resync(&hash, RESYNC_RETRY_TIMEOUT.as_millis() as u64)?;
 					}
 					continue;
@@ -256,10 +256,12 @@ impl BlockManager {
 			.map(|x| u64_from_bytes(x.as_ref()) > 0)
 			.unwrap_or(false);
 
-		eprintln!(
+		if exists != needed {
-			"Resync block {:?}: exists {}, needed {}",
+			info!(
-			hash, exists, needed
+				"Resync block {:?}: exists {}, needed {}",
-		);
+				hash, exists, needed
+			);
+		}
 
 		if exists && !needed {
 			let garage = self.garage.load_full().unwrap();
@@ -396,7 +398,7 @@ impl BlockManager {
 
 			let mut ls_data_dir_2 = match fs::read_dir(data_dir_ent.path()).await {
 				Err(e) => {
-					eprintln!(
+					warn!(
 						"Warning: could not list dir {:?}: {}",
 						data_dir_ent.path().to_str(),
 						e

src/main.rs

@@ -1,5 +1,8 @@
 #![recursion_limit = "1024"]
 
+#[macro_use]
+extern crate log;
+
 mod data;
 mod error;
 
@@ -190,6 +193,8 @@ pub struct RepairOpt {
 
 #[tokio::main]
 async fn main() {
+	pretty_env_logger::init();
+
 	let opt = Opt::from_args();
 
 	let tls_config = match (opt.ca_cert, opt.client_cert, opt.client_key) {
@@ -200,7 +205,7 @@ async fn main() {
 		}),
 		(None, None, None) => None,
 		_ => {
-			eprintln!("Missing one of: --ca-cert, --node-cert, --node-key. Not using TLS.");
+			warn!("Missing one of: --ca-cert, --node-cert, --node-key. Not using TLS.");
 			None
 		}
 	};
@@ -215,7 +220,7 @@ async fn main() {
 		Command::Server(server_opt) => {
 			// Abort on panic (same behavior as in Go)
 			std::panic::set_hook(Box::new(|panic_info| {
-				eprintln!("{}", panic_info.to_string());
+				error!("{}", panic_info.to_string());
 				std::process::abort();
 			}));
 
@@ -237,7 +242,7 @@ async fn main() {
 	};
 
 	if let Err(e) = resp {
-		eprintln!("Error: {}", e);
+		error!("Error: {}", e);
 	}
 }
 
@@ -414,7 +419,7 @@ async fn cmd_admin(
 			println!("{:?}", bucket);
 		}
 		r => {
-			eprintln!("Unexpected response: {:?}", r);
+			error!("Unexpected response: {:?}", r);
 		}
 	}
 	Ok(())

src/membership.rs

@@ -133,7 +133,7 @@ impl Status {
 		);
 		match old_status {
 			None => {
-				eprintln!("Newly pingable node: {}", hex::encode(&info.id));
+				info!("Newly pingable node: {}", hex::encode(&info.id));
 				true
 			}
 			Some(x) => x.addr != addr,
@@ -145,12 +145,12 @@ impl Status {
 		nodes.sort_unstable_by_key(|(id, _status)| *id);
 
 		let mut hasher = Sha256::new();
-		eprintln!("Current set of pingable nodes: --");
+		debug!("Current set of pingable nodes: --");
 		for (id, status) in nodes {
-			eprintln!("{} {}", hex::encode(&id), status.addr);
+			debug!("{} {}", hex::encode(&id), status.addr);
 			hasher.input(format!("{} {}\n", hex::encode(&id), status.addr));
 		}
-		eprintln!("END --");
+		debug!("END --");
 		self.hash
 			.as_slice_mut()
 			.copy_from_slice(&hasher.result()[..]);
@@ -263,7 +263,7 @@ impl System {
 		let net_config = match read_network_config(&config.metadata_dir) {
 			Ok(x) => x,
 			Err(e) => {
-				println!(
+				info!(
 					"No valid previous network configuration stored ({}), starting fresh.",
 					e
 				);
@@ -448,7 +448,7 @@ impl System {
 					.map(|x| x.remaining_ping_attempts)
 					.unwrap_or(0);
 				if remaining_attempts == 0 {
-					eprintln!(
+					warn!(
 						"Removing node {} after too many failed pings",
 						hex::encode(&id)
 					);
@@ -465,7 +465,7 @@ impl System {
 			status.recalculate_hash();
 		}
 		if let Err(e) = update_locked.0.broadcast(Arc::new(status)) {
-			eprintln!("In ping_nodes: could not save status update ({})", e);
+			error!("In ping_nodes: could not save status update ({})", e);
 		}
 		drop(update_locked);
 

src/rpc_client.rs

@@ -221,7 +221,7 @@ impl RpcHttpClient {
 		let resp = tokio::time::timeout(timeout, resp_fut)
 			.await?
 			.map_err(|e| {
-				eprintln!(
+				warn!(
 					"RPC HTTP client error when connecting to {}: {}",
 					to_addr, e
 				);

src/rpc_server.rs

@@ -1,6 +1,7 @@
 use std::collections::HashMap;
 use std::net::SocketAddr;
 use std::pin::Pin;
+use std::time::Instant;
 use std::sync::Arc;
 
 use bytes::IntoBuf;
@@ -36,17 +37,21 @@ async fn handle_func<M, F, Fut>(
 	handler: Arc<F>,
 	req: Request<Body>,
 	sockaddr: SocketAddr,
+	name: Arc<String>,
 ) -> Result<Response<Body>, Error>
 where
 	M: RpcMessage + 'static,
 	F: Fn(M, SocketAddr) -> Fut + Send + Sync + 'static,
 	Fut: Future<Output = Result<M, Error>> + Send + 'static,
 {
+	let begin_time = Instant::now();
 	let whole_body = hyper::body::to_bytes(req.into_body()).await?;
 	let msg = rmp_serde::decode::from_read::<_, M>(whole_body.into_buf())?;
+	let req_str = debug_serialize(&msg);
 	match handler(msg, sockaddr).await {
 		Ok(resp) => {
 			let resp_bytes = rmp_to_vec_all_named::<Result<M, String>>(&Ok(resp))?;
+			trace!("]RPC:{},ok ({} ms)", name, (Instant::now()-begin_time).as_millis());
 			Ok(Response::new(Body::from(resp_bytes)))
 		}
 		Err(e) => {
@@ -54,6 +59,7 @@ where
 			let rep_bytes = rmp_to_vec_all_named::<Result<M, String>>(&Err(err_str))?;
 			let mut err_response = Response::new(Body::from(rep_bytes));
 			*err_response.status_mut() = e.http_status_code();
+			warn!("RPC error ({}): {} ({} ms), request: {}", name, e, (Instant::now()-begin_time).as_millis(), req_str);
 			Ok(err_response)
 		}
 	}
@@ -74,10 +80,11 @@ impl RpcServer {
 		F: Fn(M, SocketAddr) -> Fut + Send + Sync + 'static,
 		Fut: Future<Output = Result<M, Error>> + Send + 'static,
 	{
+		let name2 = Arc::new(name.clone());
 		let handler_arc = Arc::new(handler);
 		let handler = Box::new(move |req: Request<Body>, sockaddr: SocketAddr| {
 			let handler2 = handler_arc.clone();
-			let b: ResponseFuture = Box::pin(handle_func(handler2, req, sockaddr));
+			let b: ResponseFuture = Box::pin(handle_func(handler2, req, sockaddr, name2.clone()));
 			b
 		});
 		self.handlers.insert(name, handler);
@@ -107,7 +114,7 @@ impl RpcServer {
 		let resp_waiter = tokio::spawn(handler(req, addr));
 		match resp_waiter.await {
 			Err(err) => {
-				eprintln!("Handler await error: {}", err);
+				warn!("Handler await error: {}", err);
 				let mut ise = Response::default();
 				*ise.status_mut() = StatusCode::INTERNAL_SERVER_ERROR;
 				Ok(ise)
@@ -163,7 +170,7 @@ impl RpcServer {
 				async move {
 					Ok::<_, Error>(service_fn(move |req: Request<Body>| {
 						self_arc.clone().handler(req, client_addr).map_err(|e| {
-							eprintln!("RPC handler error: {}", e);
+							warn!("RPC handler error: {}", e);
 							e
 						})
 					}))
@@ -173,7 +180,7 @@ impl RpcServer {
 			let server = Server::builder(incoming).serve(service);
 
 			let graceful = server.with_graceful_shutdown(shutdown_signal);
-			println!("RPC server listening on http://{}", self.bind_addr);
+			info!("RPC server listening on http://{}", self.bind_addr);
 
 			graceful.await?;
 		} else {
@@ -184,7 +191,7 @@ impl RpcServer {
 				async move {
 					Ok::<_, Error>(service_fn(move |req: Request<Body>| {
 						self_arc.clone().handler(req, client_addr).map_err(|e| {
-							eprintln!("RPC handler error: {}", e);
+							warn!("RPC handler error: {}", e);
 							e
 						})
 					}))
@@ -194,7 +201,7 @@ impl RpcServer {
 			let server = Server::bind(&self.bind_addr).serve(service);
 
 			let graceful = server.with_graceful_shutdown(shutdown_signal);
-			println!("RPC server listening on http://{}", self.bind_addr);
+			info!("RPC server listening on http://{}", self.bind_addr);
 
 			graceful.await?;
 		}

src/server.rs

@@ -87,10 +87,10 @@ impl Garage {
 		background: Arc<BackgroundRunner>,
 		rpc_server: &mut RpcServer,
 	) -> Arc<Self> {
-		println!("Initialize membership management system...");
+		info!("Initialize membership management system...");
 		let system = System::new(config.clone(), id, background.clone(), rpc_server);
 
-		println!("Initialize block manager...");
+		info!("Initialize block manager...");
 		let block_manager =
 			BlockManager::new(&db, config.data_dir.clone(), system.clone(), rpc_server);
 
@@ -111,7 +111,7 @@ impl Garage {
 			(system.config.meta_epidemic_factor + 1) / 2,
 		);
 
-		println!("Initialize block_ref_table...");
+		info!("Initialize block_ref_table...");
 		let block_ref_table = Table::new(
 			BlockRefTable {
 				background: background.clone(),
@@ -125,7 +125,7 @@ impl Garage {
 		)
 		.await;
 
-		println!("Initialize version_table...");
+		info!("Initialize version_table...");
 		let version_table = Table::new(
 			VersionTable {
 				background: background.clone(),
@@ -139,7 +139,7 @@ impl Garage {
 		)
 		.await;
 
-		println!("Initialize object_table...");
+		info!("Initialize object_table...");
 		let object_table = Table::new(
 			ObjectTable {
 				background: background.clone(),
@@ -153,7 +153,7 @@ impl Garage {
 		)
 		.await;
 
-		println!("Initialize bucket_table...");
+		info!("Initialize bucket_table...");
 		let bucket_table = Table::new(
 			BucketTable,
 			control_rep_param.clone(),
@@ -164,7 +164,7 @@ impl Garage {
 		)
 		.await;
 
-		println!("Initialize Garage...");
+		info!("Initialize Garage...");
 		let garage = Arc::new(Self {
 			db,
 			system: system.clone(),
@@ -176,10 +176,10 @@ impl Garage {
 			block_ref_table,
 		});
 
-		println!("Crate admin RPC handler...");
+		info!("Crate admin RPC handler...");
 		AdminRpcHandler::new(garage.clone()).register_handler(rpc_server);
 
-		println!("Start block manager background thread...");
+		info!("Start block manager background thread...");
 		garage.block_manager.garage.swap(Some(garage.clone()));
 		garage.block_manager.clone().spawn_background_worker().await;
 
@@ -226,7 +226,7 @@ async fn shutdown_signal(send_cancel: watch::Sender<bool>) -> Result<(), Error>
 	tokio::signal::ctrl_c()
 		.await
 		.expect("failed to install CTRL+C signal handler");
-	println!("Received CTRL+C, shutting down.");
+	info!("Received CTRL+C, shutting down.");
 	send_cancel.broadcast(true)?;
 	Ok(())
 }
@@ -240,51 +240,51 @@ async fn wait_from(mut chan: watch::Receiver<bool>) -> () {
 }
 
 pub async fn run_server(config_file: PathBuf) -> Result<(), Error> {
-	println!("Loading configuration...");
+	info!("Loading configuration...");
 	let config = read_config(config_file).expect("Unable to read config file");
 
 	let id = gen_node_id(&config.metadata_dir).expect("Unable to read or generate node ID");
-	println!("Node ID: {}", hex::encode(&id));
+	info!("Node ID: {}", hex::encode(&id));
 
-	println!("Opening database...");
+	info!("Opening database...");
 	let mut db_path = config.metadata_dir.clone();
 	db_path.push("db");
 	let db = sled::open(db_path).expect("Unable to open DB");
 
-	println!("Initialize RPC server...");
+	info!("Initialize RPC server...");
 	let mut rpc_server = RpcServer::new(config.rpc_bind_addr.clone(), config.rpc_tls.clone());
 
-	println!("Initializing background runner...");
+	info!("Initializing background runner...");
 	let (send_cancel, watch_cancel) = watch::channel(false);
 	let background = BackgroundRunner::new(8, watch_cancel.clone());
 
 	let garage = Garage::new(config, id, db, background.clone(), &mut rpc_server).await;
 
-	println!("Initializing RPC and API servers...");
+	info!("Initializing RPC and API servers...");
 	let run_rpc_server = Arc::new(rpc_server).run(wait_from(watch_cancel.clone()));
 	let api_server = api_server::run_api_server(garage.clone(), wait_from(watch_cancel.clone()));
 
 	futures::try_join!(
 		garage.system.clone().bootstrap().map(|rv| {
-			println!("Bootstrap done");
+			info!("Bootstrap done");
 			Ok(rv)
 		}),
 		run_rpc_server.map(|rv| {
-			println!("RPC server exited");
+			info!("RPC server exited");
 			rv
 		}),
 		api_server.map(|rv| {
-			println!("API server exited");
+			info!("API server exited");
 			rv
 		}),
 		background.run().map(|rv| {
-			println!("Background runner exited");
+			info!("Background runner exited");
 			Ok(rv)
 		}),
 		shutdown_signal(send_cancel),
 	)?;
 
-	println!("Cleaning up...");
+	info!("Cleaning up...");
 
 	Ok(())
 }

src/table.rs

@@ -489,7 +489,7 @@ where
 	pub async fn delete_range(&self, begin: &Hash, end: &Hash) -> Result<(), Error> {
 		let syncer = self.syncer.load_full().unwrap();
 
-		eprintln!("({}) Deleting range {:?} - {:?}", self.name, begin, end);
+		debug!("({}) Deleting range {:?} - {:?}", self.name, begin, end);
 		let mut count = 0;
 		while let Some((key, _value)) = self.store.get_lt(end.as_slice())? {
 			if key.as_ref() < begin.as_slice() {
@@ -504,7 +504,7 @@ where
 				count += 1;
 			}
 		}
-		eprintln!("({}) {} entries deleted", self.name, count);
+		debug!("({}) {} entries deleted", self.name, count);
 		Ok(())
 	}
 

src/table_sync.rs

@@ -134,7 +134,7 @@ where
 			select! {
 				new_ring_r = s_ring_recv => {
 					if let Some(new_ring) = new_ring_r {
-						eprintln!("({}) Adding ring difference to syncer todo list", self.table.name);
+						debug!("({}) Adding ring difference to syncer todo list", self.table.name);
 						self.todo.lock().await.add_ring_difference(&self.table, &prev_ring, &new_ring);
 						prev_ring = new_ring;
 					}
@@ -158,7 +158,7 @@ where
 				_ = s_timeout => {
 					if nothing_to_do_since.map(|t| Instant::now() - t >= SCAN_INTERVAL).unwrap_or(false) {
 						nothing_to_do_since = None;
-						eprintln!("({}) Adding full scan to syncer todo list", self.table.name);
+						debug!("({}) Adding full scan to syncer todo list", self.table.name);
 						self.todo.lock().await.add_full_scan(&self.table);
 					}
 				}
@@ -180,7 +180,7 @@ where
 					.sync_partition(&partition, &mut must_exit)
 					.await;
 				if let Err(e) = res {
-					eprintln!(
+					warn!(
 						"({}) Error while syncing {:?}: {}",
 						self.table.name, partition, e
 					);
@@ -198,7 +198,7 @@ where
 		partition: &TodoPartition,
 		must_exit: &mut watch::Receiver<bool>,
 	) -> Result<(), Error> {
-		eprintln!("({}) Preparing to sync {:?}...", self.table.name, partition);
+		debug!("({}) Preparing to sync {:?}...", self.table.name, partition);
 		let root_cks = self
 			.root_checksum(&partition.begin, &partition.end, must_exit)
 			.await?;
@@ -226,7 +226,7 @@ where
 		while let Some(r) = sync_futures.next().await {
 			if let Err(e) = r {
 				n_errors += 1;
-				eprintln!("({}) Sync error: {}", self.table.name, e);
+				warn!("({}) Sync error: {}", self.table.name, e);
 			}
 		}
 		if n_errors > self.table.replication.max_write_errors() {
@@ -284,7 +284,7 @@ where
 			drop(cache);
 
 			let v = self.range_checksum_inner(&range, must_exit).await?;
-			eprintln!(
+			trace!(
 				"({}) New checksum calculated for {}-{}/{}, {} children",
 				self.table.name,
 				hex::encode(&range.begin[..]),
@@ -418,7 +418,7 @@ where
 
 		while !todo.is_empty() && !*must_exit.borrow() {
 			let total_children = todo.iter().map(|x| x.children.len()).fold(0, |x, y| x + y);
-			eprintln!(
+			trace!(
 				"({}) Sync with {:?}: {} ({}) remaining",
 				self.table.name,
 				who,
@@ -442,7 +442,7 @@ where
 				rpc_resp
 			{
 				if diff_ranges.len() > 0 || diff_items.len() > 0 {
-					eprintln!(
+					info!(
 						"({}) Sync with {:?}: difference {} ranges, {} items",
 						self.table.name,
 						who,
@@ -479,7 +479,7 @@ where
 	}
 
 	async fn send_items(self: Arc<Self>, who: UUID, item_list: Vec<Vec<u8>>) -> Result<(), Error> {
-		eprintln!(
+		info!(
 			"({}) Sending {} items to {:?}",
 			self.table.name,
 			item_list.len(),
@@ -594,7 +594,7 @@ where
 			.map(|x| x.children.len())
 			.fold(0, |x, y| x + y);
 		if ret_ranges.len() > 0 || ret_items.len() > 0 {
-			eprintln!(
+			trace!(
 				"({}) Checksum comparison RPC: {} different + {} items for {} received",
 				self.table.name,
 				ret_ranges.len(),