Update session log messages

* Use PSR-3 templates and context where applicable
* Add log coverage for exceptional events

Bug: T125452
Change-Id: I8f96fa1c5766c739a21219abcae2dbb76de53e2a

5 files changed, 239 insertions, 70 deletions

diff --git a/includes/session/BotPasswordSessionProvider.php b/includes/session/BotPasswordSessionProvider.php
index d9c60c706fc3..81c7ebfb8184 100644
--- a/includes/session/BotPasswordSessionProvider.php
+++ b/includes/session/BotPasswordSessionProvider.php
@@ -118,26 +118,44 @@ class BotPasswordSessionProvider extends ImmutableSessionProviderWithCookie {
 			array_keys( $metadata )
 		);
 		if ( $missingKeys ) {
-			$this->logger->info( "Session $info: Missing metadata: " . join( ', ', $missingKeys ) );
+			$this->logger->info( 'Session "{session}": Missing metadata: {missing}', array(
+				'session' => $info,
+				'missing' => join( ', ', $missingKeys ),
+			) );
 			return false;
 		}
 
 		$bp = BotPassword::newFromCentralId( $metadata['centralId'], $metadata['appId'] );
 		if ( !$bp ) {
 			$this->logger->info(
-				"Session $info: No BotPassword for {$metadata['centralId']} {$metadata['appId']}"
-			);
+				'Session "{session}": No BotPassword for {centralId} {appId}',
+				array(
+					'session' => $info,
+					'centralId' => $metadata['centralId'],
+					'appId' => $metadata['appId'],
+			) );
 			return false;
 		}
 
 		if ( !hash_equals( $metadata['token'], $bp->getToken() ) ) {
-			$this->logger->info( "Session $info: BotPassword token check failed" );
+			$this->logger->info( 'Session "{session}": BotPassword token check failed', array(
+				'session' => $info,
+				'centralId' => $metadata['centralId'],
+				'appId' => $metadata['appId'],
+			) );
 			return false;
 		}
 
 		$status = $bp->getRestrictions()->check( $request );
 		if ( !$status->isOk() ) {
-			$this->logger->info( "Session $info: Restrictions check failed", $status->getValue() );
+			$this->logger->info(
+				'Session "{session}": Restrictions check failed',
+				array(
+					'session' => $info,
+					'restrictions' => $status->getValue(),
+					'centralId' => $metadata['centralId'],
+					'appId' => $metadata['appId'],
+			) );
 			return false;
 		}
 
