feat: add tracing log identifier to each HTTP route handler

Cargo.lock

@@ -1468,7 +1468,7 @@ version = "0.4.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "975de676448231fcde04b9149d2543077e166b78fc29eae5aa219e7928410da2"
 dependencies = [
- "uuid",
+ "uuid 0.8.2",
 ]
 
 [[package]]
@@ -1601,7 +1601,6 @@ dependencies = [
  "futures",
  "git2",
  "lazy_static",
- "log",
  "mime",
  "mime_guess",
  "mktemp",
@@ -1615,6 +1614,8 @@ dependencies = [
  "sqlx",
  "tera",
  "tokio",
+ "tracing",
+ "tracing-actix-web",
  "url",
  "urlencoding",
 ]
@@ -1767,6 +1768,26 @@ dependencies = [
  "siphasher",
 ]
 
+[[package]]
+name = "pin-project"
+version = "1.0.12"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ad29a609b6bcd67fee905812e544992d216af9d755757c05ed2d0e15a74c6ecc"
+dependencies = [
+ "pin-project-internal",
+]
+
+[[package]]
+name = "pin-project-internal"
+version = "1.0.12"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "069bdb1e05adc7a8990dce9cc75370895fbe4e3d58b9b73bf1aee56359344a55"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "pin-project-lite"
 version = "0.2.9"
@@ -2554,21 +2575,45 @@ dependencies = [
 
 [[package]]
 name = "tracing"
-version = "0.1.36"
+version = "0.1.37"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "2fce9567bd60a67d08a16488756721ba392f24f29006402881e43b19aac64307"
+checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8"
 dependencies = [
  "cfg-if",
  "log",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
 [[package]]
-name = "tracing-core"
-version = "0.1.29"
+name = "tracing-actix-web"
+version = "0.6.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "5aeea4303076558a00714b823f9ad67d58a3bbda1df83d8827d21193156e22f7"
+checksum = "d725b8fa6ef307b3f4856913523337de45c47cc79271bafd7acfb39559e3a2da"
+dependencies = [
+ "actix-web",
+ "pin-project",
+ "tracing",
+ "uuid 1.2.1",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.23"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.30"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a"
 dependencies = [
  "once_cell",
 ]
@@ -2726,6 +2771,15 @@ dependencies = [
  "getrandom",
 ]
 
+[[package]]
+name = "uuid"
+version = "1.2.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "feb41e78f93363bb2df8b0e86a2ca30eed7806ea16ea0c790d757cf93f79be83"
+dependencies = [
+ "getrandom",
+]
+
 [[package]]
 name = "validator"
 version = "0.15.0"

Cargo.toml

@@ -29,7 +29,6 @@ serde = { version = "1", features = ["derive", "rc"]}
 serde_json = "1"
 
 pretty_env_logger = "0.4"
-log = "0.4"
 
 lazy_static = "1.4"
 
@@ -47,7 +46,8 @@ mime_guess = "2.0.4"
 mime = "0.3.16"
 rust-embed = "6.3.0"
 rand = "0.8.5"
-
+tracing = { version = "0.1.37", features = ["log"]}
+tracing-actix-web = "0.6.2"
 
 [dependencies.cache-buster]
 git = "https://github.com/realaravinth/cache-buster"

src/api/v1/account/mod.rs

@@ -58,6 +58,7 @@ pub struct Username {
     path = "crate::V1_API_ROUTES.account.update_username",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Update username", skip(ctx, payload, id))]
 async fn set_username(
     id: Identity,
     payload: web::Json<Username>,
@@ -74,6 +75,7 @@ async fn set_username(
 }
 
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.account.username_exists")]
+#[tracing::instrument(name = "Check if username exists", skip(ctx, payload))]
 async fn username_exists(
     payload: web::Json<AccountCheckPayload>,
     ctx: AppCtx,
@@ -82,6 +84,7 @@ async fn username_exists(
 }
 
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.account.email_exists")]
+#[tracing::instrument(name = "Check if email exists", skip(ctx, payload))]
 pub async fn email_exists(
     payload: web::Json<AccountCheckPayload>,
     ctx: AppCtx,
@@ -94,6 +97,7 @@ pub async fn email_exists(
     path = "crate::V1_API_ROUTES.account.update_email",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Update email", skip(ctx, payload, id))]
 async fn set_email(
     id: Identity,
     payload: web::Json<Email>,
@@ -108,6 +112,7 @@ async fn set_email(
     path = "crate::V1_API_ROUTES.account.delete",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Delete account", skip(ctx, payload, id))]
 async fn delete_account(
     id: Identity,
     payload: web::Json<Password>,
@@ -124,6 +129,7 @@ async fn delete_account(
     path = "crate::V1_API_ROUTES.account.update_password",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Update user password", skip(ctx, payload, id))]
 async fn update_user_password(
     id: Identity,
     ctx: AppCtx,

src/api/v1/auth.rs

@@ -30,12 +30,14 @@ pub fn services(cfg: &mut web::ServiceConfig) {
     cfg.service(signout);
 }
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.auth.register")]
+#[tracing::instrument(name = "Register new user", skip(ctx, payload))]
 async fn register(payload: web::Json<Register>, ctx: AppCtx) -> ServiceResult<impl Responder> {
     ctx.register(&payload).await?;
     Ok(HttpResponse::Ok())
 }
 
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.auth.login")]
+#[tracing::instrument(name = "Login", skip(ctx, payload, id, query))]
 async fn login(
     id: Identity,
     payload: web::Json<Login>,
@@ -59,6 +61,7 @@ async fn login(
     path = "crate::V1_API_ROUTES.auth.logout",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Sign out", skip(id))]
 async fn signout(id: Identity) -> impl Responder {
     use actix_auth_middleware::GetLoginRoute;
 

src/api/v1/pages.rs

@@ -0,0 +1,17 @@
+/*
+ * Copyright (C) 2022  Aravinth Manivannan <realaravinth@batsense.net>
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation, either version 3 of the
+ * License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <https://www.gnu.org/licenses/>.
+ */
+

src/ctx/mod.rs

@@ -20,6 +20,7 @@ use std::thread;
 use crate::db::*;
 use crate::settings::Settings;
 use argon2_creds::{Config as ArgonConfig, ConfigBuilder as ArgonConfigBuilder, PasswordPolicy};
+use tracing::info;
 
 pub mod api;
 
@@ -51,9 +52,9 @@ impl Ctx {
 
         #[allow(unused_variables)]
         let init = thread::spawn(move || {
-            log::info!("Initializing credential manager");
+            info!("Initializing credential manager");
             c.init();
-            log::info!("Initialized credential manager");
+            info!("Initialized credential manager");
         });
         let db = get_db(&settings).await;
 

src/db.rs

@@ -22,6 +22,7 @@ use sqlx::types::time::OffsetDateTime;
 //use sqlx::types::Json;
 use sqlx::ConnectOptions;
 use sqlx::PgPool;
+use tracing::error;
 use url::quirks::hostname;
 
 use crate::errors::*;
@@ -490,7 +491,7 @@ fn map_register_err(e: sqlx::Error) -> ServiceError {
             } else if msg.contains("librepages_users_email_key") {
                 ServiceError::EmailTaken
             } else {
-                log::error!("{}", msg);
+                error!("{}", msg);
                 ServiceError::InternalServerError
             }
         } else {

src/deploy.rs

@@ -45,6 +45,7 @@ pub struct DeployEvent {
 }
 
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.deploy.update")]
+#[tracing::instrument(name = "Update webpages", skip(payload, ctx))]
 async fn update(payload: web::Json<DeployEvent>, ctx: AppCtx) -> ServiceResult<impl Responder> {
     let payload = payload.into_inner();
     ctx.update_site(&payload.secret, Some(payload.branch))
@@ -81,12 +82,12 @@ impl DeployInfo {
 }
 
 #[actix_web_codegen_const_routes::post(path = "crate::V1_API_ROUTES.deploy.info")]
+#[tracing::instrument(name = "Get webpage deploy info", skip(payload, ctx))]
 async fn deploy_info(
     payload: web::Json<DeploySecret>,
     ctx: AppCtx,
 ) -> ServiceResult<impl Responder> {
     if let Ok(page) = ctx.db.get_site_from_secret(&payload.secret).await {
-        //    if let Some(page) = find_page(&payload.secret, &ctx) {
         let resp = DeployInfo::from_page(&Page::from_site(&ctx.settings, page))?;
         Ok(HttpResponse::Ok().json(resp))
     } else {

src/main.rs

@@ -22,8 +22,9 @@ use actix_web::{
     web::JsonConfig, App, HttpServer,
 };
 use clap::{Parser, Subcommand};
-use log::info;
 use static_assets::FileMap;
+use tracing::info;
+use tracing_actix_web::TracingLogger;
 
 mod api;
 mod ctx;
@@ -80,10 +81,11 @@ enum Commands {
 #[actix_web::main]
 #[cfg(not(tarpaulin_include))]
 async fn main() -> std::io::Result<()> {
-    env::set_var("RUST_LOG", "info");
+    if env::var("RUST_LOG").is_err() {
+        env::set_var("RUST_LOG", "info");
+    }
 
     pretty_env_logger::init();
-
     let cli = Cli::parse();
 
     info!(
@@ -111,7 +113,7 @@ async fn serve(settings: Settings, ctx: AppCtx) -> std::io::Result<()> {
     info!("Starting server on: http://{}", ip);
     HttpServer::new(move || {
         App::new()
-            .wrap(actix_middleware::Logger::default())
+            .wrap(TracingLogger::default())
             .wrap(actix_middleware::Compress::default())
             .app_data(ctx.clone())
             .app_data(get_json_err())

src/meta.rs

@@ -44,6 +44,7 @@ pub mod routes {
 
 /// emits build details of the binary
 #[actix_web_codegen_const_routes::get(path = "crate::V1_API_ROUTES.meta.build_details")]
+#[tracing::instrument(name = "Fetch Build Details", skip(ctx))]
 async fn build_details(ctx: AppCtx) -> impl Responder {
     let build = BuildDetails {
         version: VERSION,
@@ -61,6 +62,7 @@ pub struct Health {
 
 /// checks all components of the system
 #[actix_web_codegen_const_routes::get(path = "crate::V1_API_ROUTES.meta.health")]
+#[tracing::instrument(name = "Fetch health", skip(ctx))]
 async fn health(ctx: crate::AppCtx) -> impl Responder {
     let res = Health {
         db: ctx.db.ping().await,

src/page.rs

@@ -14,16 +14,18 @@
  * You should have received a copy of the GNU Affero General Public License
  * along with this program.  If not, see <https://www.gnu.org/licenses/>.
  */
-
-use git2::{build::CheckoutBuilder, BranchType, Direction, Oid, Remote, Repository};
-#[cfg(not(test))]
-use log::info;
-
 #[cfg(test)]
 use std::println as info;
+#[cfg(test)]
+use std::println as error;
+#[cfg(test)]
+use std::println as debug;
 
+use git2::{build::CheckoutBuilder, BranchType, Direction, Oid, Remote, Repository};
 use serde::Deserialize;
 use serde::Serialize;
+#[cfg(not(test))]
+use tracing::{debug, error, info};
 
 use crate::db::Site;
 use crate::errors::*;
@@ -95,7 +97,7 @@ impl Page {
         branch: &str,
     ) -> ServiceResult<git2::AnnotatedCommit<'a>> {
         let mut remote = repo.find_remote("origin")?;
-        log::info!("Fetching {} for repo", remote.name().unwrap());
+        info!("Fetching {} for repo", remote.name().unwrap());
         remote.fetch(&[branch], None, None)?;
         let fetch_head = repo.find_reference("FETCH_HEAD")?;
         Ok(repo.reference_to_annotated_commit(&fetch_head)?)
@@ -112,20 +114,19 @@ impl Page {
 
         // 2. Do the appropriate merge
         if analysis.0.is_fast_forward() {
-            //log::debug!("Doing a fast forward");
-            log::debug!("Doing a fast forward");
+            debug!("Doing a fast forward");
             // do a fast forward
             let refname = format!("refs/heads/{}", branch);
             match repo.find_reference(&refname) {
                 Ok(mut r) => {
-                    log::debug!("fast forwarding");
+                    debug!("fast forwarding");
                     Self::fast_forward(repo, &mut r, &fetch_commit).unwrap();
                 }
                 Err(_) => {
                     // The branch doesn't exist so just set the reference to the
                     // commit directly. Usually this is because you are pulling
                     // into an empty repository.
-                    log::error!("Error in find ref");
+                    error!("Error in find ref");
                     repo.reference(
                         &refname,
                         fetch_commit.id(),
@@ -151,7 +152,7 @@ impl Page {
                 .unwrap();
             Self::normal_merge(repo, &head_commit, &fetch_commit).unwrap();
         } else {
-            log::info!("Nothing to do...");
+            info!("Nothing to do...");
         }
         Ok(())
     }
@@ -178,7 +179,7 @@ impl Page {
     ) -> Result<(), git2::Error> {
         let local_tree = repo.find_commit(local.id())?.tree().unwrap();
         let remote_tree = repo.find_commit(remote.id())?.tree().unwrap();
-        println!("{} {}", local.id(), remote.id());
+        debug!("{} {}", local.id(), remote.id());
         let ancestor = repo
             .find_commit(repo.merge_base(local.id(), remote.id()).unwrap())
             .unwrap()
@@ -189,7 +190,7 @@ impl Page {
             .unwrap();
 
         if idx.has_conflicts() {
-            log::debug!("Merge conflicts detected...");
+            debug!("Merge conflicts detected...");
             repo.checkout_index(Some(&mut idx), None)?;
             return Ok(());
         }
@@ -223,7 +224,7 @@ impl Page {
             None => String::from_utf8_lossy(lb.name_bytes()).to_string(),
         };
         let msg = format!("Fast-Forward: Setting {} to id: {}", name, rc.id());
-        log::debug!("{}", msg);
+        debug!("{}", msg);
         lb.set_target(rc.id(), &msg)?;
         repo.set_head(&name)?;
         repo.checkout_head(Some(git2::build::CheckoutBuilder::default().force()))?;

src/pages/auth/login.rs

@@ -61,6 +61,7 @@ impl Login {
 }
 
 #[actix_web_codegen_const_routes::get(path = "PAGES.auth.login")]
+#[tracing::instrument(name = "Serve login page", skip(ctx))]
 pub async fn get_login(ctx: AppCtx) -> impl Responder {
     let login = Login::page(&ctx.settings);
     let html = ContentType::html();
@@ -73,6 +74,7 @@ pub fn services(cfg: &mut web::ServiceConfig) {
 }
 
 #[actix_web_codegen_const_routes::post(path = "PAGES.auth.login")]
+#[tracing::instrument(name = "Web UI Login", skip(id, payload, query, ctx))]
 pub async fn login_submit(
     id: Identity,
     payload: web::Form<LoginPayload>,

src/pages/auth/mod.rs

@@ -42,13 +42,13 @@ pub fn services(cfg: &mut web::ServiceConfig) {
     path = "PAGES.auth.logout",
     wrap = "super::get_auth_middleware()"
 )]
+#[tracing::instrument(name = "Sign out", skip(id))]
 async fn signout(id: Identity) -> impl Responder {
     use actix_auth_middleware::GetLoginRoute;
 
     if id.identity().is_some() {
         id.forget();
     }
-    println!("received signout");
     HttpResponse::Found()
         .append_header((http::header::LOCATION, PAGES.get_login_route(None)))
         .finish()

src/pages/auth/register.rs

@@ -58,6 +58,7 @@ impl Register {
 }
 
 #[actix_web_codegen_const_routes::get(path = "PAGES.auth.register")]
+#[tracing::instrument(name = "Serve registration page", skip(ctx))]
 pub async fn get_register(ctx: AppCtx) -> impl Responder {
     let login = Register::page(&ctx.settings);
     let html = ContentType::html();
@@ -70,6 +71,7 @@ pub fn services(cfg: &mut web::ServiceConfig) {
 }
 
 #[actix_web_codegen_const_routes::post(path = "PAGES.auth.register")]
+#[tracing::instrument(name = "Process web UI registration", skip(ctx))]
 pub async fn register_submit(
     payload: web::Form<RegisterPayload>,
     ctx: AppCtx,

src/pages/dash/home.rs

@@ -16,11 +16,9 @@
  */
 use std::cell::RefCell;
 
-use actix_identity::Identity;
 use actix_web::http::header::ContentType;
 use tera::Context;
 
-use crate::api::v1::RedirectQuery;
 use crate::ctx::api::v1::auth::Login as LoginPayload;
 use crate::pages::errors::*;
 use crate::settings::Settings;
@@ -63,6 +61,7 @@ impl Home {
 }
 
 #[actix_web_codegen_const_routes::get(path = "PAGES.dash.home")]
+#[tracing::instrument(name = "Dashboard homepage", skip(ctx))]
 pub async fn get_home(ctx: AppCtx) -> impl Responder {
     let home = Home::page(&ctx.settings);
     let html = ContentType::html();

src/pages/mod.rs

@@ -165,6 +165,7 @@ impl Home {
 }
 
 #[actix_web_codegen_const_routes::get(path = "PAGES.home")]
+#[tracing::instrument(name = "Dashboard homepage", skip(id, ctx))]
 pub async fn home(ctx: AppCtx, id: Identity) -> impl Responder {
     if id.identity().is_none() {
         let home = Home::page(&ctx.settings);

src/serve.rs

@@ -34,6 +34,7 @@ pub mod routes {
 }
 
 #[actix_web_codegen_const_routes::get(path = "crate::V1_API_ROUTES.serve.catch_all")]
+#[tracing::instrument(name = "Serve webpages", skip(req, ctx))]
 async fn index(req: HttpRequest, ctx: AppCtx) -> ServiceResult<impl Responder> {
     let c = req.connection_info();
     let mut host = c.host();

src/settings.rs

@@ -21,7 +21,7 @@ use std::sync::Arc;
 use config::{Config, ConfigError, Environment, File};
 use derive_more::Display;
 #[cfg(not(test))]
-use log::{error, warn};
+use tracing::{error, warn};
 
 #[cfg(test)]
 use std::{println as warn, println as error};