Improve logging of failed subscription scheduled actions

[james-allan]

Description

In WC 8.6, WC core change the logger to have new features that enable you to store additional context about an error and for that to be viewable in the log file itself.

This PR updates our WCS_Failed_Scheduled_Action_Manager to make use of those features. As part of this update I've also updated what is logged to better assist with narrowing down the cause of these issues.

How to test this PR

Setup

1. Go to your database wp_actionscheduler_actions table
2. Find a pending scheduled woocommerce_scheduled_subscription_payment action
3. Manually edit the action and set the date to be in the past (eg just change the year to 2023).
   • This will make it easier to test and will use Action Scheduler's queue rather than having to run the actions manually.
4. Add the following code snippet to assist with testing various scenarios.

add_action( 'woocommerce_scheduled_subscription_payment', 'test_trigger_failure' );
add_action( 'woocommerce_scheduled_subscription_payment', 'trigger_wc_exceptions', 1 );

function test_trigger_failure() {
    $error_type = 'timeout';
    //$error_type = 'fatal';
    //$error_type = 'error';
    //$error_type = 'exception';

    switch ( $error_type ) {
        case 'timeout':
            // An hard exit will trigger the action to eventually timeout.
            exit;
            break;
        case 'error':
            undefined_function();
            break;
        case 'fatal':
            // Fatal error
            // Note: Fatal errors are caught and thrown as exceptions so you'd need to disable the AS error handler in the `process_action` method to see the fatal error.
            trigger_error( 'This is a fatal error', E_USER_ERROR );
            break;
        case 'exception':
            // Exception
            throw new Exception( 'This is an exception' );
            break;
    }
}

function trigger_wc_exceptions() {
    //return; // Uncomment to disable this function.

    // Change the number of exceptions to trigger. Default is 2.
    foreach ( range( 1, 2 ) as $exception_number ) {
        wc_caught_exception( new Exception( 'Oopsy ' . $exception_number ) );
    }
}

Timeouts

1. With the code above running, set your scheduled action to pending and refresh any admin page.
2. Action Scheduler should start processing the action and it should appear as in-progress in the database.
3. Wait 5 minutes ⏲️
4. View the failed-scheduled-actions log in WooComemrce > Status > Logs
5. You should see an error like this:

Errors

1. Optional. Delete the failed-scheduled-actions file if you want to keep things tidy.
2. Uncomment the $error_type = 'error' line.
3. Set your testing scheduled action to pending and refresh any admin page.
4. Action Scheduler should start processing the action and it should appear as in-progress in the database.
5. View the failed-scheduled-actions log in WooComemrce > Status > Logs
6. You should see an error like this:

^{Full stack traces are now included for errors like this.}

6. View the scheduled action in the Tools > Scheduled action screen and you'll see the exceptions that were caught by WC will also be logged there.

Uncaught Exceptions

1. Optional. Delete the failed-scheduled-actions file if you want to keep things tidy.
2. Uncomment the $error_type = 'exception' line.
3. Set your testing scheduled action to pending and refresh any admin page.
4. Action Scheduler should start processing the action and it should appear as in-progress in the database.
5. View the failed-scheduled-actions log in WooComemrce > Status > Logs
6. You should see an error like this:

Fatal errors

[!note] Action Scheduler overrides the default error handler when processing actions (see this code in: ActionScheduler_Abstract_QueueRunner::process_action()). This error handler catches all errors and converts them into exceptions. This means I was never able to test the action_scheduler_unexpected_shutdown approach, because it never shut down - every error (including the undefined function error) is caught and treated as an exception. Our WCS_Failed_Scheduled_Action_Manager has code which handles unexpected shutdowns so we want to confirm that still works just incase there's a type of error that bypasses AS's error handler.

1. Comment out Action Scheduler's error handler in ActionScheduler_Abstract_QueueRunner::process_action()).
2. Optional. Delete the failed-scheduled-actions file if you want to keep things tidy.
3. Uncomment the $error_type = 'fatal' line.
4. Set your testing scheduled action to pending and refresh any admin page.
5. Action Scheduler should start processing the action and it should appear as in-progress in the database.
6. View the failed-scheduled-actions log in WooComemrce > Status > Logs
7. You should see an error like this:

^{We don't get a full stack here unfortunately because the shutdown handlers just passes us the last error from `get_last_error()` and it only includes line and file information.}

Product impact

• [x] Added changelog entry (or does not apply)
• [ ] Will this PR affect WooCommerce Subscriptions? yes/no/tbc, add issue ref
• [ ] Will this PR affect WooCommerce Payments? yes/no/tbc, add issue ref
• [ ] Added deprecated functions, hooks or classes to the spreadsheet

[james-allan]

In WC 8.6, WC core change the logger to have new features

I've also tested on 8.5.2 (WC old logger) and these changes work consistant with how it worked in the past. ie additional context is logged as separate entries.

[james-allan]

I also wanted to highlight that as part of these changes I've also improved the main error message that is logged.

Previously we would just log this:

...failed to finish processing due to the following exception: This is a fatal error 

We now log the file and line information

... failed to finish processing due to the following exception: This is a fatal error in /public/wp-content/plugins/woocommerce/packages/action-scheduler/classes/abstracts/ActionScheduler_Abstract_QueueRunner.php:63 

In this case, its not particularly helpful because it points to AS as that's where the exception was created. For exceptions its more accurate. I'm going to file an issue on AS to see if they could use ErrorException instead.