feat: improved trace logging

Cargo.lock

@@ -342,6 +342,8 @@ dependencies = [
  "tower 0.4.13",
  "tower-cookies",
  "tracing",
+ "tracing-bunyan-formatter",
+ "tracing-log 0.2.0",
  "tracing-subscriber",
  "wiremock",
 ]
@@ -842,6 +844,16 @@ dependencies = [
  "version_check",
 ]
 
+[[package]]
+name = "gethostname"
+version = "0.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c1ebd34e35c46e00bb73e81363248d627782724609fe1b6396f553f68fe3862e"
+dependencies = [
+ "libc",
+ "winapi",
+]
+
 [[package]]
 name = "getrandom"
 version = "0.2.16"
@@ -2863,6 +2875,24 @@ dependencies = [
  "syn 2.0.110",
 ]
 
+[[package]]
+name = "tracing-bunyan-formatter"
+version = "0.3.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2d637245a0d8774bd48df6482e086c59a8b5348a910c3b0579354045a9d82411"
+dependencies = [
+ "ahash",
+ "gethostname",
+ "log",
+ "serde",
+ "serde_json",
+ "time",
+ "tracing",
+ "tracing-core",
+ "tracing-log 0.1.4",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.34"
@@ -2873,6 +2903,17 @@ dependencies = [
  "valuable",
 ]
 
+[[package]]
+name = "tracing-log"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f751112709b4e791d8ce53e32c4ed2d353565a795ce84da2285393f41557bdf2"
+dependencies = [
+ "log",
+ "once_cell",
+ "tracing-core",
+]
+
 [[package]]
 name = "tracing-log"
 version = "0.2.0"
@@ -2899,7 +2940,7 @@ dependencies = [
  "thread_local",
  "tracing",
  "tracing-core",
- "tracing-log",
+ "tracing-log 0.2.0",
 ]
 
 [[package]]
@@ -3140,6 +3181,28 @@ dependencies = [
  "wasite",
 ]
 
+[[package]]
+name = "winapi"
+version = "0.3.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5c839a674fcd7a98952e593242ea400abe93992746761e38641405d28b00f419"
+dependencies = [
+ "winapi-i686-pc-windows-gnu",
+ "winapi-x86_64-pc-windows-gnu",
+]
+
+[[package]]
+name = "winapi-i686-pc-windows-gnu"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
+
+[[package]]
+name = "winapi-x86_64-pc-windows-gnu"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f"
+
 [[package]]
 name = "windows-core"
 version = "0.62.2"

Cargo.toml

@@ -37,6 +37,8 @@ tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 tower = "0.4"
 tower-cookies = "0.10"
 slug = "0.1.6"
+tracing-bunyan-formatter = "0.3.10"
+tracing-log = "0.2.0"
 
 [dev-dependencies]
 portpicker = "0.1"

src/application/auth.rs

@@ -12,7 +12,7 @@ use crate::infrastructure::auth::hash_token;
 const SESSION_COOKIE_NAME: &str = "brewlog_session";
 
 /// Extension type to carry authenticated user through request handlers
-#[derive(Clone)]
+#[derive(Debug, Clone)]
 pub struct AuthenticatedUser(pub User);
 
 #[async_trait]

src/application/routes/auth.rs

@@ -29,6 +29,7 @@ pub struct LoginForm {
     password: String,
 }
 
+#[tracing::instrument(skip(state, cookies))]
 pub(crate) async fn login_page(
     State(state): State<AppState>,
     cookies: Cookies,
@@ -47,6 +48,7 @@ pub(crate) async fn login_page(
     render_html(template).map(IntoResponse::into_response)
 }
 
+#[tracing::instrument(name = "User attempting login", skip(state, cookies, form), fields(username = %form.username))]
 pub(crate) async fn login_submit(
     State(state): State<AppState>,
     cookies: Cookies,
@@ -103,6 +105,7 @@ pub(crate) async fn login_submit(
     Ok(Redirect::to("/timeline").into_response())
 }
 
+#[tracing::instrument(skip(state, cookies))]
 pub(crate) async fn logout(State(state): State<AppState>, cookies: Cookies) -> Redirect {
     // Try to delete session from database if cookie exists
     if let Some(cookie) = cookies.get(SESSION_COOKIE_NAME) {
@@ -135,6 +138,7 @@ fn show_login_error(message: &str) -> Result<Response, StatusCode> {
 
 /// Check if user is authenticated based on session cookie
 /// Validates the session token against the database
+#[tracing::instrument(skip(state, cookies))]
 pub async fn is_authenticated(state: &AppState, cookies: &Cookies) -> bool {
     let Some(cookie) = cookies.get(SESSION_COOKIE_NAME) else {
         return false;

src/application/routes/roasters.rs

@@ -21,6 +21,7 @@ use crate::presentation::web::views::{ListNavigator, Paginated, RoastView, Roast
 const ROASTER_PAGE_PATH: &str = "/roasters";
 const ROASTER_FRAGMENT_PATH: &str = "/roasters#roaster-list";
 
+#[tracing::instrument(skip(state))]
 async fn load_roaster_page(
     state: &AppState,
     request: ListRequest<RoasterSortKey>,
@@ -40,6 +41,7 @@ async fn load_roaster_page(
     ))
 }
 
+#[tracing::instrument(skip(state, cookies, headers, query))]
 pub(crate) async fn roasters_page(
     State(state): State<AppState>,
     cookies: tower_cookies::Cookies,
@@ -73,6 +75,7 @@ pub(crate) async fn roasters_page(
     render_html(template).map(IntoResponse::into_response)
 }
 
+#[tracing::instrument(skip(state, cookies))]
 pub(crate) async fn roaster_page(
     State(state): State<AppState>,
     cookies: tower_cookies::Cookies,
@@ -103,6 +106,7 @@ pub(crate) async fn roaster_page(
     render_html(template)
 }
 
+#[tracing::instrument(skip(state))]
 pub(crate) async fn list_roasters(
     State(state): State<AppState>,
 ) -> Result<Json<Vec<Roaster>>, ApiError> {
@@ -114,6 +118,7 @@ pub(crate) async fn list_roasters(
     Ok(Json(roasters))
 }
 
+#[tracing::instrument(skip(state, _auth_user, headers, query))]
 pub(crate) async fn create_roaster(
     State(state): State<AppState>,
     _auth_user: AuthenticatedUser,
@@ -143,6 +148,7 @@ pub(crate) async fn create_roaster(
     }
 }
 
+#[tracing::instrument(skip(state))]
 pub(crate) async fn get_roaster(
     State(state): State<AppState>,
     Path(id): Path<RoasterId>,
@@ -151,6 +157,7 @@ pub(crate) async fn get_roaster(
     Ok(Json(roaster))
 }
 
+#[tracing::instrument(skip(state, _auth_user))]
 pub(crate) async fn update_roaster(
     State(state): State<AppState>,
     _auth_user: AuthenticatedUser,
@@ -175,6 +182,7 @@ pub(crate) async fn update_roaster(
     Ok(Json(roaster))
 }
 
+#[tracing::instrument(skip(state, _auth_user, headers, query))]
 pub(crate) async fn delete_roaster(
     State(state): State<AppState>,
     _auth_user: AuthenticatedUser,

src/application/routes/roasts.rs

@@ -21,6 +21,7 @@ use crate::presentation::web::views::{ListNavigator, Paginated, RoastView, Roast
 const ROAST_PAGE_PATH: &str = "/roasts";
 const ROAST_FRAGMENT_PATH: &str = "/roasts#roast-list";
 
+#[tracing::instrument(skip(state))]
 async fn load_roast_page(
     state: &AppState,
     request: ListRequest<RoastSortKey>,
@@ -40,6 +41,7 @@ async fn load_roast_page(
     ))
 }
 
+#[tracing::instrument(skip(state, cookies, headers, query))]
 pub(crate) async fn roasts_page(
     State(state): State<AppState>,
     cookies: tower_cookies::Cookies,
@@ -82,6 +84,7 @@ pub(crate) async fn roasts_page(
     render_html(template).map(IntoResponse::into_response)
 }
 
+#[tracing::instrument(skip(state, cookies))]
 pub(crate) async fn roast_page(
     State(state): State<AppState>,
     cookies: tower_cookies::Cookies,
@@ -111,6 +114,7 @@ pub(crate) async fn roast_page(
     render_html(template)
 }
 
+#[tracing::instrument(skip(state, _auth_user, headers, query))]
 pub(crate) async fn create_roast(
     State(state): State<AppState>,
     _auth_user: AuthenticatedUser,
@@ -146,6 +150,7 @@ pub(crate) async fn create_roast(
     }
 }
 
+#[tracing::instrument(skip(state))]
 pub(crate) async fn list_roasts(
     State(state): State<AppState>,
     Query(params): Query<RoastsQuery>,
@@ -161,6 +166,7 @@ pub(crate) async fn list_roasts(
     Ok(Json(roasts))
 }
 
+#[tracing::instrument(skip(state))]
 pub(crate) async fn get_roast(
     State(state): State<AppState>,
     Path(id): Path<RoastId>,
@@ -169,6 +175,7 @@ pub(crate) async fn get_roast(
     Ok(Json(roast))
 }
 
+#[tracing::instrument(skip(state, _auth_user, headers, query))]
 pub(crate) async fn delete_roast(
     State(state): State<AppState>,
     _auth_user: AuthenticatedUser,

src/application/routes/support.rs

@@ -17,6 +17,7 @@ pub enum PayloadSource {
     Form,
 }
 
+#[derive(Debug)]
 pub struct FlexiblePayload<T> {
     inner: T,
     source: PayloadSource,

src/application/routes/timeline.rs

@@ -18,6 +18,7 @@ const TIMELINE_PAGE_PATH: &str = "/timeline";
 const TIMELINE_FRAGMENT_PATH: &str = "/timeline";
 const TIMELINE_DEFAULT_PAGE_SIZE: u32 = 5;
 
+#[tracing::instrument(skip(state, cookies, headers, query))]
 pub(crate) async fn timeline_page(
     State(state): State<AppState>,
     cookies: tower_cookies::Cookies,
@@ -75,6 +76,7 @@ struct TimelinePageData {
     months: Vec<TimelineMonthView>,
 }
 
+#[tracing::instrument(skip(state))]
 async fn load_timeline_page(
     state: &AppState,
     request: ListRequest<TimelineSortKey>,

src/application/routes/tokens.rs

@@ -47,6 +47,7 @@ impl From<Token> for TokenResponse {
     }
 }
 
+#[tracing::instrument(skip(state, payload), fields(token_name = %payload.name, username = %payload.username))]
 pub async fn create_token(
     State(state): State<AppState>,
     Json(payload): Json<CreateTokenRequest>,
@@ -86,6 +87,7 @@ pub async fn create_token(
     }))
 }
 
+#[tracing::instrument(skip(state, auth_user))]
 pub async fn list_tokens(
     State(state): State<AppState>,
     auth_user: AuthenticatedUser,
@@ -101,6 +103,7 @@ pub async fn list_tokens(
     Ok(Json(token_responses))
 }
 
+#[tracing::instrument(skip(state, auth_user), fields(token_id = %token_id, username = %auth_user.0.username))]
 pub async fn revoke_token(
     State(state): State<AppState>,
     auth_user: AuthenticatedUser,

src/main.rs

@@ -3,13 +3,17 @@ use brewlog::application::{ServerConfig, serve};
 use brewlog::infrastructure::client::BrewlogClient;
 use brewlog::presentation::cli::{Cli, Commands, ServeCommand, roasters, roasts, tokens};
 use clap::Parser;
-use tracing_subscriber::{EnvFilter, fmt, prelude::*};
+
+use tracing::{Subscriber, subscriber::set_global_default};
+use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
+use tracing_log::LogTracer;
+use tracing_subscriber::fmt::MakeWriter;
+use tracing_subscriber::{EnvFilter, Registry, layer::SubscriberExt};
 
 #[tokio::main]
 async fn main() -> Result<()> {
-    if let Err(err) = init_tracing() {
+    let subscriber = get_subscriber("brewlog".into(), "info".into(), std::io::stdout);
-        eprintln!("failed to initialize tracing: {err}");
+    init_subscriber(subscriber);
-    }
 
     let cli = Cli::parse();
 
@@ -51,12 +55,28 @@ async fn run_server(command: ServeCommand) -> Result<()> {
     serve(config).await
 }
 
-fn init_tracing() -> anyhow::Result<()> {
+pub fn get_subscriber<Sink>(
-    let env_filter = EnvFilter::try_from_default_env().or_else(|_| EnvFilter::try_new("info"))?;
+    name: String,
+    env_filter: String,
+    sink: Sink,
+) -> impl Subscriber + Send + Sync
+where
+    Sink: for<'a> MakeWriter<'a> + Send + Sync + 'static,
+{
+    let env_filter =
+        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(env_filter));
+    let formatting_layer = BunyanFormattingLayer::new(name, sink);
 
-    tracing_subscriber::registry()
+    Registry::default()
         .with(env_filter)
-        .with(fmt::layer())
+        .with(JsonStorageLayer)
-        .try_init()
+        .with(formatting_layer)
-        .map_err(|err| anyhow::anyhow!("failed to initialize tracing: {err}"))
+}
+
+/// Register a subscriber as global default to process span data.
+///
+/// This should only be called once!
+pub fn init_subscriber(subscriber: impl Subscriber + Send + Sync) {
+    LogTracer::init().expect("Failed to set logger");
+    set_global_default(subscriber).expect("Failed to set subscriber");
 }