From 2792ea9783dfe01a2a7285a073608c2eeea2d958 Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Mon, 23 Jun 2014 16:25:55 -0600 Subject: [PATCH] Add logging context to database logs * 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 | 65 ++++++++++++----- includes/db/Database.php | 43 +++++++++++- includes/db/DatabaseMysqlBase.php | 22 +++++- includes/db/LoadBalancer.php | 18 +++-- includes/debug/logger/legacy/Logger.php | 26 ++++++- .../debug/logging/legacy/LoggerTest.php | 70 +++++++++++++++++++ 6 files changed, 214 insertions(+), 30 deletions(-) create mode 100644 tests/phpunit/includes/debug/logging/legacy/LoggerTest.php diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php index 71c3791749..25b352bdb4 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -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 ); } /** diff --git a/includes/db/Database.php b/includes/db/Database.php index 18cd39f6a9..2d14bcb358 100644 --- a/includes/db/Database.php +++ b/includes/db/Database.php @@ -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. diff --git a/includes/db/DatabaseMysqlBase.php b/includes/db/DatabaseMysqlBase.php index 2008f4d73c..7dfae6302b 100644 --- a/includes/db/DatabaseMysqlBase.php +++ b/includes/db/DatabaseMysqlBase.php @@ -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" ); } diff --git a/includes/db/LoadBalancer.php b/includes/db/LoadBalancer.php index 0fb2d094a4..233c92f4a6 100644 --- a/includes/db/LoadBalancer.php +++ b/includes/db/LoadBalancer.php @@ -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 */ diff --git a/includes/debug/logger/legacy/Logger.php b/includes/debug/logger/legacy/Logger.php index daf3f51d69..c6d915ef39 100644 --- a/includes/debug/logger/legacy/Logger.php +++ b/includes/debug/logger/legacy/Logger.php @@ -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 index 0000000000..bad8d8d5cc --- /dev/null +++ b/tests/phpunit/includes/debug/logging/legacy/LoggerTest.php @@ -0,0 +1,70 @@ +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 }', + ), + ); + } + +} -- 2.20.1