Use tracing in the server component

Cargo.lock

@@ -775,6 +775,8 @@ dependencies = [
  "csv",
  "recipes",
  "static_dir",
+ "tracing",
+ "tracing-subscriber",
  "warp",
 ]
 
@@ -1026,9 +1028,9 @@ dependencies = [
 
 [[package]]
 name = "once_cell"
-version = "1.10.0"
+version = "1.13.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "87f3e037eac156d1775da914196f0f37741a274155e34a0b7e427c35d2a2ecb9"
+checksum = "18a6dbe30758c9f83eb00cbea4ac95966305f5a7772f3f42ebfc7fc7eddbd8e1"
 
 [[package]]
 name = "opaque-debug"
@@ -1310,6 +1312,15 @@ dependencies = [
  "digest 0.10.3",
 ]
 
+[[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.5"
@@ -1460,6 +1471,15 @@ dependencies = [
  "syn",
 ]
 
+[[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 = "time"
 version = "0.1.43"
@@ -1547,23 +1567,61 @@ checksum = "360dfd1d6d30e05fda32ace2c8c70e9c0a9da713275777f5a4dbb8a1893930c6"
 
 [[package]]
 name = "tracing"
-version = "0.1.31"
+version = "0.1.35"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "f6c650a8ef0cd2dd93736f033d21cbd1224c5a967aa0c258d00fcf7dafef9b9f"
+checksum = "a400e31aa60b9d44a52a8ee0343b5b18566b03a8321e0d321f695cf56e940160"
 dependencies = [
  "cfg-if",
  "log",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
 [[package]]
-name = "tracing-core"
+name = "tracing-attributes"
 version = "0.1.22"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "03cfcb51380632a72d3111cb8d3447a8d908e577d31beeac006f836383d29a23"
+checksum = "11c75893af559bc8e10716548bdef5cb2b983f8e637db9d0e15126b61b484ee2"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.28"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7"
+dependencies = [
+ "once_cell",
+ "valuable",
+]
+
+[[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.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3a713421342a5a666b7577783721d3117f1b69a393df803ee17bb73b1e122a59"
+dependencies = [
+ "ansi_term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -1666,6 +1724,12 @@ version = "0.7.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "09cc8ee72d2a9becf2f2febe0205bbed8fc6615b7cb429ad062dc7b7ddd036a9"
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "value-bag"
 version = "1.0.0-alpha.8"

kitchen/Cargo.toml

@@ -7,6 +7,8 @@ edition = "2021"
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
+tracing = "0.1.35"
+tracing-subscriber = "0.3.14"
 recipes = {path = "../recipes" }
 csv = "1.1.1"
 warp = "0.3.2"

kitchen/src/cli.rs

@@ -21,6 +21,7 @@ use csv;
 
 use crate::api::ParseError;
 use recipes::{parse, IngredientAccumulator, Recipe};
+use tracing::{error, info, instrument, warn};
 
 // TODO(jwall): We should think a little more closely about
 // the error modeling for this application.
@@ -29,13 +30,14 @@ macro_rules! try_open {
         match File::open(&$path) {
             Ok(reader) => reader,
             Err(e) => {
-                eprintln!("Error opening file for read: {:?}", $path);
+                error!(path=?$path, "Error opening file for read");
                 return Err(ParseError::from(e));
             }
         }
     };
 }
 
+#[instrument]
 pub fn parse_recipe<P>(path: P) -> Result<Recipe, ParseError>
 where
     P: AsRef<Path> + Debug,
@@ -47,6 +49,7 @@ where
     Ok(parse::as_recipe(&i)?)
 }
 
+#[instrument]
 pub fn read_menu_list<P>(path: P) -> Result<Vec<Recipe>, ParseError>
 where
     P: AsRef<Path> + Debug,
@@ -54,7 +57,7 @@ where
     let path = path.as_ref();
     let wd = path.parent().unwrap();
     let mut br = BufReader::new(try_open!(path));
-    eprintln!("Switching to {:?}", wd);
+    info!(directory=?wd, "Switching working directory");
     std::env::set_current_dir(wd)?;
     let mut buf = String::new();
     let mut recipe_list = Vec::new();

kitchen/src/main.rs

@@ -12,11 +12,14 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 use std::env;
+use std::io;
 use std::net::SocketAddr;
 use std::path::PathBuf;
 
 use clap;
 use clap::{clap_app, crate_authors, crate_version};
+use tracing::{error, info, instrument, warn, Level};
+use tracing_subscriber::FmtSubscriber;
 
 pub mod api;
 mod cli;
@@ -30,6 +33,7 @@ where
         (version: crate_version!())
         (author: crate_authors!())
         (about: "Kitchen Management CLI")
+        (@arg verbose: --verbose -v "Verbosity level for logging (error, warn, info, debug, trace")
         (@subcommand recipe =>
             (about: "parse a recipe file and output info about it")
             (@arg ingredients: -i --ingredients "Output the ingredients list.")
@@ -49,8 +53,29 @@ where
     .setting(clap::AppSettings::SubcommandRequiredElseHelp)
 }
 
+#[instrument]
 fn main() {
     let matches = create_app().get_matches();
+    let subscriber_builder = if let Some(verbosity) = matches.value_of("verbosity") {
+        // Se want verbosity level
+        let level = match verbosity {
+            "error" | "ERROR" => Level::ERROR,
+            "warn" | "WARN" => Level::WARN,
+            "info" | "INFO" => Level::INFO,
+            "debug" | "DEBUG" => Level::DEBUG,
+            "trace" | "TRACE" => Level::TRACE,
+            _ => {
+                println!("Invalid logging level using TRACE");
+                Level::TRACE
+            }
+        };
+        FmtSubscriber::builder().with_max_level(level)
+    } else {
+        FmtSubscriber::builder().with_max_level(Level::INFO)
+    };
+    tracing::subscriber::set_global_default(subscriber_builder.with_writer(io::stderr).finish())
+        .expect("setting default subscriber failed");
+
     if let Some(matches) = matches.subcommand_matches("recipe") {
         // The input argument is required so if we made it here then it's safe to unrwap this value.
         let recipe_file = matches.value_of("INPUT").unwrap();
@@ -58,8 +83,8 @@ fn main() {
             Ok(r) => {
                 cli::output_recipe_info(r, matches.is_present("ingredients"));
             }
-            Err(e) => {
+            Err(err) => {
-                eprintln!("{:?}", e);
+                error!(?err);
             }
         }
     } else if let Some(matches) = matches.subcommand_matches("groceries") {
@@ -73,8 +98,8 @@ fn main() {
                     cli::output_ingredients_list(rs);
                 }
             }
-            Err(e) => {
+            Err(err) => {
-                eprintln!("{:?}", e);
+                error!(?err);
             }
         }
     } else if let Some(matches) = matches.subcommand_matches("serve") {
@@ -91,8 +116,7 @@ fn main() {
         } else {
             "127.0.0.1:3030".parse().unwrap()
         };
-        println!("Launching web interface...");
+        info!(listen=%listen_socket, "Launching web interface...");
-        println!("listening on {}", listen_socket);
         async_std::task::block_on(async { web::ui_main(recipe_dir_path, listen_socket).await });
     }
 }

kitchen/src/web.rs

@@ -17,10 +17,12 @@ use std::path::PathBuf;
 use async_std::fs::{self, read_dir, read_to_string, DirEntry};
 use async_std::stream::StreamExt;
 use static_dir::static_dir;
+use tracing::{info, instrument, warn};
 use warp::{http::StatusCode, hyper::Uri, Filter};
 
 use crate::api::ParseError;
 
+#[instrument(fields(recipe_dir=?recipe_dir_path), skip_all)]
 pub async fn get_recipes(recipe_dir_path: PathBuf) -> Result<Vec<String>, ParseError> {
     let mut entries = read_dir(recipe_dir_path).await?;
     let mut entry_vec = Vec::new();
@@ -35,19 +37,20 @@ pub async fn get_recipes(recipe_dir_path: PathBuf) -> Result<Vec<String>, ParseE
                 .any(|&s| s == entry.file_name().to_string_lossy().to_string())
         {
             // add it to the entry
-            eprintln!("adding recipe file {}", entry.file_name().to_string_lossy());
+            info!("adding recipe file {}", entry.file_name().to_string_lossy());
             let recipe_contents = read_to_string(entry.path()).await?;
             entry_vec.push(recipe_contents);
         } else {
-            eprintln!(
+            warn!(
-                "skipping file {} not a recipe",
+                file = %entry.path().to_string_lossy(),
-                entry.path().to_string_lossy()
+                "skipping file not a recipe",
             );
         }
     }
     Ok(entry_vec)
 }
 
+#[instrument(fields(recipe_dir=?recipe_dir_path,listen=?listen_socket), skip_all)]
 pub async fn ui_main(recipe_dir_path: PathBuf, listen_socket: SocketAddr) {
     let root = warp::path::end().map(|| warp::redirect::found(Uri::from_static("/ui")));
     let ui = warp::path("ui").and(static_dir!("../web/dist"));
@@ -56,7 +59,7 @@ pub async fn ui_main(recipe_dir_path: PathBuf, listen_socket: SocketAddr) {
     // recipes api path route
     let recipe_path = warp::path("recipes").then(move || {
         let dir_path = (&dir_path).clone();
-        eprintln!("servicing recipe api request.");
+        info!(?dir_path, "servicing recipe api request.");
         async move {
             match get_recipes(dir_path).await {
                 Ok(recipes) => {
@@ -74,7 +77,7 @@ pub async fn ui_main(recipe_dir_path: PathBuf, listen_socket: SocketAddr) {
     let mut file_path = (&recipe_dir_path).clone();
     file_path.push("categories.txt");
     let categories_path = warp::path("categories").then(move || {
-        eprintln!("servicing category api request");
+        info!(?file_path, "servicing category api request");
         let file_path = (&file_path).clone();
         async move {
             match fs::metadata(&file_path).await {