fix(logging): record client IPs behind trusted proxies

README.md

@@ -84,7 +84,7 @@ There are two ways to configure `sync-server`
 | `privacy_policy_url`            | Optional absolute HTTP(S) privacy policy URL without credentials, advertised in `/health`. Environment variable: `PRIVACY_POLICY_URL` | None | `https://example.org/privacy` |
 | `secret_key`                    | Used to sign authentication tokens. Required, min. 32 bytes | None | output of `openssl rand -hex 32` |
 | `username_secret`               | Used to derive account name hashes. Set it so that `secret_key` stays rotatable | falls back to `secret_key` | output of `openssl rand -hex 32` |
-| `trust_forwarded_for`           | Derive rate limiting client addresses from `X-Forwarded-For`. Required behind a reverse proxy | `false` | `true` |
+| `trust_forwarded_for`           | Derive rate limiting and access logging client addresses from `X-Forwarded-For`. Required behind a reverse proxy | `false` | `true` |
 | `trusted_proxy_hops`            | Number of proxies in front of this server, used to pick the right `X-Forwarded-For` entry | `1` | `2` |
 | `allow_registration`            | Whether to allow registering on this server          | `true`  | `false`              |
 | `validate_submitted_metadata`   | Whether to check incoming video data against YouTube | `true`  | `false`              |
@@ -112,6 +112,10 @@ your proxy appended, so a client cannot pick its own bucket by sending the heade
 itself. Only enable this when the server is not reachable directly, otherwise a
 client can do exactly that.
 
+Access logs use the same client address and trusted proxy hop count as rate
+limiting. When forwarded headers are not trusted, missing, or invalid, logs fall
+back to the immediate peer address.
+
 If you have more than one proxy in the chain, set `trusted_proxy_hops` to how many
 there are. Each proxy appends an entry, so with two the last one is the inner
 proxy's address rather than the client's.

src/config.rs

