[pbs-devel] [PATCH backup 1/3] server/rest: implement request access log

[pbs-devel] [PATCH backup 1/3] server/rest: implement request access log

[Thomas Lamprecht]

reuse the FileLogger module in append mode.
As it implements write, which is not thread safe (mutable self) and
we use it in a async context we need to serialize access using a
mutex.

Try to use the same format we do in pveproxy, namely the one which is
also used in apache or nginx by default.

Use the response extensions to pass up the userid, if we extract it
from a ticket.

The privileged and unprivileged dameons log both to the same file, to
have a unified view, and avoiding the need to handle more log files.
We avoid extra intra-process locking by reusing the fact that a write
smaller than PIPE_BUF (4k on linux) is atomic for files opened with
the 'O_APPEND' flag. For now the logged request path is not yet
guaranteed to be smaller than that, this will be improved in a future
patch.

Signed-off-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
---

sane log rotation is still missing

 src/bin/proxmox-backup-api.rs   |  4 ++-
 src/bin/proxmox-backup-proxy.rs |  2 ++
 src/buildcfg.rs                 |  2 ++
 src/server/config.rs            | 32 +++++++++++++++++-
 src/server/rest.rs              | 57 ++++++++++++++++++++++++++++-----
 5 files changed, 87 insertions(+), 10 deletions(-)

diff --git a/src/bin/proxmox-backup-api.rs b/src/bin/proxmox-backup-api.rs
index ea306cf0..8f9a4c82 100644
--- a/src/bin/proxmox-backup-api.rs
+++ b/src/bin/proxmox-backup-api.rs
@@ -49,9 +49,11 @@ async fn run() -> Result<(), Error> {
     }
     let _ = csrf_secret(); // load with lazy_static
 
-    let config = server::ApiConfig::new(
+    let mut config = server::ApiConfig::new(
         buildcfg::JS_DIR, &proxmox_backup::api2::ROUTER, RpcEnvironmentType::PRIVILEGED)?;
 
+    config.enable_file_log(buildcfg::API_ACCESS_LOG_FN)?;
+
     let rest_server = RestServer::new(config);
 
     // http server future:
diff --git a/src/bin/proxmox-backup-proxy.rs b/src/bin/proxmox-backup-proxy.rs
index 7593dc43..47376970 100644
--- a/src/bin/proxmox-backup-proxy.rs
+++ b/src/bin/proxmox-backup-proxy.rs
@@ -63,6 +63,8 @@ async fn run() -> Result<(), Error> {
     config.register_template("index", &indexpath)?;
     config.register_template("console", "/usr/share/pve-xtermjs/index.html.hbs")?;
 
+    config.enable_file_log(buildcfg::API_ACCESS_LOG_FN)?;
+
     let rest_server = RestServer::new(config);
 
     //openssl req -x509 -newkey rsa:4096 -keyout /etc/proxmox-backup/proxy.key -out /etc/proxmox-backup/proxy.pem -nodes
diff --git a/src/buildcfg.rs b/src/buildcfg.rs
index 3d951bfb..2adde105 100644
--- a/src/buildcfg.rs
+++ b/src/buildcfg.rs
@@ -4,6 +4,8 @@
 pub const CONFIGDIR: &str = "/etc/proxmox-backup";
 pub const JS_DIR: &str = "/usr/share/javascript/proxmox-backup";
 
+pub const API_ACCESS_LOG_FN: &str = "/var/log/proxmox-backup/api/access.log";
+
 /// Prepend configuration directory to a file name
 ///
 /// This is a simply way to get the full path for configuration files.
diff --git a/src/server/config.rs b/src/server/config.rs
index 3ee4ea13..cdaa5acd 100644
--- a/src/server/config.rs
+++ b/src/server/config.rs
@@ -2,7 +2,7 @@ use std::collections::HashMap;
 use std::path::PathBuf;
 use std::time::SystemTime;
 use std::fs::metadata;
-use std::sync::RwLock;
+use std::sync::{Mutex, RwLock};
 
 use anyhow::{bail, Error, format_err};
 use hyper::Method;
@@ -10,6 +10,9 @@ use handlebars::Handlebars;
 use serde::Serialize;
 
 use proxmox::api::{ApiMethod, Router, RpcEnvironmentType};
+use proxmox::tools::fs::{create_path, CreateOptions};
+
+use crate::tools::{FileLogger, FileLogOptions};
 
 pub struct ApiConfig {
     basedir: PathBuf,
@@ -18,6 +21,7 @@ pub struct ApiConfig {
     env_type: RpcEnvironmentType,
     templates: RwLock<Handlebars<'static>>,
     template_files: RwLock<HashMap<String, (SystemTime, PathBuf)>>,
+    request_log: Option<Mutex<FileLogger>>,
 }
 
 impl ApiConfig {
@@ -30,6 +34,7 @@ impl ApiConfig {
             env_type,
             templates: RwLock::new(Handlebars::new()),
             template_files: RwLock::new(HashMap::new()),
+            request_log: None,
         })
     }
 
@@ -118,4 +123,29 @@ impl ApiConfig {
             templates.render(name, data).map_err(|err| format_err!("{}", err))
         }
     }
+
+    pub fn enable_file_log<P>(&mut self, path: P) -> Result<(), Error>
+    where
+        P: Into<PathBuf>
+    {
+        let path: PathBuf = path.into();
+        if let Some(base) = path.parent() {
+            if !base.exists() {
+                let backup_user = crate::backup::backup_user()?;
+                let opts = CreateOptions::new().owner(backup_user.uid).group(backup_user.gid);
+                create_path(base, None, Some(opts)).map_err(|err| format_err!("{}", err))?;
+            }
+        }
+
+        let logger_options = FileLogOptions {
+            append: true,
+            ..Default::default()
+        };
+        self.request_log = Some(Mutex::new(FileLogger::new(&path, logger_options)?));
+
+        Ok(())
+    }
+    pub fn get_file_log(&self) -> Option<&Mutex<FileLogger>> {
+        self.request_log.as_ref()
+    }
 }
