Skip to content

Commit 49a00fa

Browse files
felipeeliafelipeelia
authored
Merge pull request #201 from 10up/feature/ai-time-between-logging-failures
Avoid too many db writes when logging failures
2 parents 9cf0cf2 + 09c0a8f commit 49a00fa

2 files changed

Lines changed: 253 additions & 8 deletions

File tree

‎includes/classes/Traits/DisableAfterFailures.php‎

100644100755
Lines changed: 48 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -58,7 +58,9 @@ public function maybe_reset_failures_count() {
5858
* @return void
5959
*/
6060
public function reset_failures_count() {
61-
delete_transient( $this->get_failures_transient_key() );
61+
$transient_key = $this->get_failures_transient_key();
62+
delete_transient( $transient_key );
63+
delete_transient( $transient_key . '_lock' );
6264
}
6365

6466
/**
@@ -67,7 +69,8 @@ public function reset_failures_count() {
6769
* @return boolean
6870
*/
6971
public function should_disable_after_failures() {
70-
$failures = $this->cleanup_failures( (array) get_transient( $this->get_failures_transient_key() ) );
72+
$stored = get_transient( $this->get_failures_transient_key() );
73+
$failures = $this->cleanup_failures( is_array( $stored ) ? $stored : [] );
7174
return count( $failures ) > $this->get_max_failures_count();
7275
}
7376

@@ -157,20 +160,60 @@ protected function get_failures_transient_key(): string {
157160
return apply_filters( 'ep_failures_transient_key', "ep_{$this->slug}_failures", $this );
158161
}
159162

163+
/**
164+
* Get the minimum time between failures storage (after the limit is hit).
165+
*
166+
* @return int
167+
*/
168+
protected function get_failures_min_time_between_writes(): int {
169+
$default_min_time_between_writes = wp_using_ext_object_cache() ? 1 : 10;
170+
171+
/**
172+
* Filter the minimum time between failures storage (after the limit is hit).
173+
*
174+
* @hook ep_failures_min_time_between_writes
175+
* @since 2.5.1
176+
* @param {int} $min_time_between_writes The minimum time between failures storage (after the limit is hit). Default is 1 seconds if using external object cache, 10 seconds otherwise.
177+
* @param {Feature} $feature The feature object.
178+
* @return {int} The minimum time between failures storage (after the limit is hit).
179+
*/
180+
return (int) apply_filters( 'ep_failures_min_time_between_writes', $default_min_time_between_writes, $this );
181+
}
182+
160183
/**
161184
* Update the failures count.
162185
*
163186
* @return void
164187
*/
165188
protected function update_failures_count() {
166189
$transient_key = $this->get_failures_transient_key();
167-
$failures = (array) get_transient( $transient_key );
168-
$failures[] = time();
190+
191+
$stored = get_transient( $transient_key );
192+
$failures = is_array( $stored ) ? $stored : [];
193+
194+
if ( count( $failures ) > $this->get_max_failures_count() ) {
195+
$time_since_last_failure = time() - max( $failures );
196+
197+
if ( $time_since_last_failure < $this->get_failures_min_time_between_writes() ) {
198+
return;
199+
}
200+
}
201+
202+
$failures[] = time();
203+
$failures = $this->cleanup_failures( $failures );
204+
205+
$lock_ttl = max( 1, (int) $this->get_failures_min_time_between_writes() );
206+
if ( wp_using_ext_object_cache() && ! wp_cache_add( $transient_key . '_lock', 1, 'transient', $lock_ttl ) ) {
207+
return;
208+
}
209+
169210
set_transient(
170211
$transient_key,
171-
$this->cleanup_failures( $failures ),
212+
$failures,
172213
$this->get_max_failures_timeframe()
173214
);
215+
216+
delete_transient( $transient_key . '_lock' );
174217
}
175218

176219
/**

‎tests/phpunit/Traits/TestDisableAfterFailures.php‎

Lines changed: 205 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,7 @@ public function tear_down() {
4646
remove_all_filters( 'ep_max_failures_count' );
4747
remove_all_filters( 'ep_max_failures_timeframe' );
4848
remove_all_filters( 'ep_failures_transient_key' );
49+
remove_all_filters( 'ep_failures_min_time_between_writes' );
4950

5051
// Unregister the feature.
5152
unset( \ElasticPress\Features::factory()->registered_features[ $this->feature->slug ] );
@@ -61,6 +62,7 @@ protected function cleanup_transients() {
6162
delete_transient( $transient_key );
6263
delete_option( '_transient_' . $transient_key );
6364
delete_option( '_transient_timeout_' . $transient_key );
65+
delete_transient( $transient_key . '_lock' );
6466
}
6567

6668
/**
@@ -75,6 +77,16 @@ protected function get_failures_transient_key() {
7577
return $method->invoke( $this->feature );
7678
}
7779

80+
/**
81+
* Failure timestamps array from a failures transient value.
82+
*
83+
* @param mixed $stored Transient value.
84+
* @return array
85+
*/
86+
protected function get_stored_failure_timestamps( $stored ): array {
87+
return is_array( $stored ) ? $stored : [];
88+
}
89+
7890
/**
7991
* Test setup_failures_count hooks admin_init
8092
*
@@ -447,6 +459,47 @@ function ( $key, $feature ) {
447459
$this->assertSame( $expected, $method->invoke( $this->feature ) );
448460
}
449461

462+
/**
463+
* Test get_failures_min_time_between_writes returns the expected default value.
464+
*
465+
* The default is 1 second when an external object cache is present and 10 seconds otherwise.
466+
*
467+
* @group disable-after-failures
468+
*/
469+
public function test_get_failures_min_time_between_writes_returns_default() {
470+
$reflection = new \ReflectionClass( $this->feature );
471+
$method = $reflection->getMethod( 'get_failures_min_time_between_writes' );
472+
$method->setAccessible( true );
473+
474+
$expected = wp_using_ext_object_cache() ? 1 : 10;
475+
$this->assertSame( $expected, $method->invoke( $this->feature ) );
476+
}
477+
478+
/**
479+
* Test get_failures_min_time_between_writes respects the ep_failures_min_time_between_writes filter.
480+
*
481+
* @group disable-after-failures
482+
*/
483+
public function test_get_failures_min_time_between_writes_respects_filter() {
484+
add_filter(
485+
'ep_failures_min_time_between_writes',
486+
function ( $min_time, $feature ) {
487+
if ( $feature->slug === $this->feature->slug ) {
488+
return 30;
489+
}
490+
return $min_time;
491+
},
492+
10,
493+
2
494+
);
495+
496+
$reflection = new \ReflectionClass( $this->feature );
497+
$method = $reflection->getMethod( 'get_failures_min_time_between_writes' );
498+
$method->setAccessible( true );
499+
500+
$this->assertSame( 30, $method->invoke( $this->feature ) );
501+
}
502+
450503
/**
451504
* Test update_failures_count adds current timestamp
452505
*
@@ -465,7 +518,8 @@ public function test_update_failures_count_adds_current_timestamp() {
465518
$method->invoke( $this->feature );
466519
$after_time = time();
467520

468-
$updated_failures = get_transient( $transient_key );
521+
$updated_stored = get_transient( $transient_key );
522+
$updated_failures = $this->get_stored_failure_timestamps( $updated_stored );
469523
$this->assertIsArray( $updated_failures );
470524
$this->assertCount( 2, $updated_failures );
471525

@@ -513,7 +567,8 @@ public function test_update_failures_count_cleans_up_old_failures() {
513567

514568
$method->invoke( $this->feature );
515569

516-
$updated_failures = get_transient( $transient_key );
570+
$updated_stored = get_transient( $transient_key );
571+
$updated_failures = $this->get_stored_failure_timestamps( $updated_stored );
517572
$this->assertIsArray( $updated_failures );
518573
// Should only have recent failures (old one cleaned up, plus new one).
519574
foreach ( $updated_failures as $failure_time ) {
@@ -524,9 +579,15 @@ public function test_update_failures_count_cleans_up_old_failures() {
524579
/**
525580
* Test update_failures_count limits stored failures
526581
*
582+
* The rate limit on writes after the limit is hit is disabled here so we can
583+
* validate that, when a write does happen, cleanup_failures keeps the array
584+
* trimmed to max + 1 entries.
585+
*
527586
* @group disable-after-failures
528587
*/
529588
public function test_update_failures_count_limits_stored_failures() {
589+
add_filter( 'ep_failures_min_time_between_writes', '__return_zero' );
590+
530591
$transient_key = $this->get_failures_transient_key();
531592

532593
// Create more failures than max + 1.
@@ -539,11 +600,115 @@ public function test_update_failures_count_limits_stored_failures() {
539600

540601
$method->invoke( $this->feature );
541602

542-
$updated_failures = get_transient( $transient_key );
603+
$updated_stored = get_transient( $transient_key );
604+
$updated_failures = $this->get_stored_failure_timestamps( $updated_stored );
543605
// Should only keep max_failures_count + 1 (3 + 1 = 4).
544606
$this->assertLessThanOrEqual( 4, count( $updated_failures ) );
545607
}
546608

609+
/**
610+
* Test update_failures_count skips the write when the failure count is already over
611+
* the max and the most recently stored failure happened within the rate-limit window.
612+
*
613+
* @group disable-after-failures
614+
*/
615+
public function test_update_failures_count_skips_write_when_over_limit_and_recent() {
616+
$transient_key = $this->get_failures_transient_key();
617+
618+
// Already over the max (3) with the most recent failure happening "now",
619+
// well within the default 10s rate-limit window.
620+
$now = time();
621+
$initial_failures = [ $now - 30, $now - 20, $now - 10, $now ];
622+
set_transient( $transient_key, $initial_failures, HOUR_IN_SECONDS );
623+
624+
$reflection = new \ReflectionClass( $this->feature );
625+
$method = $reflection->getMethod( 'update_failures_count' );
626+
$method->setAccessible( true );
627+
628+
$method->invoke( $this->feature );
629+
630+
// The transient should be untouched: no new entry, same values.
631+
$updated_failures = get_transient( $transient_key );
632+
$this->assertSame( $initial_failures, $updated_failures );
633+
}
634+
635+
/**
636+
* Test update_failures_count writes when over the limit but the last stored failure
637+
* is older than the configured min_time_between_writes window.
638+
*
639+
* @group disable-after-failures
640+
*/
641+
public function test_update_failures_count_writes_when_over_limit_and_last_failure_is_old() {
642+
// Set a small window so the test is not flaky on slow runners.
643+
add_filter(
644+
'ep_failures_min_time_between_writes',
645+
function ( $min_time, $feature ) {
646+
if ( $feature->slug === $this->feature->slug ) {
647+
return 1;
648+
}
649+
return $min_time;
650+
},
651+
10,
652+
2
653+
);
654+
655+
$transient_key = $this->get_failures_transient_key();
656+
657+
// Already over the max (3), but the most recent stored failure is 30s old.
658+
$now = time();
659+
$initial_failures = [ $now - 60, $now - 50, $now - 40, $now - 30 ];
660+
set_transient( $transient_key, $initial_failures, HOUR_IN_SECONDS );
661+
662+
$reflection = new \ReflectionClass( $this->feature );
663+
$method = $reflection->getMethod( 'update_failures_count' );
664+
$method->setAccessible( true );
665+
666+
$before_time = time();
667+
$method->invoke( $this->feature );
668+
$after_time = time();
669+
670+
$updated_stored = get_transient( $transient_key );
671+
$updated_failures = $this->get_stored_failure_timestamps( $updated_stored );
672+
$this->assertIsArray( $updated_failures );
673+
674+
// The newly added timestamp should be the last entry in the stored array.
675+
$last_failure = end( $updated_failures );
676+
$this->assertGreaterThanOrEqual( $before_time, $last_failure );
677+
$this->assertLessThanOrEqual( $after_time, $last_failure );
678+
679+
// cleanup_failures keeps at most max + 1 entries.
680+
$this->assertLessThanOrEqual( 4, count( $updated_failures ) );
681+
}
682+
683+
/**
684+
* Test update_failures_count writes normally while the failure count is still at or below max.
685+
*
686+
* The rate-limit logic must not affect calls happening before the feature gets
687+
* temporarily disabled, otherwise the disable threshold could never be reached.
688+
*
689+
* @group disable-after-failures
690+
*/
691+
public function test_update_failures_count_writes_when_at_or_below_max() {
692+
$transient_key = $this->get_failures_transient_key();
693+
694+
// Exactly at max, all timestamps are "now" which is the worst case for the
695+
// rate limit if it were applied below the max.
696+
$now = time();
697+
$initial_failures = [ $now, $now, $now ];
698+
set_transient( $transient_key, $initial_failures, HOUR_IN_SECONDS );
699+
700+
$reflection = new \ReflectionClass( $this->feature );
701+
$method = $reflection->getMethod( 'update_failures_count' );
702+
$method->setAccessible( true );
703+
704+
$method->invoke( $this->feature );
705+
706+
$updated_stored = get_transient( $transient_key );
707+
$updated_failures = $this->get_stored_failure_timestamps( $updated_stored );
708+
$this->assertIsArray( $updated_failures );
709+
$this->assertCount( count( $initial_failures ) + 1, $updated_failures );
710+
}
711+
547712
/**
548713
* Test cleanup_failures removes old failures
549714
*
@@ -625,6 +790,43 @@ public function test_integration_full_flow_failures_to_disable() {
625790
$this->assertSame( FeatureRequirementsStatus::TEMPORARILY_DISABLED, $status->code );
626791
}
627792

793+
/**
794+
* Test integration: once the feature is temporarily disabled, additional failures
795+
* happening in rapid succession do not write to the transient (rate limit), but
796+
* the feature remains disabled.
797+
*
798+
* @group disable-after-failures
799+
*/
800+
public function test_integration_rate_limits_writes_after_disabled() {
801+
$transient_key = $this->get_failures_transient_key();
802+
803+
$reflection = new \ReflectionClass( $this->feature );
804+
$update_method = $reflection->getMethod( 'update_failures_count' );
805+
$update_method->setAccessible( true );
806+
807+
// Trigger enough failures (max + 1 = 4) to disable the feature.
808+
for ( $i = 0; $i < 4; $i++ ) {
809+
$update_method->invoke( $this->feature );
810+
}
811+
812+
$failures_after_disable = get_transient( $transient_key );
813+
$this->assertIsArray( $failures_after_disable );
814+
$this->assertCount(
815+
4,
816+
$this->get_stored_failure_timestamps( $failures_after_disable )
817+
);
818+
$this->assertTrue( $this->feature->should_disable_after_failures() );
819+
820+
// Subsequent rapid calls should be skipped: the transient must remain identical.
821+
for ( $i = 0; $i < 5; $i++ ) {
822+
$update_method->invoke( $this->feature );
823+
}
824+
825+
$failures_after_rapid_calls = get_transient( $transient_key );
826+
$this->assertSame( $failures_after_disable, $failures_after_rapid_calls );
827+
$this->assertTrue( $this->feature->should_disable_after_failures() );
828+
}
829+
628830
/**
629831
* Test integration: failures expire after timeframe
630832
*

0 commit comments

Comments
 (0)