[horde] Problems with Horde Cache after upgrading to Webmail 5.2.12

Thu Feb 18 20:11:06 UTC 2016

Citeren Jan Schneider <jan at horde.org>:

> Zitat von Arjen de Korte <arjen+horde at de-korte.org>:
>
>> Citeren Anton Köstlbacher <horde3 at dingsbums.org>:
>>
>>> Am 10.02.2016 um 16:13 schrieb Arjen de Korte:
>>>> Citeren Jan Schneider <jan at horde.org>:
>>>>
>>>>> Zitat von Anton Köstlbacher <horde3 at dingsbums.org>:
>>>>>
>>>>>> Am 10.02.2016 um 12:04 schrieb Jan Schneider:
>>>>>>>
>>>>>>> Zitat von Anton Köstlbacher <horde3 at dingsbums.org>:
>>>>>>>
>>>>>>>> Am 10.02.2016 um 09:57 schrieb Jan Schneider:
>>>>>>>>>
>>>>>>>>> Zitat von Anton Köstlbacher <horde3 at dingsbums.org>:
>>>>>>>>>
>>>>>>>>>> Am 09.02.2016 um 15:36 schrieb Jan Schneider:
>>>>>>>>>>>
>>>>>>>>>>> Zitat von Anton Köstlbacher <horde3 at dingsbums.org>:
>>>>>>>>>>>
>>>>>>>>>>>> Dear List,
>>>>>>>>>>>>
>>>>>>>>>>>> a few hours after upgrading I couldn't login to my Horde Webmail.
>>>>>>>>>>>>
>>>>>>>>>>>> Error meesage was "couldn't write to cache". Reason was horde
>>>>>>>>>>>> cache
>>>>>>>>>>>> used up all space on the volume.
>>>>>>>>>>>>
>>>>>>>>>>>> Horde cache was set up as filesystem cache on a 1GB tmpfs volume,
>>>>>>>>>>>> which was sufficient the last years. Lifetime was set to 43200
>>>>>>>>>>>> seconds.
>>>>>>>>>>>>
>>>>>>>>>>>> I changed it to 2GB. This is now sufficient for about two days,
>>>>>>>>>>>> then
>>>>>>>>>>>> it's full again.
>>>>>>>>>>>>
>>>>>>>>>>>> Did anything change regarding cache expiration?
>>>>>>>>>>>>
>>>>>>>>>>>> Looks like it doesn't work anymore. I also replaced
>>>>>>>>>>>> pear/Console_Getopt with pear/Console_GetoptPlus during the
>>>>>>>>>>>> update.
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks in advance!
>>>>>>>>>>>>
>>>>>>>>>>>> Anton
>>>>>>>>>>>> --
>>>>>>>>>>>> Horde mailing list
>>>>>>>>>>>> Frequently Asked Questions: http://horde.org/faq/
>>>>>>>>>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>>>>>>>>
>>>>>>>>>>> Actually the opposite was fixed in the latest Horde_Cache release.
>>>>>>>>>>> Under
>>>>>>>>>>> certain circumstances garbage collection didn't work, and it should
>>>>>>>>>>> work
>>>>>>>>>>> now in all cases.
>>>>>>>>>>>
>>>>>>>>>>> No idea why you mention Console_Getopt.
>>>>>>>>>>>
>>>>>>>>>>> You can try running the unit tests as a first measure, to see if
>>>>>>>>>>> they
>>>>>>>>>>> succeed for you:
>>>>>>>>>>>
>>>>>>>>>>> pear install horde/Horde_Test
>>>>>>>>>>> php $(pear config-get
>>>>>>>>>>> test_dir)/Horde_Cache/Horde/Cache/AllTests.php
>>>>>>>>>>
>>>>>>>>>> Hi Jan,
>>>>>>>>>>
>>>>>>>>>> thanks for your quick reply. I mentioned Console_Getopt just because
>>>>>>>>>> it was the only other thing that changed since the problem occurred.
>>>>>>>>>>
>>>>>>>>>> Output of unit tests, they don't succeed:
>>>>>>>>>>
>>>>>>>>>> PHPUnit 4.5.0 by Sebastian Bergmann and contributors.
>>>>>>>>>>
>>>>>>>>>> F.FFFFFFSSSSSSSS...................SSSSSSSS........SSSSSSSS....
>>>>>>>>>> 63 /
>>>>>>>>>> 123 ( 51%)
>>>>>>>>>> ....SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSPHP Warning:  Uncaught
>>>>>>>>>> Undefined variable: reason
>>>>>>>>>>
>>>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/Sql/Pdo/SqliteTest.php:30
>>>>>>>>>>
>>>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:32
>>>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>>>
>>>>>>>>>> thrown in
>>>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/Sql/Pdo/SqliteTest.php
>>>>>>>>>> on
>>>>>>>>>> line 30
>>>>>>>>>> PHP Fatal error:  Cannot access empty property in
>>>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/Sql/Pdo/SqliteTest.php
>>>>>>>>>> on
>>>>>>>>>> line 30
>>>>>>>>>>
>>>>>>>>>> Any Ideas?
>>>>>>>>>>
>>>>>>>>>> Regards,
>>>>>>>>>> Anton
>>>>>>>>>
>>>>>>>>> This had been fixed with
>>>>>>>>> https://github.com/horde/horde/commit/00821173de24f83586aa3ff57dae5c3ea6f94c5f
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> already, but is hasn't been released yet. Please try this patch
>>>>>>>>> manually.
>>>>>>>>
>>>>>>>> Ok, after patching I get this output from unit tests:
>>>>>>>>
>>>>>>>>
>>>>>>>> PHPUnit 4.5.0 by Sebastian Bergmann and contributors.
>>>>>>>>
>>>>>>>> F.FFFFFFSSSSSSSS...................SSSSSSSS........SSSSSSSS....  63 /
>>>>>>>> 123 ( 51%)
>>>>>>>> ....SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
>>>>>>>>
>>>>>>>> Time: 214 ms, Memory: 7.50Mb
>>>>>>>>
>>>>>>>> There were 7 failures:
>>>>>>>>
>>>>>>>> 1) Horde_Cache_ApcTest::testReadWrite
>>>>>>>> Failed asserting that false is true.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:40
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 2) Horde_Cache_ApcTest::testExists
>>>>>>>> Failed asserting that false is true.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:56
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 3) Horde_Cache_ApcTest::testGet
>>>>>>>> Failed asserting that false matches expected 'data1'.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:66
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 4) Horde_Cache_ApcTest::testOutput
>>>>>>>> Failed asserting that false is true.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:75
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 5) Horde_Cache_ApcTest::testExpire
>>>>>>>> Failed asserting that false matches expected 'data1'.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:83
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 6) Horde_Cache_ApcTest::testClear
>>>>>>>> Failed asserting that false matches expected 'data1'.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:91
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> 7) Horde_Cache_ApcTest::testCompress
>>>>>>>> Failed asserting that false matches expected 'data1'.
>>>>>>>>
>>>>>>>> /usr/share/php/tests/Horde_Cache/Horde/Cache/TestBase.php:108
>>>>>>>> /usr/share/php/Horde/Test/AllTests.php:84
>>>>>>>>
>>>>>>>> FAILURES!
>>>>>>>> Tests: 123, Assertions: 111, Failures: 7, Skipped: 80.
>>>>>>>
>>>>>>> So no failures for the File backend that you use.
>>>>>>>
>>>>>>> Do you use the 'sub' setting? If yes, to you still have a
>>>>>>> horde_cache_gc
>>>>>>> file in the base directory?
>>>>>>>
>>>>>>
>>>>>> I use the 'sub' setting (5) and there is no horde_cache_gc file in
>>>>>> the base cache directory.
>>>>>
>>>>> But there are such files in the leaf directories, right? This means
>>>>> that at least the migration from the old to the new GC technique
>>>>> succeeded.
>>>>>
>>>>> You'll have to find out why GC'ing doesn't work for you anymore.
>>>>> Depending on the traffic of your site, you may want to raise the GC
>>>>> probability in __destruct(). Next you should check if _getGCFiles()
>>>>> (called from _gc()) really returns a valid list of horde_cache_gc
>>>>> files from your leaf directories.
>>>>
>>>> Which at sub setting (5) means that this list may potentially contain
>>>> 16^5 = 1048576 entries. I doubt you'll have configured enough memory to
>>>> store this list. So chances are the process runs out of memory before
>>>> GC'ing actually takes place.
>>>
>>> I reduced to 3 now. Before updating horde_cache it worked  
>>> perfectly with 5 levels for years.
>>
>> Most likely https://bugs.horde.org/ticket/14258
>
> Can you guys please see if this fixes the problem? The garbage  
> collection has to be triggered at least once to clean this up.
>
> http://github.com/horde/horde/commit/395d10cb8b05d3732f627eda9c7d7280bb2bf1bc

The garbage collection on my system (default set to 86400 seconds) has  
been triggered a couple of times now and I can confirm the  
horde_cache_gc files only contain the contents of the leaf nodes and  
old entries from the cache are evicted from the cache when they expire.

Thanks for the quick fix!