Use MWLogger logging for wfLogProfilingData

Output structured profiling report data from wfLogProfilingData using
MWLogger.

Requires Ie667944, I5c82299, and I1e5596d.

Change-Id: Iae11e1e4fe970ada74136f0e969dc624c586ce17

diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php
index 379335a..55e6e27 100644 (file)
--- a/includes/GlobalFunctions.php
+++ b/includes/GlobalFunctions.php
@@ -1184,53 +1184,54 @@ function wfLogProfilingData() {
 
        $profiler->logData();
 
-       // Check whether this should be logged in the debug file.
        if ( isset( $wgDebugLogGroups['profileoutput'] )
                && $wgDebugLogGroups['profileoutput'] === false
        ) {
-               // Explicitely disabled
-               return;
-       }
-       if ( !isset( $wgDebugLogGroups['profileoutput'] ) && $wgDebugLogFile == '' ) {
-               // Logging not enabled; no point going further
+               // Explicitly disabled
                return;
        }
        if ( !$wgDebugRawPage && wfIsDebugRawPage() ) {
                return;
        }
 
-       $forward = '';
+       $ctx = array( 'elapsed' => $elapsed );
        if ( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) {
-               $forward = ' forwarded for ' . $_SERVER['HTTP_X_FORWARDED_FOR'];
+               $ctx['forwarded_for'] = $_SERVER['HTTP_X_FORWARDED_FOR'];
        }
        if ( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) {
-               $forward .= ' client IP ' . $_SERVER['HTTP_CLIENT_IP'];
+               $ctx['client_ip'] = $_SERVER['HTTP_CLIENT_IP'];
        }
        if ( !empty( $_SERVER['HTTP_FROM'] ) ) {
-               $forward .= ' from ' . $_SERVER['HTTP_FROM'];
+               $ctx['from'] = $_SERVER['HTTP_FROM'];
        }
-       if ( $forward ) {
-               $forward = "\t(proxied via {$_SERVER['REMOTE_ADDR']}{$forward})";
+       if ( isset( $ctx['forwarded_for'] ) ||
+               isset( $ctx['client_ip'] ) ||
+               isset( $ctx['from'] ) ) {
+               $ctx['proxy'] = $_SERVER['REMOTE_ADDR'];
        }
+
        // Don't load $wgUser at this late stage just for statistics purposes
-       // @todo FIXME: We can detect some anons even if it is not loaded. See User::getId()
+       // @todo FIXME: We can detect some anons even if it is not loaded.
+       // See User::getId()
        if ( $wgUser->isItemLoaded( 'id' ) && $wgUser->isAnon() ) {
-               $forward .= ' anon';
+               $ctx['anon'] = true;
+       } else {
+               $ctx['anon'] = false;
        }
 
        // Command line script uses a FauxRequest object which does not have
        // any knowledge about an URL and throw an exception instead.
        try {
-               $requestUrl = $wgRequest->getRequestURL();
-       } catch ( MWException $e ) {
-               $requestUrl = 'n/a';
+               $ctx['url'] = urldecode( $wgRequest->getRequestURL() );
+       } catch ( MWException $ignored ) {
+               // no-op
        }
 
-       $log = sprintf( "%s\t%04.3f\t%s\n",
-               gmdate( 'YmdHis' ), $elapsed,
-               urldecode( $requestUrl . $forward ) );
+       $ctx['output'] = $profiler->getOutput();
+       $ctx['profile'] = $profiler->getRawData();
 
-       wfDebugLog( 'profileoutput', $log . $profiler->getOutput() );
+       $log = MWLogger::getInstance( 'profileoutput' );
+       $log->info( 'Elapsed: {elapsed}', $ctx );
 }
 
 /**

diff --git a/includes/debug/logger/legacy/Logger.php b/includes/debug/logger/legacy/Logger.php
index ff6336b..f994da3 100644 (file)
--- a/includes/debug/logger/legacy/Logger.php
+++ b/includes/debug/logger/legacy/Logger.php
@@ -134,24 +134,49 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
                global $wgDebugLogGroups;
 
                if ( $channel === 'wfDebug' ) {
-                       $text = self::formatWfDebug( $channel, $message, $context );
+                       $text = self::formatAsWfDebug( $channel, $message, $context );
 
                } elseif ( $channel === 'wfLogDBError' ) {
-                       $text = self::formatWfLogDBError( $channel, $message, $context );
+                       $text = self::formatAsWfLogDBError( $channel, $message, $context );
 
                } elseif ( $channel === 'wfErrorLog' ) {
                        $text = "{$message}\n";
 
+               } elseif ( $channel === 'profileoutput' ) {
+                       // Legacy wfLogProfilingData formatitng
+                       $forward = '';
+                       if ( isset( $context['forwarded_for'] )) {
+                               $forward = " forwarded for {$context['forwarded_for']}";
+                       }
+                       if ( isset( $context['client_ip'] ) ) {
+                               $forward .= " client IP {$context['client_ip']}";
+                       }
+                       if ( isset( $context['from'] ) ) {
+                               $forward .= " from {$context['from']}";
+                       }
+                       if ( $forward ) {
+                               $forward = "\t(proxied via {$context['proxy']}{$forward})";
+                       }
+                       if ( $context['anon'] ) {
+                               $forward .= ' anon';
+                       }
+                       if ( !isset( $context['url'] ) ) {
+                               $context['url'] = 'n/a';
+                       }
+
+                       $log = sprintf( "%s\t%04.3f\t%s%s\n",
+                               gmdate( 'YmdHis' ), $context['elapsed'], $context['url'], $forward );
+
+                       $text = self::formatAsWfDebugLog(
+                               $channel, $log . $context['output'], $context );
+
                } elseif ( !isset( $wgDebugLogGroups[$channel] ) ) {
-                       $text = self::formatWfDebug(
+                       $text = self::formatAsWfDebug(
                                $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";
+                       $text = self::formatAsWfDebugLog( $channel, $message, $context );
                }
                return $text;
        }
@@ -165,7 +190,7 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
         * @param array $context
         * @return string
         */
-       protected static function formatWfDebug( $channel, $message, $context ) {
+       protected static function formatAsWfDebug( $channel, $message, $context ) {
                $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message );
                if ( isset( $context['prefix'] ) ) {
                        $text = "{$context['prefix']}{$text}";
@@ -182,7 +207,7 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
         * @param array $context
         * @return string
         */
-       protected static function formatWfLogDBError( $channel, $message, $context ) {
+       protected static function formatAsWfLogDBError( $channel, $message, $context ) {
                global $wgDBerrorLogTZ;
                static $cachedTimezone = null;
 
@@ -207,6 +232,22 @@ class MWLoggerLegacyLogger extends \Psr\Log\AbstractLogger {
        }
 
 
+       /**
+        * Format a message as `wfDebugLog() would have formatted it.
+        *
+        * @param string $channel
+        * @param string $message
+        * @param array $context
+        */
+       protected static function formatAsWfDebugLog( $channel, $message, $context ) {
+               $time = wfTimestamp( TS_DB );
+               $wiki = wfWikiID();
+               $host = wfHostname();
+               $text = "{$time} {$host} {$wiki}: {$message}\n";
+               return $text;
+       }
+
+
        /**
         * Select the appropriate log output destination for the given log event.
         *