Improve logging consistency and coherency

This commit implements comprehensive logging improvements to ensure coherent
and consistent HTTP request/response logging throughout the Keylime system.

Changes made:

1. Centralized HTTP Logging in ResilientClient:
   - Added consistent response code and header logging at DEBUG level
   - All HTTP requests now have uniform logging behavior across the codebase
   - Request headers already logged, now response headers match the same format

2. Fixed JSON Logging Issues:
   - Request JSON now logged as proper JSON string instead of Rust debug format
   - Changed from `{:?}` format to `serde_json::to_string()` for clean output
   - All JSON logging moved from INFO to DEBUG level for consistency
   - Added proper error handling for JSON serialization failures

3. Eliminated Duplicate Response Logging:
   - Removed redundant response body logging in state_machine.rs
   - Response information now logged exactly once per HTTP request
   - Maintained necessary response data for application logic

4. Enhanced URL Logging Context:
   - Added HTTP methods to URL logging (POST/PATCH)
   - Improved chronological order: Phase 1 logs negotiation URL, Phase 2 logs evidence URL
   - Made location header source explicit ("from 201 Created response")
   - Consistent format: "Purpose URL (METHOD): {url}"

5. Protocol Flow Clarity:
   - Capabilities negotiation URL logged in Phase 1 where it's used
   - Evidence handling URL logged in Phase 2 where it's used
   - Clear separation between configuration URLs and runtime URLs

The logging system now provides:
- Consistent DEBUG-level JSON and header logging
- No duplication of response information
- Clear chronological flow for the two-phase attestation protocol
- Centralized HTTP logging behavior via ResilientClient middleware

Co-Authored-By: Claude <[email protected]>
Signed-off-by: Sergio Arroutbi <[email protected]>

Author: 2 people

keylime-push-model-agent/src/attestation.rs

@@ -84,13 +84,16 @@ impl AttestationClient {
         config: &NegotiationConfig<'_>,
     ) -> Result<ResponseInformation> {
         info!("--- Phase 1: Sending Capabilities Negotiation ---");
+        info!("Capabilities negotiation URL (POST): {}", config.url);
         let mut context_info =
             context_info_handler::get_context_info(config.avoid_tpm)?;
         let mut filler =
             struct_filler::get_filler_request(context_info.as_mut());
 
         let req = filler.get_attestation_request();
-        debug!("Request body: {:?}", serde_json::to_string(&req));
+        if let Ok(json_str) = serde_json::to_string(&req) {
+            debug!("Request body: {}", json_str);
+        }
 
         let request_builder = self.client.get_json_request_from_struct(
             reqwest::Method::POST,
@@ -103,12 +106,10 @@ impl AttestationClient {
 
         let sc = response.status();
         let headers = response.headers().clone();
-        info!("Response code:{}", response.status());
-        info!("Response headers: {headers:?}");
 
         let response_body = response.text().await?;
         if !response_body.is_empty() {
-            info!("Response body: {response_body}");
+            debug!("Response body: {response_body}");
         }
 
         let rsp = ResponseInformation {
@@ -154,7 +155,7 @@ impl AttestationClient {
         }
 
         if !response_body.is_empty() {
-            info!("PATCH Response body: {response_body}");
+            debug!("PATCH Response body: {response_body}");
         }
 
         Ok(ResponseInformation {
@@ -194,9 +195,8 @@ impl AttestationClient {
             },
         );
 
-        info!("Config URL: {}", config.url);
-        info!("Location header: {location_header}");
-        info!("Sending evidence (PATCH) to: {patch_url}");
+        info!("Location header from 201 Created response: {location_header}");
+        info!("Evidence handling URL (PATCH): {patch_url}");
 
         // Use struct_filler to handle evidence collection and construction
         let mut context_info =

keylime-push-model-agent/src/state_machine.rs

@@ -179,7 +179,6 @@ impl<'a> StateMachine<'a> {
             Ok(res) => {
                 if res.status_code == reqwest::StatusCode::ACCEPTED {
                     info!("SUCCESS! Evidence accepted by the Verifier.");
-                    info!("Response body: {}", res.body);
 
                     // Extract seconds_to_next_attestation from verifier response.
                     let next_interval =

keylime/src/resilient_client.rs

@@ -45,7 +45,16 @@ impl Middleware for LoggingMiddleware {
         for (key, value) in req.headers() {
             debug!("  {key}: {value:?}");
         }
-        next.run(req, extensions).await
+
+        let response = next.run(req, extensions).await?;
+
+        debug!("Response code: {}", response.status());
+        debug!("Response headers:");
+        for (key, value) in response.headers() {
+            debug!("  {key}: {value:?}");
+        }
+
+        Ok(response)
     }
 }