Add logging context to database logs
authorBryan Davis <bd808@wikimedia.org>
Mon, 23 Jun 2014 22:25:55 +0000 (16:25 -0600)
committerLegoktm <legoktm.wikipedia@gmail.com>
Wed, 19 Nov 2014 17:59:55 +0000 (17:59 +0000)
* Add optional $context parameter to wfDebug, wfDebugLog, wfLogDBError
  and wfErrorLog that will be passed to MWLogger.
* Add support for PSR-3 style log message parameter interpolation in
  MWLoggerLegacyLogger.
* Add context information to wfLogDBError calls made from DatabaseBase,
  DatabaseMysqlBase and LoadBalancer instances.
* Deprecate wfDebugTimer() which now appears to be unused.

Change-Id: Ic90d593d00a2b0b5b80ed205908cbe624042603c

includes/GlobalFunctions.php
includes/db/Database.php
includes/db/DatabaseMysqlBase.php
includes/db/LoadBalancer.php
includes/debug/logger/legacy/Logger.php
tests/phpunit/includes/debug/logging/legacy/LoggerTest.php [new file with mode: 0644]

index 71c3791..25b352b 100644 (file)
@@ -950,6 +950,8 @@ function wfMatchesDomainList( $url, $domains ) {
  * $wgDebugRawPage - if false, 'action=raw' hits will not result in debug output.
  * $wgDebugComments - if on, some debug items may appear in comments in the HTML output.
  *
+ * @since 1.25 support for additional context data
+ *
  * @param string $text
  * @param string|bool $dest Destination of the message:
  *     - 'all': both to the log and HTML (debug toolbar or HTML comments)
@@ -957,9 +959,11 @@ function wfMatchesDomainList( $url, $domains ) {
  *   For backward compatibility, it can also take a boolean:
  *     - true: same as 'all'
  *     - false: same as 'log'
+ * @param array $context Additional logging context data
  */
-function wfDebug( $text, $dest = 'all' ) {
+function wfDebug( $text, $dest = 'all', array $context = array() ) {
        global $wgDebugRawPage, $wgDebugLogPrefix;
+       global $wgDebugTimestamps, $wgRequestTime;
 
        if ( !$wgDebugRawPage && wfIsDebugRawPage() ) {
                return;
@@ -972,23 +976,36 @@ function wfDebug( $text, $dest = 'all' ) {
                $dest = 'log';
        }
 
-       $timer = wfDebugTimer();
-       if ( $timer !== '' ) {
-               // Prepend elapsed request time and real memory usage to each line
-               $text = preg_replace( '/[^\n]/', $timer . '\0', $text, 1 );
+       $text = trim( $text );
+
+       // Inline logic from deprecated wfDebugTimer()
+       if ( $wgDebugTimestamps ) {
+               $context['seconds_elapsed'] = sprintf(
+                       '%6.4f',
+                       microtime( true ) - $wgRequestTime
+               );
+               $context['memory_used'] = sprintf(
+                       '%5.1fM',
+                       ( memory_get_usage( true ) / ( 1024 * 1024 ) )
+               );
        }
 
        if ( $dest === 'all' ) {
-               MWDebug::debugMsg( $text );
+               $prefix = '';
+               if ( $wgDebugTimestamps ) {
+                       // Prepend elapsed request time and real memory usage with two
+                       // trailing spaces.
+                       $prefix = "{$context['seconds_elapsed']} {$context['memory_used']}  ";
+               }
+               MWDebug::debugMsg( "{$prefix}{$text}" );
        }
 
-       $ctx = array();
        if ( $wgDebugLogPrefix !== '' ) {
-               $ctx['prefix'] = $wgDebugLogPrefix;
+               $context['prefix'] = $wgDebugLogPrefix;
        }
 
        $logger = MWLogger::getInstance( 'wfDebug' );
-       $logger->debug( rtrim( $text, "\n" ), $ctx );
+       $logger->debug( $text, $context );
 }
 
 /**
@@ -1017,11 +1034,14 @@ function wfIsDebugRawPage() {
 /**
  * Get microsecond timestamps for debug logs
  *
+ * @deprecated since 1.25
  * @return string
  */
 function wfDebugTimer() {
        global $wgDebugTimestamps, $wgRequestTime;
 
+       wfDeprecated( __METHOD__, '1.25' );
+
        if ( !$wgDebugTimestamps ) {
                return '';
        }
@@ -1054,6 +1074,7 @@ function wfDebugMem( $exact = false ) {
  * a sampling factor.
  *
  * @since 1.23 support for sampling log messages via $wgDebugLogGroups.
+ * @since 1.25 support for additional context data
  *
  * @param string $logGroup
  * @param string $text
@@ -1065,8 +1086,11 @@ function wfDebugMem( $exact = false ) {
  *   For backward compatibility, it can also take a boolean:
  *     - true: same as 'all'
  *     - false: same as 'private'
+ * @param array $context Additional logging context data
  */
-function wfDebugLog( $logGroup, $text, $dest = 'all' ) {
+function wfDebugLog(
+       $logGroup, $text, $dest = 'all', array $context = array()
+) {
        // Turn $dest into a string if it's a boolean (for b/c)
        if ( $dest === true ) {
                $dest = 'all';
@@ -1081,19 +1105,21 @@ function wfDebugLog( $logGroup, $text, $dest = 'all' ) {
        }
 
        $logger = MWLogger::getInstance( $logGroup );
-       $logger->debug( $text, array(
-               'private' => ( $dest === 'private' ),
-       ) );
+       $context['private'] = ( $dest === 'private' );
+       $logger->debug( $text, $context );
 }
 
 /**
  * Log for database errors
  *
+ * @since 1.25 support for additional context data
+ *
  * @param string $text Database error message.
+ * @param array $context Additional logging context data
  */
-function wfLogDBError( $text ) {
+function wfLogDBError( $text, array $context = array() ) {
        $logger = MWLogger::getInstance( 'wfLogDBError' );
-       $logger->error( trim( $text ) );
+       $logger->error( trim( $text ), $context );
 }
 
 /**
@@ -1145,16 +1171,17 @@ function wfLogWarning( $msg, $callerOffset = 1, $level = E_USER_WARNING ) {
  *
  * Can also log to TCP or UDP with the syntax udp://host:port/prefix. This will
  * send lines to the specified port, prefixed by the specified prefix and a space.
+ * @since 1.25 support for additional context data
  *
  * @param string $text
  * @param string $file Filename
+ * @param array $context Additional logging context data
  * @throws MWException
  */
-function wfErrorLog( $text, $file ) {
+function wfErrorLog( $text, $file, array $context = array() ) {
        $logger = MWLogger::getInstance( 'wfErrorLog' );
-       $logger->info( trim( $text ), array(
-               'destination' => $file,
-       ) );
+       $context['destination'] = $file;
+       $logger->info( trim( $text ), $context );
 }
 
 /**
index 18cd39f..2d14bcb 100644 (file)
@@ -798,6 +798,23 @@ abstract class DatabaseBase implements IDatabase {
                $this->mPHPError = $errstr;
        }
 
+       /**
+        * Create a log context to pass to wfLogDBError or other logging functions.
+        *
+        * @param array $extras Additional data to add to context
+        * @return array
+        */
+       protected function getLogContext( array $extras = array() ) {
+               return array_merge(
+                       array(
+                               'db_server' => $this->mServer,
+                               'db_name' => $this->mDBname,
+                               'db_user' => $this->mUser,
+                       ),
+                       $extras
+               );
+       }
+
        /**
         * Closes a database connection.
         * if it is open : commits any open transactions
@@ -1015,7 +1032,13 @@ abstract class DatabaseBase implements IDatabase {
                                $elapsed = round( microtime( true ) - $wgRequestTime, 3 );
                                if ( $elapsed < 300 ) {
                                        # Not a database error to lose a transaction after a minute or two
-                                       wfLogDBError( "Connection lost and reconnected after {$elapsed}s, query: $sqlx" );
+                                       wfLogDBError(
+                                               "Connection lost and reconnected after {$elapsed}s, query: $sqlx",
+                                               $this->getLogContext( array(
+                                                       'method' => __METHOD__,
+                                                       'query' => $sqlx,
+                                               ) )
+                                       );
                                }
                                if ( $hadTrx ) {
                                        # Leave $ret as false and let an error be reported.
@@ -1063,7 +1086,16 @@ abstract class DatabaseBase implements IDatabase {
                        $this->ignoreErrors( $ignore );
                } else {
                        $sql1line = mb_substr( str_replace( "\n", "\\n", $sql ), 0, 5 * 1024 );
-                       wfLogDBError( "$fname\t{$this->mServer}\t$errno\t$error\t$sql1line" );
+                       wfLogDBError(
+                               "{fname}\t{db_server}\t{errno}\t{error}\t{sql1line}",
+                               $this->getLogContext( array(
+                                       'method' => __METHOD__,
+                                       'errno' => $errno,
+                                       'error' => $error,
+                                       'sql1line' => $sql1line,
+                                       'fname' => $fname,
+                               ) )
+                       );
                        wfDebug( "SQL ERROR: " . $error . "\n" );
                        throw new DBQueryError( $this, $error, $errno, $sql, $fname );
                }
@@ -3338,7 +3370,12 @@ abstract class DatabaseBase implements IDatabase {
                                $msg = "$fname: Transaction already in progress (from {$this->mTrxFname}), " .
                                        " performing implicit commit!";
                                wfWarn( $msg );
-                               wfLogDBError( $msg );
+                               wfLogDBError( $msg,
+                                       $this->getLogContext( array(
+                                               'method' => __METHOD__,
+                                               'fname' => $fname,
+                                       ) )
+                               );
                        } else {
                                // if the transaction was automatic and has done write operations,
                                // log it if $wgDebugDBTransactions is enabled.
index 2008f4d..7dfae63 100644 (file)
@@ -96,7 +96,13 @@ abstract class DatabaseMysqlBase extends DatabaseBase {
                        if ( !$error ) {
                                $error = $this->lastError();
                        }
-                       wfLogDBError( "Error connecting to {$this->mServer}: $error" );
+                       wfLogDBError(
+                               "Error connecting to {db_server}: {error}",
+                               $this->getLogContext( array(
+                                       'method' => __METHOD__,
+                                       'error' => $error,
+                               ) )
+                       );
                        wfDebug( "DB connection error\n" .
                                "Server: $server, User: $user, Password: " .
                                substr( $password, 0, 3 ) . "..., error: " . $error . "\n" );
@@ -111,7 +117,12 @@ abstract class DatabaseMysqlBase extends DatabaseBase {
                        $success = $this->selectDB( $dbName );
                        wfRestoreWarnings();
                        if ( !$success ) {
-                               wfLogDBError( "Error selecting database $dbName on server {$this->mServer}" );
+                               wfLogDBError(
+                                       "Error selecting database {db_name} on server {db_server}",
+                                       $this->getLogContext( array(
+                                               'method' => __METHOD__,
+                                       ) )
+                               );
                                wfDebug( "Error selecting database $dbName on server {$this->mServer} " .
                                        "from client host " . wfHostname() . "\n" );
 
@@ -132,7 +143,12 @@ abstract class DatabaseMysqlBase extends DatabaseBase {
                        // Use doQuery() to avoid opening implicit transactions (DBO_TRX)
                        $success = $this->doQuery( "SET sql_mode = $mode", __METHOD__ );
                        if ( !$success ) {
-                               wfLogDBError( "Error setting sql_mode to $mode on server {$this->mServer}" );
+                               wfLogDBError(
+                                       "Error setting sql_mode to $mode on server {db_server}",
+                                       $this->getLogContext( array(
+                                               'method' => __METHOD__,
+                                       ) )
+                               );
                                wfProfileOut( __METHOD__ );
                                $this->reportConnectionError( "Error setting sql_mode to $mode" );
                        }
index 0fb2d09..233c92f 100644 (file)
@@ -760,17 +760,27 @@ class LoadBalancer {
         */
        private function reportConnectionError() {
                $conn = $this->mErrorConnection; // The connection which caused the error
+               $context = array(
+                       'method' => __METHOD__,
+                       'last_error' => $this->mLastError,
+               );
 
                if ( !is_object( $conn ) ) {
                        // No last connection, probably due to all servers being too busy
-                       wfLogDBError( "LB failure with no last connection. Connection error: {$this->mLastError}" );
+                       wfLogDBError(
+                               "LB failure with no last connection. Connection error: {last_error}",
+                               $context
+                       );
 
                        // If all servers were busy, mLastError will contain something sensible
                        throw new DBConnectionError( null, $this->mLastError );
                } else {
-                       $server = $conn->getProperty( 'mServer' );
-                       wfLogDBError( "Connection error: {$this->mLastError} ({$server})" );
-                       $conn->reportConnectionError( "{$this->mLastError} ({$server})" ); // throws DBConnectionError
+                       $context['db_server'] = $conn->getProperty( 'mServer' );
+                       wfLogDBError(
+                               "Connection error: {last_error} ({db_server})",
+                               $context
+                       );
+                       $conn->reportConnectionError( "{$this->mLastError} ({$context['db_server']})" ); // throws DBConnectionError
                }
 
                return false; /* not reached */
index daf3f51..c6d915e 100644 (file)
@@ -178,7 +178,8 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
                        // Default formatting is wfDebugLog's historic style
                        $text = self::formatAsWfDebugLog( $channel, $message, $context );
                }
-               return $text;
+
+               return self::interpolate( $text, $context );
        }
 
 
@@ -192,6 +193,11 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
         */
        protected static function formatAsWfDebug( $channel, $message, $context ) {
                $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message );
+               if ( isset( $context['seconds_elapsed'] ) ) {
+                       // Prepend elapsed request time and real memory usage with two
+                       // trailing spaces.
+                       $text = "{$context['seconds_elapsed']} {$context['memory_used']}  {$text}";
+               }
                if ( isset( $context['prefix'] ) ) {
                        $text = "{$context['prefix']}{$text}";
                }
@@ -248,6 +254,24 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
        }
 
 
+       /**
+        * Interpolate placeholders in logging message.
+        *
+        * @param string $message
+        * @param array $context
+        */
+       public static function interpolate( $message, array $context ) {
+               if ( strpos( $message, '{' ) !== false ) {
+                       $replace = array();
+                       foreach ( $context as $key => $val ) {
+                               $replace['{' . $key . '}'] = $val;
+                       }
+                       $message = strtr( $message, $replace );
+               }
+               return $message;
+       }
+
+
        /**
         * Select the appropriate log output destination for the given log event.
         *
diff --git a/tests/phpunit/includes/debug/logging/legacy/LoggerTest.php b/tests/phpunit/includes/debug/logging/legacy/LoggerTest.php
new file mode 100644 (file)
index 0000000..bad8d8d
--- /dev/null
@@ -0,0 +1,70 @@
+<?php
+/**
+ * @section LICENSE
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License along
+ * with this program; if not, write to the Free Software Foundation, Inc.,
+ * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ * http://www.gnu.org/copyleft/gpl.html
+ *
+ * @file
+ */
+
+class MWLoggerLegacyLoggerTest extends MediaWikiTestCase {
+
+       /**
+        * @covers MWLoggerLegacyLogger::interpolate
+        * @dataProvider provideInterpolate
+        */
+       public function testInterpolate( $message, $context, $expect ) {
+               $this->assertEquals(
+                       $expect, MWLoggerLegacyLogger::interpolate( $message, $context ) );
+       }
+
+       public function provideInterpolate() {
+               return array(
+                       array(
+                               'no-op',
+                               array(),
+                               'no-op',
+                       ),
+                       array(
+                               'Hello {world}!',
+                               array(
+                                       'world' => 'World',
+                               ),
+                               'Hello World!',
+                       ),
+                       array(
+                               '{greeting} {user}',
+                               array(
+                                       'greeting' => 'Goodnight',
+                                       'user' => 'Moon',
+                               ),
+                               'Goodnight Moon',
+                       ),
+                       array(
+                               'Oops {key_not_set}',
+                               array(),
+                               'Oops {key_not_set}',
+                       ),
+                       array(
+                               '{ not interpolated }',
+                               array(
+                                       'not interpolated' => 'This should NOT show up in the message',
+                               ),
+                               '{ not interpolated }',
+                       ),
+               );
+       }
+
+}