Malin
296693ebd4
Root cause of the 2-hour stall: a category page's PHP process hung (CLI-run cron processes typically have no execution time limit) and never returned, so it never reached the code path that marks a page complete, queues the next page, or marks the run failed. Action Scheduler's own watchdog eventually marked the action failed after its 3600s timeout, but by then the plugin's own run-tracking option was permanently stuck at status=running with no further pages ever queued - and since manual and scheduled syncs both check the same lock, this silently blocked all future syncs (not just this one) for the full 4-hour lock safety-net. Adds an 'updated_at' timestamp refreshed on every batch/page, and checks it in queue_full_sync(): if a "running" sync hasn't made progress in over 10 minutes, treat it as abandoned, clear the lock, and start fresh instead of waiting out the multi-hour safety-net. Also caps the 429 retry-after sleep at 30s rather than trusting an external API-supplied value without bound, as a defensive measure against another unbounded stall. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
462 lines
18 KiB
PHP
462 lines
18 KiB
PHP
<?php
|
|
/**
|
|
* Background batch orchestration for product sync
|
|
*
|
|
* Splits the WooCommerce-first product sync into small chunks processed via
|
|
* Action Scheduler (bundled with WooCommerce), so neither the "Sync Now"
|
|
* AJAX request nor the WP-Cron event has to process the entire catalog in a
|
|
* single PHP execution. At real catalog sizes (tens of thousands of SKUs)
|
|
* that single-request approach exceeds PHP's max_execution_time and the
|
|
* webserver/proxy's read timeout, surfacing as a 502 Bad Gateway.
|
|
*
|
|
* @package WooBusinessCentral
|
|
*/
|
|
|
|
// Prevent direct access
|
|
if ( ! defined( 'ABSPATH' ) ) {
|
|
exit;
|
|
}
|
|
|
|
/**
|
|
* Class WBC_Batch_Sync
|
|
*/
|
|
class WBC_Batch_Sync {
|
|
|
|
/**
|
|
* Number of products processed per background action
|
|
*/
|
|
const BATCH_SIZE = 25;
|
|
|
|
/**
|
|
* Number of BC items fetched per page in category-filtered mode
|
|
*
|
|
* Kept small on purpose: each item can trigger several sequential BC
|
|
* calls while processing it (location stock, price lists, brand/category
|
|
* lookup), not just the one page fetch. 100 items/page was measured to
|
|
* take 150-250+ seconds per page - long enough to exceed PHP's
|
|
* execution limit and strand the action mid-run ("in-progress" forever,
|
|
* never completing or erroring). Matches BATCH_SIZE, which is proven to
|
|
* finish reliably within one execution.
|
|
*/
|
|
const CATEGORY_PAGE_SIZE = 25;
|
|
|
|
/**
|
|
* Option name storing the current/last run's progress
|
|
*/
|
|
const RUN_OPTION = 'wbc_sync_run';
|
|
|
|
/**
|
|
* Transient used as a simple "a sync is already running" guard
|
|
*/
|
|
const LOCK_TRANSIENT = 'wbc_sync_lock';
|
|
|
|
/**
|
|
* Action Scheduler hook processed per batch (WooCommerce-first mode)
|
|
*/
|
|
const ACTION_HOOK = 'wbc_process_sync_batch';
|
|
|
|
/**
|
|
* Action Scheduler hook processed per page (category-filtered, BC-first mode)
|
|
*/
|
|
const CATEGORY_ACTION_HOOK = 'wbc_process_category_page';
|
|
|
|
/**
|
|
* Action Scheduler group name
|
|
*/
|
|
const ACTION_GROUP = 'wbc_product_sync';
|
|
|
|
/**
|
|
* How long a "running" sync can go without progress before it's treated
|
|
* as abandoned and cleared automatically on the next sync attempt.
|
|
*
|
|
* Normal pages/batches complete in well under a minute; 10 minutes gives
|
|
* generous slack for a slow page or a couple of missed cron ticks while
|
|
* still recovering quickly from a genuinely stuck run - which otherwise
|
|
* blocks every sync (manual and scheduled) for the full 4-hour lock
|
|
* safety-net, since a hung PHP process never reaches the code that would
|
|
* mark the run failed or complete.
|
|
*/
|
|
const STALE_THRESHOLD = 10 * MINUTE_IN_SECONDS;
|
|
|
|
/**
|
|
* Register the Action Scheduler batch handlers
|
|
*/
|
|
public function register_hooks() {
|
|
add_action( self::ACTION_HOOK, array( $this, 'process_batch' ), 10, 2 );
|
|
add_action( self::CATEGORY_ACTION_HOOK, array( $this, 'process_category_page' ), 10, 2 );
|
|
}
|
|
|
|
/**
|
|
* Kick off a full catalog sync in the background
|
|
*
|
|
* If a category filter is configured, syncs BC-first: pages through
|
|
* /items filtered server-side by itemCategoryCode and matches each item
|
|
* to a WooCommerce product locally. This avoids querying BC once per
|
|
* WooCommerce product only to discard most of them - with a filter set,
|
|
* the vast majority of products aren't in an allowed category, so doing
|
|
* the filtering on BC's side first is far fewer API calls.
|
|
*
|
|
* Without a filter, falls back to the WooCommerce-first approach (ID-only
|
|
* query, batched, never loads the whole catalog as full objects), which
|
|
* doesn't have BC-side filtering available to narrow the scope.
|
|
*
|
|
* Returns immediately; actual work happens asynchronously.
|
|
*
|
|
* @return array Result with 'success' and 'message'.
|
|
*/
|
|
public static function queue_full_sync() {
|
|
if ( get_transient( self::LOCK_TRANSIENT ) && ! self::current_run_is_stale() ) {
|
|
$run = get_option( self::RUN_OPTION, array() );
|
|
return array(
|
|
'success' => true,
|
|
'started' => false,
|
|
'message' => __( 'A sync is already running.', 'woo-business-central' ),
|
|
'run' => $run,
|
|
);
|
|
}
|
|
|
|
if ( get_transient( self::LOCK_TRANSIENT ) ) {
|
|
// The lock exists but the run went stale (no progress in a while) -
|
|
// the process handling it almost certainly died mid-execution
|
|
// without reaching either the "next page" or "completed/failed"
|
|
// path (e.g. a hung request in a CLI process with no execution
|
|
// time limit). Don't make every future sync wait out the full
|
|
// multi-hour lock safety-net for a one-off stuck run.
|
|
$stale_run = get_option( self::RUN_OPTION, array() );
|
|
WBC_Logger::warning( 'BatchSync', 'Previous sync run went stale, clearing and starting fresh', array(
|
|
'stale_run_id' => $stale_run['run_id'] ?? '',
|
|
'updated_at' => $stale_run['updated_at'] ?? ( $stale_run['started_at'] ?? '' ),
|
|
) );
|
|
delete_transient( self::LOCK_TRANSIENT );
|
|
}
|
|
|
|
if ( get_option( 'wbc_enable_stock_sync', 'yes' ) !== 'yes' && get_option( 'wbc_enable_price_sync', 'yes' ) !== 'yes' ) {
|
|
WBC_Logger::info( 'BatchSync', 'Sync skipped - both stock and price sync are disabled' );
|
|
return array(
|
|
'success' => true,
|
|
'message' => __( 'Sync skipped - both stock and price sync are disabled.', 'woo-business-central' ),
|
|
);
|
|
}
|
|
|
|
if ( ! WBC_OAuth::is_configured() ) {
|
|
WBC_Logger::error( 'BatchSync', 'Sync failed - API credentials not configured' );
|
|
return array(
|
|
'success' => false,
|
|
'message' => __( 'Sync failed - API credentials not configured.', 'woo-business-central' ),
|
|
);
|
|
}
|
|
|
|
if ( ! function_exists( 'as_enqueue_async_action' ) ) {
|
|
WBC_Logger::error( 'BatchSync', 'Action Scheduler not available (ships with WooCommerce)' );
|
|
return array(
|
|
'success' => false,
|
|
'message' => __( 'Background task runner is not available.', 'woo-business-central' ),
|
|
);
|
|
}
|
|
|
|
$category_filter = get_option( 'wbc_category_filter', '' );
|
|
$categories = array_filter( array_map( 'trim', explode( ',', $category_filter ) ) );
|
|
|
|
if ( ! empty( $categories ) ) {
|
|
return self::queue_category_filtered_sync( array_values( $categories ) );
|
|
}
|
|
|
|
// ID-only query with a meta filter, so 60k+ catalogs don't get loaded
|
|
// as full WC_Product objects just to check for a SKU.
|
|
$product_ids = wc_get_products( array(
|
|
'limit' => -1,
|
|
'status' => 'publish',
|
|
'return' => 'ids',
|
|
'meta_query' => array( // phpcs:ignore WooCommerce.Commenting -- deliberate, avoids full-object load at scale.
|
|
array(
|
|
'key' => '_sku',
|
|
'value' => '',
|
|
'compare' => '!=',
|
|
),
|
|
),
|
|
) );
|
|
|
|
if ( empty( $product_ids ) ) {
|
|
WBC_Logger::info( 'BatchSync', 'No WooCommerce products with SKU found' );
|
|
return array(
|
|
'success' => true,
|
|
'message' => __( 'No WooCommerce products with SKU found.', 'woo-business-central' ),
|
|
);
|
|
}
|
|
|
|
$run_id = uniqid( 'wbc_', true );
|
|
$batches = array_chunk( $product_ids, self::BATCH_SIZE );
|
|
|
|
update_option( self::RUN_OPTION, array(
|
|
'run_id' => $run_id,
|
|
'mode' => 'by_id',
|
|
'status' => 'running',
|
|
'total' => count( $product_ids ),
|
|
'total_batches' => count( $batches ),
|
|
'batches_done' => 0,
|
|
'success' => 0,
|
|
'failed' => 0,
|
|
'skipped' => 0,
|
|
'started_at' => current_time( 'mysql' ),
|
|
'updated_at' => current_time( 'timestamp' ), // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- staleness math only, see current_run_is_stale().
|
|
'finished_at' => '',
|
|
), false );
|
|
|
|
// Safety-net expiry in case a batch throws and never reports back;
|
|
// prevents the lock from wedging the sync button forever.
|
|
set_transient( self::LOCK_TRANSIENT, $run_id, 4 * HOUR_IN_SECONDS );
|
|
|
|
foreach ( $batches as $batch ) {
|
|
as_enqueue_async_action( self::ACTION_HOOK, array(
|
|
'run_id' => $run_id,
|
|
'product_ids' => $batch,
|
|
), self::ACTION_GROUP );
|
|
}
|
|
|
|
WBC_Logger::info( 'BatchSync', 'Queued background sync', array(
|
|
'run_id' => $run_id,
|
|
'total_products' => count( $product_ids ),
|
|
'total_batches' => count( $batches ),
|
|
) );
|
|
|
|
return array(
|
|
'success' => true,
|
|
'started' => true,
|
|
'message' => sprintf(
|
|
/* translators: %d: number of products */
|
|
__( 'Sync started in the background for %d product(s).', 'woo-business-central' ),
|
|
count( $product_ids )
|
|
),
|
|
);
|
|
}
|
|
|
|
/**
|
|
* Whether the current tracked run has stopped making progress
|
|
*
|
|
* @return bool
|
|
*/
|
|
private static function current_run_is_stale() {
|
|
$run = get_option( self::RUN_OPTION, array() );
|
|
|
|
if ( empty( $run ) || ( $run['status'] ?? '' ) !== 'running' ) {
|
|
return false;
|
|
}
|
|
|
|
$last_activity = (int) ( $run['updated_at'] ?? 0 );
|
|
|
|
if ( empty( $last_activity ) ) {
|
|
return true;
|
|
}
|
|
|
|
// Raw Unix timestamps on both sides (current_time('timestamp') is
|
|
// WP-local but consistent with what's stored), so no string-parsing
|
|
// timezone ambiguity between this and how 'updated_at' was written.
|
|
return ( current_time( 'timestamp' ) - $last_activity ) > self::STALE_THRESHOLD; // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- comparing against a stored WP-local timestamp, not doing date math that needs UTC.
|
|
}
|
|
|
|
/**
|
|
* Kick off a BC-first, category-filtered sync
|
|
*
|
|
* Pages through BC's /items endpoint filtered server-side by
|
|
* itemCategoryCode (or-chained eq - BC's classic OData rejects the `in`
|
|
* operator here) and self-chains one background action per page, since
|
|
* the total item count isn't known upfront. Each page is matched against
|
|
* WooCommerce locally (no further BC calls in the common case).
|
|
*
|
|
* @param string[] $categories Allowed BC item category codes.
|
|
* @return array Result with 'success' and 'message'.
|
|
*/
|
|
private static function queue_category_filtered_sync( array $categories ) {
|
|
$run_id = uniqid( 'wbc_', true );
|
|
|
|
update_option( self::RUN_OPTION, array(
|
|
'run_id' => $run_id,
|
|
'mode' => 'category',
|
|
'status' => 'running',
|
|
'categories' => $categories,
|
|
'skip' => 0,
|
|
'pages_done' => 0,
|
|
'total' => 0,
|
|
'success' => 0,
|
|
'failed' => 0,
|
|
'skipped' => 0,
|
|
'started_at' => current_time( 'mysql' ),
|
|
'updated_at' => current_time( 'timestamp' ), // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- staleness math only, see current_run_is_stale().
|
|
'finished_at' => '',
|
|
), false );
|
|
|
|
set_transient( self::LOCK_TRANSIENT, $run_id, 4 * HOUR_IN_SECONDS );
|
|
|
|
as_enqueue_async_action( self::CATEGORY_ACTION_HOOK, array( $run_id, 0 ), self::ACTION_GROUP );
|
|
|
|
WBC_Logger::info( 'BatchSync', 'Queued category-filtered background sync', array(
|
|
'run_id' => $run_id,
|
|
'categories' => $categories,
|
|
) );
|
|
|
|
return array(
|
|
'success' => true,
|
|
'started' => true,
|
|
'message' => sprintf(
|
|
/* translators: %s: comma-separated category codes */
|
|
__( 'Sync started in the background, filtered to categories: %s.', 'woo-business-central' ),
|
|
implode( ', ', $categories )
|
|
),
|
|
);
|
|
}
|
|
|
|
/**
|
|
* Process one page of BC items filtered by category (called by Action Scheduler)
|
|
*
|
|
* Self-chains: enqueues the next page if this one came back full, or marks
|
|
* the run complete otherwise. Positional args, not a combined array - see
|
|
* the note on process_batch().
|
|
*
|
|
* @param string $run_id Run ID this page belongs to.
|
|
* @param int $skip OData $skip offset for this page.
|
|
*/
|
|
public function process_category_page( $run_id, $skip = 0 ) {
|
|
$run = get_option( self::RUN_OPTION, array() );
|
|
|
|
if ( empty( $run ) || ( $run['run_id'] ?? '' ) !== $run_id ) {
|
|
return;
|
|
}
|
|
|
|
$categories = $run['categories'] ?? array();
|
|
|
|
if ( empty( $categories ) ) {
|
|
return;
|
|
}
|
|
|
|
$filter_parts = array_map( function ( $code ) {
|
|
return "itemCategoryCode eq '" . WBC_API_Client::escape_odata_string( $code ) . "'";
|
|
}, $categories );
|
|
|
|
$result = WBC_API_Client::get( '/items', array(
|
|
'$filter' => '(' . implode( ' or ', $filter_parts ) . ')',
|
|
'$select' => WBC_Product_Sync::SELECT_FIELDS,
|
|
'$top' => self::CATEGORY_PAGE_SIZE,
|
|
'$skip' => $skip,
|
|
) );
|
|
|
|
if ( is_wp_error( $result ) ) {
|
|
WBC_Logger::error( 'BatchSync', 'Failed to fetch category page from BC, stopping run', array(
|
|
'run_id' => $run_id,
|
|
'skip' => $skip,
|
|
'error' => $result->get_error_message(),
|
|
) );
|
|
|
|
$run['status'] = 'failed';
|
|
$run['finished_at'] = current_time( 'mysql' );
|
|
$run['updated_at'] = current_time( 'timestamp' ); // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- staleness math only.
|
|
update_option( self::RUN_OPTION, $run, false );
|
|
delete_transient( self::LOCK_TRANSIENT );
|
|
return;
|
|
}
|
|
|
|
$items = isset( $result['value'] ) ? $result['value'] : array();
|
|
|
|
$sync = new WBC_Product_Sync();
|
|
foreach ( $items as $item ) {
|
|
$sync->process_bc_item( $item );
|
|
usleep( 50000 ); // 50ms, matches the rate limiting used elsewhere
|
|
}
|
|
$page_results = $sync->get_results();
|
|
|
|
// Best-effort counters - see note on process_batch().
|
|
$run = get_option( self::RUN_OPTION, $run );
|
|
if ( ( $run['run_id'] ?? '' ) !== $run_id ) {
|
|
return;
|
|
}
|
|
|
|
$run['pages_done'] = (int) ( $run['pages_done'] ?? 0 ) + 1;
|
|
$run['total'] = (int) ( $run['total'] ?? 0 ) + count( $items );
|
|
$run['success'] = (int) ( $run['success'] ?? 0 ) + $page_results['success'];
|
|
$run['failed'] = (int) ( $run['failed'] ?? 0 ) + $page_results['failed'];
|
|
$run['skipped'] = (int) ( $run['skipped'] ?? 0 ) + $page_results['skipped'];
|
|
$run['updated_at'] = current_time( 'timestamp' ); // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- staleness math only.
|
|
|
|
$has_more_pages = count( $items ) === self::CATEGORY_PAGE_SIZE;
|
|
|
|
if ( $has_more_pages ) {
|
|
$next_skip = $skip + self::CATEGORY_PAGE_SIZE;
|
|
$run['skip'] = $next_skip;
|
|
update_option( self::RUN_OPTION, $run, false );
|
|
as_enqueue_async_action( self::CATEGORY_ACTION_HOOK, array( $run_id, $next_skip ), self::ACTION_GROUP );
|
|
} else {
|
|
$run['status'] = 'completed';
|
|
$run['finished_at'] = current_time( 'mysql' );
|
|
update_option( self::RUN_OPTION, $run, false );
|
|
WBC_Cron::update_last_sync_time();
|
|
delete_transient( self::LOCK_TRANSIENT );
|
|
|
|
WBC_Logger::info( 'BatchSync', 'Category-filtered background sync completed', $run );
|
|
}
|
|
}
|
|
|
|
/**
|
|
* Process a single batch (called by Action Scheduler)
|
|
*
|
|
* Action Scheduler spreads the associative args array passed to
|
|
* as_enqueue_async_action() into separate positional parameters here
|
|
* (it does not pass a single combined array) - the parameter order
|
|
* must match the key order used when the action was enqueued.
|
|
*
|
|
* @param string $run_id Run ID this batch belongs to.
|
|
* @param array $product_ids WooCommerce product IDs in this batch.
|
|
*/
|
|
public function process_batch( $run_id, $product_ids = array() ) {
|
|
$run = get_option( self::RUN_OPTION, array() );
|
|
|
|
// A newer sync superseded this run (e.g. re-triggered manually) - drop it.
|
|
if ( empty( $run ) || ( $run['run_id'] ?? '' ) !== $run_id ) {
|
|
return;
|
|
}
|
|
|
|
$sync = new WBC_Product_Sync();
|
|
$sync->run_sync_for_ids( $product_ids );
|
|
$batch_results = $sync->get_results();
|
|
|
|
// Progress counters are best-effort: Action Scheduler can run batches
|
|
// concurrently, and update_option() read-modify-write isn't atomic.
|
|
// Good enough for a progress indicator; not used for anything
|
|
// correctness-critical.
|
|
$run = get_option( self::RUN_OPTION, $run );
|
|
if ( ( $run['run_id'] ?? '' ) !== $run_id ) {
|
|
return;
|
|
}
|
|
|
|
$run['batches_done'] = (int) ( $run['batches_done'] ?? 0 ) + 1;
|
|
$run['success'] = (int) ( $run['success'] ?? 0 ) + $batch_results['success'];
|
|
$run['failed'] = (int) ( $run['failed'] ?? 0 ) + $batch_results['failed'];
|
|
$run['skipped'] = (int) ( $run['skipped'] ?? 0 ) + $batch_results['skipped'];
|
|
$run['updated_at'] = current_time( 'timestamp' ); // phpcs:ignore WordPress.DateTime.CurrentTimeTimestamp -- staleness math only.
|
|
|
|
if ( $run['batches_done'] >= $run['total_batches'] ) {
|
|
$run['status'] = 'completed';
|
|
$run['finished_at'] = current_time( 'mysql' );
|
|
WBC_Cron::update_last_sync_time();
|
|
delete_transient( self::LOCK_TRANSIENT );
|
|
|
|
WBC_Logger::info( 'BatchSync', 'Background sync completed', $run );
|
|
}
|
|
|
|
update_option( self::RUN_OPTION, $run, false );
|
|
}
|
|
|
|
/**
|
|
* Get the current/last sync run status
|
|
*
|
|
* @return array Run status, or array('status' => 'none') if never run.
|
|
*/
|
|
public static function get_status() {
|
|
$run = get_option( self::RUN_OPTION, array() );
|
|
|
|
if ( empty( $run ) ) {
|
|
return array( 'status' => 'none' );
|
|
}
|
|
|
|
return $run;
|
|
}
|
|
}
|