Update session log messages
authorBryan Davis <bd808@wikimedia.org>
Tue, 2 Feb 2016 16:37:27 +0000 (09:37 -0700)
committerBryan Davis <bd808@wikimedia.org>
Sat, 6 Feb 2016 23:18:01 +0000 (16:18 -0700)
* Use PSR-3 templates and context where applicable
* Add log coverage for exceptional events

Bug: T125452
Change-Id: I8f96fa1c5766c739a21219abcae2dbb76de53e2a

includes/session/BotPasswordSessionProvider.php
includes/session/CookieSessionProvider.php
includes/session/PHPSessionHandler.php
includes/session/SessionBackend.php
includes/session/SessionManager.php
tests/phpunit/includes/session/BotPasswordSessionProviderTest.php
tests/phpunit/includes/session/CookieSessionProviderTest.php
tests/phpunit/includes/session/PHPSessionHandlerTest.php
tests/phpunit/includes/session/SessionManagerTest.php

index d9c60c7..81c7ebf 100644 (file)
@@ -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;
                }
 
index f989cbc..3177dc2 100644 (file)
@@ -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
index 4dea274..795e253 100644 (file)
@@ -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;
                }
 
index 2bff173..a79c5cb 100644 (file)
@@ -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' );
                        }
index 57d5664..5e2ef01 100644 (file)
@@ -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;
                }
 
index 52872a4..e1ba0ba 100644 (file)
@@ -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();
 
index 9ba67df..f5c8b05 100644 (file)
@@ -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() {
index 3044aa7..e071132 100644 (file)
@@ -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,
index d8d5b4b..e60cefe 100644 (file)
@@ -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();
        }