From: Bryan Davis Date: Fri, 21 Mar 2014 05:01:24 +0000 (-0600) Subject: Use MWLogger logging for legacy logging methods X-Git-Tag: 1.31.0-rc.0~13453 X-Git-Url: https://git.cyclocoop.org/%7B%24admin_url%7Dmembres/%7B%7B%20url_for%28%27vote%27%2C%20idvote=vote.voteid%29%20%7D%7D?a=commitdiff_plain;h=28a7ce420bd94e77db9a4cff983499c61292ab4c;p=lhc%2Fweb%2Fwiklou.git Use MWLogger logging for legacy logging methods Send wfDebug, wfDebugLog, wfLogDBError and wfLogDBError log messages to the new MWLogger PSR-3 logger subsystem. Compatibility with the historic logging operations of wfLogDBError are provided by MWLoggerLegacyLogger and the MWLoggerLegacySpi logger factory. Requires the MWLogger system introduced in I5c82299 and the Composer managed libraries from Ie667944. Change-Id: I1e5596d590144fbfdfd5f18bc42cf1ef0dbcac12 --- diff --git a/RELEASE-NOTES-1.25 b/RELEASE-NOTES-1.25 index 28a3958543..f67a9e90b1 100644 --- a/RELEASE-NOTES-1.25 +++ b/RELEASE-NOTES-1.25 @@ -42,6 +42,8 @@ production. https://www.mediawiki.org/wiki/Manual:Skinning#Page_status_indicators * Edit tokens may now be time-limited: passing a maximum age to User::matchEditToken will reject any older tokens. +* The debug logging internals have been overhauled, and are now using the + PSR-3 interfaces. === Bug fixes in 1.25 === * (bug 71003) No additional code will be generated to try to load CSS-embedded diff --git a/docs/mwlogger.txt b/docs/mwlogger.txt index 5a3e249b3d..aab95992f0 100644 --- a/docs/mwlogger.txt +++ b/docs/mwlogger.txt @@ -24,6 +24,14 @@ instance. Alternately the MWLogger::registerProvider method can be called to inject an MWLoggerSpi instance into MWLogger and bypass the use of this configuration variable. +The MWLoggerLegacySpi class implements a service provider to generate +MWLoggerLegacyLogger instances. The MWLoggerLegacyLogger class implements the +PSR-3 logger interface and provides output and configuration equivalent to the +historic logging output of wfDebug, wfDebugLog, wfLogDBError and wfErrorLog. +The MWLoggerLegacySpi class is the default service provider configured in +DefaultSettings.php. It's usage should be transparent for users who are not +ready or do not wish to switch to a alternate logging platform. + The MWLoggerMonologSpi class implements a service provider to generate MWLogger instances that use the Monolog [1] logging library. See the PHP docs (or source) for MWLoggerMonologSpi for details on the configuration of this @@ -39,6 +47,11 @@ a more feature rich logging configuration. : Service provider interface for MWLogger factories ; MWLoggerNullSpi : MWLoggerSpi for creating instances that discard all log events +; MWLoggerLegacySpi +: Service provider for creating MWLoggerLegacyLogger instances +; MWLoggerLegacyLogger +: PSR-3 logger that mimics the historical output and configuration of wfDebug, + wfErrorLog and other global logging functions. ; MWLoggerMonologSpi : MWLoggerSpi for creating instances backed by the monolog logging library ; MwLoggerMonologHandler diff --git a/includes/AutoLoader.php b/includes/AutoLoader.php index 09bc5c04e4..08958738c8 100644 --- a/includes/AutoLoader.php +++ b/includes/AutoLoader.php @@ -464,6 +464,8 @@ $wgAutoloadLocalClasses = array( # includes/debug 'MWDebug' => 'includes/debug/MWDebug.php', 'MWLogger' => 'includes/debug/logger/Logger.php', + 'MWLoggerLegacyLogger' => 'includes/debug/logger/legacy/Logger.php', + 'MWLoggerLegacySpi' => 'includes/debug/logger/legacy/Spi.php', 'MWLoggerMonologHandler' => 'includes/debug/logger/monolog/Handler.php', 'MWLoggerMonologProcessor' => 'includes/debug/logger/monolog/Processor.php', 'MWLoggerMonologSpi' => 'includes/debug/logger/monolog/Spi.php', diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index 6b937eab26..cfc84389ad 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -5233,7 +5233,7 @@ $wgDebugLogGroups = array(); * @see MwLogger */ $wgMWLoggerDefaultSpi = array( - 'class' => 'MWLoggerNullSpi', + 'class' => 'MWLoggerLegacySpi', ); /** diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php index 11388e8607..379335ab5a 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -959,7 +959,7 @@ function wfMatchesDomainList( $url, $domains ) { * - false: same as 'log' */ function wfDebug( $text, $dest = 'all' ) { - global $wgDebugLogFile, $wgDebugRawPage, $wgDebugLogPrefix; + global $wgDebugRawPage, $wgDebugLogPrefix; if ( !$wgDebugRawPage && wfIsDebugRawPage() ) { return; @@ -974,6 +974,7 @@ function wfDebug( $text, $dest = 'all' ) { $timer = wfDebugTimer(); if ( $timer !== '' ) { + // Prepend elapsed request time and real memory usage to each line $text = preg_replace( '/[^\n]/', $timer . '\0', $text, 1 ); } @@ -981,13 +982,13 @@ function wfDebug( $text, $dest = 'all' ) { MWDebug::debugMsg( $text ); } - if ( $wgDebugLogFile != '' ) { - # Strip unprintables; they can switch terminal modes when binary data - # gets dumped, which is pretty annoying. - $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $text ); - $text = $wgDebugLogPrefix . $text; - wfErrorLog( $text, $wgDebugLogFile ); + $ctx = array(); + if ( $wgDebugLogPrefix !== '' ) { + $ctx['prefix'] = $wgDebugLogPrefix; } + + $logger = MWLogger::getInstance( 'wfDebug' ); + $logger->debug( rtrim( $text, "\n" ), $ctx ); } /** @@ -1068,8 +1069,6 @@ function wfDebugMem( $exact = false ) { function wfDebugLog( $logGroup, $text, $dest = 'all' ) { global $wgDebugLogGroups; - $text = trim( $text ) . "\n"; - // Turn $dest into a string if it's a boolean (for b/c) if ( $dest === true ) { $dest = 'all'; @@ -1077,34 +1076,16 @@ function wfDebugLog( $logGroup, $text, $dest = 'all' ) { $dest = 'private'; } - if ( !isset( $wgDebugLogGroups[$logGroup] ) ) { - if ( $dest !== 'private' ) { - wfDebug( "[$logGroup] $text", $dest ); - } - return; - } + $text = trim( $text ); if ( $dest === 'all' ) { - MWDebug::debugMsg( "[$logGroup] $text" ); - } - - $logConfig = $wgDebugLogGroups[$logGroup]; - if ( $logConfig === false ) { - return; - } - if ( is_array( $logConfig ) ) { - if ( isset( $logConfig['sample'] ) && mt_rand( 1, $logConfig['sample'] ) !== 1 ) { - return; - } - $destination = $logConfig['destination']; - } else { - $destination = strval( $logConfig ); + MWDebug::debugMsg( "[{$logGroup}] {$text}\n" ); } - $time = wfTimestamp( TS_DB ); - $wiki = wfWikiID(); - $host = wfHostname(); - wfErrorLog( "$time $host $wiki: $text", $destination ); + $logger = MWLogger::getInstance( $logGroup ); + $logger->debug( $text, array( + 'private' => ( $dest === 'private' ), + ) ); } /** @@ -1113,30 +1094,8 @@ function wfDebugLog( $logGroup, $text, $dest = 'all' ) { * @param string $text Database error message. */ function wfLogDBError( $text ) { - global $wgDBerrorLog, $wgDBerrorLogTZ; - static $logDBErrorTimeZoneObject = null; - - if ( $wgDBerrorLog ) { - $host = wfHostname(); - $wiki = wfWikiID(); - - if ( $wgDBerrorLogTZ && !$logDBErrorTimeZoneObject ) { - $logDBErrorTimeZoneObject = new DateTimeZone( $wgDBerrorLogTZ ); - } - - // Workaround for https://bugs.php.net/bug.php?id=52063 - // Can be removed when min PHP > 5.3.2 - if ( $logDBErrorTimeZoneObject === null ) { - $d = date_create( "now" ); - } else { - $d = date_create( "now", $logDBErrorTimeZoneObject ); - } - - $date = $d->format( 'D M j G:i:s T Y' ); - - $text = "$date\t$host\t$wiki\t" . trim( $text ) . "\n"; - wfErrorLog( $text, $wgDBerrorLog ); - } + $logger = MWLogger::getInstance( 'wfLogDBError' ); + $logger->error( trim( $text ) ); } /** @@ -1194,58 +1153,10 @@ function wfLogWarning( $msg, $callerOffset = 1, $level = E_USER_WARNING ) { * @throws MWException */ function wfErrorLog( $text, $file ) { - if ( substr( $file, 0, 4 ) == 'udp:' ) { - # Needs the sockets extension - if ( preg_match( '!^(tcp|udp):(?://)?\[([0-9a-fA-F:]+)\]:(\d+)(?:/(.*))?$!', $file, $m ) ) { - // IPv6 bracketed host - $host = $m[2]; - $port = intval( $m[3] ); - $prefix = isset( $m[4] ) ? $m[4] : false; - $domain = AF_INET6; - } elseif ( preg_match( '!^(tcp|udp):(?://)?([a-zA-Z0-9.-]+):(\d+)(?:/(.*))?$!', $file, $m ) ) { - $host = $m[2]; - if ( !IP::isIPv4( $host ) ) { - $host = gethostbyname( $host ); - } - $port = intval( $m[3] ); - $prefix = isset( $m[4] ) ? $m[4] : false; - $domain = AF_INET; - } else { - throw new MWException( __METHOD__ . ': Invalid UDP specification' ); - } - - // Clean it up for the multiplexer - if ( strval( $prefix ) !== '' ) { - $text = preg_replace( '/^/m', $prefix . ' ', $text ); - - // Limit to 64KB - if ( strlen( $text ) > 65506 ) { - $text = substr( $text, 0, 65506 ); - } - - if ( substr( $text, -1 ) != "\n" ) { - $text .= "\n"; - } - } elseif ( strlen( $text ) > 65507 ) { - $text = substr( $text, 0, 65507 ); - } - - $sock = socket_create( $domain, SOCK_DGRAM, SOL_UDP ); - if ( !$sock ) { - return; - } - - socket_sendto( $sock, $text, strlen( $text ), 0, $host, $port ); - socket_close( $sock ); - } else { - wfSuppressWarnings(); - $exists = file_exists( $file ); - $size = $exists ? filesize( $file ) : false; - if ( !$exists || ( $size !== false && $size + strlen( $text ) < 0x7fffffff ) ) { - file_put_contents( $file, $text, FILE_APPEND ); - } - wfRestoreWarnings(); - } + $logger = MWLogger::getInstance( 'wfErrorLog' ); + $logger->info( trim( $text ), array( + 'destination' => $file, + ) ); } /** diff --git a/includes/debug/logger/legacy/Logger.php b/includes/debug/logger/legacy/Logger.php new file mode 100644 index 0000000000..ff6336bd00 --- /dev/null +++ b/includes/debug/logger/legacy/Logger.php @@ -0,0 +1,318 @@ + + * @copyright © 2014 Bryan Davis and Wikimedia Foundation. + */ +class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger { + + /** + * @var string $channel + */ + protected $channel; + + + /** + * @param string $channel + */ + public function __construct( $channel ) { + $this->channel = $channel; + } + + /** + * Logs with an arbitrary level. + * + * @param string|int $level + * @param string $message + * @param array $context + */ + public function log( $level, $message, array $context = array() ) { + if ( self::shouldEmit( $this->channel, $message, $context ) ) { + $text = self::format( $this->channel, $message, $context ); + $destination = self::destination( $this->channel, $message, $context ); + self::emit( $text, $destination ); + } + } + + + /** + * Determine if the given message should be emitted or not. + * + * @param string $channel + * @param string $message + * @param array $context + * @return bool True if message should be sent to disk/network, false + * otherwise + */ + protected static function shouldEmit( $channel, $message, $context ) { + global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups; + + if ( $channel === 'wfLogDBError' ) { + // wfLogDBError messages are emitted if a database log location is + // specfied. + $shouldEmit = (bool) $wgDBerrorLog; + + } elseif ( $channel === 'wfErrorLog' ) { + // All messages on the wfErrorLog channel should be emitted. + $shouldEmit = true; + + } elseif ( isset( $wgDebugLogGroups[$channel] ) ) { + $logConfig = $wgDebugLogGroups[$channel]; + + if ( is_array( $logConfig ) && isset( $logConfig['sample'] ) ) { + // Emit randomly with a 1 in 'sample' chance for each message. + $shouldEmit = mt_rand( 1, $logConfig['sample'] ) === 1; + + } else { + // Emit unless the config value is explictly false. + $shouldEmit = $logConfig !== false; + } + + } elseif ( isset( $context['private'] ) && $context['private'] ) { + // Don't emit if the message didn't match previous checks based on the + // channel and the event is marked as private. This check discards + // messages sent via wfDebugLog() with dest == 'private' and no explicit + // wgDebugLogGroups configuration. + $shouldEmit = false; + } else { + // Default return value is the the same as the historic wfDebug + // method: emit if $wgDebugLogFile has been set. + $shouldEmit = $wgDebugLogFile != ''; + } + + return $shouldEmit; + } + + + /** + * Format a message. + * + * Messages to the 'wfDebug', 'wfLogDBError' and 'wfErrorLog' channels + * receive special fomatting to mimic the historic output of the functions + * of the same name. All other channel values are formatted based on the + * historic output of the `wfDebugLog()` global function. + * + * @param string $channel + * @param string $message + * @param array $context + * @return string + */ + protected static function format( $channel, $message, $context ) { + global $wgDebugLogGroups; + + if ( $channel === 'wfDebug' ) { + $text = self::formatWfDebug( $channel, $message, $context ); + + } elseif ( $channel === 'wfLogDBError' ) { + $text = self::formatWfLogDBError( $channel, $message, $context ); + + } elseif ( $channel === 'wfErrorLog' ) { + $text = "{$message}\n"; + + } elseif ( !isset( $wgDebugLogGroups[$channel] ) ) { + $text = self::formatWfDebug( + $channel, "[{$channel}] {$message}", $context ); + + } else { + // Default formatting is wfDebugLog's historic style + $time = wfTimestamp( TS_DB ); + $wiki = wfWikiID(); + $host = wfHostname(); + $text = "{$time} {$host} {$wiki}: {$message}\n"; + } + return $text; + } + + + /** + * Format a message as `wfDebug()` would have formatted it. + * + * @param string $channel + * @param string $message + * @param array $context + * @return string + */ + protected static function formatWfDebug( $channel, $message, $context ) { + $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message ); + if ( isset( $context['prefix'] ) ) { + $text = "{$context['prefix']}{$text}"; + } + return "{$text}\n"; + } + + + /** + * Format a message as `wfLogDBError()` would have formatted it. + * + * @param string $channel + * @param string $message + * @param array $context + * @return string + */ + protected static function formatWfLogDBError( $channel, $message, $context ) { + global $wgDBerrorLogTZ; + static $cachedTimezone = null; + + if ( $wgDBerrorLogTZ && !$cachedTimezone ) { + $cachedTimezone = new DateTimeZone( $wgDBerrorLogTZ ); + } + + // Workaround for https://bugs.php.net/bug.php?id=52063 + // Can be removed when min PHP > 5.3.2 + if ( $cachedTimezone === null ) { + $d = date_create( 'now' ); + } else { + $d = date_create( 'now', $cachedTimezone ); + } + $date = $d->format( 'D M j G:i:s T Y' ); + + $host = wfHostname(); + $wiki = wfWikiID(); + + $text = "{$date}\t{$host}\t{$wiki}\t{$message}\n"; + return $text; + } + + + /** + * Select the appropriate log output destination for the given log event. + * + * If the event context contains 'destination' + * + * @param string $channel + * @param string $message + * @param array $context + * @return string + */ + protected static function destination( $channel, $message, $context ) { + global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups; + + // Default destination is the debug log file as historically used by + // the wfDebug function. + $destination = $wgDebugLogFile; + + if ( isset( $context['destination'] ) ) { + // Use destination explicitly provided in context + $destination = $context['destination']; + + } elseif ( $channel === 'wfDebug' ) { + $destination = $wgDebugLogFile; + + } elseif ( $channel === 'wfLogDBError' ) { + $destination = $wgDBerrorLog; + + } elseif ( isset( $wgDebugLogGroups[$channel] ) ) { + $logConfig = $wgDebugLogGroups[$channel]; + + if ( is_array( $logConfig ) ) { + $destination = $logConfig['destination']; + } else { + $destination = strval( $logConfig ); + } + } + + return $destination; + } + + + /** + * Log to a file without getting "file size exceeded" signals. + * + * Can also log to UDP with the syntax udp://host:port/prefix. This will send + * lines to the specified port, prefixed by the specified prefix and a space. + * + * @param string $text + * @param string $file Filename + * @throws MWException + */ + public static function emit( $text, $file ) { + if ( substr( $file, 0, 4 ) == 'udp:' ) { + # Needs the sockets extension + if ( preg_match( '!^udp:(?://)?\[([0-9a-fA-F:]+)\]:(\d+)(?:/(.*))?$!', $file, $m ) ) { + // IPv6 bracketed host + $host = $m[1]; + $port = intval( $m[2] ); + $prefix = isset( $m[3] ) ? $m[3] : false; + $domain = AF_INET6; + } elseif ( preg_match( '!^udp:(?://)?([a-zA-Z0-9.-]+):(\d+)(?:/(.*))?$!', $file, $m ) ) { + $host = $m[1]; + if ( !IP::isIPv4( $host ) ) { + $host = gethostbyname( $host ); + } + $port = intval( $m[2] ); + $prefix = isset( $m[3] ) ? $m[3] : false; + $domain = AF_INET; + } else { + throw new MWException( __METHOD__ . ': Invalid UDP specification' ); + } + + // Clean it up for the multiplexer + if ( strval( $prefix ) !== '' ) { + $text = preg_replace( '/^/m', $prefix . ' ', $text ); + + // Limit to 64KB + if ( strlen( $text ) > 65506 ) { + $text = substr( $text, 0, 65506 ); + } + + if ( substr( $text, -1 ) != "\n" ) { + $text .= "\n"; + } + } elseif ( strlen( $text ) > 65507 ) { + $text = substr( $text, 0, 65507 ); + } + + $sock = socket_create( $domain, SOCK_DGRAM, SOL_UDP ); + if ( !$sock ) { + return; + } + + socket_sendto( $sock, $text, strlen( $text ), 0, $host, $port ); + socket_close( $sock ); + } else { + wfSuppressWarnings(); + $exists = file_exists( $file ); + $size = $exists ? filesize( $file ) : false; + if ( !$exists || + ( $size !== false && $size + strlen( $text ) < 0x7fffffff ) + ) { + file_put_contents( $file, $text, FILE_APPEND ); + } + wfRestoreWarnings(); + } + } + +} diff --git a/includes/debug/logger/legacy/Spi.php b/includes/debug/logger/legacy/Spi.php new file mode 100644 index 0000000000..51e14a27ae --- /dev/null +++ b/includes/debug/logger/legacy/Spi.php @@ -0,0 +1,58 @@ + 'MWLoggerLegacySpi', + * ); + * @endcode + * + * @see MWLogger + * @since 1.25 + * @author Bryan Davis + * @copyright © 2014 Bryan Davis and Wikimedia Foundation. + */ +class MWLoggerLegacySpi implements MWLoggerSpi { + + /** + * @var array $singletons + */ + protected $singletons = array(); + + + /** + * Get a logger instance. + * + * @param string $channel Logging channel + * @return MWLogger Logger instance + */ + public function getLogger( $channel ) { + if ( !isset( $this->singletons[$channel] ) ) { + $this->singletons[$channel] = new MWLoggerLegacyLogger($channel); + } + return $this->singletons[$channel]; + } + +} diff --git a/tests/phpunit/includes/GlobalFunctions/GlobalTest.php b/tests/phpunit/includes/GlobalFunctions/GlobalTest.php index 3acc48e27c..2bfabe4df7 100644 --- a/tests/phpunit/includes/GlobalFunctions/GlobalTest.php +++ b/tests/phpunit/includes/GlobalFunctions/GlobalTest.php @@ -322,16 +322,16 @@ class GlobalTest extends MediaWikiTestCase { $wgDebugTimestamps = false; wfDebug( "This is a normal string" ); - $this->assertEquals( "This is a normal string", file_get_contents( $wgDebugLogFile ) ); + $this->assertEquals( "This is a normal string\n", file_get_contents( $wgDebugLogFile ) ); unlink( $wgDebugLogFile ); wfDebug( "This is nöt an ASCII string" ); - $this->assertEquals( "This is nöt an ASCII string", file_get_contents( $wgDebugLogFile ) ); + $this->assertEquals( "This is nöt an ASCII string\n", file_get_contents( $wgDebugLogFile ) ); unlink( $wgDebugLogFile ); wfDebug( "\00305This has böth UTF and control chars\003" ); $this->assertEquals( - " 05This has böth UTF and control chars ", + " 05This has böth UTF and control chars \n", file_get_contents( $wgDebugLogFile ) ); unlink( $wgDebugLogFile );