diff --git a/includes/session/CookieSessionProvider.php b/includes/session/CookieSessionProvider.php
index f989cbc7f263..3177dc236377 100644
--- a/includes/session/CookieSessionProvider.php
+++ b/includes/session/CookieSessionProvider.php
@@ -123,11 +123,28 @@ class CookieSessionProvider extends SessionProvider {
 
 			// Sanity check
 			if ( $userName !== null && $userInfo->getName() !== $userName ) {
+				$this->logger->warning(
+					'Session "{session}" requested with mismatched UserID and UserName cookies.',
+					array(
+						'session' => $info['id'],
+						'mismatch' => array(
+							'userid' => $userId,
+							'cookie_username' => $userName,
+							'username' => $userInfo->getName(),
+						),
+				) );
 				return null;
 			}
 
 			if ( $token !== null ) {
 				if ( !hash_equals( $userInfo->getToken(), $token ) ) {
+					$this->logger->warning(
+						'Session "{session}" requested with invalid Token cookie.',
+						array(
+							'session' => $info['id'],
+							'userid' => $userId,
+							'username' => $userInfo->getName(),
+					 ) );
 					return null;
 				}
 				$info['userInfo'] = $userInfo->verified();
@@ -140,6 +157,15 @@ class CookieSessionProvider extends SessionProvider {
 			}
 		} elseif ( isset( $info['id'] ) ) {
 			// No UserID cookie, so insist that the session is anonymous.
+			// Note: this event occurs for several normal activities:
+			// * anon visits Special:UserLogin
+			// * anon browsing after seeing Special:UserLogin
+			// * anon browsing after edit or preview
+			$this->logger->debug(
+				'Session "{session}" requested without UserID cookie',
+				array(
+					'session' => $info['id'],
+			) );
 			$info['userInfo'] = UserInfo::newAnonymous();
 		} else {
 			// No session ID and no user is the same as an empty session, so
diff --git a/includes/session/PHPSessionHandler.php b/includes/session/PHPSessionHandler.php
index 4dea2743374e..795e2532546a 100644
--- a/includes/session/PHPSessionHandler.php
+++ b/includes/session/PHPSessionHandler.php
@@ -247,8 +247,10 @@ class PHPSessionHandler {
 			// This can happen under normal circumstances, if the session exists but is
 			// invalid. Let's emit a log warning instead of a PHP warning.
 			$this->logger->warning(
-				__METHOD__ . ": Session \"$id\" cannot be loaded, skipping write."
-			);
+				__METHOD__ . ': Session "{session}" cannot be loaded, skipping write.',
+				array(
+					'session' => $id,
+			) );
 			return true;
 		}
 
diff --git a/includes/session/SessionBackend.php b/includes/session/SessionBackend.php
index 2bff1738027b..a79c5cb089fa 100644
--- a/includes/session/SessionBackend.php
+++ b/includes/session/SessionBackend.php
@@ -138,7 +138,11 @@ final class SessionBackend {
 			$this->data = array();
 			$this->dataDirty = true;
 			$this->metaDirty = true;
-			$this->logger->debug( "SessionBackend $this->id is unsaved, marking dirty in constructor" );
+			$this->logger->debug(
+				'SessionBackend "{session}" is unsaved, marking dirty in constructor',
+				array(
+					'session' => $this->id,
+			) );
 		} else {
 			$this->data = $blob['data'];
 			if ( isset( $blob['metadata']['loggedOut'] ) ) {
@@ -149,8 +153,10 @@ final class SessionBackend {
 			} else {
 				$this->metaDirty = true;
 				$this->logger->debug(
-					"SessionBackend $this->id metadata dirty due to missing expiration timestamp"
-				);
+					'SessionBackend "{session}" metadata dirty due to missing expiration timestamp',
+				array(
+					'session' => $this->id,
+				) );
 			}
 		}
 		$this->dataHash = md5( serialize( $this->data ) );
@@ -218,8 +224,11 @@ final class SessionBackend {
 			$this->provider->sessionIdWasReset( $this, $oldId );
 			$this->metaDirty = true;
 			$this->logger->debug(
-				"SessionBackend $this->id metadata dirty due to ID reset (formerly $oldId)"
-			);
+				'SessionBackend "{session}" metadata dirty due to ID reset (formerly "{oldId}")',
+				array(
+					'session' => $this->id,
+					'oldId' => $oldId,
+			) );
 
 			if ( $restart ) {
 				session_id( (string)$this->id );
@@ -263,7 +272,11 @@ final class SessionBackend {
 			$this->persist = true;
 			$this->forcePersist = true;
 			$this->metaDirty = true;
-			$this->logger->debug( "SessionBackend $this->id force-persist due to persist()" );
+			$this->logger->debug(
+				'SessionBackend "{session}" force-persist due to persist()',
+				array(
+					'session' => $this->id,
+			) );
 			$this->autosave();
 		} else {
 			$this->renew();
@@ -288,7 +301,11 @@ final class SessionBackend {
 		if ( $this->remember !== (bool)$remember ) {
 			$this->remember = (bool)$remember;
 			$this->metaDirty = true;
-			$this->logger->debug( "SessionBackend $this->id metadata dirty due to remember-user change" );
+			$this->logger->debug(
+				'SessionBackend "{session}" metadata dirty due to remember-user change',
+				array(
+					'session' => $this->id,
+			) );
 			$this->autosave();
 		}
 	}
@@ -345,7 +362,11 @@ final class SessionBackend {
 
 		$this->user = $user;
 		$this->metaDirty = true;
-		$this->logger->debug( "SessionBackend $this->id metadata dirty due to user change" );
+		$this->logger->debug(
+			'SessionBackend "{session}" metadata dirty due to user change',
+			array(
+				'session' => $this->id,
+		) );
 		$this->autosave();
 	}
 
@@ -377,7 +398,11 @@ final class SessionBackend {
 		if ( $this->forceHTTPS !== (bool)$force ) {
 			$this->forceHTTPS = (bool)$force;
 			$this->metaDirty = true;
-			$this->logger->debug( "SessionBackend $this->id metadata dirty due to force-HTTPS change" );
+			$this->logger->debug(
+				'SessionBackend "{session}" metadata dirty due to force-HTTPS change',
+				array(
+					'session' => $this->id,
+			) );
 			$this->autosave();
 		}
 	}
@@ -400,8 +425,10 @@ final class SessionBackend {
 			$this->loggedOut = $ts;
 			$this->metaDirty = true;
 			$this->logger->debug(
-				"SessionBackend $this->id metadata dirty due to logged-out-timestamp change"
-			);
+				'SessionBackend "{session}" metadata dirty due to logged-out-timestamp change',
+				array(
+					'session' => $this->id,
+			) );
 			$this->autosave();
 		}
 	}
@@ -428,8 +455,10 @@ final class SessionBackend {
 			$this->providerMetadata = $metadata;
 			$this->metaDirty = true;
 			$this->logger->debug(
-				"SessionBackend $this->id metadata dirty due to provider metadata change"
-			);
+				'SessionBackend "{session}" metadata dirty due to provider metadata change',
+				array(
+					'session' => $this->id,
+			) );
 			$this->autosave();
 		}
 	}
