From 9bbcbca1e2ed70032415cfb1bd081fb6c89522ab Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Mon, 8 Sep 2025 13:58:58 -0400 Subject: [PATCH] better logging --- .../stripe_artcraft_webhook_handler.rs | 29 ++++++++++++------- .../handle_webhook_event_enrichment.rs | 19 ++++++------ .../plugins/billing_artcraft/src/utils/mod.rs | 1 + .../src/utils/stripe_event_descriptor.rs | 24 +++++++++++++++ 4 files changed, 52 insertions(+), 21 deletions(-) create mode 100644 crates/service/plugins/billing_artcraft/src/utils/stripe_event_descriptor.rs diff --git a/crates/service/plugins/billing_artcraft/src/endpoints/webhook/stripe_artcraft_webhook_handler.rs b/crates/service/plugins/billing_artcraft/src/endpoints/webhook/stripe_artcraft_webhook_handler.rs index b6be10813b..b849f44ae3 100644 --- a/crates/service/plugins/billing_artcraft/src/endpoints/webhook/stripe_artcraft_webhook_handler.rs +++ b/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. diff --git a/crates/service/plugins/billing_artcraft/src/endpoints/webhook/webhook_event_enrichment/handle_webhook_event_enrichment.rs b/crates/service/plugins/billing_artcraft/src/endpoints/webhook/webhook_event_enrichment/handle_webhook_event_enrichment.rs index 00ed4a2dfb..a140d14800 100644 --- a/crates/service/plugins/billing_artcraft/src/endpoints/webhook/webhook_event_enrichment/handle_webhook_event_enrichment.rs +++ b/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 { 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 { diff --git a/crates/service/plugins/billing_artcraft/src/utils/mod.rs b/crates/service/plugins/billing_artcraft/src/utils/mod.rs index 837c3ddaee..c02140dc45 100644 --- a/crates/service/plugins/billing_artcraft/src/utils/mod.rs +++ b/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; \ No newline at end of file diff --git a/crates/service/plugins/billing_artcraft/src/utils/stripe_event_descriptor.rs b/crates/service/plugins/billing_artcraft/src/utils/stripe_event_descriptor.rs new file mode 100644 index 0000000000..93cd063f15 --- /dev/null +++ b/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) + } +}