Skip to content

feat(logger): actionscheduler integration #4611

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
miguelpeixe wants to merge 2 commits into
base: trunk
Choose a base branch
from
Draft

feat(logger): actionscheduler integration #4611

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ce830c1
feat(logger): actionscheduler integration
miguelpeixe Mar 30, 2026
933cb10
refactor: data event and sync to rely on the logger to push AS logs
miguelpeixe Mar 30, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 46 additions & 1 deletion includes/class-logger.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand All @@ -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.
*
Expand All @@ -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 ) {
Expand Down Expand Up @@ -139,3 +183,4 @@ public static function newspack_log( $code, $message, $data = [], $type = 'error
);
}
}
Logger::init();
30 changes: 0 additions & 30 deletions includes/data-events/class-data-events.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down Expand Up @@ -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' ] );
}

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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.
*
Expand Down
63 changes: 7 additions & 56 deletions includes/reader-activation/sync/class-contact-sync.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand All @@ -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' ] );
}

Expand All @@ -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.
Expand All @@ -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'] ) ) {
Expand Down Expand Up @@ -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' ) );
}
}

Expand Down Expand Up @@ -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.
*
Expand Down Expand Up @@ -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 ) {
Expand All @@ -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 );
}
}
}

Expand Down Expand Up @@ -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;
Expand All @@ -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 = [];
}
}
Expand Down
99 changes: 0 additions & 99 deletions tests/unit-tests/data-events.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down
Loading
Loading