add logging when subscription is suspended (#5430)

* add logging when subscription is suspended:
- because merchant or subscriber (or ?) changed status to on-hold
- because next payment date is 0

* add order (subscription) notes when sub is suspended +
+ use consistent past tense for logging and notes

* log and add order notes after suspending subscription

* add some extra checks that subscription is wcpay / non tokenised, log if incorrect

* use local wcpay sub id in log message + tidy log message (semicolon between values)

* changelong

* fix php unit tests:
- missing require Logger (doh!)
- update test_suspend_subscription mock subscription so it passes the new `is_wcpay_subscription` check

* fix / improve docblock comments:
- suspend executes a suspend on a given subscription
- handle_status handles a specific status transition

* fix temporary unhooking of on-hold status change handler:
- this PR decouples the handler from what it does, as suspend_subscription is used outside this context, and so we can log the status change explicitly
- this commit fixes the places we temporarily unhook the action to refer to new handler

* log a stack trace with suspend due to on-hold status

* clarify invoice.upcoming suspend note / log

Co-authored-by: Rua Haszard <[email protected]>

Author: haszari

changelog/fix-5429-log-suspend-subscription

@@ -0,0 +1,4 @@
+Significance: minor
+Type: add
+
+Add logging and order notes when WCPay Subscriptions are suspended or put on-hold.

includes/subscriptions/class-wc-payments-subscription-service.php

@@ -133,7 +133,7 @@ public function __construct(
 
 		add_action( 'woocommerce_subscription_status_cancelled', [ $this, 'cancel_subscription' ] );
 		add_action( 'woocommerce_subscription_status_expired', [ $this, 'cancel_subscription' ] );
-		add_action( 'woocommerce_subscription_status_on-hold', [ $this, 'suspend_subscription' ] );
+		add_action( 'woocommerce_subscription_status_on-hold', [ $this, 'handle_subscription_status_on_hold' ] );
 		add_action( 'woocommerce_subscription_status_pending-cancel', [ $this, 'set_pending_cancel_for_subscription' ] );
 		add_action( 'woocommerce_subscription_status_pending-cancel_to_active', [ $this, 'reactivate_subscription' ] );
 		add_action( 'woocommerce_subscription_status_on-hold_to_active', [ $this, 'reactivate_subscription' ] );
@@ -452,13 +452,59 @@ public function cancel_subscription( WC_Subscription $subscription ) {
 	}
 
 	/**
-	 * Suspends the WCPay subscription when a WC subscription is put on-hold.
+	 * Handle subscription status change to on-hold.
 	 *
-	 * @param WC_Subscription $subscription The WC subscription that was suspended.
+	 * @param WC_Subscription $subscription The WC subscription.
+	 *
+	 * @return void
+	 */
+	public function handle_subscription_status_on_hold( WC_Subscription $subscription ) {
+		// Check if the subscription is a WCPay subscription before proceeding.
+		// In stores that have WC Subscriptions active, or previously had WC S,
+		// this method may be called with regular tokenised subscriptions.
+		if ( ! $this->is_wcpay_subscription( $subscription ) ) {
+			return;
+		}
+
+		$this->suspend_subscription( $subscription );
+
+		// Add an order note as a visible record of suspend.
+		$subscription->add_order_note( __( 'Suspended WCPay Subscription because subscription status changed to on-hold.', 'woocommerce-payments' ) );
+
+		// Log that the subscription was suspended.
+		// Include a brief stack trace to help determine where status change originated.
+		// For example, admin user action, or a code interaction with customizations.
+		$e     = new Exception();
+		$trace = $e->getTraceAsString();
+		Logger::log(
+			sprintf(
+				'Suspended WCPay Subscription because subscription status changed to on-hold. WC ID: %d; WCPay ID: %s; stack: %s',
+				$subscription->get_id(),
+				self::get_wcpay_subscription_id( $subscription ),
+				$trace
+			)
+		);
+	}
+
+	/**
+	 * Suspends a WCPay subscription.
+	 *
+	 * @param WC_Subscription $subscription The WC subscription to suspend.
 	 *
 	 * @return void
 	 */
 	public function suspend_subscription( WC_Subscription $subscription ) {
+		// Check if the subscription is a WCPay subscription before proceeding.
+		if ( ! $this->is_wcpay_subscription( $subscription ) ) {
+			Logger::log(
+				sprintf(
+					'Aborting WC_Payments_Subscription_Service::suspend_subscription; subscription is a tokenised (non WCPay) subscription. WC ID: %d.',
+					$subscription->get_id()
+				)
+			);
+			return;
+		}
+
 		$this->update_subscription( $subscription, [ 'pause_collection' => [ 'behavior' => 'void' ] ] );
 	}
 

includes/subscriptions/class-wc-payments-subscriptions-event-handler.php

@@ -5,6 +5,7 @@
  * @package WooCommerce\Payments
  */
 
+use WCPay\Logger;
 use WCPay\Exceptions\Invalid_Webhook_Data_Exception;
 
 /**
@@ -72,6 +73,14 @@ public function handle_invoice_upcoming( array $body ) {
 				$this->subscription_service->cancel_subscription( $subscription );
 			} else {
 				$this->subscription_service->suspend_subscription( $subscription );
+				$subscription->add_order_note( __( 'Suspended WCPay Subscription in invoice.upcoming webhook handler because subscription next_payment date is 0.', 'woocommerce-payments' ) );
+				Logger::log(
+					sprintf(
+						'Suspended WCPay Subscription in invoice.upcoming webhook handler because subscription next_payment date is 0. WC ID: %d; WCPay ID: %s.',
+						$subscription->get_id(),
+						$wcpay_subscription_id
+					)
+				);
 			}
 		} else {
 			// Translators: %s Scheduled/upcoming payment date in Y-m-d H:i:s format.
@@ -124,9 +133,9 @@ public function handle_invoice_paid( array $body ) {
 			 * This ensures the downstream effects take place, e.g. a payment status order note is added and the
 			 * 'woocommerce_subscription_payment_complete' action is fired.
 			 */
-			remove_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'suspend_subscription' ] );
+			remove_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'handle_subscription_status_on_hold' ] );
 			$subscription->update_status( 'on-hold' );
