PDOException: Numeric value out of range (negative timer value / potential microtime issues)

Yes, I received the exact same error this morning:

PDOException: SQLSTATE[22003]: Numeric value out of range: 1264 Out of range value for column 'timer' at row 1: INSERT INTO {accesslog} (title, path, url, hostname, uid, sid, timer, timestamp) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7); Array ( [:db_insert_placeholder_0] => InTown Guide - Das Städte-Portal [:db_insert_placeholder_1] => node/1 [:db_insert_placeholder_2] => [:db_insert_placeholder_3] => 66.249.67.19 [:db_insert_placeholder_4] => 0 [:db_insert_placeholder_5] => yi1uzwCRVuzZ2pksr1lO7EQfexVucHo72IvV5B-sNHM [:db_insert_placeholder_6] => -694 [:db_insert_placeholder_7] => 1335506409 ) in statistics_exit() (Zeile 93 von /home/www-data/xxxxx.info/modules/statistics/statistics.module).

Luckily it only started to happen 30 minuted before I arrived for work, so I could fix it (by turning off the statistics module). So I am uncertain as to why this error still occurred.

Surely there must be a simple fix that can be coded into the stats module to prevent this (by checking the lenght of the 'timer' value maybe before trying to enter it into the db.)

If you check placeholder 7 in the above error message, which should be the timer, it actually contains the timestamp (1335506409) - where as the 'timer' should actually contain the 'Time in milliseconds that the page took to load.'

Strangely though, the timer field has the exact same settings as the timestamp field in the db - namely 'int(10)'. So I would have thought that is would just enter the value.

Here is the part of the stats module that cause the error - line 93 is the -> execute command.

if (variable_get('statistics_enable_access_log', 0)) {
    drupal_bootstrap(DRUPAL_BOOTSTRAP_SESSION);

    // For anonymous users unicode.inc will not have been loaded.
    include_once DRUPAL_ROOT . '/includes/unicode.inc';
    // Log this page access.
    db_insert('accesslog')
      ->fields(array(
        'title' => truncate_utf8(strip_tags(drupal_get_title()), 255),
        'path' => truncate_utf8($_GET['q'], 255),
        'url' => isset($_SERVER['HTTP_REFERER']) ? $_SERVER['HTTP_REFERER'] : '',
        'hostname' => ip_address(),
        'uid' => $user->uid,
        'sid' => session_id(),
        'timer' => (int) timer_read('page'),
        'timestamp' => REQUEST_TIME,
      ))
      ->execute();
  }

And the timer_read function (includes/bootstrap.inc, line 457) is defined as:

function timer_read($name) {
  global $timers;

  if (isset($timers[$name]['start'])) {
    $stop = microtime(TRUE);
    $diff = round(($stop - $timers[$name]['start']) * 1000, 2);

    if (isset($timers[$name]['time'])) {
      $diff += $timers[$name]['time'];
    }
    return $diff;
  }
  return $timers[$name]['time'];
}

Nice detective work @tecjam. Looking at the pasted results, though, it looks like it's not actually submitting the timestamp as the timer, though--that's the next placeholder, for the timestamp field. What it's submitting (that is out of range) is the negative value -2 in the original post, or -694 in @tecjam's case.

See:

• timer_start()
• timer_read()
• timer_stop()
• _drupal_bootstrap_configuration() (I checked and this is the only function in core that starts the page timer, and nothing stops it.)

So timer_read() would return a negative value if $timers['page']['start'] were greater than the current timestamp, or if $timers['page']['time'] were negative.

The fact that the timer is in a global means absolutely anything could mess with this variable if it wanted. Gross. (I personally would use a plain static in something like a _timer_static_cache().) I did confirm that this global is only used in core in the three timer functions above.

I can't figure out how this would happen unless one of the following were true:

1. Some installed code is tinkering with that global.
2. The server time were somehow mysteriously changing, or some other weird environment problem.
3. PHP autoglobals are on. =/
4. A bug in the behavior of microtime().

Could you check and see if there are any modules installed on your sites that update the $timer global or call any of the functions above?

It might be a bug in microtime. As saying in http://www.php.net/manual/en/function.microtime.php#101628

All these timing scripts rely on microtime which relies on gettimebyday(2)

This can be inaccurate on servers that run ntp to syncronise the servers time.

