Debug for the sake of testSaveOverwritesIfFastIsFull()

Shardj · Aug 17, 2023 · 50d3926 · 50d3926
1 parent f751b33
commit 50d3926
Show file tree

Hide file tree

Showing 6 changed files with 156 additions and 93 deletions.
diff --git a/.github/workflows/phpunit.yml b/.github/workflows/phpunit.yml
@@ -11,16 +11,16 @@ jobs:
     env:
       PHP_INI_VALUES: memory_limit=-1, assert.exception=1, zend.assertions=1, error_reporting=-1, log_errors_max_len=0, display_errors=On
 
-      TESTS_ZEND_DB_ADAPTER_PDO_MYSQL_ENABLED: true
-      TESTS_ZEND_DB_ADAPTER_MYSQL_USERNAME: github
-      TESTS_ZEND_DB_ADAPTER_MYSQL_PASSWORD: github
-      TESTS_ZEND_DB_ADAPTER_MYSQL_DATABASE: zftest
-      TESTS_ZEND_DB_ADAPTER_MYSQL_HOSTNAME: 127.0.0.1
-
-      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_ENABLED: true
-      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_USERNAME: github
-      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_PASSWORD: github
-      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_DATABASE: zftest
+#      TESTS_ZEND_DB_ADAPTER_PDO_MYSQL_ENABLED: true
+#      TESTS_ZEND_DB_ADAPTER_MYSQL_USERNAME: github
+#      TESTS_ZEND_DB_ADAPTER_MYSQL_PASSWORD: github
+#      TESTS_ZEND_DB_ADAPTER_MYSQL_DATABASE: zftest
+#      TESTS_ZEND_DB_ADAPTER_MYSQL_HOSTNAME: 127.0.0.1
+#
+#      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_ENABLED: true
+#      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_USERNAME: github
+#      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_PASSWORD: github
+#      TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_DATABASE: zftest
 
       TESTS_ZEND_CACHE_SQLITE_ENABLED: true
       TESTS_ZEND_DB_ADAPTER_PDO_SQLITE_ENABLED: true
@@ -35,16 +35,16 @@ jobs:
 
       TESTS_ZEND_CACHE_APC_ENABLED: true
 
-      # https://hub.docker.com/r/bitnami/openldap
-      LDAP_ROOT: "dc=example,dc=com"
-      LDAP_ALLOW_ANON_BINDING: false
-      LDAP_SKIP_DEFAULT_TREE: "yes"
-      LDAP_ADMIN_USERNAME: "admin"
-      LDAP_ADMIN_PASSWORD: "insecure"
-      LDAP_CONFIG_ADMIN_USERNAME: "admin"
-      LDAP_CONFIG_ADMIN_PASSWORD: "configpassword"
-      TESTS_ZEND_LDAP_ONLINE_ENABLED: true
-      TESTS_ZEND_AUTH_ADAPTER_LDAP_ONLINE_ENABLED: true
+#      # https://hub.docker.com/r/bitnami/openldap
+#      LDAP_ROOT: "dc=example,dc=com"
+#      LDAP_ALLOW_ANON_BINDING: false
+#      LDAP_SKIP_DEFAULT_TREE: "yes"
+#      LDAP_ADMIN_USERNAME: "admin"
+#      LDAP_ADMIN_PASSWORD: "insecure"
+#      LDAP_CONFIG_ADMIN_USERNAME: "admin"
+#      LDAP_CONFIG_ADMIN_PASSWORD: "configpassword"
+#      TESTS_ZEND_LDAP_ONLINE_ENABLED: true
+#      TESTS_ZEND_AUTH_ADAPTER_LDAP_ONLINE_ENABLED: true
 
       LOCALES: "fr_FR@euro fr_FR fr_BE.UTF-8 de en_US"
       OPENSSL_CONF: "./tests/openssl.conf"
@@ -54,48 +54,48 @@ jobs:
         ports:
           - 11211:11211
 
