php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #65915 Inconsistent results with require return value
Submitted: 2013-10-16 13:30 UTC Modified: 2013-11-03 11:50 UTC
From: arjen at react dot com Assigned: dmitry
Status: Closed Package: opcache
PHP Version: 5.5.4 OS: Linux
Private report: No CVE-ID:
 [2013-10-16 13:30 UTC] arjen at react dot com
Description:
------------
opcache seems to 'cache' the return value of a require statement, even if opcache_invalidate or opcache_reset is called. A test script which returns a closure is written to disk, required and result method is called. File is overwritten and called again. Output should differ, but is the same. A helper var written to the same file IS correctly updated.

Result is wrong most of the times.

php -d zend_extension=/usr/lib/php/modules/opcache.so -d opcache.enabled=1 -d opcache.enable_cli=1 -d opcache.optimization_level=0xffffffff public_html/php/opcache.php

opcache.optimization_level=0x00000000 also fails.

Test script:
---------------
<?php

$tmp = tempnam(sys_get_temp_dir(), 'test');

file_put_contents($tmp, '<?php $s = ' . microtime(true) . ';return function(){ return "a";};');

$f = require $tmp;
var_dump($s, $f());

sleep(2);
file_put_contents($tmp, '<?php $s = ' . microtime(true) . ';return function(){ return "ab";};');

opcache_invalidate($tmp, true);
$f = require $tmp;

var_dump($s, $f());
unset($f);
opcache_reset();

$f = require $tmp;
var_dump($s, $f());


Expected result:
----------------
double(1381930079.4517)
string(1) "a"
double(1381930079.452)
string(2) "ab"
double(1381930079.452)
string(2) "ab"


Actual result:
--------------
double(1381930079.4517)
string(1) "a"
double(1381930079.452)
string(1) "a"
double(1381930079.452)
string(1) "a"


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2013-11-03 11:50 UTC] felipe@php.net
-Status: Open +Status: Assigned -Assigned To: +Assigned To: dmitry
 [2013-11-04 14:42 UTC] zoeslam at gmail dot com
This bug is likely related to https://bugs.php.net/bug.php?id=65559
 [2013-11-19 17:00 UTC] Terry at ellisons dot org dot uk
This is quite a subtle problem, that I will document and post a fix back here.
 [2013-11-20 13:52 UTC] Terry at ellisons dot org dot uk
This is not related to #65559.

I've stripted the example down to a minimum for chaising through gdb to localize the error.

<?php
$tmp = '/tmp/testNg3hUy';

file_put_contents($tmp, '<?php $s = 1; return function(){ return "a"; };');
$f = require $tmp;
printf( "%d=%s ", $s, $f());
opcache_invalidate($tmp, true);

file_put_contents($tmp, '<?php $s = 2; return function(){ return "ab"; };');
$f = require $tmp;
printf( "%d=%s\n", $s, $f());
unlink($tmp);

in that it outputs the expects "1=a 2=ab" when OPcache is disabled.  (I've also disabled optimization to keep things simple as this doesn't impact the error.)  If the opcache_invalidate() is commented out then it outputs "1=a 1=a" which is the issue pointed up by #65559, but here is outputs "1=a 2=a", and indeed stepping through this, the two require statements execute the opcodes:

    INCLUDE_OR_EVAL                $n  !0, REQUIRE
    ASSIGN                             !1, $n

as expected with the OPcache persistent_compile_file catching the compile hook and forwarding this on to the language scanner default compile_file routine to do the compile for the two compiles of the /tmp/testNg3hUy routines.

Note that these compiles emit *two* op_arrays: one for the top level /tmp/testNg3hUy:

    ASSIGN                             !0, 1
    ZEND_DECLARE_LAMBDA_FUNCTION       '%00%7Bclosure%7D%2Ftmp%2FtestNg3hUy0xXXXXXXXXXXXX'
    RETURN                             ~1
    RETURN                             1

where 0xXXXXXXXXXXXX is the addr of the closure string in the buffered file. And for the closure

    RETURN                             'X'
    RETURN                             null

