search

Automattic / woocommerce-subscriptions-core

Subscriptions core package for WooCommerce
Other
87 stars 32 forks source link

Renewal orders instantly marked as Processing due to possible cache issue #707

Open brnbs opened 1 month ago

brnbs commented 1 month ago

Describe the bug

When the wp-cron runs on our site to create renewal orders for subscriptions, there is an intermittent issue where renewal orders for subscriptions paid using manual payments are automatically marked as Processing without any payment being made. This occurs around once or twice a week.

This is a critical problem because we have automation that triggers invoice generation and other processes when an order is marked as Processing, but in these cases, no payment has been received.

We traced the issue to this line in the code: https://github.com/Automattic/woocommerce-subscriptions-core/blob/trunk/includes/class-wc-subscriptions-manager.php#L155

if ( 0 == $renewal_order->get_total() ) {
    $renewal_order->payment_complete(); // We don't need to reactivate the subscription here because calling payment complete on the order will do that for us.
} else {
    ...
}

It appears the get_total() method returns 0 for some orders, even though payments are still pending. We do not have any free subscriptions or free renewals on our site, so the order total should never be zero. When I check the given order later on the admin panel, the order total is not zero.

After adding logging, I suspect the issue is related to caching. Specifically, when logging the WC_Order instance, it appears that the order is missing crucial data such as the order total and billing fields. However, the order still contains order items and other meta fields. This points to a potential issue with how the data is cached. I have attached the full log for reference. renewal_order.log

We use the Redis Object Cache 2.5.4 plugin on our site. I replaced it with Object Cache Pro 1.21.2 (also using Redis), but the issue persists with both caching setups.

To Reproduce

I don’t have a consistent way to reproduce the issue as it occurs intermittently. However, the steps below outline the general process where the issue sometimes appears:

  1. Install and activate either Redis Object Cache or Object Cache Pro plugin.
  2. Schedule wp-cron to run automatic renewal jobs.
  3. Ensure there are active subscriptions with manual payment methods.
  4. Wait for renewal orders to be generated.
  5. Occasionally, a renewal order will be incorrectly marked as Processing without any payment being made.

Since this issue occurs randomly (about once or twice per week), it may require monitoring over time to observe the problem.

Expected behavior

I would expect the WooCommerce Subscriptions plugin to handle caching efficiently when creating renewal orders. Ideally, the order should be cleared from the cache before calling the get_total() method to ensure that the correct, updated value is returned, so the renewal order should only be marked as Processing after payment has been received.

Actual behavior

Some renewal orders for manual payment subscriptions are marked as Processing without any payment being made.

Product impact

Additional context

Wordpress 6.6.2 WooCommerce 9.3.3 WooCommerce Subscriptions 6.7.0 Redis Object Cache 2.5.4 Object Cache Pro 1.21.2

mattallan commented 1 week ago

Hi @brnbs, I've been looking into this issue with the goal of getting a fix into the next scheduled Subscriptions release but i'll need to investigate this a bit further. To confirm that this is a caching issue, could you please run the following code snippet on your store:

add_filter( 'wcs_renewal_order_created' , 'wcs_force_read_renewal_order_data', 500, 1 );
function wcs_force_read_renewal_order_data( $renewal_order ) {
    $renewal_order->get_data_store()->read( $renewal_order );
    return $renewal_order;
}

This hooks late onto the renewal order creation and forces the latest data to be read, right before the 0 == $renewal_order->get_total() check happens.

I'm not sure this is a caching issue though because the cache is cleared immediately after we copy the total from the subscription and then save the order. For instance:

  1. a blank renewal order is created with a 0 total,
  2. we copy the total from the subscription along with all other relevant data
  3. we then save the order

Saving the order should be clearing the cache and so even with object caching enabled, I'm not sure how it's passing the 0 == $renewal_order->get_total() later on. We also fetch a fresh copy of the order wc_get_order() after all of this.

If the above code snippet fixes your issues then I'll implement it into the plugin, but if this problem continues, are you able to share a screenshot of the Edit Order page for the manual renewal order that is being marked as processing as well as the Subscription that it belongs to? Thanks