diff --git a/src/server/rest.rs b/src/server/rest.rs
index 7305643c..0b3bc067 100644
--- a/src/server/rest.rs
+++ b/src/server/rest.rs
@@ -3,13 +3,14 @@ use std::future::Future;
 use std::hash::BuildHasher;
 use std::path::{Path, PathBuf};
 use std::pin::Pin;
-use std::sync::Arc;
+use std::sync::{Arc, Mutex};
 use std::task::{Context, Poll};
 
 use anyhow::{bail, format_err, Error};
 use futures::future::{self, FutureExt, TryFutureExt};
 use futures::stream::TryStreamExt;
 use hyper::header::{self, HeaderMap};
+use hyper::body::HttpBody;
 use hyper::http::request::Parts;
 use hyper::{Body, Request, Response, StatusCode};
 use lazy_static::lazy_static;
@@ -43,6 +44,7 @@ use super::ApiConfig;
 use crate::auth_helpers::*;
 use crate::api2::types::Userid;
 use crate::tools;
+use crate::tools::FileLogger;
 use crate::tools::ticket::Ticket;
 use crate::config::cached_user_info::CachedUserInfo;
 
@@ -109,6 +111,7 @@ pub struct ApiService {
 }
 
 fn log_response(
+    logfile: Option<&Mutex<FileLogger>>,
     peer: &std::net::SocketAddr,
     method: hyper::Method,
     path_query: &str,
@@ -133,6 +136,30 @@ fn log_response(
 
         log::error!("{} {}: {} {}: [client {}] {}", method.as_str(), path, status.as_str(), reason, peer, message);
     }
+    if let Some(logfile) = logfile {
+        let user = match resp.extensions().get::<Userid>() {
+            Some(userid) => userid.as_str(),
+            None => "-",
+        };
+        let now = proxmox::tools::time::epoch_i64();
+        // time format which apache/nginx use (by default), copied from pve-http-server
+        let datetime = proxmox::tools::time::strftime_local("%d/%m/%Y:%H:%M:%S %z", now)
+            .unwrap_or("-".into());
+
+        logfile
+            .lock()
+            .unwrap()
+            .log(format!(
+                "{} - {} [{}] \"{} {}\" {} {}",
+                peer.ip(),
+                user,
+                datetime,
+                method.as_str(),
+                path,
+                status.as_str(),
+                resp.body().size_hint().lower(),
+            ));
+    }
 }
 
 fn get_proxied_peer(headers: &HeaderMap) -> Option<std::net::SocketAddr> {
@@ -165,7 +192,7 @@ impl tower_service::Service<Request<Body>> for ApiService {
             None => self.peer,
         };
         async move {
-            let response = match handle_request(config, req, &peer).await {
+            let response = match handle_request(Arc::clone(&config), req, &peer).await {
                 Ok(response) => response,
                 Err(err) => {
                     let (err, code) = match err.downcast_ref::<HttpError>() {
@@ -175,7 +202,8 @@ impl tower_service::Service<Request<Body>> for ApiService {
                     Response::builder().status(code).body(err.into())?
                 }
             };
-            log_response(&peer, method, &path, &response);
+            let logger = config.get_file_log();
+            log_response(logger, &peer, method, &path, &response);
             Ok(response)
         }
         .boxed()
@@ -394,11 +422,17 @@ fn get_index(
         }
     };
 
-    Response::builder()
+    let mut resp = Response::builder()
         .status(StatusCode::OK)
         .header(header::CONTENT_TYPE, ct)
         .body(index.into())
-        .unwrap()
+        .unwrap();
+
+    if let Some(userid) = userid {
+        resp.extensions_mut().insert(userid);
+    }
+
+    resp
 }
 
 fn extension_to_content_type(filename: &Path) -> (&'static str, bool) {
@@ -615,10 +649,17 @@ async fn handle_request(
                         handle_api_request(rpcenv, api_method, formatter, parts, body, uri_param).await
                     };
 
-                    if let Err(err) = result {
-                        return Ok((formatter.format_error)(err));
+                    let mut response = match result {
+                        Ok(resp) => resp,
+                        Err(err) => (formatter.format_error)(err),
+                    };
+
+                    if let Some(user) = user {
+                        let userid: Userid = user.parse()?;
+                        response.extensions_mut().insert(userid);
                     }
-                    return result;
+
+                    return Ok(response);
                 }
             }
 
-- 
2.27.0

[pbs-devel] [PATCH backup 2/3] server/rest: also log user agent

[Thomas Lamprecht]

allows easily to see if a request is from a browser or a proxmox-backup-client
CLI

Signed-off-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
---
 src/server/rest.rs | 16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

diff --git a/src/server/rest.rs b/src/server/rest.rs
index 0b3bc067..7235a291 100644
--- a/src/server/rest.rs
+++ b/src/server/rest.rs
@@ -116,6 +116,7 @@ fn log_response(
     method: hyper::Method,
     path_query: &str,
     resp: &Response<Body>,
+    user_agent: Option<String>,
 ) {
 
     if resp.extensions().get::<NoLogExtension>().is_some() { return; };
@@ -150,7 +151,7 @@ fn log_response(
             .lock()
             .unwrap()
             .log(format!(
-                "{} - {} [{}] \"{} {}\" {} {}",
+                "{} - {} [{}] \"{} {}\" {} {} {}",
                 peer.ip(),
                 user,
                 datetime,
@@ -158,6 +159,7 @@ fn log_response(
                 path,
                 status.as_str(),
                 resp.body().size_hint().lower(),
+                user_agent.unwrap_or("-".into()),
             ));
     }
 }
@@ -173,6 +175,15 @@ fn get_proxied_peer(headers: &HeaderMap) -> Option<std::net::SocketAddr> {
     rhost.parse().ok()
 }
 
+fn get_user_agent(headers: &HeaderMap) -> Option<String> {
+    let agent = headers.get(header::USER_AGENT)?.to_str();
+    agent.map(|s| {
+        let mut s = s.to_owned();
+        s.truncate(128);
+        s
+    }).ok()
+}
+
 impl tower_service::Service<Request<Body>> for ApiService {
     type Response = Response<Body>;
     type Error = Error;
@@ -185,6 +196,7 @@ impl tower_service::Service<Request<Body>> for ApiService {
     fn call(&mut self, req: Request<Body>) -> Self::Future {
         let path = req.uri().path_and_query().unwrap().as_str().to_owned();
         let method = req.method().clone();
+        let user_agent = get_user_agent(req.headers());
 
         let config = Arc::clone(&self.api_config);
         let peer = match get_proxied_peer(req.headers()) {
@@ -203,7 +215,7 @@ impl tower_service::Service<Request<Body>> for ApiService {
                 }
             };
             let logger = config.get_file_log();
-            log_response(logger, &peer, method, &path, &response);
+            log_response(logger, &peer, method, &path, &response, user_agent);
             Ok(response)
         }
         .boxed()
-- 
2.27.0

[pbs-devel] [PATCH backup 3/3] api: access: log to separate file, reduce syslog to errors

[Thomas Lamprecht]

for now log auth errors also to the syslog, on a protected (LAN
and/or firewalled) setup this should normally happen due to
missconfiguration, not tries to break in.

This reduces syslog noise *a lot*. A current full journal output from
the current boot here has 72066 lines, of which 71444 (>99% !!) are
"successful auth for user ..." messages

Signed-off-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
---
 src/api2/access.rs | 20 ++++++++++++++++++--
 1 file changed, 18 insertions(+), 2 deletions(-)

diff --git a/src/api2/access.rs b/src/api2/access.rs
index 19b128b1..c302e0c7 100644
--- a/src/api2/access.rs
+++ b/src/api2/access.rs
@@ -10,6 +10,7 @@ use proxmox::{http_err, list_subdirs_api_method};
 use crate::tools::ticket::{self, Empty, Ticket};
 use crate::auth_helpers::*;
 use crate::api2::types::*;
+use crate::tools::{FileLogOptions, FileLogger};
 
 use crate::config::cached_user_info::CachedUserInfo;
 use crate::config::acl::{PRIVILEGES, PRIV_PERMISSIONS_MODIFY};
@@ -140,13 +141,20 @@ fn create_ticket(
     port: Option<u16>,
     rpcenv: &mut dyn RpcEnvironment,
 ) -> Result<Value, Error> {
+    let logger_options = FileLogOptions {
+        append: true,
+        prefix_time: true,
+        ..Default::default()
+    };
+    let mut auth_log = FileLogger::new("/var/log/proxmox-backup/api/auth.log", logger_options)?;
+
     match authenticate_user(&username, &password, path, privs, port) {
         Ok(true) => {
             let ticket = Ticket::new("PBS", &username)?.sign(private_auth_key(), None)?;
 
             let token = assemble_csrf_prevention_token(csrf_secret(), &username);
 
-            log::info!("successful auth for user '{}'", username);
+            auth_log.log(format!("successful auth for user '{}'", username));
 
             Ok(json!({
                 "username": username,
@@ -163,7 +171,15 @@ fn create_ticket(
                 None => "unknown".into(),
             };
 
-            log::error!("authentication failure; rhost={} user={} msg={}", client_ip, username, err.to_string());
+            let msg = format!(
+                "authentication failure; rhost={} user={} msg={}",
+                client_ip,
+                username,
+                err.to_string()
+            );
+            auth_log.log(&msg);
+            log::error!("{}", msg);
+
             Err(http_err!(UNAUTHORIZED, "permission check failed."))
         }
     }
-- 
2.27.0

[pbs-devel] applied: [PATCH backup 1/3] server/rest: implement request access log

[Dietmar Maurer]

applied.

But I am not sure if we want to log error to both locations?