From 319c03f63413a82d9266ed939eba7f7e552dd2b2 Mon Sep 17 00:00:00 2001 From: Florian Klink Date: Wed, 28 Dec 2022 17:17:53 +0100 Subject: feat(tvix/store): add logging with tracing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Change-Id: Id42a41db33782d82abfb8dc0e49a8915000e5d89 Reviewed-on: https://cl.tvl.fyi/c/depot/+/7665 Reviewed-by: tazjin Tested-by: BuildkiteCI --- tvix/Cargo.lock | 68 ++++++++++ tvix/Cargo.nix | 216 +++++++++++++++++++++++++++++- tvix/store/Cargo.toml | 2 + tvix/store/src/dummy_blob_service.rs | 15 ++- tvix/store/src/dummy_directory_service.rs | 11 +- tvix/store/src/dummy_path_info_service.rs | 15 ++- tvix/store/src/main.rs | 10 +- 7 files changed, 327 insertions(+), 10 deletions(-) diff --git a/tvix/Cargo.lock b/tvix/Cargo.lock index 8b6647f299..9e31df0fe6 100644 --- a/tvix/Cargo.lock +++ b/tvix/Cargo.lock @@ -1049,6 +1049,16 @@ dependencies = [ "tempfile", ] +[[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" @@ -1104,6 +1114,12 @@ dependencies = [ "winapi", ] +[[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" @@ -1646,6 +1662,15 @@ dependencies = [ "serde", ] +[[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" @@ -1868,6 +1893,15 @@ dependencies = [ "syn 1.0.103", ] +[[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" @@ -2084,6 +2118,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" dependencies = [ "once_cell", + "valuable", ] [[package]] @@ -2096,6 +2131,31 @@ dependencies = [ "tracing", ] +[[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" @@ -2172,6 +2232,8 @@ dependencies = [ "tonic", "tonic-build", "tonic-reflection", + "tracing", + "tracing-subscriber", ] [[package]] @@ -2210,6 +2272,12 @@ version = "0.2.0" 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" diff --git a/tvix/Cargo.nix b/tvix/Cargo.nix index 225f0f04ad..57b5e2a0ff 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) " + "Josh Triplett " + "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"; @@ -3154,6 +3183,16 @@ rec { } ]; + }; + "overload" = rec { + crateName = "overload"; + version = "0.1.1"; + edition = "2018"; + sha256 = "0fdgbaqwknillagy1xq7xfgv60qdbk010diwl7s1p0qx7hb16n5i"; + authors = [ + "Daniel Salvadori " + ]; + }; "path-clean" = rec { crateName = "path-clean"; @@ -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 " + ]; + 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 " + ]; + 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 " + ]; + 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 " + "David Barsky " + "Tokio Contributors " + ]; + 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 90672b6d03..111667cd74 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 7731ea3344..690f6bde38 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>; + #[instrument(skip(self))] async fn stat(&self, _request: Request) -> Result> { - Err(Status::unimplemented("not implemented")) + warn!(NOT_IMPLEMENTED_MSG); + Err(Status::unimplemented(NOT_IMPLEMENTED_MSG)) } + #[instrument(skip(self))] async fn read( &self, _request: Request, ) -> Result, 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>, ) -> Result> { - 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 e9b54d85af..183f146b58 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>; + #[instrument(skip(self))] async fn get( &self, _request: Request, ) -> Result, 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>, ) -> Result> { - 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 3bc99ad334..93359377f3 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) -> Result> { - Err(Status::unimplemented("not implemented")) + warn!(NOT_IMPLEMENTED_MSG); + Err(Status::unimplemented(NOT_IMPLEMENTED_MSG)) } + #[instrument(skip(self))] async fn put(&self, _request: Request) -> Result> { - 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, ) -> Result> { - 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 b28c3fdeef..d9261fc34d 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, + + #[clap(long)] + log_level: Option, } #[tokio::main] @@ -34,6 +38,10 @@ async fn main() -> Result<(), Box> { .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> { 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?; -- cgit 1.4.1