better logging

crates/service/plugins/billing_artcraft/src/endpoints/webhook/stripe_artcraft_webhook_handler.rs

@@ -6,6 +6,7 @@ use crate::endpoints::webhook::common::enriched_webhook_event::EnrichedWebhookEv
 use crate::endpoints::webhook::common::stripe_artcraft_webhook_error::StripeArtcraftWebhookError;
 use crate::endpoints::webhook::webhook_event_enrichment::handle_webhook_event_enrichment::handle_webhook_event_enrichment;
 use crate::utils::artcraft_stripe_config::ArtcraftStripeConfigWithClient;
+use crate::utils::stripe_event_descriptor::StripeEventDescriptor;
 use crate::utils::verify_stripe_webhook_ip_address::verify_stripe_webhook_ip_address;
 use chrono::NaiveDateTime;
 use http_server_common::request::get_request_header_optional::get_request_header_optional;
@@ -18,6 +19,7 @@ use sqlx::pool::PoolConnection;
 use sqlx::{Acquire, MySql, MySqlConnection, MySqlPool, Transaction};
 use std::sync::Arc;
 use stripe_webhook::{Event, EventObject, Webhook};
+
 /*
 For one-off payments (eg. credits packs), we see this typical sequence of events:
 
@@ -86,9 +88,13 @@ pub async fn stripe_artcraft_webhook_handler(
   let stripe_event_created_at = NaiveDateTime::from_timestamp(webhook_payload.created, 0);
   let stripe_is_production = webhook_payload.livemode; // NB: Whether this was 'test' data or live data
 
-  info!("Stripe webhook event type: {} ({:?}); is production: {}, created at: {}, pending events to be handled: {}",
-    &stripe_event_type,
-    &webhook_payload.id,
+  let stripe_event_descriptor = StripeEventDescriptor {
+    stripe_event_id: stripe_event_id.clone(),
+    stripe_event_type: stripe_event_type.clone(),
+  };
+
+  info!("Stripe webhook event type: {} ; is production: {}, created at: {}, pending events to be handled: {}",
+    &stripe_event_descriptor,
     stripe_is_production,
     &stripe_event_created_at,
     webhook_payload.pending_webhooks);
@@ -104,7 +110,7 @@ pub async fn stripe_artcraft_webhook_handler(
   let maybe_previously_played_event = get_stripe_webhook_event_log_by_id_with_connection(&stripe_event_id, &mut mysql_connection)
       .await
       .map_err(|err| {
-        error!("Could not query previous event by ID ({}): {:?}", &stripe_event_id, err);
+        error!("Could not query previous event by ID ({}): {:?}", &stripe_event_descriptor, err);
         StripeArtcraftWebhookError::ServerError("database error".to_string())
       })?;
 
@@ -114,7 +120,7 @@ pub async fn stripe_artcraft_webhook_handler(
     // We'll ignore it so that we remain idempotent.
     if event.should_ignore_retry {
       warn!("Stripe is replaying event ID={} ; ignoring it since we have already previously handled it.",
-        &stripe_event_id);
+        &stripe_event_descriptor);
 
       return Ok(Json(StripeArtcraftWebhookSuccessResponse {
         success: true,
@@ -123,10 +129,10 @@ pub async fn stripe_artcraft_webhook_handler(
   }
 
   let enriched_event = handle_webhook_event_enrichment(
+    &stripe_event_descriptor,
     &stripe_config.client,
     **server_environment,
     webhook_payload,
-    &stripe_event_type,
   ).await?;
 
   let mut transaction = mysql_connection.begin().await?;
@@ -135,6 +141,7 @@ pub async fn stripe_artcraft_webhook_handler(
     **server_environment, 
     &stripe_config,
     enriched_event,
+    stripe_event_descriptor.clone(),
     stripe_event_id.clone(), 
     stripe_event_created_at, 
     stripe_event_type.clone(), 
@@ -147,9 +154,8 @@ pub async fn stripe_artcraft_webhook_handler(
       transaction.commit().await?;
     },
     Err(err) => {
-      error!("Error handling Stripe webhook event `{}` ({}): {:?}", 
-        stripe_event_type, 
-        stripe_event_id, 
+      error!("Error handling Stripe webhook event {} : {:?}", 
+        stripe_event_descriptor, 
         err);
 
       transaction.rollback().await?;
@@ -167,6 +173,7 @@ async fn process_enriched_event(
   server_environment: ServerEnvironment, 
   stripe_config: &ArtcraftStripeConfigWithClient, 
   artcraft_event: EnrichedWebhookEvent,
+  stripe_event_descriptor: StripeEventDescriptor,
   stripe_event_id: String, 
   stripe_event_created_at: NaiveDateTime, 
   stripe_event_type: String, 
@@ -175,7 +182,7 @@ async fn process_enriched_event(
 ) -> Result<(), StripeArtcraftWebhookError> {
 
   if let Some(billing_action) = &artcraft_event.maybe_billing_action {
-    info!("Billing action being taken for event type: {}", &stripe_event_type);
+    info!("Billing action being taken for event : {}", &stripe_event_descriptor);
     // This is where we fulfill the purchase, subscription, non-payment, etc.!
     // TODO: Maybe grab the primary key of the impacted entity?
     transactionally_fulfill_artcraft_billing_action(
@@ -183,7 +190,7 @@ async fn process_enriched_event(
       transaction,
     ).await?;
   } else {
-    info!("No billing action to take for event type: {}", &stripe_event_type);
+    info!("No billing action to take for event : {}", &stripe_event_descriptor);
   }
 
   // NB: These records are uniquely keyed by ID, so this only happens once.

crates/service/plugins/billing_artcraft/src/endpoints/webhook/webhook_event_enrichment/handle_webhook_event_enrichment.rs

@@ -9,6 +9,7 @@ use crate::endpoints::webhook::webhook_event_enrichment::ignore_known_unwanted_e
 use crate::endpoints::webhook::webhook_event_enrichment::invoice::invoice_paid_handler::invoice_paid_handler;
 use crate::endpoints::webhook::webhook_event_enrichment::invoice::invoice_payment_failed::invoice_payment_failed_handler;
 use crate::endpoints::webhook::webhook_event_enrichment::payment_intent::payment_intent_succeeded_extractor::payment_intent_succeeded_extractor;
+use crate::utils::stripe_event_descriptor::StripeEventDescriptor;
 use log::{info, warn};
 use reusable_types::server_environment::ServerEnvironment;
 use sqlx::pool::PoolConnection;
@@ -30,10 +31,10 @@ use stripe_webhook::{Event, EventObject};
 */
 
 pub async fn handle_webhook_event_enrichment(
+  stripe_event_descriptor: &StripeEventDescriptor,
   stripe_client: &Client,
   server_environment: ServerEnvironment,
   webhook_payload: Event,
-  stripe_event_type: &str,
 ) -> Result<EnrichedWebhookEvent, StripeArtcraftWebhookError> {
 
   if let Some(summary) = ignore_known_unwanted_events(&webhook_payload) {
@@ -61,7 +62,7 @@ pub async fn handle_webhook_event_enrichment(
       // `payment_intent.succeeded` is responsible for enabling one-off payments (eg. credits packs).
       // We'll ignore any payment intents from subscription invoices and let other event handlers
       // fulfill subscription states.
-      info!("Event: {}, data: {:?}", webhook_payload.type_, payment_intent);
+      info!("Event {}, data: {:?}", stripe_event_descriptor, payment_intent);
       return payment_intent_succeeded_extractor(
         &payment_intent,
         server_environment,
@@ -81,7 +82,7 @@ pub async fn handle_webhook_event_enrichment(
       // This can be used to upsert the subscription record, but may be `incomplete` and unpaid.
       // This is good for the overall subscription state, renewal dates, etc.
       //
-      info!("Event: {}, data: {:?}", webhook_payload.type_, subscription);
+      info!("Event: {}, data: {:?}", stripe_event_descriptor, subscription);
       return customer_subscription_created_handler(
         &subscription,
         server_environment,
@@ -89,7 +90,7 @@ pub async fn handle_webhook_event_enrichment(
     }
 
     EventObject::CustomerSubscriptionUpdated(subscription) => {
-      info!("Event: {}, data: {:?}", webhook_payload.type_, subscription);
+      info!("Event: {}, data: {:?}", stripe_event_descriptor, subscription);
       return customer_subscription_updated_handler(
         &subscription,
         server_environment,
@@ -97,7 +98,7 @@ pub async fn handle_webhook_event_enrichment(
     }
 
     EventObject::CustomerSubscriptionDeleted(subscription) => {
-      info!("Event: {}, data: {:?}", webhook_payload.type_, subscription);
+      info!("Event: {}, data: {:?}", stripe_event_descriptor, subscription);
       return customer_subscription_deleted_handler(
         &subscription,
         server_environment,
@@ -115,7 +116,7 @@ pub async fn handle_webhook_event_enrichment(
       // Invoices are for subscriptions, not one-off charges and purchases.
       // This is the *required* event that enables the subscription!
       // These are fired on an interval - whatever the billing cadence is.
-      info!("Event: {}, data: {:?}", webhook_payload.type_, invoice);
+      info!("Event: {}, data: {:?}", stripe_event_descriptor, invoice);
       return invoice_paid_handler(&invoice, server_environment, stripe_client).await;
     }
 
@@ -124,7 +125,7 @@ pub async fn handle_webhook_event_enrichment(
       // TODO: in wallet schema, hold a 'lifetime_total_credits_used' - no, that wastes space. `credits_used` then SUM() for reports
       // When we detect invoice payment failures, we need to disable
       // subscription services.
-      info!("Event: {}, data: {:?}", webhook_payload.type_, invoice);
+      info!("Event: {:?}, data: {:?}", stripe_event_descriptor, invoice);
       webhook_summary = invoice_payment_failed_handler(&invoice)?;
     }
     */
@@ -178,9 +179,7 @@ pub async fn handle_webhook_event_enrichment(
   // info!("event payload as json: {}", json);
 
   if unhandled_event_type {
-    warn!("Unhandled Stripe webhook event type: {} ({:?})",
-      &stripe_event_type,
-      &webhook_payload.type_);
+    warn!("Unhandled Stripe webhook event : {}", &stripe_event_descriptor);
   }
 
   Ok(EnrichedWebhookEvent {

crates/service/plugins/billing_artcraft/src/utils/mod.rs

@@ -3,4 +3,5 @@ pub mod artcraft_stripe_config;
 pub mod common_web_error;
 pub mod enum_conversion;
 pub mod expand_ids;
+pub mod stripe_event_descriptor;
 pub mod verify_stripe_webhook_ip_address;

crates/service/plugins/billing_artcraft/src/utils/stripe_event_descriptor.rs

@@ -0,0 +1,24 @@
+use std::fmt::{Debug, Display, Formatter};
+
+/// Convenience type for logging, error messages, etc.
+/// NB: `Debug` not derived.
+#[derive(Clone)]
+pub struct StripeEventDescriptor {
+  /// Stripe primary key for event, eg. `evt_1S592qEobp4xy4TljPApEJXe`
+  pub stripe_event_id: String,
+
+  /// Type of event, eg. `payment_intent.succeeded`
+  pub stripe_event_type: String,
+}
+
+impl Display for StripeEventDescriptor {
+  fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+    write!(f, "{} ({})", self.stripe_event_type, self.stripe_event_id)
+  }
+}
+
+impl Debug for StripeEventDescriptor {
+  fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+    write!(f, "{} ({})", self.stripe_event_type, self.stripe_event_id)
+  }
+}