Getting this error thrown out every minute. Any ideas on how to solve this?

[gekinz]

Stack trace:
#0 /public_html/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php(437): WC_Vipps_Recurring_Api->handle_http_response(Array, '{"status":"STOP...', 'recurring/v2/ag...', '')
#1 /public_html/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php(221): WC_Vipps_Recurring_Api->http_call('recurring/v2/ag...', 'PATCH', Array, Array)
#2 /public_html/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-gateway-vipps-recurring.php(1232): WC_Vipps_Recurring_Api->cancel_agreement('agr_2sA22Px')
#3 /public_html/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/woo-vipps-recurring in /public_html/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php on line 533

[Marcuzz]

Hi,

This doesn't seem to be the entire stacktrace, do you have any more context to this error? :)

[magnuskl]

Here is a similar and more recent PHP log entry, including stack trace, which I suspect stems from the same error:

2023-05-24T17:43:10+00:00 CRITICAL Uncaught WC_Vipps_Recurring_Exception: Bad Request Illegal update in /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php:499
Stack trace:
#0 /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php(354): WC_Vipps_Recurring_Api->handle_http_response()
#1 /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php(154): WC_Vipps_Recurring_Api->http_call()
#2 /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-gateway-vipps-recurring.php(1204): WC_Vipps_Recurring_Api->cancel_agreement()
#3 /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/woo-vipps-recurring.php(756): WC_Gateway_Vipps_Recurring->maybe_process_gateway_change()
#4 /var/www/wp-includes/class-wp-hook.php(308): WC_Vipps_Recurring->check_gateway_change_agreement_statuses()
#5 /var/www/wp-includes/class-wp-hook.php(332): WP_Hook->apply_filters()
#6 /var/www/wp-includes/plugin.php(565): WP_Hook->do_action()
#7 /var/www/wp-cron.php(188): do_action_ref_array()
#8 {main}
  thrown i /var/www/wp-content/plugins/vipps-recurring-payments-gateway-for-woocommerce/includes/wc-vipps-recurring-api.php på linje 499

In this case, maybe_process_gateway_change(), running every minute through the action scheduler, gets stuck attempting to stop an agreement that has already been stopped. See also the corresponding Vipps Recurring log entry:

2023-05-24T17:43:10+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.0 ====
==== Start Log ====
HTTP Response Error (400): Bad Request Illegal update (recurring/v3/agreements/agr_4GbkAKb) with request body: {"status":"STOPPED"}. The response was: {"type":"https:\/\/vippsas.github.io\/vipps-developer-docs\/docs\/APIs\/recurring-api\/vipps-recurring-api-problems#illegal-agreement-update","title":"Bad Request","status":400,"detail":"Illegal update","instance":"\/vipps-recurring-merchant-api\/v3\/agreements\/agr_4GbkAKb","contextId":"35f6c1a2-f288-4615-9315-a9a8f0b0ae60","extraDetails":[{"status":"Cannot modify an agreement which is not active."}]}
==== End Log ====

[magnuskl]

Another problem occurs when old_agreement_id is empty. Here are the relevant Vipps Recurring log entries:

2023-05-24T18:36:49+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.0 ====
==== Start Log ====
[531080] Processing subscription gateway change with new agreement id: agr_sSftwaC and old agreement id: 
==== End Log ====

2023-05-24T18:36:49+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.0 ====
==== Start Log ====
[531080] Subscription gateway change completed
==== End Log ====

No PHP error is produced, but maybe_process_gateway_change() gets stuck in the action scheduler in like manner.

[magnuskl]

I have solved these problems by manually updating the concerned subscriptions. @Marcuzz: You may want to look into why cancel_agreement() is called on old_agreement_id when the variable refers to an agreement that has already been stopped or when the variable is empty.

[Marcuzz]

Hmm... good catch. I will look into this.

I suspect it might happen when a customer is swapping from another payment gateway. Do you have multiple payment gateways available @magnuskl?

[magnuskl]

Indeed. In addition to Vipps, we use Stripe and PayPal. All instances that I discovered involved a change of payment method, but at least one instance involved merely changing “from Vipps to Vipps”, as WooCommerce noted.

[Marcuzz]

Another problem occurs when old_agreement_id is empty. Here are the relevant Vipps Recurring log entries:

2023-05-24T18:36:49+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.0 ====
==== Start Log ====
[531080] Processing subscription gateway change with new agreement id: agr_sSftwaC and old agreement id: 
==== End Log ====

2023-05-24T18:36:49+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.0 ====
==== Start Log ====
[531080] Subscription gateway change completed
==== End Log ====

No PHP error is produced, but maybe_process_gateway_change() gets stuck in the action scheduler in like manner.

It looks like this is a non-issue as the code block that attempts to cancel an agreement is already skipped when there is no old agreement id. If it was not skipped we would also see a log message with the following:

[%s] Cancelling old agreement id: %s in Vipps due to gateway change

However, there is definitely a problem where it tries to cancel an already cancelled agreement. I now suspect it happens when customers swap from Vipps to Vipps on an old subscription that has already been cancelled once. I think it's possible to 'resume' an agreement you've previously cancelled in some instances.

So what I'll do is I'll make sure to check the current status of each agreement in cancel_agreement before attempting to stop an agreement. I'll release a patch version with c592f897688c649e46bb90f055f996ee6d9b85aa in it shortly :)

[Marcuzz]

@magnuskl Please try version 1.15.2 😄

[magnuskl]

I have put version 1.15.2 in production. I will keep an eye on the logs and let you know if there are any issues.

[magnuskl]

It seems that the problem is still lingering. Today another subscription got stuck in the action scheduler. Here are the relevant Vipps Recurring log entries, repeating every minute:

2023-06-21T13:12:17+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.2 ====
==== Start Log ====
[508556] Processing subscription gateway change with new agreement id: agr_EefhgPa and old agreement id: 
==== End Log ====

2023-06-21T13:12:17+00:00 DEBUG 
==== Vipps Recurring Version: 1.15.2 ====
==== Start Log ====
[508556] Subscription gateway change completed
==== End Log ====

In this case, the customer wanted to pay a failed renewal order manually. First, he switched from PayPal to Vipps, creating but not confirming a new agreement, that is, agr_EefhgPa. Then, he changed his mind and switched from Vipps to Stripe, successfully paying the order.

[Marcuzz]

Hi,

Does this mean that the message "Subscription gateway change completed" is spammed repeatedly for order 508556?

[magnuskl]

Indeed. Just to be clear: 508556 is the subscription, not the order. Looking at the subscription notes, the roll must be several hundred meters long :laughing:

[Marcuzz]

I'm not sure why I didn't reply to this issue when the issue was fixed. This should've been fixed on 25th of August in this commit: 2ee4ab2e72d70a554468aa2eef4ae2f37e5601a1 (plugin version 1.16.4)

Apologies for somehow forgetting to reply here 😮

[magnuskl]

No worries. Thank you for fixing the issue!