rdbms: set cpPosIndex to null in ChronologyProtector::shutdown on failure

This already happens on lock acquisition failure but not on write failure.
If the write failed, then there is not point timing out on the next request
after waiting "waitForPosStoreTimeout" seconds.

Also raise the initPositions() logging for missing positions to WARNING
and improve the wait loop log entries in that method.

Change-Id: Id738eb6f85c91dd05fadd2e6c3f19ae3204e2575

diff --git a/includes/libs/rdbms/ChronologyProtector.php b/includes/libs/rdbms/ChronologyProtector.php
index e115286..90e697e 100644 (file)
--- a/includes/libs/rdbms/ChronologyProtector.php
+++ b/includes/libs/rdbms/ChronologyProtector.php
@@ -212,10 +212,10 @@ class ChronologyProtector implements LoggerAwareInterface {
                        $store->unlock( $this->key );
                } else {
                        $ok = false;
-                       $cpIndex = null; // nothing saved
                }
 
                if ( !$ok ) {
+                       $cpIndex = null; // nothing saved
                        $bouncedPositions = $this->shutdownPositions;
                        // Raced out too many times or stash is down
                        $this->logger->warning( __METHOD__ . ": failed to save master pos for " .
@@ -269,14 +269,16 @@ class ChronologyProtector implements LoggerAwareInterface {
                        // already be expired and thus treated as non-existing, maintaining correctness.
                        if ( $this->waitForPosIndex > 0 ) {
                                $data = null;
+                               $indexReached = null; // highest index reached in the position store
                                $loop = new WaitConditionLoop(
-                                       function () use ( &$data ) {
+                                       function () use ( &$data, &$indexReached ) {
                                                $data = $this->store->get( $this->key );
                                                if ( !is_array( $data ) ) {
                                                        return WaitConditionLoop::CONDITION_CONTINUE; // not found yet
                                                } elseif ( !isset( $data['writeIndex'] ) ) {
                                                        return WaitConditionLoop::CONDITION_REACHED; // b/c
                                                }
+                                               $indexReached = max( $data['writeIndex'], $indexReached );
 
                                                return ( $data['writeIndex'] >= $this->waitForPosIndex )
                                                        ? WaitConditionLoop::CONDITION_REACHED
@@ -288,11 +290,22 @@ class ChronologyProtector implements LoggerAwareInterface {
                                $waitedMs = $loop->getLastWaitTime() * 1e3;
 
                                if ( $result == $loop::CONDITION_REACHED ) {
-                                       $msg = "expected and found pos index {$this->waitForPosIndex} ({$waitedMs}ms)";
-                                       $this->logger->debug( $msg );
+                                       $this->logger->debug(
+                                               __METHOD__ . ": expected and found position index.",
+                                               [
+                                                       'cpPosIndex' => $this->waitForPosIndex,
+                                                       'waitTimeMs' => $waitedMs
+                                               ]
+                                       );
                                } else {
-                                       $msg = "expected but missed pos index {$this->waitForPosIndex} ({$waitedMs}ms)";
-                                       $this->logger->info( $msg );
+                                       $this->logger->warning(
+                                               __METHOD__ . ": expected but failed to find position index.",
+                                               [
+                                                       'cpPosIndex' => $this->waitForPosIndex,
+                                                       'indexReached' => $indexReached,
+                                                       'waitTimeMs' => $waitedMs
+                                               ]
+                                       );
                                }
                        } else {
                                $data = $this->store->get( $this->key );