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

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();
 	}
 

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 );

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 ) ) {

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();
 		}

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 = '' );
 }

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' ) );
 	}
 

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.

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 ) ) );

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);
 	}