Bug #65915 [Com]: Inconsistent results with require return value

From: Date: Thu, 21 Nov 2013 15:09:52 +0000
Subject: Bug #65915 [Com]: Inconsistent results with require return value
References: 1  Groups: php.bugs 
Request: Send a blank email to php-bugs+get-182880@lists.php.net to get a copy of this message
Edit report at https://bugs.php.net/bug.php?id=65915&edit=1

 ID:                 65915
 Comment by:         Terry at ellisons dot org dot uk
 Reported by:        arjen at react dot com
 Summary:            Inconsistent results with require return value
 Status:             Assigned
 Type:               Bug
 Package:            opcache
 Operating System:   Linux
 PHP Version:        5.5.4
 Assigned To:        dmitry
 Block user comment: N
 Private report:     N

 New Comment:

Fixing #64291 makes this issue go away.  This is a manifestation of #64291 and should be closed as a
duplicate of the same.


Previous Comments:
------------------------------------------------------------------------
[2013-11-20 15:06:14] 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-20 13:52:14] 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-19 17:00:44] 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-04 14:42:29] zoeslam at gmail dot com

This bug is likely related to https://bugs.php.net/bug.php?id=65559

------------------------------------------------------------------------
[2013-10-16 13:30:37] 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"



------------------------------------------------------------------------



-- 
Edit this bug report at https://bugs.php.net/bug.php?id=65915&edit=1


Thread (8 messages)

« previous php.bugs (#182880) next »