diff --git a/README.md b/README.md index 6738807..f7d1188 100644 --- a/README.md +++ b/README.md @@ -20,6 +20,7 @@ bedrock_stale_cache: stale_cache_service_id: # Desired id for this new stale cache instance cache_pool: cache_pool_id # Cache pool on top of which stale cache will be used max_stale: 3600 # Stale period duration, in seconds + enable_debug_logs: true # Optional (defaults to false), produce a bunch of debug logs ``` It will declare a `@stale_cache_service_id`, that you can use as an injected dependency. @@ -37,9 +38,10 @@ The method `allowStaleCacheUsage` can be used for some custom logic, or you can A `Bedrock\StaleCacheBundle\Event\StaleCacheUsage` event is sent on stale cache usage. It is strongly advised to log it, with the associated error. -### Remarks +### Logs -This bundle disables [the stampede prevention from Symfony Cache](https://symfony.com/doc/current/components/cache.html#stampede-prevention). +Debug logs can be enabled to ensure correct stale cache usage. +It should not be enabled in a production environment since it can cause performance issue. ## Contribute diff --git a/composer.json b/composer.json index dab131b..fafb8df 100644 --- a/composer.json +++ b/composer.json @@ -25,6 +25,7 @@ "require": { "php": "^7.4 || ^8.0", "psr/event-dispatcher": "^1.0", + "psr/log": "^1 || ^2 || ^3", "symfony/dependency-injection": "^4.4 || ^5.4 || ^6.0" , "symfony/http-kernel": "^4.4 || ^5.4 || ^6.0", "symfony/cache-contracts": "^1.0 || ^2.0", diff --git a/src/Cache/Stale.php b/src/Cache/Stale.php index 6769259..328685c 100644 --- a/src/Cache/Stale.php +++ b/src/Cache/Stale.php @@ -7,6 +7,7 @@ use Bedrock\StaleCacheBundle\Event\StaleCacheUsage; use Bedrock\StaleCacheBundle\Exception\UnavailableResourceException; use Psr\EventDispatcher\EventDispatcherInterface; +use Psr\Log\LoggerInterface; use Symfony\Component\Cache\CacheItem; use Symfony\Contracts\Cache\CacheInterface; use Symfony\Contracts\Cache\ItemInterface; @@ -20,16 +21,20 @@ class Stale implements TagAwareCacheInterface private int $maxStale; + private ?LoggerInterface $logger; + private ?int $defaultLifetime = null; public function __construct( CacheInterface $internalCache, EventDispatcherInterface $dispatcher, - int $maxStale + int $maxStale, + ?LoggerInterface $logger = null ) { $this->internalCache = $internalCache; $this->dispatcher = $dispatcher; $this->maxStale = $maxStale; + $this->logger = $logger; } /** @@ -53,18 +58,36 @@ public function get(string $key, callable $callback, float $beta = null, array & // $beta = 0 to disable early recompute $value = $this->internalCache->get($key, $callbackWithIncreasedCacheTime, 0, $metadata); - // If value is cached and we're in stale mode, try to force recomputing it - // Ignore correctly marked exceptions: this is where the stale mode should work as a fallback - if ($isHit && ($this->isStale($metadata) || $this->shouldTriggerEarlyCacheExpiry($metadata, $beta))) { + $recompute = false; + if ($this->isStale($metadata)) { + $this->logDebugMessage('Value is stale, try to recompute it', $key); + $recompute = true; + } + + if (!$recompute && $this->shouldTriggerEarlyCacheExpiry($metadata, $beta)) { + $this->logDebugMessage('Value elected to early expiration, try to recompute it', $key); + $recompute = true; + } + + if ($isHit && $recompute) { try { // $beta = \INF to force an early recompute $value = $this->internalCache->get($key, $callbackWithIncreasedCacheTime, \INF, $metadata); } catch (UnavailableResourceException $exception) { if (!$exception->allowStaleCacheUsage()) { + $this->logDebugMessage('Cannot fallback to stale mode', $key, $exception); throw $exception; } - $this->dispatcher->dispatch(new StaleCacheUsage($exception)); + $this->logDebugMessage('Fallback to stale mode', $key, $exception); + $this->dispatcher->dispatch(new StaleCacheUsage($exception, $key)); + } catch (\Throwable $throwable) { + $this->logDebugMessage( + sprintf('Exception %s do not allow stale cache, it will be rethrown', get_class($throwable)), + $key, $throwable + ); + + throw $throwable; } } @@ -140,4 +163,11 @@ private function shouldTriggerEarlyCacheExpiry(?array $metadata, ?float $beta): // it should be triggered a few hundreds of ms before due time. return ($expiry - $this->maxStale) <= microtime(true) - $ctime / 1000 * $beta * log(random_int(1, \PHP_INT_MAX) / \PHP_INT_MAX); } + + private function logDebugMessage(string $message, string $cacheKey, ?\Throwable $throwable = null): void + { + if ($this->logger) { + $this->logger->debug($message, ['cache_key' => $cacheKey, 'exception' => $throwable]); + } + } } diff --git a/src/DependencyInjection/AddStaleCacheLifetime.php b/src/DependencyInjection/AddStaleCacheLifetime.php index c053f95..ac0d80c 100644 --- a/src/DependencyInjection/AddStaleCacheLifetime.php +++ b/src/DependencyInjection/AddStaleCacheLifetime.php @@ -33,7 +33,7 @@ public function process(ContainerBuilder $container): void */ private function findCachePoolDefaultLifetime(string $cachePool, array $cachePoolServices): ?int { - foreach ($cachePoolServices as $serviceId => $tags) { + foreach ($cachePoolServices as $tags) { foreach ($tags as $tag) { if (array_key_exists('name', $tag) && $tag['name'] === $cachePool) { return $tag['default_lifetime'] ?? null; diff --git a/src/DependencyInjection/BedrockStaleCacheExtension.php b/src/DependencyInjection/BedrockStaleCacheExtension.php index 697db05..8a78ad5 100644 --- a/src/DependencyInjection/BedrockStaleCacheExtension.php +++ b/src/DependencyInjection/BedrockStaleCacheExtension.php @@ -36,5 +36,11 @@ private function configureStaleCacheService(ContainerBuilder $container, string $definition->setAutoconfigured(true); $definition->setAutowired(true); $definition->addTag('bedrock_stale_cache.stale_cache', $options); + + // By default, disable debug logs + $enableDebugLogs = $options['enable_debug_logs'] ?? false; + if (!$enableDebugLogs) { + $definition->setArgument('$logger', null); + } } } diff --git a/src/Event/StaleCacheUsage.php b/src/Event/StaleCacheUsage.php index cb0db1f..cc5c9e9 100644 --- a/src/Event/StaleCacheUsage.php +++ b/src/Event/StaleCacheUsage.php @@ -10,14 +10,21 @@ class StaleCacheUsage extends Event { private UnavailableResourceException $exception; + private string $cacheKey; - public function __construct(UnavailableResourceException $exception) + public function __construct(UnavailableResourceException $exception, string $cacheKey) { $this->exception = $exception; + $this->cacheKey = $cacheKey; } public function getException(): UnavailableResourceException { return $this->exception; } + + public function getCacheKey(): string + { + return $this->cacheKey; + } } diff --git a/tests/Unit/Cache/StaleTest.php b/tests/Unit/Cache/StaleTest.php index 420d36b..a4a6658 100644 --- a/tests/Unit/Cache/StaleTest.php +++ b/tests/Unit/Cache/StaleTest.php @@ -12,6 +12,7 @@ use Prophecy\PhpUnit\ProphecyTrait; use Prophecy\Prophecy\ObjectProphecy; use Psr\EventDispatcher\EventDispatcherInterface; +use Psr\Log\LoggerInterface; use Symfony\Component\Cache\CacheItem; use Symfony\Contracts\Cache\ItemInterface; use Symfony\Contracts\Cache\TagAwareCacheInterface; @@ -28,17 +29,22 @@ class StaleTest extends TestCase /** @var ObjectProphecy|EventDispatcherInterface */ private ObjectProphecy $eventDispatcher; + /** @var ObjectProphecy|LoggerInterface */ + private ObjectProphecy $logger; + private Stale $testedInstance; public function setUp(): void { $this->internalCache = $this->prophesize(TagAwareCacheInterface::class); $this->eventDispatcher = $this->prophesize(EventDispatcherInterface::class); + $this->logger = $this->prophesize(LoggerInterface::class); $this->testedInstance = new Stale( $this->internalCache->reveal(), $this->eventDispatcher->reveal(), - self::DEFAULT_MAX_STALE + self::DEFAULT_MAX_STALE, + $this->logger->reveal(), ); } @@ -71,6 +77,9 @@ public function testGetNewItem($value, callable $callback): void $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug(Argument::cetera()) + ->shouldNotBeCalled(); + $metadata = []; $result = $this->testedInstance->get($key, $callback, $beta, $metadata); self::assertEquals($value, $result); @@ -108,6 +117,11 @@ public function testGetItemHitAndForceRefresh($newValue, callable $callback) $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldNotBeCalled(); + // Item is in cache, but in stale mode // We force refreshing the value, getting a new one $metadata = [ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE / 2]; @@ -167,6 +181,11 @@ public function testGetItemHitAndUseStaleMode(): void $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldBeCalledOnce(); + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldBeCalled(); + // Item is in cache, but in stale mode // Value cannot be refreshed due to failing source $metadata = [ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE / 2]; @@ -175,10 +194,7 @@ public function testGetItemHitAndUseStaleMode(): void self::assertCacheItemExpiryEquals($initialExpiryAsFloat, $cacheItem); } - /** - * @dataProvider provideGetItemHitAndFailsToUseStaleMode - */ - public function testGetItemHitAndFailsToUseStaleMode(callable $callback, string $exceptionClass): void + public function testGetItemHitAndFailsAndNotAllowedToUseStaleMode(): void { $key = uniqid('key_', true); $value = uniqid('value_', true); @@ -187,6 +203,9 @@ public function testGetItemHitAndFailsToUseStaleMode(callable $callback, string ->modify('+1 hour'); $cacheItem = new CacheItem(); $cacheItem->expiresAt($initialExpiry); + $callback = function () { + throw new UnavailableResourceExceptionMock(false); + }; $metadataArgument = Argument::any(); $this->internalCache->get($key, Argument::any(), 0, $metadataArgument) @@ -205,28 +224,59 @@ public function testGetItemHitAndFailsToUseStaleMode(callable $callback, string $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldNotBeCalled(); + // Item is in cache, but in stale mode // Value cannot be refreshed due to failing source $metadata = [ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE / 2]; - $this->expectException($exceptionClass); + $this->expectException(UnavailableResourceExceptionMock::class); $this->testedInstance->get($key, $callback, $beta, $metadata); } - public function provideGetItemHitAndFailsToUseStaleMode(): iterable + public function testGetItemHitAndFailsAndCannotUseStaleMode(): void { - yield 'error do not allow stale cache mode' => [ - 'callback' => function () { - throw new UnavailableResourceExceptionMock(false); - }, - 'exception_class' => UnavailableResourceExceptionMock::class, - ]; + $key = uniqid('key_', true); + $value = uniqid('value_', true); + $beta = (float) rand(1, 10); + $initialExpiry = \DateTimeImmutable::createFromFormat('U.u', (string) microtime(true)) + ->modify('+1 hour'); + $cacheItem = new CacheItem(); + $cacheItem->expiresAt($initialExpiry); + $callback = function () { + throw new \Exception(); + }; - yield 'error do not implement the correct interface' => [ - 'callback' => function () { - throw new \Exception(); - }, - 'exception_class' => \Exception::class, - ]; + $metadataArgument = Argument::any(); + $this->internalCache->get($key, Argument::any(), 0, $metadataArgument) + // Use cached value + ->willReturn($value); + + $this->internalCache->get($key, Argument::any(), \INF, $metadataArgument) + ->shouldBeCalledOnce() + // Execute $callback + ->will(function ($args) use ($cacheItem) { + $save = true; + + return $args[1]($cacheItem, $save); + }); + + $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) + ->shouldNotBeCalled(); + + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Exception Exception do not allow stale cache, it will be rethrown', Argument::any())->shouldBeCalledOnce(); + + // Item is in cache, but in stale mode + // Value cannot be refreshed due to failing source + $metadata = [ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE / 2]; + $this->expectException(\Exception::class); + $this->testedInstance->get($key, $callback, $beta, $metadata); } /** @@ -252,6 +302,9 @@ public function testGetItemHitWithoutStaleMode(array $metadata): void $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug(Argument::cetera()) + ->shouldNotBeCalled(); + $result = $this->testedInstance->get($key, $callback, $beta, $metadata); self::assertEquals($value, $result); } @@ -290,6 +343,9 @@ public function testGetItemMissWithFailingCallback(): void $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug(Argument::cetera()) + ->shouldNotBeCalled(); + $metadata = []; $this->expectException(UnavailableResourceExceptionMock::class); $this->testedInstance->get($key, $callback, $beta, $metadata); @@ -306,8 +362,6 @@ public function testGetItemWithDefaultLifetime() $cacheItem = new CacheItem(); - $expectedExpiryMin = microtime(true) + self::DEFAULT_MAX_STALE + $defaultLifetime; - $metadataArgument = Argument::any(); $this->internalCache->get($key, Argument::any(), 0, $metadataArgument) // Use cached value @@ -322,20 +376,24 @@ public function testGetItemWithDefaultLifetime() return $args[1]($cacheItem, $save); }); - $this->testedInstance->setDefaultLifetime($defaultLifetime); + $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) + ->shouldNotBeCalled(); + + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldNotBeCalled(); // Item is in cache, but in stale mode // Value cannot be refreshed due to failing source $metadata = [ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE / 2]; + $this->testedInstance->setDefaultLifetime($defaultLifetime); + $expectedExpiryMin = microtime(true) + self::DEFAULT_MAX_STALE + $defaultLifetime; $result = $this->testedInstance->get($key, $callback, $beta, $metadata); - $expectedExpiryMax = microtime(true) + self::DEFAULT_MAX_STALE + $defaultLifetime; self::assertEquals($value, $result); - - $cacheItemExpiry = self::getCacheItemExpiry($cacheItem); - self::assertGreaterThan($expectedExpiryMin, $cacheItemExpiry); - self::assertLessThan($expectedExpiryMax, $cacheItemExpiry); + self::assertCacheItemExpiryBetween($expectedExpiryMin, $expectedExpiryMax, $cacheItem); } /** @@ -371,11 +429,16 @@ public function testGetItemHitWithEarlyExpiry(int $ctime, float $beta) $this->eventDispatcher->dispatch(Argument::that(fn ($event) => $event instanceof StaleCacheUsage)) ->shouldNotBeCalled(); + $this->logger->debug('Value is stale, try to recompute it', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Value elected to early expiration, try to recompute it', Argument::any())->shouldBeCalledOnce(); + $this->logger->debug('Cannot fallback to stale mode', Argument::any())->shouldNotBeCalled(); + $this->logger->debug('Fallback to stale mode', Argument::any())->shouldNotBeCalled(); + // Item is in cache, will soon expire but not yet in stale mode // Using a huge beta & ctime we force early cache expiry $metadata = [ ItemInterface::METADATA_EXPIRY => microtime(true) + self::DEFAULT_MAX_STALE + 1, - ItemInterface::METADATA_CTIME => PHP_INT_MAX + ItemInterface::METADATA_CTIME => PHP_INT_MAX, ]; $result = $this->testedInstance->get($key, $callback, $beta, $metadata); // There is an **extremely low** probability for this to fail... @@ -388,12 +451,12 @@ public function provideValuesThatTriggerEarlyExpiry(): iterable { yield 'Big ctime with normal beta' => [ 'ctime' => \PHP_INT_MAX, - 'beta' => 1.0 + 'beta' => 1.0, ]; yield 'Normal ctime with INF beta' => [ 'ctime' => 100, - 'beta' => \INF + 'beta' => \INF, ]; } @@ -425,10 +488,14 @@ public function testInvalidateTags(): void private static function assertCacheItemExpiryEquals(float $expiry, CacheItem $cacheItem) { - $cacheItemExpiry = (\Closure::bind(function (CacheItem $item) { - return $item->expiry; - }, null, CacheItem::class))($cacheItem); - self::assertEquals($expiry, $cacheItemExpiry); + self::assertEquals($expiry, self::getCacheItemExpiry($cacheItem)); + } + + private static function assertCacheItemExpiryBetween(float $expiryMin, float $expiryMax, CacheItem $cacheItem) + { + $cacheItemExpiry = self::getCacheItemExpiry($cacheItem); + self::assertGreaterThan($expiryMin, $cacheItemExpiry); + self::assertLessThan($expiryMax, $cacheItemExpiry); } private static function getCacheItemExpiry(CacheItem $cacheItem)