Fatal error on order save in PHP 7.0+

[khag7]

First, I'll say this is definitely a 3rd party plugin issue, however I think Action Scheduler could handle this scenario gracefully. Maybe there's a way to prevent a fatal error in this scenario.

Second, I want to say I don't understand why this is happening. Someone smarter than me might be able to shed some light on that.

Third, the issue is not consistent. It doesn't happen every time I save/update an order from the admin area. I did manage to find a way to reproduce it consistently, but it's not really a situation that would happen often.

In order to produce the error I'm seeing, one could do the following:

1. Clean install of WP
2. Install WooCommerce, activate and setup
3. Install a plugin that makes use of the Action Scheduler and has hooks for actions on a post save. A good example of this would be to install Mailchimp for Woocommerce or WooCommerce Admin. Do NOT yet activate this plugin.
4. Install a plugin which is incorrectly calling new WC_Order( $post_id ) instead of wc_get_order( $post_id ) and has that in a function which gets called on save_post. An example plugin is attached below. The plugin does absolutely nothing, but does call new WC_Order every time a shop_order is saved.
5. Create a new order and save it. Don't need to enter any info, just need a created and saved blank order.
6. Activate either Mailchimp for WooCommerce or the WooCommerce Admin plugin (or presumably any other plugin which makes use of Action Scheduler on the update of an order).
7. Go back to the order you created and update it. Don't need to change anything, just click update. This will call new WC_Order and the fatal error shown relates to Action Scheduler.

Now, I'm fully aware the easy answer to this is that its a 3rd party plugin not using wc_get_order when it should be. But how specifically is that causing Action Scheduler to fail? And is it possible to fail more gracefully? And why does it only happen right after the plugin is activated, and not consistently?

EXAMPLE of code that is poorly written but definitely does exist in the plethora of available WooCommerce plugins out there:

<?php
/*
Plugin Name: WooCommerce Save Order Bug
*/

add_action( 'save_post', function( $post_id ) {

	//set some early returns. we only want this to happen when saving a shop order 
	if ( defined( 'DOING_AUTOSAVE' ) && DOING_AUTOSAVE ) return;
	if ( ! isset( $_POST['post_type'] ) ) return;
	if ( 'shop_order' != $_POST['post_type'] ) return;
	if ( ! current_user_can( 'edit_post', $post_id ) ) return;

	//now we're presumably saving a shop order
	
	//lets create a WC_Order from this post_id
	$order = new WC_Order($post_id);
	
	//we don't even need to do anything with $order, the error will happen (or not)
	//but an example of something someone might be doing in this instance...
	//maybe we want to log every time one of our users saves an order
	//$order->add_order_note( "Order was updated by {$user_name}" );

});

[khag7]

Also I think it relates to this: https://github.com/woocommerce/woocommerce/issues/24593

[khag7]

And I was wrong above to assume it had to do with new WC_Order. Using wc_get_order instead and then trying to call a method on the returned order object still fails, but differently.

The snippet below would work fine on its own to add a comment every time an order saves, but if there exists a plugin like WooCommerce Admin or Mailchimp for Woocommerce that is making use of the Action Scheduler then saving the post can fail fatally.

add_action( 'save_post', function( $post_id ) {
	//set some early returns. we only want this to happen when saving a shop order 
	if ( defined( 'DOING_AUTOSAVE' ) && DOING_AUTOSAVE ) return;
	if ( ! isset( $_POST['post_type'] ) ) return;
	if ( 'shop_order' != $_POST['post_type'] ) return;
	if ( ! current_user_can( 'edit_post', $post_id ) ) return;

	//now we're presumably saving a shop order
	$order = wc_get_order( $post_id );
	$order->add_order_note( "Order was updated" );
});

[thenbrent]

Fatal error on order save

@khag7 what's the error message?

[khag7]

Hah, sorry, that would be helpful I suppose.

First, the errors I get on a production site, intermittently, not with every order save.

First this error is thrown in the WooCommerce Log: Status transition of order #10524 errored!

At the same time the WooCommerce Fatal Errors Log shows:

CRITICAL Uncaught RuntimeException: Error while saving action: Invalid order. in /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_wpPostStore.php:29
Stack trace:
#0 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_ActionFactory.php(109): ActionScheduler_wpPostStore->save_action(Object(ActionScheduler_Action))
#1 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_ActionFactory.php(59): ActionScheduler_ActionFactory->store(Object(ActionScheduler_Action))
#2 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/functions.php(18): ActionScheduler_ActionFactory->single('wc-admin_import...', Array, 1573587015, 'wc-admin-data')
#3 /wp-content/plugins/woocommerce/includes/queue/class-wc-action-queue.php(44): as_sc in /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_wpPostStore.php on line 29