For timing, you should really use clock_gettime(2) with the CLOCK_MONOTONIC flag set.

This returns REAL WORLD time, not affected by intentional clock drift.

This may seem a bit picky, but I recently saw a server that's clock was an hour out, and they'd set it to 'drift' to the correct time (clock is speeded up until it reaches the correct time)

Those sorts of things can make a real impact.

Any solutions, seeing as php doesn't have a hook into clock_gettime?

More info here:
http://blog.habets.pp.se/2010/09/gettimeofday-should-never-be-used-to-me...

Oh, see this:
http://www.php.net/manual/en/function.microtime.php#108255

So it sounds like we should put in some things to enforce non-negative values, at least, on account of the potential PHP/environment issues.

I'll work on this.

@xjm I'm not sure that's it. I don't think Drupal can be bootstrapped and exit in less than 1 microsecond. Usually it should take a dozens of thousand times more than that.

The point is that there is a documented instance there of chronological microtime()s resulting in negative values on windows. I'm not saying to use the guy's "solution"; I'm just saying that is shows there are PHP issues.

See also:
https://bugs.php.net/bug.php?id=42659

Would be good if people reporting this issue could confirm what web server/OS/PHP version they are running.

I think if we can confirm this as a PHP bug and not caused by something we are doing wrong then we could simply set negative values to 0 with a reference to the php bug report and be done with it.

There are possibly multiple problems:
- microtime() might return incorrect value when called twice in less than 1 microsecond
- microtime() might have problem in scripts running for weeks (Windows only, bug reported in 2007 but has not had many replies)
- microtime() might return incorrect value because server time is update between the two calls because server time is update by ntpd - I think it is the most likely problem.

"Ugly", but simple and useful enough, fix is just set time = 0 if < 0. Complex, but may be better, is to use another function instead of microtime().

I grepped for instances of microtime() in core, and noticed that Symfony has a StopWatch class similar to our timer, and Symfony's Stopwatch and StopwatchEvent use the same patterns we do (without any sanity checking that time is not going backwards).

All instances of microtime in core:

[milankovitch:drupal | Sat 08:39:12] $ grep -r "microtime" *
core/includes/batch.inc:    $current_set['start'] = microtime(TRUE);
core/includes/batch.inc:      $current_set['start'] = microtime(TRUE);
core/includes/batch.inc:      $current_set['elapsed'] = round((microtime(TRUE) - $current_set['start']) * 1000, 2);
core/includes/bootstrap.inc:  $timers[$name]['start'] = microtime(TRUE);
core/includes/bootstrap.inc:    $stop = microtime(TRUE);
core/includes/bootstrap.inc:    $stop = microtime(TRUE);
core/includes/bootstrap.inc:    // the microtime() - is prepended rather than appended. This is to avoid
core/includes/bootstrap.inc:      $random_state = hash('sha256', microtime() . mt_rand() . $random_state);
core/lib/Drupal/Core/Database/Statement.php:      $query_start = microtime(TRUE);
core/lib/Drupal/Core/Database/Statement.php:      $query_end = microtime(TRUE);
core/lib/Drupal/Core/Database/StatementPrefetch.php:      $query_start = microtime(TRUE);
core/lib/Drupal/Core/Database/StatementPrefetch.php:      $query_end = microtime(TRUE);
core/lib/Drupal/Core/Lock/DatabaseLockBackend.php:    $expire = microtime(TRUE) + $timeout;
core/lib/Drupal/Core/Lock/DatabaseLockBackend.php:    $now = microtime(TRUE);
core/modules/color/color.module:  $id = $theme . '-' . substr(hash('sha256', serialize($palette) . microtime()), 0, 8);
core/modules/system/tests/registry.test:    $chrs = hash('sha256', microtime() . mt_rand());
core/modules/system/tests/registry.test:      $chrs = hash('sha256', microtime() . mt_rand());
core/modules/system/tests/registry.test:              'name' => $type . hash('sha256', microtime() . mt_rand()),
core/vendor/Symfony/Component/HttpKernel/Debug/Stopwatch.php:            $session = $this->children[] = new self(microtime(true) * 1000);
core/vendor/Symfony/Component/HttpKernel/Debug/Stopwatch.php:            $this->events[$name] = new StopwatchEvent($this->origin ?: microtime(true) * 1000, $category);
core/vendor/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php:        return $this->formatTime(microtime(true) * 1000 - $this->origin);
core/vendor/Symfony/Component/HttpKernel/Kernel.php:            $this->startTime = microtime(true);
core/vendor/Symfony/Component/HttpKernel/Kernel.php:            $this->startTime = microtime(true);

