Merge "Update session log messages"
authorjenkins-bot <jenkins-bot@gerrit.wikimedia.org>
Mon, 8 Feb 2016 16:02:45 +0000 (16:02 +0000)
committerGerrit Code Review <gerrit@wikimedia.org>
Mon, 8 Feb 2016 16:02:45 +0000 (16:02 +0000)
1  2 
includes/session/SessionManager.php
tests/phpunit/includes/session/SessionManagerTest.php

@@@ -216,8 -216,11 +216,11 @@@ final class SessionManager implements S
                        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;
                        }
                }
  
                // 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;
                        }
                } 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
        public function preventSessionsForUser( $username ) {
                $this->preventUsers[$username] = true;
  
 -              // Reset the user's token to kill existing sessions
 -              $user = User::newFromName( $username );
 -              if ( $user && $user->getToken( false ) ) {
 -                      $user->setToken();
 -                      $user->saveSettings();
 -              }
 -
                // Instruct the session providers to kill any other sessions too.
                foreach ( $this->getProviders() as $provider ) {
                        $provider->preventSessionsForUser( $username );
                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;
                        }
                        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;
                        }
                                !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;
                        }
                        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;
                        }
  
                                                        $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;
                                        }
                                }
                                                $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;
                                // 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;
                                        }
  
                                        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;
                                }
                        }
                        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() ) {
                } 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;
                        }
  
                                        $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;
                        }
  
                        'SessionCheckInfo',
                        array( &$reason, $info, $request, $metadata, $data )
                ) ) {
-                       $this->logger->warning( "Session $info: $reason" );
+                       $this->logger->warning( 'Session "{session}": ' . $reason, array(
+                               'session' => $info,
+                       ) );
                        return false;
                }
  
@@@ -2,8 -2,9 +2,9 @@@
  
  namespace MediaWiki\Session;
  
- use Psr\Log\LogLevel;
+ use AuthPlugin;
  use MediaWikiTestCase;
+ use Psr\Log\LogLevel;
  use User;
  
  /**
@@@ -596,6 -597,7 +597,6 @@@ class SessionManagerTest extends MediaW
                        'Bar' => array( 'X', 'Bar1', 3 => 'Bar2' ),
                        'Quux' => array( 'Quux' ),
                        'Baz' => array(),
 -                      'Quux' => array( 'Quux' ),
                );
  
                $this->assertEquals( $expect, $manager->getVaryHeaders() );
  
                \ObjectCache::$instances[__METHOD__] = new TestBagOStuff();
                $this->setMwGlobals( array( 'wgMainCacheType' => __METHOD__ ) );
+               $this->setMWGlobals( array(
+                       'wgAuth' => new AuthPlugin,
+               ) );
  
                $this->stashMwGlobals( array( 'wgGroupPermissions' ) );
                $wgGroupPermissions['*']['createaccount'] = true;
                                return null;
                        }
                        $m = str_replace( 'MediaWiki\Session\SessionManager::autoCreateUser: ', '', $m );
-                       $m = preg_replace( '/ - from: .*$/', ' - from: XXX', $m );
                        return $m;
                } );
                $manager->setLogger( $logger );
                        $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();
  
                $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();
  
                        $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();
  
                        $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();
  
                        '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();
        }
                        $this->objectCacheDef( $provider1 ),
                ) );
  
 -              $user = User::newFromName( 'UTSysop' );
 -              $token = $user->getToken( true );
 -
                $this->assertFalse( $manager->isUserSessionPrevented( 'UTSysop' ) );
                $manager->preventSessionsForUser( 'UTSysop' );
 -              $this->assertNotEquals( $token, User::newFromName( 'UTSysop' )->getToken() );
                $this->assertTrue( $manager->isUserSessionPrevented( 'UTSysop' ) );
        }
  
        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();
  
                $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();
  
                ) );
                $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();
  
                $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();
  
                $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();
  
                $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();
  
                        $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();
                }
                ) );
                $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();
  
                ) );
                $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();
  
                ) );
                $this->assertFalse( $loadSessionInfoFromStore( $info ) );
                $this->assertSame( array(
-                       array( LogLevel::ERROR, 'Session X: Invalid ID' ),
+                       array( LogLevel::ERROR, 'Session "{session}": {exception}' ),
                ), $logger->getBuffer() );
                $logger->clearBuffer();
  
                ) );
                $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();
  
                ) );
                $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();
  
                ) );
                $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();
  
                $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();
                $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();
                ) );
                $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();
  
                ) );
                $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();
  
                $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();
        }