From c908123a7440c498f19c4cc40a52e4718bd528a3 Mon Sep 17 00:00:00 2001 From: "Z. Charles Dziura" Date: Thu, 3 Oct 2024 10:05:30 -0400 Subject: [PATCH] Further logging changes, and include some additional log messages when creating new users --- api/Cargo.toml | 2 + api/src/requests/mod.rs | 19 ++--- api/src/requests/user/create/handler.rs | 72 +++++++++++++------ .../create/models/registration_request.rs | 15 +++- .../create/models/registration_response.rs | 6 +- api/src/services/logger.rs | 25 ++++--- 6 files changed, 95 insertions(+), 44 deletions(-) diff --git a/api/Cargo.toml b/api/Cargo.toml index 3f2cdc2..e1c3b75 100644 --- a/api/Cargo.toml +++ b/api/Cargo.toml @@ -37,9 +37,11 @@ sqlx = { version = "0.8", features = [ "runtime-tokio", ] } syslog-tracing = "0.3.1" +time = { version = "0.3.36", features = ["formatting", "macros"] } tokio = { version = "1.35", features = ["full"] } tower = "0.5" tower-http = { version = "0.6", features = ["full"] } tracing = "0.1.40" tracing-subscriber = { version = "0.3.18", features = ["env-filter", "time"] } +ulid = "1.1" uuid = { version = "1.10", features = ["serde", "v7"] } diff --git a/api/src/requests/mod.rs b/api/src/requests/mod.rs index 7c9fdb2..deb4e5a 100644 --- a/api/src/requests/mod.rs +++ b/api/src/requests/mod.rs @@ -7,9 +7,11 @@ use axum::{ response::Response, Router, }; +use humantime::format_duration; use tokio::net::TcpListener; use tower_http::trace::TraceLayer; use tracing::{error, info, info_span, warn, Span}; +use ulid::Ulid; use crate::{ db::DbPool, @@ -47,22 +49,21 @@ pub async fn start_app(pool: DbPool, env: Environment) -> Result<(), AppError> { let logging_layer = TraceLayer::new_for_http() .make_span_with(|request: &Request| { - let request_path = request + let path = request .extensions() .get::() .map(MatchedPath::as_str).unwrap(); - info_span!("http_request", method = %request.method(), path = %request_path, status = tracing::field::Empty) + info_span!("api_request", request_id = %Ulid::new(), method = %request.method(), %path, status = tracing::field::Empty) }) - .on_response(|response: &Response, _duration: Duration, _span: &Span| { + .on_response(|response: &Response, duration: Duration, span: &Span| { let status = response.status(); + span.record("status", status.to_string()); - _span.record("status", status.to_string()); - - match status.as_u16() { - w if (300..400).contains(&w) => warn!(""), - e if e >= 400 => error!(""), - _ => info!("") + match status { + w if w.is_redirection() => warn!(duration = ?format_duration(duration).to_string()), + e if e.is_client_error() || e.is_server_error() => error!(duration = ?format_duration(duration).to_string()), + _ => info!(duration = ?format_duration(duration).to_string()) } }); diff --git a/api/src/requests/user/create/handler.rs b/api/src/requests/user/create/handler.rs index 0bbc723..6f4ac41 100644 --- a/api/src/requests/user/create/handler.rs +++ b/api/src/requests/user/create/handler.rs @@ -1,28 +1,55 @@ +use std::sync::mpsc::Sender; + use crate::{ - db::{insert_new_user, NewUserEntity, UserEntity}, + db::{insert_new_user, DbPool, NewUserEntity, UserEntity}, models::ApiResponse, requests::AppState, services::{auth_token::generate_new_user_token, hash_string, UserConfirmationMessage}, }; use axum::{ + debug_handler, extract::State, response::{IntoResponse, Response}, Json, }; use http::StatusCode; +use pasetors::{keys::SymmetricKey, version4::V4}; +use tracing::debug; use super::models::{UserRegistrationRequest, UserRegistrationResponse}; +#[debug_handler] pub async fn user_registration_post_handler( - State(app_state): State, + State(state): State, Json(request): Json, ) -> Result { + let env = state.env(); + + register_new_user_request( + request, + state.pool(), + env.token_key(), + env.send_verification_email(), + env.email_sender(), + ) + .await +} + +async fn register_new_user_request( + body: UserRegistrationRequest, + pool: &DbPool, + signing_key: &SymmetricKey, + send_verification_email: bool, + email_sender: &Sender, +) -> Result { + debug!(?body, send_verification_email); + let UserRegistrationRequest { username, password, email, name, - } = request; + } = body; let hashed_password = hash_string(password); @@ -33,7 +60,7 @@ pub async fn user_registration_post_handler( name, }; - let UserEntity { id: user_id, name, email , ..} = insert_new_user(app_state.pool(), new_user).await + let UserEntity { id: user_id, name, email , ..} = insert_new_user(pool, new_user).await .map_err(|err| { if err.is_duplicate_record() { (StatusCode::CONFLICT, ApiResponse::error("There is already an account associated with this username or email address.").into_json_response()).into_response() @@ -42,32 +69,37 @@ pub async fn user_registration_post_handler( } })?; - let signing_key = app_state.env().token_key(); let (auth_token, expiration) = generate_new_user_token(signing_key, user_id); - let new_user_confirmation_message = UserConfirmationMessage { - email: email.clone(), - name: name.clone(), - auth_token: auth_token.clone(), - }; + let response_body = if send_verification_email { + let new_user_confirmation_message = UserConfirmationMessage { + email, + name, + auth_token: auth_token.clone(), + }; - if app_state.env().send_verification_email() { - let _ = app_state - .env() - .email_sender() + let _ = email_sender .send(new_user_confirmation_message) .inspect_err(|err| { eprintln!("Got the rollowing error while sending across the channel: {err}"); }); - } + + UserRegistrationResponse { + id: user_id, + expiration, + auth_token: None, + } + } else { + UserRegistrationResponse { + id: user_id, + expiration, + auth_token: Some(auth_token), + } + }; let response = ( StatusCode::CREATED, - ApiResponse::new(UserRegistrationResponse { - id: user_id, - expiration, - }) - .into_json_response(), + ApiResponse::new(response_body).into_json_response(), ); Ok(response.into_response()) diff --git a/api/src/requests/user/create/models/registration_request.rs b/api/src/requests/user/create/models/registration_request.rs index d1ac282..86f3bd1 100644 --- a/api/src/requests/user/create/models/registration_request.rs +++ b/api/src/requests/user/create/models/registration_request.rs @@ -1,6 +1,8 @@ +use std::fmt::Debug; + use serde::Deserialize; -#[derive(Debug, Deserialize)] +#[derive(Deserialize)] #[serde(rename_all = "camelCase")] pub struct UserRegistrationRequest { pub username: String, @@ -8,3 +10,14 @@ pub struct UserRegistrationRequest { pub email: String, pub name: String, } + +impl Debug for UserRegistrationRequest { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("UserRegistrationRequest") + .field("username", &self.username) + .field("password", &"********") + .field("email", &self.email) + .field("name", &self.name) + .finish() + } +} diff --git a/api/src/requests/user/create/models/registration_response.rs b/api/src/requests/user/create/models/registration_response.rs index 651d11d..d25a20f 100644 --- a/api/src/requests/user/create/models/registration_response.rs +++ b/api/src/requests/user/create/models/registration_response.rs @@ -1,13 +1,17 @@ use std::time::SystemTime; use serde::Serialize; -use serde_with::serde_as; +use serde_with::{serde_as, skip_serializing_none}; #[serde_as] +#[skip_serializing_none] #[derive(Debug, Serialize)] +#[serde(rename_all = "camelCase")] pub struct UserRegistrationResponse { pub id: i32, #[serde(serialize_with = "humantime_serde::serialize")] pub expiration: SystemTime, + + pub auth_token: Option, } diff --git a/api/src/services/logger.rs b/api/src/services/logger.rs index ead58de..987c4f2 100644 --- a/api/src/services/logger.rs +++ b/api/src/services/logger.rs @@ -2,10 +2,12 @@ use std::time::SystemTime; use humantime::format_rfc3339_millis; +use time::macros::format_description; use tracing::{level_filters::LevelFilter, Event, Subscriber}; use tracing_subscriber::{ fmt::{ format::{DefaultFields, Writer}, + time::UtcTime, FmtContext, FormatEvent, FormatFields, FormattedFields, }, registry::{LookupSpan, Scope}, @@ -16,29 +18,26 @@ use crate::models::Environment; pub fn initialize_logger(env: &Environment) { let log_level = env.rust_log(); + let env_filter = EnvFilter::builder() + .with_default_directive(LevelFilter::TRACE.into()) + .parse_lossy(log_level); #[cfg(debug_assertions)] tracing_subscriber::fmt() - .with_env_filter( - EnvFilter::builder() - .with_default_directive(LevelFilter::TRACE.into()) - .parse_lossy(log_level), - ) + .with_env_filter(env_filter) .event_format(tracing_subscriber::fmt::format().compact()) .with_target(false) .with_file(true) .with_line_number(true) + .with_timer(UtcTime::new(format_description!( + "[year]-[month]-[day]T[hour repr:24]:[minute]:[second].[subsecond digits:3]Z" + ))) .init(); #[cfg(not(debug_assertions))] tracing_subscriber::fmt() - .with_env_filter( - EnvFilter::builder() - .with_default_directive(LevelFilter::INFO.into()) - .parse_lossy(log_level), - ) + .with_env_filter(env_filter) .event_format(EventFormatter) - .fmt_fields(DefaultFields::new()) .init(); } @@ -57,7 +56,7 @@ where let timestamp = format_rfc3339_millis(SystemTime::now()); let level = event.metadata().level(); - write!(writer, "{timestamp} {level:<5} ")?; + write!(writer, "{timestamp} {level:>5} ")?; ctx.field_format().format_fields(writer.by_ref(), event)?; @@ -65,7 +64,7 @@ where let exts = span.extensions(); if let Some(fields) = exts.get::>() { if !fields.is_empty() { - write!(writer, "{}", fields.fields)?; + write!(writer, " {}", fields.fields)?; } } }