Revalidate Failure / Files Not Refreshed

laurinkeithdavis commented 10 years ago

We've had some issues with this, but until now, could not nail down for certain what was occurring. This issue occurs about 50% of the time during the process that I will describe.

Specs:

PHP 5.5.4 (bundled ZendOpcache)
IIS 7.5 Server 2008 x64
opcache.revalidate_freq=15
1. I tried to deploy our site (we use a robocopy script after tagging and checking out with Git), it's a large site, but the issue seems to always be with composer files (specifically with the autoload.php file, but not 100% that is always the file)
2. After deployment, the site will not load (blank page)
3. FastCGI log showed this on every request: 1.[02-Oct-2013 02:38:31 America/Chicago] PHP Fatal error: Class 'ComposerAutoloaderInita8d874c72e26eea58cb1ad4a2bfaaf31' not found in C:\inetpub\wwwroot\vendor\autoload.php on line 7
4. That error is correct, the class ''ComposerAutoloaderInita8d874c72e26eea58cb1ad4a2bfaaf31' does not exist anymore
5. I checked and there was not physical file with that call being made, that was the previous autoloader created by composer
6. I ran opcache_reset() and the file refreshed and the site loaded

laurinkeithdavis commented 10 years ago

Is there something that I can do to help this along?

dstogov commented 10 years ago

To understand the problem we need be able to reproduce it. The less the reproduction case the better :)

For now I can just guess. Probably, the deployment process is not atomic. The file where ComposerAutoloaderInita8d874c72e26eea58cb1ad4a2bfaaf31 was defined was reloaded but file where ComposerAutoloaderInita8d874c72e26eea58cb1ad4a2bfaaf31 was used wasn't yet.

rk3rn3r commented 10 years ago

Hello!

We are having a similar issue and in our case it comes from the parameter "opcache.enable_file_override".

Default is 0, but for performance reasons it is a good idea to activate it "opcache.enable_file_override = 1" or "opcache.enable_file_override = On".

But there is a bug because ZendOptimizer does no timestamp revalidation on file_exist, is_file and is_readable calls. This is not a problem as long as you only include or require a removed file, because it is in the cache (as long it is not removed), but it could become an issue when checking with file_exist, is_file or is_readable functions and then calling for example filemtime then.

For example think of a symfony 2 app using Symfony DIC, twig etc. Symfony caches configuration files (xml, yaml), annotations, twig templates, etc to the ./app/cache directory as php files. In some cases you want to manually invalidate the cache dir by removing it's content ("rm -Rf app/cache/*"). When files are already in the cache because of browsing your app, with opcache.enable_file_override enabled your application will break, because there is always a is_file or is_readable check and then a filemtime check in dev mode, to find out if ProjectContainer class (the dumped DIC service container), has to be refreshed or in case of twig: check, if the cached php file that represents the template has to be flushed/reloaded.

Here is a test-script:

<?php

$src = <<<END
<?php
echo 'Hello World!' . PHP_EOL;
END;

$filename = uniqid('test-tmp_') . '.php';

echo 'writing hello-world example to: ' . $filename . PHP_EOL;

file_put_contents($filename, $src);

echo 'readable check on example file...' . PHP_EOL;

$is_readable = is_readable($filename);

echo 'readable status is: ';
var_dump($is_readable);
echo PHP_EOL;

if($is_readable)
{
    echo 'running example file...' . PHP_EOL;

    require $filename;

    echo 'done.' . PHP_EOL;

    echo 'check example file mtime...' . PHP_EOL;

    $mtime = filemtime($filename);

    echo 'mtime is: ';
    var_dump($mtime);
    echo PHP_EOL;
}

echo 'removing/deleting example file...' . PHP_EOL;

unlink($filename);

sleep(10);

echo 'done.' . PHP_EOL;

$is_readable = is_readable($filename);

echo 'new readable status is: ';
var_dump($is_readable);
echo PHP_EOL;

