rest server: cleanup auth-log handling

Handle auth logs the same way as access log.
- Configure with ApiConfig
- CommandoSocket command to reload auth-logs "api-auth-log-reopen"

Inside API calls, we now access the ApiConfig using the RestEnvironment.

The openid_login api now also logs failed logins and return http_err!(UNAUTHORIZED, ..)
on failed logins.

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

proxmox-rest-server/src/api_config.rs

@@ -26,6 +26,7 @@ pub struct ApiConfig {
     templates: RwLock<Handlebars<'static>>,
     template_files: RwLock<HashMap<String, (SystemTime, PathBuf)>>,
     request_log: Option<Arc<Mutex<FileLogger>>>,
+    auth_log: Option<Arc<Mutex<FileLogger>>>,
     pub api_auth: Arc<dyn ApiAuth + Send + Sync>,
     get_index_fn: GetIndexFn,
 }
@@ -46,6 +47,7 @@ impl ApiConfig {
             templates: RwLock::new(Handlebars::new()),
             template_files: RwLock::new(HashMap::new()),
             request_log: None,
+            auth_log: None,
             api_auth,
             get_index_fn,
         })
@@ -172,7 +174,7 @@ impl ApiConfig {
         self.request_log = Some(Arc::clone(&request_log));
 
         commando_sock.register_command("api-access-log-reopen".into(), move |_args| {
-            println!("re-opening log file");
+            println!("re-opening access-log file");
             request_log.lock().unwrap().reopen()?;
             Ok(serde_json::Value::Null)
         })?;
@@ -180,7 +182,46 @@ impl ApiConfig {
         Ok(())
     }
 
-    pub fn get_file_log(&self) -> Option<&Arc<Mutex<FileLogger>>> {
+    pub fn enable_auth_log<P>(
+        &mut self,
+        path: P,
+        dir_opts: Option<CreateOptions>,
+        file_opts: Option<CreateOptions>,
+        commando_sock: &mut CommandoSocket,
+    ) -> Result<(), Error>
+    where
+        P: Into<PathBuf>
+    {
+        let path: PathBuf = path.into();
+        if let Some(base) = path.parent() {
+            if !base.exists() {
+                create_path(base, None, dir_opts).map_err(|err| format_err!("{}", err))?;
+            }
+        }
+
+        let logger_options = FileLogOptions {
+            append: true,
+            prefix_time: true,
+            file_opts: file_opts.unwrap_or(CreateOptions::default()),
+            ..Default::default()
+        };
+        let auth_log = Arc::new(Mutex::new(FileLogger::new(&path, logger_options)?));
+        self.auth_log = Some(Arc::clone(&auth_log));
+
+        commando_sock.register_command("api-auth-log-reopen".into(), move |_args| {
+            println!("re-opening auth-log file");
+            auth_log.lock().unwrap().reopen()?;
+            Ok(serde_json::Value::Null)
+        })?;
+
+        Ok(())
+    }
+
+    pub fn get_access_log(&self) -> Option<&Arc<Mutex<FileLogger>>> {
         self.request_log.as_ref()
     }
+
+    pub fn get_auth_log(&self) -> Option<&Arc<Mutex<FileLogger>>> {
+        self.auth_log.as_ref()
+    }
 }

proxmox-rest-server/src/environment.rs

@@ -1,24 +1,65 @@
+use std::sync::Arc;
+use std::net::SocketAddr;
+
 use serde_json::{json, Value};
 
 use proxmox::api::{RpcEnvironment, RpcEnvironmentType};
 
+use crate::ApiConfig;
+
 /// Encapsulates information about the runtime environment
 pub struct RestEnvironment {
     env_type: RpcEnvironmentType,
     result_attributes: Value,
     auth_id: Option<String>,
-    client_ip: Option<std::net::SocketAddr>,
+    client_ip: Option<SocketAddr>,
+    api: Arc<ApiConfig>,
 }
 
 impl RestEnvironment {
-    pub fn new(env_type: RpcEnvironmentType) -> Self {
+    pub fn new(env_type: RpcEnvironmentType, api: Arc<ApiConfig>) -> Self {
         Self {
             result_attributes: json!({}),
             auth_id: None,
             client_ip: None,
             env_type,
+            api,
         }
     }
+
+    pub fn api_config(&self) -> &ApiConfig {
+        &self.api
+    }
+
+    pub fn log_auth(&self, auth_id: &str) {
+        let msg = format!("successful auth for user '{}'", auth_id);
+        log::info!("{}", msg);
+        if let Some(auth_logger) = self.api.get_auth_log() {
+            auth_logger.lock().unwrap().log(&msg);
+        }
+    }
+
+    pub fn log_failed_auth(&self, failed_auth_id: Option<String>, msg: &str) {
+        let msg = match (self.client_ip, failed_auth_id) {
+            (Some(peer), Some(user)) => {
+                format!("authentication failure; rhost={} user={} msg={}", peer, user, msg)
+            }
+            (Some(peer), None) => {
+                format!("authentication failure; rhost={} msg={}", peer, msg)
+            }
+            (None, Some(user)) => {
+                format!("authentication failure; rhost=unknown user={} msg={}", user, msg)
+            }
+            (None, None) => {
+                format!("authentication failure; rhost=unknown msg={}", msg)
+            }
+        };
+        log::error!("{}", msg);
+        if let Some(auth_logger) = self.api.get_auth_log() {
+            auth_logger.lock().unwrap().log(&msg);
+        }
+    }
+
 }
 
 impl RpcEnvironment for RestEnvironment {
@@ -43,11 +84,11 @@ impl RpcEnvironment for RestEnvironment {
         self.auth_id.clone()
     }
 
-    fn set_client_ip(&mut self, client_ip: Option<std::net::SocketAddr>) {
+    fn set_client_ip(&mut self, client_ip: Option<SocketAddr>) {
         self.client_ip = client_ip;
     }
 
-    fn get_client_ip(&self) -> Option<std::net::SocketAddr> {
+    fn get_client_ip(&self) -> Option<SocketAddr> {
         self.client_ip
     }
 }

src/api2/access/mod.rs

@@ -12,7 +12,7 @@ use proxmox::{http_err, list_subdirs_api_method};
 use proxmox::{identity, sortable};
 
 use pbs_api_types::{
-    Userid, Authid, PASSWORD_SCHEMA, ACL_PATH_SCHEMA, 
+    Userid, Authid, PASSWORD_SCHEMA, ACL_PATH_SCHEMA,
     PRIVILEGES, PRIV_PERMISSIONS_MODIFY, PRIV_SYS_AUDIT,
 };
 use pbs_tools::auth::private_auth_key;
@@ -196,6 +196,12 @@ pub fn create_ticket(
     tfa_challenge: Option<String>,
     rpcenv: &mut dyn RpcEnvironment,
 ) -> Result<Value, Error> {
+
+    use proxmox_rest_server::RestEnvironment;
+
+    let env: &RestEnvironment = rpcenv.as_any().downcast_ref::<RestEnvironment>()
+        .ok_or_else(|| format_err!("detected worng RpcEnvironment type"))?;
+
     match authenticate_user(&username, &password, path, privs, port, tfa_challenge) {
         Ok(AuthResult::Success) => Ok(json!({ "username": username })),
         Ok(AuthResult::CreateTicket) => {
@@ -203,8 +209,7 @@ pub fn create_ticket(
             let ticket = Ticket::new("PBS", &api_ticket)?.sign(private_auth_key(), None)?;
             let token = assemble_csrf_prevention_token(csrf_secret(), &username);
 
-            crate::server::rest::auth_logger()?
+            env.log_auth(username.as_str());
-                .log(format!("successful auth for user '{}'", username));
 
             Ok(json!({
                 "username": username,
@@ -223,20 +228,7 @@ pub fn create_ticket(
             }))
         }
         Err(err) => {
-            let client_ip = match rpcenv.get_client_ip().map(|addr| addr.ip()) {
+            env.log_failed_auth(Some(username.to_string()), &err.to_string());
-                Some(ip) => format!("{}", ip),
-                None => "unknown".into(),
-            };
-
-            let msg = format!(
-                "authentication failure; rhost={} user={} msg={}",
-                client_ip,
-                username,
-                err.to_string()
-            );
-            crate::server::rest::auth_logger()?.log(&msg);
-            log::error!("{}", msg);
-
             Err(http_err!(UNAUTHORIZED, "permission check failed."))
         }
     }

src/api2/access/openid.rs

@@ -1,14 +1,13 @@
 //! OpenID redirect/login API
 use std::convert::TryFrom;
 
-use anyhow::{bail, Error};
+use anyhow::{bail, format_err, Error};
 
 use serde_json::{json, Value};
 
 use proxmox::api::router::{Router, SubdirMap};
 use proxmox::api::{api, Permission, RpcEnvironment};
-use proxmox::{list_subdirs_api_method};
+use proxmox::{http_err, list_subdirs_api_method, identity, sortable};
-use proxmox::{identity, sortable};
 
 use proxmox_openid::{OpenIdAuthenticator,  OpenIdConfig};
 
@@ -80,76 +79,95 @@ pub fn openid_login(
     state: String,
     code: String,
     redirect_url: String,
-    _rpcenv: &mut dyn RpcEnvironment,
+    rpcenv: &mut dyn RpcEnvironment,
 ) -> Result<Value, Error> {
+    use proxmox_rest_server::RestEnvironment;
+
+    let env: &RestEnvironment = rpcenv.as_any().downcast_ref::<RestEnvironment>()
+        .ok_or_else(|| format_err!("detected worng RpcEnvironment type"))?;
+
     let user_info = CachedUserInfo::new()?;
 
-    let (realm, private_auth_state) =
+    let mut tested_username = None;
-        OpenIdAuthenticator::verify_public_auth_state(PROXMOX_BACKUP_RUN_DIR_M!(), &state)?;
 
-    let (domains, _digest) = pbs_config::domains::config()?;
+    let result = proxmox::try_block!({
-    let config: OpenIdRealmConfig = domains.lookup("openid", &realm)?;
 
-    let open_id = openid_authenticator(&config, &redirect_url)?;
+        let (realm, private_auth_state) =
+            OpenIdAuthenticator::verify_public_auth_state(PROXMOX_BACKUP_RUN_DIR_M!(), &state)?;
 
-    let info = open_id.verify_authorization_code(&code, &private_auth_state)?;
+        let (domains, _digest) = pbs_config::domains::config()?;
+        let config: OpenIdRealmConfig = domains.lookup("openid", &realm)?;
 
-    // eprintln!("VERIFIED {} {:?} {:?}", info.subject().as_str(), info.name(), info.email());
+        let open_id = openid_authenticator(&config, &redirect_url)?;
 
-    let unique_name = match config.username_claim {
+        let info = open_id.verify_authorization_code(&code, &private_auth_state)?;
-        None | Some(OpenIdUserAttribute::Subject) => info.subject().as_str(),
+
-        Some(OpenIdUserAttribute::Username) => {
+        // eprintln!("VERIFIED {} {:?} {:?}", info.subject().as_str(), info.name(), info.email());
-            match info.preferred_username() {
+
-                Some(name) => name.as_str(),
+        let unique_name = match config.username_claim {
-                None => bail!("missing claim 'preferred_name'"),
+            None | Some(OpenIdUserAttribute::Subject) => info.subject().as_str(),
+            Some(OpenIdUserAttribute::Username) => {
+                match info.preferred_username() {
+                    Some(name) => name.as_str(),
+                    None => bail!("missing claim 'preferred_name'"),
+                }
+            }
+            Some(OpenIdUserAttribute::Email) => {
+                match info.email() {
+                    Some(name) => name.as_str(),
+                    None => bail!("missing claim 'email'"),
+                }
+            }
+        };
+
+
+        let user_id = Userid::try_from(format!("{}@{}", unique_name, realm))?;
+        tested_username = Some(unique_name.to_string());
+
+        if !user_info.is_active_user_id(&user_id) {
+            if config.autocreate.unwrap_or(false) {
+                use pbs_config::user;
+                let _lock = open_backup_lockfile(user::USER_CFG_LOCKFILE, None, true)?;
+                let user = User {
+                    userid: user_id.clone(),
+                    comment: None,
+                    enable: None,
+                    expire: None,
+                    firstname: info.given_name().and_then(|n| n.get(None)).map(|n| n.to_string()),
+                    lastname: info.family_name().and_then(|n| n.get(None)).map(|n| n.to_string()),
+                    email: info.email().map(|e| e.to_string()),
+                };
+                let (mut config, _digest) = user::config()?;
+                if config.sections.get(user.userid.as_str()).is_some() {
+                    bail!("autocreate user failed - '{}' already exists.", user.userid);
+                }
+                config.set_data(user.userid.as_str(), "user", &user)?;
+                user::save_config(&config)?;
+            } else {
+                bail!("user account '{}' missing, disabled or expired.", user_id);
             }
         }
-        Some(OpenIdUserAttribute::Email) => {
-            match info.email() {
-                Some(name) => name.as_str(),
-                None => bail!("missing claim 'email'"),
-            }
-        }
-    };
 
-    let user_id = Userid::try_from(format!("{}@{}", unique_name, realm))?;
+        let api_ticket = ApiTicket::full(user_id.clone());
+        let ticket = Ticket::new("PBS", &api_ticket)?.sign(private_auth_key(), None)?;
+        let token = assemble_csrf_prevention_token(csrf_secret(), &user_id);
 
-    if !user_info.is_active_user_id(&user_id) {
+        env.log_auth(user_id.as_str());
-        if config.autocreate.unwrap_or(false) {
+
-            use pbs_config::user;
+        Ok(json!({
-            let _lock = open_backup_lockfile(user::USER_CFG_LOCKFILE, None, true)?;
+            "username": user_id,
-            let user = User {
+            "ticket": ticket,
-                userid: user_id.clone(),
+            "CSRFPreventionToken": token,
-                comment: None,
+        }))
-                enable: None,
+    });
-                expire: None,
+
-                firstname: info.given_name().and_then(|n| n.get(None)).map(|n| n.to_string()),
+    if let Err(ref err) = result {
-                lastname: info.family_name().and_then(|n| n.get(None)).map(|n| n.to_string()),
+        let msg = err.to_string();
-                email: info.email().map(|e| e.to_string()),
+        env.log_failed_auth(tested_username, &msg);
-            };
+        return Err(http_err!(UNAUTHORIZED, "{}", msg))
-            let (mut config, _digest) = user::config()?;
-            if config.sections.get(user.userid.as_str()).is_some() {
-                bail!("autocreate user failed - '{}' already exists.", user.userid);
-            }
-            config.set_data(user.userid.as_str(), "user", &user)?;
-            user::save_config(&config)?;
-        } else {
-            bail!("user account '{}' missing, disabled or expired.", user_id);
-        }
     }
 
-    let api_ticket = ApiTicket::full(user_id.clone());
+    result
-    let ticket = Ticket::new("PBS", &api_ticket)?.sign(private_auth_key(), None)?;
-    let token = assemble_csrf_prevention_token(csrf_secret(), &user_id);
-
-    crate::server::rest::auth_logger()?
-        .log(format!("successful auth for user '{}'", user_id));
-
-    Ok(json!({
-        "username": user_id,
-        "ticket": ticket,
-        "CSRFPreventionToken": token,
-    }))
 }
 
 #[api(

src/bin/proxmox-backup-api.rs

@@ -96,11 +96,19 @@ async fn run() -> Result<(), Error> {
 
     config.enable_file_log(
         pbs_buildcfg::API_ACCESS_LOG_FN,
+        Some(dir_opts.clone()),
+        Some(file_opts.clone()),
+        &mut commando_sock,
+    )?;
+
+    config.enable_auth_log(
+        pbs_buildcfg::API_AUTH_LOG_FN,
         Some(dir_opts),
         Some(file_opts),
         &mut commando_sock,
     )?;
 
+
     let rest_server = RestServer::new(config);
 
     // http server future:

src/bin/proxmox-backup-proxy.rs

@@ -196,6 +196,13 @@ async fn run() -> Result<(), Error> {
 
     config.enable_file_log(
         pbs_buildcfg::API_ACCESS_LOG_FN,
+        Some(dir_opts.clone()),
+        Some(file_opts.clone()),
+        &mut commando_sock,
+    )?;
+
+    config.enable_auth_log(
+        pbs_buildcfg::API_AUTH_LOG_FN,
         Some(dir_opts),
         Some(file_opts),
         &mut commando_sock,
@@ -762,7 +769,7 @@ async fn schedule_task_log_rotate() {
 
                 if logrotate.rotate(max_size, None, Some(max_files))? {
                     println!("rotated access log, telling daemons to re-open log file");
-                    pbs_runtime::block_on(command_reopen_logfiles())?;
+                    pbs_runtime::block_on(command_reopen_access_logfiles())?;
                     worker.log("API access log was rotated".to_string());
                 } else {
                     worker.log("API access log was not rotated".to_string());
@@ -772,6 +779,8 @@ async fn schedule_task_log_rotate() {
                         .ok_or_else(|| format_err!("could not get API auth log file names"))?;
 
                 if logrotate.rotate(max_size, None, Some(max_files))? {
+                    println!("rotated auth log, telling daemons to re-open log file");
+                    pbs_runtime::block_on(command_reopen_auth_logfiles())?;
                     worker.log("API authentication log was rotated".to_string());
                 } else {
                     worker.log("API authentication log was not rotated".to_string());
@@ -794,7 +803,7 @@ async fn schedule_task_log_rotate() {
 
 }
 
-async fn command_reopen_logfiles() -> Result<(), Error> {
+async fn command_reopen_access_logfiles() -> Result<(), Error> {
     // only care about the most recent daemon instance for each, proxy & api, as other older ones
     // should not respond to new requests anyway, but only finish their current one and then exit.
     let sock = crate::server::our_ctrl_sock();
@@ -812,6 +821,24 @@ async fn command_reopen_logfiles() -> Result<(), Error> {
     }
 }
 
+async fn command_reopen_auth_logfiles() -> Result<(), Error> {
+    // only care about the most recent daemon instance for each, proxy & api, as other older ones
+    // should not respond to new requests anyway, but only finish their current one and then exit.
+    let sock = crate::server::our_ctrl_sock();
+    let f1 = proxmox_rest_server::send_command(sock, "{\"command\":\"api-auth-log-reopen\"}\n");
+
+    let pid = crate::server::read_pid(pbs_buildcfg::PROXMOX_BACKUP_API_PID_FN)?;
+    let sock = crate::server::ctrl_sock_from_pid(pid);
+    let f2 = proxmox_rest_server::send_command(sock, "{\"command\":\"api-auth-log-reopen\"}\n");
+
+    match futures::join!(f1, f2) {
+        (Err(e1), Err(e2)) => Err(format_err!("reopen commands failed, proxy: {}; api: {}", e1, e2)),
+        (Err(e1), Ok(_)) => Err(format_err!("reopen commands failed, proxy: {}", e1)),
+        (Ok(_), Err(e2)) => Err(format_err!("reopen commands failed, api: {}", e2)),
+        _ => Ok(()),
+    }
+}
+
 async fn run_stat_generator() {
 
     let mut count = 0;

src/server/rest.rs

@@ -29,12 +29,11 @@ use proxmox::api::{
     RpcEnvironmentType, UserInformation,
 };
 use proxmox::http_err;
-use proxmox::tools::fs::CreateOptions;
 
 use pbs_tools::compression::{DeflateEncoder, Level};
 use pbs_tools::stream::AsyncReaderStream;
 use proxmox_rest_server::{
-    ApiConfig, FileLogger, FileLogOptions, AuthError, RestEnvironment, CompressionMethod,
+    ApiConfig, FileLogger, AuthError, RestEnvironment, CompressionMethod,
     extract_cookie, normalize_uri_path,
 };
 use proxmox_rest_server::formatter::*;
@@ -200,22 +199,6 @@ fn log_response(
     }
 }
 
-pub fn auth_logger() -> Result<FileLogger, Error> {
-    let backup_user = pbs_config::backup_user()?;
-
-    let file_opts = CreateOptions::new()
-        .owner(backup_user.uid)
-        .group(backup_user.gid);
-
-    let logger_options = FileLogOptions {
-        append: true,
-        prefix_time: true,
-        file_opts,
-        ..Default::default()
-    };
-    FileLogger::new(pbs_buildcfg::API_AUTH_LOG_FN, logger_options)
-}
-
 fn get_proxied_peer(headers: &HeaderMap) -> Option<std::net::SocketAddr> {
     lazy_static! {
         static ref RE: Regex = Regex::new(r#"for="([^"]+)""#).unwrap();
@@ -272,7 +255,7 @@ impl tower_service::Service<Request<Body>> for ApiService {
                         .body(err.into())?
                 }
             };
-            let logger = config.get_file_log();
+            let logger = config.get_access_log();
             log_response(logger, &peer, method, &path, &response, user_agent);
             Ok(response)
         }
@@ -631,7 +614,7 @@ async fn handle_request(
     }
 
     let env_type = api.env_type();
-    let mut rpcenv = RestEnvironment::new(env_type);
+    let mut rpcenv = RestEnvironment::new(env_type, Arc::clone(&api));
 
     rpcenv.set_client_ip(Some(*peer));
 
@@ -675,11 +658,8 @@ async fn handle_request(
                                 format_err!("no authentication credentials provided.")
                             }
                         };
-                        let peer = peer.ip();
+                        // fixme: log Username??
-                        auth_logger()?.log(format!(
+                        rpcenv.log_failed_auth(None, &err.to_string());
-                            "authentication failure; rhost={} msg={}",
-                            peer, err
-                        ));
 
                         // always delay unauthorized calls by 3 seconds (from start of request)
                         let err = http_err!(UNAUTHORIZED, "authentication failed - {}", err);