Then a minute later when the queue runs, if WooCommerce Admin is installed:

CRITICAL Uncaught ArgumentCountError: Too few arguments to function Automattic\WooCommerce\Admin\ReportsSync::orders_lookup_import_order(), 0 passed in /wp-includes/class-wp-hook.php on line 286 and exactly 1 expected in /wp-content/plugins/woocommerce-admin/src/ReportsSync.php:462
Stack trace:
#0 /wp-includes/class-wp-hook.php(286): Automattic\WooCommerce\Admin\ReportsSync::orders_lookup_import_order()
#1 /wp-includes/class-wp-hook.php(310): WP_Hook->apply_filters('', Array)
#2 /wp-includes/plugin.php(531): WP_Hook->do_action(Array)
#3 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_Action.php(22): do_action_ref_array('wc-admin_import...', Array)
#4 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_Abstract_QueueRunner.php(59) in /wp-content/plugins/woocommerce-admin/src/ReportsSync.php on line 462

And a minute later when the queue runs, if Mailchimp for WooCommerce is installed:

CRITICAL Uncaught ArgumentCountError: Too few arguments to function MailChimp_Service::mailchimp_process_single_job(), 0 passed in /wp-includes/class-wp-hook.php on line 286 and exactly 1 expected in /wp-content/plugins/mailchimp-for-woocommerce/includes/class-mailchimp-woocommerce-service.php:806
Stack trace:
#0 /wp-includes/class-wp-hook.php(286): MailChimp_Service->mailchimp_process_single_job()
#1 /wp-includes/class-wp-hook.php(310): WP_Hook->apply_filters('', Array)
#2 /wp-includes/plugin.php(531): WP_Hook->do_action(Array)
#3 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_Action.php(22): do_action_ref_array('MailChimp_WooCo...', Array)
#4 /wp-content/plugins/woocommerce/includes/libraries/action-scheduler/classes/ActionScheduler_Abstract_QueueRunner.php(59): Act in /home/public_html/wp-content/plugins/mailchimp-for-woocommerce/includes/class-mailchimp-woocommerce-service.php on line 806

Lastly, this is the error I get on a test site just for solving this issue:

( ! ) Fatal error: Uncaught Error: Call to a member function add_order_note() on bool in C:\Users\Kevin\Local Sites\wcsaveorderbug\app\public\wp-content\plugins\woocommerce-save-order-bug.php on line 15
--

1 | 0.0001 | 411240 | {main}( ) | ...\post.php:0
2 | 0.3004 | 4684648 | edit_post( ) | ...\post.php:218
3 | 0.3027 | 4681904 | wp_update_post( ) | ...\post.php:405
4 | 0.3028 | 4687144 | wp_insert_post( ) | ...\post.php:4028
5 | 0.3112 | 4735976 | do_action( ) | ...\post.php:3951
6 | 0.3112 | 4736248 | WP_Hook->do_action( ) | ...\plugin.php:465
7 | 0.3112 | 4736248 | WP_Hook->apply_filters( ) | ...\class-wp-hook.php:310
8 | 0.4086 | 4990280 | Automattic\WooCommerce\Admin\ReportsSync::schedule_single_order_import( ) | ...\class-wp-hook.php:288
9 | 0.4093 | 4991128 | Automattic\WooCommerce\Admin\ReportsSync::queue_dependent_action( ) | ...\ReportsSync.php:318
10 | 0.4100 | 4991384 | WC_Action_Queue->schedule_single( ) | ...\ReportsSync.php:617
11 | 0.4100 | 4991384 | as_schedule_single_action( ) | ...\class-wc-action-queue.php:44
12 | 0.4100 | 4991384 | ActionScheduler_ActionFactory->single( ) | ...\functions.php:18
13 | 0.4101 | 4992096 | ActionScheduler_ActionFactory->store( ) | ...\ActionScheduler_ActionFactory.php:59
14 | 0.4101 | 4992096 | Automattic\WooCommerce\Admin\Overrides\WPPostStore->save_action( ) | ...\ActionScheduler_ActionFactory.php:109
15 | 0.4105 | 4993696 | Automattic\WooCommerce\Admin\Overrides\WPPostStore->save_post_array( ) | ...\ActionScheduler_wpPostStore.php:21
16 | 0.4105 | 4995728 | wp_insert_post( ) | ...\ActionScheduler_wpPostStore.php:52
17 | 0.4198 | 5004208 | do_action( ) | ...\post.php:3951
18 | 0.4198 | 5004480 | WP_Hook->do_action( ) | ...\plugin.php:465
19 | 0.4198 | 5004480 | WP_Hook->apply_filters( ) | ...\class-wp-hook.php:310
20 | 0.4198 | 5004776 | {closure:C:\Users\Kevin\Local Sites\wcsaveorderbug\app\public\wp-content\plugins\woocommerce-save-order-bug.php:6-18}( ) | ...\class-wp-hook.php:288