-			add_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'suspend_subscription' ] );
+			add_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'handle_subscription_status_on_hold' ] );
 
 			/*
 			 * Remove the reactivate_subscription callback that occurs when a subscription transitions from on-hold to active.
@@ -190,9 +199,9 @@ public function handle_invoice_payment_failed( array $body ) {
 		$subscription->add_order_note( sprintf( _n( 'WCPay subscription renewal attempt %d failed.', 'WCPay subscription renewal attempt %d failed.', $attempts, 'woocommerce-payments' ), $attempts ) );
 
 		if ( self::MAX_RETRIES > $attempts ) {
-			remove_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'suspend_subscription' ] );
+			remove_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'handle_subscription_status_on_hold' ] );
 			$subscription->payment_failed();
-			add_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'suspend_subscription' ] );
+			add_action( 'woocommerce_subscription_status_on-hold', [ $this->subscription_service, 'handle_subscription_status_on_hold' ] );
 		} else {
 			$subscription->payment_failed( 'cancelled' );
 		}

tests/unit/subscriptions/test-class-wc-payments-subscription-service.php

@@ -340,6 +340,7 @@ public function test_suspend_subscription() {
 		$input_data                 = [ 'pause_collection' => [ 'behavior' => 'void' ] ];
 
 		$mock_subscription->update_meta_data( self::SUBSCRIPTION_ID_META_KEY, $mock_wcpay_subscription_id );
+		$mock_subscription->payment_method = 'woocommerce_payments';
 
 		$this->mock_api_client->expects( $this->once() )
 			->method( 'update_subscription' )