feat: fail2ban-friendly log format

src/handlers/desktop_client_mfa.rs

@@ -21,14 +21,17 @@ async fn start_client_mfa(
     device_info: Option<DeviceInfo>,
     Json(req): Json<ClientMfaStartRequest>,
 ) -> Result<Json<ClientMfaStartResponse>, 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)

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<ActivateUserRequest>,
 ) -> Result<PrivateCookieJar, ApiError> {
-    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<NewDevice>,
 ) -> Result<Json<DeviceConfigResponse>, 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<ExistingDevice>,
 ) -> Result<Json<DeviceConfigResponse>, 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)

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)

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: <https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html>
+// For more info read: <https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html>
 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("<unknown time>")?;
+        }
+        writer.write_char(' ')
+    }
+}
+
+impl<S, N> FormatEvent<S, N> 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<String> = Vec::new();
+        let mut http_log: Option<String> = 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::<FormattedFields<N>>() {
+                    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)
+    }
+}