Edit report at https://bugs.php.net/bug.php?id=72011&edit=1
ID: 72011
User updated by: benjamin dot roth at jaumo dot com
Reported by: benjamin dot roth at jaumo dot com
Summary: DateTime serializes as empty object
Status: Closed
Type: Bug
Package: Date/time related
Operating System: Linux
PHP Version: 7.0.5
Block user comment: N
Private report: N
New Comment:
Workaround:
We try to detect the bug at the end of a script and if it occurs we enqueue the termination of that
FPM worker with a gearman job.
class Service_Model_Fpm extends Jaumo_Model_Abstract {
private static $serializeBug = false;
private static $instance;
public static function getInstance() {
if (self::$instance === null) {
self::$instance = new self();
}
return self::$instance;
}
public function command($workload) {
$cmd = $workload['command'];
$host = $workload['host'];
$pid = $workload['pid'];
if ($cmd == 'stop') {
$this->getLog()->info("Kill FPM worker $pid on $host");
$cmd = "ssh $host sudo kill -TERM $pid";
$cmd;
}
}
public function detectSerializeBug() {
$date = new DateTime();
$serialized = serialize($date);
if (strpos($serialized, '"DateTime":0') !== false) {
self::$serializeBug = true;
$pid = \Sensphere_Process::getProcessId();
$host = \Sensphere_Process::getHostName();
$this->getLog()->info("(PID: $pid) DateTime serialization bug detected");
if (php_sapi_name() !== 'cli') {
$queue = new Jaumo_Queue('fpmManager');
$queue->put([
'command' => 'stop',
'host' => $host,
'pid' => $pid
], "$host::$pid");
}
return true;
}
return false;
}
/**
* @return mixed
*/
public static function hasSerializeBug() {
return self::$serializeBug;
}
}
Previous Comments:
------------------------------------------------------------------------
[2016-06-22 05:58:20] krakjoe@php.net
Automatic comment on behalf of nikic
Revision: http://git.php.net/?p=php-src.git;a=commit;h=248fdfcf7356f2c20ab1e6afd1e9f295d08331c7
Log: Maybe fix bug #72011
------------------------------------------------------------------------
[2016-06-20 21:38:52] ladirecciondeangel at gmail dot com
Is there a way to catch this error?
------------------------------------------------------------------------
[2016-06-17 14:19:20] bill at zeroedin dot com
@nikic and I chatted some on SO and he found a test case that reproduces the bug.
The bug occurs when the max_execution_time is reached *while* GC is running. Because of the way the
timeout is handled, GC is never given an opportunity to clean up and reset the gc_active flag or
finish collecting garbage.
In PHP-FPM, the worker does not exit when the timeout error occurs, but it doesn't clean up the
invalid GC state either. When the bug has occurred in an FPM worker process, the worker continues
serving requests, but any DateTime objects created by the worker appear to have no properties when
accessed via the get_properties handler. Additionally, a bugged FPM worker will segfault if the bug
test code is run twice. I'm not sure why that is happening, but it's not surprising, as
once the bug occurs, the worker is in an invalid and indeterminate state anyway.
The issue occurs on Linux only, as Windows builds do not have ZEND_SIGNALS enabled. It appears both
7 and 5.x are affected.
Because this bug affects the state of the fpm worker itself, and affects subsequent requests,
I'd rate it as fairly high priority. At the very least, the fpm worker should die when this
condition occurs.
I'm not entirely sure, but should the body of gc_collect_cycles be wrapped in a
HANDLE_BLOCK_INTERRUPTIONS ... HANDLE_UNBLOCK_INTERRUPTIONS block?
The following test case works for me on Ubuntu 14.04 with PHP 5.6.22. It only occurs in a fraction
of runs, as the timeout coincidence with the GC run is probabilistic.
If you test via a curl call to this script served via php-fpm, you can see that subsequent calls to
the same test script handled by that process will segfault, but if you call a script containing just
the first 2 lines instead, it will simply output the PID and an empty DateTime.
Result below is as output by php-cli - fpm output differs.
Test script:
---------------
<?php
// Uncomment to see PID - useful for checking fpm behavior
//echo "PID: " . getmypid() . "\n";
print_r(DateTime::createFromFormat('Y-m-d H:i:s', '2016-01-01 00:00:00'));
set_time_limit(1);
ini_set('display_errors', 1);
error_reporting(E_ALL);
function shutdownFunc()
{
print_r(DateTime::createFromFormat('Y-m-d H:i:s', '2016-01-01 00:00:00'));
}
register_shutdown_function('shutdownFunc');
while (true) {
for ($i = 0; $i < 100; $i++) {
$a = new stdClass;
$a->b = $a;
unset($a);
}
gc_collect_cycles();
}
Expected result:
----------------
DateTime Object
(
[date] => 2016-01-01 00:00:00.000000
[timezone_type] => 3
[timezone] => America/New_York
)
PHP Fatal error: Maximum execution time of 1 second exceeded in /var/www/testcase.php on line 23
Fatal error: Maximum execution time of 1 second exceeded in /var/www/testcase.php on line 23
DateTime Object
(
[date] => 2016-01-01 00:00:00.000000
[timezone_type] => 3
[timezone] => America/New_York
)
Actual result:
--------------
DateTime Object
(
[date] => 2016-01-01 00:00:00.000000
[timezone_type] => 3
[timezone] => America/New_York
)
PHP Fatal error: Maximum execution time of 1 second exceeded in /var/www/testcase.php on line 23
Fatal error: Maximum execution time of 1 second exceeded in /var/www/testcase.php on line 23
DateTime Object
(
)
------------------------------------------------------------------------
[2016-06-15 00:53:04] bill at zeroedin dot com
Ok, I have a test case that exhibits the broken datetime behavior on Windows, but I can't seem
to get the conditions right on Linux because the gc seems to behave quite differently, happily
freeing cycles without overrunning memory limits.
I have no php-fpm to test on Windows, so I can't go all the way with the bug, but I think this
does provide a further hint that under certain memory utilization conditions, the gc_active flag is
getting set and not reset in php-fpm.
Maybe on Thursday if anyone has any hints I can tinker with this test case a bit more and see if I
can get it to zombie out php-fpm on linux.
Test script:
---------------
<?php
$memoryLimit = 1024*1024*((int)ini_get("memory_limit")); // assuming your memory limit is
megs...
echo "Memory limit: $memoryLimit\n";
ini_set('display_errors', 1);
error_reporting(E_ALL);
echo sprintf("usage: %s real: %s peak: %s peak_real: %s\n", memory_get_usage(),
memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
$cycles = [];
function shutdownFunc()
{
echo sprintf("usage: %s real: %s peak: %s peak_real: %s\n", memory_get_usage(),
memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
// Serialize goes wrong
echo serialize(new DateTime);
echo "\n";
// So does print_r
print_r(new DateTime);
// And createFromFormat. Just super borked.
print_r(DateTime::createFromFormat('Y-m-d', '2004-01-01'));
}
register_shutdown_function('shutdownFunc');
class F {
public $next;
public function __destruct() {
global $foo;
//$foo[] = 'bar';
}
}
// Do this until allowed memory is full
while(memory_get_usage(true) < $memoryLimit) {
//echo sprintf("cycle: %d usage: %s real: %s peak: %s peak_real: %s\n", count($cycles),
memory_get_usage(), memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
$a = new F();
$cycles[] = $a;
$a->next = $a;
$last = $a;
$i = 0;
// Build a cycle.
while($i++ < 500 && memory_get_usage(true) < $memoryLimit) {
$b = new F();
$last->next = $b;
$b->next = $a;
$last = $b;
}
}
// Orphan all the cycles
echo "Orphaning " . count($cycles) . " cycles.\n";
echo sprintf("usage: %s real: %s peak: %s peak_real: %s\n", memory_get_usage(),
memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
unset($cycles);
echo sprintf("usage: %s real: %s peak: %s peak_real: %s\n", memory_get_usage(),
memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
gc_collect_cycles();
echo sprintf("usage: %s real: %s peak: %s peak_real: %s\n", memory_get_usage(),
memory_get_usage(true), memory_get_peak_usage(), memory_get_peak_usage(true));
Expected result:
----------------
Memory limit: 268435456
usage: 388040 real: 2097152 peak: 400640 peak_real: 2097152
--snip--
O:8:"DateTime":3:{s:4:"date";s:26:"2016-06-14
17:42:49.000000";s:13:"timezone_type";i:3;s:8:"timezone";s:19:"America/Los_Angeles";}
DateTime Object
(
[date] => 2016-06-14 17:42:49.000000
[timezone_type] => 3
[timezone] => America/Los_Angeles
)
DateTime Object
(
[date] => 2004-01-01 17:42:49.000000
[timezone_type] => 3
[timezone] => America/Los_Angeles
)
Actual result:
--------------
Memory limit: 268435456
Orphaning 11505 cycles.
usage: 264856032 real: 268435456 peak: 264856032 peak_real: 268435456
Fatal error: Allowed memory size of 268435456 bytes exhausted (tried to allocate 4096 bytes) in
E:\wwwroot\platform-git\segfault_linux.php on line 55
Call Stack:
0.2040 365312 1. {main}() E:\wwwroot\platform-git\segfault_linux.php:0
usage: 266926344 real: 268435456 peak: 266926920 peak_real: 268435456
O:8:"DateTime":0:{}
DateTime Object
(
)
DateTime Object
(
)
------------------------------------------------------------------------
[2016-06-14 22:44:46] bill at zeroedin dot com
Actually no, that is just straight up crashing, nothing DateTime involved there.
I'll have to try again for a working test case...
<?php
$a = new stdClass();
$a->next = $a;
$last = $a;
$i = 0;
while($i++ < 500000) {
$b = new stdClass();
$last->next = $b;
$b->next = $a;
$last = $b;
}
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
https://bugs.php.net/bug.php?id=72011
--
Edit this bug report at https://bugs.php.net/bug.php?id=72011&edit=1