Lock system is broken in many regards (was: needs a precision of at least 14 for timestamp comparison)

We'll tackle this one at our code sprint next week.

Patch for this

What would we be testing? ini_set()? Not sure this does need tests.

I don't think it was mentione: 14 is the default precision for PHP. http://www.php.net/manual/en/ini.core.php#ini.precision

Can we get the script in the OP as an automated test so we don't break this again?

5: drupal_core-lock_system_precision-2077827-5.patch queued for re-testing.

I am happy to do a reroll for patch in #5.

Rerolled patch in #5.

As required by @webchick, I've rewritten the patch and included a test for the precision. Let's see what the test bot comes back with!

+++ b/core/tests/Drupal/Tests/Core/Lock/LockBackendAbstractTest.php
@@ -35,10 +35,19 @@ public static function getInfo() {
+    // Locks require a precision of at least 14.

I think we should expand on this a little. It's not clear that we're setting it to 12 so we can later test to ensure that the constructor updated the prevision to at least 14.

Fair enough @benjy.

@Fabianx said that the default precision is 14, If that is the case, why did it break?

Instinctively, this sounds like trying to patch the symptoms.

@Fabianx: do you have more detail on why precision matters? From a quick read of the code we don't seem to be doing any floating point manipulation, other then the expiration logic that we could get rid of, and should not affect the normal code path.

DatabaseLockBackend::aquire calls microtime(true) which returns a float. That is then rendered into a string for the SQL, and it makes sense that's where precision kicks in. Testing locally, with a precision of 12, the timestamp gets rendered with only two decimal digits, which is sure to mess something up. Basically, it only prints decimal digits up until the precision.

One way to avoid the problem would be to use microtime() and do some string manipulation to get the proper string, but then we're basically passing the buck to the DB. It's currently a big float which should be sufficient, but figuring out the exact limits we need and using a decimal would be a tad safer.

But as this setting influences *all* float rendering, I think it should be promoted to be set in bootstrapping so it's consistent all across.

I'm elevating this to critical as it *will* break Drupal on hosts configured with non-standard precision.

+++ b/core/tests/Drupal/Tests/Core/Lock/LockBackendAbstractTest.php
@@ -35,10 +35,19 @@ public static function getInfo() {
+    // Locks require a precision of at least 14.
+    ini_set('precision', 12);

Ha, this comment is a bit confusing, let's explain that we test the automatic changing to precision 14 later, maybe with an @see ?

Let's fix that comment, otherwise looks RTBC.

will update the comment shortly...

Re-roll only. Leaving comment for @gobinathm.

Awaiting change to comment by @gobinathm

I thought the comment in __construct() was going to be updated as well to explain why we need a precision of 14.

Happy to do it @Fabianx given that the poor comment is mine :-)

@jorgegc, I'd all but exported the patch before I saw your messages. Feel free to change the comment.

While looking into the issue to attempt to write an appropriate comment I did stumble across this post: http://php.net/manual/en/function.microtime.php#113078

It is suggested in that post that a precision of 16 could ensure that the full value that microtime returns could be preserved on string conversions. But precision 14 has been found to be enough for this?

I do also wonder if setting this precision value should be more global. microtime() is used extensively in core.

I think we should consider just setting this globally to the higher precision in this issue. The lock system could then throw an exception if it's somehow not set correctly.

DrupalKernel::bootEnvironment()

I will work on supplying a patch for review later today.

I hope this is what you were going for. Please provide feedback.

1. +++ b/core/lib/Drupal/Core/DrupalKernel.php
   @@ -746,6 +746,13 @@ public static function bootEnvironment() {
   +    // Ensure a precision value of at least 14.
   +    // It is vital that an appropriate precision level is set so that reliable
   +    // comparisons of timestamps can be made.
   +    if (ini_get('precision') < 14) {
   +      ini_set('precision', 14);
   +    }
   
   +++ b/core/lib/Drupal/Core/Lock/LockBackendAbstract.php
   @@ -29,6 +29,19 @@
   +    // It is vital that an appropriate precision level is set or the process
   +    // that holds the lock and tries to re-acquire it will fail.
   +
   +    // Ensure a precision value of at least 14.
   +    if (ini_get('precision') < 14) {
   +      throw new \Exception('Precision level less than 14 detected.');
   +    }
   

   Is it really right to throw an exception given that DrupalKernel contains the ini_set()?

2. +++ b/core/tests/Drupal/Tests/Core/Lock/LockBackendAbstractTest.php
   @@ -27,6 +27,13 @@ protected function setUp() {
   +  public function testMinimumPrecision() {
   +    $this->assertTrue(ini_get('precision') >= 14);
   +  }
   

   This fail might be wrong. I think we should skip the unit test in this case. DrupalKernal has not run btw so the only reason this passes is that precision is 14 or more on testbots.

That leaves us with just setting the precision.

It makes sense to remove this test, particularly since DrupalKernel is not run :) The only thing a test or check would protect from is if someone later decided that setting the precision was unnecessary then the problems described in this issue would re-occur. But git blame on this code should lead someone back to this issue before thinking about changing it.

Here is a patch for review.

Woops! I triggered the testbot with my interdiff because I mistakenly added the .patch extension. Here it is again as .txt :) Sorry testbot!

Ignore the failed interdiff-2077827-44-49.patch (#holdsheadinshame). Patch in #49 is good for review.

@alexpott I think it's worth throwing the exception to ensure an early failure if DrupalKernel hasn't run.

ini_set('precision', 8);
$x = \Drupal::lock()->acquire('a', 15);
$y = \Drupal::lock()->acquire('a', 15);
$z = \Drupal::lock()->acquire('a', 15);
var_dump($x);
var_dump($y);
var_dump($z);

This returns:

bool(true)
bool(true)
bool(true)

Is this a memcache only issue?

Discussed with @nlisgo on IRC I think the problem is in DatabaseLockBackend::lockMayBeAvailable()

    $expire = (float) $lock['expire'];
    $now = microtime(TRUE);
    if ($now > $expire) {

Given:

"So never trust floating number results to the last digit, and do not compare floating point numbers directly for equality. If higher precision is necessary, the arbitrary precision math functions and gmp functions are available."

See http://php.net/manual/en/language.types.float.php - thanks @catch

    $expire = (float) $lock['expire'];
    $now = microtime(TRUE);
    // Test if $now is greater that $expire.
    if (bccomp($now, $expire, 14) == 1) {

Happy to take on the refactoring of this. Will post up for review.

The solution proposed in #56 does not address the issue described in #21. If the precision value is not high enough then the expire value that is written to the database will not be fit for a comparison later on in the lockMayBeAvailable method.

What the suggested solution in #56 does draw attention to, however, is that microtime comparisons are only at risk because of the precision setting if the value or values being compared are converted to and from a string.

I think we still need to address the precision setting. But it will strengthen this issue if we can provide more reliable steps to reproduce the issue.

@Fabianx can you respond to #55?

In an effort to continue the momentum of this issue. I believe that we should consider the last patch for review again. When reviewing please take on board the comments since the last patch was submitted.

The patch for review is in #49.

This fits the definition of a major bug per: https://www.drupal.org/core/issue-priority#major-bugs. There are also workarounds possible on those hosts affected; for example, in Apache configuration, .htaccess, settings.php, etc. Therefore, it need not block release. However, it is major because it will render the system unusable in these cases and will likely be difficult to isolate.

This could also be addressed with a hook_requirements() when a higher precision is needed.

The issue summary is quite out of date with more recent comments.

Re-uploading patch for the bots.

I just encountered this problem. Since this is one of the most frustrating bugs I've had to deal with, I wanted to share some details in case a concrete example is useful. I'm working in D7, but I was able to duplicate the problem in a clean install of D8.1.x

I started the day trying to test a new page I was developing on my test site. But I couldn't get drupal to recognize the new page. I tried to rebuild menus every way I know; disabled and re-enabled the module; etc. But menu-rebuilding just refused to happen, and there were no warnings or messages in any of the logs. At this point I assumed something was broken with the menu system.

But over the next few hours I kept diving deeper and deeper into core code, and eventually tracked the problem to lock_may_be_available(). Apparently a menu rebuild had failed about a month ago, and had left the following entry in the semaphore table:

+--------------+-----------------------------------+-----------------+
| name         | value                             | expire          |
+--------------+-----------------------------------+-----------------+
| menu_rebuild | 190985459756c6119fbb0ec6.22649124 | 1455821246.6831 |
+--------------+-----------------------------------+-----------------+

Attempts to delete the entry were failing because the deletion conditions were rounding expire to two digits (e.g.,
WHERE expire <= 1455821246.68). Therefore all menu_rebuild requests were being silently ignored.

Once I finally found this issue, a D7 version of patch #49 worked (as did the patch provided by the OP). I also duplicated the issue in D8, by inserting the same row into the D8 semaphore table, except with name changed to menuLinksRebuild. The same problem occurred in D8 -- all attempts to rebuild menus were ignored -- and patch #49 fixed the problem. Also note that memcache is not enabled on my test site, but problems still occurred.

One point of my example is to echo #60: lock expiration rounding errors are indeed "difficult to isolate." They make seemingly unrelated drupal components fail and only very determined developers have any chance of identifying the underlying problem. So this may be the cause of many reported errors on this site -- including many errors tagged as unreproducible, given that the behavior depends upon an obscure PHP setting.

I would vote in favor of implementing patch #49, and sooner rather than later, to help resolve all the possibly undiagnosed but related problems. The tests in #44 seem unnecessary, given that testbots will never trigger the error.

However patch #49 is a band-aid rather than a real fix. Perhaps a separate followup issue should be created to explore other, more stable options, that are not dependent upon floating-point rounding. My guess is that development of any such alternative will take some time, which is why the current patch should be implemented first.

Tested and verified that #66 works

@webchick and @Fabianx the default PHP setting is 14. What should we be testing?

http://php.net/manual/en/ini.core.php#ini.precision

Just wondering: any reason why we cannot use an explicit high-accuracy serialization starting from microtime(FALSE) ?

When using that format, the microsecond part appears to have 1E-8 resolution, but 1E-6 accuracy, while microtime(TRUE) only has 1E-4 accuracy.

So we could just replace the double in the semaphore schema by a CHAR(16) (10 digits for seconds, 6 for microseconds) and store the actual microsecond value as a fixed length string. This should both remove the need for the dependency on the PHP precision check and eliminate any risk of rounding error mentioned against @alexpott's code in #56. Think of something like that:

list($micro, $sec) = explode(' ', microtime(FALSE));
$expire = gmp_init($sec . substr($micro, 2, 6));
// The add timeout, etc. And write to DB using gmp_strval().

That timing logic could even be moved to LockBackendAbstract() to allow it to be shared between lock backends.

Re-uploading patch for re-testing in 8.6.x-dev.
I used the code from #49. It is the same as #66 so interdiff is not needed.

Since this needs tests and an IS update, setting to NW.

Here's a 7.x patch for anyone who might find it handy.

No guarantee of usefulness or problem-solving-ness... Just a conversion to 7.x.

Also, I noticed in the docs that we also have this: https://www.php.net/manual/en/ini.core.php#ini.serialize-precision

That is, serialize_precision is a thing, and maybe we need to care about it.