feat(tvix/store): add logging with tracing r/5558

This uses [tracing](https://github.com/tokio-rs/tracing) for logs/
tracing.

Annotate all method handlers with an instrument macro, and warn! a
message for them being unimplemented.

Co-Authored-By: Márton Boros <martonboros@gmail.com>
Change-Id: Id42a41db33782d82abfb8dc0e49a8915000e5d89
Reviewed-on: https://cl.tvl.fyi/c/depot/+/7665
Reviewed-by: tazjin <tazjin@tvl.su>
Tested-by: BuildkiteCI

7 files changed, 327 insertions, 10 deletions

diff --git a/tvix/Cargo.lock b/tvix/Cargo.lock
index 8b6647f29938..9e31df0fe651 100644
--- a/tvix/Cargo.lock
+++ b/tvix/Cargo.lock
@@ -1050,6 +1050,16 @@ dependencies = [
 ]
 
 [[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
+[[package]]
 name = "num-traits"
 version = "0.2.15"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1105,6 +1115,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
+[[package]]
 name = "path-clean"
 version = "0.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1647,6 +1663,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
+[[package]]
 name = "slab"
 version = "0.4.7"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1869,6 +1894,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "thread_local"
+version = "1.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180"
+dependencies = [
+ "once_cell",
+]
+
+[[package]]
 name = "tinytemplate"
 version = "1.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2084,6 +2118,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a"
 dependencies = [
  "once_cell",
+ "valuable",
 ]
 
 [[package]]
@@ -2097,6 +2132,31 @@ dependencies = [
 ]
 
 [[package]]
+name = "tracing-log"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.16"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70"
+dependencies = [
+ "nu-ansi-term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
+]
+
+[[package]]
 name = "try-lock"
 version = "0.2.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2172,6 +2232,8 @@ dependencies = [
  "tonic",
  "tonic-build",
  "tonic-reflection",
+ "tracing",
+ "tracing-subscriber",
 ]
 
 [[package]]
@@ -2211,6 +2273,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "936e4b492acfd135421d8dca4b1aa80a7bfc26e702ef3af710e0752684df5372"
 
 [[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
+[[package]]
 name = "version_check"
 version = "0.9.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/tvix/Cargo.nix b/tvix/Cargo.nix
index 225f0f04ad23..57b5e2a0ff6a 100644
--- a/tvix/Cargo.nix
+++ b/tvix/Cargo.nix
@@ -2729,6 +2729,7 @@ rec {
           "sval" = [ "dep:sval" ];
           "value-bag" = [ "dep:value-bag" ];
         };
+        resolvedDefaultFeatures = [ "std" ];
       };
       "matchit" = rec {
         crateName = "matchit";
@@ -3013,6 +3014,34 @@ rec {
         features = { };
         resolvedDefaultFeatures = [ "integration_tests" ];
       };
+      "nu-ansi-term" = rec {
+        crateName = "nu-ansi-term";
+        version = "0.46.0";
+        edition = "2018";
+        sha256 = "115sywxh53p190lyw97alm14nc004qj5jm5lvdj608z84rbida3p";
+        authors = [
+          "ogham@bsago.me"
+          "Ryan Scheel (Havvy) <ryan.havvy@gmail.com>"
+          "Josh Triplett <josh@joshtriplett.org>"
+          "The Nushell Project Developers"
+        ];
+        dependencies = [
+          {
+            name = "overload";
+            packageId = "overload";
+          }
+          {
+            name = "winapi";
+            packageId = "winapi";
+            target = { target, features }: ("windows" == target."os");
+            features = [ "consoleapi" "errhandlingapi" "fileapi" "handleapi" "processenv" ];
+          }
+        ];
+        features = {
+          "derive_serde_style" = [ "serde" ];
+          "serde" = [ "dep:serde" ];
+        };
+      };
       "num-traits" = rec {
         crateName = "num-traits";
         version = "0.2.15";
@@ -3155,6 +3184,16 @@ rec {
         ];
 
       };
+      "overload" = rec {
+        crateName = "overload";
+        version = "0.1.1";
+        edition = "2018";
+        sha256 = "0fdgbaqwknillagy1xq7xfgv60qdbk010diwl7s1p0qx7hb16n5i";
+        authors = [
+          "Daniel Salvadori <danaugrs@gmail.com>"
+        ];
+
+      };
       "path-clean" = rec {
         crateName = "path-clean";
         version = "0.1.0";
@@ -4726,6 +4765,24 @@ rec {
         };
         resolvedDefaultFeatures = [ "default" "std" ];
       };
+      "sharded-slab" = rec {
+        crateName = "sharded-slab";
+        version = "0.1.4";
+        edition = "2018";
+        sha256 = "0cbb8kgwsyr3zzhsv8jrs3y1j3vsw4jxil42lfq31ikhdy0bl3wh";
+        authors = [
+          "Eliza Weisman <eliza@buoyant.io>"
+        ];
+        dependencies = [
+          {
+            name = "lazy_static";
+            packageId = "lazy_static";
+          }
+        ];
+        features = {
+          "loom" = [ "dep:loom" ];
+        };
+      };
       "slab" = rec {
         crateName = "slab";
         version = "0.4.7";
@@ -5283,6 +5340,24 @@ rec {
         ];
 
       };
+      "thread_local" = rec {
+        crateName = "thread_local";
+        version = "1.1.4";
+        edition = "2018";
+        sha256 = "1001bvz6a688wf3izcrh3jqrkiqaarf44wf08azm071ig1xw45jm";
+        authors = [
+          "Amanieu d'Antras <amanieu@gmail.com>"
+        ];
+        dependencies = [
+          {
+            name = "once_cell";
+            packageId = "once_cell";
+          }
+        ];
+        features = {
+          "criterion" = [ "dep:criterion" ];
+        };
+      };
       "tinytemplate" = rec {
         crateName = "tinytemplate";
         version = "1.2.1";
@@ -6155,6 +6230,13 @@ rec {
             packageId = "once_cell";
             optional = true;
           }
+          {
+            name = "valuable";
+            packageId = "valuable";
+            optional = true;
+            usesDefaultFeatures = false;
+            target = { target, features }: (target."tracing_unstable" or false);
+          }
         ];
         features = {
           "default" = [ "std" "valuable/std" ];
@@ -6162,7 +6244,7 @@ rec {
           "std" = [ "once_cell" ];
           "valuable" = [ "dep:valuable" ];
         };
-        resolvedDefaultFeatures = [ "once_cell" "std" ];
+        resolvedDefaultFeatures = [ "default" "once_cell" "std" "valuable" ];
       };
       "tracing-futures" = rec {
         crateName = "tracing-futures";
@@ -6200,6 +6282,117 @@ rec {
         };
         resolvedDefaultFeatures = [ "default" "pin-project" "std" "std-future" ];
       };
+      "tracing-log" = rec {
+        crateName = "tracing-log";
+        version = "0.1.3";
+        edition = "2018";
+        sha256 = "08prnkxq8yas6jvvjnvyx5v3hwblas5527wxxgbiw2yis8rsvpbq";
+        authors = [
+          "Tokio Contributors <team@tokio.rs>"
+        ];
+        dependencies = [
+          {
+            name = "lazy_static";
+            packageId = "lazy_static";
+          }
+          {
+            name = "log";
+            packageId = "log";
+          }
+          {
+            name = "tracing-core";
+            packageId = "tracing-core";
+          }
+        ];
+        features = {
+          "ahash" = [ "dep:ahash" ];
+          "default" = [ "log-tracer" "trace-logger" "std" ];
+          "env_logger" = [ "dep:env_logger" ];
+          "interest-cache" = [ "lru" "ahash" ];
+          "lru" = [ "dep:lru" ];
+          "std" = [ "log/std" ];
+        };
+        resolvedDefaultFeatures = [ "log-tracer" "std" ];
+      };
+      "tracing-subscriber" = rec {
+        crateName = "tracing-subscriber";
+        version = "0.3.16";
+        edition = "2018";
+        sha256 = "0w2sdf97g1ynbmk3j4q6sxmjgaalgf4pg4vl374x0w6x4sp6w5x6";
+        authors = [
+          "Eliza Weisman <eliza@buoyant.io>"
+          "David Barsky <me@davidbarsky.com>"
+          "Tokio Contributors <team@tokio.rs>"
+        ];
+        dependencies = [
+          {
+            name = "nu-ansi-term";
+            packageId = "nu-ansi-term";
+            optional = true;
+          }
+          {
+            name = "sharded-slab";
+            packageId = "sharded-slab";
+            optional = true;
+          }
+          {
+            name = "smallvec";
+            packageId = "smallvec";
+            optional = true;
+          }
+          {
+            name = "thread_local";
+            packageId = "thread_local";
+            optional = true;
+          }
+          {
+            name = "tracing-core";
+            packageId = "tracing-core";
+            usesDefaultFeatures = false;
+          }
+          {
+            name = "tracing-log";
+            packageId = "tracing-log";
+            optional = true;
+            usesDefaultFeatures = false;
+            features = [ "log-tracer" "std" ];
+          }
+        ];
+        devDependencies = [
+          {
+            name = "tracing-log";
+            packageId = "tracing-log";
+          }
+        ];
+        features = {
+          "ansi" = [ "fmt" "nu-ansi-term" ];
+          "default" = [ "smallvec" "fmt" "ansi" "tracing-log" "std" ];
+          "env-filter" = [ "matchers" "regex" "once_cell" "tracing" "std" "thread_local" ];
+          "fmt" = [ "registry" "std" ];
+          "json" = [ "tracing-serde" "serde" "serde_json" ];
+          "local-time" = [ "time/local-offset" ];
+          "matchers" = [ "dep:matchers" ];
+          "nu-ansi-term" = [ "dep:nu-ansi-term" ];
+          "once_cell" = [ "dep:once_cell" ];
+          "parking_lot" = [ "dep:parking_lot" ];
+          "regex" = [ "dep:regex" ];
+          "registry" = [ "sharded-slab" "thread_local" "std" ];
+          "serde" = [ "dep:serde" ];
+          "serde_json" = [ "dep:serde_json" ];
+          "sharded-slab" = [ "dep:sharded-slab" ];
+          "smallvec" = [ "dep:smallvec" ];
+          "std" = [ "alloc" "tracing-core/std" ];
+          "thread_local" = [ "dep:thread_local" ];
+          "time" = [ "dep:time" ];
+          "tracing" = [ "dep:tracing" ];
+          "tracing-log" = [ "dep:tracing-log" ];
+          "tracing-serde" = [ "dep:tracing-serde" ];
+          "valuable" = [ "tracing-core/valuable" "valuable_crate" "valuable-serde" "tracing-serde/valuable" ];
+          "valuable-serde" = [ "dep:valuable-serde" ];
+          "valuable_crate" = [ "dep:valuable_crate" ];
+        };
+        resolvedDefaultFeatures = [ "alloc" "ansi" "default" "fmt" "nu-ansi-term" "registry" "sharded-slab" "smallvec" "std" "thread_local" "tracing-log" ];
+      };
       "try-lock" = rec {
         crateName = "try-lock";
         version = "0.2.3";
@@ -6482,6 +6675,14 @@ rec {
             packageId = "tonic-reflection";
             optional = true;
           }
+          {
+            name = "tracing";
+            packageId = "tracing";
+          }
+          {
+            name = "tracing-subscriber";
+            packageId = "tracing-subscriber";
+          }
         ];
         buildDependencies = [
           {
@@ -6583,6 +6784,19 @@ rec {
         features = { };
         resolvedDefaultFeatures = [ "default" ];
       };
+      "valuable" = rec {
+        crateName = "valuable";
+        version = "0.1.0";
+        edition = "2018";
+        sha256 = "0v9gp3nkjbl30z0fd56d8mx7w1csk86wwjhfjhr400wh9mfpw2w3";
+        features = {
+          "default" = [ "std" ];
+          "derive" = [ "valuable-derive" ];
+          "std" = [ "alloc" ];
+          "valuable-derive" = [ "dep:valuable-derive" ];
+        };
+        resolvedDefaultFeatures = [ "alloc" "std" ];
+      };
       "version_check" = rec {
         crateName = "version_check";
         version = "0.9.4";
diff --git a/tvix/store/Cargo.toml b/tvix/store/Cargo.toml
index 90672b6d037f..111667cd74d1 100644
--- a/tvix/store/Cargo.toml
+++ b/tvix/store/Cargo.toml
@@ -14,6 +14,8 @@ thiserror = "1.0.38"
 tokio = { version = "1.23.0", features = ["rt-multi-thread"] }
 tokio-stream = "0.1.11"
 tonic = "0.8.2"
+tracing-subscriber = "0.3.16"
+tracing = "0.1.37"
 
 [dependencies.tonic-reflection]
 optional = true
diff --git a/tvix/store/src/dummy_blob_service.rs b/tvix/store/src/dummy_blob_service.rs
index 7731ea3344e3..690f6bde3869 100644
--- a/tvix/store/src/dummy_blob_service.rs
+++ b/tvix/store/src/dummy_blob_service.rs
@@ -7,6 +7,9 @@ use crate::proto::PutBlobResponse;
 use crate::proto::ReadBlobRequest;
 use crate::proto::StatBlobRequest;
 use tonic::{Request, Response, Result, Status, Streaming};
+use tracing::{instrument, warn};
+
+const NOT_IMPLEMENTED_MSG: &str = "not implemented";
 
 pub struct DummyBlobService {}
 
@@ -14,21 +17,27 @@ pub struct DummyBlobService {}
 impl BlobService for DummyBlobService {
     type ReadStream = ReceiverStream<Result<BlobChunk>>;
 
+    #[instrument(skip(self))]
     async fn stat(&self, _request: Request<StatBlobRequest>) -> Result<Response<BlobMeta>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 
+    #[instrument(skip(self))]
     async fn read(
         &self,
         _request: Request<ReadBlobRequest>,
     ) -> Result<Response<Self::ReadStream>, Status> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 
+    #[instrument(skip(self, _request))]
     async fn put(
         &self,
         _request: Request<Streaming<BlobChunk>>,
     ) -> Result<Response<PutBlobResponse>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 }
diff --git a/tvix/store/src/dummy_directory_service.rs b/tvix/store/src/dummy_directory_service.rs
index e9b54d85afd4..183f146b5814 100644
--- a/tvix/store/src/dummy_directory_service.rs
+++ b/tvix/store/src/dummy_directory_service.rs
@@ -5,6 +5,9 @@ use crate::proto::Directory;
 use crate::proto::GetDirectoryRequest;
 use crate::proto::PutDirectoryResponse;
 use tonic::{Request, Response, Result, Status, Streaming};
+use tracing::{instrument, warn};
+
+const NOT_IMPLEMENTED_MSG: &str = "not implemented";
 
 pub struct DummyDirectoryService {}
 
@@ -12,17 +15,21 @@ pub struct DummyDirectoryService {}
 impl DirectoryService for DummyDirectoryService {
     type GetStream = ReceiverStream<Result<Directory>>;
 
+    #[instrument(skip(self))]
     async fn get(
         &self,
         _request: Request<GetDirectoryRequest>,
     ) -> Result<Response<Self::GetStream>, Status> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 
+    #[instrument(skip(self, _request))]
     async fn put(
         &self,
         _request: Request<Streaming<Directory>>,
     ) -> Result<Response<PutDirectoryResponse>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 }
diff --git a/tvix/store/src/dummy_path_info_service.rs b/tvix/store/src/dummy_path_info_service.rs
index 3bc99ad334d9..93359377f3dc 100644
--- a/tvix/store/src/dummy_path_info_service.rs
+++ b/tvix/store/src/dummy_path_info_service.rs
@@ -4,23 +4,32 @@ use crate::proto::GetPathInfoRequest;
 use crate::proto::Node;
 use crate::proto::PathInfo;
 use tonic::{Request, Response, Result, Status};
+use tracing::{instrument, warn};
 
 pub struct DummyPathInfoService {}
 
+const NOT_IMPLEMENTED_MSG: &str = "not implemented";
+
 #[tonic::async_trait]
 impl PathInfoService for DummyPathInfoService {
+    #[instrument(skip(self))]
     async fn get(&self, _request: Request<GetPathInfoRequest>) -> Result<Response<PathInfo>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 
+    #[instrument(skip(self))]
     async fn put(&self, _request: Request<PathInfo>) -> Result<Response<PathInfo>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 
+    #[instrument(skip(self))]
     async fn calculate_nar(
         &self,
         _request: Request<Node>,
     ) -> Result<Response<CalculateNarResponse>> {
-        Err(Status::unimplemented("not implemented"))
+        warn!(NOT_IMPLEMENTED_MSG);
+        Err(Status::unimplemented(NOT_IMPLEMENTED_MSG))
     }
 }
diff --git a/tvix/store/src/main.rs b/tvix/store/src/main.rs
index b28c3fdeefe8..d9261fc34d6e 100644
--- a/tvix/store/src/main.rs
+++ b/tvix/store/src/main.rs
@@ -7,6 +7,7 @@ use crate::proto::FILE_DESCRIPTOR_SET;
 
 use clap::Parser;
 use tonic::{transport::Server, Result};
+use tracing::{info, Level};
 
 mod dummy_blob_service;
 mod dummy_directory_service;
@@ -23,6 +24,9 @@ mod tests;
 struct Cli {
     #[clap(long, short = 'l')]
     listen_address: Option<String>,
+
+    #[clap(long)]
+    log_level: Option<Level>,
 }
 
 #[tokio::main]
@@ -34,6 +38,10 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
         .parse()
         .unwrap();
 
+    let level = cli.log_level.unwrap_or(Level::INFO);
+    let subscriber = tracing_subscriber::fmt().with_max_level(level).finish();
+    tracing::subscriber::set_global_default(subscriber).ok();
+
     let mut server = Server::builder();
 
     let blob_service = dummy_blob_service::DummyBlobService {};
@@ -53,7 +61,7 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
         router = router.add_service(reflection_svc);
     }
 
-    println!("tvix-store listening on {}", listen_address);
+    info!("tvix-store listening on {}", listen_address);
 
     router.serve(listen_address).await?;