Further logging changes, and include some additional log messages when creating new users

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"] }

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::<MatchedPath>()
 				.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())
 			}
 		});
 

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<AppState>,
+    State(state): State<AppState>,
     Json(request): Json<UserRegistrationRequest>,
 ) -> Result<Response, Response> {
+    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<V4>,
+    send_verification_email: bool,
+    email_sender: &Sender<UserConfirmationMessage>,
+) -> Result<Response, Response> {
+    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 response_body = if send_verification_email {
         let new_user_confirmation_message = UserConfirmationMessage {
-        email: email.clone(),
-        name: name.clone(),
+            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())

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()
+    }
+}

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<String>,
 }

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)?;