action-scheduler-high-volume icon indicating copy to clipboard operation
action-scheduler-high-volume copied to clipboard

Since enabling ASHV, `woocommerce_payment_complete` processing chain fails to execute an otherwise normally working filter

Open lkraav opened this issue 6 years ago • 8 comments

Traceback https://sentry.io/share/issue/beaf5527005d44719cbe5664ecc16414/

If you could peek at "plugins/woocommerce-freshbooks/includes/class-wc-freshbooks-handler.php in auto_create_invoice at line 148" there's a custom apply_filters( 'wc_freshbooks_auto_create_invoices', true, $order ) call for a platform plugin to determine whether this invoice should be auto-created.

Since enabling ASHV, renewal payments are failing to trigger this filter. New transactions work fine. It's like during ASHV processing, our platform plugin is not getting loaded at all, which is otherwise initialized via add_action( 'plugins_loaded', 'cxli', 11 ); singleton instantiation call, and I was thinking whether ASHV could somehow be short-circuiting things for performance.

Any thoughts here? I think I will go look for a constant of some kind to identify an AS queue run, and inject another traceback trigger to see what the platform plugin loading state is during ASHV execution. Better ideas would be much appreciated :+1:

lkraav avatar Jan 18 '19 04:01 lkraav

which is otherwise initialized via add_action( 'plugins_loaded', 'cxli', 11 );

Hrm, is it possible that plugin/priority is the issue?

I find it unlikely, but because ASHV initiates additional queues via admin ajax endpoints, perhaps what is happening is that the additional runners are being created before 'plugins_loaded' with that priority?

I'd be surprised, because 'plugins_loaded' happening after 'wp_ajax_nopriv_ would make it hard for a lot of other things, but that's the best guess I've got.

To help with debugging, you could also install the Disable plugin, if you haven't already, because then you can be sure all queues are being run via ashp_create_additional_runners().

thenbrent avatar Jan 18 '19 04:01 thenbrent

... because ASHV initiates additional queues via admin ajax endpoints

To help with debugging, you could also install the Disable plugin, if you haven't already, because then you can be sure all queues are being run via ashp_create_additional_runners().

Hm, if my cron is WP-CLI-only, is there a way to not go through admin-ajax at all? Is it a requirement or just an implementation option?

I installed ASHV to see what the difference is when investigating the rogue blank webhooks getting created and renewal jobs piling up in the queue (really looking forward to 3.5.4).

Everything otherwise seems to behave, except this one execution path.

lkraav avatar Jan 18 '19 16:01 lkraav

How can I tell if I'm in a AS-backed job? I'm not sure action_scheduler_before_process_queue is only visible to the main CLI process, and everything launched via admin-ajax is oblivious (I'm not getting expected sentry events, OR as discussed above, my platform plugin just isn't loaded by the time job is executed):

...

public function __construct() {
    if ( did_action( 'action_scheduler_before_process_queue' ) ) {
        \WP_Sentry_Php_Tracker::get_instance()->get_client()->captureMessage( __FUNCTION__, [], [], true );
    }

    ...
}

lkraav avatar Jan 18 '19 19:01 lkraav

if my cron is WP-CLI-only, is there a way to not go through admin-ajax at all?

I you're cron is WP CLI only, I'd recommend making your Action Scheduler WP CLI only too (the Disable plugin shared above helps with that).

The admin ajax calls are only sent on the WP Cron hook. So they won't be sent.

Everything otherwise seems to behave, except this one execution path.

IIRC, WP Cron happens on an odd hook. I can't remember exactly, but it might be init with default priority 10 or something, so sometimes that can lead to unexpected execution paths too.

How can I tell if I'm in a AS-backed job? I'm not sure action_scheduler_before_process_queue is only visible to the main CLI process

That hook is called by ActionScheduler_WPCLI_QueueRunner::run(), so it should be fine to use. I suspect your __construct() method is occurring before ActionScheduler_WPCLI_QueueRunner::run() though and did_action() is returning false.

thenbrent avatar Jan 21 '19 00:01 thenbrent

I you're cron is WP CLI only, I'd recommend making your [Action Scheduler WP CLI only]https://actionscheduler.org/wp-cli/) too (the Disable plugin shared above helps with that).

I agree, it's time. Posting my action item plan for validity check:

  • install + activate https://github.com/Prospress/action-scheduler-disable-default-runner
  • add a new wp action-scheduler run crontab item

BEFORE

*/5 * * * * /usr/local/bin/php /usr/local/bin/wp --path=$HOME/www cron event run --due-now > /dev/null 2>&1

AFTER

*/5 * * * * /usr/local/bin/php /usr/local/bin/wp --path=$HOME/www cron event run --due-now > /dev/null 2>&1
*/5 * * * * /usr/local/bin/php /usr/local/bin/wp --path=$HOME/www action-scheduler run > /dev/null 2>&1

lkraav avatar Jan 21 '19 15:01 lkraav

LGTM thus far. Removed piping to null at first, to monitor.

Found 5 scheduled tasks
Started processing action 995787
Completed processing action 995787
Warning: Attempting to reduce used memory...
Started processing action 995788
Completed processing action 995788
Warning: Attempting to reduce used memory...
Started processing action 995789
Completed processing action 995789
Warning: Attempting to reduce used memory...
Started processing action 995790
Completed processing action 995790
Warning: Attempting to reduce used memory...
Started processing action 995791
Completed processing action 995791
Warning: Attempting to reduce used memory...
1 batch executed.
Success: 0 scheduled tasks completed.

Would be nice to get some additional information in console output, such as executed hook name.

lkraav avatar Jan 21 '19 16:01 lkraav

Would be nice to get some additional information in console output, such as executed hook name.

Agreed.

Posting my action item plan for validity check:

That looks valid. 👍

Can you confirm everything is working now?

If so, I suspect the issue related to load order with admin ajax hooks and/or WP Cron.

thenbrent avatar Jan 22 '19 00:01 thenbrent

After some travel and monitoring a few days, I'm fairly certain that my plugin loads correctly only when ASHV is disabled.

Fortunately, with migrating AS to pure CLI runner, and WC 3.5.4 released, it looks like the regular runner is doing just fine.

Of course, scientific curiosity about why ASHV would cause misbehavior, is still there.. just not enough time to chase it immediately.

lkraav avatar Jan 28 '19 20:01 lkraav