if($is_readable)
{
    echo 'with "opcache.enable_file_override = On" file seems still be readable after deleting it. BUG!' .PHP_EOL;

    echo 'so example file seems still be readable, require file again...' . PHP_EOL;

    require $filename;

    echo 'done. funny, this is working, but ok it\'s in the cache.' . PHP_EOL;

    echo 'check example file mtime of this unlinked file...' . PHP_EOL;
    echo '(this should break) hehehehe...' . PHP_EOL;

    $mtime = @filemtime($filename);

    echo 'mtime is: ';
    var_dump($mtime);
    echo PHP_EOL;

    if(false === $mtime)
    {
        die('BOOOM! a bug found.' . PHP_EOL);
    }
}

echo 'everything worked fine.' .PHP_EOL;

the "sleep(10)" is only to make sure the cache ttl is outdated when we set the revalidate frequence to 1 second with "opcache.revalidate_freq=1" (but it is not used in case of enable_file_override enabled handling. But the bug also occurs when sleep is removed because the revalidation is not used in case of file_exist, is_file and is_readable checks (what is the bug from my point of view).

expected output and with "opcache.enable_file_override" disabled (default):

writing hello-world example to: test-tmp_?????????.php
readable check on example file...
readable status is: bool(true)

running example file...
Hello World!
done.
check example file mtime...
mtime is: int(1386238553)

removing/deleting example file...
done.
new readable status is: bool(false)

everything worked fine.

broken output with "opcache.enable_file_override" enabled:

writing hello-world example to: test-tmp_52a056a70c67b.php
readable check on example file...
readable status is: bool(true)

running example file...
Hello World!
done.
check example file mtime...
mtime is: int(1386239655)

removing/deleting example file...
done.
new readable status is: bool(true)

with "opcache.enable_file_override = On" file seems still be readable after deleting it. BUG!
so example file seems still be readable, require file again...
Hello World!
done. funny, this is working, but ok it's in the cache.
check example file mtime of this unlinked file...
(this should break) hehehehe...
mtime is: bool(false)

BOOOM! a bug found.

Configuration, working scenario:

opcache.memory_consumption=512
opcache.interned_strings_buffer=8
opcache.max_accelerated_files=20000
opcache.revalidate_freq=1
opcache.fast_shutdown=1
opcache.enable_cli=1
opcache.save_comments=1
opcache.enable_file_override=0

Configuration, broken scenario:

opcache.memory_consumption=512
opcache.interned_strings_buffer=8
opcache.max_accelerated_files=20000
opcache.revalidate_freq=1
opcache.fast_shutdown=1
opcache.enable_cli=1
opcache.save_comments=1
opcache.enable_file_override=1

The problem seems to come from the "static int filename_is_in_cache(char *filename, int filename_len TSRMLS_DC)" function in zend_accelerator_module.c. It only makes a hashmap lookup to find out if the file is in the cache, but it did not revalidate the cache timestamp (and when it is outdated it should return 0 or false).

best regards, René.

rk3rn3r commented 10 years ago

@dstogov could you have a look at my example to reproduce this issue (at least the one we had), or @laurin1 ?

dstogov commented 10 years ago

Rene, I can confirm the issue. The overridden functions (file_exists, etc) don't revalidate the timestamp. We will fix it, but I'm not sure if it'll work for all use cases anyway. Imagine you removed sleep() in your example...

On Tue, Dec 10, 2013 at 5:48 PM, René Kerner notifications@github.comwrote:

@dstogov https://github.com/dstogov could you have a look at my example to reproduce this issue (at least the one we had)

— Reply to this email directly or view it on GitHubhttps://github.com/zendtech/ZendOptimizerPlus/issues/140#issuecomment-30227867 .

dstogov commented 10 years ago

The is_readable() problem must be fixed in GIT, however it might not work exactly the same way as without caching.

zendtech / ZendOptimizerPlus

Revalidate Failure / Files Not Refreshed #140