diff --git a/src/handlers/desktop_client_mfa.rs b/src/handlers/desktop_client_mfa.rs index a64ab69..36fc72e 100644 --- a/src/handlers/desktop_client_mfa.rs +++ b/src/handlers/desktop_client_mfa.rs @@ -21,14 +21,17 @@ async fn start_client_mfa( device_info: Option, Json(req): Json, ) -> Result, ApiError> { - info!("Starting desktop client authorization"); + info!("Starting desktop client authorization {req:?}"); let rx = state.grpc_server.send( - Some(core_request::Payload::ClientMfaStart(req)), + Some(core_request::Payload::ClientMfaStart(req.clone())), device_info, )?; let payload = get_core_response(rx).await?; match payload { - core_response::Payload::ClientMfaStart(response) => Ok(Json(response)), + core_response::Payload::ClientMfaStart(response) => { + info!("Started desktop client authorization {req:?}"); + Ok(Json(response)) + } _ => { error!("Received invalid gRPC response type: {payload:?}"); Err(ApiError::InvalidResponseType) @@ -49,7 +52,10 @@ async fn finish_client_mfa( )?; let payload = get_core_response(rx).await?; match payload { - core_response::Payload::ClientMfaFinish(response) => Ok(Json(response)), + core_response::Payload::ClientMfaFinish(response) => { + info!("Finished desktop client authorization"); + Ok(Json(response)) + } _ => { error!("Received invalid gRPC response type: {payload:?}"); Err(ApiError::InvalidResponseType) diff --git a/src/handlers/enrollment.rs b/src/handlers/enrollment.rs index 3e6f4ce..7e5856f 100644 --- a/src/handlers/enrollment.rs +++ b/src/handlers/enrollment.rs @@ -42,8 +42,11 @@ pub async fn start_enrollment_process( let payload = get_core_response(rx).await?; match payload { core_response::Payload::EnrollmentStart(response) => { + info!( + "Started enrollment process for user {:?} by admin {:?}", + response.user, response.admin + ); // set session cookie - info!("Started enrollment process: {response:?}"); let cookie = Cookie::build((ENROLLMENT_COOKIE_NAME, token)) .expires(OffsetDateTime::from_unix_timestamp(response.deadline_timestamp).unwrap()); @@ -63,7 +66,8 @@ pub async fn activate_user( mut private_cookies: PrivateCookieJar, Json(mut req): Json, ) -> Result { - info!("Activating user"); + let phone = req.phone_number.clone(); + info!("Activating user - phone number {phone:?}"); // set auth info req.token = private_cookies @@ -77,6 +81,7 @@ pub async fn activate_user( match payload { core_response::Payload::Empty(_) => { if let Some(cookie) = private_cookies.get(ENROLLMENT_COOKIE_NAME) { + info!("Activated user - phone number {phone:?}"); debug!("Enrollment finished. Removing session cookie"); private_cookies = private_cookies.remove(cookie); } @@ -97,7 +102,8 @@ pub async fn create_device( private_cookies: PrivateCookieJar, Json(mut req): Json, ) -> Result, ApiError> { - info!("Adding new device"); + let (name, pubkey) = (req.name.clone(), req.pubkey.clone()); + info!("Adding new device {name} {pubkey}"); // set auth info req.token = private_cookies @@ -109,7 +115,10 @@ pub async fn create_device( .send(Some(core_request::Payload::NewDevice(req)), device_info)?; let payload = get_core_response(rx).await?; match payload { - core_response::Payload::DeviceConfig(response) => Ok(Json(response)), + core_response::Payload::DeviceConfig(response) => { + info!("Added new device {name} {pubkey}"); + Ok(Json(response)) + } _ => { error!("Received invalid gRPC response type: {payload:?}"); Err(ApiError::InvalidResponseType) @@ -123,7 +132,8 @@ pub async fn get_network_info( private_cookies: PrivateCookieJar, Json(mut req): Json, ) -> Result, ApiError> { - info!("Getting network info"); + let pubkey = req.pubkey.clone(); + info!("Getting network info for device {pubkey}"); // set auth info req.token = private_cookies @@ -135,7 +145,10 @@ pub async fn get_network_info( .send(Some(core_request::Payload::ExistingDevice(req)), None)?; let payload = get_core_response(rx).await?; match payload { - core_response::Payload::DeviceConfig(response) => Ok(Json(response)), + core_response::Payload::DeviceConfig(response) => { + info!("Got network info for device {pubkey}"); + Ok(Json(response)) + } _ => { error!("Received invalid gRPC response type: {payload:?}"); Err(ApiError::InvalidResponseType) diff --git a/src/handlers/password_reset.rs b/src/handlers/password_reset.rs index 88e9e44..f09a9ce 100644 --- a/src/handlers/password_reset.rs +++ b/src/handlers/password_reset.rs @@ -28,12 +28,15 @@ pub async fn request_password_reset( info!("Starting password reset request for {}", req.email); let rx = state.grpc_server.send( - Some(core_request::Payload::PasswordResetInit(req)), + Some(core_request::Payload::PasswordResetInit(req.clone())), device_info, )?; let payload = get_core_response(rx).await?; match payload { - core_response::Payload::Empty(_) => Ok(()), + core_response::Payload::Empty(_) => { + info!("Started password reset request for {}", req.email); + Ok(()) + } _ => { error!("Received invalid gRPC response type: {payload:?}"); Err(ApiError::InvalidResponseType) @@ -69,6 +72,7 @@ pub async fn start_password_reset( let cookie = Cookie::build((PASSWORD_RESET_COOKIE_NAME, token)) .expires(OffsetDateTime::from_unix_timestamp(response.deadline_timestamp).unwrap()); + info!("Started password reset process"); Ok((private_cookies.add(cookie), Json(response))) } _ => { @@ -99,7 +103,7 @@ pub async fn reset_password( match payload { core_response::Payload::Empty(_) => { if let Some(cookie) = private_cookies.get(PASSWORD_RESET_COOKIE_NAME) { - debug!("Password reset finished. Removing session cookie"); + info!("Password reset finished. Removing session cookie"); private_cookies = private_cookies.remove(cookie); } Ok(private_cookies) diff --git a/src/tracing.rs b/src/tracing.rs index 4e7f5c8..7308f96 100644 --- a/src/tracing.rs +++ b/src/tracing.rs @@ -1,17 +1,122 @@ +use rust_tracing::{Event, Subscriber}; +use tracing_subscriber::{ + fmt::{ + format::{self, FormatEvent, FormatFields, Writer}, + time::{FormatTime, SystemTime}, + FmtContext, FormattedFields, + }, + registry::LookupSpan, +}; + use tracing::log::LevelFilter; use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; // Initializes tracing with the specified log level. // Allows fine-grained filtering with `EnvFilter` directives. // The directives are read from `DEFGUARD_PROXY_LOG_FILTER` env variable. -// For more info check: +// For more info read: pub fn init_tracing(level: &LevelFilter) { tracing_subscriber::registry() .with( EnvFilter::try_from_env("DEFGUARD_PROXY_LOG_FILTER") .unwrap_or_else(|_| level.to_string().into()), ) - .with(fmt::layer()) + .with(fmt::layer().event_format(HttpFormatter::default())) .init(); info!("Tracing initialized"); } + +/// Implements fail2ban-friendly log format using `tracing_subscriber::fmt::format::FormatEvent` trait. +/// HTTP info (if available) is extracted from the specified tracing span. The format is as follows: +/// TIMESTAMP LEVEL CLIENT_ADDR METHOD URI LOG_MESSAGE || TRACING_DATA +pub(crate) struct HttpFormatter<'a> { + span: &'a str, + timer: SystemTime, +} + +impl<'a> Default for HttpFormatter<'a> { + fn default() -> Self { + Self { + span: "http_request", + timer: SystemTime, + } + } +} + +impl HttpFormatter<'_> { + fn format_timestamp(&self, writer: &mut Writer<'_>) -> std::fmt::Result { + if self.timer.format_time(writer).is_err() { + writer.write_str("")?; + } + writer.write_char(' ') + } +} + +impl FormatEvent for HttpFormatter<'_> +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: format::Writer<'_>, + event: &Event<'_>, + ) -> std::fmt::Result { + let meta = event.metadata(); + + // timestamp & level + self.format_timestamp(&mut writer)?; + write!(writer, "{} ", meta.level())?; + + // iterate and accumulate spans storing our special span in separate variable if encountered + let mut context_logs: Vec = Vec::new(); + let mut http_log: Option = None; + if let Some(scope) = ctx.event_scope() { + let mut seen = false; + for span in scope.from_root() { + let span_name = span.metadata().name(); + context_logs.push(span_name.to_string()); + seen = true; + + if let Some(fields) = span.extensions().get::>() { + if !fields.is_empty() { + match span_name { + x if x == self.span => http_log = Some(format!("{fields}")), + _ => context_logs.push(format!("{{{fields}}}")), + } + } + } + context_logs.push(":".into()); + } + if seen { + context_logs.push(' '.into()); + } + }; + + // write http context log (ip, method, path) + if let Some(log) = http_log { + let split: Vec<&str> = log.split(['=', ' ']).collect(); + let method = split.get(1).unwrap_or(&"unknown"); + let path = split.get(3).unwrap_or(&"unknown"); + + let addr = split.get(5).and_then(|s| Some(s.replace('"', ""))); + let ip = addr + .and_then(|s| s.split(":").next().map(|s| s.to_string())) + .unwrap_or("unknown".to_string()); + write!(writer, "{ip} {method} {path} ")?; + } + + // write actual log message + ctx.format_fields(writer.by_ref(), event)?; + + // write span context + if !context_logs.is_empty() { + write!(writer, " || Tracing data: ")?; + for log in context_logs { + write!(writer, "{log}")? + } + } + writeln!(writer) + } +}