where X is either "a" or "ab" depending on which version has been compiled.  This closure is referenced by the closure object in $f and is stored as an entry in the EG(function_table).  Because of the default string memory reuse, the storage is reused for the second compile and therefore the two versions of the closure have the same key in the EG(function_table). Note that GC(function_table) and EG(function_table) point to the same hash table.

The closure entry in the function_table is added in zend_do_begin_function_declaration() at zend_compile.c:1711 using a zend_hash_quick_update(CG(function_table), ...) and the opcodes filled in during pass_two() at zend_opcode.c:537 called from zend_do_end_function_declaration() at zend_compile.c:1800.  In the second compile the hash value, that is the zend_function, is overwritten by the new function value. 

How the executor handles closures is already a bit of a botch.  (See https://bugs.php.net/bug.php?id=64291 where I discuss some of the unintended consequences of the reuse that I discuss scenarios where the above reuse goes wrong).  When OPcache is enabled, OPcache copies internal functionals from the CG(function_table) into ZCG(function_table) during startup, and then does hash table flipping to capture function addition during compilation.  In this test case, the second compile completes opcode[0].op1 zval is "ab" but at some point in this flipping, the new function entry is silently discarded and the previous copy of the closure is used (the one with opcode[0].op1 zval is "a") but with the new calling routine -- hence the "2=a" response. 

I will need to do more tracking / debugging to work out exactly where.  Instrumenting this is a little convolved because of the interaction with the closure destructors.  I also suspect that I might need to fix #64291 to fix this.  What this space.  :-)
 [2013-11-20 15:06 UTC] Terry at ellisons dot org dot uk
[Note that the line no's in the above are off because I am using a slightly stale dev test rig, but of course I will validate against current for the final fix.  Sorry.]

Yup this is a #64291 issue, and how it interplays with OPcache.

*  OPcache builds a persistent script per-compiled unit.  This includes any functions that were compiled during this unit.  Because of the function_table hash flipping, these new compiles get 
backed out of the live EG(function_table).

*  OPcache moves the content of the persistent script to the live tables using zend_accel_load_script() which calls zend_accel_function_hash_copy() to copy across any additional functions using zend_hash_unique_copy() on a per script basis.

*  Now consider the implications of #64291.  When the compiler compiles a closure it uses the 
generated key sprintf("\0{closure}%s%p",name,addr) where the name is the resolved filename of the source where the function was defined and the addr is the absolute address of the function definition within the memory resident copy of the source during the compilation process and overwrites any existing function entry -- even though that function might be related to a still in-scope closure object.  OPcache does not.  It will only add new entries and not overwrite existing ones.  Hence it's behaviour is different.

We could "fix" OPcache by replicating the error in closures, but IMO the correct thing to do here is to fix the underlying error in closures.  Though there are wider issues so this might be worth developing some more easily understandable test cases.  I suggest anyone tracking this also subscribe to #64291.
 [2013-11-21 15:09 UTC] Terry at ellisons dot org dot uk
Fixing #64291 makes this issue go away.  This is a manifestation of #64291 and should be closed as a duplicate of the same.
 [2013-11-25 10:12 UTC] dmitry@php.net
Automatic comment on behalf of dmitry@zend.com
Revision: http://git.php.net/?p=php-src.git;a=commit;h=27dc82d0ec199ee8aab9548f64aab29bdeccedd3
Log: Fixed bug #65915 (Inconsistent results with require return value)
 [2013-11-25 10:12 UTC] dmitry@php.net
-Status: Assigned +Status: Closed
 [2013-11-26 10:00 UTC] ab@php.net
Automatic comment on behalf of dmitry@zend.com
Revision: http://git.php.net/?p=php-src.git;a=commit;h=27dc82d0ec199ee8aab9548f64aab29bdeccedd3
Log: Fixed bug #65915 (Inconsistent results with require return value)
 
PHP Copyright © 2001-2014 The PHP Group
All rights reserved.
Last updated: Sat Apr 19 19:02:15 2014 UTC