diff --git a/inc/media_offload.php b/inc/media_offload.php index c08ab51d..397478b6 100644 --- a/inc/media_offload.php +++ b/inc/media_offload.php @@ -67,6 +67,17 @@ class Optml_Media_Offload extends Optml_App_Replacer { */ const TRANSFER_LOCK_TTL = 600; + /** + * Option counting the failed attempts of the current transfer step, and the steps skipped so far. + * It is an option rather than a transient so an object cache eviction can't reset the count. + */ + const STEP_FAILURES_OPTION = 'optml_transfer_step_failures'; + + /** + * How many times a failing transfer step is retried before the chain moves on. + */ + const MAX_STEP_RETRIES = 5; + /** * Flag used inside wp_get_attachment url filter. * @@ -1988,6 +1999,7 @@ public static function move_images( $action, $refresh ) { $lock_token = self::acquire_transfer_lock( $action ); if ( false !== $lock_token ) { + delete_option( self::STEP_FAILURES_OPTION ); $total = ceil( $count / $batch ); self::schedule_action( time(), @@ -2274,9 +2286,16 @@ public function start_processing_images( $action, $batch, $page, $total, $step, self::$instance->settings->update( $option, 'disabled' ); - self::$instance->settings->update( 'show_offload_finish_notice', $type ); + // A transfer that skipped failing steps left images behind, so it does not report success. + $skipped = self::get_skipped_steps( $lock_token ); + delete_option( self::STEP_FAILURES_OPTION ); + if ( $skipped > 0 ) { + self::$instance->logger->add_log( $type, $skipped . ' step(s) were skipped after failing ' . self::MAX_STEP_RETRIES . ' times. Start the transfer again to move the images left behind.' ); + } else { + self::$instance->settings->update( 'show_offload_finish_notice', $type ); + } - // Transfer completed successfully: release the lock. + // Transfer finished: release the lock. self::release_transfer_lock( $lock_token ); return; @@ -2322,12 +2341,22 @@ public function start_processing_images( $action, $batch, $page, $total, $step, $lock_token, ] ); + self::clear_step_failures( $lock_token ); } catch ( Exception $e ) { // Reschedule the cron to run again after a delay. Sometimes memory limit is exausted. // This is a retryable error, so the lock is kept rather than released. $delay_in_seconds = 10; self::$instance->logger->add_log( $type, $e->getMessage() ); + // A step that keeps failing would be retried every few seconds forever, with the transfer + // shown as running. After a few attempts the chain moves on, so the transfer can finish + // and the images left behind can be retried. + if ( self::count_step_failure( $lock_token, $action, $step ) >= self::MAX_STEP_RETRIES ) { + self::record_skipped_step( $lock_token ); + self::$instance->logger->add_log( $type, 'Step ' . $step . ' failed ' . self::MAX_STEP_RETRIES . ' times, moving on to the next one.' ); + $step = $step + 1; + } + self::schedule_action( time() + $delay_in_seconds, 'optml_start_processing_images', @@ -2345,6 +2374,98 @@ public function start_processing_images( $action, $batch, $page, $total, $step, } } + /** + * Read the step failures record of a transfer chain. + * + * @param string $lock_token The transfer lock token of the chain. + * + * @return array{token: string, action: string, step: int, count: int, skipped: int} The record, empty for another chain. + */ + private static function get_step_failures( string $lock_token ): array { + $failures = get_option( self::STEP_FAILURES_OPTION ); + $record = [ + 'token' => $lock_token, + 'action' => '', + 'step' => 0, + 'count' => 0, + 'skipped' => 0, + ]; + if ( ! is_array( $failures ) || ! isset( $failures['token'] ) || $failures['token'] !== $lock_token ) { + return $record; + } + + return [ + 'token' => $lock_token, + 'action' => isset( $failures['action'] ) ? (string) $failures['action'] : '', + 'step' => isset( $failures['step'] ) ? (int) $failures['step'] : 0, + 'count' => isset( $failures['count'] ) ? (int) $failures['count'] : 0, + 'skipped' => isset( $failures['skipped'] ) ? (int) $failures['skipped'] : 0, + ]; + } + + /** + * Count a failed attempt of a transfer step. + * + * @param string $lock_token The transfer lock token of the chain. + * @param string $action The transfer action. + * @param int $step The step that failed. + * + * @return int How many times in a row this step has failed. + */ + private static function count_step_failure( string $lock_token, string $action, int $step ): int { + $record = self::get_step_failures( $lock_token ); + if ( $record['action'] !== $action || $record['step'] !== $step ) { + $record['count'] = 0; + } + $record['action'] = $action; + $record['step'] = $step; + ++$record['count']; + update_option( self::STEP_FAILURES_OPTION, $record, false ); + + return $record['count']; + } + + /** + * Remember that the chain skipped a step that kept failing. + * + * @param string $lock_token The transfer lock token of the chain. + * + * @return void + */ + private static function record_skipped_step( string $lock_token ): void { + $record = self::get_step_failures( $lock_token ); + $record['count'] = 0; + ++$record['skipped']; + update_option( self::STEP_FAILURES_OPTION, $record, false ); + } + + /** + * Clear the failed attempts after a step succeeds, keeping the count of skipped steps. + * + * @param string $lock_token The transfer lock token of the chain. + * + * @return void + */ + private static function clear_step_failures( string $lock_token ): void { + $record = self::get_step_failures( $lock_token ); + if ( 0 === $record['count'] ) { + return; + } + $record['count'] = 0; + update_option( self::STEP_FAILURES_OPTION, $record, false ); + } + + /** + * How many steps the chain skipped after they kept failing. + * + * @param string $lock_token The transfer lock token of the chain. + * + * @return int + */ + public static function get_skipped_steps( string $lock_token ): int { + return self::get_step_failures( $lock_token )['skipped']; + } + /** * Alter attachment image src for offloaded images. * diff --git a/tests/test-media.php b/tests/test-media.php index f8a9eaa1..85605bea 100644 --- a/tests/test-media.php +++ b/tests/test-media.php @@ -543,6 +543,139 @@ public function test_background_step_does_nothing_while_another_run_moves_images $this->assert_moving_images_lock_is_free(); } + /** + * A step that throws every time is retried a few times, then the chain moves on to the next step + * instead of retrying it every few seconds forever. + */ + public function test_failing_step_moves_on_after_retries(): void { + ( new Optml_Settings() )->update( 'rollback_status', 'enabled' ); + delete_option( Optml_Media_Offload::STEP_FAILURES_OPTION ); + $token = Optml_Media_Offload::acquire_transfer_lock( 'rollback_images' ); + $fail = function () { + throw new Exception( 'cloud lookup failed' ); + }; + add_action( 'pre_get_posts', $fail ); + + $steps = []; + for ( $attempt = 1; $attempt <= Optml_Media_Offload::MAX_STEP_RETRIES; $attempt++ ) { + _set_cron_array( [] ); + Optml_Media_Offload::instance()->start_processing_images( 'rollback_images', 10, 1, 5, 1, $token ); + $steps[] = $this->scheduled_transfer_step(); + } + remove_action( 'pre_get_posts', $fail ); + + $this->assertSame( array_merge( array_fill( 0, Optml_Media_Offload::MAX_STEP_RETRIES - 1, 1 ), [ 2 ] ), $steps ); + $this->assertSame( 1, Optml_Media_Offload::get_skipped_steps( $token ) ); + $this->assertSame( 0, get_option( Optml_Media_Offload::STEP_FAILURES_OPTION )['count'] ); + delete_transient( Optml_Media_Offload::TRANSFER_LOCK_TRANSIENT ); + } + + /** + * A step that succeeds clears the failures of the one before it, but the skipped steps are kept. + */ + public function test_successful_step_clears_failures(): void { + ( new Optml_Settings() )->update( 'rollback_status', 'enabled' ); + $token = Optml_Media_Offload::acquire_transfer_lock( 'rollback_images' ); + update_option( Optml_Media_Offload::STEP_FAILURES_OPTION, $this->step_failures( $token, Optml_Media_Offload::MAX_STEP_RETRIES - 1, 1 ), false ); + + _set_cron_array( [] ); + Optml_Media_Offload::instance()->start_processing_images( 'rollback_images', 10, 1, 5, 1, $token ); + + $this->assertSame( 2, $this->scheduled_transfer_step() ); + $this->assertSame( 0, get_option( Optml_Media_Offload::STEP_FAILURES_OPTION )['count'] ); + $this->assertSame( 1, Optml_Media_Offload::get_skipped_steps( $token ) ); + delete_transient( Optml_Media_Offload::TRANSFER_LOCK_TRANSIENT ); + } + + /** + * Failures left by an earlier transfer don't count toward the retries of a new one. + */ + public function test_failures_of_another_transfer_are_ignored(): void { + ( new Optml_Settings() )->update( 'rollback_status', 'enabled' ); + $token = Optml_Media_Offload::acquire_transfer_lock( 'rollback_images' ); + update_option( Optml_Media_Offload::STEP_FAILURES_OPTION, $this->step_failures( 'old-transfer', Optml_Media_Offload::MAX_STEP_RETRIES - 1, 2 ), false ); + $fail = function () { + throw new Exception( 'cloud lookup failed' ); + }; + add_action( 'pre_get_posts', $fail ); + + _set_cron_array( [] ); + Optml_Media_Offload::instance()->start_processing_images( 'rollback_images', 10, 1, 5, 1, $token ); + remove_action( 'pre_get_posts', $fail ); + + $this->assertSame( 1, $this->scheduled_transfer_step() ); + $this->assertSame( 1, get_option( Optml_Media_Offload::STEP_FAILURES_OPTION )['count'] ); + $this->assertSame( 0, Optml_Media_Offload::get_skipped_steps( $token ) ); + delete_transient( Optml_Media_Offload::TRANSFER_LOCK_TRANSIENT ); + } + + /** + * A transfer that skipped steps does not show the "Transfer Complete" notice. + */ + public function test_transfer_with_skipped_steps_does_not_report_success(): void { + $settings = new Optml_Settings(); + $settings->update( 'rollback_status', 'enabled' ); + $settings->update( 'show_offload_finish_notice', '' ); + $token = Optml_Media_Offload::acquire_transfer_lock( 'rollback_images' ); + update_option( Optml_Media_Offload::STEP_FAILURES_OPTION, $this->step_failures( $token, 0, 1 ), false ); + + Optml_Media_Offload::instance()->start_processing_images( 'rollback_images', 10, 6, 5, 6, $token ); + + $settings = new Optml_Settings(); + $this->assertSame( 'disabled', $settings->get( 'rollback_status' ) ); + $this->assertSame( '', $settings->get( 'show_offload_finish_notice' ) ); + $this->assertFalse( get_option( Optml_Media_Offload::STEP_FAILURES_OPTION ) ); + } + + /** + * A transfer that ran every step shows the "Transfer Complete" notice. + */ + public function test_transfer_without_skipped_steps_reports_success(): void { + $settings = new Optml_Settings(); + $settings->update( 'rollback_status', 'enabled' ); + $settings->update( 'show_offload_finish_notice', '' ); + $token = Optml_Media_Offload::acquire_transfer_lock( 'rollback_images' ); + update_option( Optml_Media_Offload::STEP_FAILURES_OPTION, $this->step_failures( 'old-transfer', 0, 3 ), false ); + + Optml_Media_Offload::instance()->start_processing_images( 'rollback_images', 10, 6, 5, 6, $token ); + + $this->assertSame( 'rollback', ( new Optml_Settings() )->get( 'show_offload_finish_notice' ) ); + } + + /** + * Build a step failures record. + * + * @param string $token The transfer lock token. + * @param int $count The failed attempts of step 1. + * @param int $skipped The skipped steps. + * + * @return array{token: string, action: string, step: int, count: int, skipped: int} + */ + private function step_failures( string $token, int $count, int $skipped ): array { + return [ + 'token' => $token, + 'action' => 'rollback_images', + 'step' => 1, + 'count' => $count, + 'skipped' => $skipped, + ]; + } + + /** + * @return int|null The step of the background transfer step waiting in WP-Cron. + */ + private function scheduled_transfer_step(): ?int { + foreach ( (array) _get_cron_array() as $hooks ) { + if ( isset( $hooks['optml_start_processing_images'] ) ) { + $event = reset( $hooks['optml_start_processing_images'] ); + + return (int) $event['args'][4]; + } + } + + return null; + } + /** * @return int The background transfer steps waiting in WP-Cron. */