fix: lower verbosity of routine logs in library crates

Library crates should not emit info! for routine, repeating operations;
that floods the default logs of the final consumer, which owns the
verbosity decision. Reserve info! for rare connection/session lifecycle
milestones, debug! for significant one-off events, and trace! for the
fine-grained detail only needed when nothing else explains a problem.

Author: CBenoit

crates/ironrdp-cliprdr/src/lib.rs

@@ -20,7 +20,7 @@ use pdu::{
     FileContentsResponse, FileDescriptor, FormatDataRequest, FormatListResponse, LockDataId, OwnedFormatDataResponse,
     PackedFileList,
 };
-use tracing::{debug, error, info, trace, warn};
+use tracing::{debug, error, trace, warn};
 
 #[rustfmt::skip] // do not reorder
 use crate::pdu::FormatList;
@@ -620,11 +620,11 @@ impl<R: Role> Cliprdr<R> {
             FormatListResponse::Ok => {
                 if !R::is_server() {
                     if self.state == CliprdrState::Initialization {
-                        info!("Clipboard virtual channel initialized");
+                        debug!("Clipboard virtual channel initialized");
                         self.state = CliprdrState::Ready;
                         self.backend.on_ready();
                     } else {
-                        info!("Remote accepted format list");
+                        trace!("Remote accepted format list");
                     }
                 }
                 self.backend.on_format_list_response(true);
@@ -640,7 +640,7 @@ impl<R: Role> Cliprdr<R> {
                 self.local_drop_effect_format_id = None;
 
                 if !self.sent_file_contents_requests.is_empty() {
-                    info!(
+                    debug!(
                         count = self.sent_file_contents_requests.len(),
                         "Clearing pending file contents requests due to FormatListResponse::Fail"
                     );
@@ -664,7 +664,7 @@ impl<R: Role> Cliprdr<R> {
 
     fn handle_format_list(&mut self, format_list: FormatList<'_>) -> PduResult<Vec<SvcMessage>> {
         if R::is_server() && self.state == CliprdrState::Initialization {
-            info!("Clipboard virtual channel initialized");
+            debug!("Clipboard virtual channel initialized");
             self.state = CliprdrState::Ready;
             self.backend.on_ready();
         }
@@ -740,7 +740,7 @@ impl<R: Role> Cliprdr<R> {
         if let Some(format) = file_list_format {
             // Store the format ID for later use when user initiates paste
             self.remote_file_list_format_id = Some(format.id);
-            info!(format_id = ?format.id, "FileGroupDescriptorW format available in FormatList");
+            trace!(format_id = ?format.id, "FileGroupDescriptorW format available in FormatList");
         }
 
         // [MS-RDPECLIP] 3.1.5.2.2 - Acknowledge the FormatList before any
@@ -830,7 +830,7 @@ impl<R: Role> Cliprdr<R> {
         } else {
             match self.state {
                 CliprdrState::Ready => {
-                    info!("User initiated copy, sending format list");
+                    trace!("User initiated copy, sending format list");
                     pdus.push(ClipboardPdu::FormatList(
                         self.build_format_list(available_formats).map_err(|e| encode_err!(e))?,
                     ));
@@ -863,7 +863,7 @@ impl<R: Role> Cliprdr<R> {
         self.pending_format_data_request = Some(requested_format);
 
         if Some(requested_format) == self.remote_file_list_format_id {
-            info!(format_id = ?requested_format, "User initiated paste for FileGroupDescriptorW");
+            trace!(format_id = ?requested_format, "User initiated paste for FileGroupDescriptorW");
         }
 
         let pdu = ClipboardPdu::FormatDataRequest(FormatDataRequest {
@@ -972,7 +972,7 @@ impl<R: Role> Cliprdr<R> {
         self.outgoing_locks.insert(clip_data_id, lock);
         self.current_lock_id = Some(clip_data_id);
 
-        info!(clip_data_id, "Sent clipboard lock");
+        trace!(clip_data_id, "Sent clipboard lock");
 
         let pdu = ClipboardPdu::LockData(LockDataId(clip_data_id));
         Some(vec![into_cliprdr_message(pdu)])
@@ -1015,7 +1015,7 @@ impl<R: Role> Cliprdr<R> {
         self.current_lock_id = None;
 
         if !newly_expired.is_empty() {
-            info!(
+            debug!(
                 count = newly_expired.len(),
                 inactivity_timeout_secs = self.lock_inactivity_timeout.as_secs(),
                 max_lifetime_secs = self.lock_max_lifetime.as_secs(),
@@ -1052,7 +1052,7 @@ impl<R: Role> Cliprdr<R> {
         self.outgoing_locks.clear();
         self.current_lock_id = None;
 
-        info!(
+        debug!(
             count = cleared.len(),
             "Releasing outgoing locks before taking clipboard ownership"
         );
@@ -1159,7 +1159,7 @@ impl<R: Role> Cliprdr<R> {
 
         // Log cleanup summary
         if !expired_ids.is_empty() {
-            info!(
+            debug!(
                 count = expired_ids.len(),
                 clip_data_ids = ?expired_ids,
                 "Automatic lock cleanup completed"
@@ -1202,7 +1202,7 @@ impl<R: Role> Cliprdr<R> {
         }
 
         if !stale_stream_ids.is_empty() {
-            info!(
+            debug!(
                 count = stale_stream_ids.len(),
                 "Stale file contents request cleanup completed"
             );
@@ -1230,7 +1230,7 @@ impl<R: Role> Cliprdr<R> {
         }
 
         if !stale_lock_ids.is_empty() {
-            info!(count = stale_lock_ids.len(), "Upload inactivity cleanup completed");
+            debug!(count = stale_lock_ids.len(), "Upload inactivity cleanup completed");
         }
 
         Ok(messages.into())
@@ -1529,7 +1529,7 @@ impl<R: Role> Cliprdr<R> {
             .collect();
 
         if validated_files.len() < original_count {
-            info!(
+            debug!(
                 total = original_count,
                 valid = validated_files.len(),
                 "File list validation completed with warnings"
@@ -1632,7 +1632,7 @@ impl<R: Role> SvcProcessor for Cliprdr<R> {
                 }
 
                 if let Some(ref file_list) = self.local_file_list {
-                    info!(clip_data_id = id.0, "Locking clipboard with file list snapshot");
+                    debug!(clip_data_id = id.0, "Locking clipboard with file list snapshot");
                     self.locked_file_lists.insert(id.0, file_list.clone());
                     self.locked_file_list_activity.insert(id.0, self.backend.now_ms());
                 } else {
@@ -1652,7 +1652,7 @@ impl<R: Role> SvcProcessor for Cliprdr<R> {
                 // Release the file list snapshot associated with this clipDataId.
                 if self.locked_file_lists.remove(&id.0).is_some() {
                     self.locked_file_list_activity.remove(&id.0);
-                    info!(
+                    debug!(
                         clip_data_id = id.0,
                         "Unlocking clipboard and releasing file list snapshot"
                     );
@@ -1681,7 +1681,7 @@ impl<R: Role> SvcProcessor for Cliprdr<R> {
                 if Some(request.format) == self.local_file_list_format_id {
                     if let Some(ref file_list) = self.local_file_list {
                         // Respond with the stored file list
-                        info!(
+                        debug!(
                             format_id = ?request.format,
                             file_count = file_list.files.len(),
                             "Responding to FileGroupDescriptorW request with stored file list"
@@ -1752,7 +1752,7 @@ impl<R: Role> SvcProcessor for Cliprdr<R> {
                                     }
                                 }
 
-                                info!(
+                                debug!(
                                     file_count = file_list.files.len(),
                                     "Received FileGroupDescriptorW from remote"
                                 );

crates/ironrdp-dvc-com-plugin/src/channel.rs

@@ -16,7 +16,7 @@ use ironrdp_core::impl_as_any;
 use ironrdp_dvc::{DvcClientProcessor, DvcMessage, DvcProcessor};
 use ironrdp_pdu::{PduResult, pdu_other_err};
 use ironrdp_svc::SvcMessage;
-use tracing::{debug, error, info, warn};
+use tracing::{debug, error, trace, warn};
 use windows::Win32::System::LibraryLoader::{GetProcAddress, LoadLibraryW};
 use windows::Win32::System::RemoteDesktop::{IWTSListenerCallback, IWTSPlugin, IWTSVirtualChannelManager};
 use windows::core::{HRESULT, PCSTR, PCWSTR};
@@ -62,7 +62,7 @@ impl DvcProcessor for DvcComChannel {
     }
 
     fn start(&mut self, channel_id: u32) -> PduResult<Vec<DvcMessage>> {
-        info!(
+        debug!(
             channel_name = %self.channel_name,
             channel_id,
             "DVC COM channel start"
@@ -92,7 +92,7 @@ impl DvcProcessor for DvcComChannel {
         let accepted = accept_rx.recv().unwrap_or(false);
 
         if accepted {
-            info!(
+            debug!(
                 channel_name = %self.channel_name,
                 channel_id,
                 "COM plugin accepted DVC channel"
@@ -164,7 +164,7 @@ pub fn load_dvc_plugin<F>(dll_path: &Path, on_write_dvc_factory: F) -> PduResult
 where
     F: Fn() -> OnWriteDvcMessage + Send + Sync + 'static,
 {
-    info!(dll = %dll_path.display(), "Loading DVC COM plugin");
+    debug!(dll = %dll_path.display(), "Loading DVC COM plugin");
 
     // Channel for sending commands to the COM worker thread
     let (command_tx, command_rx) = std_mpsc::channel();
@@ -185,7 +185,7 @@ where
             match initialize_plugin_on_thread(&dll_path_owned) {
                 Ok((plugin, manager, listeners)) => {
                     let channel_names: Vec<String> = listeners.keys().cloned().collect();
-                    info!(
+                    debug!(
                         channels = ?channel_names,
                         "Plugin initialized, registered {} listener(s)",
                         channel_names.len()
@@ -256,7 +256,7 @@ fn initialize_plugin_on_thread(
     // SAFETY: loading the DLL into this process
     let hmodule = unsafe { LoadLibraryW(dll_path_pcwstr) }.map_err(|e| format!("LoadLibraryW failed: {e}"))?;
 
-    info!(dll = %dll_path.display(), "DLL loaded successfully");
+    trace!(dll = %dll_path.display(), "DLL loaded successfully");
 
     // Get the VirtualChannelGetInstance export
     let proc_name = PCSTR::from_raw(c"VirtualChannelGetInstance".as_ptr().cast::<u8>());
@@ -268,7 +268,7 @@ fn initialize_plugin_on_thread(
     // SAFETY: transmuting the function pointer; we trust the DLL follows the documented API
     let get_instance: VirtualChannelGetInstanceFn = unsafe { core::mem::transmute(proc_addr) };
 
-    info!("VirtualChannelGetInstance export found");
+    trace!("VirtualChannelGetInstance export found");
 
     // Phase 1: query the number of plugin objects
     let iid = IWTSPlugin::IID;
@@ -283,7 +283,7 @@ fn initialize_plugin_on_thread(
         ));
     }
 
-    info!(count = num_objs, "Plugin reports {} object(s)", num_objs);
+    trace!(count = num_objs, "Plugin reports {} object(s)", num_objs);
 
     if num_objs == 0 {
         return Err("plugin returned 0 objects".to_owned());
@@ -311,7 +311,7 @@ fn initialize_plugin_on_thread(
     // SAFETY: the plugin pointer is a valid IWTSPlugin COM interface pointer
     let plugin: IWTSPlugin = unsafe { IWTSPlugin::from_raw(plugin_ptr) };
 
-    info!("Got IWTSPlugin COM object");
+    trace!("Got IWTSPlugin COM object");
 
     // Create shared state for listeners: we keep an Rc clone so we can read the
     // map after Initialize() without needing an unsafe cast from the COM pointer.
@@ -322,7 +322,7 @@ fn initialize_plugin_on_thread(
     // SAFETY: calling IWTSPlugin::Initialize with our channel manager
     unsafe { plugin.Initialize(&manager) }.map_err(|e| format!("IWTSPlugin::Initialize failed: {e}"))?;
 
-    info!("IWTSPlugin::Initialize succeeded");
+    trace!("IWTSPlugin::Initialize succeeded");
 
     // Read the listener map that the plugin populated during Initialize.
     let listeners: HashMap<String, IWTSListenerCallback> = listeners_rc.borrow().clone();

crates/ironrdp-dvc-com-plugin/src/worker.rs

@@ -7,7 +7,7 @@
 use std::collections::HashMap;
 use std::sync::mpsc as std_mpsc;
 
-use tracing::{debug, error, info, trace, warn};
+use tracing::{debug, error, trace, warn};
 use windows::Win32::System::RemoteDesktop::{
     IWTSListenerCallback, IWTSPlugin, IWTSVirtualChannel, IWTSVirtualChannelCallback, IWTSVirtualChannelManager,
 };
@@ -50,7 +50,7 @@ pub(crate) fn run_com_worker(
     command_rx: std_mpsc::Receiver<ComCommand>,
     on_write_dvc_rx: std_mpsc::Receiver<OnWriteDvc>,
 ) {
-    info!("COM worker thread started");
+    debug!("COM worker thread started");
 
     let mut active_channels: HashMap<u32, ActiveChannel> = HashMap::new();
 
@@ -129,7 +129,7 @@ pub(crate) fn run_com_worker(
                 match result {
                     Ok(()) if accept.as_bool() => {
                         if let Some(callback) = channel_callback {
-                            info!(channel_name = %channel_name, channel_id, "Plugin accepted DVC channel");
+                            debug!(channel_name = %channel_name, channel_id, "Plugin accepted DVC channel");
                             active_channels.insert(
                                 channel_id,
                                 ActiveChannel {
@@ -187,7 +187,7 @@ pub(crate) fn run_com_worker(
             }
 
             ComCommand::Shutdown => {
-                info!("Shutting down COM plugin");
+                debug!("Shutting down COM plugin");
 
                 // Close all active channels
                 for (channel_id, active) in active_channels.drain() {
@@ -216,5 +216,5 @@ pub(crate) fn run_com_worker(
         }
     }
 
-    info!("COM worker thread exiting");
+    debug!("COM worker thread exiting");
 }

crates/ironrdp-dvc-pipe-proxy/src/platform/unix.rs

@@ -1,7 +1,7 @@
 use async_trait::async_trait;
 use tokio::fs;
 use tokio::io::{AsyncReadExt as _, AsyncWriteExt as _};
-use tracing::{info, trace};
+use tracing::{debug, trace};
 
 use crate::error::DvcPipeProxyError;
 use crate::os_pipe::OsPipe;
@@ -19,7 +19,7 @@ impl OsPipe for UnixPipe {
             Ok(metadata) => {
                 use std::os::unix::fs::FileTypeExt as _;
 
-                info!(
+                debug!(
                     %pipe_name,
                     "DVC pipe already exists, removing stale file."
                 );

crates/ironrdp-dvc-pipe-proxy/src/proxy.rs

@@ -4,7 +4,7 @@ use ironrdp_core::impl_as_any;
 use ironrdp_dvc::{DvcClientProcessor, DvcMessage, DvcProcessor};
 use ironrdp_pdu::{PduResult, pdu_other_err};
 use ironrdp_svc::SvcMessage;
-use tracing::{debug, info};
+use tracing::debug;
 
 use crate::worker::{OnWriteDvcMessage, WorkerCtx, run_worker};
 
@@ -49,7 +49,7 @@ impl DvcProcessor for DvcNamedPipeProxy {
     }
 
     fn start(&mut self, channel_id: u32) -> PduResult<Vec<DvcMessage>> {
-        info!(%self.channel_name, %self.named_pipe_name, "Starting DVC named pipe proxy");
+        debug!(%self.channel_name, %self.named_pipe_name, "Starting DVC named pipe proxy");
 
         let on_write_dvc = self
             .dvc_write_callback