chore(logs): improve log messages [NR-457551] (#1613)

* chore(logs): trace agent-control event-processor

* Instrument agent-control event-processor
* Remove redundant ids
* Add missing target_id for instance-id logs

* chore: add clarifying comment

* chore: improve naming

Author: sigilioso

agent-control/src/agent_control.rs

@@ -12,6 +12,7 @@ pub mod run;
 pub mod uptime_report;
 pub mod version_updater;
 
+use crate::agent_control::defaults::AGENT_CONTROL_ID;
 use crate::event::AgentControlInternalEvent;
 use crate::event::channel::EventPublisher;
 use crate::event::{
@@ -39,7 +40,7 @@ use opamp_client::StartedClient;
 use resource_cleaner::ResourceCleaner;
 use std::sync::Arc;
 use std::time::SystemTime;
-use tracing::{debug, error, info, instrument, trace, warn};
+use tracing::{debug, error, info, info_span, instrument, trace, warn};
 use uptime_report::UptimeReporter;
 use version_updater::updater::VersionUpdater;
 
@@ -121,6 +122,8 @@ where
     }
 
     pub fn run(self) -> Result<(), AgentError> {
+        let ac_startup_span = info_span!("start_agent_control", id = AGENT_CONTROL_ID);
+        let _ac_startup_span_guard = ac_startup_span.enter();
         info!("Starting the agents supervisor runtime");
         // This is a first-time run and we already read the config earlier, the `initial_config` contains
         // the result as read by the `AgentControlConfigLoader`.
@@ -178,6 +181,8 @@ where
             .inspect_err(|err| error!("Error executing Agent Control updater: {err}"));
 
         info!("Agents supervisor runtime successfully started");
+        drop(_ac_startup_span_guard); // The span representing agent start finishes before entering in the `process_events` loop. Otherwise the span would be open while Agent Control runs.
+
         self.process_events(running_sub_agents);
 
         if let Some(opamp_client) = self.opamp_client {
@@ -287,6 +292,8 @@ where
         loop {
             select! {
                 recv(&opamp_receiver.as_ref()) -> opamp_event_res => {
+                    let span = info_span!("process_fleet_event", id=AGENT_CONTROL_ID);
+                    let _span_guard = span.enter();
                     match opamp_event_res {
                         Err(_) => {
                             debug!("channel closed");
@@ -316,6 +323,8 @@ where
                     }
                 },
                 recv(&self.agent_control_internal_consumer.as_ref()) -> internal_event_res => {
+                    let span = info_span!("process_event", id=AGENT_CONTROL_ID);
+                    let _span_guard = span.enter();
                     match internal_event_res {
                         Err(err) => {
                             debug!("Error receiving Agent Control internal event {err}");
@@ -337,6 +346,8 @@ where
                     }
                 }
                 recv(self.application_event_consumer.as_ref()) -> _agent_control_event => {
+                    let span = info_span!("process_application_event", id=AGENT_CONTROL_ID);
+                    let _span_guard = span.enter();
                     debug!("stopping Agent Control event processor");
                     self.agent_control_publisher.broadcast(AgentControlEvent::AgentControlStopped);
                     break sub_agents.stop();
@@ -402,7 +413,6 @@ where
         }
     }
 
-    #[instrument(skip_all)]
     pub(super) fn validate_apply_store_remote_config(
         &self,
         opamp_remote_config: &OpampRemoteConfig,
@@ -488,7 +498,7 @@ where
 
             let apply_result = match current_dynamic_config.agents.get(agent_id) {
                 Some(old_sub_agent_config) if old_sub_agent_config == agent_config => {
-                    debug!(%agent_id, "Retaining the existing running SubAgent as its configuration remains unchanged");
+                    debug!(%agent_id, "Retaining the existing running SubAgent as its type remains unchanged");
                     Ok(())
                 }
                 Some(old_sub_agent_config) => {

agent-control/src/opamp/callbacks.rs

@@ -184,7 +184,7 @@ where
     }
 
     fn on_connect_failed(&self, err: ConnectionError) {
-        log_connection_error(&err, self.agent_id.clone());
+        log_connection_error(&err);
         self.publish_on_connect_failed(&err);
     }
 
@@ -219,44 +219,38 @@ where
     }
 
     fn get_effective_config(&self) -> Result<EffectiveConfig, Self::Error> {
-        debug!(
-            agent_id = %self.agent_id,
-            "OpAMP get effective config");
+        debug!("OpAMP get effective config");
 
         let effective_config = self
             .effective_config_loader
             .load()
             .map_err(EffectiveConfigError::Loader)?;
 
         // Not printing the effective config in case it contains sensitive info
-        debug!(
-            agent_id = %self.agent_id,
-            "OpAMP effective config loaded"
-        );
+        debug!("OpAMP effective config loaded");
 
         Ok(effective_config.into())
     }
 }
 
-fn log_connection_error(err: &ConnectionError, agent_id: AgentID) {
+fn log_connection_error(err: &ConnectionError) {
     // Check if the error comes from receiving an undesired HTTP status code
     if let HTTPClientError(UnsuccessfulResponse(http_code, http_reason)) = &err {
         let reason = match http_code {
-            400 => "The request was malformed",
-            401 => "Check for missing or invalid license key",
-            403 => "The account provided is not allowed to use this resource",
-            404 => "The requested resource was not found",
+            400 => "the request was malformed",
+            401 => "check for missing or invalid license key",
+            403 => "the account provided is not allowed to use this resource",
+            404 => "the requested resource was not found",
             415 => "Content-Type or Content-Encoding for the HTTP request was wrong",
-            500 => "Server-side problem",
-            _ => "Reasons unknown",
+            500 => "server-side problem",
+            _ => "unknown",
         };
-        error!(%agent_id, http_code, http_reason, reason,"OpAMP HTTP connection error");
-    } else {
         error!(
-            %agent_id,
-            reason = err.to_string(),
-            "OpAMP HTTP connection error"
-        )
+            http_code,
+            http_reason, "OpAMP HTTP connection error: {reason}"
+        );
+    } else {
+        error!("OpAMP HTTP connection error: {err}")
     }
 }
 

agent-control/src/opamp/instance_id/getter.rs

@@ -63,7 +63,7 @@ where
 {
     fn get(&self, agent_id: &AgentID) -> Result<InstanceID, GetterError> {
         let storer = self.storer.lock().expect("failed to acquire the lock");
-        debug!("retrieving instance id");
+        debug!(target_agent_id = %agent_id, "retrieving instance id");
         let data = storer.get(agent_id)?;
 
         match data {
@@ -72,8 +72,8 @@ where
             }
             Some(d) if d.identifiers == self.identifiers => return Ok(d.instance_id),
             Some(d) => debug!(
-                "stored data had different identifiers {:?}!={:?}",
-                d.identifiers, self.identifiers
+                target_agent_id = %agent_id,
+                "stored data had different identifiers {:?}!={:?}", d.identifiers, self.identifiers
             ),
         }
 
@@ -82,7 +82,7 @@ where
             identifiers: self.identifiers.clone(),
         };
 
-        debug!("persisting instance id {}", new_data.instance_id);
+        debug!(target_agent_id = %agent_id, "persisting instance id {}", new_data.instance_id);
         storer.set(agent_id, &new_data)?;
 
         Ok(new_data.instance_id)