From: Aaron Schulz <aschulz@wikimedia.org>
Date: Thu, 12 Jul 2018 15:26:13 +0000 (+0100)
Subject: objectcache: improve logging and error handling in BagOStuff
X-Git-Tag: 1.34.0-rc.0~4670^2
X-Git-Url: http://git.cyclocoop.org/%28?a=commitdiff_plain;h=c7054356289a87379724aceaf0c0dcd75965e059;p=lhc%2Fweb%2Fwiklou.git

objectcache: improve logging and error handling in BagOStuff

Bug: T198239
Bug: T199383
Change-Id: I0b4110396d03b98e83a7b614caf57d7e7c284361
---

diff --git a/includes/libs/objectcache/BagOStuff.php b/includes/libs/objectcache/BagOStuff.php
index 0100fb2c41..be09aadd5b 100644
--- a/includes/libs/objectcache/BagOStuff.php
+++ b/includes/libs/objectcache/BagOStuff.php
@@ -133,7 +133,7 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 
 	/**
 	 * @param LoggerInterface $logger
-	 * @return null
+	 * @return void
 	 */
 	public function setLogger( LoggerInterface $logger ) {
 		$this->logger = $logger;
@@ -308,6 +308,11 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 			$this->reportDupes = $reportDupes;
 
 			if ( $this->getLastError() ) {
+				$this->logger->warning(
+					__METHOD__ . ' failed due to I/O error on get() for {key}.',
+					[ 'key' => $key ]
+				);
+
 				return false; // don't spam retries (retry only on races)
 			}
 
@@ -325,6 +330,11 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 				$success = $this->cas( $casToken, $key, $value, $exptime );
 			}
 			if ( $this->getLastError() ) {
+				$this->logger->warning(
+					__METHOD__ . ' failed due to I/O error for {key}.',
+					[ 'key' => $key ]
+				);
+
 				return false; // IO error; don't spam retries
 			}
 		} while ( !$success && --$attempts );
@@ -352,6 +362,11 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 		if ( $casToken === $curCasToken ) {
 			$success = $this->set( $key, $value, $exptime );
 		} else {
+			$this->logger->info(
+				__METHOD__ . ' failed due to race condition for {key}.',
+				[ 'key' => $key ]
+			);
+
 			$success = false; // mismatched or failed
 		}
 
@@ -382,6 +397,11 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 		$this->reportDupes = $reportDupes;
 
 		if ( $this->getLastError() ) {
+			$this->logger->warning(
+				__METHOD__ . ' failed due to I/O error on get() for {key}.',
+				[ 'key' => $key ]
+			);
+
 			$success = false;
 		} else {
 			// Derive the new value from the old value
@@ -437,13 +457,19 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 			}
 		}
 
+		$fname = __METHOD__;
 		$expiry = min( $expiry ?: INF, self::TTL_DAY );
 		$loop = new WaitConditionLoop(
-			function () use ( $key, $timeout, $expiry ) {
+			function () use ( $key, $timeout, $expiry, $fname ) {
 				$this->clearLastError();
 				if ( $this->add( "{$key}:lock", 1, $expiry ) ) {
 					return true; // locked!
 				} elseif ( $this->getLastError() ) {
+					$this->logger->warning(
+						$fname . ' failed due to I/O error for {key}.',
+						[ 'key' => $key ]
+					);
+
 					return WaitConditionLoop::CONDITION_ABORTED; // network partition?
 				}
 
@@ -452,9 +478,15 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 			$timeout
 		);
 
-		$locked = ( $loop->invoke() === $loop::CONDITION_REACHED );
+		$code = $loop->invoke();
+		$locked = ( $code === $loop::CONDITION_REACHED );
 		if ( $locked ) {
 			$this->locks[$key] = [ 'class' => $rclass, 'depth' => 1 ];
+		} elseif ( $code === $loop::CONDITION_TIMED_OUT ) {
+			$this->logger->warning(
+				"$fname failed due to timeout for {key}.",
+				[ 'key' => $key, 'timeout' => $timeout ]
+			);
 		}
 
 		return $locked;
@@ -470,7 +502,15 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 		if ( isset( $this->locks[$key] ) && --$this->locks[$key]['depth'] <= 0 ) {
 			unset( $this->locks[$key] );
 
-			return $this->delete( "{$key}:lock" );
+			$ok = $this->delete( "{$key}:lock" );
+			if ( !$ok ) {
+				$this->logger->warning(
+					__METHOD__ . ' failed to release lock for {key}.',
+					[ 'key' => $key ]
+				);
+			}
+
+			return $ok;
 		}
 
 		return true;
@@ -505,7 +545,10 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 			$latency = 0.050; // latency skew (err towards keeping lock present)
 			$age = ( $this->getCurrentTime() - $lSince + $latency );
 			if ( ( $age + $latency ) >= $expiry ) {
-				$this->logger->warning( "Lock for $key held too long ($age sec)." );
+				$this->logger->warning(
+					"Lock for {key} held too long ({age} sec).",
+					[ 'key' => $key, 'age' => $age ]
+				);
 				return; // expired; it's not "safe" to delete the key
 			}
 			$this->unlock( $key );
@@ -567,6 +610,7 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 	 * @return bool Success
 	 */
 	public function add( $key, $value, $exptime = 0 ) {
+		// @note: avoid lock() here since that method uses *this* method by default
 		if ( $this->get( $key ) === false ) {
 			return $this->set( $key, $value, $exptime );
 		}
@@ -580,7 +624,7 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 	 * @return int|bool New value or false on failure
 	 */
 	public function incr( $key, $value = 1 ) {
-		if ( !$this->lock( $key ) ) {
+		if ( !$this->lock( $key, 1 ) ) {
 			return false;
 		}
 		$n = $this->get( $key );
@@ -618,14 +662,15 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface {
 	 * @since 1.24
 	 */
 	public function incrWithInit( $key, $ttl, $value = 1, $init = 1 ) {
+		$this->clearLastError();
 		$newValue = $this->incr( $key, $value );
-		if ( $newValue === false ) {
+		if ( $newValue === false && !$this->getLastError() ) {
 			// No key set; initialize
 			$newValue = $this->add( $key, (int)$init, $ttl ) ? $init : false;
-		}
-		if ( $newValue === false ) {
-			// Raced out initializing; increment
-			$newValue = $this->incr( $key, $value );
+			if ( $newValue === false && !$this->getLastError() ) {
+				// Raced out initializing; increment
+				$newValue = $this->incr( $key, $value );
+			}
 		}
 
 		return $newValue;