Debug for the sake of testSaveOverwritesIfFastIsFull()

.github/workflows/phpunit.yml

@@ -161,7 +161,7 @@ jobs:
           restore-keys: ${{ runner.os }}-${{ matrix.php-version }}-composer-
 
       - name: Install dependencies
-        run: composer install --prefer-dist --no-progress --no-suggest
+        run: composer install --prefer-dist --no-progress --no-interaction
 
       - name: Lint PHP source files
         run: |

library/Zend/Cache/Backend/Apc.php

@@ -76,7 +76,6 @@ public function load($id, $doNotTestCacheValidity = false)
         if (is_array($tmp)) {
             return $tmp[0] ?? false;
         }
-        apcu_delete($id);
         return false;
     }
 

library/Zend/Cache/Backend/File.php

@@ -250,6 +250,7 @@ public function save($data, $id, $tags = [], $specificLifetime = false)
                 $this->_recursiveMkdirAndChmod($id);
             }
             if (!is_writable($path)) {
+                $this->_log('Zend_Cache_Backend_File::save() : path ' . $path . ' is not writable');
                 return false;
             }
         }
@@ -1011,14 +1012,20 @@ protected function _filePutContents($file, $string)
         $result = false;
         $f = @fopen($file, 'ab+');
         if ($f) {
-            if ($this->_options['file_locking']) @flock($f, LOCK_EX);
+            if ($this->_options['file_locking']) {
+                @flock($f, LOCK_EX);
+            }
             fseek($f, 0);
             ftruncate($f, 0);
             $tmp = @fwrite($f, $string);
             if (!($tmp === FALSE)) {
                 $result = true;
+            } else {
+                $this->_log("Zend_Cache_Backend_File::_filePutContents() : failed to write contents");
             }
             @fclose($f);
+        } else {
+            $this->_log("Zend_Cache_Backend_File::_filePutContents() : we can't obtain handle");
         }
         @chmod($file, $this->_options['cache_file_perm']);
         return $result;

library/Zend/Cache/Backend/TwoLevels.php

