From f60fd42b33ed226f999dd6b6cc1cc499a1f6b151 Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Tue, 2 Feb 2016 09:37:27 -0700 Subject: [PATCH] Update session log messages * Use PSR-3 templates and context where applicable * Add log coverage for exceptional events Bug: T125452 Change-Id: I8f96fa1c5766c739a21219abcae2dbb76de53e2a --- .../session/BotPasswordSessionProvider.php | 28 +++- includes/session/CookieSessionProvider.php | 26 ++++ includes/session/PHPSessionHandler.php | 6 +- includes/session/SessionBackend.php | 128 +++++++++++++----- includes/session/SessionManager.php | 121 +++++++++++++---- .../BotPasswordSessionProviderTest.php | 14 +- .../session/CookieSessionProviderTest.php | 41 +++++- .../session/PHPSessionHandlerTest.php | 3 +- .../includes/session/SessionManagerTest.php | 75 +++++----- 9 files changed, 329 insertions(+), 113 deletions(-) diff --git a/includes/session/BotPasswordSessionProvider.php b/includes/session/BotPasswordSessionProvider.php index d9c60c706f..81c7ebfb81 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 f989cbc7f2..3177dc2363 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 4dea274337..795e253254 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 2bff173802..a79c5cb089 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 57d56646b4..5e2ef01141 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; } diff --git a/tests/phpunit/includes/session/BotPasswordSessionProviderTest.php b/tests/phpunit/includes/session/BotPasswordSessionProviderTest.php index 52872a4f14..e1ba0ba7f6 100644 --- a/tests/phpunit/includes/session/BotPasswordSessionProviderTest.php +++ b/tests/phpunit/includes/session/BotPasswordSessionProviderTest.php @@ -207,11 +207,7 @@ class BotPasswordSessionProviderTest extends MediaWikiTestCase { } public function testCheckSessionInfo() { - $logger = new \TestLogger( true, function ( $m ) { - return preg_replace( - '/^Session \[\d+\][a-zA-Z0-9_\\\\]+<(?:null|anon|[+-]:\d+:\w+)>\w+: /', 'Session X: ', $m - ); - } ); + $logger = new \TestLogger( true ); $provider = $this->getProvider(); $provider->setLogger( $logger ); @@ -242,7 +238,7 @@ class BotPasswordSessionProviderTest extends MediaWikiTestCase { $this->assertFalse( $provider->refreshSessionInfo( $info, $request, $metadata ) ); $this->assertSame( array( - array( LogLevel::INFO, "Session X: Missing metadata: $key" ) + array( LogLevel::INFO, 'Session "{session}": Missing metadata: {missing}' ) ), $logger->getBuffer() ); $logger->clearBuffer(); } @@ -253,7 +249,7 @@ class BotPasswordSessionProviderTest extends MediaWikiTestCase { $metadata = $info->getProviderMetadata(); $this->assertFalse( $provider->refreshSessionInfo( $info, $request, $metadata ) ); $this->assertSame( array( - array( LogLevel::INFO, "Session X: No BotPassword for {$bp->getUserCentralId()} Foobar" ), + array( LogLevel::INFO, 'Session "{session}": No BotPassword for {centralId} {appId}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -263,7 +259,7 @@ class BotPasswordSessionProviderTest extends MediaWikiTestCase { $metadata = $info->getProviderMetadata(); $this->assertFalse( $provider->refreshSessionInfo( $info, $request, $metadata ) ); $this->assertSame( array( - array( LogLevel::INFO, 'Session X: BotPassword token check failed' ), + array( LogLevel::INFO, 'Session "{session}": BotPassword token check failed' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -275,7 +271,7 @@ class BotPasswordSessionProviderTest extends MediaWikiTestCase { $metadata = $info->getProviderMetadata(); $this->assertFalse( $provider->refreshSessionInfo( $info, $request2, $metadata ) ); $this->assertSame( array( - array( LogLevel::INFO, 'Session X: Restrictions check failed' ), + array( LogLevel::INFO, 'Session "{session}": Restrictions check failed' ), ), $logger->getBuffer() ); $logger->clearBuffer(); diff --git a/tests/phpunit/includes/session/CookieSessionProviderTest.php b/tests/phpunit/includes/session/CookieSessionProviderTest.php index 9ba67df244..f5c8b05b78 100644 --- a/tests/phpunit/includes/session/CookieSessionProviderTest.php +++ b/tests/phpunit/includes/session/CookieSessionProviderTest.php @@ -4,6 +4,7 @@ namespace MediaWiki\Session; use MediaWikiTestCase; use User; +use Psr\Log\LogLevel; /** * @group Session @@ -159,7 +160,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { 'cookieOptions' => array( 'prefix' => 'x' ), ); $provider = new CookieSessionProvider( $params ); - $provider->setLogger( new \TestLogger() ); + $logger = new \TestLogger( true ); + $provider->setLogger( $logger ); $provider->setConfig( $this->getConfig() ); $provider->setManager( new SessionManager() ); @@ -174,6 +176,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $request = new \FauxRequest(); $info = $provider->provideSessionInfo( $request ); $this->assertNull( $info ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // Session key only $request = new \FauxRequest(); @@ -188,6 +192,13 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( 0, $info->getUserInfo()->getId() ); $this->assertNull( $info->getUserInfo()->getName() ); $this->assertFalse( $info->forceHTTPS() ); + $this->assertSame( array( + array( + LogLevel::DEBUG, + 'Session "{session}" requested without UserID cookie', + ), + ), $logger->getBuffer() ); + $logger->clearBuffer(); // User, no session key $request = new \FauxRequest(); @@ -203,6 +214,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( $id, $info->getUserInfo()->getId() ); $this->assertSame( $name, $info->getUserInfo()->getName() ); $this->assertFalse( $info->forceHTTPS() ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // User and session key $request = new \FauxRequest(); @@ -219,6 +232,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( $id, $info->getUserInfo()->getId() ); $this->assertSame( $name, $info->getUserInfo()->getName() ); $this->assertFalse( $info->forceHTTPS() ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // User with bad token $request = new \FauxRequest(); @@ -229,6 +244,13 @@ class CookieSessionProviderTest extends MediaWikiTestCase { ), '' ); $info = $provider->provideSessionInfo( $request ); $this->assertNull( $info ); + $this->assertSame( array( + array( + LogLevel::WARNING, + 'Session "{session}" requested with invalid Token cookie.' + ), + ), $logger->getBuffer() ); + $logger->clearBuffer(); // User id with no token $request = new \FauxRequest(); @@ -245,6 +267,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( $id, $info->getUserInfo()->getId() ); $this->assertSame( $name, $info->getUserInfo()->getName() ); $this->assertFalse( $info->forceHTTPS() ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); $request = new \FauxRequest(); $request->setCookies( array( @@ -252,6 +276,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { ), '' ); $info = $provider->provideSessionInfo( $request ); $this->assertNull( $info ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // User and session key, with forceHTTPS flag $request = new \FauxRequest(); @@ -269,6 +295,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( $id, $info->getUserInfo()->getId() ); $this->assertSame( $name, $info->getUserInfo()->getName() ); $this->assertTrue( $info->forceHTTPS() ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // Invalid user id $request = new \FauxRequest(); @@ -278,6 +306,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { ), '' ); $info = $provider->provideSessionInfo( $request ); $this->assertNull( $info ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // User id with matching name $request = new \FauxRequest(); @@ -295,6 +325,8 @@ class CookieSessionProviderTest extends MediaWikiTestCase { $this->assertSame( $id, $info->getUserInfo()->getId() ); $this->assertSame( $name, $info->getUserInfo()->getName() ); $this->assertFalse( $info->forceHTTPS() ); + $this->assertSame( array(), $logger->getBuffer() ); + $logger->clearBuffer(); // User id with wrong name $request = new \FauxRequest(); @@ -305,6 +337,13 @@ class CookieSessionProviderTest extends MediaWikiTestCase { ), '' ); $info = $provider->provideSessionInfo( $request ); $this->assertNull( $info ); + $this->assertSame( array( + array( + LogLevel::WARNING, + 'Session "{session}" requested with mismatched UserID and UserName cookies.', + ), + ), $logger->getBuffer() ); + $logger->clearBuffer(); } public function testGetVaryCookies() { diff --git a/tests/phpunit/includes/session/PHPSessionHandlerTest.php b/tests/phpunit/includes/session/PHPSessionHandlerTest.php index 3044aa7a61..e071132cd2 100644 --- a/tests/phpunit/includes/session/PHPSessionHandlerTest.php +++ b/tests/phpunit/includes/session/PHPSessionHandlerTest.php @@ -114,7 +114,8 @@ class PHPSessionHandlerTest extends MediaWikiTestCase { $store = new TestBagOStuff(); $logger = new \TestLogger( true, function ( $m ) { - return preg_match( '/^SessionBackend a{32} /', $m ) ? null : $m; + // Discard all log events starting with expected prefix + return preg_match( '/^SessionBackend "\{session\}" /', $m ) ? null : $m; } ); $manager = new SessionManager( array( 'store' => $store, diff --git a/tests/phpunit/includes/session/SessionManagerTest.php b/tests/phpunit/includes/session/SessionManagerTest.php index d8d5b4b5fb..e60cefeef4 100644 --- a/tests/phpunit/includes/session/SessionManagerTest.php +++ b/tests/phpunit/includes/session/SessionManagerTest.php @@ -2,8 +2,9 @@ namespace MediaWiki\Session; -use Psr\Log\LogLevel; +use AuthPlugin; use MediaWikiTestCase; +use Psr\Log\LogLevel; use User; /** @@ -764,6 +765,9 @@ class SessionManagerTest extends MediaWikiTestCase { \ObjectCache::$instances[__METHOD__] = new TestBagOStuff(); $this->setMwGlobals( array( 'wgMainCacheType' => __METHOD__ ) ); + $this->setMWGlobals( array( + 'wgAuth' => new AuthPlugin, + ) ); $this->stashMwGlobals( array( 'wgGroupPermissions' ) ); $wgGroupPermissions['*']['createaccount'] = true; @@ -779,7 +783,6 @@ class SessionManagerTest extends MediaWikiTestCase { return null; } $m = str_replace( 'MediaWiki\Session\SessionManager::autoCreateUser: ', '', $m ); - $m = preg_replace( '/ - from: .*$/', ' - from: XXX', $m ); return $m; } ); $manager->setLogger( $logger ); @@ -805,7 +808,7 @@ class SessionManagerTest extends MediaWikiTestCase { $user->getId(), User::idFromName( 'UTSessionAutoCreate1', User::READ_LATEST ) ); $this->assertSame( array( - array( LogLevel::INFO, 'creating new user (UTSessionAutoCreate1) - from: XXX' ), + array( LogLevel::INFO, 'creating new user ({username}) - from: {url}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -819,7 +822,10 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertEquals( 0, User::idFromName( 'UTDoesNotExist', User::READ_LATEST ) ); $session->clear(); $this->assertSame( array( - array( LogLevel::DEBUG, 'user is blocked from this wiki, blacklisting' ), + array( + LogLevel::DEBUG, + 'user is blocked from this wiki, blacklisting', + ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -835,7 +841,7 @@ class SessionManagerTest extends MediaWikiTestCase { $user->getId(), User::idFromName( 'UTSessionAutoCreate2', User::READ_LATEST ) ); $this->assertSame( array( - array( LogLevel::INFO, 'creating new user (UTSessionAutoCreate2) - from: XXX' ), + array( LogLevel::INFO, 'creating new user ({username}) - from: {url}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -873,7 +879,7 @@ class SessionManagerTest extends MediaWikiTestCase { $user->getId(), User::idFromName( 'UTSessionAutoCreate3', User::READ_LATEST ) ); $this->assertSame( array( - array( LogLevel::INFO, 'creating new user (UTSessionAutoCreate3) - from: XXX' ), + array( LogLevel::INFO, 'creating new user ({username}) - from: {url}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1039,7 +1045,7 @@ class SessionManagerTest extends MediaWikiTestCase { 'LocalUserCreated' => array(), ) ); $this->assertSame( array( - array( LogLevel::INFO, 'creating new user (UTSessionAutoCreate4) - from: XXX' ), + array( LogLevel::INFO, 'creating new user ({username}) - from: {url}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); } @@ -1074,11 +1080,7 @@ class SessionManagerTest extends MediaWikiTestCase { public function testLoadSessionInfoFromStore() { $manager = $this->getManager(); - $logger = new \TestLogger( true, function ( $m ) { - return preg_replace( - '/^Session \[\d+\]\w+<(?:null|anon|[+-]:\d+:\w+)>\w+: /', 'Session X: ', $m - ); - } ); + $logger = new \TestLogger( true ); $manager->setLogger( $logger ); $request = new \FauxRequest(); @@ -1192,7 +1194,10 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertSame( $unverifiedUserInfo, $info->getUserInfo() ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Unverified user provided and no metadata to auth it' ) + array( + LogLevel::WARNING, + 'Session "{session}": Unverified user provided and no metadata to auth it', + ) ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1203,7 +1208,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Null provider and no metadata' ), + array( LogLevel::WARNING, 'Session "{session}": Null provider and no metadata' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1226,7 +1231,7 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertFalse( $info->isIdSafe(), 'sanity check' ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::INFO, 'Session X: No user provided and provider cannot set user' ) + array( LogLevel::INFO, 'Session "{session}": No user provided and provider cannot set user' ) ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1234,14 +1239,14 @@ class SessionManagerTest extends MediaWikiTestCase { $this->store->setRawSession( $id, true ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad data' ), + array( LogLevel::WARNING, 'Session "{session}": Bad data' ), ), $logger->getBuffer() ); $logger->clearBuffer(); $this->store->setRawSession( $id, array( 'data' => array() ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad data structure' ), + array( LogLevel::WARNING, 'Session "{session}": Bad data structure' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1249,21 +1254,21 @@ class SessionManagerTest extends MediaWikiTestCase { $this->store->setRawSession( $id, array( 'metadata' => $metadata ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad data structure' ), + array( LogLevel::WARNING, 'Session "{session}": Bad data structure' ), ), $logger->getBuffer() ); $logger->clearBuffer(); $this->store->setRawSession( $id, array( 'metadata' => $metadata, 'data' => true ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad data structure' ), + array( LogLevel::WARNING, 'Session "{session}": Bad data structure' ), ), $logger->getBuffer() ); $logger->clearBuffer(); $this->store->setRawSession( $id, array( 'metadata' => true, 'data' => array() ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad data structure' ), + array( LogLevel::WARNING, 'Session "{session}": Bad data structure' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1273,7 +1278,7 @@ class SessionManagerTest extends MediaWikiTestCase { $this->store->setRawSession( $id, array( 'metadata' => $tmp, 'data' => array() ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Bad metadata' ), + array( LogLevel::WARNING, 'Session "{session}": Bad metadata' ), ), $logger->getBuffer() ); $logger->clearBuffer(); } @@ -1299,7 +1304,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Wrong provider, Bad !== Mock' ), + array( LogLevel::WARNING, 'Session "{session}": Wrong provider Bad !== Mock' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1311,7 +1316,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Unknown provider, Bad' ), + array( LogLevel::WARNING, 'Session "{session}": Unknown provider Bad' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1334,7 +1339,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::ERROR, 'Session X: Invalid ID' ), + array( LogLevel::ERROR, 'Session "{session}": {exception}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1347,7 +1352,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::ERROR, 'Session X: Invalid user name' ), + array( LogLevel::ERROR, 'Session "{session}": {exception}', ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1362,7 +1367,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: User ID mismatch, 2 !== 1' ), + array( LogLevel::WARNING, 'Session "{session}": User ID mismatch, {uid_a} !== {uid_b}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1377,7 +1382,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: User name mismatch, X !== UTSysop' ), + array( LogLevel::WARNING, 'Session "{session}": User name mismatch, {uname_a} !== {uname_b}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1393,7 +1398,8 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( array( - LogLevel::WARNING, 'Session X: User ID matched but name didn\'t (rename?), X !== UTSysop' + LogLevel::WARNING, + 'Session "{session}": User ID matched but name didn\'t (rename?), {uname_a} !== {uname_b}' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1410,7 +1416,9 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( array( - LogLevel::WARNING, 'Session X: Metadata has an anonymous user, but a non-anon user was provided' + LogLevel::WARNING, + 'Session "{session}": Metadata has an anonymous user, ' . + 'but a non-anon user was provided', ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1494,7 +1502,7 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: User token mismatch' ), + array( LogLevel::WARNING, 'Session "{session}": User token mismatch' ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1538,7 +1546,10 @@ class SessionManagerTest extends MediaWikiTestCase { ) ); $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Metadata merge failed: no merge!' ), + array( + LogLevel::WARNING, + 'Session "{session}": Metadata merge failed: {exception}', + ), ), $logger->getBuffer() ); $logger->clearBuffer(); @@ -1669,7 +1680,7 @@ class SessionManagerTest extends MediaWikiTestCase { $this->assertFalse( $loadSessionInfoFromStore( $info ) ); $this->assertTrue( $called ); $this->assertSame( array( - array( LogLevel::WARNING, 'Session X: Hook aborted' ), + array( LogLevel::WARNING, 'Session "{session}": Hook aborted' ), ), $logger->getBuffer() ); $logger->clearBuffer(); } -- 2.20.1