We've seen this on a number of PHP major versions including 5.4, 5.6 & 7
This seems to occur randomly but in the past we've seen a definite correlation between high server load and frequency of occurrence. At those times it was often a process unrelated to PHP or Apache that was straining the server so the increase in errors was not simply due to an increased number of requests.

I've added some additional logging to our serialisation code which I've included below. I've also included a log snippet from the most recent occurrence.

This particular incident happened on a Linux box running PHP 7.0.0.

One thing that's strange in the log extract is when we serialise the entire object (which contains an array that contains DateTimes) the DateTime object gets serialised as 'O:8:"DateTime":0:{}' however when we attempt to serialise that DateTime object directly it just returns a reference number (e.g. 'r:530'). Not sure if this is a side effect of the way I'm printing them.

    static private function print_dates($data, $path = ''){
        foreach ($data as $k => $v){
            if (is_array($v)) self::print_dates($v, "$path.$k");
            if (!($v instanceof DateTime)) continue;
            log_message("*** ser $path.$k = " . @serialize($v));
            log_message("*** print  $path.$k = " . print_r($v, true));
            log_message("*** format  $path.$k = " . $v->format('r'));
            log_message("*** time  $path.$k = " . $v->getTimestamp());
            log_message("******");
        }
    }
    
    
    public function serialize() {
        $data = get_object_vars($this);
        unset($data['_relationships']);
 
        $ser = @serialize($data);
        if (strpos($ser, 'O:8:"DateTime":0:{}') !== false) {
            $class_name = get_class();
            log_message("*** Bad serialization: $class_name : $ser");
            self::print_dates($data, $class_name);
        }
        return $ser;
    }

2016-04-27 09:47:21	*** Bad serialization: ModelObject : a:3:{s:4:"_vnc";b:0;s:16:"_fetched_columns";a:6:{s:2:"ID";s:3:"650";s:10:"CREATED_AT";O:8:"DateTime":0:{}s:13:"CREATED_BY_ID";s:3:"179";s:11:"MODIFIED_AT";O:8:"DateTime":0:{}s:14:"MODIFIED_BY_ID";s:3:"179";s:4:"NAME";s:9:"X.X. Xxxx";}s:16:"_changed_columns";a:0:{}}
2016-04-27 09:47:21	*** ser ModelObject._fetched_columns.CREATED_AT = r:530;
2016-04-27 09:47:21	*** print  ModelObject._fetched_columns.CREATED_AT = DateTime Object\n(\n)\n
2016-04-27 09:47:21	*** format  ModelObject._fetched_columns.CREATED_AT = Thu, 25 Jul 2013 23:12:08 +0100
2016-04-27 09:47:21	*** time  ModelObject._fetched_columns.CREATED_AT = 1374790328
2016-04-27 09:47:21	******
2016-04-27 09:47:21	*** ser ModelObject._fetched_columns.MODIFIED_AT = r:532;
2016-04-27 09:47:21	*** print  ModelObject._fetched_columns.MODIFIED_AT = DateTime Object\n(\n)\n
2016-04-27 09:47:21	*** format  ModelObject._fetched_columns.MODIFIED_AT = Thu, 25 Jul 2013 23:12:08 +0100
2016-04-27 09:47:21	*** time  ModelObject._fetched_columns.MODIFIED_AT = 1374790328
2016-04-27 09:47:21	******

@atkinson:
As you mention high load: I also recognized this misbehaviour only when the system was under abnormal high load.

I have also seen this problem. I am running php-fpm 5.6.22-1+donate.sury.org~trusty+1 via nginx inside a docker container. Under periods of unusually high load, it seems one or more php-fpm processes will begin exhibiting this broken serialization behavior. From the time the bug is first triggered until php-fpm is restarted, some requests will show the bad behavior, and some will not. 

I have put some extra logic in our app caching logic to prevent tainting the cache pool with bad serialized DateTime data, but this seems like a rather critical bug. Since PHP is not outright crashing, data processed by bugged php-fpm workers could conceivably bring down or corrupt large applications. In our experience, it brought down our prod site until the worker pools could be recycled.

