chore(service): add debug logging to receipt handling

Author: suchapalaver

crates/service/src/middleware/auth/tap.rs

@@ -55,21 +55,42 @@ where
 
         async move {
             let execute = || async {
-                let receipt = receipt.ok_or(IndexerServiceError::ReceiptNotFound)?;
+                let receipt = receipt.ok_or_else(|| {
+                    tracing::debug!(
+                        "TAP receipt validation failed: receipt not found in request extensions"
+                    );
+                    IndexerServiceError::ReceiptNotFound
+                })?;
+
+                let version = match &receipt {
+                    TapReceipt::V1(_) => "V1",
+                    TapReceipt::V2(_) => "V2",
+                };
+                tracing::debug!(receipt_version = version, "Starting TAP receipt validation");
+
                 // Verify the receipt and store it in the database
                 tap_manager
                     .verify_and_store_receipt(&ctx.unwrap_or_default(), receipt)
                     .await
-                    .inspect_err(|_| {
-                        if let Some(labels) = labels {
+                    .inspect_err(|err| {
+                        tracing::debug!(error = %err, receipt_version = version, "TAP receipt validation failed");
+                        if let Some(labels) = &labels {
                             failed_receipt_metric
                                 .with_label_values(&labels.get_labels())
                                 .inc()
                         }
                     })?;
+
+                tracing::debug!(
+                    receipt_version = version,
+                    "TAP receipt validation successful"
+                );
                 Ok::<_, IndexerServiceError>(request)
             };
-            execute().await.map_err(|error| error.into_response())
+            execute().await.map_err(|error| {
+                tracing::debug!(error = %error, "TAP authorization failed, returning HTTP error response");
+                error.into_response()
+            })
         }
     }
 }

crates/service/src/middleware/tap_receipt.rs

@@ -14,10 +14,21 @@ use crate::service::TapHeader;
 ///
 /// This is useful to not deserialize multiple times the same receipt
 pub async fn receipt_middleware(mut request: Request, next: Next) -> Response {
-    if let Ok(TypedHeader(TapHeader(receipt))) =
-        request.extract_parts::<TypedHeader<TapHeader>>().await
-    {
-        request.extensions_mut().insert(receipt);
+    match request.extract_parts::<TypedHeader<TapHeader>>().await {
+        Ok(TypedHeader(TapHeader(receipt))) => {
+            let version = match &receipt {
+                crate::tap::TapReceipt::V1(_) => "V1",
+                crate::tap::TapReceipt::V2(_) => "V2",
+            };
+            tracing::debug!(
+                receipt_version = version,
+                "TAP receipt extracted successfully"
+            );
+            request.extensions_mut().insert(receipt);
+        }
+        Err(e) => {
+            tracing::debug!(error = %e, "No TAP receipt found in request headers");
+        }
     }
     next.run(request).await
 }

crates/service/src/service/tap_receipt_header.rs

@@ -31,19 +31,40 @@ impl Header for TapHeader {
     {
         let mut execute = || -> anyhow::Result<TapHeader> {
             let raw_receipt = values.next().ok_or(headers::Error::invalid())?;
+            tracing::debug!(
+                raw_receipt_length = raw_receipt.len(),
+                "Processing TAP receipt header"
+            );
 
             // we first try to decode a v2 receipt since it's cheaper and fail earlier than using
             // serde
             match BASE64_STANDARD.decode(raw_receipt) {
                 Ok(raw_receipt) => {
-                    tracing::debug!("Decoded v2");
-                    let receipt = grpc::v2::SignedReceipt::decode(raw_receipt.as_ref())?;
-                    Ok(TapHeader(TapReceipt::V2(receipt.try_into()?)))
+                    tracing::debug!(
+                        decoded_length = raw_receipt.len(),
+                        "Successfully base64 decoded v2 receipt"
+                    );
+                    let receipt =
+                        grpc::v2::SignedReceipt::decode(raw_receipt.as_ref()).map_err(|e| {
+                            tracing::debug!(error = %e, "Failed to protobuf decode v2 receipt");
+                            e
+                        })?;
+                    tracing::debug!("Successfully protobuf decoded v2 receipt");
+                    let converted_receipt = receipt.try_into().map_err(|e: anyhow::Error| {
+                        tracing::debug!(error = %e, "Failed to convert v2 receipt");
+                        e
+                    })?;
+                    tracing::debug!("Successfully converted v2 receipt to TapReceipt::V2");
+                    Ok(TapHeader(TapReceipt::V2(converted_receipt)))
                 }
-                Err(_) => {
-                    tracing::debug!("Could not decode v2, trying v1");
+                Err(e) => {
+                    tracing::debug!(error = %e, "Could not base64 decode v2 receipt, trying v1");
                     let parsed_receipt: SignedReceipt =
-                        serde_json::from_slice(raw_receipt.as_ref())?;
+                        serde_json::from_slice(raw_receipt.as_ref()).map_err(|e| {
+                            tracing::debug!(error = %e, "Failed to JSON decode v1 receipt");
+                            e
+                        })?;
+                    tracing::debug!("Successfully decoded v1 receipt");
                     Ok(TapHeader(TapReceipt::V1(parsed_receipt)))
                 }
             }