All use of the timer_ functions:

core/includes/batch.inc:    timer_start('batch_processing');
core/includes/batch.inc:    if ($batch['progressive'] && timer_read('batch_processing') > 1000) {
core/includes/bootstrap.inc:function timer_start($name) {
core/includes/bootstrap.inc:function timer_read($name) {
core/includes/bootstrap.inc:function timer_stop($name) {
core/includes/bootstrap.inc:  timer_start('page');
core/includes/common.inc:  timer_start(__FUNCTION__);
core/includes/common.inc:  $timeout = $options['timeout'] - timer_read(__FUNCTION__) / 1000;
core/includes/common.inc:    $timeout = $options['timeout'] - timer_read(__FUNCTION__) / 1000;
core/includes/common.inc:      $options['timeout'] -= timer_read(__FUNCTION__) / 1000;
core/modules/statistics/statistics.module:        'timer' => (int) timer_read('page'),
core/modules/system/tests/bootstrap.test:      'description' => 'Test that timer_read() works both when a timer is running and when a timer is stopped.',
core/modules/system/tests/bootstrap.test:   * Test timer_read() to ensure it properly accumulates time when the timer
core/modules/system/tests/bootstrap.test:    timer_start('test');
core/modules/system/tests/bootstrap.test:    $this->assertTrue(timer_read('test') >= 1000, t('Timer measured 1 second of sleeping while running.'));
core/modules/system/tests/bootstrap.test:    timer_stop('test');
core/modules/system/tests/bootstrap.test:    $this->assertTrue(timer_read('test') >= 2000, t('Timer measured 2 seconds of sleeping after being stopped.'));
core/modules/system/tests/bootstrap.test:    timer_start('test');
core/modules/system/tests/bootstrap.test:    $this->assertTrue(timer_read('test') >= 3000, t('Timer measured 3 seconds of sleeping after being restarted.'));
core/modules/system/tests/bootstrap.test:    $timer = timer_stop('test');
core/modules/system/tests/bootstrap.test:    $this->assertTrue(timer_read('test') >= 4000, t('Timer measured 4 seconds of sleeping after being stopped for a second time.'));
core/modules/system/tests/common.test:      timer_start(__METHOD__);
core/modules/system/tests/common.test:      $time = timer_read(__METHOD__) / 1000;
core/scripts/run-tests.sh:simpletest_script_reporter_timer_stop();
core/scripts/run-tests.sh:  timer_start('run-tests');
core/scripts/run-tests.sh:function simpletest_script_reporter_timer_stop() {
core/scripts/run-tests.sh:  $end = timer_stop('run-tests');

So the microtime is used for:

• The timer, including the page timer, statistics logging, batch processing, simpletest, and the HTTP timeout.
• Elapsed time within batches (in addition to the timer use).
• Query logging.
• The database locking mechanism.
• The Symfony Stopwatch (not used in core or in any Symfony components we've yet bundled).
• Hashing, which is not relevant here.

Based on the scope of this--it's way more than just a potential problem with funky statistics--I think we probably need more details about the host environments for those receiving this error. So, if you have encountered this error, please reply with:

• Your server OS.
• Your web server (Apache, IIS, etc.).
• Your hosting provider, if applicable.
• Your version of PHP.
• Any relevant server-specific configurations, including whether your server is configured for ntp and whether register_globals is enabled (it really really should not be).

Edit: I also updated the issue summary.

Regarding microtime(), see also:

• #1225404: Modernize lock acquisition to RAII
• #838976: lock_acquire() breaks if new expiration is the same as old one

Updated issue summary.

Updated issue summary.

Updated issue summary.

Updated issue summary.

.

Not sure whats going on here when trying to connect to database in installing process. I have re downloaded drupal-7.15 and removed /usr/local/pgsql/data before reiniting: /usr/local/etc/rc.d/postgresql initdb and builded the database I needed.

Here the output:
SQLSTATE[22003]: Numeric value out of range: 7 ERROR: value "1344573360564" is out of range for type integer LINE 1: ...'placeholder-for-uid-1', 'placeholder-for-uid-1', '134457336... ^

Then hitting refresh produces this:
Table variable already exists.

PS: This problem didn't happen on another machine using the same OS & Version
_______________________________________________________-______________________________________
apache22
string "register_globals" not found in httpd.conf
lang/php5.4
database/php5-pdo_pgsql
lang/php5-extensions (
extension=ctype.so
extension=curl.so
extension=dom.so
extension=exif.so
extension=fileinfo.so
extension=filter.so
extension=pdo.so
extension=gd.so
extension=gettext.so
extension=hash.so
extension=iconv.so
extension=json.so
extension=mbstring.so
extension=mcrypt.so
extension=openssl.so
extension=phar.so
extension=posix.so
extension=session.so
extension=simplexml.so
extension=sockets.so
extension=sqlite3.so
extension=tokenizer.so
extension=xml.so
extension=xmlreader.so
extension=xmlwriter.so
extension=bz2.so
extension=mysql.so
extension=mysqli.so
extension=pdo_sqlite.so
extension=pgsql.so
extension=pspell.so
extension=zip.so
extension=zlib.so
extension=pdo_pgsql.so
)
apache22

FreeBSD localhost.localdomain 9.0-RELEASE FreeBSD 9.0-RELEASE #0: Tue Jan 3 07:46:30 UTC 2012 root@farrell.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC amd64

############
I'm going to rebuild apache22 and related php5 ports with portmaster and try again.

no change:
Upgrade apache-2.2.21 to apache-2.2.22_5
Upgrade perl-5.12.4_3 to perl-5.12.4_4

How I licked this was with

php53-pdo_pgsql

also had to reinstall php5 to php53 and php5-extensions to php53-extensions.
because the default php5 installs php54.

Hope this helps I'm happy as a clam now.

I was running the latest Drupal 8.x from a couple weeks ago and had no problems and now today, after a git pull and a fresh install, I'm hitting this error when uploading images! (So, not statistics module...)

Here is the error I get:

Drupal\Core\Entity\EntityStorageException: SQLSTATE[22003]: Numeric value out of range: 1264 Out of range value for column 'timestamp' at row 1: INSERT INTO {file_managed} (fid, uuid, uid, filename, uri, langcode, filemime, filesize, status, timestamp) VALUES (default, :db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8); Array ( [:db_insert_placeholder_0] => 0ab92e6b-58bc-4040-9f04-4f16e2362f99 [:db_insert_placeholder_1] => 1 [:db_insert_placeholder_2] => me.jpg [:db_insert_placeholder_3] => public://field/image/me_14.jpg [:db_insert_placeholder_4] => und [:db_insert_placeholder_5] => image/jpeg [:db_insert_placeholder_6] => 31927 [:db_insert_placeholder_7] => 0 [:db_insert_placeholder_8] => -1187834336 ) in Drupal\Core\Entity\DatabaseStorageController->save() (line 565 of /var/www/drupal/core/lib/Drupal/Core/Entity/DatabaseStorageController.php).

It's setting 'timestamp' to REQUEST_TIME which is strangely negative: -1187834336

Server OS: Debian 7.0
Web server: Apache 2.2.22
Hosting provider: none, I'm running in a VirtualBox VM on my local machine
PHP version: 5.4.4
NTP: Yes, it's configured to use ntp
register_globals: This was removed entirely in PHP 5.4 (http://php.net/manual/en/security.globals.php)

I hope that's enough info! The truly weird thing is that everything worked fine on this same system 3-ish weeks ago during Sprint Weekend...

Yesterday, I tried disabling NTP with no effect.

Today, I decided I was going to come back to this and try some more things to fix the problem (for example: switch from PHP 5.4 to 5.3 like @paulfrottawa did in #16). But now the problem is mysteriously gone! REQUEST_TIME is set to a positive value and I have no problems uploading images...

If the problem comes back I'll try and do some more experimenting. I suspect that this has to do with PHP 5.4 or some changes made to the PHP environment by Debian 7.0 (which is still unstable).

Updated issue summary.

Closing since the issue could not be reproduced 2 years ago, and also, D8 now requires php 5.4 (which seems to have resolved the issue).

#2855282: PDOException: Numeric value out of range (negative timer value)