tracing (#315)

* enable tracing on server

* fmt

* instrument handlers

9 files changed, 121 insertions, 8 deletions

diff --git a/Cargo.lock b/Cargo.lock
index e25c51a1..7fed6667 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -23,6 +23,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "ansi_term"
+version = "0.12.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
+dependencies = [
+ "winapi",
+]
+
+[[package]]
 name = "async-trait"
 version = "0.1.53"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -82,6 +91,7 @@ dependencies = [
  "tabwriter",
  "termion",
  "tokio",
+ "tracing-subscriber",
  "tui",
  "unicode-width",
 ]
@@ -149,7 +159,6 @@ dependencies = [
  "eyre",
  "fs-err",
  "http",
- "log",
  "rand 0.8.5",
  "rust-crypto",
  "serde",
@@ -158,6 +167,9 @@ dependencies = [
  "sodiumoxide",
  "sqlx",
  "tokio",
+ "tower",
+ "tower-http",
+ "tracing",
  "uuid",
  "whoami",
 ]
@@ -1168,6 +1180,15 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d"
 
 [[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata",
+]
+
+[[package]]
 name = "matches"
 version = "0.1.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1725,6 +1746,9 @@ name = "regex-automata"
 version = "0.1.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax",
+]
 
 [[package]]
 name = "regex-syntax"
@@ -2005,6 +2029,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 = "shellexpand"
 version = "2.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2291,6 +2324,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 = "time"
 version = "0.1.43"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2436,6 +2478,7 @@ dependencies = [
  "tower",
  "tower-layer",
  "tower-service",
+ "tracing",
 ]
 
 [[package]]
@@ -2481,6 +2524,23 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "90442985ee2f57c9e1b548ee72ae842f4a9a20e3f417cc38dbc5dc684d9bb4ee"
 dependencies = [
  "lazy_static",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.11"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4bc28f93baff38037f64e6f43d34cfa1605f27a49c34e8a04c5e78b0babf2596"
+dependencies = [
+ "ansi_term",
+ "lazy_static",
+ "matchers",
+ "regex",
+ "sharded-slab",
+ "thread_local",
+ "tracing",
+ "tracing-core",
 ]
 
 [[package]]
@@ -2587,6 +2647,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
+[[package]]
 name = "vcpkg"
 version = "0.2.15"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/Cargo.toml b/Cargo.toml
index b39a4f59..b860e40a 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -59,6 +59,17 @@ clap = { version = "3.1.10", features = ["derive"] }
 clap_complete = "3.1.1"
 fs-err = "2.7"
 
+
+[dependencies.tracing-subscriber]
+version = "0.3"
+default-features = false
+features = [
+    "ansi",
+    "fmt",
+    "registry",
+    "env-filter",
+]
+
 [profile.release]
 lto = "fat"
 codegen-units = 1
diff --git a/atuin-server/Cargo.toml b/atuin-server/Cargo.toml
index 871a31f7..33f5f7cd 100644
--- a/atuin-server/Cargo.toml
+++ b/atuin-server/Cargo.toml
@@ -11,7 +11,7 @@ repository = "https://github.com/ellie/atuin"
 [dependencies]
 atuin-common = { path = "../atuin-common", version = "0.8.1" }
 
-log = "0.4"
+tracing = "0.1"
 chrono = { version = "0.4", features = ["serde"] }
 eyre = "0.6"
 uuid = { version = "0.8", features = ["v4"] }
@@ -31,3 +31,5 @@ axum = "0.5"
 http = "0.2"
 fs-err = "2.7"
 chronoutil = "0.2.3"
+tower = "0.4"
+tower-http = { version = "0.2", features = ["trace"] }
diff --git a/atuin-server/src/database.rs b/atuin-server/src/database.rs
index efde86a3..2d3f8be1 100644
--- a/atuin-server/src/database.rs
+++ b/atuin-server/src/database.rs
@@ -1,5 +1,6 @@
 use async_trait::async_trait;
 use std::collections::HashMap;
+use tracing::{debug, instrument};
 
 use sqlx::{postgres::PgPoolOptions, Result};
 
@@ -77,6 +78,7 @@ impl Postgres {
 
 #[async_trait]
 impl Database for Postgres {
+    #[instrument(skip_all)]
     async fn get_session(&self, token: &str) -> Result<Session> {
         sqlx::query_as::<_, Session>("select * from sessions where token = $1")
             .bind(token)
@@ -84,6 +86,7 @@ impl Database for Postgres {
             .await
     }
 
+    #[instrument(skip_all)]
     async fn get_user(&self, username: &str) -> Result<User> {
         sqlx::query_as::<_, User>("select * from users where username = $1")
             .bind(username)
@@ -91,6 +94,7 @@ impl Database for Postgres {
             .await
     }
 
+    #[instrument(skip_all)]
     async fn get_session_user(&self, token: &str) -> Result<User> {
         sqlx::query_as::<_, User>(
             "select * from users 
@@ -103,6 +107,7 @@ impl Database for Postgres {
         .await
     }
 
+    #[instrument(skip_all)]
     async fn count_history(&self, user: &User) -> Result<i64> {
         // The cache is new, and the user might not yet have a cache value.
         // They will have one as soon as they post up some new history, but handle that
@@ -119,6 +124,7 @@ impl Database for Postgres {
         Ok(res.0)
     }
 
+    #[instrument(skip_all)]
     async fn count_history_cached(&self, user: &User) -> Result<i64> {
         let res: (i32,) = sqlx::query_as(
             "select total from total_history_count_user
@@ -131,6 +137,7 @@ impl Database for Postgres {
         Ok(res.0 as i64)
     }
 
+    #[instrument(skip_all)]
     async fn count_history_range(
         &self,
         user: &User,
@@ -153,6 +160,7 @@ impl Database for Postgres {
     }
 
     // Count the history for a given year
+    #[instrument(skip_all)]
     async fn count_history_year(&self, user: &User, year: i32) -> Result<i64> {
         let start = chrono::Utc.ymd(year, 1, 1).and_hms_nano(0, 0, 0, 0);
         let end = start + RelativeDuration::years(1);
@@ -164,6 +172,7 @@ impl Database for Postgres {
     }
 
     // Count the history for a given month
+    #[instrument(skip_all)]
     async fn count_history_month(&self, user: &User, month: chrono::NaiveDate) -> Result<i64> {
         let start = chrono::Utc
             .ymd(month.year(), month.month(), 1)
@@ -189,6 +198,7 @@ impl Database for Postgres {
     }
 
     // Count the history for a given day
+    #[instrument(skip_all)]
     async fn count_history_day(&self, user: &User, day: chrono::NaiveDate) -> Result<i64> {
         let start = chrono::Utc
             .ymd(day.year(), day.month(), day.day())
@@ -203,6 +213,7 @@ impl Database for Postgres {
         Ok(res)
     }
 
+    #[instrument(skip_all)]
     async fn list_history(
         &self,
         user: &User,
@@ -230,6 +241,7 @@ impl Database for Postgres {
         Ok(res)
     }
 
+    #[instrument(skip_all)]
     async fn add_history(&self, history: &[NewHistory]) -> Result<()> {
         let mut tx = self.pool.begin().await?;
 
@@ -259,6 +271,7 @@ impl Database for Postgres {
         Ok(())
     }
 
+    #[instrument(skip_all)]
     async fn add_user(&self, user: &NewUser) -> Result<i64> {
         let email: &str = &user.email;
         let username: &str = &user.username;
@@ -279,6 +292,7 @@ impl Database for Postgres {
         Ok(res.0)
     }
 
+    #[instrument(skip_all)]
     async fn add_session(&self, session: &NewSession) -> Result<()> {
         let token: &str = &session.token;
 
@@ -295,6 +309,7 @@ impl Database for Postgres {
         Ok(())
     }
 
+    #[instrument(skip_all)]
     async fn get_user_session(&self, u: &User) -> Result<Session> {
         sqlx::query_as::<_, Session>("select * from sessions where user_id = $1")
             .bind(u.id)
@@ -302,6 +317,7 @@ impl Database for Postgres {
             .await
     }
 
+    #[instrument(skip_all)]
     async fn oldest_history(&self, user: &User) -> Result<History> {
         let res = sqlx::query_as::<_, History>(
             "select * from history 
@@ -316,6 +332,7 @@ impl Database for Postgres {
         Ok(res)
     }
 
+    #[instrument(skip_all)]
     async fn calendar(
         &self,
         user: &User,
diff --git a/atuin-server/src/handlers/history.rs b/atuin-server/src/handlers/history.rs
index 4fa2a962..b7112526 100644
--- a/atuin-server/src/handlers/history.rs
+++ b/atuin-server/src/handlers/history.rs
@@ -2,6 +2,7 @@ use axum::extract::Query;
 use axum::{extract::Path, Extension, Json};
 use http::StatusCode;
 use std::collections::HashMap;
+use tracing::{debug, error, instrument};
 
 use crate::database::{Database, Postgres};
 use crate::models::{NewHistory, User};
@@ -9,6 +10,7 @@ use atuin_common::api::*;
 
 use crate::calendar::{TimePeriod, TimePeriodInfo};
 
+#[instrument(skip_all, fields(user.id = user.id))]
 pub async fn count(
     user: User,
     db: Extension<Postgres>,
@@ -27,6 +29,7 @@ pub async fn count(
     }
 }
 
+#[instrument(skip_all, fields(user.id = user.id))]
 pub async fn list(
     req: Query<SyncHistoryRequest>,
     user: User,
@@ -62,6 +65,7 @@ pub async fn list(
     Ok(Json(SyncHistoryResponse { history }))
 }
 
+#[instrument(skip_all, fields(user.id = user.id))]
 pub async fn add(
     Json(req): Json<Vec<AddHistoryRequest>>,
     user: User,
@@ -90,6 +94,7 @@ pub async fn add(
     Ok(())
 }
 
+#[instrument(skip_all, fields(user.id = user.id))]
 pub async fn calendar(
     Path(focus): Path<String>,
     Query(params): Query<HashMap<String, u64>>,
diff --git a/atuin-server/src/handlers/user.rs b/atuin-server/src/handlers/user.rs
index 42e4aa33..a9a48fdc 100644
--- a/atuin-server/src/handlers/user.rs
+++ b/atuin-server/src/handlers/user.rs
@@ -6,6 +6,7 @@ use axum::extract::Path;
 use axum::{Extension, Json};
 use http::StatusCode;
 use sodiumoxide::crypto::pwhash::argon2id13;
+use tracing::{debug, error, instrument};
 use uuid::Uuid;
 
 use crate::database::{Database, Postgres};
@@ -26,6 +27,7 @@ pub fn verify_str(secret: &str, verify: &str) -> bool {
     }
 }
 
+#[instrument(skip_all, fields(user.username = username.as_str()))]
 pub async fn get(
     Path(username): Path<String>,
     db: Extension<Postgres>,
@@ -48,6 +50,7 @@ pub async fn get(
     }))
 }
 
+#[instrument(skip_all)]
 pub async fn register(
     Json(register): Json<RegisterRequest>,
     settings: Extension<Settings>,
@@ -95,6 +98,7 @@ pub async fn register(
     }
 }
 
+#[instrument(skip_all, fields(user.username = login.username.as_str()))]
 pub async fn login(
     login: Json<LoginRequest>,
     db: Extension<Postgres>,
diff --git a/atuin-server/src/lib.rs b/atuin-server/src/lib.rs
index 02b3fdae..8811986e 100644
--- a/atuin-server/src/lib.rs
+++ b/atuin-server/src/lib.rs
@@ -9,9 +9,6 @@ use eyre::{Context, Result};
 use crate::settings::Settings;
 
 #[macro_use]
-extern crate log;
-
-#[macro_use]
 extern crate serde_derive;
 
 pub mod auth;
diff --git a/atuin-server/src/router.rs b/atuin-server/src/router.rs
index 146cc991..9b525e05 100644
--- a/atuin-server/src/router.rs
+++ b/atuin-server/src/router.rs
@@ -7,6 +7,8 @@ use axum::{
     Extension, Router,
 };
 use eyre::Result;
+use tower::ServiceBuilder;
+use tower_http::trace::TraceLayer;
 
 use super::{
     database::{Database, Postgres},
@@ -65,6 +67,10 @@ pub fn router(postgres: Postgres, settings: Settings) -> Router {
         .route("/register", post(handlers::user::register))
         .route("/login", post(handlers::user::login))
         .fallback(teapot.into_service())
-        .layer(Extension(postgres))
-        .layer(Extension(settings))
+        .layer(
+            ServiceBuilder::new()
+                .layer(TraceLayer::new_for_http())
+                .layer(Extension(postgres))
+                .layer(Extension(settings)),
+        )
 }
diff --git a/src/command/server.rs b/src/command/server.rs
index cd05caca..c5af9ae5 100644
--- a/src/command/server.rs
+++ b/src/command/server.rs
@@ -1,3 +1,5 @@
+use tracing_subscriber::{fmt, prelude::*, EnvFilter};
+
 use clap::Parser;
 use eyre::{Context, Result};
 
@@ -21,7 +23,10 @@ pub enum Cmd {
 
 impl Cmd {
     pub async fn run(self) -> Result<()> {
-        pretty_env_logger::init();
+        tracing_subscriber::registry()
+            .with(fmt::layer())
+            .with(EnvFilter::from_default_env())
+            .init();
 
         let settings = Settings::new().wrap_err("could not load server settings")?;