symfony · fabpot · Apr 3, 2019 · Apr 3, 2019 · bendavies · Apr 3, 2019
diff --git a/src/Symfony/Component/Cache/LockRegistry.php b/src/Symfony/Component/Cache/LockRegistry.php
@@ -11,6 +11,7 @@

 namespace Symfony\Component\Cache;

+use Psr\Log\LoggerInterface;
 use Symfony\Contracts\Cache\CacheInterface;
 use Symfony\Contracts\Cache\ItemInterface;

@@ -75,7 +76,7 @@ public static function setFiles(array $files): array
        return $previousFiles;
    }

-    public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null)
+    public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null, LoggerInterface $logger = null)
    {
        $key = self::$files ? crc32($item->getKey()) % \count(self::$files) : -1;

@@ -87,6 +88,7 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s
            try {
                // race to get the lock in non-blocking mode
                if (flock($lock, LOCK_EX | LOCK_NB)) {
+                    $logger && $logger->info('Lock acquired, now computing item "{key}"', ['key' => $item->getKey()]);
                    self::$lockedFiles[$key] = true;

                    $value = $callback($item, $save);
@@ -103,6 +105,7 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s
                    return $value;
                }
                // if we failed the race, retry locking in blocking mode to wait for the winner
+                $logger && $logger->info('Item "{key}" is locked, waiting for it to be released', ['key' => $item->getKey()]);
                flock($lock, LOCK_SH);
            } finally {
                flock($lock, LOCK_UN);
@@ -114,13 +117,15 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s

            try {
                $value = $pool->get($item->getKey(), $signalingCallback, 0);
+                $logger && $logger->info('Item "{key}" retrieved after lock was released', ['key' => $item->getKey()]);
                $save = false;

                return $value;
            } catch (\Exception $e) {
                if ($signalingException !== $e) {
                    throw $e;
                }
+                $logger && $logger->info('Item "{key}" not found while lock was released, now retrying', ['key' => $item->getKey()]);
            }
        }
    }

diff --git a/src/Symfony/Component/Cache/Traits/ContractsTrait.php b/src/Symfony/Component/Cache/Traits/ContractsTrait.php
@@ -11,6 +11,7 @@

 namespace Symfony\Component\Cache\Traits;

+use Psr\Log\LoggerInterface;
 use Symfony\Component\Cache\Adapter\AdapterInterface;
 use Symfony\Component\Cache\CacheItem;
 use Symfony\Component\Cache\Exception\InvalidArgumentException;
@@ -40,7 +41,7 @@ trait ContractsTrait
    public function setCallbackWrapper(?callable $callbackWrapper): callable
    {
        $previousWrapper = $this->callbackWrapper;
-        $this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata) {
+        $this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata, ?LoggerInterface $logger) {
            return $callback($item, $save);
        };

@@ -82,13 +83,13 @@ function (CacheItem $item, float $startTime, ?array &$metadata) {
            try {
                $value = $callbackWrapper($callback, $item, $save, $pool, function (CacheItem $item) use ($setMetadata, $startTime, &$metadata) {
                    $setMetadata($item, $startTime, $metadata);
-                });
+                }, $this->logger ?? null);
                $setMetadata($item, $startTime, $metadata);

                return $value;
            } finally {
                $this->callbackWrapper = $callbackWrapper;
            }
-        }, $beta, $metadata);
+        }, $beta, $metadata, $this->logger ?? null);
    }
 }
diff --git a/src/Symfony/Contracts/Cache/CacheTrait.php b/src/Symfony/Contracts/Cache/CacheTrait.php
@@ -13,6 +13,7 @@

 use Psr\Cache\CacheItemPoolInterface;
 use Psr\Cache\InvalidArgumentException;
+use Psr\Log\LoggerInterface;

 /**
 * An implementation of CacheInterface for PSR-6 CacheItemPoolInterface classes.
@@ -37,7 +38,7 @@ public function delete(string $key): bool
        return $this->deleteItem($key);
    }

-    private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null)
+    private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null, LoggerInterface $logger = null)
    {
        if (0 > $beta = $beta ?? 1.0) {
            throw new class(sprintf('Argument "$beta" provided to "%s::get()" must be a positive number, %f given.', \get_class($this), $beta)) extends \InvalidArgumentException implements InvalidArgumentException {
@@ -52,9 +53,13 @@ private function doGet(CacheItemPoolInterface $pool, string $key, callable $call
            $expiry = $metadata[ItemInterface::METADATA_EXPIRY] ?? false;
            $ctime = $metadata[ItemInterface::METADATA_CTIME] ?? false;

-            if ($recompute = $ctime && $expiry && $expiry <= microtime(true) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) {
+            if ($recompute = $ctime && $expiry && $expiry <= ($now = microtime(true)) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) {
                // force applying defaultLifetime to expiry
                $item->expiresAt(null);
+                $this->logger && $this->logger->info('Item "{key}" elected for early recomputation {delta}s before its expiration', [
+                    'key' => $key,
+                    'delta' => sprintf('%.1f', $expiry - $now),
+                ]);
            }
        }