Commit 6a7f8f41598 for woocommerce
commit 6a7f8f41598efad02bbc74941e0ab48174193317
Author: Seghir Nadir <nadir.seghir@gmail.com>
Date: Wed Aug 5 12:44:22 2026 +0200
Fix per-write log directory scans and order debug log cleanup rate (#66870)
* Fix per-write log directory scans and order debug log cleanup rate
* Add changelog entries for logging performance and cleanup fixes
* Bound order log cleanup to one batch per run and reschedule until drained
* Avoid redundant directory scans in the order log cleanup path
* Replace order cleanup global callback
* Update order logging filter since version
* Only treat pending actions as an already-scheduled extended cleanup
as_has_scheduled_action() also matches in-progress actions, so the
extended cleanup run matched itself and never scheduled its follow-up.
* Let OrderLogsCleanupHelper register its own extended cleanup hook
Resolve the helper alongside the other self-hooking services in
WooCommerce::init_hooks() instead of registering a global static
callback. The orders data store is now detected on demand so the early
resolution doesn't run the data store filters during boot.
* Detect the orders data store through OrderUtil
Replaces the hand-rolled lazy resolution added for the boot-time
container resolution: OrderUtil's accessors are already lazy, so the
memoization flag and the CustomOrdersTableController injection go away.
* Address review feedback on log cleanup
- Keep clear_logs_and_delete_meta()'s void return type and move the bool-returning
logic into a private method, so the public signature stays compatible.
- Log a warning when the log directory can't be enumerated for a stale-file sweep.
- Log a warning when debug log meta was expected to be deleted but no rows were.
- Correct the woocommerce_order_step_logging_enabled @since to 11.1.0.
* Target the order step logging filter at 11.0.1
---------
Co-authored-by: Seghir Nadir <nadir.seghir@a8c.com>
diff --git a/plugins/woocommerce/changelog/66815-add-order-step-logging-opt-out-filter b/plugins/woocommerce/changelog/66815-add-order-step-logging-opt-out-filter
new file mode 100644
index 00000000000..3879027ccaa
--- /dev/null
+++ b/plugins/woocommerce/changelog/66815-add-order-step-logging-opt-out-filter
@@ -0,0 +1,4 @@
+Significance: minor
+Type: add
+
+Add a woocommerce_order_step_logging_enabled filter that allows disabling per-order place-order-debug logging without raising the site-wide logging level threshold.
diff --git a/plugins/woocommerce/changelog/66815-fix-log-write-glob-and-order-log-cleanup b/plugins/woocommerce/changelog/66815-fix-log-write-glob-and-order-log-cleanup
new file mode 100644
index 00000000000..5ba6d7382b0
--- /dev/null
+++ b/plugins/woocommerce/changelog/66815-fix-log-write-glob-and-order-log-cleanup
@@ -0,0 +1,4 @@
+Significance: patch
+Type: performance
+
+Log writes no longer scan the whole wc-logs directory to locate their target file (the path is now constructed deterministically), and the daily place-order debug log cleanup now deletes a bounded batch per run and reschedules itself until the backlog is drained, instead of stopping at 100 files per day.
diff --git a/plugins/woocommerce/includes/class-woocommerce.php b/plugins/woocommerce/includes/class-woocommerce.php
index 3ca44822882..725bd86b7a9 100644
--- a/plugins/woocommerce/includes/class-woocommerce.php
+++ b/plugins/woocommerce/includes/class-woocommerce.php
@@ -37,6 +37,7 @@ use Automattic\WooCommerce\Internal\Admin\Marketplace;
use Automattic\WooCommerce\Internal\Admin\OrderMilestoneEasterEgg;
use Automattic\WooCommerce\Proxies\LegacyProxy;
use Automattic\WooCommerce\Utilities\{LoggingUtil, TimeUtil};
+use Automattic\WooCommerce\Internal\Logging\OrderLogsCleanupHelper;
use Automattic\WooCommerce\Internal\Logging\RemoteLogger;
use Automattic\WooCommerce\Caches\OrderCountCacheService;
use Automattic\WooCommerce\Caches\ProductCountCacheService;
@@ -389,6 +390,7 @@ final class WooCommerce {
$container->get( TaxRateVersionStringInvalidator::class );
$container->get( OrderMilestoneEasterEgg::class );
$container->get( CustomerEmailVerification::class );
+ $container->get( OrderLogsCleanupHelper::class );
// Feature flags.
if ( Constants::is_true( 'WOOCOMMERCE_BIS_ALPHA_ENABLED' ) ) {
diff --git a/plugins/woocommerce/includes/wc-order-step-logger-functions.php b/plugins/woocommerce/includes/wc-order-step-logger-functions.php
index 444d54a6e70..c405249ff88 100644
--- a/plugins/woocommerce/includes/wc-order-step-logger-functions.php
+++ b/plugins/woocommerce/includes/wc-order-step-logger-functions.php
@@ -37,7 +37,16 @@ function wc_log_order_step( string $message, ?array $context = null, bool $final
}
if ( $first_step ) {
- $logging_active = true;
+ /**
+ * Filters whether order step logging is enabled.
+ *
+ * Evaluated once per logging session, so that a checkout is either logged in full or not at all.
+ *
+ * @param bool $enabled Whether order step logging is enabled. Default true.
+ *
+ * @since 11.0.1
+ */
+ $logging_active = (bool) apply_filters( 'woocommerce_order_step_logging_enabled', true );
}
if ( ! $logging_active ) {
diff --git a/plugins/woocommerce/src/Internal/Admin/Logging/FileV2/FileController.php b/plugins/woocommerce/src/Internal/Admin/Logging/FileV2/FileController.php
index 30233a241eb..bab2ef924b2 100644
--- a/plugins/woocommerce/src/Internal/Admin/Logging/FileV2/FileController.php
+++ b/plugins/woocommerce/src/Internal/Admin/Logging/FileV2/FileController.php
@@ -5,6 +5,8 @@ namespace Automattic\WooCommerce\Internal\Admin\Logging\FileV2;
use Automattic\Jetpack\Constants;
use Automattic\WooCommerce\Internal\Admin\Logging\Settings;
+use Automattic\WooCommerce\Internal\Utilities\FilesystemUtil;
+use Exception;
use PclZip;
use WC_Cache_Helper;
use WP_Error;
@@ -115,22 +117,16 @@ class FileController {
$time = time();
}
- $file_id = File::generate_file_id( $source, null, $time );
- $file = $this->get_file_by_id( $file_id );
-
- if ( $file instanceof File && $file->get_file_size() >= $this->get_file_size_limit() ) {
- $rotated = $this->rotate_file( $file->get_file_id() );
+ $path = Settings::get_log_directory() . $this->generate_filename( $source, $time );
+ $file = new File( $path );
- if ( $rotated ) {
- $file = null;
- } else {
+ $size = $file->get_file_size();
+ if ( false !== $size && $size >= $this->get_file_size_limit() ) {
+ if ( ! $this->rotate_file( $file ) ) {
return false;
}
- }
- if ( ! $file instanceof File ) {
- $new_path = Settings::get_log_directory() . $this->generate_filename( $source, $time );
- $file = new File( $new_path );
+ $file = new File( $path );
}
return $file->write( $text );
@@ -154,16 +150,12 @@ class FileController {
/**
* Get all the rotations of a file and increment them, so that they overwrite the previous file with that rotation.
*
- * @param string $file_id A file ID (file basename without the hash).
+ * @param File $file The un-rotated ("current") iteration of the file to rotate.
*
* @return bool True if the file and all its rotations were successfully rotated.
*/
- private function rotate_file( $file_id ): bool {
- $rotations = $this->get_file_rotations( $file_id );
-
- if ( is_wp_error( $rotations ) || ! isset( $rotations['current'] ) ) {
- return false;
- }
+ private function rotate_file( File $file ): bool {
+ $rotations = $this->get_rotation_siblings( $file );
$max_rotation_marker = self::MAX_FILE_ROTATIONS - 1;
@@ -177,7 +169,7 @@ class FileController {
$results[] = $rotations[ $i ]->rotate();
}
}
- $results[] = $rotations['current']->rotate();
+ $results[] = $file->rotate();
return ! in_array( false, $results, true );
}
@@ -403,25 +395,43 @@ class FileController {
return $file;
}
- $current = array();
- $rotations = array();
-
- $source = $file->get_source();
- $created = 0;
- if ( $file->has_standard_filename() ) {
- $created = $file->get_created_timestamp();
- }
+ $current = array();
if ( is_null( $file->get_rotation() ) ) {
$current['current'] = $file;
} else {
- $current_file_id = File::generate_file_id( $source, null, $created );
+ $current_file_id = File::generate_file_id( $file->get_source(), null, $this->get_filename_timestamp( $file ) );
$result = $this->get_file_by_id( $current_file_id );
if ( ! is_wp_error( $result ) ) {
$current['current'] = $result;
}
}
+ return array_merge( $current, $this->get_rotation_siblings( $file ) );
+ }
+
+ /**
+ * Get the creation timestamp encoded in a file's name, or 0 if it doesn't use the standard format.
+ *
+ * @param File $file The file to get the timestamp from.
+ *
+ * @return int
+ */
+ private function get_filename_timestamp( File $file ): int {
+ return $file->has_standard_filename() ? $file->get_created_timestamp() : 0;
+ }
+
+ /**
+ * Get File instances for the existing rotations of a file.
+ *
+ * @param File $file Any iteration of a file, from which the source and creation date are taken.
+ *
+ * @return File[] An associative array where the rotation integer of the file is the key, sorted by rotation.
+ */
+ private function get_rotation_siblings( File $file ): array {
+ $source = $file->get_source();
+ $created = $this->get_filename_timestamp( $file );
+
$rotations_pattern = sprintf(
'.[%s]',
implode(
@@ -435,6 +445,8 @@ class FileController {
$rotation_pattern = Settings::get_log_directory() . $source . $rotations_pattern . $created_pattern . '*.log';
$rotation_paths = glob( $rotation_pattern );
$rotation_files = $this->convert_paths_to_objects( $rotation_paths );
+
+ $rotations = array();
foreach ( $rotation_files as $rotation_file ) {
if ( $rotation_file->is_readable() ) {
$rotations[ $rotation_file->get_rotation() ] = $rotation_file;
@@ -443,7 +455,7 @@ class FileController {
ksort( $rotations );
- return array_merge( $current, $rotations );
+ return $rotations;
}
/**
@@ -516,6 +528,74 @@ class FileController {
return $deleted;
}
+ /**
+ * Delete files of a given source that were last modified before a given time.
+ *
+ * Files are enumerated lazily and are neither sorted nor turned into File instances, so this
+ * stays cheap on directories holding a large number of files, unlike get_files().
+ *
+ * @param string $source Match files whose name begins with this source.
+ * @param int $modified_before Only delete files modified before this Unix timestamp.
+ * @param int $limit The maximum number of files to delete.
+ *
+ * @return int The number of files that were deleted.
+ */
+ public function delete_stale_files( string $source, int $modified_before, int $limit ): int {
+ if ( '' === $source || $limit < 1 ) {
+ return 0;
+ }
+
+ try {
+ $filesystem = FilesystemUtil::get_wp_filesystem_direct();
+ $iterator = new \FilesystemIterator(
+ Settings::get_log_directory(),
+ \FilesystemIterator::SKIP_DOTS | \FilesystemIterator::CURRENT_AS_PATHNAME | \FilesystemIterator::KEY_AS_FILENAME
+ );
+ } catch ( Exception $exception ) {
+ // Surface this so a persistent failure to reach the log directory doesn't stay silent.
+ wc_get_logger()->warning(
+ sprintf(
+ 'Could not enumerate the log directory to delete stale "%1$s" files: %2$s',
+ $source,
+ $exception->getMessage()
+ ),
+ array( 'source' => 'wc-logs-cleanup' )
+ );
+
+ return 0;
+ }
+
+ $deleted = 0;
+
+ foreach ( $iterator as $basename => $path ) {
+ if ( ! str_starts_with( (string) $basename, $source ) || ! str_ends_with( (string) $basename, '.log' ) ) {
+ continue;
+ }
+
+ $path = (string) $path;
+
+ $modified = $filesystem->mtime( $path );
+
+ if ( false === $modified || $modified >= $modified_before ) {
+ continue;
+ }
+
+ if ( $filesystem->delete( $path, false, 'f' ) ) {
+ ++$deleted;
+ }
+
+ if ( $deleted >= $limit ) {
+ break;
+ }
+ }
+
+ if ( $deleted > 0 ) {
+ $this->invalidate_cache();
+ }
+
+ return $deleted;
+ }
+
/**
* Stream a single file to the browser without zipping it first.
*
diff --git a/plugins/woocommerce/src/Internal/Logging/OrderLogsCleanupHelper.php b/plugins/woocommerce/src/Internal/Logging/OrderLogsCleanupHelper.php
index c8cebd525fd..c231b41603f 100644
--- a/plugins/woocommerce/src/Internal/Logging/OrderLogsCleanupHelper.php
+++ b/plugins/woocommerce/src/Internal/Logging/OrderLogsCleanupHelper.php
@@ -4,8 +4,11 @@ declare( strict_types=1 );
namespace Automattic\WooCommerce\Internal\Logging;
-use Automattic\WooCommerce\Internal\DataStores\Orders\CustomOrdersTableController;
+use Automattic\WooCommerce\Internal\Admin\Logging\FileV2\FileController;
+use Automattic\WooCommerce\Internal\Admin\Logging\LogHandlerFileV2;
use Automattic\WooCommerce\Internal\DataStores\Orders\DataSynchronizer;
+use Automattic\WooCommerce\Utilities\LoggingUtil;
+use Automattic\WooCommerce\Utilities\OrderUtil;
use WC_Logger;
/**
@@ -18,7 +21,7 @@ class OrderLogsCleanupHelper {
/**
* Maximum number of log files to delete per run.
*/
- public const MAX_FILES_PER_RUN = 100;
+ public const MAX_FILES_PER_RUN = 1000;
/**
* Maximum number of orders to clean up per run.
@@ -26,18 +29,14 @@ class OrderLogsCleanupHelper {
public const MAX_ORDERS_PER_RUN = 100;
/**
- * True if HPOS is enabled.
- *
- * @var bool
+ * Hook of the action scheduled to continue a cleanup that didn't drain the backlog.
*/
- private bool $hpos_in_use = false;
+ public const EXTENDED_CLEANUP_HOOK = 'woocommerce_cleanup_logs_extended';
/**
- * True if HPOS is disabled and the orders data store in use is the old CPT one.
- *
- * @var bool
+ * Delay, in seconds, before a follow-up cleanup run.
*/
- private bool $cpt_in_use = false;
+ private const EXTENDED_CLEANUP_DELAY = 5 * MINUTE_IN_SECONDS;
/**
* The instance of DataSynchronizer to use.
@@ -47,23 +46,19 @@ class OrderLogsCleanupHelper {
private DataSynchronizer $data_synchronizer;
/**
- * Initialize the instance.
+ * Initialize the instance and register hooks.
* This is invoked by the dependency injection container.
*
* @internal
*
- * @param CustomOrdersTableController $hpos_controller The instance of CustomOrdersTableController to use.
- * @param DataSynchronizer $data_synchronizer The instance of DataSynchronizer to use.
+ * @param DataSynchronizer $data_synchronizer The instance of DataSynchronizer to use.
*
* @return void
*/
- final public function init( CustomOrdersTableController $hpos_controller, DataSynchronizer $data_synchronizer ): void {
- $this->hpos_in_use = $hpos_controller->custom_orders_table_usage_is_enabled();
- if ( ! $this->hpos_in_use ) {
- $this->cpt_in_use = \WC_Order_Data_Store_CPT::class === \WC_Data_Store::load( 'order' )->get_current_class_name();
- }
-
+ final public function init( DataSynchronizer $data_synchronizer ): void {
$this->data_synchronizer = $data_synchronizer;
+
+ add_action( self::EXTENDED_CLEANUP_HOOK, array( $this, 'cleanup' ) );
}
/**
@@ -87,6 +82,8 @@ class OrderLogsCleanupHelper {
/**
* Run all cleanup tasks: dangling order meta and old log files.
*
+ * Also the callback for the extended cleanup action.
+ *
* @since 10.7.0
*/
public function cleanup(): void {
@@ -96,42 +93,88 @@ class OrderLogsCleanupHelper {
return;
}
- // Dangling orders have `_debug_log_source` meta but no `_debug_log_source_pending_deletion`.
+ $files_swept_in_bulk = LogHandlerFileV2::class === LoggingUtil::get_default_handler();
+
+ $more_files = $files_swept_in_bulk && $this->cleanup_old_log_files( $max_age );
+ $more_orders = $this->cleanup_dangling_orders( $max_age, $files_swept_in_bulk );
+
+ // Each run handles a single batch, so that it can't grow unbounded on a large
+ // backlog. Anything left over is picked up by a follow-up run a few minutes later.
+ if ( $more_files || $more_orders ) {
+ $this->schedule_extended_cleanup();
+ }
+ }
+
+ /**
+ * Clean up a batch of orders with dangling debug log meta.
+ *
+ * Dangling orders have `_debug_log_source` meta but no `_debug_log_source_pending_deletion`.
+ *
+ * @param int $max_age Maximum age in seconds before an order's debug log meta is eligible for cleanup.
+ * @param bool $files_swept_in_bulk True if the file sweep is already deleting these orders' log files.
+ *
+ * @return bool True if there may be more orders left to clean up.
+ */
+ private function cleanup_dangling_orders( int $max_age, bool $files_swept_in_bulk ): bool {
$dangling_orders = $this->get_dangling_orders( $max_age );
- $this->clear_logs_and_delete_meta( $dangling_orders );
- // Old log files are those that are older than the given max age.
- $this->cleanup_old_log_files( $max_age );
+ if ( empty( $dangling_orders ) ) {
+ return false;
+ }
+
+ // Clearing each order's log source individually scans the log directory once per
+ // order, so it's only worth doing when the bulk sweep isn't deleting the files.
+ $deleted = $files_swept_in_bulk
+ ? $this->delete_debug_log_meta_entries( array_keys( $dangling_orders ) )
+ : $this->clear_logs_and_delete_meta_entries( $dangling_orders );
+
+ return $deleted && self::MAX_ORDERS_PER_RUN === count( $dangling_orders );
}
/**
- * Delete place-order-debug-* log files from the filesystem.
+ * Delete a batch of place-order-debug-* log files from the filesystem.
*
* @param int $max_age Maximum age in seconds before a file is eligible for deletion.
+ *
+ * @return bool True if there may be more files left to delete.
+ */
+ private function cleanup_old_log_files( int $max_age ): bool {
+ $deleted = wc_get_container()->get( FileController::class )->delete_stale_files(
+ 'place-order-debug',
+ time() - $max_age,
+ self::MAX_FILES_PER_RUN
+ );
+
+ return self::MAX_FILES_PER_RUN === $deleted;
+ }
+
+ /**
+ * Schedule a follow-up cleanup run to continue draining the backlog.
*/
- private function cleanup_old_log_files( int $max_age ): void {
- if ( \Automattic\WooCommerce\Utilities\LoggingUtil::get_default_handler() !== \Automattic\WooCommerce\Internal\Admin\Logging\LogHandlerFileV2::class ) {
+ private function schedule_extended_cleanup(): void {
+ if ( ! function_exists( 'as_schedule_single_action' ) || ! function_exists( 'as_get_scheduled_actions' ) ) {
return;
}
- $file_controller = wc_get_container()->get( \Automattic\WooCommerce\Internal\Admin\Logging\FileV2\FileController::class );
- $files = $file_controller->get_files(
+ // Only pending actions count: when this runs as the extended cleanup callback, the
+ // current action is in-progress and would otherwise match, blocking the follow-up.
+ $pending = as_get_scheduled_actions(
array(
- 'source' => 'place-order-debug',
- 'date_filter' => 'modified',
- 'date_start' => 1,
- 'date_end' => time() - $max_age,
- 'per_page' => self::MAX_FILES_PER_RUN,
- )
+ 'hook' => self::EXTENDED_CLEANUP_HOOK,
+ 'args' => array(),
+ 'group' => 'woocommerce',
+ 'status' => \ActionScheduler_Store::STATUS_PENDING,
+ 'per_page' => 1,
+ 'orderby' => 'none',
+ ),
+ 'ids'
);
- if ( ! is_array( $files ) ) {
+ if ( $pending ) {
return;
}
- foreach ( $files as $file ) {
- $file->delete();
- }
+ as_schedule_single_action( time() + self::EXTENDED_CLEANUP_DELAY, self::EXTENDED_CLEANUP_HOOK, array(), 'woocommerce' );
}
/**
@@ -145,8 +188,22 @@ class OrderLogsCleanupHelper {
* @return void
*/
public function clear_logs_and_delete_meta( array $items ): void {
+ $this->clear_logs_and_delete_meta_entries( $items );
+ }
+
+ /**
+ * Clear debug log files and delete associated order meta for the given items, reporting whether anything
+ * was deleted.
+ *
+ * This backs the public clear_logs_and_delete_meta(), whose `void` return type is kept for compatibility.
+ *
+ * @param array $items Associative array of order ID => log source name.
+ *
+ * @return bool True if any meta entries were deleted.
+ */
+ private function clear_logs_and_delete_meta_entries( array $items ): bool {
if ( empty( $items ) ) {
- return;
+ return false;
}
$logger = wc_get_logger();
@@ -156,8 +213,7 @@ class OrderLogsCleanupHelper {
}
}
- $order_ids = array_keys( $items );
- $this->delete_debug_log_meta_entries( $order_ids );
+ return $this->delete_debug_log_meta_entries( array_keys( $items ) );
}
/**
@@ -171,19 +227,20 @@ class OrderLogsCleanupHelper {
* @return array Associative array of order ID => log source name.
*/
private function get_dangling_orders( int $max_age ): array {
- if ( ! $this->hpos_in_use && ! $this->cpt_in_use ) {
+ if ( OrderUtil::unknown_orders_data_store_in_use() ) {
return array();
}
global $wpdb;
+ $hpos_in_use = OrderUtil::custom_orders_table_usage_is_enabled();
$cutoff_date = gmdate( 'Y-m-d H:i:s', time() - $max_age );
- $meta_table = $this->hpos_in_use ? "{$wpdb->prefix}wc_orders_meta" : $wpdb->postmeta;
- $order_table = $this->hpos_in_use ? "{$wpdb->prefix}wc_orders" : $wpdb->posts;
- $id_column = $this->hpos_in_use ? 'order_id' : 'post_id';
- $type_column = $this->hpos_in_use ? 'type' : 'post_type';
- $date_column = $this->hpos_in_use ? 'date_created_gmt' : 'post_date_gmt';
+ $meta_table = $hpos_in_use ? "{$wpdb->prefix}wc_orders_meta" : $wpdb->postmeta;
+ $order_table = $hpos_in_use ? "{$wpdb->prefix}wc_orders" : $wpdb->posts;
+ $id_column = $hpos_in_use ? 'order_id' : 'post_id';
+ $type_column = $hpos_in_use ? 'type' : 'post_type';
+ $date_column = $hpos_in_use ? 'date_created_gmt' : 'post_date_gmt';
// phpcs:disable WordPress.DB.PreparedSQL.InterpolatedNotPrepared
$rows = $wpdb->get_results(
@@ -212,29 +269,35 @@ class OrderLogsCleanupHelper {
* from the authoritative table and the backup table (when data sync is enabled).
*
* @param array $order_ids Array of order IDs to delete meta for.
+ *
+ * @return bool True if any meta entries were deleted.
*/
- private function delete_debug_log_meta_entries( array $order_ids ): void {
+ private function delete_debug_log_meta_entries( array $order_ids ): bool {
global $wpdb;
+ $hpos_in_use = OrderUtil::custom_orders_table_usage_is_enabled();
+
$tables = array(
array(
- 'table' => $this->hpos_in_use ? "{$wpdb->prefix}wc_orders_meta" : $wpdb->postmeta,
- 'id_column' => $this->hpos_in_use ? 'order_id' : 'post_id',
+ 'table' => $hpos_in_use ? "{$wpdb->prefix}wc_orders_meta" : $wpdb->postmeta,
+ 'id_column' => $hpos_in_use ? 'order_id' : 'post_id',
),
);
if ( $this->data_synchronizer->data_sync_is_enabled() ) {
$tables[] = array(
- 'table' => $this->hpos_in_use ? $wpdb->postmeta : "{$wpdb->prefix}wc_orders_meta",
- 'id_column' => $this->hpos_in_use ? 'post_id' : 'order_id',
+ 'table' => $hpos_in_use ? $wpdb->postmeta : "{$wpdb->prefix}wc_orders_meta",
+ 'id_column' => $hpos_in_use ? 'post_id' : 'order_id',
);
}
$id_placeholders = implode( ',', array_fill( 0, count( $order_ids ), '%d' ) );
+ $deleted = false;
+
foreach ( $tables as $table_config ) {
// phpcs:disable WordPress.DB.PreparedSQL.InterpolatedNotPrepared, WordPress.DB.PreparedSQLPlaceholders.ReplacementsWrongNumber
- $wpdb->query(
+ $result = $wpdb->query(
$wpdb->prepare(
"DELETE FROM {$table_config['table']}
WHERE {$table_config['id_column']} IN ({$id_placeholders})
@@ -243,6 +306,24 @@ class OrderLogsCleanupHelper {
)
);
// phpcs:enable WordPress.DB.PreparedSQL.InterpolatedNotPrepared, WordPress.DB.PreparedSQLPlaceholders.ReplacementsWrongNumber
+
+ if ( is_int( $result ) && $result > 0 ) {
+ $deleted = true;
+ }
}
+
+ if ( ! $deleted ) {
+ // These IDs came from a query that just matched them on `_debug_log_source`, so deleting nothing
+ // means either another process got there first or the writes are failing. Worth surfacing either way.
+ wc_get_logger()->warning(
+ sprintf(
+ 'Expected to delete debug log meta for %d order(s), but no rows were removed.',
+ count( $order_ids )
+ ),
+ array( 'source' => 'wc-logs-cleanup' )
+ );
+ }
+
+ return $deleted;
}
}
diff --git a/plugins/woocommerce/tests/php/includes/wc-order-step-logger-functions-test.php b/plugins/woocommerce/tests/php/includes/wc-order-step-logger-functions-test.php
index 9d85819417b..b12457a823f 100644
--- a/plugins/woocommerce/tests/php/includes/wc-order-step-logger-functions-test.php
+++ b/plugins/woocommerce/tests/php/includes/wc-order-step-logger-functions-test.php
@@ -308,4 +308,43 @@ class WC_Order_Step_Logger_Functions_Test extends \WC_Unit_Test_Case {
// Clean up the order.
$order->delete( true );
}
+
+ /**
+ * @testdox Order step logging can be disabled entirely via the woocommerce_order_step_logging_enabled filter.
+ */
+ public function test_wc_log_order_step_can_be_disabled_via_filter(): void {
+ Constants::set_constant( 'WC_LOG_THRESHOLD', WC_Log_Levels::DEBUG );
+
+ add_filter( 'woocommerce_order_step_logging_enabled', '__return_false' );
+
+ $order = WC_Helper_Order::create_order();
+
+ wc_log_order_step(
+ 'Step 1 - should not be logged',
+ array( 'order_object' => $order ),
+ false,
+ true
+ );
+
+ wc_log_order_step(
+ 'Step 2 - Final - should not be logged',
+ array( 'order_object' => $order ),
+ true,
+ false
+ );
+
+ remove_filter( 'woocommerce_order_step_logging_enabled', '__return_false' );
+
+ $this->assertEmpty(
+ $this->get_log_files(),
+ 'Expected no log files to be created when order step logging is disabled via filter'
+ );
+
+ $this->assertEmpty(
+ $order->get_meta( '_debug_log_source' ),
+ 'Expected no debug log meta to be added to the order when order step logging is disabled via filter'
+ );
+
+ $order->delete( true );
+ }
}
diff --git a/plugins/woocommerce/tests/php/src/Internal/Admin/Logging/FileV2/FileControllerTest.php b/plugins/woocommerce/tests/php/src/Internal/Admin/Logging/FileV2/FileControllerTest.php
index 838c4351aa0..f799a800910 100644
--- a/plugins/woocommerce/tests/php/src/Internal/Admin/Logging/FileV2/FileControllerTest.php
+++ b/plugins/woocommerce/tests/php/src/Internal/Admin/Logging/FileV2/FileControllerTest.php
@@ -99,13 +99,14 @@ class FileControllerTest extends WC_Unit_Test_Case {
* @testdox The write_to_file method should append content to an existing file of the correct source that isn't rotated.
*/
public function test_write_to_file_existing() {
- $time = time();
- $hash = wp_hash( 'cheddar' );
+ $time = time();
+ $file_id = File::generate_file_id( 'unit-testing', null, $time );
+ $hash = File::generate_hash( $file_id );
$existing_files = array(
- 'target' => 'unit-testing-' . gmdate( 'Y-m-d', $time ) . '-' . $hash . '.log',
- 'other1' => 'unit-testing.0-' . gmdate( 'Y-m-d', $time ) . '-' . $hash . '.log',
- 'other2' => 'unit-testing-' . gmdate( 'Y-m-d', strtotime( '-2 days' ) ) . '-' . $hash . '.log',
+ 'target' => $file_id . '-' . $hash . '.log',
+ 'other1' => 'unit-testing.0-' . gmdate( 'Y-m-d', $time ) . '-' . wp_hash( 'cheddar' ) . '.log',
+ 'other2' => 'unit-testing-' . gmdate( 'Y-m-d', strtotime( '-2 days' ) ) . '-' . wp_hash( 'cheddar' ) . '.log',
);
foreach ( $existing_files as $filename ) {
$path = Settings::get_log_directory() . $filename;
@@ -135,8 +136,9 @@ class FileControllerTest extends WC_Unit_Test_Case {
* @testdox The write_to_file method should rotate a file that has reached the size limit and then write the content to a fresh file.
*/
public function test_write_to_file_needs_rotation() {
- $time = time();
- $path = Settings::get_log_directory() . 'unit-testing-' . gmdate( 'Y-m-d', $time ) . '-' . wp_hash( 'cheddar' ) . '.log';
+ $time = time();
+ $file_id = File::generate_file_id( 'unit-testing', null, $time );
+ $path = Settings::get_log_directory() . $file_id . '-' . File::generate_hash( $file_id ) . '.log';
$resource = fopen( $path, 'a' );
$existing_content = random_bytes( 200 ) . "\n";
@@ -182,6 +184,81 @@ class FileControllerTest extends WC_Unit_Test_Case {
remove_filter( 'woocommerce_log_file_size_limit', $filter_callback );
}
+ /**
+ * @testdox The delete_stale_files method should only delete files of the given source that are older than the given time, up to the limit.
+ */
+ public function test_delete_stale_files() {
+ $directory = Settings::get_log_directory();
+ $old_time = time() - 4 * DAY_IN_SECONDS;
+
+ $paths = array(
+ 'stale1' => $directory . 'unit-testing-a-2025-01-01-' . wp_hash( 'a' ) . '.log',
+ 'stale2' => $directory . 'unit-testing-b-2025-01-01-' . wp_hash( 'b' ) . '.log',
+ 'recent' => $directory . 'unit-testing-c-2025-01-01-' . wp_hash( 'c' ) . '.log',
+ 'other_source' => $directory . 'other-source-2025-01-01-' . wp_hash( 'd' ) . '.log',
+ );
+
+ foreach ( $paths as $key => $path ) {
+ file_put_contents( $path, 'entry' ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_file_put_contents
+ if ( 'recent' !== $key ) {
+ touch( $path, $old_time ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ }
+ }
+ clearstatcache();
+
+ $deleted = $this->sut->delete_stale_files( 'unit-testing', time() - DAY_IN_SECONDS, 10 );
+
+ $this->assertEquals( 2, $deleted );
+ $this->assertFileDoesNotExist( $paths['stale1'] );
+ $this->assertFileDoesNotExist( $paths['stale2'] );
+ $this->assertFileExists( $paths['recent'], 'Files newer than the cutoff should be kept' );
+ $this->assertFileExists( $paths['other_source'], 'Files of other sources should be kept' );
+ }
+
+ /**
+ * @testdox The delete_stale_files method should not delete more files than the given limit.
+ */
+ public function test_delete_stale_files_respects_limit() {
+ $directory = Settings::get_log_directory();
+ $old_time = time() - 4 * DAY_IN_SECONDS;
+
+ for ( $i = 0; $i < 5; $i++ ) {
+ $path = $directory . "unit-testing-{$i}-2025-01-01-" . wp_hash( (string) $i ) . '.log';
+ file_put_contents( $path, 'entry' ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_file_put_contents
+ touch( $path, $old_time ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ }
+ clearstatcache();
+
+ $deleted = $this->sut->delete_stale_files( 'unit-testing', time() - DAY_IN_SECONDS, 3 );
+
+ $this->assertEquals( 3, $deleted );
+ $this->assertCount( 2, glob( $directory . '*.log' ) );
+ }
+
+ /**
+ * @testdox The write_to_file method should leave a file with a stale hash suffix alone and write to a new file with the current hash.
+ */
+ public function test_write_to_file_hash_mismatch_creates_new_file() {
+ $time = time();
+ $file_id = File::generate_file_id( 'unit-testing', null, $time );
+ $stale_path = Settings::get_log_directory() . $file_id . '-' . wp_hash( 'cheddar' ) . '.log';
+
+ file_put_contents( $stale_path, "stale\n" ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_file_put_contents
+
+ $result = $this->sut->write_to_file( 'unit-testing', 'test', $time );
+ $this->assertTrue( $result );
+
+ $paths = glob( Settings::get_log_directory() . '*.log' );
+ $this->assertCount( 2, $paths, 'A new file with the current hash should be created next to the stale one' );
+
+ // phpcs:ignore WordPress.WP.AlternativeFunctions.file_get_contents_file_get_contents
+ $this->assertEquals( "stale\n", file_get_contents( $stale_path ), 'The stale file should not receive new entries' );
+
+ $current_path = Settings::get_log_directory() . $file_id . '-' . File::generate_hash( $file_id ) . '.log';
+ // phpcs:ignore WordPress.WP.AlternativeFunctions.file_get_contents_file_get_contents
+ $this->assertEquals( "test\n", file_get_contents( $current_path ), 'The new entry should be written to a file with the current hash' );
+ }
+
/**
* @testdox The get_files method should retrieve log files as File instances, in a specified order.
*/
diff --git a/plugins/woocommerce/tests/php/src/Internal/Logging/OrderLogsCleanupTest.php b/plugins/woocommerce/tests/php/src/Internal/Logging/OrderLogsCleanupTest.php
index ac2d286da6b..670b1479406 100644
--- a/plugins/woocommerce/tests/php/src/Internal/Logging/OrderLogsCleanupTest.php
+++ b/plugins/woocommerce/tests/php/src/Internal/Logging/OrderLogsCleanupTest.php
@@ -113,6 +113,7 @@ class OrderLogsCleanupTest extends \WC_Unit_Test_Case {
$wpdb->delete( $wpdb->postmeta, array( 'meta_key' => '_debug_log_source' ) );
self::delete_all_log_files();
+ as_unschedule_all_actions( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK );
$this->sut = $this->container->get( OrderLogsDeletionProcessor::class );
$this->sut_cleanup_helper = $this->container->get( OrderLogsCleanupHelper::class );
@@ -132,6 +133,7 @@ class OrderLogsCleanupTest extends \WC_Unit_Test_Case {
*/
public function tearDown(): void {
self::delete_all_log_files();
+ as_unschedule_all_actions( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK );
parent::tearDown();
if ( $this->data_store_filter_callback ) {
remove_filter( 'woocommerce_order_data_store', $this->data_store_filter_callback, 99999 );
@@ -475,6 +477,8 @@ class OrderLogsCleanupTest extends \WC_Unit_Test_Case {
// Backdate the "old" file's modification time to 4 days ago.
touch( $old_files[0]->get_path(), time() - 4 * DAY_IN_SECONDS ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ // Drop the stale stat cache entry from before the touch.
+ clearstatcache();
$recent_files = $file_controller->get_files( array( 'source' => 'place-order-debug-recent' ) );
$this->assertCount( 1, $recent_files );
@@ -535,10 +539,240 @@ class OrderLogsCleanupTest extends \WC_Unit_Test_Case {
$this->assertEquals( 'place-order-debug-fresh', $recent_order_reloaded->get_meta( '_debug_log_source' ) );
}
+ /**
+ * @testdox cleanup() deletes one batch of old log files per run and schedules a follow-up run to drain the rest.
+ */
+ public function test_cleanup_deletes_one_batch_of_log_files_and_reschedules(): void {
+ $file_controller = wc_get_container()->get( FileController::class );
+ $log_directory = Settings::get_log_directory();
+
+ $extra = 5;
+ $file_count = OrderLogsCleanupHelper::MAX_FILES_PER_RUN + $extra;
+ $date = gmdate( 'Y-m-d', strtotime( '-4 days' ) );
+ $old_time = time() - 4 * DAY_IN_SECONDS;
+
+ // Create the files directly; going through the logger would be much slower.
+ for ( $i = 0; $i < $file_count; $i++ ) {
+ $path = $log_directory . "place-order-debug-{$i}-{$date}-" . md5( (string) $i ) . '.log';
+ file_put_contents( $path, 'entry' ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_file_put_contents
+ touch( $path, $old_time ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ }
+ // Drop the stale stat cache entry from before the touch.
+ clearstatcache();
+
+ $this->assertEquals( $file_count, $file_controller->get_files( array( 'source' => 'place-order-debug' ), true ) );
+
+ $this->sut_cleanup_helper->cleanup();
+
+ $this->assertEquals(
+ $extra,
+ $file_controller->get_files( array( 'source' => 'place-order-debug' ), true ),
+ 'Only one batch should be deleted per run'
+ );
+ $this->assertTrue(
+ as_has_scheduled_action( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK, array(), 'woocommerce' ),
+ 'A follow-up run should be scheduled while files remain'
+ );
+
+ as_unschedule_all_actions( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK );
+ $this->sut_cleanup_helper->cleanup();
+
+ $this->assertEquals(
+ 0,
+ $file_controller->get_files( array( 'source' => 'place-order-debug' ), true ),
+ 'The follow-up run should delete the remaining files'
+ );
+ $this->assertFalse(
+ as_has_scheduled_action( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK, array(), 'woocommerce' ),
+ 'No follow-up run should be scheduled once the backlog is drained'
+ );
+ }
+
+ /**
+ * @testdox cleanup() deletes one batch of dangling order meta per run and schedules a follow-up run to drain the rest.
+ */
+ public function test_cleanup_deletes_one_batch_of_dangling_orders_and_reschedules(): void {
+ $this->setup_hpos_and_reset_container( true );
+
+ $extra = 5;
+ $order_count = OrderLogsCleanupHelper::MAX_ORDERS_PER_RUN + $extra;
+
+ for ( $i = 0; $i < $order_count; $i++ ) {
+ $order = wc_create_order();
+ $order->set_date_created( strtotime( '-5 days' ) );
+ $order->add_meta_data( '_debug_log_source', 'place-order-debug-drain-' . $i, true );
+ $order->save();
+ }
+
+ $this->assertEquals( $order_count, $this->count_debug_log_source_meta_entries() );
+
+ $this->sut_cleanup_helper->cleanup();
+
+ $this->assertEquals(
+ $extra,
+ $this->count_debug_log_source_meta_entries(),
+ 'Only one batch should be cleaned up per run'
+ );
+ $this->assertTrue(
+ as_has_scheduled_action( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK, array(), 'woocommerce' ),
+ 'A follow-up run should be scheduled while dangling orders remain'
+ );
+
+ as_unschedule_all_actions( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK );
+ $this->sut_cleanup_helper->cleanup();
+
+ $this->assertEquals(
+ 0,
+ $this->count_debug_log_source_meta_entries(),
+ 'The follow-up run should clean up the remaining orders'
+ );
+ }
+
+ /**
+ * @testdox The cleanup helper registers the extended cleanup callback when the container initializes it.
+ */
+ public function test_extended_cleanup_hook_is_registered_on_init(): void {
+ $this->assertNotFalse(
+ has_action( OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK, array( $this->sut_cleanup_helper, 'cleanup' ) )
+ );
+ }
+
+ /**
+ * @testdox An in-progress extended cleanup run still schedules the next follow-up run.
+ */
+ public function test_extended_cleanup_schedules_a_follow_up_while_running(): void {
+ $this->setup_hpos_and_reset_container( true );
+
+ // Two full batches, so the second run still has a batch left to hand over.
+ for ( $i = 0; $i < 2 * OrderLogsCleanupHelper::MAX_ORDERS_PER_RUN; $i++ ) {
+ $order = wc_create_order();
+ $order->set_date_created( strtotime( '-5 days' ) );
+ $order->add_meta_data( '_debug_log_source', 'place-order-debug-running-' . $i, true );
+ $order->save();
+ }
+
+ $this->sut_cleanup_helper->cleanup();
+ $first = $this->get_pending_extended_cleanup_ids();
+ $this->assertCount( 1, $first );
+
+ // Simulate the queue runner picking the action up, then run it.
+ \ActionScheduler::store()->log_execution( current( $first ) );
+ $this->sut_cleanup_helper->cleanup();
+
+ $second = $this->get_pending_extended_cleanup_ids();
+ $this->assertCount( 1, $second, 'A follow-up run should be scheduled while the current one is in progress' );
+ $this->assertNotEquals( current( $first ), current( $second ) );
+
+ // as_unschedule_all_actions() only cancels pending actions, so drop the in-progress one here.
+ \ActionScheduler::store()->delete_action( current( $first ) );
+ }
+
+ /**
+ * Get the IDs of the pending extended cleanup actions.
+ *
+ * @return array
+ */
+ private function get_pending_extended_cleanup_ids(): array {
+ return as_get_scheduled_actions(
+ array(
+ 'hook' => OrderLogsCleanupHelper::EXTENDED_CLEANUP_HOOK,
+ 'args' => array(),
+ 'group' => 'woocommerce',
+ 'status' => \ActionScheduler_Store::STATUS_PENDING,
+ 'per_page' => 5,
+ ),
+ 'ids'
+ );
+ }
+
+ /**
+ * Count the `_debug_log_source` meta entries in the HPOS orders meta table.
+ *
+ * @return int
+ */
+ private function count_debug_log_source_meta_entries(): int {
+ global $wpdb;
+
+ // phpcs:disable WordPress.DB.SlowDBQuery
+ return (int) $wpdb->get_var(
+ $wpdb->prepare(
+ "SELECT COUNT(*) FROM {$wpdb->prefix}wc_orders_meta WHERE meta_key = %s", // phpcs:ignore WordPress.DB.PreparedSQL.InterpolatedNotPrepared
+ '_debug_log_source'
+ )
+ );
+ // phpcs:enable WordPress.DB.SlowDBQuery
+ }
+
+ /**
+ * @testdox cleanup() removes both the meta and the log file of a dangling order when the FileV2 handler is the default.
+ */
+ public function test_cleanup_removes_dangling_order_meta_and_file_with_file_v2_handler(): void {
+ $handler = new LogHandlerFileV2();
+ $file_controller = wc_get_container()->get( FileController::class );
+
+ $order = OrderHelper::create_order();
+ $order->set_date_created( strtotime( '-5 days' ) );
+ $order->add_meta_data( '_debug_log_source', 'place-order-debug-dangling', true );
+ $order->save();
+
+ $handler->handle( time(), 'debug', 'a step', array( 'source' => 'place-order-debug-dangling' ) );
+ $files = $file_controller->get_files( array( 'source' => 'place-order-debug-dangling' ) );
+ $this->assertCount( 1, $files );
+ touch( $files[0]->get_path(), time() - 4 * DAY_IN_SECONDS ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ // Drop the stale stat cache entry from before the touch.
+ clearstatcache();
+
+ $this->sut_cleanup_helper->cleanup();
+
+ $order_reloaded = wc_get_order( $order->get_id() );
+ $this->assertEmpty( $order_reloaded->get_meta( '_debug_log_source' ) );
+ $this->assertCount(
+ 0,
+ $file_controller->get_files( array( 'source' => 'place-order-debug-dangling' ) ),
+ 'The dangling order\'s log file should be deleted by the file sweep'
+ );
+ }
+
+ /**
+ * @testdox cleanup() deletes dangling order meta but does not sweep log files when the default handler is not FileV2.
+ */
+ public function test_cleanup_skips_file_sweep_when_handler_is_not_file_v2(): void {
+ $handler = new LogHandlerFileV2();
+ $file_controller = wc_get_container()->get( FileController::class );
+
+ $order = OrderHelper::create_order();
+ $order->set_date_created( strtotime( '-5 days' ) );
+ $order->add_meta_data( '_debug_log_source', 'place-order-debug-dbhandler', true );
+ $order->save();
+
+ $handler->handle( time(), 'debug', 'a step', array( 'source' => 'place-order-debug-dbhandler' ) );
+ $files = $file_controller->get_files( array( 'source' => 'place-order-debug-dbhandler' ) );
+ $this->assertCount( 1, $files );
+ touch( $files[0]->get_path(), time() - 4 * DAY_IN_SECONDS ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_touch
+ // Drop the stale stat cache entry from before the touch.
+ clearstatcache();
+
+ update_option( 'woocommerce_logs_default_handler', \WC_Log_Handler_DB::class );
+
+ try {
+ $this->sut_cleanup_helper->cleanup();
+ } finally {
+ delete_option( 'woocommerce_logs_default_handler' );
+ }
+
+ $order_reloaded = wc_get_order( $order->get_id() );
+ $this->assertEmpty( $order_reloaded->get_meta( '_debug_log_source' ), 'Dangling meta should still be cleaned up' );
+ $this->assertCount(
+ 1,
+ $file_controller->get_files( array( 'source' => 'place-order-debug-dbhandler' ) ),
+ 'The file sweep should not run when the FileV2 handler is not the default'
+ );
+ }
+
/**
* Initialize HPOS and reset the DI container resolutions
- * (resetting the container is needed because the tested class checks for HPOS activation
- * only once when the DI container first retrieves it).
+ * (resetting the container is needed because OrderLogsDeletionProcessor checks for HPOS
+ * activation only once when the DI container first retrieves it).
*
* @param bool $enable_hpos Test with HPOS active or not.
*/
@@ -553,16 +787,6 @@ class OrderLogsCleanupTest extends \WC_Unit_Test_Case {
* Delete all place-order-debug log files using the FileV2 controller.
*/
private static function delete_all_log_files(): void {
- $file_controller = wc_get_container()->get( FileController::class );
- $files = $file_controller->get_files(
- array(
- 'source' => 'place-order-debug',
- 'per_page' => 1000,
- )
- );
-
- if ( is_array( $files ) && ! empty( $files ) ) {
- $file_controller->delete_files( array_map( fn( $file ) => $file->get_file_id(), $files ) );
- }
+ wc_get_container()->get( FileController::class )->delete_stale_files( 'place-order-debug', PHP_INT_MAX, PHP_INT_MAX );
}
}