And the contents of woocommerce-save-order-bug.php is:

<?php
/*
Plugin Name: WooCommerce Save Order Bug
*/

add_action( 'save_post', function( $post_id ) {
	if ( defined( 'DOING_AUTOSAVE' ) && DOING_AUTOSAVE ) return;
	if ( ! isset( $_POST['post_type'] ) ) return;
	if ( 'shop_order' != $_POST['post_type'] ) return;
	if ( ! current_user_can( 'edit_post', $post_id ) ) return;

	//$order = new WC_Order($post_id);
	$order = wc_get_order( $post_id );
	
	$order->add_order_note( "Order was updated" );


});

Note the testing site has only WooCommerce, WooCommerce-Admin, and the plugin above installed.

[rrennick]

add_action( 'save_post', function( $post_id ) {

That hook runs on the save of any post (including a scheduled action if you are using 2.X of Action Scheduler.

	$order = wc_get_order( $post_id );
	if ( $order ) {
	$order->add_order_note( "Order was updated" );
        }

[khag7]

I agree that the hook I wrote is flawed. It doesn't check for proper information returned. But how does the hook above lead to an ArgumentCountError on ActionScheduler code and put entries into the WooCommerce log about failed actions? The hook I wrote shouldn't be able to cause that much damage, and the ActionScheduler should be able to do some kind of sanity check at some point to prevent that from happening.

[rrennick]

@khag7 When you save the order WC Admin creates a Scheduled Action to import the order. Creating the action also triggers the save_post hook which runs your hook against something that isn't an order causing the fatal error. With your original code you would trigger an error saving a page, post, product, etc. because save_post is triggered on any post type save.

[khag7]

I agree its an imperfect plugin. I think you're missing the forest for the trees here. A plugin which throws an error should not be able to completely derail Action Scheduler in this manner. In my specific case, one plugin which is firing with the save_post_shop_order hook used to work fine, only saving when shop_orders were saved, as implied by the hook name. And somehow on that site the Action Scheduler log is getting filled up with failed actions which continually get retried even though it is very clear to a human that the action can never work. There are certainly other plugins which are using save_post and not checking to see if they are being called by Action Scheduler or not. The point is, these plugins are out there, and although its not consistent, the Action Scheduler is allowing in some cases for invalid actions to be scheduled. I'm not sure it should allow that, it seems like a thing that could be checked for and handled gracefully. The plugin I provided is intentionally garbage. It is supposed to be an example of some other less-than-ideal coding that exists in the Wordpress Plugin ecosystem and will certainly be installed on other people's sites. Maybe if someone here who understands Action Scheduler more than I could reproduce the error and find out why Action Scheduler is creating invalid actions, they or we could help fix that.

[thenbrent]

The point is, these plugins are out there, and although its not consistent, the Action Scheduler is allowing in some cases for invalid actions to be scheduled.

Action Scheduler no longer uses custom post types as of 3.0 (currently in RC), so the save_post hook won't be triggered for actions, and this error wouldn't occur anymore.

somehow on that site the Action Scheduler log is getting filled up with failed actions which continually get retried even though it is very clear to a human that the action can never work.

The 3rd party code scheduling the action is most likely it on init whenever no pending action is found. If that's the case, then that code has explicitly requested actions continue to be scheduled and run even if there is a failure on a prior action. The code scheduling the action could choose to only reschedule an action after the previous action has run if it wants to halt processing for any fatal errors. It's decided it wants to run regardless though. Which most times, is the better option, because you never know when some errant plugin is going to release an update to fix a bug / conflict causing the failure.

A plugin which throws an error should not be able to completely derail Action Scheduler in this manner.

PHP provides no way to recover from a fatal error for the most part. What you are describing is inherent to open ecosystems based on PHP. One weak leak in the chain can take down the whole application.

If you meant an exception not an error, Action Scheduler could catch exceptions that occur during processing of actions, but it wouldn't know how to handle them, so it would effectively do the same thing it does now - mark the action as failed and log the exception so a human can investigate if it's a critical error.

I'm closing this now, but happy to reopen or investigate a specific issue with Action Scheduler on a separate Issue if you have one.

[khag7]

Action Scheduler no longer uses custom post types as of 3.0 (currently in RC), so the save_post hook won't be triggered for actions,

That makes this a non-issue. Thank you.

[rrennick]

Re-opening due to additional reports to add a trap for the error.

[barryhughes]

Brief précis of a chat with @rrennick on this:

• We're trapping and handling exceptions but not errors.
• When those errors occur, the queue runner stops (unlike with exceptions, we don't mark the scheduled action as failed and move on—so this has the potential to block the pipeline).
• A further bump to a minimum required PHP version of 7.0 could help us solve this cleanly.

Note there as a related report posted recently where this issue was a likely cause.

[peterfabian]

• [x] publish a dev advisory
• [ ] bump the min PHP version
• [ ] solve this problem

[wppunk]

Please, look at the register_shutdown_function function or shutdown hook before bumping the PHP minimal required version. Perhaps, it can cover the case more efficiently.

[barryhughes]

@wppunk—thanks for the idea. Can you go into a little more detail and sketch out how you see us utilizing the shutdown hook to handle this?

[wppunk]

@barryhughes If the problem is only in the error handling in PHP5.6, then it can be processed via a shutdown callback. Approximately it looks:

1. Register an error handler.
2. Before running a task, save all needed data and status (what to do if the task fails) in storage (DB, global state, sessions, etc.).
3. Read the status and needed data and complete/cancel/update/reschedule the task in the error handler callback.

[barryhughes]

That sounds like it may be viable, though I'm not understanding why it would be more efficient (given that processing of a batch of actions could still be brought to an abrupt halt).

Are you using Action Scheduler within a project where support for PHP 5.6 is still essential?

[wppunk]

@barryhughes I don't, but I think about other WordPress websites. AS is part of the most popular WordPress plugins that still support PHP5.6. Also, WordPress still supports PHP5.6.

I'm not sure that is an excellent point to bump requirements before WordPress does it. Despite the WooCommerce project being big and not keeping PHP5.6, the Top10 plugins with millions of active customers have customers with PHP5.6. Even 1% from 1 million it's 10 thousand websites.

So, bumping the PHP version can touch much more websites than you thought.

[barryhughes]

Yes: we're conscious of those sorts of factors though, of course, the situation is a bit more nuanced than those numbers suggest. For instance, the intersection of active installations running PHP 5.6 and those running the latest version of any given plugin is not necessarily in proportion to what we see when compared with PHP 7.2+.

Additionally, making a change to requirements in a future release does not automatically mean that other plugins need to adopt that release, if it is out of sync with their own requirements.

I take your point, though, and we'll pause before making a final call on this.

[ju1ius]

Hi, coming in from #833.

If the problem is only in the error handling in PHP5.6, then it can be processed via a shutdown callback.

1. Register an error handler.
2. Before running a task, save all needed data and status (what to do if the task fails) in storage (DB, global state, sessions, etc.).
3. Read the status and needed data and complete/cancel/update/reschedule the task in the error handler callback.

@wppunk Let me known if I'm missing something, but I think it can be solved in a much simpler way:

// in class ActionScheduler_Abstract_QueueRunner
public function process_action($action_id, $context = '') {
    set_error_handler(function ($type, $message) {
        // or any other exception that makes sense
        throw new \RuntimeException($message);
    }, E_USER_ERROR|E_RECOVERABLE_ERROR);
    try {
        $action = $this->process_action_without_error_handling($action_id, $context);
    } catch(\Throwable $e) {
        // catchall for PHP >= 7.0
        $this->handle_action_failure($action_id, $context);
    } catch(\Exception $e) {
        // BC layer for PHP 5.6
        $this->handle_action_failure($action_id, $context);
    } finally {
        restore_error_handler();
    }
    // maybe schedule next action
}

https://3v4l.org/c8ZnM

I fail to see why you would need to use register_shutdown_function() here...

Also, note that since OP seems to be running PHP 7+, the set_error_handler stuff is not even needed, so the code could simply be:

public function process_action($action_id, $context = '') {
    try {
        $action = $this->process_action_without_error_handling($action_id, $context);
    } catch(\Throwable $e) {
        // catchall for PHP >= 7.0
        $this->handle_action_failure($action_id, $context);
    } catch(\Exception $e) {
        // BC layer for PHP 5.6
        $this->handle_action_failure($action_id, $context);
    }
    // maybe schedule next action
}

https://3v4l.org/TQpGc

[barryhughes]

That looks like a nice approach: @ju1ius are you still interested in submitting a PR for this?