I have noticed that this issue has only occurred for us between 3-5pm EST. I don't know if that matters at all, but this is a heisenbug, so it might be relevant.

Is this with or without opcache?

This is with opcache in my case.

In my case (PHP7) it is with opcache:

zend_extension=opcache.so

opcache.optimization_level=0xffffffff

----

PHP 7.0.5-2+deb.sury.org~trusty+1 (cli) ( NTS )
Copyright (c) 1997-2016 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologies
    with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2016, by Zend Technologies

Going out on a limb here ... this might be happening because serialize() is called while gc_active=1. The DateTime get_properties handler contains a check that will return an empty properties HT in that case. What's not clear here is how serialize() could be called while gc_active=1. My guess would be that somehow a fatal error is triggered during GC, causing a bailout without resetting the flag. This would be consistent with following requests experiencing the same issue, as the flag would stay enabled.

Do any of see fatal errors (e.g. due to timeout, memory limit, OOM) in your logs around the time this issue starts to occur?

Even if this should be totally unrelated, we should still drop those gc_active checks ... they aren't necessary as long as everything defines a proper get_gc handler.

Actually yes, this bug has consistently appeared after a maximum execution time or allowed memory exhaustion bailout. After increasing the timeout in our dev environment, the bug has not reappeared, but I haven't tested the allowed memory ceiling yet.

@bill: Thanks! I've now applied https://github.com/php/php-src/commit/248fdfcf7356f2c20ab1e6afd1e9f295d08331c7 to 5.6 and upwards, which will hopefully fix the problem.

We should probably still either catch bailouts during GC and reset state, or at least reset the GC state for new requests.

@nikic thanks! I'll be running with execution time and memory limits relaxed for now, but once the patch hits a release I'll bump things back down and retest.

I still can't reliably reproduce the issue. Is it possible that the garbage collector is allocating just enough memory at some stage to trigger the memory exhaustion error? I managed to get a segfault out of it on both linux and windows, fpm and cli, 5.6.22 and 7.0.4, but not the broken DateTime behavior.

<?php
// Segfault this shizz
$start = microtime(true);
set_time_limit(3);
ini_set('display_errors', 1);
error_reporting(E_ALL);

function shutdownFunc()
{
    if (!is_null($e = error_get_last()))
    {
        echo serialize(new DateTime);
    }
}

register_shutdown_function('shutdownFunc');
$a = new stdClass();
$a->next = $a;
$last = $a;
$mem_start = memory_get_usage();
echo "Building cycle...\n";
while((microtime(true) - $start < 2.9) && (memory_get_usage() - $mem_start) < 1024*1024*128) {
    $b = new stdClass();
    $last->next = $b;
    $b->next = $a;
    $last = $b;
}
$i=0;
echo "Waiting...\n";
while ((microtime(true)-$start < 2.9)) {
    $i++;
}
unset ($last);
unset ($a);
echo "Explode!\n";
gc_collect_cycles();

Basically that code just makes a lot of work for the garbage collector to do, then waits until the execution time is almost up, and triggers the garbage collector so that the execution time expires while the garbage collector is running. Or at least I *think* that's what it's doing. Who knows.

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;
}

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
(
)

@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
(
)

Is there a way to catch this error?

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;
	}

}

All,

We run a high volume application and we saw this in production for some of our cache objects, and I just wanted to say that we cherry-picked commit 248fdfcf7356f2c20ab1e6afd1e9f295d08331c7 into a 5.5 build, and after some tests, deployed it to our production environment. We have not seen the issue reoccur and it is pretty safe to say that removing gc solves this issue.

Thank you for researching + fixing this bug, it had been plaguing us for at least 2 months.

Secondly, if DateTime serializes as an empty object, even with proper type safety, I don't agree that it should throw a fatal exception, but rather a warning because it doesn't necessarily represent an interpretation failure.