-      mysql:
-        image: bitnami/mysql:8.0.31
-        env:
-          MYSQL_ROOT_USER: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_USERNAME }}
-          MYSQL_ROOT_PASSWORD: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_PASSWORD }}
-          MYSQL_DATABASE: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_DATABASE }}
-          MYSQL_AUTHENTICATION_PLUGIN: mysql_native_password
-        ports:
-          - 3306:3306
-        options: >-
-          --health-cmd "mysqladmin ping"
-          --health-interval 10s
-          --health-timeout 5s
-          --health-retries 10
-
-      postgres:
-        image: postgres:15.1-alpine
-        ports:
-          - 5432:5432
-        env:
-          POSTGRES_USER: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_USERNAME }}
-          POSTGRES_PASSWORD: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_PASSWORD }}
-          POSTGRES_DB: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_DATABASE }}
-        options: >-
-          --health-cmd pg_isready
-          --health-interval 10s
-          --health-timeout 5s
-          --health-retries 5
-
-      openldap:
-        image: bitnami/openldap:2.5
-        ports:
-          - 1389:1389
-        env:
-          LDAP_ROOT: ${{ env.LDAP_ROOT }}
-          LDAP_ALLOW_ANON_BINDING: ${{ env.LDAP_ALLOW_ANON_BINDING }}
-          LDAP_SKIP_DEFAULT_TREE: ${{ env.LDAP_SKIP_DEFAULT_TREE }}
-          LDAP_ADMIN_USERNAME: ${{ env.LDAP_ADMIN_USERNAME }}
-          LDAP_ADMIN_PASSWORD: ${{ env.LDAP_ADMIN_PASSWORD }}
-          LDAP_CONFIG_ADMIN_ENABLED: "yes"
-          LDAP_CONFIG_ADMIN_USERNAME: ${{ env.LDAP_CONFIG_ADMIN_USERNAME }}
-          LDAP_CONFIG_ADMIN_PASSWORD: ${{ env.LDAP_CONFIG_ADMIN_PASSWORD }}
+#      mysql:
+#        image: bitnami/mysql:8.0.31
+#        env:
+#          MYSQL_ROOT_USER: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_USERNAME }}
+#          MYSQL_ROOT_PASSWORD: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_PASSWORD }}
+#          MYSQL_DATABASE: ${{ env.TESTS_ZEND_DB_ADAPTER_MYSQL_DATABASE }}
+#          MYSQL_AUTHENTICATION_PLUGIN: mysql_native_password
+#        ports:
+#          - 3306:3306
+#        options: >-
+#          --health-cmd "mysqladmin ping"
+#          --health-interval 10s
+#          --health-timeout 5s
+#          --health-retries 10
+#
+#      postgres:
+#        image: postgres:15.1-alpine
+#        ports:
+#          - 5432:5432
+#        env:
+#          POSTGRES_USER: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_USERNAME }}
+#          POSTGRES_PASSWORD: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_PASSWORD }}
+#          POSTGRES_DB: ${{ env.TESTS_ZEND_DB_ADAPTER_PDO_PGSQL_DATABASE }}
+#        options: >-
+#          --health-cmd pg_isready
+#          --health-interval 10s
+#          --health-timeout 5s
+#          --health-retries 5
+
+#      openldap:
+#        image: bitnami/openldap:2.5
+#        ports:
+#          - 1389:1389
+#        env:
+#          LDAP_ROOT: ${{ env.LDAP_ROOT }}
+#          LDAP_ALLOW_ANON_BINDING: ${{ env.LDAP_ALLOW_ANON_BINDING }}
+#          LDAP_SKIP_DEFAULT_TREE: ${{ env.LDAP_SKIP_DEFAULT_TREE }}
+#          LDAP_ADMIN_USERNAME: ${{ env.LDAP_ADMIN_USERNAME }}
+#          LDAP_ADMIN_PASSWORD: ${{ env.LDAP_ADMIN_PASSWORD }}
+#          LDAP_CONFIG_ADMIN_ENABLED: "yes"
+#          LDAP_CONFIG_ADMIN_USERNAME: ${{ env.LDAP_CONFIG_ADMIN_USERNAME }}
+#          LDAP_CONFIG_ADMIN_PASSWORD: ${{ env.LDAP_CONFIG_ADMIN_PASSWORD }}
 
     strategy:
       fail-fast: false
@@ -161,21 +161,21 @@ jobs:
           restore-keys: ${{ runner.os }}-${{ matrix.php-version }}-composer-
 
       - name: Install dependencies
-        run: composer install --prefer-dist --no-progress --no-suggest
-
-      - name: Lint PHP source files
-        run: |
-          bin/parallel-lint --exclude vendor --exclude tests/Zend/Loader/_files/ParseError.php . --checkstyle | cs2pr
-
-      - name: "Run tests on PHP ${{ matrix.php-version }} (Experimental: ${{ matrix.experimental }}) with minimal extensions"
-        run: |
-          bin/phpunit -c tests/phpunit.xml
-        continue-on-error: ${{ matrix.experimental }}
-
-      - name: Setup LDAP
-        run: |
-          sudo apt-get install -y libnss-ldap libpam-ldap ldap-utils
-          tests/resources/openldap/docker-entrypoint-initdb.d/init.sh
+        run: composer install --prefer-dist --no-progress --no-interaction
+
+#      - name: Lint PHP source files
+#        run: |
+#          bin/parallel-lint --exclude vendor --exclude tests/Zend/Loader/_files/ParseError.php . --checkstyle | cs2pr
+#
+#      - name: "Run tests on PHP ${{ matrix.php-version }} (Experimental: ${{ matrix.experimental }}) with minimal extensions"
+#        run: |
+#          bin/phpunit -c tests/phpunit.xml
+#        continue-on-error: ${{ matrix.experimental }}
+
+#      - name: Setup LDAP
+#        run: |
+#          sudo apt-get install -y libnss-ldap libpam-ldap ldap-utils
+#          tests/resources/openldap/docker-entrypoint-initdb.d/init.sh
 
       - name: Install PHP with extensions
         uses: shivammathur/setup-php@v2

diff --git a/library/Zend/Cache/Backend/Apc.php b/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;
     }
 

diff --git a/library/Zend/Cache/Backend/File.php b/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;

diff --git a/library/Zend/Cache/Backend/TwoLevels.php b/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();

diff --git a/tests/Zend/Cache/FileBackendTest.php b/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]);
+    }
 }
diff --git a/tests/Zend/Cache/TwoLevelsBackendTest.php b/tests/Zend/Cache/TwoLevelsBackendTest.php
@@ -99,30 +99,55 @@ 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);
+//        $fastBackend->expects($this->atLeastOnce())
+//            ->method('save');
+//        $fastBackend->expects($this->atLeastOnce())
+//            ->method('load');
 
         $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));
+//        $logWriter = new Zend_Log_Writer_Mock();
+//        $logger = new Zend_Log($logWriter);
         $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" .
+            //var_export($logWriter->events, true);
+            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" .
+            //var_export($logWriter->events, true);
+            stream_get_contents($logStream, -1, 0);
+        //rewind($logStream);
+        $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" .
+            //var_export($logWriter->events, true);
+            stream_get_contents($logStream, -1, 0);
+        $this->assertEquals(100, $loadResult, $failMessage);
     }
 
     /**