@@ -195,23 +195,32 @@ public function test($id)
      */
     public function save($data, $id, $tags = [], $specificLifetime = false, $priority = 8)
     {
+        $this->_log('Calling two level save', Zend_Log::DEBUG);
         $usage = $this->_getFastFillingPercentage('saving');
+        $this->_log('Fast filling usage percentage on save: (' . gettype($usage) . ') ' . var_export($usage, true), Zend_Log::DEBUG);
         $boolFast = true;
         $lifetime = $this->getLifetime($specificLifetime);
         $preparedData = $this->_prepareData($data, $lifetime, $priority);
         if (($priority > 0) && (10 * $priority >= $usage)) {
+            $this->_log('Saving in fast and slow cache', Zend_Log::DEBUG);
             $fastLifetime = $this->_getFastLifetime($lifetime, $priority);
             $boolFast = $this->_fastBackend->save($preparedData, $id, [], $fastLifetime);
+            $this->_log($boolFast ? 'Saving in fast cache is OK' : 'Saving in fast cache is not OK', Zend_Log::DEBUG);
             $boolSlow = $this->_slowBackend->save($preparedData, $id, $tags, $lifetime);
+            $this->_log($boolSlow ? 'Saving in slow cache is OK' : 'Saving in slow cache is not OK', Zend_Log::DEBUG);
         } else {
+            $this->_log('Saving in slow cache only', Zend_Log::DEBUG);
             $boolSlow = $this->_slowBackend->save($preparedData, $id, $tags, $lifetime);
+            $this->_log($boolSlow ? 'Saving in slow cache is OK' : 'Saving in slow cache is not OK', Zend_Log::DEBUG);
             if ($boolSlow === true) {
+                $this->_log('Purging from fast cache on save', Zend_Log::DEBUG);
                 $boolFast = $this->_fastBackend->remove($id);
                 if (!$boolFast && !$this->_fastBackend->test($id)) {
                     // some backends return false on remove() even if the key never existed. (and it won't if fast is full)
                     // all we care about is that the key doesn't exist now
                     $boolFast = true;
                 }
+                $this->_log($boolFast ? 'Successfully purged from fast cache on save' : 'Failed to purge from fast cache on save', Zend_Log::DEBUG);
             }
         }
 
@@ -229,6 +238,7 @@ public function save($data, $id, $tags = [], $specificLifetime = false, $priorit
      */
     public function load($id, $doNotTestCacheValidity = false)
     {
+        $this->_log('Calling two level load', Zend_Log::DEBUG);
         $resultFast = $this->_fastBackend->load($id, $doNotTestCacheValidity);
         $array = null;
         $isFastResult = is_string($resultFast);
@@ -253,9 +263,10 @@ public function load($id, $doNotTestCacheValidity = false)
                 $this->_slowBackend->remove($id);
                 return false;
             }
+            $isFastResult = false;
         }
 
-        //In case no cache entry was found in the FastCache and auto-filling is enabled, copy data to FastCache
+        //In case no cache entry was found in the FastCache (or was corrupted) and auto-filling is enabled, copy data to FastCache
         if (!$isFastResult && $this->_options['auto_fill_fast_cache']) {
             $preparedData = $this->_prepareData($array['data'], $array['lifetime'], $array['priority']);
             $this->_fastBackend->save($preparedData, $id, [], $array['lifetime']);
@@ -540,7 +551,7 @@ public function ___expire($id)
     private function _getFastFillingPercentage($mode)
     {
 
-        if ($mode == 'saving') {
+        if ($mode === 'saving') {
             // mode saving
             if ($this->_fastBackendFillingPercentage === null) {
                 $this->_fastBackendFillingPercentage = $this->_fastBackend->getFillingPercentage();

tests/Zend/Cache/FileBackendTest.php

@@ -200,4 +200,25 @@ public function testShouldDeleteOldMetadataFiles()
         $this->assertTrue($this->_instance->clean(Zend_Cache::CLEANING_MODE_ALL));
         $this->assertFalse(file_exists($fn));
     }
+
+    public function testSaveCorrectCall()
+    {
+        $this->_instance->setDirectives(['logging' => false]);
+        parent::testSaveCorrectCall();
+        $this->_instance->setDirectives(['logging' => true]);
+    }
+
+    public function testSaveWithNullLifeTime()
+    {
+        $this->_instance->setDirectives(['logging' => false]);
+        parent::testSaveWithNullLifeTime();
+        $this->_instance->setDirectives(['logging' => true]);
+    }
+
+    public function testSaveWithSpecificLifeTime()
+    {
+        $this->_instance->setDirectives(['logging' => false]);
+        parent::testSaveWithSpecificLifeTime();
+        $this->_instance->setDirectives(['logging' => true]);
+    }
 }

tests/Zend/Cache/TwoLevelsBackendTest.php

@@ -99,30 +99,45 @@ public function testConstructorCorrectCall()
     public function testSaveOverwritesIfFastIsFull()
     {
         $slowBackend = 'File';
-        $fastBackend = $this->createMock('Zend_Cache_Backend_Apc');
-        $fastBackend->expects($this->at(0))
-            ->method('getFillingPercentage')
-            ->will($this->returnValue(0));
-        $fastBackend->expects($this->at(1))
+        $fastBackend = $this->createPartialMock('Zend_Cache_Backend_Apc', ['getFillingPercentage']);
+        $fastBackend->expects($this->exactly(2))
             ->method('getFillingPercentage')
-            ->will($this->returnValue(90));
-
+            ->willReturn(0, 90);
 
         $slowBackendOptions = [
-            'cache_dir' => $this->_cache_dir
+            'cache_dir' => $this->_cache_dir,
         ];
+
+        $logStream = fopen('php://temp/maxmemory:4194304', 'a+b');
+        $logger = new Zend_Log(new Zend_Log_Writer_Stream($logStream));
         $cache = new Zend_Cache_Backend_TwoLevels([
             'fast_backend' => $fastBackend,
             'slow_backend' => $slowBackend,
             'slow_backend_options' => $slowBackendOptions,
             'stats_update_factor' => 1
         ]);
+        $cache->setDirectives(['logging' => true, 'logger' => $logger]);
 
         $id = 'test' . uniqid();
-        $this->assertTrue($cache->save(10, $id)); //fast usage at 0%
-
-        $this->assertTrue($cache->save(100, $id)); //fast usage at 90%
-        $this->assertEquals(100, $cache->load($id));
+
+        $saveResult = $cache->save(10, $id);
+        $failMessage = 'Failed to save when fast usage is 0. Two level logs: ' . "\n" .
+            stream_get_contents($logStream, -1, 0);
+        $this->assertTrue($saveResult, $failMessage); //fast usage at 0%
+
+        $logger->debug('Finished saving when usage is at 0');
+
+        $saveResult = $cache->save(100, $id);
+        $failMessage = 'Failed to save when fast usage is 90. Two level logs: ' . "\n" .
+            stream_get_contents($logStream, -1, 0);
+        $this->assertTrue($saveResult, $failMessage); //fast usage at 90%
+
+        $logger->debug('Finished saving when usage is at 90');
+
+        $loadResult = $cache->load($id);
+        $failMessage = 'Failed to load when fast usage is 90. Two level logs: ' . "\n" .
+            stream_get_contents($logStream, -1, 0);
+        $this->assertEquals(100, $loadResult, $failMessage);
     }
 
     /**