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: Open
Type: Bug
Package: Date/time related
Operating System: Linux
PHP Version: 7.0.5
Block user comment: N
Private report: N
New Comment:
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
Previous Comments:
------------------------------------------------------------------------
[2016-06-14 19:10:26] bill at zeroedin dot com
This is with opcache in my case.
------------------------------------------------------------------------
[2016-06-14 19:00:21] derick@php.net
Is this with or without opcache?
------------------------------------------------------------------------
[2016-06-14 17:11:39] bill at zeroedin dot com
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.
------------------------------------------------------------------------
[2016-04-27 14:46:40] benjamin dot roth at jaumo dot com
@atkinson:
As you mention high load: I also recognized this misbehaviour only when the system was under
abnormal high load.
------------------------------------------------------------------------
[2016-04-27 09:27:40] atkinson dot d at mac dot com
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 ******
------------------------------------------------------------------------
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