@@ -461,8 +490,11 @@ final class SessionBackend {
 				$data[$key] = $value;
 				$this->dataDirty = true;
 				$this->logger->debug(
-					"SessionBackend $this->id data dirty due to addData(): " . wfGetAllCallers( 5 )
-				);
+					'SessionBackend "{session}" data dirty due to addData(): {callers}',
+					array(
+						'session' => $this->id,
+						'callers' => wfGetAllCallers( 5 ),
+				) );
 			}
 		}
 	}
@@ -474,8 +506,11 @@ final class SessionBackend {
 	public function dirty() {
 		$this->dataDirty = true;
 		$this->logger->debug(
-			"SessionBackend $this->id data dirty due to dirty(): " . wfGetAllCallers( 5 )
-		);
+			'SessionBackend "{session}" data dirty due to dirty(): {callers}',
+			array(
+				'session' => $this->id,
+				'callers' => wfGetAllCallers( 5 ),
+		) );
 	}
 
 	/**
@@ -488,13 +523,19 @@ final class SessionBackend {
 		if ( time() + $this->lifetime / 2 > $this->expires ) {
 			$this->metaDirty = true;
 			$this->logger->debug(
-				"SessionBackend $this->id metadata dirty for renew(): " . wfGetAllCallers( 5 )
-			);
+				'SessionBackend "{callers}" metadata dirty for renew(): {callers}',
+				array(
+					'session' => $this->id,
+					'callers' => wfGetAllCallers( 5 ),
+			) );
 			if ( $this->persist ) {
 				$this->forcePersist = true;
 				$this->logger->debug(
-					"SessionBackend $this->id force-persist for renew(): " . wfGetAllCallers( 5 )
-				);
+					'SessionBackend "{session}" force-persist for renew(): {callers}',
+					array(
+						'session' => $this->id,
+						'callers' => wfGetAllCallers( 5 ),
+				) );
 			}
 		}
 		$this->autosave();
@@ -535,9 +576,12 @@ final class SessionBackend {
 	public function save( $closing = false ) {
 		if ( $this->provider->getManager()->isUserSessionPrevented( $this->user->getName() ) ) {
 			$this->logger->debug(
-				"SessionBackend $this->id not saving, " .
-					"user {$this->user} was passed to SessionManager::preventSessionsForUser"
-			);
+				'SessionBackend "{session}" not saving, user {user} was ' .
+				'passed to SessionManager::preventSessionsForUser',
+				array(
+					'session' => $this->id,
+					'user' => $this->user,
+			) );
 			return;
 		}
 
@@ -546,8 +590,11 @@ final class SessionBackend {
 		$anon = $this->user->isAnon();
 		if ( !$anon && !$this->user->getToken( false ) ) {
 			$this->logger->debug(
-				"SessionBackend $this->id creating token for user {$this->user} on save"
-			);
+				'SessionBackend "{session}" creating token for user {user} on save',
+				array(
+					'session' => $this->id,
+					'user' => $this->user,
+			) );
 			$this->user->setToken();
 			if ( !wfReadOnly() ) {
 				$this->user->saveSettings();
@@ -559,8 +606,13 @@ final class SessionBackend {
 		if ( !$this->metaDirty && !$this->dataDirty &&
 			$this->dataHash !== md5( serialize( $this->data ) )
 		) {
-			$this->logger->debug( "SessionBackend $this->id data dirty due to hash mismatch, " .
-				"$this->dataHash !== " . md5( serialize( $this->data ) ) );
+			$this->logger->debug(
+				'SessionBackend "{session}" data dirty due to hash mismatch, {expected} !== {got}',
+				array(
+					'session' => $this->id,
+					'expected' => $this->dataHash,
+					'got' => md5( serialize( $this->data ) ),
+			) );
 			$this->dataDirty = true;
 		}
 
@@ -568,11 +620,15 @@ final class SessionBackend {
 			return;
 		}
 
-		$this->logger->debug( "SessionBackend $this->id save: " .
-			'dataDirty=' . (int)$this->dataDirty . ' ' .
-			'metaDirty=' . (int)$this->metaDirty . ' ' .
-			'forcePersist=' . (int)$this->forcePersist
-		);
+		$this->logger->debug(
+			'SessionBackend "{session}" save: dataDirty={dataDirty} ' .
+			'metaDirty={metaDirty} forcePersist={forcePersist}',
+			array(
+				'session' => $this->id,
+				'dataDirty' => (int)$this->dataDirty,
+				'metaDirty' => (int)$this->metaDirty,
+				'forcePersist' => (int)$this->forcePersist,
+		) );
 
 		// Persist to the provider, if flagged
 		if ( $this->persist && ( $this->metaDirty || $this->forcePersist ) ) {
@@ -644,7 +700,11 @@ final class SessionBackend {
 			if ( $this->usePhpSessionHandling && session_id() === '' && PHPSessionHandler::isEnabled() &&
 				SessionManager::getGlobalSession()->getId() === (string)$this->id
 			) {
-				$this->logger->debug( "SessionBackend $this->id: Taking over PHP session" );
+				$this->logger->debug(
+					'SessionBackend "{session}" Taking over PHP session',
+					array(
+						'session' => $this->id,
+				) );
 				session_id( (string)$this->id );
 				\MediaWiki\quietCall( 'session_start' );
 			}
diff --git a/includes/session/SessionManager.php b/includes/session/SessionManager.php
index 57d56646b435..5e2ef0114161 100644
--- a/includes/session/SessionManager.php
+++ b/includes/session/SessionManager.php
@@ -216,8 +216,11 @@ final class SessionManager implements SessionManagerInterface {
 			try {
 				$session = $this->getEmptySessionInternal( $request, $id );
 			} catch ( \Exception $ex ) {
-				$this->logger->error( __METHOD__ . ': failed to create empty session: ' .
-					$ex->getMessage() );
+				$this->logger->error( 'Failed to create empty session: {exception}',
+					array(
+						'method' => __METHOD__,
+						'exception' => $ex,
+				) );
 				$session = null;
 			}
 		}
@@ -462,14 +465,21 @@ final class SessionManager implements SessionManagerInterface {
 
 		// Checks passed, create the user...
 		$from = isset( $_SERVER['REQUEST_URI'] ) ? $_SERVER['REQUEST_URI'] : 'CLI';
-		$logger->info( __METHOD__ . ": creating new user ($userName) - from: $from" );
+		$logger->info( __METHOD__ . ': creating new user ({username}) - from: {url}',
+			array(
+				'username' => $userName,
+				'url' => $from,
+		) );
 
 		try {
 			// Insert the user into the local DB master
 			$status = $user->addToDatabase();
 			if ( !$status->isOK() ) {
 				// @codeCoverageIgnoreStart
-				$logger->error( __METHOD__ . ': failed with message ' . $status->getWikiText() );
+				$logger->error( __METHOD__ . ': failed with message ' . $status->getWikiText(),
+					array(
+						'username' => $userName,
+				) );
 				$user->setId( 0 );
 				$user->loadFromId();
 				return false;
@@ -477,7 +487,10 @@ final class SessionManager implements SessionManagerInterface {
 			}
 		} catch ( \Exception $ex ) {
 			// @codeCoverageIgnoreStart
-			$logger->error( __METHOD__ . ': failed with exception ' . $ex->getMessage() );
+			$logger->error( __METHOD__ . ': failed with exception {exception}', array(
+				'exception' => $ex,
+				'username' => $userName,
+			) );
 			// Do not keep throwing errors for a while
 			$cache->set( $backoffKey, 1, 600 );
 			// Bubble up error; which should normally trigger DB rollbacks
@@ -669,7 +682,9 @@ final class SessionManager implements SessionManagerInterface {
 		if ( $blob !== false ) {
 			// Sanity check: blob must be an array, if it's saved at all
 			if ( !is_array( $blob ) ) {
-				$this->logger->warning( "Session $info: Bad data" );
+				$this->logger->warning( 'Session "{session}": Bad data', array(
+					'session' => $info,
+				) );
 				$this->store->delete( $key );
 				return false;
 			}
@@ -678,7 +693,9 @@ final class SessionManager implements SessionManagerInterface {
 			if ( !isset( $blob['data'] ) || !is_array( $blob['data'] ) ||
 				!isset( $blob['metadata'] ) || !is_array( $blob['metadata'] )
 			) {
-				$this->logger->warning( "Session $info: Bad data structure" );
+				$this->logger->warning( 'Session "{session}": Bad data structure', array(
+					'session' => $info,
+				) );
 				$this->store->delete( $key );
 				return false;
 			}
@@ -693,7 +710,9 @@ final class SessionManager implements SessionManagerInterface {
 				!array_key_exists( 'userToken', $metadata ) ||
 				!array_key_exists( 'provider', $metadata )
 			) {
-				$this->logger->warning( "Session $info: Bad metadata" );
+				$this->logger->warning( 'Session "{session}": Bad metadata', array(
+					'session' => $info,
+				) );
 				$this->store->delete( $key );
 				return false;
 			}
@@ -703,13 +722,21 @@ final class SessionManager implements SessionManagerInterface {
 			if ( $provider === null ) {
 				$newParams['provider'] = $provider = $this->getProvider( $metadata['provider'] );
 				if ( !$provider ) {
-					$this->logger->warning( "Session $info: Unknown provider, " . $metadata['provider'] );
+					$this->logger->warning(
+						'Session "{session}": Unknown provider ' . $metadata['provider'],
+						array(
+							'session' => $info,
+						)
+					);
 					$this->store->delete( $key );
 					return false;
 				}
 			} elseif ( $metadata['provider'] !== (string)$provider ) {
-				$this->logger->warning( "Session $info: Wrong provider, " .
-					$metadata['provider'] . ' !== ' . $provider );
+				$this->logger->warning( 'Session "{session}": Wrong provider ' .
+					$metadata['provider'] . ' !== ' . $provider,
+					array(
+						'session' => $info,
+				) );
 				return false;
 			}
 
@@ -727,7 +754,12 @@ final class SessionManager implements SessionManagerInterface {
 							$newParams['metadata'] = $newProviderMetadata;
 						}
 					} catch ( \UnexpectedValueException $ex ) {
-						$this->logger->warning( "Session $info: Metadata merge failed: " . $ex->getMessage() );
+						$this->logger->warning(
+							'Session "{session}": Metadata merge failed: {exception}',
+							array(
+								'session' => $info,
+								'exception' => $ex,
+						) );
 						return false;
 					}
 				}
@@ -746,7 +778,10 @@ final class SessionManager implements SessionManagerInterface {
 						$userInfo = UserInfo::newAnonymous();
 					}
 				} catch ( \InvalidArgumentException $ex ) {
-					$this->logger->error( "Session $info: " . $ex->getMessage() );
+					$this->logger->error( 'Session "{session}": {exception}', array(
+						'session' => $info,
+						'exception' => $ex,
+					) );
 					return false;
 				}
 				$newParams['userInfo'] = $userInfo;
@@ -755,8 +790,13 @@ final class SessionManager implements SessionManagerInterface {
 				// is no saved ID and the names match.
 				if ( $metadata['userId'] ) {
 					if ( $metadata['userId'] !== $userInfo->getId() ) {
-						$this->logger->warning( "Session $info: User ID mismatch, " .
-							$metadata['userId'] . ' !== ' . $userInfo->getId() );
+						$this->logger->warning(
+							'Session "{session}": User ID mismatch, {uid_a} !== {uid_b}',
+							array(
+								'session' => $info,
+								'uid_a' => $metadata['userId'],
+								'uid_b' => $userInfo->getId(),
+						) );
 						return false;
 					}
 
@@ -764,24 +804,35 @@ final class SessionManager implements SessionManagerInterface {
 					if ( $metadata['userName'] !== null &&
 						$userInfo->getName() !== $metadata['userName']
 					) {
-						$this->logger->warning( "Session $info: User ID matched but name didn't (rename?), " .
-							$metadata['userName'] . ' !== ' . $userInfo->getName() );
+						$this->logger->warning(
+							'Session "{session}": User ID matched but name didn\'t (rename?), {uname_a} !== {uname_b}',
+							array(
+								'session' => $info,
+								'uname_a' => $metadata['userName'],
+								'uname_b' => $userInfo->getName(),
+						) );
 						return false;
 					}
 
 				} elseif ( $metadata['userName'] !== null ) { // Shouldn't happen, but just in case
 					if ( $metadata['userName'] !== $userInfo->getName() ) {
-						$this->logger->warning( "Session $info: User name mismatch, " .
-							$metadata['userName'] . ' !== ' . $userInfo->getName() );
+						$this->logger->warning(
+							'Session "{session}": User name mismatch, {uname_a} !== {uname_b}',
+							array(
+								'session' => $info,
+								'uname_a' => $metadata['userName'],
+								'uname_b' => $userInfo->getName(),
+						) );
 						return false;
 					}
 				} elseif ( !$userInfo->isAnon() ) {
 					// Metadata specifies an anonymous user, but the passed-in
 					// user isn't anonymous.
 					$this->logger->warning(
-						"Session $info: Metadata has an anonymous user, " .
-							'but a non-anon user was provided'
-					);
+						'Session "{session}": Metadata has an anonymous user, but a non-anon user was provided',
+						array(
+							'session' => $info,
+					) );
 					return false;
 				}
 			}
@@ -790,7 +841,9 @@ final class SessionManager implements SessionManagerInterface {
 			if ( $metadata['userToken'] !== null &&
 				$userInfo->getToken() !== $metadata['userToken']
 			) {
-				$this->logger->warning( "Session $info: User token mismatch" );
+				$this->logger->warning( 'Session "{session}": User token mismatch', array(
+					'session' => $info,
+				) );
 				return false;
 			}
 			if ( !$userInfo->isVerified() ) {
@@ -813,7 +866,11 @@ final class SessionManager implements SessionManagerInterface {
 		} else {
 			// No metadata, so we can't load the provider if one wasn't given.
 			if ( $info->getProvider() === null ) {
-				$this->logger->warning( "Session $info: Null provider and no metadata" );
+				$this->logger->warning(
+					'Session "{session}": Null provider and no metadata',
+					array(
+						'session' => $info,
+				) );
 				return false;
 			}
 
@@ -823,14 +880,18 @@ final class SessionManager implements SessionManagerInterface {
 					$newParams['userInfo'] = UserInfo::newAnonymous();
 				} else {
 					$this->logger->info(
-						"Session $info: No user provided and provider cannot set user"
-					);
+						'Session "{session}": No user provided and provider cannot set user',
+						array(
+							'session' => $info,
+					) );
 					return false;
 				}
 			} elseif ( !$info->getUserInfo()->isVerified() ) {
 				$this->logger->warning(
-					"Session $info: Unverified user provided and no metadata to auth it"
-				);
+					'Session "{session}": Unverified user provided and no metadata to auth it',
+					array(
+						'session' => $info,
+				) );
 				return false;
 			}
 
@@ -870,7 +931,9 @@ final class SessionManager implements SessionManagerInterface {
 			'SessionCheckInfo',
 			array( &$reason, $info, $request, $metadata, $data )
 		) ) {
-			$this->logger->warning( "Session $info: $reason" );
+			$this->logger->warning( 'Session "{session}": ' . $reason, array(
+				'session' => $info,
+			) );
 			return false;
 		}