@@ -41,7 +41,7 @@ pub struct Config {
     /// for deployments created before the two were split.
     #[serde(default)]
     username_secret: Option<String>,
-    /// Whether to derive the rate limiting client address from
+    /// Whether to derive the rate limiting and access logging client address from
     /// `X-Forwarded-For` instead of the immediate peer.
     ///
     /// Enable this only when the server is reachable exclusively through a

src/handlers/user.rs

@@ -509,8 +509,8 @@ pub async fn rate_limit_middleware(
     let limiter: Option<&web::Data<RateLimiter>> = req.app_data();
 
     if let Some(limiter) = limiter
-        && let Some(client) = rate_limit_client(
-            &req,
+        && let Some(client) = request_client_ip(
+            req.request(),
             limiter.trusts_forwarded_for(),
             limiter.trusted_proxy_hops(),
         )
@@ -522,9 +522,9 @@ pub async fn rate_limit_middleware(
     next.call(req).await
 }
 
-/// Address to rate limit a request against.
-fn rate_limit_client(
-    req: &ServiceRequest,
+/// Client address shared by rate limiting and access logging.
+pub(crate) fn request_client_ip(
+    req: &HttpRequest,
     trust_forwarded_for: bool,
     trusted_proxy_hops: usize,
 ) -> Option<IpAddr> {
@@ -564,16 +564,11 @@ fn forwarded_client(header: &str, trusted_proxy_hops: usize) -> Option<IpAddr> {
 }
 
 pub(crate) fn request_within_rate_limit(req: &HttpRequest, limiter: &RateLimiter) -> bool {
-    let peer = req.peer_addr().map(|address| address.ip());
-    let client = if limiter.trusts_forwarded_for() {
-        req.headers()
-            .get("X-Forwarded-For")
-            .and_then(|value| value.to_str().ok())
-            .and_then(|header| forwarded_client(header, limiter.trusted_proxy_hops()))
-            .or(peer)
-    } else {
-        peer
-    };
+    let client = request_client_ip(
+        req,
+        limiter.trusts_forwarded_for(),
+        limiter.trusted_proxy_hops(),
+    );
     client.is_none_or(|address| limiter.check(address))
 }
 

src/main.rs

@@ -120,13 +120,29 @@ async fn main() -> io::Result<()> {
         // docs service must be registered before health handler!
         app.service(Scalar::with_url("/docs", api))
             .service(HealthHandler::get_service())
-            .wrap(middleware::Logger::default())
+            .wrap(access_logger(
+                CONFIG.trust_forwarded_for,
+                CONFIG.trusted_proxy_hops,
+            ))
     })
     .bind(("0.0.0.0", 8080))?
     .run()
     .await
 }
 
+fn access_logger(trust_forwarded_for: bool, trusted_proxy_hops: usize) -> middleware::Logger {
+    middleware::Logger::new("%{client_ip}xi \"%r\" %s %b \"%{Referer}i\" \"%{User-Agent}i\" %T")
+        .custom_request_replace("client_ip", move |request| {
+            handlers::user::request_client_ip(
+                request.request(),
+                trust_forwarded_for,
+                trusted_proxy_hops,
+            )
+            .map(|address| address.to_string())
+            .unwrap_or_else(|| "-".to_owned())
+        })
+}
+
 fn configure_v1_routes(config: &mut ServiceConfig<'_>) {
     config
         .service(UserHandler::get_service())
@@ -297,6 +313,89 @@ async fn run_migrations(pool: &DbPool, database_url: &str, approval: Option<&str
 mod tests {
     use super::require_migration_approval;
 
+    struct CapturedAccessLogs(std::sync::Mutex<Vec<String>>);
+
+    impl log::Log for CapturedAccessLogs {
+        fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
+            metadata.target() == "access-log-test"
+        }
+
+        fn log(&self, record: &log::Record<'_>) {
+            if self.enabled(record.metadata()) {
+                self.0.lock().unwrap().push(record.args().to_string());
+            }
+        }
+
+        fn flush(&self) {}
+    }
+
+    #[actix_web::test]
+    async fn access_logs_resolve_trusted_client_addresses() {
+        use actix_web::{App, HttpResponse, test, web};
+
+        static LOGS: CapturedAccessLogs = CapturedAccessLogs(std::sync::Mutex::new(Vec::new()));
+        log::set_logger(&LOGS).unwrap();
+        log::set_max_level(log::LevelFilter::Info);
+
+        let cases = [
+            (
+                false,
+                2,
+                Some("192.0.2.99, 198.51.100.20, 10.0.0.7"),
+                "172.23.0.1",
+            ),
+            (true, 1, Some("198.51.100.20"), "198.51.100.20"),
+            (
+                true,
+                2,
+                Some("192.0.2.99, 198.51.100.20, 10.0.0.7"),
+                "198.51.100.20",
+            ),
+            (true, 2, Some("2001:db8::7, 10.0.0.7"), "2001:db8::7"),
+            (true, 1, Some("[2001:db8::7]:443"), "2001:db8::7"),
+            (true, 2, None, "172.23.0.1"),
+            (true, 2, Some("198.51.100.20"), "172.23.0.1"),
+            (true, 2, Some("invalid, 10.0.0.7"), "172.23.0.1"),
+        ];
+
+        for (trust_forwarded_for, hops, forwarded, expected) in cases {
+            LOGS.0.lock().unwrap().clear();
+            let app = test::init_service(
+                App::new()
+                    .wrap(
+                        super::access_logger(trust_forwarded_for, hops)
+                            .log_target("access-log-test"),
+                    )
+                    .route(
+                        "/logging-test",
+                        web::get().to(|| async { HttpResponse::NoContent().finish() }),
+                    ),
+            )
+            .await;
+            let mut request = test::TestRequest::get()
+                .uri("/logging-test")
+                .peer_addr("172.23.0.1:1234".parse().unwrap())
+                .insert_header(("Forwarded", "for=192.0.2.99"))
+                .insert_header(("CF-Connecting-IP", "192.0.2.99"))
+                .insert_header(("Authorization", "secret-login-token"));
+            if let Some(forwarded) = forwarded {
+                request = request.insert_header(("X-Forwarded-For", forwarded));
+            }
+            let response = test::call_service(&app, request.to_request()).await;
+            assert_eq!(response.status(), 204);
+            test::read_body(response).await;
+
+            let logs = LOGS.0.lock().unwrap();
+            assert_eq!(logs.len(), 1);
+            assert_eq!(
+                logs[0].split_whitespace().next(),
+                Some(expected),
+                "{logs:?}"
+            );
+            assert!(!logs[0].contains("secret-login-token"));
+        }
+    }
+
     #[cfg(feature = "sqlite")]
     #[derive(diesel::QueryableByName)]
     struct RowCount {