From 70bbe09c1add50fbc1e74dc497b3efe2c1259ebe Mon Sep 17 00:00:00 2001 From: Brent Shepherd Date: Fri, 12 Jul 2019 13:58:07 +1000 Subject: [PATCH] Add context to action processing So that we can log where the action was run from, e.g. WP CLI, WP Cron the Admin List Table or the upcoming Async Runner. Very handy for debugging issues after the fact. Fixes #129 --- ...tionScheduler_AsyncRequest_QueueRunner.php | 2 +- classes/ActionScheduler_ListTable.php | 2 +- classes/ActionScheduler_QueueRunner.php | 45 ++++++++++++++++--- .../ActionScheduler_WPCLI_QueueRunner.php | 2 +- .../ActionScheduler_Abstract_QueueRunner.php | 16 ++++--- classes/abstracts/ActionScheduler_Logger.php | 42 ++++++++++++----- docs/faq.md | 2 +- .../ActionScheduler_wpCommentLogger_Test.php | 14 +++--- .../ActionScheduler_QueueRunner_Test.php | 2 +- 9 files changed, 92 insertions(+), 35 deletions(-) diff --git a/classes/ActionScheduler_AsyncRequest_QueueRunner.php b/classes/ActionScheduler_AsyncRequest_QueueRunner.php index ca8f81bfa..df52a5a25 100644 --- a/classes/ActionScheduler_AsyncRequest_QueueRunner.php +++ b/classes/ActionScheduler_AsyncRequest_QueueRunner.php @@ -49,7 +49,7 @@ public function __construct( ActionScheduler_Store $store ) { * if there are still pending actions after completing a queue in this request. */ protected function handle() { - do_action( 'action_scheduler_run_queue' ); // run a queue in the exact same way as WP Cron + do_action( 'action_scheduler_run_queue', 'Async Request' ); // run a queue in the same way as WP Cron, but declare the Async Request context $this->maybe_dispatch(); } diff --git a/classes/ActionScheduler_ListTable.php b/classes/ActionScheduler_ListTable.php index c99a63fe5..27d0db428 100644 --- a/classes/ActionScheduler_ListTable.php +++ b/classes/ActionScheduler_ListTable.php @@ -458,7 +458,7 @@ protected function process_row_action( $action_id, $row_action_type ) { try { switch ( $row_action_type ) { case 'run' : - $this->runner->process_action( $action_id ); + $this->runner->process_action( $action_id, 'Admin List Table' ); break; case 'cancel' : $this->store->cancel_action( $action_id ); diff --git a/classes/ActionScheduler_QueueRunner.php b/classes/ActionScheduler_QueueRunner.php index 1c247c572..9c1ad5b64 100644 --- a/classes/ActionScheduler_QueueRunner.php +++ b/classes/ActionScheduler_QueueRunner.php @@ -46,9 +46,18 @@ public function init() { add_filter( 'cron_schedules', array( self::instance(), 'add_wp_cron_schedule' ) ); - if ( !wp_next_scheduled(self::WP_CRON_HOOK) ) { + $cron_context = array( 'WP Cron' ); + + if ( ! wp_next_scheduled( self::WP_CRON_HOOK, $cron_context ) ) { + + // Check for and remove any WP Cron hook scheduled by Action Scheduler < 3.0.0, which didn't include the $context param + $next_timestamp = wp_next_scheduled( self::WP_CRON_HOOK ); + if ( $next_timestamp ) { + wp_unschedule_event( $next_timestamp, self::WP_CRON_HOOK ); + } + $schedule = apply_filters( 'action_scheduler_run_schedule', self::WP_CRON_SCHEDULE ); - wp_schedule_event( time(), $schedule, self::WP_CRON_HOOK ); + wp_schedule_event( time(), $schedule, self::WP_CRON_HOOK, $cron_context ); } add_action( self::WP_CRON_HOOK, array( self::instance(), 'run' ) ); @@ -82,7 +91,20 @@ public function maybe_dispatch_async_request() { } } - public function run() { + /** + * Process actions in the queue. Attached to self::WP_CRON_HOOK i.e. 'action_scheduler_run_queue' + * + * The $context param of this method defaults to 'WP Cron', because prior to Action Scheduler 3.0.0 + * that was the only context in which this method was run, and the self::WP_CRON_HOOK hook had no context + * passed along with it. New code calling this method directly, or by triggering the self::WP_CRON_HOOK, + * should set a context as the first parameter. For an example of this, refer to the code seen in + * @see ActionScheduler_AsyncRequest_QueueRunner::handle() + * + * @param string $context Optional identifer for the context in which this action is being processed, e.g. 'WP CLI' or 'WP Cron' + * Generally, this should be capitalised and not localised as it's a proper noun. + * @return int The number of actions processed. + */ + public function run( $context = 'WP Cron' ) { ActionScheduler_Compatibility::raise_memory_limit(); ActionScheduler_Compatibility::raise_time_limit( $this->get_time_limit() ); do_action( 'action_scheduler_before_process_queue' ); @@ -91,7 +113,7 @@ public function run() { if ( false === $this->has_maximum_concurrent_batches() ) { $batch_size = apply_filters( 'action_scheduler_queue_runner_batch_size', 25 ); do { - $processed_actions_in_batch = $this->do_batch( $batch_size ); + $processed_actions_in_batch = $this->do_batch( $batch_size, $context ); $processed_actions += $processed_actions_in_batch; } while ( $processed_actions_in_batch > 0 && ! $this->batch_limits_exceeded( $processed_actions ) ); // keep going until we run out of actions, time, or memory } @@ -100,7 +122,18 @@ public function run() { return $processed_actions; } - protected function do_batch( $size = 100 ) { + /** + * Process a batch of actions pending in the queue. + * + * Actions are processed by claiming a set of pending actions then processing each one until either the batch + * size is completed, or memory or time limits are reached, defined by @see $this->batch_limits_exceeded(). + * + * @param int $size The maximum number of actions to process in the batch. + * @param string $context Optional identifer for the context in which this action is being processed, e.g. 'WP CLI' or 'WP Cron' + * Generally, this should be capitalised and not localised as it's a proper noun. + * @return int The number of actions processed. + */ + protected function do_batch( $size = 100, $context = '' ) { $claim = $this->store->stake_claim($size); $this->monitor->attach($claim); $processed_actions = 0; @@ -110,7 +143,7 @@ protected function do_batch( $size = 100 ) { if ( ! in_array( $action_id, $this->store->find_actions_by_claim_id( $claim->get_id() ) ) ) { break; } - $this->process_action( $action_id ); + $this->process_action( $action_id, $context ); $processed_actions++; if ( $this->batch_limits_exceeded( $processed_actions ) ) { diff --git a/classes/WP_CLI/ActionScheduler_WPCLI_QueueRunner.php b/classes/WP_CLI/ActionScheduler_WPCLI_QueueRunner.php index da34407a7..613e20977 100644 --- a/classes/WP_CLI/ActionScheduler_WPCLI_QueueRunner.php +++ b/classes/WP_CLI/ActionScheduler_WPCLI_QueueRunner.php @@ -108,7 +108,7 @@ public function run() { break; } - $this->process_action( $action_id ); + $this->process_action( $action_id, 'WP CLI' ); $this->progress_bar->tick(); $this->maybe_stop_the_insanity(); } diff --git a/classes/abstracts/ActionScheduler_Abstract_QueueRunner.php b/classes/abstracts/ActionScheduler_Abstract_QueueRunner.php index 62839560e..81602928e 100644 --- a/classes/abstracts/ActionScheduler_Abstract_QueueRunner.php +++ b/classes/abstracts/ActionScheduler_Abstract_QueueRunner.php @@ -44,24 +44,26 @@ public function __construct( ActionScheduler_Store $store = null, ActionSchedule * Process an individual action. * * @param int $action_id The action ID to process. + * @param string $context Optional identifer for the context in which this action is being processed, e.g. 'WP CLI' or 'WP Cron' + * Generally, this should be capitalised and not localised as it's a proper noun. */ - public function process_action( $action_id ) { + public function process_action( $action_id, $context = '' ) { try { - do_action( 'action_scheduler_before_execute', $action_id ); + do_action( 'action_scheduler_before_execute', $action_id, $context ); if ( ActionScheduler_Store::STATUS_PENDING !== $this->store->get_status( $action_id ) ) { - do_action( 'action_scheduler_execution_ignored', $action_id ); + do_action( 'action_scheduler_execution_ignored', $action_id, $context ); return; } $action = $this->store->fetch_action( $action_id ); $this->store->log_execution( $action_id ); $action->execute(); - do_action( 'action_scheduler_after_execute', $action_id, $action ); + do_action( 'action_scheduler_after_execute', $action_id, $action, $context ); $this->store->mark_complete( $action_id ); } catch ( Exception $e ) { $this->store->mark_failure( $action_id ); - do_action( 'action_scheduler_failed_execution', $action_id, $e ); + do_action( 'action_scheduler_failed_execution', $action_id, $e, $context ); } if ( isset( $action ) && is_a( $action, 'ActionScheduler_Action' ) ) { @@ -222,7 +224,9 @@ protected function batch_limits_exceeded( $processed_actions ) { * Process actions in the queue. * * @author Jeremy Pry + * @param string $context Optional identifer for the context in which this action is being processed, e.g. 'WP CLI' or 'WP Cron' + * Generally, this should be capitalised and not localised as it's a proper noun. * @return int The number of actions processed. */ - abstract public function run(); + abstract public function run( $context = '' ); } diff --git a/classes/abstracts/ActionScheduler_Logger.php b/classes/abstracts/ActionScheduler_Logger.php index b87134cd6..049adc5fa 100644 --- a/classes/abstracts/ActionScheduler_Logger.php +++ b/classes/abstracts/ActionScheduler_Logger.php @@ -48,13 +48,13 @@ abstract public function get_logs( $action_id ); public function init() { add_action( 'action_scheduler_stored_action', array( $this, 'log_stored_action' ), 10, 1 ); add_action( 'action_scheduler_canceled_action', array( $this, 'log_canceled_action' ), 10, 1 ); - add_action( 'action_scheduler_before_execute', array( $this, 'log_started_action' ), 10, 1 ); - add_action( 'action_scheduler_after_execute', array( $this, 'log_completed_action' ), 10, 1 ); - add_action( 'action_scheduler_failed_execution', array( $this, 'log_failed_action' ), 10, 2 ); + add_action( 'action_scheduler_before_execute', array( $this, 'log_started_action' ), 10, 2 ); + add_action( 'action_scheduler_after_execute', array( $this, 'log_completed_action' ), 10, 3 ); + add_action( 'action_scheduler_failed_execution', array( $this, 'log_failed_action' ), 10, 3 ); add_action( 'action_scheduler_failed_action', array( $this, 'log_timed_out_action' ), 10, 2 ); add_action( 'action_scheduler_unexpected_shutdown', array( $this, 'log_unexpected_shutdown' ), 10, 2 ); add_action( 'action_scheduler_reset_action', array( $this, 'log_reset_action' ), 10, 1 ); - add_action( 'action_scheduler_execution_ignored', array( $this, 'log_ignored_action' ), 10, 1 ); + add_action( 'action_scheduler_execution_ignored', array( $this, 'log_ignored_action' ), 10, 2 ); add_action( 'action_scheduler_failed_fetch_action', array( $this, 'log_failed_fetch_action' ), 10, 1 ); } @@ -66,16 +66,31 @@ public function log_canceled_action( $action_id ) { $this->log( $action_id, __( 'action canceled', 'action-scheduler' ) ); } - public function log_started_action( $action_id ) { - $this->log( $action_id, __( 'action started', 'action-scheduler' ) ); + public function log_started_action( $action_id, $context = '' ) { + if ( ! empty( $context ) ) { + $message = sprintf( __( 'action started via %s', 'action-scheduler' ), $context ); + } else { + $message = __( 'action started', 'action-scheduler' ); + } + $this->log( $action_id, $message ); } - public function log_completed_action( $action_id ) { - $this->log( $action_id, __( 'action complete', 'action-scheduler' ) ); + public function log_completed_action( $action_id, $action = NULL, $context = '' ) { + if ( ! empty( $context ) ) { + $message = sprintf( __( 'action complete via %s', 'action-scheduler' ), $context ); + } else { + $message = __( 'action complete', 'action-scheduler' ); + } + $this->log( $action_id, $message ); } - public function log_failed_action( $action_id, Exception $exception ) { - $this->log( $action_id, sprintf( __( 'action failed: %s', 'action-scheduler' ), $exception->getMessage() ) ); + public function log_failed_action( $action_id, Exception $exception, $context = '' ) { + if ( ! empty( $context ) ) { + $message = sprintf( __( 'action failed via %s: %s', 'action-scheduler' ), $context, $exception->getMessage() ); + } else { + $message = sprintf( __( 'action failed: %s', 'action-scheduler' ), $exception->getMessage() ); + } + $this->log( $action_id, $message ); } public function log_timed_out_action( $action_id, $timeout ) { @@ -92,7 +107,12 @@ public function log_reset_action( $action_id ) { $this->log( $action_id, __( 'action reset', 'action_scheduler' ) ); } - public function log_ignored_action( $action_id ) { + public function log_ignored_action( $action_id, $context = '' ) { + if ( ! empty( $context ) ) { + $message = sprintf( __( 'action ignored via %s', 'action-scheduler' ), $context ); + } else { + $message = __( 'action ignored', 'action-scheduler' ); + } $this->log( $action_id, __( 'action ignored', 'action-scheduler' ) ); } diff --git a/docs/faq.md b/docs/faq.md index 2da7e7cb3..90d4bcb31 100644 --- a/docs/faq.md +++ b/docs/faq.md @@ -19,7 +19,7 @@ ActionScheduler::runner()->run(); Or trigger the `'action_scheduler_run_queue'` hook and let Action Scheduler do it for you: ```php -do_action( 'action_scheduler_run_queue' ); +do_action( 'action_scheduler_run_queue', $context_identifier ); ``` Further customization can be done by extending the `ActionScheduler_Abstract_QueueRunner` class to create a custom Queue Runner. For an example of a customized queue runner, see the [`ActionScheduler_WPCLI_QueueRunner`](https://github.com/Prospress/action-scheduler/blob/master/classes/ActionScheduler_WPCLI_QueueRunner.php), which is used when running WP CLI. diff --git a/tests/phpunit/logging/ActionScheduler_wpCommentLogger_Test.php b/tests/phpunit/logging/ActionScheduler_wpCommentLogger_Test.php index 154b822a8..c8ccb70f9 100644 --- a/tests/phpunit/logging/ActionScheduler_wpCommentLogger_Test.php +++ b/tests/phpunit/logging/ActionScheduler_wpCommentLogger_Test.php @@ -83,11 +83,11 @@ protected function log_entry_to_array( $logs ) { public function test_execution_comments() { $action_id = as_schedule_single_action( time(), 'a hook' ); $logger = ActionScheduler::logger(); - $started = new ActionScheduler_LogEntry( $action_id, 'action started' ); - $finished = new ActionScheduler_LogEntry( $action_id, 'action complete' ); + $started = new ActionScheduler_LogEntry( $action_id, 'action started via Unit Tests' ); + $finished = new ActionScheduler_LogEntry( $action_id, 'action complete via Unit Tests' ); $runner = new ActionScheduler_QueueRunner(); - $runner->run(); + $runner->run( 'Unit Tests' ); $logs = $logger->get_logs( $action_id ); $this->assertTrue( in_array( $this->log_entry_to_array( $started ), $this->log_entry_to_array( $logs ) ) ); @@ -99,12 +99,12 @@ public function test_failed_execution_comments() { add_action( $hook, array( $this, '_a_hook_callback_that_throws_an_exception' ) ); $action_id = as_schedule_single_action( time(), $hook ); $logger = ActionScheduler::logger(); - $started = new ActionScheduler_LogEntry( $action_id, 'action started' ); - $finished = new ActionScheduler_LogEntry( $action_id, 'action complete' ); - $failed = new ActionScheduler_LogEntry( $action_id, 'action failed: Execution failed' ); + $started = new ActionScheduler_LogEntry( $action_id, 'action started via Unit Tests' ); + $finished = new ActionScheduler_LogEntry( $action_id, 'action complete via Unit Tests' ); + $failed = new ActionScheduler_LogEntry( $action_id, 'action failed via Unit Tests: Execution failed' ); $runner = new ActionScheduler_QueueRunner(); - $runner->run(); + $runner->run( 'Unit Tests' ); $logs = $logger->get_logs( $action_id ); $this->assertTrue( in_array( $this->log_entry_to_array( $started ), $this->log_entry_to_array( $logs ) ) ); diff --git a/tests/phpunit/runner/ActionScheduler_QueueRunner_Test.php b/tests/phpunit/runner/ActionScheduler_QueueRunner_Test.php index 0087b40c7..a21d06f42 100644 --- a/tests/phpunit/runner/ActionScheduler_QueueRunner_Test.php +++ b/tests/phpunit/runner/ActionScheduler_QueueRunner_Test.php @@ -108,7 +108,7 @@ public function test_next_instance_of_action() { } public function test_hooked_into_wp_cron() { - $next = wp_next_scheduled( ActionScheduler_QueueRunner::WP_CRON_HOOK ); + $next = wp_next_scheduled( ActionScheduler_QueueRunner::WP_CRON_HOOK, array( 'WP Cron' ) ); $this->assertNotEmpty($next); }