diff --git a/includes/class-logger.php b/includes/class-logger.php index 1c93f3aa10..63876434fa 100644 --- a/includes/class-logger.php +++ b/includes/class-logger.php @@ -13,6 +13,46 @@ * Logger. */ class Logger { + /** + * Current ActionScheduler action ID, if running inside an AS action. + * + * @var int|null + */ + private static $current_as_action_id = null; + + /** + * Initialize ActionScheduler logging hooks. + */ + public static function init() { + add_action( 'action_scheduler_begin_execute', [ __CLASS__, 'set_current_as_action_id' ] ); + add_action( 'action_scheduler_after_execute', [ __CLASS__, 'clear_current_as_action_id' ] ); + } + + /** + * Set the current ActionScheduler action ID. + * + * @param int $action_id The AS action ID. + */ + public static function set_current_as_action_id( $action_id ) { + self::$current_as_action_id = $action_id; + } + + /** + * Get the current ActionScheduler action ID. + * + * @return int|null The current AS action ID, or null if not running inside an AS action. + */ + public static function get_current_as_action_id() { + return self::$current_as_action_id; + } + + /** + * Clear the current ActionScheduler action ID. + */ + public static function clear_current_as_action_id() { + self::$current_as_action_id = null; + } + /** * A logger. * @@ -21,6 +61,10 @@ class Logger { * @param string $type Type of the message. */ public static function log( $payload, $header = 'NEWSPACK', $type = 'info' ) { + $message = 'string' === gettype( $payload ) ? $payload : wp_json_encode( $payload, JSON_PRETTY_PRINT ); + if ( self::$current_as_action_id && class_exists( '\ActionScheduler_Logger' ) ) { + \ActionScheduler_Logger::instance()->log( self::$current_as_action_id, "[$header] $message" ); + } /** * Controls logging verbosity across Newspack plugins. * @@ -45,7 +89,7 @@ public static function log( $payload, $header = 'NEWSPACK', $type = 'info' ) { // Add information about the caller function, if log level is > 1. if ( 1 < NEWSPACK_LOG_LEVEL ) { try { - $backtrace = debug_backtrace(); // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_debug_backtrace + $backtrace = debug_backtrace(); // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_debug_backtrace, PHPCompatibility.FunctionUse.ArgumentFunctionsReportCurrentValue.NeedsInspection if ( 2 < count( $backtrace ) ) { $caller_frame = $backtrace[1]; if ( stripos( $caller_frame['class'], 'Logger' ) !== false ) { @@ -139,3 +183,4 @@ public static function newspack_log( $code, $message, $data = [], $type = 'error ); } } +Logger::init(); diff --git a/includes/data-events/class-data-events.php b/includes/data-events/class-data-events.php index 07d00126a8..8a4dc46a5d 100644 --- a/includes/data-events/class-data-events.php +++ b/includes/data-events/class-data-events.php @@ -81,13 +81,6 @@ final class Data_Events { */ private static $current_event = null; - /** - * The ID of the currently-executing ActionScheduler action. - * - * @var int|null - */ - private static $current_as_action_id = null; - /** * ActionScheduler hook for handling dispatched events. */ @@ -128,8 +121,6 @@ public static function init() { \add_action( 'shutdown', [ __CLASS__, 'execute_queued_dispatches' ] ); \add_action( self::DISPATCH_AS_HOOK, [ __CLASS__, 'handle_from_scheduler' ] ); \add_action( self::HANDLER_RETRY_HOOK, [ __CLASS__, 'execute_handler_retry' ] ); - \add_action( 'action_scheduler_begin_execute', [ __CLASS__, 'set_current_as_action_id' ] ); - \add_action( 'action_scheduler_after_execute', [ __CLASS__, 'clear_current_as_action_id' ] ); \add_filter( 'newspack_action_scheduler_hook_labels', [ __CLASS__, 'register_hook_labels' ] ); } @@ -389,21 +380,6 @@ private static function set_current_event( $name ) { self::$current_event = $name; } - /** - * Set the current ActionScheduler action ID. - * - * @param int $action_id The AS action ID. - */ - public static function set_current_as_action_id( $action_id ) { - self::$current_as_action_id = $action_id; - } - - /** - * Clear the current ActionScheduler action ID. - */ - public static function clear_current_as_action_id() { - self::$current_as_action_id = null; - } /** * Register a triggerable action. @@ -799,12 +775,6 @@ private static function schedule_handler_retry( $handler, $action_name, $timesta ), 'error' ); - if ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( - self::$current_as_action_id, - sprintf( 'Max retries exhausted. Final error: %s', $error->getMessage() ) - ); - } /** * Fires when a Data Events handler has exhausted all retry attempts. * diff --git a/includes/reader-activation/sync/class-contact-sync.php b/includes/reader-activation/sync/class-contact-sync.php index 10d2365766..d6517533f2 100644 --- a/includes/reader-activation/sync/class-contact-sync.php +++ b/includes/reader-activation/sync/class-contact-sync.php @@ -32,13 +32,6 @@ class Contact_Sync extends Sync { */ protected static $queued_syncs = []; - /** - * The ID of the currently-executing ActionScheduler action. - * - * @var int|null - */ - private static $current_as_action_id = null; - /** * ActionScheduler hook for retrying a failed integration sync. */ @@ -62,8 +55,6 @@ public static function init_hooks() { add_action( 'newspack_scheduled_esp_sync', [ __CLASS__, 'scheduled_sync' ], 10, 2 ); add_action( 'shutdown', [ __CLASS__, 'run_queued_syncs' ] ); add_action( self::RETRY_HOOK, [ __CLASS__, 'execute_integration_retry' ] ); - add_action( 'action_scheduler_begin_execute', [ __CLASS__, 'set_current_as_action_id' ] ); - add_action( 'action_scheduler_after_execute', [ __CLASS__, 'clear_current_as_action_id' ] ); add_filter( 'newspack_action_scheduler_hook_labels', [ __CLASS__, 'register_hook_labels' ] ); } @@ -78,21 +69,6 @@ public static function register_hook_labels( $labels ) { return $labels; } - /** - * Set the current ActionScheduler action ID. - * - * @param int $action_id The AS action ID. - */ - public static function set_current_as_action_id( $action_id ) { - self::$current_as_action_id = $action_id; - } - - /** - * Clear the current ActionScheduler action ID. - */ - public static function clear_current_as_action_id() { - self::$current_as_action_id = null; - } /** * Sync contact to the ESP. @@ -119,7 +95,7 @@ public static function sync( $contact, $context = '', $existing_contact = null ) self::$queued_syncs[ $contact['email'] ] = [ 'contexts' => [], 'contact' => [], - 'as_action_id' => self::$current_as_action_id, + 'as_action_id' => Logger::get_current_as_action_id(), ]; } if ( ! empty( self::$queued_syncs[ $contact['email'] ]['contact']['metadata'] ) ) { @@ -198,17 +174,9 @@ private static function push_to_integrations( $contact, $context, $existing_cont ); self::schedule_integration_retry( $integration_id, $user_id, $context, 0, $result, $previous_email ); $errors[] = sprintf( '[%s] %s', $integration_id, $result->get_error_message() ); - if ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( - self::$current_as_action_id, - sprintf( 'Sync failed for integration "%s" of %s: %s', $integration_id, $contact['email'] ?? 'unknown', $result->get_error_message() ) - ); - } - } elseif ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( - self::$current_as_action_id, - sprintf( 'Sync succeeded for integration "%s" of %s.', $integration_id, $contact['email'] ?? 'unknown' ) - ); + static::log( sprintf( 'Sync failed for integration "%s" of %s: %s', $integration_id, $contact['email'] ?? 'unknown', $result->get_error_message() ) ); + } else { + static::log( sprintf( 'Sync succeeded for integration "%s" of %s.', $integration_id, $contact['email'] ?? 'unknown' ) ); } } @@ -255,12 +223,6 @@ private static function schedule_integration_retry( $integration_id, $user_id, $ $error_message ) ); - if ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( - self::$current_as_action_id, - 'Max retries exhausted.' - ); - } /** * Fires when a contact sync integration has exhausted all retry attempts. * @@ -402,12 +364,6 @@ public static function execute_integration_retry( $retry_data ) { $contact['email'] ?? 'unknown', $error_messages ); - if ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( - self::$current_as_action_id, - $error_message - ); - } // Only throw on the last retry so ActionScheduler marks it as "failed". // Intermediate retries schedule the next attempt and complete normally. if ( $retry_count >= self::MAX_RETRIES ) { @@ -423,9 +379,6 @@ public static function execute_integration_retry( $retry_data ) { $contact['email'] ?? 'unknown' ); static::log( $success_message ); - if ( self::$current_as_action_id ) { - \ActionScheduler_Logger::instance()->log( self::$current_as_action_id, $success_message ); - } } } @@ -571,11 +524,9 @@ public static function run_queued_syncs() { return; } - // Restore the AS action ID so push_to_integrations() can log against it. - $saved_action_id = self::$current_as_action_id; - foreach ( self::$queued_syncs as $email => $queued_sync ) { - self::$current_as_action_id = $queued_sync['as_action_id'] ?? null; + // Set Logger's AS action ID so logs are attached to the originating action. + Logger::set_current_as_action_id( $queued_sync['as_action_id'] ?? null ); $user = get_user_by( 'email', $email ); $contact = null; @@ -593,7 +544,7 @@ public static function run_queued_syncs() { self::sync( $contact, implode( '; ', $contexts ) ); } - self::$current_as_action_id = $saved_action_id; + Logger::clear_current_as_action_id(); self::$queued_syncs = []; } } diff --git a/tests/unit-tests/data-events.php b/tests/unit-tests/data-events.php index 28f86fa933..e68aafe703 100644 --- a/tests/unit-tests/data-events.php +++ b/tests/unit-tests/data-events.php @@ -859,105 +859,6 @@ public function test_current_event_set_during_retry() { $this->assertNull( Data_Events::current_event(), 'current_event should be null after retry completes.' ); } - /** - * Test that scheduling a handler retry creates an AS log entry with the failure reason. - */ - public function test_handler_retry_as_log_entry() { - if ( ! function_exists( 'as_schedule_single_action' ) ) { - $this->markTestSkipped( 'ActionScheduler not available.' ); - } - - as_unschedule_all_actions( Data_Events::HANDLER_RETRY_HOOK ); - - $action_name = 'test_retry_as_log'; - Data_Events::register_action( $action_name ); - - $handler = [ self::class, 'throwing_handler' ]; - Data_Events::register_handler( $handler, $action_name ); - - Data_Events::handle( $action_name, time(), [ 'test' => 'data' ], 'client-1' ); - - // Get the scheduled retry action. - $pending = as_get_scheduled_actions( - [ - 'hook' => Data_Events::HANDLER_RETRY_HOOK, - 'group' => 'newspack', - 'status' => \ActionScheduler_Store::STATUS_PENDING, - ], - 'ARRAY_A' - ); - $this->assertNotEmpty( $pending ); - - $action_id = array_key_first( $pending ); - - // Verify AS log entry. - $logs = \ActionScheduler_Logger::instance()->get_logs( $action_id ); - $messages = array_map( - function ( $log ) { - return $log->get_message(); - }, - $logs - ); - $this->assertTrue( - in_array( 'Failure reason: Test handler failure', $messages, true ), - 'AS logs should contain the failure reason.' - ); - } - - /** - * Test that max retries exhausted creates an AS log entry on the current action. - */ - public function test_max_retries_as_log_entry() { - if ( ! function_exists( 'as_schedule_single_action' ) ) { - $this->markTestSkipped( 'ActionScheduler not available.' ); - } - - as_unschedule_all_actions( Data_Events::HANDLER_RETRY_HOOK ); - - $action_name = 'test_max_retries_log'; - Data_Events::register_action( $action_name ); - - $handler = [ self::class, 'throwing_handler' ]; - Data_Events::register_handler( $handler, $action_name ); - - // Schedule a dummy AS action to simulate the currently-executing action. - $dummy_action_id = as_schedule_single_action( time() + 3600, 'newspack_dummy_action' ); - - // Set the current AS action ID to simulate being inside an AS execution. - Data_Events::set_current_as_action_id( $dummy_action_id ); - - // Execute at max retry count — handler throws, triggers max-retries guard. - Data_Events::execute_handler_retry( - [ - 'handler' => $handler, - 'action_name' => $action_name, - 'timestamp' => time(), - 'data' => [], - 'client_id' => null, - 'is_global' => false, - 'retry_count' => Data_Events::MAX_HANDLER_RETRIES, - ] - ); - - Data_Events::clear_current_as_action_id(); - - // Verify AS log entry on the dummy action. - $logs = \ActionScheduler_Logger::instance()->get_logs( $dummy_action_id ); - $messages = array_map( - function ( $log ) { - return $log->get_message(); - }, - $logs - ); - $this->assertTrue( - in_array( 'Max retries exhausted. Final error: Test handler failure', $messages, true ), - 'AS logs should contain the max retries exhausted message.' - ); - - // Clean up. - as_unschedule_all_actions( 'newspack_dummy_action' ); - } - /** * Test that retry exhaustion fires the alert hook. */ diff --git a/tests/unit-tests/reader-activation-sync.php b/tests/unit-tests/reader-activation-sync.php index a7962d3d04..c93da4e53d 100644 --- a/tests/unit-tests/reader-activation-sync.php +++ b/tests/unit-tests/reader-activation-sync.php @@ -419,115 +419,6 @@ public function test_integration_max_retries() { $this->assertEmpty( $pending, 'No retry should be scheduled after max retries.' ); } - /** - * Test that a failed integration retry logs the error to the current AS action. - */ - public function test_integration_retry_as_log_entry() { - if ( ! function_exists( 'as_schedule_single_action' ) ) { - $this->markTestSkipped( 'ActionScheduler not available.' ); - } - - Failing_Sample_Integration::reset(); - Failing_Sample_Integration::$should_fail = true; - $this->register_failing_integration( 'log_mock' ); - - as_unschedule_all_actions( Contact_Sync::RETRY_HOOK ); - - $user_id = $this->factory()->user->create( [ 'user_email' => 'log@test.com' ] ); - - // Schedule a dummy AS action to simulate the currently-executing action. - $dummy_action_id = as_schedule_single_action( time() + 3600, 'newspack_dummy_log_action' ); - Contact_Sync::set_current_as_action_id( $dummy_action_id ); - - Contact_Sync::execute_integration_retry( - [ - 'integration_id' => 'log_mock', - 'user_id' => $user_id, - 'context' => 'Test', - 'retry_count' => 1, - ] - ); - - Contact_Sync::clear_current_as_action_id(); - - // Intermediate retries log a formatted failure message to the current AS action. - $logs = \ActionScheduler_Logger::instance()->get_logs( $dummy_action_id ); - $messages = array_map( - function ( $log ) { - return $log->get_message(); - }, - $logs - ); - $has_retry_log = false; - foreach ( $messages as $message ) { - if ( false !== strpos( $message, 'Retry 1/' . Contact_Sync::MAX_RETRIES . ' failed for integration "log_mock"' ) ) { - $has_retry_log = true; - break; - } - } - $this->assertTrue( - $has_retry_log, - 'Intermediate retries should log a formatted failure message to AS.' - ); - - // Clean up. - as_unschedule_all_actions( 'newspack_dummy_log_action' ); - } - - /** - * Test that max retries exhausted creates an AS log entry on the current action. - */ - public function test_integration_max_retries_as_log_entry() { - if ( ! function_exists( 'as_schedule_single_action' ) ) { - $this->markTestSkipped( 'ActionScheduler not available.' ); - } - - Failing_Sample_Integration::reset(); - Failing_Sample_Integration::$should_fail = true; - $this->register_failing_integration( 'deadletter_mock' ); - - as_unschedule_all_actions( Contact_Sync::RETRY_HOOK ); - - $user_id = $this->factory()->user->create( [ 'user_email' => 'deadletter@test.com' ] ); - - // Schedule a dummy AS action to simulate the currently-executing action. - $dummy_action_id = as_schedule_single_action( time() + 3600, 'newspack_dummy_sync_action' ); - - // Set the current AS action ID. - Contact_Sync::set_current_as_action_id( $dummy_action_id ); - - // Execute at max retry count — push fails, triggers max-retries guard and throws. - try { - Contact_Sync::execute_integration_retry( - [ - 'integration_id' => 'deadletter_mock', - 'user_id' => $user_id, - 'context' => 'Test', - 'retry_count' => Contact_Sync::MAX_RETRIES, - ] - ); - } catch ( \Exception $e ) { // phpcs:ignore Generic.CodeAnalysis.EmptyStatement.DetectedCatch - // Expected — final retry throws so AS marks the action as failed. - } - - Contact_Sync::clear_current_as_action_id(); - - // Verify AS log entry on the dummy action. - $logs = \ActionScheduler_Logger::instance()->get_logs( $dummy_action_id ); - $messages = array_map( - function ( $log ) { - return $log->get_message(); - }, - $logs - ); - $this->assertTrue( - in_array( 'Max retries exhausted.', $messages, true ), - 'AS logs should contain the max retries exhausted message.' - ); - - // Clean up. - as_unschedule_all_actions( 'newspack_dummy_sync_action' ); - } /** * Test that sync retry exhaustion fires the alert hook.