Edit report at https://bugs.php.net/bug.php?id=72011&edit=1
ID: 72011
Comment by: bill at zeroedin 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:
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.
Previous Comments:
------------------------------------------------------------------------
[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 ******
------------------------------------------------------------------------
[2016-04-12 13:52:32] benjamin dot roth at jaumo dot com
Description:
------------
I recognize occasionally that DateTime serializes as an empty object. Deserializing then throws a
fatal error with "Invalid serialization data for DateTime object"
Also print_r outputs the DateTime Object like
DateTime Object
(
)
This is the output of a real example when serializing an arbitrary structure with a DateTime object:
Serialize:
a:4:{s:6:"userId";i:27008573;s:9:"longitude";d:1.5192019999999999;s:8:"latitude";d:48.432855000000004;s:4:"date";O:8:"DateTime":0:{}}
print_r:
Array
(
[userId] => 27008573
[longitude] => 1,519202
[latitude] => 48,432855
[date] => DateTime Object
(
)
)
Unfortunately I was not able to reproduce it reliably, I was only able to detect it, when it occured
in may be one of 100.000 requests. In our production environment this occurs frequently but I was
not able to track it down.
I noticed this behaviour only in FPM workers not in CLI. WHEN this bug occurs, the affected FPM
worker behaves wrong until it is respawned, also in following requests.
I know this information is very rough. I am happy to provide any more information that can help :)
Test script:
---------------
<?php
// This should only demontrate what happens, if bug occurs
// Bug is VERY flaky
$d = new DateTime();
print_r($d);
Expected result:
----------------
DateTime Object
(
[date] => 2016-04-12 13:35:15.000000
[timezone_type] => 3
[timezone] => UTC
)
Actual result:
--------------
DateTime Object
(
)
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=72011&edit=1