From db70a7acf5552f714a736eac8ea9e2f72e9e2223 Mon Sep 17 00:00:00 2001 From: Aleksander <170264518+t-aleksander@users.noreply.github.com> Date: Thu, 13 Jun 2024 15:45:54 +0200 Subject: [PATCH] add even more logs --- src-tauri/src/appstate.rs | 11 +++-- src-tauri/src/commands.rs | 62 +++++++++++++++++++--------- src-tauri/src/service/log_watcher.rs | 10 ++--- src-tauri/src/tray.rs | 2 +- src-tauri/src/utils.rs | 58 +++++++++++++++++++++++--- 5 files changed, 110 insertions(+), 33 deletions(-) diff --git a/src-tauri/src/appstate.rs b/src-tauri/src/appstate.rs index de763559..58b50ce7 100644 --- a/src-tauri/src/appstate.rs +++ b/src-tauri/src/appstate.rs @@ -71,6 +71,7 @@ impl AppState { info!("Removed connection from active connections: {removed_connection:#?}"); Some(removed_connection) } else { + debug!("No active connection found with location_id: {location_id}"); None } } @@ -97,11 +98,15 @@ impl AppState { let active_connections = self.get_connections(); info!("Found {} active connections", active_connections.len()); for connection in active_connections { - debug!("Found active connection"); + debug!( + "Found active connection with location {}", + connection.location_id + ); trace!("Connection: {connection:#?}"); - debug!("Removing interface"); + debug!("Removing interface {}", connection.interface_name); disconnect_interface(connection, self).await?; } + info!("All active connections closed"); Ok(()) } @@ -123,7 +128,7 @@ impl AppState { debug!("Found connection: {connection:#?}"); Some(connection.to_owned()) } else { - error!("Element with id: {id}, connection_type: {connection_type:?} not found."); + error!("Couldn't find connection with id: {id}, connection_type: {connection_type:?} in active connections."); None } } diff --git a/src-tauri/src/commands.rs b/src-tauri/src/commands.rs index bd28e09f..684c2f1e 100644 --- a/src-tauri/src/commands.rs +++ b/src-tauri/src/commands.rs @@ -78,7 +78,7 @@ pub async fn disconnect( info!("Disconnected from location with id: {location_id}"); Ok(()) } else { - error!("Connection for location with id: {location_id} not found"); + error!("Error while disconnecting from location with id: {location_id} not found"); Err(Error::NotFound) } } @@ -130,7 +130,7 @@ pub async fn save_device_config( app_state: State<'_, AppState>, handle: AppHandle, ) -> Result { - debug!("Received device configuration: {response:#?}"); + debug!("Received device configuration: {response:#?}."); let mut transaction = app_state.get_pool().begin().await?; let instance_info = response @@ -168,6 +168,7 @@ pub async fn save_device_config( locations, instance, }; + info!("Device configuration saved."); Ok(res) } @@ -309,6 +310,7 @@ pub async fn update_instance( let mut transaction = pool.begin().await?; // update instance + debug!("Updating instance {instance_id}."); let instance_info = response .instance .expect("Missing instance info in device config response"); @@ -319,6 +321,7 @@ pub async fn update_instance( instance.save(&mut *transaction).await?; // process locations received in response + debug!("Updating locations for instance {instance_id}."); for location in response.configs { // parse device config let mut new_location = device_config_to_location(location, instance_id); @@ -330,6 +333,10 @@ pub async fn update_instance( { // remove from list of existing locations let mut current_location = current_locations.remove(position); + debug!( + "Updating existing location {} for instance {instance_id}.", + current_location.name + ); // update existing location current_location.name = new_location.name; current_location.address = new_location.address; @@ -339,17 +346,26 @@ pub async fn update_instance( current_location.mfa_enabled = new_location.mfa_enabled; current_location.keepalive_interval = new_location.keepalive_interval; current_location.save(&mut *transaction).await?; + info!( + "Location {} updated for instance {instance_id}.", + current_location.name + ); } else { // create new location + debug!("Creating new location for instance {instance_id}."); new_location.save(&mut *transaction).await?; + info!("New location created for instance {instance_id}."); } } + info!("Locations updated for instance {instance_id}."); // remove locations which were present in current locations // but no longer found in core response + debug!("Removing locations for instance {instance_id}."); for removed_location in current_locations { removed_location.delete(&mut *transaction).await?; } + info!("Locations removed for instance {instance_id}."); transaction.commit().await?; @@ -456,7 +472,7 @@ pub async fn all_connections( .collect() } }; - debug!("Connections received, returning."); + info!("Connections retrieved({})", connections.len()); trace!("Connections found:\n{:#?}", connections); Ok(connections) } @@ -469,7 +485,7 @@ pub async fn all_tunnel_connections( debug!("Retrieving connections for location {location_id}"); let connections = TunnelConnectionInfo::all_by_tunnel_id(&app_state.get_pool(), location_id).await?; - debug!("Connections received, returning."); + info!("Tunnel connections retrieved({})", connections.len()); trace!("Connections found:\n{:#?}", connections); Ok(connections) } @@ -487,8 +503,8 @@ pub async fn active_connection( if connection.is_some() { debug!("Active connection found"); } - trace!("Connection:\n{:#?}", connection); - debug!("Connection returned"); + trace!("Connection retrieved:\n{:#?}", connection); + info!("Connection retrieved"); Ok(connection) } @@ -503,7 +519,7 @@ pub async fn last_connection( if let Some(connection) = Connection::latest_by_location_id(&app_state.get_pool(), location_id).await? { - trace!("Connection found"); + info!("Found last connection at {}", connection.end); Ok(Some(connection.into())) } else { Ok(None) @@ -511,10 +527,10 @@ pub async fn last_connection( } else if let Some(connection) = TunnelConnection::latest_by_tunnel_id(&app_state.get_pool(), location_id).await? { - trace!("Connection found"); + info!("Found last connection at {}", connection.end); Ok(Some(connection.into())) } else { - trace!("No last connection found"); + info!("No last connection found"); Ok(None) } } @@ -536,7 +552,7 @@ pub async fn update_location_routing( { location.route_all_traffic = route_all_traffic; location.save(&app_state.get_pool()).await?; - debug!("Location routing updated for location {location_id}"); + info!("Location routing updated for location {location_id}"); handle.emit_all( "location-update", Payload { @@ -556,7 +572,7 @@ pub async fn update_location_routing( { tunnel.route_all_traffic = route_all_traffic; tunnel.save(&app_state.get_pool()).await?; - debug!("Tunnel routing updated for tunnel {location_id}"); + info!("Tunnel routing updated for tunnel {location_id}"); handle.emit_all( "location-update", Payload { @@ -577,6 +593,7 @@ pub async fn get_settings(handle: AppHandle) -> Result { debug!("Retrieving settings"); let app_state = handle.state::(); let settings = Settings::get(&app_state.get_pool()).await?; + info!("Settings retrieved"); Ok(settings) } @@ -595,7 +612,7 @@ pub async fn update_settings(data: SettingsPatch, handle: AppHandle) -> Result {} Err(e) => { error!( - "During settings update, tray configuration update failed. err : {}", + "Tray configuration update failed during settings update. err : {}", e.to_string() ); } @@ -632,7 +649,7 @@ pub async fn delete_instance(instance_id: i64, handle: AppHandle) -> Result<(), error!("{msg}"); Error::InternalError(msg) })?; - debug!("Connection closed and interface removed"); + info!("Connection closed and interface removed"); } } } @@ -648,10 +665,12 @@ pub async fn delete_instance(instance_id: i64, handle: AppHandle) -> Result<(), #[tauri::command(async)] pub async fn parse_tunnel_config(config: String) -> Result { debug!("Parsing config file"); - parse_wireguard_config(&config).map_err(|error| { + let tunnel_config = parse_wireguard_config(&config).map_err(|error| { error!("{error}"); Error::ConfigParseError(error.to_string()) - }) + })?; + info!("Config file parsed"); + Ok(tunnel_config) } #[tauri::command(async)] pub async fn save_tunnel(mut tunnel: Tunnel, handle: AppHandle) -> Result<(), Error> { @@ -700,6 +719,8 @@ pub async fn all_tunnels(app_state: State<'_, AppState>) -> Result Result<(), Erro error!("{msg}"); Error::InternalError(msg) })?; - debug!("Connection closed and interface removed"); + info!("Connection closed and interface removed"); } tunnel.delete(pool).await?; } else { @@ -798,10 +819,13 @@ pub async fn get_latest_app_version(handle: AppHandle) -> Result = response.json::().await; - response_json.map_err(|err| { + let response = response_json.map_err(|err| { error!("Failed to deserialize latest application version response {err}"); Error::CommandError(err.to_string()) - }) + })?; + + info!("Latest application version fetched: {}", response.version); + Ok(response) } else { let err = res.err().unwrap(); error!("Failed to fetch latest application version {err}"); diff --git a/src-tauri/src/service/log_watcher.rs b/src-tauri/src/service/log_watcher.rs index c628ba6e..c01b1bc5 100644 --- a/src-tauri/src/service/log_watcher.rs +++ b/src-tauri/src/service/log_watcher.rs @@ -142,7 +142,7 @@ impl ServiceLogWatcher { fn parse_log_dir(&mut self) -> Result<(), LogWatcherError> { // get latest log file let latest_log_file = self.get_latest_log_file()?; - info!("found latest log file: {latest_log_file:?}"); + debug!("found latest log file: {latest_log_file:?}"); // check if latest file changed if latest_log_file.is_some() && latest_log_file != self.current_log_file { @@ -180,9 +180,9 @@ impl ServiceLogWatcher { /// Deserializes the log line into a known struct and checks if the line is relevant /// to the specified interface. Also performs filtering by log level and optional timestamp. fn parse_log_line(&self, line: String) -> Result, LogWatcherError> { - debug!("Parsing log line: {line}"); + trace!("Parsing log line: {line}"); let log_line = serde_json::from_str::(&line)?; - debug!("Parsed log line into: {log_line:?}"); + trace!("Parsed log line into: {log_line:?}"); // filter by log level if log_line.level > self.log_level { @@ -205,7 +205,7 @@ impl ServiceLogWatcher { if let Some(ref span) = log_line.span { if let Some(interface_name) = &span.interface_name { if interface_name != &self.interface_name { - debug!("Interface name {interface_name} is not the configured name {}. Skipping line...", self.interface_name); + trace!("Interface name {interface_name} is not the configured name {}. Skipping line...", self.interface_name); return Ok(None); } } @@ -244,7 +244,7 @@ impl ServiceLogWatcher { } fn extract_timestamp(filename: &str) -> Option { - debug!("Extracting timestamp from log file name: {filename}"); + trace!("Extracting timestamp from log file name: {filename}"); // we know that the date is always in the last 10 characters let split_pos = filename.char_indices().nth_back(9)?.0; let timestamp = &filename[split_pos..]; diff --git a/src-tauri/src/tray.rs b/src-tauri/src/tray.rs index 8365185a..9ecf5d40 100644 --- a/src-tauri/src/tray.rs +++ b/src-tauri/src/tray.rs @@ -101,7 +101,7 @@ pub fn configure_tray_icon(app: &AppHandle, theme: &TrayIconTheme) -> Result<(), Some(icon_path) => { let icon = tauri::Icon::File(icon_path); app.tray_handle().set_icon(icon)?; - debug!("Tray icon changed"); + info!("Tray icon changed"); Ok(()) } None => { diff --git a/src-tauri/src/utils.rs b/src-tauri/src/utils.rs index a15f7c4c..5587c0ac 100644 --- a/src-tauri/src/utils.rs +++ b/src-tauri/src/utils.rs @@ -47,14 +47,20 @@ pub async fn setup_interface( // prepare peer config debug!("Decoding location public key: {}.", location.pubkey); let peer_key: Key = Key::from_str(&location.pubkey)?; + info!("Location public key decoded."); + debug!("Location public key: {peer_key}"); let mut peer = Peer::new(peer_key); debug!("Parsing location endpoint: {}", location.endpoint); peer.set_endpoint(&location.endpoint)?; peer.persistent_keepalive_interval = Some(25); + info!("Parsed location endpoint."); + debug!("Location endpoint: {}", location.endpoint); if let Some(psk) = preshared_key { + debug!("Decoding preshared key."); let peer_psk = Key::from_str(&psk)?; + info!("Preshared key decoded."); peer.preshared_key = Some(peer_psk); } @@ -86,9 +92,13 @@ pub async fn setup_interface( } } } + info!("Parsed allowed IPs for location."); + debug!("Allowed IPs: {:#?}", peer.allowed_ips); // request interface configuration + debug!("Looking for a free port for interface {interface_name}..."); if let Some(port) = find_random_free_port() { + info!("Found free port: {port} for interface {interface_name}."); let interface_config = InterfaceConfiguration { name: interface_name, prvkey: keys.prvkey, @@ -278,6 +288,8 @@ pub async fn setup_interface_tunnel( // prepare peer config debug!("Decoding location public key: {}.", tunnel.server_pubkey); let peer_key: Key = Key::from_str(&tunnel.server_pubkey)?; + info!("Location public key decoded."); + debug!("Location public key: {peer_key}"); let mut peer = Peer::new(peer_key); debug!("Parsing location endpoint: {}", tunnel.endpoint); @@ -288,9 +300,13 @@ pub async fn setup_interface_tunnel( .try_into() .expect("Failed to parse persistent keep alive"), ); + info!("Parsed location endpoint."); + debug!("Location endpoint: {}", tunnel.endpoint); if let Some(psk) = &tunnel.preshared_key { + debug!("Decoding preshared key."); let peer_psk = Key::from_str(psk)?; + debug!("Preshared key decoded."); peer.preshared_key = Some(peer_psk); } @@ -323,9 +339,13 @@ pub async fn setup_interface_tunnel( } } } + info!("Parsed allowed IPs."); + debug!("Allowed IPs: {:#?}", peer.allowed_ips); // request interface configuration + debug!("Looking for a free port for interface {interface_name}..."); if let Some(port) = find_random_free_port() { + info!("Found free port: {port} for interface {interface_name}."); let interface_config = InterfaceConfiguration { name: interface_name, prvkey: tunnel.prvkey.clone(), @@ -346,7 +366,8 @@ pub async fn setup_interface_tunnel( error!("{msg}"); Err(Error::InternalError(msg)) } else { - info!("Created interface {interface_config:#?}"); + info!("Created interface {}", interface_config.name); + debug!("Created interface with config: {interface_config:#?}"); Ok(()) } } else { @@ -367,7 +388,6 @@ pub async fn get_tunnel_interface_details( ) -> Result { debug!("Fetching tunnel details for tunnel ID {tunnel_id}"); if let Some(tunnel) = Tunnel::find_by_id(pool, tunnel_id).await? { - debug!("Fetching WireGuard keys for location {}", tunnel.name); let peer_pubkey = tunnel.pubkey; // generate interface name @@ -376,6 +396,7 @@ pub async fn get_tunnel_interface_details( #[cfg(not(target_os = "macos"))] let interface_name = get_interface_name(&tunnel.name); + debug!("Fetching tunnel stats for tunnel ID {tunnel_id}"); let result = query!( r#" SELECT last_handshake, listen_port as "listen_port!: u32", @@ -387,6 +408,7 @@ pub async fn get_tunnel_interface_details( ) .fetch_optional(pool) .await?; + info!("Fetched tunnel stats for tunnel ID {tunnel_id}"); let (listen_port, persistent_keepalive_interval, last_handshake) = match result { Some(record) => ( @@ -397,6 +419,8 @@ pub async fn get_tunnel_interface_details( None => (None, None, None), }; + info!("Fetched tunnel details for tunnel ID {tunnel_id}"); + Ok(LocationInterfaceDetails { location_id: tunnel_id, name: interface_name, @@ -425,6 +449,10 @@ pub async fn get_location_interface_details( let keys = WireguardKeys::find_by_instance_id(pool, location.instance_id) .await? .ok_or(Error::NotFound)?; + info!( + "Successfully fetched WireGuard keys for location {}", + location.name + ); let peer_pubkey = keys.pubkey; // generate interface name @@ -433,6 +461,7 @@ pub async fn get_location_interface_details( #[cfg(not(target_os = "macos"))] let interface_name = get_interface_name(&location.name); + debug!("Fetching location stats for location ID {location_id}"); let result = query!( r#" SELECT last_handshake, listen_port as "listen_port!: u32", @@ -444,6 +473,7 @@ pub async fn get_location_interface_details( ) .fetch_optional(pool) .await?; + info!("Fetched location stats for location ID {location_id}"); let (listen_port, persistent_keepalive_interval, last_handshake) = match result { Some(record) => ( @@ -454,6 +484,8 @@ pub async fn get_location_interface_details( None => (None, None, None), }; + info!("Fetched location details for location ID {location_id}"); + Ok(LocationInterfaceDetails { location_id, name: interface_name, @@ -509,6 +541,10 @@ pub async fn handle_connection_for_location( .lock() .map_err(|_| Error::MutexError)? .push(connection); + info!( + "Finished creating new interface connection for location: {}", + location.name + ); debug!( "Active connections: {:#?}", state @@ -516,24 +552,27 @@ pub async fn handle_connection_for_location( .lock() .map_err(|_| Error::MutexError)? ); - debug!("Sending event connection-changed."); + debug!("Sending event connection-changed..."); handle.emit_all( "connection-changed", Payload { message: "Created new connection".into(), }, )?; + debug!("Event connection-changed sent."); // Spawn stats threads - debug!("Spawning stats thread"); + debug!("Spawning stats thread..."); spawn_stats_thread( handle.clone(), interface_name.clone(), ConnectionType::Location, ) .await; + info!("Stats thread spawned."); // spawn log watcher + debug!("Spawning log watcher..."); spawn_log_watcher_task( handle, location.id.expect("Missing Location ID"), @@ -543,6 +582,7 @@ pub async fn handle_connection_for_location( None, ) .await?; + info!("Log watcher spawned."); Ok(()) } @@ -570,6 +610,10 @@ pub async fn handle_connection_for_tunnel(tunnel: &Tunnel, handle: AppHandle) -> .lock() .map_err(|_| Error::MutexError)? .push(connection); + info!( + "Finished creating new interface connection for tunnel: {}", + tunnel.name + ); debug!( "Active connections: {:#?}", state @@ -584,17 +628,20 @@ pub async fn handle_connection_for_tunnel(tunnel: &Tunnel, handle: AppHandle) -> message: "Created new connection".into(), }, )?; + debug!("Event connection-changed sent."); // Spawn stats threads - info!("Spawning stats thread"); + debug!("Spawning stats thread"); spawn_stats_thread( handle.clone(), interface_name.clone(), ConnectionType::Tunnel, ) .await; + info!("Stats thread spawned"); //spawn log watcher + debug!("Spawning log watcher"); spawn_log_watcher_task( handle, tunnel.id.expect("Missing Tunnel ID"), @@ -604,6 +651,7 @@ pub async fn handle_connection_for_tunnel(tunnel: &Tunnel, handle: AppHandle) -> None, ) .await?; + info!("Log watcher spawned"); Ok(()) } /// Execute command passed as argument.