Closed pokhiii closed 4 years ago
Hi @abhishek-pokhriyal,
If you have the Follow Up Emails
WooCommerce extension installed you need to either deactivate it or update to the latest version?
If you don't have that installed, could you provide a list of you active plugins?
Hi @rrennick,
Thank you for the super quick response. I am using the follow up emails plugin on my website. Could you tell me which version I should update to to get this issue fixed?
It looks like the latest version is 4.8.22 https://woocommerce.com/products/follow-up-emails/.
@rrennick that's the one installed on my site
Can you provide your list of active plugins? if not, try checking for conflicts https://docs.woocommerce.com/document/how-to-test-for-conflicts/
Hi @rrennick, sorry for the delay, I was checking with my hosting if the issue is still there or the plugin upgrade solved it. Unfortunately, the issue is still there. Here's the response:
I had a look at the request
/wp-admin/admin-ajax.php?action=as_async_request_queue_runner&nonce=
in the logs... for today so far. (that's midnight GMT+0 - 1:30pm GMT +0)/It looks like the requests are still occurring, and receiving 499 responses. Here are the responses it got and the amount:
41000 499 1 502
This means the issue is ongoing.
name | status | update | version |
---|---|---|---|
affiliate-wp | active | none | 2.4.3 |
affiliatewp-affiliate-area-tabs | active | none | 1.2.8 |
affiliatewp-affiliate-forms-gravity-forms | active | none | 1.0.20 |
classic-editor | active | none | 1.5 |
custom-meals-report | active | none | 1.0.0 |
facebook-for-woocommerce | active | none | 1.9.15 |
woocommerce-follow-up-emails | active | none | 4.8.22 |
free-gifts-for-woocommerce | active | none | 2.2 |
frontend-reports-for-woocommerce | active | none | 1.0.3 |
duracelltomi-google-tag-manager | active | none | 1.11.2 |
gravityforms | active | none | 1.9.16 |
jetpack | active | none | 8.1.1 |
mailchimp-for-woocommerce | active | none | 2.3.1 |
megafitmeals-enhanced-subscriptions | active | none | 1.0.0 |
cc-nutritional-values | active | none | 1.0 |
megafitmeals-shipment-calendar | active | none | 1.2.0 |
megafitmeals-woocommerce-customizations | active | none | 1.0.0 |
members | active | none | 2.2.0 |
hm-product-sales-report-pro | active | none | 2.1.13 |
quantity-field-on-shop-page-for-woocommerce | active | none | 1.1.0 |
resmushit-image-optimizer | active | none | 0.2.4 |
simple-author-box | active | none | 2.3.14 |
revslider | active | none | 5.4.8 |
theme-customisations-master | active | none | 1.0.0 |
tidio-live-chat | active | none | 4.2.1 |
toolbox-for-woocommerce-subscriptions | active | none | 1.4.13 |
under-construction-page | active | version higher than expected | 5.57 |
wck-custom-fields-and-custom-post-types-creator | active | none | 2.2.5 |
woocommerce | active | none | 3.9.0 |
woocommerce-gravityforms-product-addons | active | available | 2.10.5 |
woocommerce-shipstation | active | none | 4.1.27 |
woocommerce-admin | active | none | 0.24.0 |
woocommerce-bulk-stock-management | active | none | 2.2.20 |
woocommerce-auto-added-coupons | active | none | 3.1.2 |
woocommerce-shipping-fedex | active | available | 3.4.4 |
woocommerce-google-adwords-conversion-tracking-tag | active | none | 1.6.2 |
woocommerce-google-analytics-pro | active | none | 1.8.8 |
woocommerce-pdf-invoices-packing-slips | active | none | 2.4.3 |
woocommerce-product-stock-alert | active | none | 1.6.1 |
woocommerce-shipment-tracking | active | none | 1.6.18 |
woocommerce-gateway-stripe | active | none | 4.3.1 |
woocommerce-subscribe-all-the-things-master | active | none | 2.1.2-dev |
woocommerce-subscriptions | active | none | 3.0.1 |
woocommerce-subscriptions-do-not-reduce-stock-on-renewal-master | active | none | |
wordfence | active | none | 7.4.5 |
js_composer | active | none | 6.1 |
wp-crontrol | active | none | 1.7.1 |
wpmandrill | active | none | 1.33 |
amazon-s3-and-cloudfront | active | none | 2.3.2 |
wp-rocket | active | none | 3.4.4 |
wp-rocket-static-exclude-defer-js-master | active | none | |
wp-session-manager | active | none | 4.2.0 |
wpseo-woocommerce | active | none | 12.4.1 |
wordpress-seo-premium | active | none | 12.9.1 |
@rrennick don't want to distract you but getting a lot of these
[Sat Jan 25 20:35:42.932896 2020] [php7:notice] [pid 30028] WordPress database error Deadlock found when trying to get lock; try restarting transaction for query UPDATE wp_actionscheduler_actions SET attempts = attempts+1, status='in-progress', last_attempt_gmt = '2020-01-25 20:35:42', last_attempt_local = '2020-01-25 14:35:42' WHERE action_id = 1252046 / From [xyz/wp-admin/admin-ajax.php?action=as_async_request_queue_runner&nonce=907e5ba792] in [/nas/content/live/xyz/wp-content/plugins/woocommerce-subscriptions/includes/libraries/action-scheduler/classes/data-stores/ActionScheduler_DBStore.php:752] / made by do_action('wp_ajax_nopriv_as_async_request_queue_runner'), WP_Hook->do_action, WP_Hook->apply_filters, WP_Async_Request->maybe_handle, ActionScheduler_AsyncRequest_QueueRunner->handle, do_action('action_scheduler_run_queue'), WP_Hook->do_action, WP_Hook->apply_filters, ActionScheduler_QueueRunner->run, ActionScheduler_QueueRunner->do_batch, ActionScheduler_Abstract_QueueRunner->process_action, ActionScheduler_DBStore->log_execution, referer: my-domain/wp-admin/admin-ajax.php?action=as_async_request_queue_runner&nonce=907e5ba792
@rrennick we are facing real trouble since we upgraded our plugins. The customer being charged multiple times on renewals
@rrennick Thing like these. Not sure what is causing these. Please help.
Are you still seeing the Error saving action: Incorrect table name '' in /wp-content/plugins/woocommerce-subscriptions/includes/libraries/action-scheduler/classes/migration/ActionScheduler_DBStoreMigrator.php:44
?
For WordPress database error Deadlock found when trying to get lock
, try adding the following
add_filter( 'action_scheduler_async_request_sleep_seconds', function() { return 5; } );
@rrennick No, I'm seeing those error now but there are a lot of those Deadlock notices.
Is there something wrong, our customers are getting charged multiple times (67 times in one case) upon subscription renewal. We had dowgraded Subscriptions to 2.5.7 with the fear of this.
@rrennick Do you have any ideas what's happening here? Multiple payments being triggered, and errors like this
2020-01-25T10:08:27-05:00 ERROR Status transition of order #921880 errored!
2020-01-25T17:57:20+00:00 ERROR Status transition of subscription #844062 errored!
2020-01-25T18:56:18+00:00 ERROR Status transition of subscription #893704 errored!
Multiple payments being triggered
Based on the other messages you reported, that sounds like there may have been issues with marking the action as complete.
Since you have downgraded can you submit a support ticket through https://woocommerce.com/contact-us/ and include a link to this issue?
I've created a ticket on woocommerce. Do you think adding this can solve the multiple payment issue:
add_filter( 'action_scheduler_async_request_sleep_seconds', function() { return 5; } );
Seems like the woocommerce support will take some time to respond if you know the answer to the following query please let me know:
We were running WooCommerce v3.9
and Subscriptions v3.0.1
when we faced this issue with multiple renewals. We know have downgraded Subscriptions to v2.5.7
but `WooCommerce and other plugins are on their latest version. What will happen to a subscription that is renewed now? Will it be buggy and receive multiple paymnents?
I was going to suggest adding that for the deadlock issue until I saw that you had rolled back WCS. The async runner is only in WCS 3.0.X so the filter would have no effect in 2.5.7.
Any idea on the renewals? Will they suffer the same issue even in WCS 2.5.7.
The fact that customers are being charged multiple times is just making this issue worse. Not sure whether the renewals will be using the new action scheduler tables.
@rrennick so there was a subscription that was scheduled to be renewed to 10 minutes ago but nothing happened (no renewal order).
When you rolled back you paused the renewals because the renewal actions were migrated to the new datastore.
If possible, it would be great to leave it that way until we can determine whether or not you have duplicate actions or if the multiple charges were due to deadlocks preventing the action being marked as completed.
until we can determine whether or not you have duplicate actions or if the multiple charges were due to deadlocks preventing the action being marked as completed
@rrennick Please tell me how I can determine that.
@rrennick we are trying to replicate this on a staging environment however after automatical renewals my orders are stuck at Pending payment
. I think it's because automatic payment is disabled. Can you suggest me some way to bypass that?
Is your staging environment having the same error? If there are no pending actions you could create an order in the dashboard and that would cause an action to be created.
No, staging is not having that problem. We are trying to replicate on staging. Problems are coming only with subscription renewals.
How many rows are there in the actionscheduler_actions
table?
select count(*) from wp_actionscheduler_actions
result: 414219
i'm trying to replicate on staging, can you help?
if you would like to see more information, let me know.
i'm trying to replicate on staging, can you help?
Can you submit credentials for staging through the support portal?
Can you submit credentials for staging through the support portal?
How do I do that?
Use https://quickforget.com/ and send the URL it gives you in a reply to the support ticket email.
Done: here is my ticket https://woocommerce.com/my-account/tickets/?id=2663606
@rrennick Are you able to log in?
@rrennick If you would take a look, I can get you the credentials of the live site. The real issue is there.
I was able to log into staging. The repeat renewals appear to be due to the actions being created multiple times during the migration due to the deadlocks.
On the live site, in the DB, how many actionscheduler_actions
have a status
of pending?
select count(*) from wp_actionscheduler_actions where `status` = 'pending';
Gives me: 1042
Let's go more fine grained
select hook, count(*) from wp_actionscheduler_actions where `status` = 'pending' group by hook;
Here are the results:
sfn_followup_emails 603 sfn_send_usage_report 1 wc_admin_unsnooze_admin_notes 2 wcs_report_update_cache 5 woocommerce_scheduled_subscription_payment 431
Let's try this
SELECT
p.scheduled_date_gmt as pending_schedule,
c.scheduled_date_gmt as complete_schedule,
p.args
FROM wp_actionscheduler_actions p, wp_actionscheduler_actions c
WHERE p.`status` = 'pending'
AND p.hook = 'woocommerce_scheduled_subscription_payment'
AND c.hook = 'woocommerce_scheduled_subscription_payment'
AND p.args = c.args
ORDER BY p.action_id, c.action_id DESC
How close the dates are should indicate whether those renewals have already been processed.
pending_schedule | complete_schedule | args |
---|---|---|
2020-01-29 10:48:20 | 2020-01-29 10:48:20 | {"subscription_id":785736} |
2020-01-28 17:36:13 | 2020-01-28 17:36:13 | {"subscription_id":785725} |
2020-01-28 17:36:13 | 2020-01-17 16:53:51 | {"subscription_id":785725} |
2020-01-28 17:36:13 | 2020-01-28 17:36:13 | {"subscription_id":785723} |
2020-01-28 17:36:13 | 2020-01-17 16:37:46 | {"subscription_id":785723} |
2020-01-29 16:50:46 | 2020-01-29 16:50:46 | {"subscription_id":785711} |
2020-01-29 16:50:46 | 2020-01-15 15:57:35 | {"subscription_id":785711} |
2020-01-29 16:50:45 | 2020-01-29 16:50:45 | {"subscription_id":785709} |
2020-01-29 16:50:45 | 2020-01-15 15:50:42 | {"subscription_id":785709} |
2020-02-05 21:14:28 | 2020-02-05 21:14:28 | {"subscription_id":785929} |
2020-02-03 11:07:45 | 2020-02-03 11:07:45 | {"subscription_id":785955} |
2020-02-03 17:00:05 | 2020-02-03 17:00:05 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 17:00:00 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 16:42:00 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 16:30:59 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 16:00:00 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 15:05:00 | {"subscription_id":785937} |
2020-02-03 17:00:05 | 2020-01-27 14:40:00 | {"subscription_id":785937} |
@rrennick Are we reaching towards some conclusion? Let me know if you need to get access to a copy of a database or something? I can prepare that for you if that works better.
Assuming you have a backup you should be able to delete any of the ones that have exactly the same schedule:
2020-01-29 10:48:20 | 2020-01-29 10:48:20 | {"subscription_id":785736}
-- | -- | --
After those were removed you could weed the rest of them by comparing the times. Once those were cleaned up then you should be safe to add the filter in your comment above and try restoring WCS 3.0.1.
@rrennick Please confirm my understanding about your last comment:
Delete all the entries that came from running the following query
SELECT
p.scheduled_date_gmt as pending_schedule,
c.scheduled_date_gmt as complete_schedule,
p.args
FROM wp_actionscheduler_actions p, wp_actionscheduler_actions c
WHERE p.`status` = 'pending'
AND p.hook = 'woocommerce_scheduled_subscription_payment'
AND c.hook = 'woocommerce_scheduled_subscription_payment'
AND p.args = c.args
ORDER BY p.action_id, c.action_id DESC
After those were removed you could weed the rest of them by comparing the times.
Sorry, I didn't get how I'll do this part.
Then add this code to the functions.php
add_filter( 'action_scheduler_async_request_sleep_seconds', function() { return 5; } );
Then upgrade the WCS to 3.0.1
.
Final thing: Is this issue caused by Follow-Up plugins? There is a huge huge amount of entries in the wp_actionscheduler_actions table from follow up emails. If I enable follow-up again won't it happen again?
Sorry, I didn't get how I'll do this part.
If you deleted them all then that part is done.
Is this issue caused by Follow-Up plugins?
The missing table name in the original description was caused by the out of date FUE plugin. I would leave FUE deactivated initially, update WC Subscriptions, monitor the pending actions for more duplicates for a few minutes. If no duplicates show up in the first few minutes then activate FUE.
Hey @rrennick, sorry about not going away. I was about to start the cleanup process but I don't seem to understand what am I deleting.
SELECT
p.scheduled_date_gmt as pending_schedule,
c.scheduled_date_gmt as complete_schedule,
p.args
FROM wp_actionscheduler_actions p, wp_actionscheduler_actions c
WHERE p.`status` = 'pending'
AND p.hook = 'woocommerce_scheduled_subscription_payment'
AND c.hook = 'woocommerce_scheduled_subscription_payment'
AND p.args = c.args
ORDER BY p.action_id, c.action_id DESC
Some of the results returned by this are as follows. I do not understand what's wrong with themm. Are you sure all theses are to be deleted?
pending_schedule | complete_schedule | args |
---|---|---|
2020-01-27 01:46:07 | 2020-01-20 01:46:07 | {"subscription_id":859964} |
2020-01-27 01:46:07 | 2020-01-27 01:46:07 | {"subscription_id":859964} |
2020-01-27 02:26:12 | 2020-01-20 02:25:53 | {"subscription_id":860026} |
2020-01-27 02:26:12 | 2020-01-27 02:26:12 | {"subscription_id":860026} |
2020-01-27 02:44:10 | 2020-01-20 02:43:31 | {"subscription_id":860042} |
2020-01-27 02:44:10 | 2020-01-27 02:44:10 | {"subscription_id":860042} |
2020-01-27 02:50:10 | 2020-01-20 02:49:04 | {"subscription_id":860051} |
2020-01-27 02:50:10 | 2020-01-27 02:50:10 | {"subscription_id":860051} |
2020-01-27 03:04:09 | 2020-01-27 03:04:09 | {"subscription_id":907776} |
2020-01-27 03:17:18 | 2020-01-20 03:17:18 | {"subscription_id":860102} |
2020-01-27 03:17:18 | 2020-01-27 03:17:18 | {"subscription_id":860102} |
2020-01-27 04:06:39 | 2020-01-20 04:06:39 | {"subscription_id":860166} |
You want to delete the pending ones and leave the completed ones. You can see the pending ones in the dashboard screen and use the bulk action feature to delete the ones that you check.
Yes, that's the screen. If you combine the pending schedule with the args, you can pick out the ones to delete. Check the checkbox for those actions. Then use the bulk action dropdown to delete them.
okay, the only other problem is that I've 1322 rows returned by running the query. Do I need to manually check this or is there a better way?
SELECT
p.scheduled_date_gmt as pending_schedule,
c.scheduled_date_gmt as complete_schedule,
p.args
FROM wp_actionscheduler_actions p, wp_actionscheduler_actions c
WHERE p.`status` = 'pending'
AND p.hook = 'woocommerce_scheduled_subscription_payment'
AND c.hook = 'woocommerce_scheduled_subscription_payment'
AND p.args = c.args
ORDER BY p.action_id, c.action_id DESC
the only other problem is that I've 1322 rows returned
Quite a few of those are duplicating the pending action because there are multiple copies of the completed action. There isn't a way in MySQL to run a query to delete from a table where the table is joined to itself to find the rows. You might save time by re-running the search query after each bulk delete in the dashboard.