diff --git a/src/grpc/desktop_client_mfa.rs b/src/grpc/desktop_client_mfa.rs index 153fb91085..b10c0ccdce 100644 --- a/src/grpc/desktop_client_mfa.rs +++ b/src/grpc/desktop_client_mfa.rs @@ -73,7 +73,7 @@ impl ClientMfaServer { &mut self, request: ClientMfaStartRequest, ) -> Result { - info!("Starting desktop client login: {request:?}"); + debug!("Starting desktop client login: {request:?}"); // fetch location let Ok(Some(location)) = WireguardNetwork::find_by_id(&self.pool, request.location_id).await @@ -117,8 +117,9 @@ impl ClientMfaServer { .any(|allowed_group| user_info.groups.contains(allowed_group)) { error!( - "User {} not allowed to connect to location {location}", - user.username + "User {} not allowed to connect to location {location} because he doesn't belong to any of the allowed groups. + User groups: {:?}, allowed groups: {:?}", + user.username, user_info.groups, groups ); return Err(Status::unauthenticated("unauthorized")); } @@ -126,7 +127,7 @@ impl ClientMfaServer { // check if selected method is enabled let method = MfaMethod::try_from(request.method).map_err(|err| { - error!("Invalid MFA method selected: {err}"); + error!("Invalid MFA method selected ({}): {err}", request.method); Status::invalid_argument("invalid MFA method selected") })?; match method { @@ -159,6 +160,11 @@ impl ClientMfaServer { // generate auth token let token = Self::generate_token(&request.pubkey)?; + info!( + "Desktop client MFA login started for {} at location {}", + user.username, location.name + ); + // store login session self.sessions.insert( request.pubkey, @@ -177,7 +183,7 @@ impl ClientMfaServer { &mut self, request: ClientMfaFinishRequest, ) -> Result { - info!("Finishing desktop client login: {request:?}"); + debug!("Finishing desktop client login: {request:?}"); // get pubkey from token let pubkey = self.parse_token(&request.token)?; @@ -261,12 +267,17 @@ impl ClientMfaServer { Status::internal("unexpected error") })?; + info!( + "Desktop client login finished for {} at location {}", + user.username, location.name + ); + // remove login session from map self.sessions.remove(&pubkey); // commit transaction transaction.commit().await.map_err(|_| { - error!("Failed to commit transaction"); + error!("Failed to commit transaction while finishing desktop client login."); Status::internal("unexpected error") })?; diff --git a/src/grpc/enrollment.rs b/src/grpc/enrollment.rs index c7db5d0932..16569d0d0b 100644 --- a/src/grpc/enrollment.rs +++ b/src/grpc/enrollment.rs @@ -99,6 +99,7 @@ impl EnrollmentServer { let enrollment = Token::find_by_id(&self.pool, token).await?; if enrollment.is_session_valid(server_config().enrollment_session_timeout.as_secs()) { + info!("Enrollment session validated"); Ok(enrollment) } else { error!("Enrollment session expired"); @@ -117,11 +118,13 @@ impl EnrollmentServer { &self, request: EnrollmentStartRequest, ) -> Result { + debug!("Starting enrollment session, request: {request:?}"); // fetch enrollment token let mut enrollment = Token::find_by_id(&self.pool, &request.token).await?; if let Some(token_type) = &enrollment.token_type { if token_type != ENROLLMENT_TOKEN_TYPE { + error!("Invalid token type used while trying to start enrollment: {token_type}"); return Err(Status::permission_denied("invalid token")); } @@ -140,13 +143,14 @@ impl EnrollmentServer { })?; // validate token & start session - info!("Starting enrollment session for user {}", user.username); + debug!("Starting enrollment session for user {}", user.username); let session_deadline = enrollment .start_session( &mut transaction, server_config().enrollment_session_timeout.as_secs(), ) .await?; + info!("Enrollment session started for user {}", user.username); let settings = Settings::get_settings(&mut *transaction) .await @@ -216,7 +220,6 @@ impl EnrollmentServer { // fetch related users let mut user = enrollment.fetch_user(&self.pool).await?; - info!("Activating user account for {}", user.username); if user.has_password() { error!("User {} already activated", user.username); return Err(Status::invalid_argument("user already activated")); @@ -285,6 +288,8 @@ impl EnrollmentServer { Status::internal("unexpected error") })?; + info!("User {} activated", user.username); + Ok(()) } @@ -300,8 +305,6 @@ impl EnrollmentServer { let user = enrollment.fetch_user(&self.pool).await?; // add device - info!("Adding new device for user {}", user.username); - if !user.is_active { error!("Can't create device for a disabled user {}", user.username); return Err(Status::invalid_argument( @@ -382,6 +385,12 @@ impl EnrollmentServer { device_info.as_deref(), ) .map_err(|_| Status::internal("Failed to render new device added template"))?; + + info!( + "Device {} assigned to user {} and added to all networks.", + device.name, user.username + ); + let response = DeviceConfigResponse { device: Some(device.into()), configs: configs.into_iter().map(Into::into).collect(), @@ -397,6 +406,7 @@ impl EnrollmentServer { &self, request: ExistingDevice, ) -> Result { + debug!("Getting network info for device: {:?}", request.pubkey); let enrollment = self.validate_session(request.token.as_deref()).await?; // get enrollment user @@ -410,7 +420,7 @@ impl EnrollmentServer { let device = Device::find_by_pubkey(&self.pool, &request.pubkey) .await .map_err(|_| { - error!("Failed to get device"); + error!("Failed to get device by its pubkey: {}", request.pubkey); Status::internal("unexpected error") })?; @@ -420,7 +430,7 @@ impl EnrollmentServer { })?; let networks = WireguardNetwork::all(&self.pool).await.map_err(|err| { - error!("Invalid failed to get networks {err}"); + error!("Failed to fetch all networks: {err}"); Status::internal(format!("unexpected error: {err}")) })?; @@ -434,7 +444,7 @@ impl EnrollmentServer { WireguardNetworkDevice::find(&self.pool, device_id, network_id) .await .map_err(|err| { - error!("Invalid failed to get networks {err}"); + error!("Failed to fetch wireguard network device for device {} and network {}: {err}", device_id, network_id); Status::internal(format!("unexpected error: {err}")) })?; if let Some(wireguard_network_device) = wireguard_network_device { @@ -460,6 +470,8 @@ impl EnrollmentServer { } } + info!("Device {} configs fetched", device.name); + let response = DeviceConfigResponse { device: Some(device.into()), configs, diff --git a/src/grpc/gateway.rs b/src/grpc/gateway.rs index a22c800471..dd8f53e3c2 100644 --- a/src/grpc/gateway.rs +++ b/src/grpc/gateway.rs @@ -237,7 +237,9 @@ impl GatewayUpdatesHandler { { Some(network_info) => { if self.network.mfa_enabled && !network_info.is_authorized { - debug!("Created WireGuard device is not authorized to connect to MFA enabled location"); + debug!("Created WireGuard device {} is not authorized to connect to MFA enabled location {}", + device.device.name, self.network.name + ); continue; }; self.send_peer_update( @@ -265,7 +267,9 @@ impl GatewayUpdatesHandler { { Some(network_info) => { if self.network.mfa_enabled && !network_info.is_authorized { - debug!("Modified WireGuard device is not authorized to connect to MFA enabled location"); + debug!("Modified WireGuard device {} is not authorized to connect to MFA enabled location {}", + device.device.name, self.network.name + ); continue; }; self.send_peer_update( @@ -329,11 +333,17 @@ impl GatewayUpdatesHandler { .await { let msg = format!( - "Failed to send network update, network {network}, update type: {update_type}, error: {err}", + "Failed to send network update, network {network}, update type: {update_type} ({}), error: {err}", + if update_type == 0 { + "CREATE" + } else { + "MODIFY" + }, ); error!(msg); return Err(Status::new(Code::Internal, msg)); } + debug!("Network update sent for network {network}"); Ok(()) } @@ -358,12 +368,13 @@ impl GatewayUpdatesHandler { .await { let msg = format!( - "Failed to send network update, network {}, update type: 2, error: {err}", + "Failed to send network update, network {}, update type: 2 (DELETE), error: {err}", self.network, ); error!(msg); return Err(Status::new(Code::Internal, msg)); } + debug!("Network delete command sent for network {}", self.network); Ok(()) } @@ -379,12 +390,18 @@ impl GatewayUpdatesHandler { .await { let msg = format!( - "Failed to send peer update for network {}, update type: {update_type}, error: {err}", - self.network + "Failed to send peer update for network {}, update type: {update_type} ({}), error: {err}", + self.network, + if update_type == 0 { + "CREATE" + } else { + "MODIFY" + }, ); error!(msg); return Err(Status::new(Code::Internal, msg)); } + debug!("Peer update sent for network {}", self.network); Ok(()) } @@ -405,12 +422,13 @@ impl GatewayUpdatesHandler { .await { let msg = format!( - "Failed to send peer update for network {}, peer {peer_pubkey}, update type: 2, error: {err}", + "Failed to send peer update for network {}, peer {peer_pubkey}, update type: 2 (DELETE), error: {err}", self.network, ); error!(msg); return Err(Status::new(Code::Internal, msg)); } + debug!("Peer delete command sent for network {}", self.network); Ok(()) } } @@ -479,8 +497,9 @@ impl gateway_service_server::GatewayService for GatewayServer { let network_id = Self::get_network_id(request.metadata())?; let mut stream = request.into_inner(); while let Some(stats_update) = stream.message().await? { + debug!("Received stats message: {stats_update:?}"); let Some(stats_update::Payload::PeerStats(peer_stats)) = stats_update.payload else { - debug!("Received empty stats message"); + debug!("Received stats message is empty, skipping."); continue; }; let public_key = peer_stats.public_key.clone(); @@ -488,9 +507,15 @@ impl gateway_service_server::GatewayService for GatewayServer { // Get device by public key and fill in stats.device_id // FIXME: keep an in-memory device map to avoid repeated DB requests stats.device_id = match Device::find_by_pubkey(&self.pool, &public_key).await { - Ok(Some(device)) => device - .id - .ok_or_else(|| Status::new(Code::Internal, "Device has no ID"))?, + Ok(Some(device)) => device.id.ok_or_else(|| { + Status::new( + Code::Internal, + format!( + "Device {} (public key: {public_key}) has no ID", + device.name + ), + ) + })?, Ok(None) => { error!("Device with public key {public_key} not found"); return Err(Status::new( @@ -533,9 +558,14 @@ impl gateway_service_server::GatewayService for GatewayServer { error!("Network {network_id} not found"); Status::new(Code::Internal, format!("Failed to retrieve network: {e}")) })? - .ok_or_else(|| Status::new(Code::Internal, "Network not found"))?; + .ok_or_else(|| { + Status::new( + Code::Internal, + format!("Network with id {} not found", network_id), + ) + })?; - info!("Sending configuration to gateway client, network {network}."); + debug!("Sending configuration to gateway client, network {network}."); // store connected gateway in memory { @@ -551,17 +581,19 @@ impl gateway_service_server::GatewayService for GatewayServer { network.connected_at = Some(Utc::now().naive_utc()); if let Err(err) = network.save(&self.pool).await { - error!("Failed to update network {network_id} status: {err}"); + error!("Failed to save updated network {network_id} in the database, status: {err}"); } let peers = network.get_peers(&self.pool).await.map_err(|error| { - error!("Failed to fetch peers for network {network_id}: {error}",); + error!("Failed to fetch peers from the database for network {network_id}: {error}",); Status::new( Code::Internal, - format!("Failed to retrieve peers for network: {network_id}"), + format!("Failed to retrieve peers from the database for network: {network_id}"), ) })?; + info!("Configuration sent to gateway client, network {network}."); + Ok(Response::new(gen_config(&network, peers))) } @@ -572,14 +604,17 @@ impl gateway_service_server::GatewayService for GatewayServer { let Some(network) = WireguardNetwork::find_by_id(&self.pool, gateway_network_id) .await .map_err(|_| { - error!("Failed to fetch network {gateway_network_id}"); + error!("Failed to fetch network {gateway_network_id} from the database"); Status::new( Code::Internal, - format!("Failed to retrieve network {gateway_network_id}"), + format!("Failed to retrieve network {gateway_network_id} from the database"), ) })? else { - return Err(Status::new(Code::Internal, "Network not found")); + return Err(Status::new( + Code::Internal, + format!("Network with id {gateway_network_id} not found"), + )); }; info!("New client connected to updates stream: {hostname}, network {network}",); @@ -590,8 +625,11 @@ impl gateway_service_server::GatewayService for GatewayServer { state .connect_gateway(gateway_network_id, &hostname) .map_err(|err| { - error!("Failed to connect gateway: {err}"); - Status::new(Code::Internal, "Failed to connect gateway") + error!("Failed to connect gateway on network {gateway_network_id}: {err}"); + Status::new( + Code::Internal, + "Failed to connect gateway on network {gateway_network_id}", + ) })?; // clone here before moving into a closure diff --git a/src/grpc/mod.rs b/src/grpc/mod.rs index 98cd6c088a..11f44a0bfd 100644 --- a/src/grpc/mod.rs +++ b/src/grpc/mod.rs @@ -121,7 +121,7 @@ impl GatewayMap { // remove gateway from map pub fn remove_gateway(&mut self, network_id: i64, uid: Uuid) -> Result<(), GatewayMapError> { - info!("Removing gateway from network {network_id}"); + debug!("Removing gateway from network {network_id}"); if let Some(network_gateway_map) = self.0.get_mut(&network_id) { // find gateway by uuid let hostname = match network_gateway_map @@ -134,6 +134,7 @@ impl GatewayMap { } Some((hostname, state)) => { if state.connected { + error!("Cannot remove. Gateway with UID {uid} is still active"); return Err(GatewayMapError::RemoveActive(uid)); } hostname.clone() @@ -146,6 +147,7 @@ impl GatewayMap { error!("Network {network_id} not found in gateway map"); return Err(GatewayMapError::NetworkNotFound(network_id)); }; + info!("Gateway with UID {uid} removed from network {network_id}"); Ok(()) } @@ -156,12 +158,16 @@ impl GatewayMap { network_id: i64, hostname: &str, ) -> Result<(), GatewayMapError> { - info!("Connecting gateway {hostname} in network {network_id}"); + debug!("Connecting gateway {hostname} in network {network_id}"); if let Some(network_gateway_map) = self.0.get_mut(&network_id) { if let Some(state) = network_gateway_map.get_mut(hostname) { state.connected = true; state.disconnected_at = None; state.connected_at = Some(Utc::now().naive_utc()); + debug!( + "Gateway {hostname} found in gateway map, current state: {:#?}", + state + ); } else { error!("Gateway {hostname} not found in gateway map for network {network_id}"); return Err(GatewayMapError::NotFound(network_id, hostname.into())); @@ -171,6 +177,7 @@ impl GatewayMap { error!("Network {network_id} not found in gateway map"); return Err(GatewayMapError::NetworkNotFound(network_id)); }; + info!("Gateway {hostname} connected in network {network_id}"); Ok(()) } @@ -181,12 +188,17 @@ impl GatewayMap { hostname: String, pool: &DbPool, ) -> Result<(), GatewayMapError> { - info!("Disconnecting gateway {hostname} in network {network_id}"); + debug!("Disconnecting gateway {hostname} in network {network_id}"); if let Some(network_gateway_map) = self.0.get_mut(&network_id) { if let Some(state) = network_gateway_map.get_mut(&hostname) { state.connected = false; state.disconnected_at = Some(Utc::now().naive_utc()); state.send_disconnect_notification(pool)?; + debug!( + "Gateway {hostname} found in gateway map, current state: {:#?}", + state + ); + info!("Gateway {hostname} disconnected in network {network_id}"); return Ok(()); }; }; @@ -279,6 +291,7 @@ impl GatewayState { /// Send gateway disconnected notification /// Sends notification only if last notification time is bigger than specified in config fn send_disconnect_notification(&mut self, pool: &DbPool) -> Result<(), GatewayMapError> { + debug!("Sending gateway disconnect email notification"); // Clone here because self doesn't live long enough let name = self.name.clone(); let mail_tx = self.mail_tx.clone(); @@ -304,10 +317,12 @@ impl GatewayState { .await { error!("Failed to send gateway disconnect notification: {e}"); + } else { + info!("Gateway {hostname} disconnected. Email notification sent",); } }); } else { - debug!( + info!( "Gateway {hostname} disconnected. Email notification not sent. Last notification was at {:?}", self.last_email_notification ); @@ -361,17 +376,18 @@ pub async fn run_grpc_bidi_stream( }; loop { - info!("Connecting to proxy"); + debug!("Connecting to proxy at {}", endpoint.uri()); let mut client = ProxyClient::new(endpoint.connect_lazy()); let (tx, rx) = mpsc::unbounded_channel(); let Ok(response) = client.bidi(UnboundedReceiverStream::new(rx)).await else { - info!("Failed to connect to proxy, retrying in 10s"); + error!("Failed to connect to proxy, retrying in 10s"); sleep(TEN_SECS).await; continue; }; + info!("Connected to proxy at {}", endpoint.uri()); let mut resp_stream = response.into_inner(); while let Some(received) = resp_stream.next().await { - info!("received message"); + info!("Received message from proxy"); match received { Ok(received) => { let payload = match received.payload { @@ -529,7 +545,7 @@ pub async fn run_grpc_server( ); // Run gRPC server let addr = SocketAddr::new(IpAddr::V4(Ipv4Addr::UNSPECIFIED), server_config().grpc_port); - info!("Starting gRPC services"); + debug!("Starting gRPC services"); let builder = if let (Some(cert), Some(key)) = (grpc_cert, grpc_key) { let identity = Identity::from_pem(cert, key); Server::builder().tls_config(ServerTlsConfig::new().identity(identity))? @@ -545,6 +561,7 @@ pub async fn run_grpc_server( #[cfg(feature = "worker")] let router = router.add_service(worker_service); router.serve(addr).await?; + info!("gRPC server started on {addr}"); Ok(()) } diff --git a/src/grpc/password_reset.rs b/src/grpc/password_reset.rs index 5b4613d96a..d94c25c7c1 100644 --- a/src/grpc/password_reset.rs +++ b/src/grpc/password_reset.rs @@ -40,6 +40,7 @@ impl PasswordResetServer { // check if token provided with request corresponds to a valid enrollment session async fn validate_session(&self, token: Option<&str>) -> Result { + debug!("Validating enrollment session"); let Some(token) = token else { error!("Missing authorization header in request"); return Err(Status::unauthenticated("Missing authorization header")); @@ -49,6 +50,10 @@ impl PasswordResetServer { let enrollment = Token::find_by_id(&self.pool, token).await?; if enrollment.is_session_valid(server_config().enrollment_session_timeout.as_secs()) { + info!( + "Enrollment session validated for user {}.", + enrollment.user_id + ); Ok(enrollment) } else { error!("Enrollment session expired"); @@ -79,17 +84,22 @@ impl PasswordResetServer { let user = User::find_by_email(&self.pool, email.to_string().as_str()) .await .map_err(|_| { - error!("Failed to fetch user by email"); + error!("Failed to fetch user by email: {email}"); Status::internal("unexpected error") })?; let Some(user) = user else { // Do not return information whether user exists + debug!("Password reset skipped for non-existing user {email}"); return Ok(()); }; // Do not allow password change if user is disabled or not enrolled if !user.has_password() || !user.is_active { + debug!( + "Password reset skipped for disabled or not enrolled user {} ({email})", + user.username + ); return Ok(()); } @@ -127,6 +137,11 @@ impl PasswordResetServer { Some(&user_agent), )?; + info!( + "Finished processing password reset request for user {}.", + user.username + ); + Ok(()) } @@ -139,6 +154,10 @@ impl PasswordResetServer { let mut enrollment = Token::find_by_id(&self.pool, &request.token).await?; if enrollment.token_type != Some("PASSWORD_RESET".to_string()) { + error!( + "Invalid token type ({:?}) for password reset session", + enrollment.token_type + ); return Err(Status::permission_denied("invalid token")); } @@ -175,6 +194,11 @@ impl PasswordResetServer { Status::internal("unexpected error") })?; + info!( + "Finished processing password reset session for user {}.", + user.username + ); + Ok(response) } diff --git a/src/handlers/auth.rs b/src/handlers/auth.rs index de277b421f..d5c076aac1 100644 --- a/src/handlers/auth.rs +++ b/src/handlers/auth.rs @@ -63,7 +63,7 @@ pub async fn authenticate( if user.is_active { user } else { - info!("Failed to authenticate user {username}: user is inactive"); + info!("Failed to authenticate user {username}: user is disabled"); return Err(WebError::Authorization("user not found".into())); } } @@ -98,7 +98,11 @@ pub async fn authenticate( let agent = parse_user_agent(&appstate.user_agent_parser, &user_agent_string); let device_info = agent.clone().map(|v| get_user_agent_device(&v)); + debug!("Cleaning up expired sessions..."); Session::delete_expired(&appstate.pool).await?; + debug!("Expired sessions cleaned up"); + + debug!("Creating new session for user {username}"); let session = Session::new( user.id.unwrap(), SessionState::PasswordVerified, @@ -106,6 +110,7 @@ pub async fn authenticate( device_info, ); session.save(&appstate.pool).await?; + debug!("New session created for user {username}"); let max_age = Duration::seconds(server_config().auth_cookie_timeout.as_secs() as i64); let config = server_config(); @@ -147,6 +152,7 @@ pub async fn authenticate( }, )) } else { + error!("Couldn't fetch MFA info for user {username} with MFA enabled"); Err(WebError::DbError("MFA info read error".into())) } } else { diff --git a/src/handlers/ssh_authorized_keys.rs b/src/handlers/ssh_authorized_keys.rs index d7fa096897..fd2f69f963 100644 --- a/src/handlers/ssh_authorized_keys.rs +++ b/src/handlers/ssh_authorized_keys.rs @@ -174,6 +174,7 @@ pub async fn add_authentication_key( // authorize request let user = user_for_admin_or_self(&appstate.pool, &session, &username).await?; let Some(user_id) = user.id else { + error!("Model returned user ({}) without ID", user.username); return Err(WebError::ModelError("Model returned without ID".into())); }; @@ -184,6 +185,7 @@ pub async fn add_authentication_key( AuthenticationKeyType::Ssh => { let parsed = trimmed_key.parse::(); if parsed.is_err() { + error!("User {username} tried to insert invalid SSH key: {data:?}"); return Err(WebError::BadRequest("SSH key failed verification.".into())); } } @@ -230,6 +232,7 @@ pub async fn fetch_authentication_keys( ) -> ApiResult { let user = user_for_admin_or_self(&appstate.pool, &session, &username).await?; let Some(user_id) = user.id else { + error!("Model returned user ({}) without ID", user.username); return Err(WebError::ModelError( "Model returned user without ID".into(), )); @@ -258,6 +261,7 @@ pub async fn delete_authentication_key( } key.delete(&appstate.pool).await?; } else { + error!("Key with id {} not found", key_id); return Err(WebError::BadRequest("Key not found".into())); } Ok(ApiResponse { @@ -283,14 +287,26 @@ pub async fn rename_authentication_key( .ok_or(WebError::DbError("Returned user had no ID".into()))?; if let Some(mut key) = AuthenticationKey::find_by_id(&appstate.pool, key_id).await? { if key.yubikey_id.is_some() { + warn!( + "User {} tried to rename authentication key instead of yubikey", + username + ); return Err(WebError::BadRequest("Rename yubikey instead.".into())); } if !session.is_admin && user_id != key.user_id { + warn!( + "User {} tried to rename key ({}) of another user with id {}", + username, key_id, key.user_id + ); return Err(WebError::Forbidden(String::new())); } key.name = Some(data.name); key.save(&appstate.pool).await?; } else { + error!( + "User {} tried to rename non-existing key with id {}", + username, key_id + ); return Err(WebError::ObjectNotFound(String::new())); } diff --git a/src/handlers/user.rs b/src/handlers/user.rs index d52e3796b0..44608a054c 100644 --- a/src/handlers/user.rs +++ b/src/handlers/user.rs @@ -126,7 +126,7 @@ pub async fn add_user( // check username if let Err(err) = check_username(&username) { - debug!("{err}"); + debug!("Username {username} rejected: {err}"); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -189,12 +189,17 @@ pub async fn start_enrollment( // validate request if data.send_enrollment_notification && data.email.is_none() { + error!( + "Email notification is enabled for user {}, but email was not provided", + session.user.username + ); return Err(WebError::BadRequest( "Email notification is enabled, but email was not provided".into(), )); } let Some(user) = User::find_by_username(&appstate.pool, &username).await? else { + error!("User {username} couldn't be found, enrollment aborted"); return Err(WebError::ObjectNotFound(format!( "user {username} not found" ))); @@ -217,6 +222,11 @@ pub async fn start_enrollment( transaction.commit().await?; + info!( + "User {} started enrollment for user {username}", + session.user.username + ); + Ok(ApiResponse { json: json!({"enrollment_token": enrollment_token, "enrollment_url": config.enrollment_url.to_string()}), status: StatusCode::CREATED, @@ -259,6 +269,11 @@ pub async fn start_remote_desktop_configuration( transaction.commit().await?; + info!( + "User {} started enrollment for user {username}", + session.user.username + ); + Ok(ApiResponse { json: json!({"enrollment_token": enrollment_token, "enrollment_url": config.enrollment_url.to_string()}), status: StatusCode::CREATED, @@ -271,14 +286,17 @@ pub async fn username_available( Json(data): Json, ) -> ApiResult { if let Err(err) = check_username(&data.username) { - debug!("{err}"); + debug!("Username {} rejected: {err}", data.username); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, }); }; let status = match User::find_by_username(&appstate.pool, &data.username).await? { - Some(_) => StatusCode::BAD_REQUEST, + Some(_) => { + debug!("Username {} is not available", data.username); + StatusCode::BAD_REQUEST + } None => StatusCode::OK, }; Ok(ApiResponse { @@ -296,7 +314,7 @@ pub async fn modify_user( debug!("User {} updating user {username}", session.user.username); let mut user = user_for_admin_or_self(&appstate.pool, &session, &username).await?; if let Err(err) = check_username(&user_info.username) { - debug!("Failed to check username {} {err}", user_info.username); + debug!("Username {} rejected: {err}", user_info.username); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -339,11 +357,16 @@ pub async fn modify_user( .handle_status_change(&mut transaction, &mut user) .await? { + debug!( + "User {} changed {username} groups or status, syncing allowed network devices", + session.user.username + ); let networks = WireguardNetwork::all(&mut *transaction).await?; for network in networks { let gateway_events = network.sync_allowed_devices(&mut transaction, None).await?; appstate.send_multiple_wireguard_events(gateway_events); } + info!("Allowed network devices of {username} synced"); }; user_info.into_user_all_fields(&mut user)?; } else { @@ -395,6 +418,7 @@ pub async fn change_self_password( State(appstate): State, Json(data): Json, ) -> ApiResult { + debug!("User {} is changing his password.", session.user.username); let mut user = session.user; if user.verify_password(&data.old_password).is_err() { return Ok(ApiResponse { @@ -403,7 +427,8 @@ pub async fn change_self_password( }); } - if check_password_strength(&data.new_password).is_err() { + if let Err(err) = check_password_strength(&data.new_password) { + debug!("User {} password change failed: {err}", user.username); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -415,7 +440,7 @@ pub async fn change_self_password( let _ = ldap_change_password(&appstate.pool, &user.username, &data.new_password).await; - info!("User {} changed password.", &user.username); + info!("User {} changed his password.", &user.username); Ok(ApiResponse { json: json!({}), @@ -436,7 +461,7 @@ pub async fn change_password( ); if session.user.username == username { - debug!("Cannot change own password with this endpoint."); + debug!("Cannot change own ({username}) password with this endpoint."); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -444,14 +469,14 @@ pub async fn change_password( } if let Err(err) = check_password_strength(&data.new_password) { - debug!("Pasword not strong enough: {err}"); + debug!("Password for user {username} not strong enough: {err}"); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, }); } if let Err(err) = check_username(&username) { - debug!("Invalid Username: {err}"); + debug!("Invalid username ({username}): {err}"); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -470,7 +495,7 @@ pub async fn change_password( ); Ok(ApiResponse::default()) } else { - debug!("User not found"); + debug!("Can't change password for user {username}, user not found"); Ok(ApiResponse { json: json!({}), status: StatusCode::NOT_FOUND, @@ -485,12 +510,12 @@ pub async fn reset_password( Path(username): Path, ) -> ApiResult { debug!( - "Admin {} changing password for user {username}", + "Admin {} resetting password for user {username}", session.user.username, ); if session.user.username == username { - debug!("Cannot change own password with this endpoint."); + debug!("Cannot reset own ({username}) password with this endpoint."); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -535,11 +560,13 @@ pub async fn reset_password( match &appstate.mail_tx.send(mail) { Ok(()) => { - info!("Password reset email sent to {to}"); + info!("Password reset email for {username} sent to {to}"); Ok(()) } Err(err) => { - error!("Failed to send password reset email to {to} with error:\n{err}"); + error!( + "Failed to send password reset email for {username} to {to} with error: {err}" + ); Err(WebError::Serialization(format!( "Could not send password reset email to user {username}" ))) @@ -549,12 +576,12 @@ pub async fn reset_password( transaction.commit().await?; info!( - "Admin {} changed password for user {username}", + "Admin {} reset password for user {username}", session.user.username ); Ok(ApiResponse::default()) } else { - debug!("User not found"); + debug!("Can't reset password for user {username}, user not found"); Ok(ApiResponse { json: json!({}), status: StatusCode::NOT_FOUND, @@ -588,6 +615,10 @@ pub async fn wallet_challenge( .await? { if wallet.validation_timestamp.is_some() { + error!( + "Can't generate wallet challange for user {username}, the wallet {} is already validated", + wallet_info.address + ); return Err(WebError::ObjectNotFound("wrong address".into())); } wallet @@ -596,6 +627,7 @@ pub async fn wallet_challenge( if let Some(settings) = Settings::find_by_id(&appstate.pool, 1).await? { Wallet::format_challenge(&wallet_info.address, &settings.challenge_template) } else { + error!("Cannot retrieve settings"); return Err(WebError::DbError("cannot retrieve settings".into())); }; let mut wallet = Wallet::new_for_user( @@ -647,9 +679,17 @@ pub async fn set_wallet( ); Ok(ApiResponse::default()) } else { + error!( + "User {} failed to set wallet signature for user {username}, wallet ({}) signature {} is invalid", + session.user.username, wallet_info.address, wallet_info.signature + ); Err(WebError::ObjectNotFound("wrong address".into())) } } else { + error!( + "User {} failed to set wallet signature for user {username}, address {} not found", + session.user.username, wallet_info.address + ); Err(WebError::ObjectNotFound("wallet not found".into())) } } @@ -708,9 +748,17 @@ pub async fn update_wallet( ); Ok(ApiResponse::default()) } else { + error!( + "User {} failed to update wallet {address} for user {username} (id: {:?}), the owner id is {}", + session.user.username, user.id, wallet.user_id + ); Err(WebError::ObjectNotFound("wrong wallet".into())) } } else { + error!( + "User {} failed to update wallet {address} for user {username}, wallet not found", + session.user.username + ); Err(WebError::ObjectNotFound("wallet not found".into())) } } @@ -738,9 +786,17 @@ pub async fn delete_wallet( ); Ok(ApiResponse::default()) } else { + error!( + "User {} failed to delete wallet {address} for user {username} (id: {:?}), the owner id is {}", + session.user.username, user.id, wallet.user_id + ); Err(WebError::ObjectNotFound("wrong wallet".into())) } } else { + error!( + "User {} failed to delete wallet {address} for user {username}, wallet not found", + session.user.username + ); Err(WebError::ObjectNotFound("wallet not found".into())) } } @@ -765,9 +821,17 @@ pub async fn delete_security_key( ); Ok(ApiResponse::default()) } else { + error!( + "User {} failed to delete security key {id} for user {username} (id: {:?}), the owner id is {}", + session.user.username, user.id, webauthn.user_id + ); Err(WebError::ObjectNotFound("wrong security key".into())) } } else { + error!( + "User {} failed to delete security key {id} for user {username}, security key not found", + session.user.username + ); Err(WebError::ObjectNotFound("security key not found".into())) } } @@ -806,9 +870,17 @@ pub async fn delete_authorized_app( ); Ok(ApiResponse::default()) } else { + error!( + "User {} failed to delete OAuth2 client {oauth2client_id} for user {username} (id: {:?}), the app owner id is {}", + session.user.username, user.id, app.user_id + ); Err(WebError::ObjectNotFound("Wrong app".into())) } } else { + error!( + "User {} failed to delete OAuth2 client {oauth2client_id} for user {username}, authorized app not found", + session.user.username + ); Err(WebError::ObjectNotFound("Authorized app not found".into())) } } diff --git a/src/handlers/wireguard.rs b/src/handlers/wireguard.rs index f7c1dfa602..b545e3c575 100644 --- a/src/handlers/wireguard.rs +++ b/src/handlers/wireguard.rs @@ -124,7 +124,7 @@ pub async fn create_network( .send_wireguard_event(GatewayEvent::NetworkCreated(*network_id, network.clone())); } None => { - error!("Network {} ID was not created during network creation, gateway event was not send!", network.name); + error!("Network {} ID was not created during network creation, gateway event was not sent!", network.name); return Ok(ApiResponse { json: json!({}), status: StatusCode::INTERNAL_SERVER_ERROR, @@ -193,7 +193,7 @@ pub async fn modify_network( } &None => { error!( - "Network {} id not found, gateway update not send!", + "Network {} id not found, gateway update not sent!", network.name ); } @@ -309,6 +309,7 @@ pub async fn gateway_status( let gateway_state = gateway_state .lock() .expect("Failed to acquire gateway state lock"); + debug!("Displayed gateway status for network {network_id}"); Ok(ApiResponse { json: json!(gateway_state.get_network_gateway_status(network_id)), @@ -321,7 +322,7 @@ pub async fn remove_gateway( _role: VpnRole, Extension(gateway_state): Extension>>, ) -> ApiResult { - info!("Removing gateway {gateway_id} in network {network_id}"); + debug!("Removing gateway {gateway_id} in network {network_id}"); let mut gateway_state = gateway_state .lock() .expect("Failed to acquire gateway state lock"); @@ -332,6 +333,8 @@ pub async fn remove_gateway( .map_err(|_| WebError::Http(StatusCode::INTERNAL_SERVER_ERROR))?, )?; + info!("Removed gateway {gateway_id} in network {network_id}"); + Ok(ApiResponse { json: Value::Null, status: StatusCode::OK, @@ -343,7 +346,7 @@ pub async fn import_network( State(appstate): State, Json(data): Json, ) -> ApiResult { - info!("Importing network from config file"); + debug!("Importing network from config file"); let (mut network, imported_devices) = parse_wireguard_config(&data.config).map_err(|error| { error!("{error}"); @@ -379,14 +382,17 @@ pub async fn import_network( appstate.send_multiple_wireguard_events(gateway_events); // assign IPs for other existing devices - info!("Assigning IPs in imported network for remaining existing devices"); + debug!("Assigning IPs in imported network for remaining existing devices"); let gateway_events = network .sync_allowed_devices(&mut transaction, Some(&reserved_ips)) .await?; appstate.send_multiple_wireguard_events(gateway_events); + debug!("Assigned IPs in imported network for remaining existing devices"); transaction.commit().await?; + info!("Imported network {network} with {} devices", devices.len()); + Ok(ApiResponse { json: json!(ImportedNetworkData { network, devices }), status: StatusCode::CREATED, @@ -405,8 +411,14 @@ pub async fn add_user_devices( let user = session.user; let device_count = mapped_devices.len(); + debug!( + "User {} mapping {device_count} devices for network {network_id}", + user.username, + ); + // finish early if no devices were provided in request if mapped_devices.is_empty() { + debug!("No devices provided in request, skipping mapping"); return Ok(ApiResponse { json: json!({}), status: StatusCode::NO_CONTENT, @@ -415,11 +427,6 @@ pub async fn add_user_devices( match WireguardNetwork::find_by_id(&appstate.pool, network_id).await? { Some(network) => { - info!( - "User {} mapping {device_count} devices for network {network_id}", - user.username, - ); - // wrap loop in transaction to abort if a device is invalid let mut transaction = appstate.pool.begin().await?; let events = network @@ -438,9 +445,12 @@ pub async fn add_user_devices( status: StatusCode::CREATED, }) } - None => Err(WebError::ObjectNotFound(format!( - "Network {network_id} not found" - ))), + None => { + error!("Failed to map devices, network {network_id} not found"); + Err(WebError::ObjectNotFound(format!( + "Network {network_id} not found" + ))) + } } } @@ -471,7 +481,7 @@ pub async fn add_device( let networks = WireguardNetwork::all(&appstate.pool).await?; if networks.is_empty() { - error!("No network found, can't add device"); + error!("Failed to add device {device_name}, no networks found"); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -482,6 +492,10 @@ pub async fn add_device( // save device let Some(user_id) = user.id else { + error!( + "Failed to add device {device_name}, user {} has no id", + user.username + ); return Err(WebError::ModelError("User has no id".to_string())); }; let mut device = Device::new(add_device.name, add_device.wireguard_pubkey, user_id); @@ -561,7 +575,7 @@ pub async fn modify_device( let networks = WireguardNetwork::all(&appstate.pool).await?; if networks.is_empty() { - error!("No network found can't modify device"); + error!("Failed to update device {device_id}, no networks found"); return Ok(ApiResponse { json: json!({}), status: StatusCode::BAD_REQUEST, @@ -571,6 +585,7 @@ pub async fn modify_device( // check pubkeys for network in &networks { if network.pubkey == data.wireguard_pubkey { + error!("Failed to update device {device_id}, device's pubkey must be different from server's pubkey"); return Ok(ApiResponse { json: json!({"msg": "device's pubkey must be different from server's pubkey"}), status: StatusCode::BAD_REQUEST, @@ -620,6 +635,7 @@ pub async fn get_device( ) -> ApiResult { debug!("Retrieving device with id: {device_id}"); let device = device_for_admin_or_self(&appstate.pool, &session, device_id).await?; + debug!("Retrieved device with id: {device_id}"); Ok(ApiResponse { json: json!(device), status: StatusCode::OK, @@ -644,7 +660,7 @@ pub async fn delete_device( pub async fn list_devices(_role: VpnRole, State(appstate): State) -> ApiResult { debug!("Listing devices"); let devices = Device::all(&appstate.pool).await?; - info!("Listed devices"); + info!("Listed {} devices", devices.len()); Ok(ApiResponse { json: json!(devices), @@ -659,10 +675,15 @@ pub async fn list_user_devices( ) -> ApiResult { // only allow for admin or user themselves if !session.is_admin && session.user.username != username { + warn!( + "User {} tried to list devices for user {username}, but is not an admin", + session.user.username + ); return Err(WebError::Forbidden("Admin access required".into())); }; debug!("Listing devices for user: {username}"); let devices = Device::all_for_username(&appstate.pool, &username).await?; + info!("Listed {} devices for user: {username}", devices.len()); Ok(ApiResponse { json: json!(devices), @@ -675,11 +696,13 @@ pub async fn download_config( State(appstate): State, Path((network_id, device_id)): Path<(i64, i64)>, ) -> Result { + debug!("Creating config for device {device_id} in network {network_id}"); let network = find_network(network_id, &appstate.pool).await?; let device = device_for_admin_or_self(&appstate.pool, &session, device_id).await?; let wireguard_network_device = WireguardNetworkDevice::find(&appstate.pool, device_id, network_id).await?; if let Some(wireguard_network_device) = wireguard_network_device { + info!("Created config for device {}({device_id})", device.name); Ok(device.create_config(&network, &wireguard_network_device)) } else { let device_id = if let Some(id) = device.id { @@ -687,6 +710,10 @@ pub async fn download_config( } else { String::new() }; + error!( + "Failed to create config, no IP address found for device: {}({device_id})", + device.name + ); Err(WebError::ObjectNotFound(format!( "No IP address found for device: {}({device_id})", device.name @@ -699,7 +726,7 @@ pub async fn create_network_token( State(appstate): State, Path(network_id): Path, ) -> ApiResult { - info!("Generating a new token for network ID {network_id}"); + debug!("Generating a new token for network ID {network_id}"); let network = find_network(network_id, &appstate.pool).await?; let token = Claims::new( ClaimsType::Gateway, @@ -709,11 +736,13 @@ pub async fn create_network_token( ) .to_jwt() .map_err(|_| { + error!("Failed to create token for gateway {}", network.name); WebError::Authorization(format!( "Failed to create token for gateway {}", network.name )) })?; + info!("Generated a new token for network ID {network_id}"); Ok(ApiResponse { json: json!({"token": token, "grpc_url": server_config().grpc_url.to_string()}), status: StatusCode::OK, @@ -754,7 +783,7 @@ pub async fn user_stats( Path(network_id): Path, Query(query_from): Query, ) -> ApiResult { - debug!("Displaying WireGuard user stats"); + debug!("Displaying WireGuard user stats for network {network_id}"); let Some(network) = WireguardNetwork::find_by_id(&appstate.pool, network_id).await? else { return Err(WebError::ObjectNotFound(format!( "Requested network ({network_id}) not found", @@ -765,7 +794,7 @@ pub async fn user_stats( let stats = network .user_stats(&appstate.pool, &from, &aggregation) .await?; - debug!("Displayed WireGuard user stats"); + debug!("Displayed WireGuard user stats for network {network_id}"); Ok(ApiResponse { json: json!(stats), @@ -779,7 +808,7 @@ pub async fn network_stats( Path(network_id): Path, Query(query_from): Query, ) -> ApiResult { - debug!("Displaying WireGuard network stats"); + debug!("Displaying WireGuard network stats for network {network_id}"); let Some(network) = WireguardNetwork::find_by_id(&appstate.pool, network_id).await? else { return Err(WebError::ObjectNotFound(format!( "Requested network ({network_id}) not found" @@ -790,7 +819,7 @@ pub async fn network_stats( let stats = network .network_stats(&appstate.pool, &from, &aggregation) .await?; - debug!("Displayed WireGuard network stats"); + debug!("Displayed WireGuard network stats for network {network_id}"); Ok(ApiResponse { json: json!(stats), diff --git a/src/handlers/worker.rs b/src/handlers/worker.rs index 54eeb229eb..86254df911 100644 --- a/src/handlers/worker.rs +++ b/src/handlers/worker.rs @@ -46,6 +46,10 @@ pub async fn create_job( Some(user) => { // only admins should be able to create jobs for other users if user != session.user && !session.is_admin { + warn!( + "User {} cannot schedule jobs for other users", + session.user.username + ); return Err(WebError::Forbidden( "Cannot schedule jobs for other users.".into(), )); @@ -69,10 +73,13 @@ pub async fn create_job( status: StatusCode::CREATED, }) } - None => Err(WebError::ObjectNotFound(format!( - "user {} not found", - job_data.username - ))), + None => { + error!("Failed to create job, user {} not found", job_data.username); + Err(WebError::ObjectNotFound(format!( + "user {} not found", + job_data.username + ))) + } } } @@ -96,8 +103,10 @@ pub async fn list_workers( _admin: AdminRole, Extension(worker_state): Extension>>, ) -> ApiResult { + debug!("Listing workers"); let state = worker_state.lock().unwrap(); let workers = state.list_workers(); + debug!("Listed workers"); Ok(ApiResponse { json: json!(workers), status: StatusCode::OK, @@ -128,21 +137,34 @@ pub async fn job_status( Extension(worker_state): Extension>>, Path(id): Path, ) -> ApiResult { + debug!( + "User {} fetching job status for job {id}", + session.user.username + ); let state = worker_state.lock().unwrap(); let job_response = state.get_job_status(id); if let Some(response) = job_response { // prevent non-admin users from accessing other users' jobs status if !session.is_admin && response.username != session.user.username { + warn!( + "User {} cannot fetch job status for other users' jobs", + session.user.username + ); return Err(WebError::Forbidden( "Cannot fetch job status for other users' jobs.".into(), )); } if response.success { + debug!("Fetched job status for job {id}"); Ok(ApiResponse { json: json!(job_response), status: StatusCode::OK, }) } else { + error!( + "Failed to fetch job status for job {id}: {}", + response.error + ); Ok(ApiResponse { json: json!(JobResponseError { message: response.error.clone() @@ -151,6 +173,7 @@ pub async fn job_status( }) } } else { + debug!("Fetched job status for job {id}"); Ok(ApiResponse { json: json!(job_response), status: StatusCode::OK, diff --git a/src/handlers/yubikey.rs b/src/handlers/yubikey.rs index 66c8a7cb72..aab077d88c 100644 --- a/src/handlers/yubikey.rs +++ b/src/handlers/yubikey.rs @@ -19,9 +19,14 @@ pub async fn delete_yubikey( .id .ok_or(WebError::DbError("Returned user had no ID".into()))?; let Some(yubikey) = YubiKey::find_by_id(&appstate.pool, key_id).await? else { + error!("Yubikey with id {key_id} not found"); return Err(WebError::ObjectNotFound("YubiKey not found".into())); }; if !session.is_admin && yubikey.user_id != user_id { + warn!( + "User {user_id} tried to delete yubikey {key_id} of user {} without being an admin.", + yubikey.user_id + ); return Err(WebError::Forbidden("Not allowed to delete YubiKey".into())); } yubikey.delete(&appstate.pool).await?; @@ -49,10 +54,11 @@ pub async fn rename_yubikey( .ok_or(WebError::DbError("Returned user had no ID".into()))?; debug!("User {} attempts to rename yubikey {}", user_id, key_id); let Some(mut yubikey) = YubiKey::find_by_id(&appstate.pool, key_id).await? else { + error!("Yubikey with id {key_id} not found"); return Err(WebError::ObjectNotFound("YubiKey not found".into())); }; if !session.is_admin && yubikey.user_id != user_id { - info!( + warn!( "User {user_id}, tried to rename yubikey {key_id} of user {} without being an admin.", yubikey.user_id );