Bug #60760
closed
Race condition during system cache flush
Added by Alexander Hense almost 10 years ago. Updated over 8 years ago.
0%
Description
TYPO3 6.2.4
When flushing the system cache there seems to be a time frame for a race condition. This can lead to different "class/interface not found" errors.
Steps to reproduce:
Use apache benchmark to start multiple concurrent requests, e.g.:
ab -n 100 -c 10 http://typo3dev.localhost/
While ab is running, flush the system cache in the backend. Now, reload the frontend to see some kind of error, e.g.:
Fatal error: Interface 'Psr\Log\LoggerInterface' not found in /home/ahense/src/TYPO3.CMS/typo3/sysext/core/Classes/Log/Logger.php on line 24
This works almost every time. For somewhat faster computers you might want to increase ab to -n 500 and -c 20.
The frontend only works again after flushing the system cache once more.
The problem seems to be a race condition which occurs when the frontend is being rendered while the system cache flushing process is still in progress. The system cache flushing does not correctly lock other calls to prevent the construction of a broken cache.
Files
| example1.txt (22.4 KB) example1.txt | Complete log of first example | Melanie Kalka, 2016-01-07 10:47 | |
| example2.txt (36.6 KB) example2.txt | Complete log of second example | Melanie Kalka, 2016-01-07 10:47 |
Updated by Mathias Schreiber over 9 years ago
- Target version set to 7.3 (Packages)
Updated by Alexander Opitz over 9 years ago
Hi,
is this issue reproduceable with a newer version of TYPO3? Namely the latest 6.2.9.
Updated by Alexander Hense over 9 years ago
is this issue reproduceable with a newer version of TYPO3? Namely the latest 6.2.9.
I have just tried it again multiple times with a TYPO3 6.2.9 system using exactly the steps I initially described. The result is the same.
Updated by Alexander Opitz over 9 years ago
- Category set to 1499
- Status changed from New to Needs Feedback
- Complexity set to medium
Hmmm ok, so I like to know something more about your system.
Windows or Unixoid? If Unixoid, what is the filesystem on which typo3temp exists? And can you check if in typo3temp/locks a file is created and removed (thats the lock file which should prevent your mentioned race condition)?
Updated by Camelia M over 9 years ago
same issue here. typo3 6.2.9 on linux
I have a lock file created today (around the time the clear cache was made). the log did not get removed. not even at log out
Updated by Alexander Opitz over 9 years ago
Hi Camelia,
on which type of filesystem does your typo3temp exists?
Updated by Benni Mack about 9 years ago
- Target version changed from 7.3 (Packages) to 7.4 (Backend)
Updated by Susanne Moog almost 9 years ago
- Target version changed from 7.4 (Backend) to 7.5
Updated by Alexander Opitz almost 9 years ago
- Status changed from Needs Feedback to Closed
No feedback within the last 90 days => closing this issue.
If you think that this is the wrong decision or experience this issue again, then please write to the mailing list typo3.teams.bugs with issue number and an explanation or open a new ticket and add a relation to this ticket number.
Updated by Alexander Opitz over 8 years ago
- Status changed from Closed to New
Reopened as requested in newsgroup typo3.teams.bugs.
Updated by Melanie Kalka over 8 years ago
I have also seen this bug frequently in some more frequented webpages.
But i was not able to reproduce the error every time using ab, only one and then.
So, in order to find a fix i made a logfile which logged access to the get(), set() and flush() functions in \TYPO3\CMS\Core\Cache\Backend\SimpleFileBackend.
When the error happened, i saw the following in the log file:
17:01:15:1452096075.5473 - FLUSH: started ... 17:01:15:1452096075.6304 - GET: tx_solr_plugincommand 17:01:15:1452096075.6306 - GET: tx_solr_plugincommand 17:01:15:1452096075.6308 - SET: tx_solr_plugincommand with length 0 ... 17:01:15:1452096075.7345 - GET: tx_solr_plugincommand ... 17:01:16:1452096076.4872 - FLUSH: end
When flush is called, the frontend calls the get method and later on rewrites the cache entry with a zero length.
After that flush ends.
Now i have an zero length cache file in Cache/Data/cache_classes, which in the specific case also prevents the cache clearing from the backend. Only clear all cache from install tool will fix the webpage.
I would suggest that when flush gets started a status variable should be set as long as flush is running.
All calls to get(), has(), and set() should be suspended as long this status variable is set. Maybe with a timeout that throws an exception when flush lasts to long.
Updated by Alexander Opitz over 8 years ago
Hi Melanie,
I digged through the source with your information in mind.
I assume the FLUSH and the GET/SET commands are done in different threads. So while one thread flushes another thread tries to read from the cache. The function behind the flush GeneralUtility::flushDirectory() does three steps.
1.) Rename the cacheDirectory
2.) Recreate the cacheDirectory
3.) Deletes the renamed cacheDirectory now
As renaming/recreating is the fastest way to get the cache empty, the flush is done after point 2 (from the point of view of another thread).
So I'd like to get more output from your logfile. ;-)
1.) Does GET stops at return false (as file doesn't exists) or does it return data from file_get_contents?
2.) Can you please add logging inside GeneralUtility::flushDirectory()? One after static::mkdir($directory);, one after clearstatcache(); and one after $result = static::rmdir($temporaryDirectory, true);
And post the result after next "crash"?
Updated by Alexander Opitz over 8 years ago
And I forget, you should also add $this->cacheDirectory to the output of SET/GET/FLUSH so we know that this is about same directory.
Updated by Melanie Kalka over 8 years ago
- File example1.txt example1.txt added
- File example2.txt example2.txt added
Yes, you are right. A static variable would not work, as that are different threads.
I have added some more logging (including the pid of the process) and even had an example where set() was executed with empty data right after flush() was finished.
The only thing that always occurs is, that it first tries to read the cache two times and that sets the length to zero. So the real problem might be somewhere else while building the cache.
Here are two excerpts from where the bug occured.
I have attached the full logs as textfiles.
All logging inside SimpleFileBackend and GeneralUtility is only done for the specific classes cache directory.
I used something like this:
$x = file_get_contents($pathAndFilename);
if ($this->cacheDirectory === '/var/www/vhosts/project/htdocs/typo3temp/Cache/Data/cache_classes/') {
file_put_contents('/var/www/vhosts/project/htdocs/debug.txt', date('H:m:s:') . microtime(TRUE) . ' - GET (pid ' . getmypid() . '): ' . $entryIdentifier . ' with length ' . strlen($x) . "\n", FILE_APPEND);
}
return $x;
Here are the examples:
10:01:43:1452158323.9109 - GET (pid 981): tx_solr_plugincommand with length 99 10:01:45:1452158325.5529 - clear_cacheCmd (pid 1729): for cache system 10:01:45:1452158325.5663 - FLUSH (pid 1729): started 10:01:45:1452158325.5664 - flushDirectory (pid 1729): before is_dir 10:01:45:1452158325.5664 - flushDirectory (pid 1729): is_dir begin 10:01:45:1452158325.5665 - flushDirectory (pid 1729): before rename 10:01:45:1452158325.5665 - flushDirectory (pid 1729): after rename 10:01:45:1452158325.5665 - flushDirectory (pid 1729): before mkdir 10:01:45:1452158325.5667 - flushDirectory (pid 1729): after mkdir 10:01:45:1452158325.5667 - flushDirectory (pid 1729): before clearstatcache 10:01:45:1452158325.5667 - flushDirectory (pid 1729): after clearstatcache/before rmdir 10:01:45:1452158325.7857 - flushDirectory (pid 1729): after rmdir 10:01:45:1452158325.7857 - flushDirectory (pid 1729): is_dir end 10:01:45:1452158325.7858 - FLUSH (pid 1729): end 10:01:45:1452158325.8162 - GET (pid 1619): tx_solr_plugincommand file not found 10:01:45:1452158325.8164 - GET (pid 1619): tx_solr_plugincommand file not found 10:01:45:1452158325.8166 - SET (pid 1619): tx_solr_plugincommand with length 0 10:01:48:1452158328.0749 - GET (pid 973): tx_solr_plugincommand with length 0 Fatal error: Class 'Tx_Solr_PluginCommand' not found in ...
10:01:07:1452159067.3329 - clear_cacheCmd (pid 3980): for cache system 10:01:07:1452159067.4154 - GET (pid 3964): tx_solr_plugincommand with length 99 10:01:07:1452159067.4202 - FLUSH (pid 3980): started 10:01:07:1452159067.4202 - flushDirectory (pid 3980): before is_dir 10:01:07:1452159067.4203 - flushDirectory (pid 3980): is_dir begin 10:01:07:1452159067.4203 - flushDirectory (pid 3980): before rename 10:01:07:1452159067.4203 - flushDirectory (pid 3980): after rename 10:01:07:1452159067.4204 - flushDirectory (pid 3980): before mkdir 10:01:07:1452159067.4205 - flushDirectory (pid 3980): after mkdir 10:01:07:1452159067.4206 - flushDirectory (pid 3980): before clearstatcache 10:01:07:1452159067.4206 - flushDirectory (pid 3980): after clearstatcache/before rmdir 10:01:07:1452159067.7094 - GET (pid 3959): tx_solr_plugincommand file not found 10:01:07:1452159067.7096 - GET (pid 3959): tx_solr_plugincommand file not found 10:01:07:1452159067.7097 - SET (pid 3959): tx_solr_plugincommand with length 0 10:01:08:1452159068.4207 - flushDirectory (pid 3980): after rmdir 10:01:08:1452159068.4208 - flushDirectory (pid 3980): is_dir end 10:01:08:1452159068.4208 - FLUSH (pid 3980): end 10:01:15:1452159075.6262 - GET (pid 3957): tx_solr_plugincommand with length 0 Fatal error: Class 'Tx_Solr_PluginCommand' not found in ...
Updated by Alexander Opitz over 8 years ago
Hi Melanie,
I read both files and I must say ... the flush of the cache looks fine. All works as expected.
The cache is read 2 times from the Core\ClassLoader while retrieving information about a class. Following steps are done by the ClassLoader::loadClass($className)
1.) Look into cache if class information is there. ClassLoader::getClassLoadingInformationFromCache()
2.) Not found then build this information. ClassLoader::buildCachedClassLoadingInformation()
3.) Aquire a look for class loader cache
4.) If look is aquired look again if class loading information is there (maybe another thread wrote it in the time we waited for the lock) ClassLoader::getClassLoadingInformationFromCache() <== This is the second time cache is read which failed.
5.) Build the class loading information, which then fails. ClassLoader::buildClassLoadingInformation()
6.) Write an empty string into cache to signaling that this class isn't found.
So the real question is, why does ClassLoader::buildClassLoadingInformation() fail for some classes? Course as we can see, there are classes which will be found, while at same time some fail to be found. So we need more information in your log file. ;-) ClassLoader::buildClassLoadingInformation() calls 4 different sub functions. So can you please log the result (false or length of the array) of every function call (first will mostly false as it seams not happen for core classes), so we know which function gives us no empty response. So we can look into which functions may course the issue.
Updated by Melanie Kalka over 8 years ago
I added a debug_backtrace after multiple classes caches where crashing in one of my tests.
The backtrace right before the class cache is set to an empty length is the following:
array (
0 =>
array (
'file' => '/var/www/t3sources/typo3_src-6.2.14/typo3/sysext/core/Classes/Cache/Frontend/StringFrontend.php',
'line' => 50,
'function' => 'set',
'class' => 'TYPO3\\CMS\\Core\\Cache\\Backend\\SimpleFileBackend',
'type' => '->',
),
1 =>
array (
'file' => '/var/www/t3sources/typo3_src-6.2.14/typo3/sysext/core/Classes/Core/ClassLoader.php',
'line' => 267,
'function' => 'set',
'class' => 'TYPO3\\CMS\\Core\\Cache\\Frontend\\StringFrontend',
'type' => '->',
),
2 =>
array (
'file' => '/var/www/t3sources/typo3_src-6.2.14/typo3/sysext/core/Classes/Core/ClassLoader.php',
'line' => 182,
'function' => 'buildCachedClassLoadingInformation',
'class' => 'TYPO3\\CMS\\Core\\Core\\ClassLoader',
'type' => '->',
),
3 =>
array (
'function' => 'loadClass',
'class' => 'TYPO3\\CMS\\Core\\Core\\ClassLoader',
'type' => '->',
),
4 =>
array (
'file' => '/var/www/vhosts/isotec/htdocs/typo3temp/Cache/Code/cache_core/ext_localconf_a0abb26f720ffb167ee0cf0739f45027d217b48b.php',
'line' => 2813,
'function' => 'spl_autoload_call',
),
)
So the bug seems to happen inside TYPO3\CMS\Core\Core\ClassLoader where it sets it to an empty in the last if condition:
protected function buildCachedClassLoadingInformation($cacheEntryIdentifier, $className) {
// We do not need locking if we are in earlyCache mode
$didLock = FALSE;
if (!$this->isEarlyCache) {
$didLock = $this->acquireLock();
}
// Look again into the cache after we got the lock, data might have been generated meanwhile
$classLoadingInformation = $this->getClassLoadingInformationFromCache($cacheEntryIdentifier);
// Handle repeated cache miss
if ($classLoadingInformation === FALSE) {
// Generate class information
$classLoadingInformation = $this->buildClassLoadingInformation($className);
if ($classLoadingInformation !== FALSE) {
// If we found class information, cache it
$this->classesCache->set(
$cacheEntryIdentifier,
implode("\xff", $classLoadingInformation),
$this->isEarlyCache ? array('early') : array()
);
} elseif (!$this->isEarlyCache) {
if ($this->context->isProduction()) {
// Cache that the class is unknown
$this->classesCache->set($cacheEntryIdentifier, '');
}
}
}
$this->releaseLock($didLock);
return $classLoadingInformation;
}
Updated by Alexander Opitz over 8 years ago
The bug isn't there, the question is, why the class couldn't be loaded.
Updated by Alexander Opitz over 8 years ago
Thoughts afterwards I've other questions.
sunzinet_isotecpartners_view_location_contacthtml is from an Extbase extension?
tx_solr_plugincommand is a non Extbase extension?
Updated by Melanie Kalka over 8 years ago
I added the logging to buildClassLoadingInformation.
When this happens all of the four calls fail to get the class information.
I had the bugs in the current site i am checking with the classes:
tx_solr_plugincommand
tx_smarty_service_compatibility
Both have in common that they make use of ext_autoload.php:
'tx_solr_plugincommand' => $extensionPath . 'Interfaces/PluginCommand.php' 'tx_smarty_service_compatibility' => $extensionClassesPath . 'Service/Compatility.php'
And you are right, the other - working class - is an extbase extension, that does not need ext_autoload.php.
I also observed this on other pages with classes like
tx_igldapssoauth_auth
tx_igldapssoauth_sv1
They too use ext_autoload.php.
Is it possible that the ext_autoload.php is not available at the time it tries to find the classes because the cache was cleared before?
Updated by Alexander Opitz over 8 years ago
It seams I understand why this happens,
you wrote you only log for "/var/www/vhosts/project/htdocs/typo3temp/Cache/Data/cache_classes/" can you also log FLUSH for "/var/www/vhosts/project/htdocs/typo3temp/Cache/Code/cache_core/" please?
Updated by Melanie Kalka over 8 years ago
Here is another log including the core cache.
In this example the core cache is fully flushed before the class loader tries to get the class information.
13:01:55:1452170635.1089 - clear_cacheCmd (pid 23605): for cache system 13:01:55:1452170635.1609 - FLUSH - core (pid 23605): started 13:01:55:1452170635.161 - flushDirectory - core (pid 23605): before is_dir 13:01:55:1452170635.161 - flushDirectory - core (pid 23605): is_dir begin 13:01:55:1452170635.161 - flushDirectory - core (pid 23605): before rename 13:01:55:1452170635.1611 - flushDirectory - core (pid 23605): after rename 13:01:55:1452170635.1611 - flushDirectory - core (pid 23605): before mkdir 13:01:55:1452170635.1613 - flushDirectory - core (pid 23605): after mkdir 13:01:55:1452170635.1613 - flushDirectory - core (pid 23605): before clearstatcache 13:01:55:1452170635.1613 - flushDirectory - core (pid 23605): after clearstatcache/before rmdir 13:01:55:1452170635.163 - flushDirectory - core (pid 23605): after rmdir 13:01:55:1452170635.163 - flushDirectory - core (pid 23605): is_dir end 13:01:55:1452170635.163 - FLUSH - core (pid 23605): end 13:01:55:1452170635.1631 - FLUSH - classes (pid 23605): started 13:01:55:1452170635.1631 - flushDirectory - classes (pid 23605): before is_dir 13:01:55:1452170635.1631 - flushDirectory - classes (pid 23605): is_dir begin 13:01:55:1452170635.1632 - flushDirectory - classes (pid 23605): before rename 13:01:55:1452170635.1632 - flushDirectory - classes (pid 23605): after rename 13:01:55:1452170635.1632 - flushDirectory - classes (pid 23605): before mkdir 13:01:55:1452170635.1634 - flushDirectory - classes (pid 23605): after mkdir 13:01:55:1452170635.1634 - flushDirectory - classes (pid 23605): before clearstatcache 13:01:55:1452170635.1634 - flushDirectory - classes (pid 23605): after clearstatcache/before rmdir 13:01:55:1452170635.2638 - GET - classes (pid 19904): tx_smarty_service_compatibility file not found 13:01:55:1452170635.273 - GET - classes (pid 19904): tx_smarty_service_compatibility file not found 13:01:55:1452170635.273 - buildClassLoadingInformationForClassFromCorePackage (pid 19904): for Tx_Smarty_Service_Compatibility failed 13:01:55:1452170635.2731 - fetchClassLoadingInformationFromRuntimeCache (pid 19904): for Tx_Smarty_Service_Compatibility failed 13:01:55:1452170635.2731 - buildClassLoadingInformationForClassFromRegisteredPackages (pid 19904): for Tx_Smarty_Service_Compatibility failed 13:01:55:1452170635.2732 - buildClassLoadingInformationForClassByNamingConvention (pid 19904): for Tx_Smarty_Service_Compatibility failed 13:01:55:1452170635.2733 - SET - classes (pid 19904): tx_smarty_service_compatibility with length 0 13:01:56:1452170636.0487 - flushDirectory - classes (pid 23605): after rmdir 13:01:56:1452170636.0488 - flushDirectory - classes (pid 23605): is_dir end 13:01:56:1452170636.0488 - FLUSH - classes (pid 23605): end
It seems that the ext_autoload.php information does not get cached. So currently i can not understand why the class do not get found by the class loader.
Updated by Melanie Kalka over 8 years ago
As far as i can see till now, the class cache data for classes from ext_autoload.php is set by transferRuntimeClassInformationCacheEntriesToClassesCache() from TYPO3\CMS\Core\Core\ClassLoader.
My suspect - as far as i can see from my log is - that this function might get executed, when clearing cache gets finished. But the problem might occure, when the class loader has to find the class, before the transfer function was called:
14:01:25:1452173005.2605 - clear_cacheCmd (pid 26954): for cache system 14:01:25:1452173005.2638 - FLUSH - core (pid 26954): started 14:01:25:1452173005.2638 - flushDirectory - core (pid 26954): before is_dir 14:01:25:1452173005.2639 - flushDirectory - core (pid 26954): is_dir begin 14:01:25:1452173005.264 - flushDirectory - core (pid 26954): before rename 14:01:25:1452173005.264 - flushDirectory - core (pid 26954): after rename 14:01:25:1452173005.264 - flushDirectory - core (pid 26954): before mkdir 14:01:25:1452173005.2642 - flushDirectory - core (pid 26954): after mkdir 14:01:25:1452173005.2642 - flushDirectory - core (pid 26954): before clearstatcache 14:01:25:1452173005.2642 - flushDirectory - core (pid 26954): after clearstatcache/before rmdir 14:01:25:1452173005.2654 - flushDirectory - core (pid 26954): after rmdir 14:01:25:1452173005.2654 - flushDirectory - core (pid 26954): is_dir end 14:01:25:1452173005.2654 - FLUSH - core (pid 26954): end 14:01:25:1452173005.2655 - FLUSH - classes (pid 26954): started 14:01:25:1452173005.2655 - flushDirectory - classes (pid 26954): before is_dir 14:01:25:1452173005.2655 - flushDirectory - classes (pid 26954): is_dir begin 14:01:25:1452173005.2656 - flushDirectory - classes (pid 26954): before rename 14:01:25:1452173005.2656 - flushDirectory - classes (pid 26954): after rename 14:01:25:1452173005.2656 - flushDirectory - classes (pid 26954): before mkdir 14:01:25:1452173005.2657 - flushDirectory - classes (pid 26954): after mkdir 14:01:25:1452173005.2658 - flushDirectory - classes (pid 26954): before clearstatcache 14:01:25:1452173005.2658 - flushDirectory - classes (pid 26954): after clearstatcache/before rmdir 14:01:25:1452173005.3225 - flushDirectory - classes (pid 26954): after rmdir 14:01:25:1452173005.3226 - flushDirectory - classes (pid 26954): is_dir end 14:01:25:1452173005.3226 - FLUSH - classes (pid 26954): end 14:01:26:1452173006.7552 - transferRuntimeClassInformationCacheEntriesToClassesCache (pid 26958): for tx_smarty_service_compatibility before has 14:01:26:1452173006.7553 - HAS - classes (pid 26958): tx_smarty_service_compatibility fail 14:01:26:1452173006.7553 - transferRuntimeClassInformationCacheEntriesToClassesCache (pid 26958): for tx_smarty_service_compatibility before set 14:01:26:1452173006.7553 - SET - classes (pid 26958): tx_smarty_service_compatibility with length 114 14:01:26:1452173006.7555 - transferRuntimeClassInformationCacheEntriesToClassesCache (pid 26958): for tx_smarty_service_compatibility after set 14:01:33:1452173013.7288 - clear_cacheCmd (pid 26954): for cache system 14:01:33:1452173013.7477 - FLUSH - core (pid 26954): started 14:01:33:1452173013.7478 - flushDirectory - core (pid 26954): before is_dir 14:01:33:1452173013.7478 - flushDirectory - core (pid 26954): is_dir begin 14:01:33:1452173013.7478 - flushDirectory - core (pid 26954): before rename 14:01:33:1452173013.756 - GET - classes (pid 26921): tx_smarty_service_compatibility with length 114 14:01:33:1452173013.7673 - GET - classes (pid 26956): tx_smarty_service_compatibility with length 114 14:01:33:1452173013.7754 - GET - classes (pid 26893): tx_news_utility_emconfiguration with length 116 14:01:33:1452173013.7889 - flushDirectory - core (pid 26954): after rename 14:01:33:1452173013.7889 - flushDirectory - core (pid 26954): before mkdir 14:01:33:1452173013.7891 - flushDirectory - core (pid 26954): after mkdir 14:01:33:1452173013.7892 - flushDirectory - core (pid 26954): before clearstatcache 14:01:33:1452173013.7892 - flushDirectory - core (pid 26954): after clearstatcache/before rmdir 14:01:33:1452173013.7893 - GET - classes (pid 26953): tx_smarty_service_compatibility with length 114 14:01:33:1452173013.7902 - flushDirectory - core (pid 26954): after rmdir 14:01:33:1452173013.7902 - flushDirectory - core (pid 26954): is_dir end 14:01:33:1452173013.7903 - FLUSH - core (pid 26954): end 14:01:33:1452173013.7903 - FLUSH - classes (pid 26954): started 14:01:33:1452173013.7904 - flushDirectory - classes (pid 26954): before is_dir 14:01:33:1452173013.7904 - flushDirectory - classes (pid 26954): is_dir begin 14:01:33:1452173013.7904 - flushDirectory - classes (pid 26954): before rename 14:01:33:1452173013.7905 - flushDirectory - classes (pid 26954): after rename 14:01:33:1452173013.7905 - flushDirectory - classes (pid 26954): before mkdir 14:01:33:1452173013.7906 - flushDirectory - classes (pid 26954): after mkdir 14:01:33:1452173013.7906 - flushDirectory - classes (pid 26954): before clearstatcache 14:01:33:1452173013.7907 - flushDirectory - classes (pid 26954): after clearstatcache/before rmdir 14:01:33:1452173013.8243 - GET - classes (pid 23613): tx_smarty_service_compatibility file not found 14:01:33:1452173013.8253 - GET - classes (pid 23613): tx_smarty_service_compatibility file not found 14:01:33:1452173013.8254 - buildClassLoadingInformationForClassFromCorePackage (pid 23613): for Tx_Smarty_Service_Compatibilityfailed 14:01:33:1452173013.8254 - fetchClassLoadingInformationFromRuntimeCache (pid 23613): for Tx_Smarty_Service_Compatibilityfailed 14:01:33:1452173013.8255 - buildClassLoadingInformationForClassFromRegisteredPackages (pid 23613): for Tx_Smarty_Service_Compatibilityfailed 14:01:33:1452173013.8256 - buildClassLoadingInformationForClassByNamingConvention (pid 23613): for Tx_Smarty_Service_Compatibilityfailed 14:01:33:1452173013.8257 - SET - classes (pid 23613): tx_smarty_service_compatibility with length 0 14:01:33:1452173013.8284 - GET - classes (pid 26897): tx_smarty_service_compatibility with length 0 14:01:33:1452173013.8435 - GET - classes (pid 26917): tx_smarty_service_compatibility with length 0 14:01:33:1452173013.8567 - GET - classes (pid 26922): tx_smarty_service_compatibility with length 0 14:01:33:1452173013.861 - GET - classes (pid 26924): tx_smarty_service_compatibility with length 0 14:01:34:1452173014.6545 - flushDirectory - classes (pid 26954): after rmdir 14:01:34:1452173014.6546 - flushDirectory - classes (pid 26954): is_dir end 14:01:34:1452173014.6546 - FLUSH - classes (pid 26954): end
So i think buildClassLoadingInformation() will always fail for classes, that need ext_autoload.php information, as long as this information was not transfered before by transferRuntimeClassInformationCacheEntriesToClassesCache()
Updated by Melanie Kalka over 8 years ago
I think, i have the reason why this happens.
The workflow in TYPO3 when a page is called in the frontend is like this:
TYPO3\CMS\Core\Core\Bootstrap
-> loadConfigurationAndInitialize
-> initializePackageManagement
TYPO3\CMS\Core\Package\PackageManager
-> initialize
TYPO3\CMS\Core\Core\ClassLoader
-> setPackages
-> buildPackageNamespacesAndClassesPaths
-> transferRuntimeClassInformationCacheEntriesToClassesCache
So the classes cache for classes in ext_autoload.php is created while the page gets loaded.
But when another thread clears the cache meanwhile, the class information for this classes gets lost.
The function buildClassLoadingInformation() uses fetchClassLoadingInformationFromRuntimeCache() as the second try which should find the autoload class and write it to the classes cache.
But this function uses the array $this->runtimeClassLoadingInformationCache.
But this array already gets cleared at the end of setPackages() after the cache was done.
So fetchClassLoadingInformationFromRuntimeCache() will always fail, when another thread has cleared the cache meanwhile.
1. Thread 1 writes ext_autoload classes to classes cache
2. Thread 2 clears the classes cache
3. Thread 1 tries to load a class from an ext_autoload class, which results in not finding it and writing a zero length cache file
4. All following threads will fail to load the class
I would suggest that transferRuntimeClassInformationCacheEntriesToClassesCache() not only checks if a specific class exists, that it also checks that the cache file is not of zero length.
Otherwise write it again in the cache. That would at least prevent, that all following threads will fail to load the class.
$this->runtimeClassLoadingInformationCache gets normally perfilled by loadClassFilesFromAutoloadRegistryIntoRuntimeClassInformationCache() which is called from buildPackageNamespacesAndClassesPaths() that was run by the bootstrap process.
Updated by Gerrit Code Review over 8 years ago
- Status changed from New to Under Review
Patch set 1 for branch TYPO3_6-2 of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/45642
Updated by Alexander Opitz over 8 years ago
- Status changed from Under Review to New
Hi Melanie,
exactly. You got it. I already wrote a patch, which checks if core_cache was cleared (while we only need class_cache) and fills it up (before we try to load the class from cache a second time).
This way around, we shouldn't get any notice.
Your described way have one nitpick, it would only help for threads started after the flush but not for threads started before flushing and loading a mapped class after flashing.
BTW: This issue described last haven't to do with the issue from the original poster, as his problem was with a class which isn't aliased. The original issue was solved.
Updated by Melanie Kalka over 8 years ago
I can confirm that your patch solves my bug with the not found ext_autoload classes.
Would be great to get this patch in the next TYPO3 version.
Updated by Alexander Opitz over 8 years ago
- Status changed from New to Under Review
- Target version set to 6.2.18
Hi Melanie,
then please vote the patch on the review server.
Updated by Alexander Opitz over 8 years ago
Hi Melanie,
which version of TYPO3 6.2 did you use before patch?
Updated by Alexander Opitz over 8 years ago
Ahh ok, since 6.2.15 there is already another fix for that.
Updated by Alexander Opitz over 8 years ago
- Assignee set to Alexander Opitz
- Target version deleted (
6.2.18)
Updated by Alexander Opitz over 8 years ago
- Status changed from Under Review to Closed