includes/debug/MWDebug.php

   1 <?php
   2 /**
   3  * Debug toolbar related code.
   4  *
   5  * This program is free software; you can redistribute it and/or modify
   6  * it under the terms of the GNU General Public License as published by
   7  * the Free Software Foundation; either version 2 of the License, or
   8  * (at your option) any later version.
   9  *
  10  * This program is distributed in the hope that it will be useful,
  11  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  12  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  13  * GNU General Public License for more details.
  14  *
  15  * You should have received a copy of the GNU General Public License along
  16  * with this program; if not, write to the Free Software Foundation, Inc.,
  17  * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
  18  * http://www.gnu.org/copyleft/gpl.html
  19  *
  20  * @file
  21  */
  22
  23 /**
  24  * New debugger system that outputs a toolbar on page view.
  25  *
  26  * By default, most methods do nothing ( self::$enabled = false ). You have
  27  * to explicitly call MWDebug::init() to enabled them.
  28  *
  29  * @since 1.19
  30  */
  31 class MWDebug {
  32         /**
  33          * Log lines
  34          *
  35          * @var array $log
  36          */
  37         protected static $log = array();
  38
  39         /**
  40          * Debug messages from wfDebug().
  41          *
  42          * @var array $debug
  43          */
  44         protected static $debug = array();
  45
  46         /**
  47          * SQL statements of the database queries.
  48          *
  49          * @var array $query
  50          */
  51         protected static $query = array();
  52
  53         /**
  54          * Is the debugger enabled?
  55          *
  56          * @var bool $enabled
  57          */
  58         protected static $enabled = false;
  59
  60         /**
  61          * Array of functions that have already been warned, formatted
  62          * function-caller to prevent a buttload of warnings
  63          *
  64          * @var array $deprecationWarnings
  65          */
  66         protected static $deprecationWarnings = array();
  67
  68         /**
  69          * Enabled the debugger and load resource module.
  70          * This is called by Setup.php when $wgDebugToolbar is true.
  71          *
  72          * @since 1.19
  73          */
  74         public static function init() {
  75                 self::$enabled = true;
  76         }
  77
  78         /**
  79          * Add ResourceLoader modules to the OutputPage object if debugging is
  80          * enabled.
  81          *
  82          * @since 1.19
  83          * @param OutputPage $out
  84          */
  85         public static function addModules( OutputPage $out ) {
  86                 if ( self::$enabled ) {
  87                         $out->addModules( 'mediawiki.debug.init' );
  88                 }
  89         }
  90
  91         /**
  92          * Adds a line to the log
  93          *
  94          * @todo Add support for passing objects
  95          *
  96          * @since 1.19
  97          * @param string $str
  98          */
  99         public static function log( $str ) {
 100                 if ( !self::$enabled ) {
 101                         return;
 102                 }
 103
 104                 self::$log[] = array(
 105                         'msg' => htmlspecialchars( $str ),
 106                         'type' => 'log',
 107                         'caller' => wfGetCaller(),
 108                 );
 109         }
 110
 111         /**
 112          * Returns internal log array
 113          * @since 1.19
 114          * @return array
 115          */
 116         public static function getLog() {
 117                 return self::$log;
 118         }
 119
 120         /**
 121          * Clears internal log array and deprecation tracking
 122          * @since 1.19
 123          */
 124         public static function clearLog() {
 125                 self::$log = array();
 126                 self::$deprecationWarnings = array();
 127         }
 128
 129         /**
 130          * Adds a warning entry to the log
 131          *
 132          * @since 1.19
 133          * @param string $msg
 134          * @param int $callerOffset
 135          * @param int $level A PHP error level. See sendMessage()
 136          * @param string $log 'production' will always trigger a php error, 'auto'
 137          *    will trigger an error if $wgDevelopmentWarnings is true, and 'debug'
 138          *    will only write to the debug log(s).
 139          *
 140          * @return mixed
 141          */
 142         public static function warning( $msg, $callerOffset = 1, $level = E_USER_NOTICE, $log = 'auto' ) {
 143                 global $wgDevelopmentWarnings;
 144
 145                 if ( $log === 'auto' && !$wgDevelopmentWarnings ) {
 146                         $log = 'debug';
 147                 }
 148
 149                 if ( $log === 'debug' ) {
 150                         $level = false;
 151                 }
 152
 153                 $callerDescription = self::getCallerDescription( $callerOffset );
 154
 155                 self::sendMessage( $msg, $callerDescription, 'warning', $level );
 156
 157                 if ( self::$enabled ) {
 158                         self::$log[] = array(
 159                                 'msg' => htmlspecialchars( $msg ),
 160                                 'type' => 'warn',
 161                                 'caller' => $callerDescription['func'],
 162                         );
 163                 }
 164         }
 165
 166         /**
 167          * Show a warning that $function is deprecated.
 168          * This will send it to the following locations:
 169          * - Debug toolbar, with one item per function and caller, if $wgDebugToolbar
 170          *   is set to true.
 171          * - PHP's error log, with level E_USER_DEPRECATED, if $wgDevelopmentWarnings
 172          *   is set to true.
 173          * - MediaWiki's debug log, if $wgDevelopmentWarnings is set to false.
 174          *
 175          * @since 1.19
 176          * @param string $function Function that is deprecated.
 177          * @param string|bool $version Version in which the function was deprecated.
 178          * @param string|bool $component Component to which the function belongs.
 179          *    If false, it is assumbed the function is in MediaWiki core.
 180          * @param int $callerOffset How far up the callstack is the original
 181          *    caller. 2 = function that called the function that called
 182          *    MWDebug::deprecated() (Added in 1.20).
 183          */
 184         public static function deprecated( $function, $version = false,
 185                 $component = false, $callerOffset = 2
 186         ) {
 187                 $callerDescription = self::getCallerDescription( $callerOffset );
 188                 $callerFunc = $callerDescription['func'];
 189
 190                 $sendToLog = true;
 191
 192                 // Check to see if there already was a warning about this function
 193                 if ( isset( self::$deprecationWarnings[$function][$callerFunc] ) ) {
 194                         return;
 195                 } elseif ( isset( self::$deprecationWarnings[$function] ) ) {
 196                         if ( self::$enabled ) {
 197                                 $sendToLog = false;
 198                         } else {
 199                                 return;
 200                         }
 201                 }
 202
 203                 self::$deprecationWarnings[$function][$callerFunc] = true;
 204
 205                 if ( $version ) {
 206                         global $wgDeprecationReleaseLimit;
 207                         if ( $wgDeprecationReleaseLimit && $component === false ) {
 208                                 # Strip -* off the end of $version so that branches can use the
 209                                 # format #.##-branchname to avoid issues if the branch is merged into
 210                                 # a version of MediaWiki later than what it was branched from
 211                                 $comparableVersion = preg_replace( '/-.*$/', '', $version );
 212
 213                                 # If the comparableVersion is larger than our release limit then
 214                                 # skip the warning message for the deprecation
 215                                 if ( version_compare( $wgDeprecationReleaseLimit, $comparableVersion, '<' ) ) {
 216                                         $sendToLog = false;
 217                                 }
 218                         }
 219
 220                         $component = $component === false ? 'MediaWiki' : $component;
 221                         $msg = "Use of $function was deprecated in $component $version.";
 222                 } else {
 223                         $msg = "Use of $function is deprecated.";
 224                 }
 225
 226                 if ( $sendToLog ) {
 227                         global $wgDevelopmentWarnings; // we could have a more specific $wgDeprecationWarnings setting.
 228                         self::sendMessage(
 229                                 $msg,
 230                                 $callerDescription,
 231                                 'deprecated',
 232                                 $wgDevelopmentWarnings ? E_USER_DEPRECATED : false
 233                         );
 234                 }
 235
 236                 if ( self::$enabled ) {
 237                         $logMsg = htmlspecialchars( $msg ) .
 238                                 Html::rawElement( 'div', array( 'class' => 'mw-debug-backtrace' ),
 239                                         Html::element( 'span', array(), 'Backtrace:' ) . wfBacktrace()
 240                                 );
 241
 242                         self::$log[] = array(
 243                                 'msg' => $logMsg,
 244                                 'type' => 'deprecated',
 245                                 'caller' => $callerFunc,
 246                         );
 247                 }
 248         }
 249
 250         /**
 251          * Get an array describing the calling function at a specified offset.
 252          *
 253          * @param int $callerOffset How far up the callstack is the original
 254          *    caller. 0 = function that called getCallerDescription()
 255          * @return array Array with two keys: 'file' and 'func'
 256          */
 257         private static function getCallerDescription( $callerOffset ) {
 258                 $callers = wfDebugBacktrace();
 259
 260                 if ( isset( $callers[$callerOffset] ) ) {
 261                         $callerfile = $callers[$callerOffset];
 262                         if ( isset( $callerfile['file'] ) && isset( $callerfile['line'] ) ) {
 263                                 $file = $callerfile['file'] . ' at line ' . $callerfile['line'];
 264                         } else {
 265                                 $file = '(internal function)';
 266                         }
 267                 } else {
 268                         $file = '(unknown location)';
 269                 }
 270
 271                 if ( isset( $callers[$callerOffset + 1] ) ) {
 272                         $callerfunc = $callers[$callerOffset + 1];
 273                         $func = '';
 274                         if ( isset( $callerfunc['class'] ) ) {
 275                                 $func .= $callerfunc['class'] . '::';
 276                         }
 277                         if ( isset( $callerfunc['function'] ) ) {
 278                                 $func .= $callerfunc['function'];
 279                         }
 280                 } else {
 281                         $func = 'unknown';
 282                 }
 283
 284                 return array( 'file' => $file, 'func' => $func );
 285         }
 286
 287         /**
 288          * Send a message to the debug log and optionally also trigger a PHP
 289          * error, depending on the $level argument.
 290          *
 291          * @param string $msg Message to send
 292          * @param array $caller Caller description get from getCallerDescription()
 293          * @param string $group Log group on which to send the message
 294          * @param int|bool $level Error level to use; set to false to not trigger an error
 295          */
 296         private static function sendMessage( $msg, $caller, $group, $level ) {
 297                 $msg .= ' [Called from ' . $caller['func'] . ' in ' . $caller['file'] . ']';
 298
 299                 if ( $level !== false ) {
 300                         trigger_error( $msg, $level );
 301                 }
 302
 303                 wfDebugLog( $group, $msg, 'log' );
 304         }
 305
 306         /**
 307          * This is a method to pass messages from wfDebug to the pretty debugger.
 308          * Do NOT use this method, use MWDebug::log or wfDebug()
 309          *
 310          * @since 1.19
 311          * @param string $str
 312          * @param array $context
 313          */
 314         public static function debugMsg( $str, $context = array() ) {
 315                 global $wgDebugComments, $wgShowDebug;
 316
 317                 if ( self::$enabled || $wgDebugComments || $wgShowDebug ) {
 318                         if ( $context ) {
 319                                 $prefix = '';
 320                                 if ( isset( $context['prefix'] ) ) {
 321                                         $prefix = $context['prefix'];
 322                                 } elseif ( isset( $context['channel'] ) && $context['channel'] !== 'wfDebug' ) {
 323                                         $prefix = "[{$context['channel']}] ";
 324                                 }
 325                                 if ( isset( $context['seconds_elapsed'] ) && isset( $context['memory_used'] ) ) {
 326                                         $prefix .= "{$context['seconds_elapsed']} {$context['memory_used']}  ";
 327                                 }
 328                                 $str = $prefix . $str;
 329                         }
 330                         self::$debug[] = rtrim( UtfNormal\Validator::cleanUp( $str ) );
 331                 }
 332         }
 333
 334         /**
 335          * Begins profiling on a database query
 336          *
 337          * @since 1.19
 338          * @param string $sql
 339          * @param string $function
 340          * @param bool $isMaster
 341          * @return int ID number of the query to pass to queryTime or -1 if the
 342          *  debugger is disabled
 343          */
 344         public static function query( $sql, $function, $isMaster ) {
 345                 if ( !self::$enabled ) {
 346                         return -1;
 347                 }
 348
 349                 // Replace invalid UTF-8 chars with a square UTF-8 character
 350                 // This prevents json_encode from erroring out due to binary SQL data
 351                 $sql = preg_replace(
 352                         '/(
 353                                 [\xC0-\xC1] # Invalid UTF-8 Bytes
 354                                 | [\xF5-\xFF] # Invalid UTF-8 Bytes
 355                                 | \xE0[\x80-\x9F] # Overlong encoding of prior code point
 356                                 | \xF0[\x80-\x8F] # Overlong encoding of prior code point
 357                                 | [\xC2-\xDF](?![\x80-\xBF]) # Invalid UTF-8 Sequence Start
 358                                 | [\xE0-\xEF](?![\x80-\xBF]{2}) # Invalid UTF-8 Sequence Start
 359                                 | [\xF0-\xF4](?![\x80-\xBF]{3}) # Invalid UTF-8 Sequence Start
 360                                 | (?<=[\x0-\x7F\xF5-\xFF])[\x80-\xBF] # Invalid UTF-8 Sequence Middle
 361                                 | (?<![\xC2-\xDF]|[\xE0-\xEF]|[\xE0-\xEF][\x80-\xBF]|[\xF0-\xF4]
 362                                    |[\xF0-\xF4][\x80-\xBF]|[\xF0-\xF4][\x80-\xBF]{2})[\x80-\xBF] # Overlong Sequence
 363                                 | (?<=[\xE0-\xEF])[\x80-\xBF](?![\x80-\xBF]) # Short 3 byte sequence
 364                                 | (?<=[\xF0-\xF4])[\x80-\xBF](?![\x80-\xBF]{2}) # Short 4 byte sequence
 365                                 | (?<=[\xF0-\xF4][\x80-\xBF])[\x80-\xBF](?![\x80-\xBF]) # Short 4 byte sequence (2)
 366                         )/x',
 367                         '■',
 368                         $sql
 369                 );
 370
 371                 self::$query[] = array(
 372                         'sql' => $sql,
 373                         'function' => $function,
 374                         'master' => (bool)$isMaster,
 375                         'time' => 0.0,
 376                         '_start' => microtime( true ),
 377                 );
 378
 379                 return count( self::$query ) - 1;
 380         }
 381
 382         /**
 383          * Calculates how long a query took.
 384          *
 385          * @since 1.19
 386          * @param int $id
 387          */
 388         public static function queryTime( $id ) {
 389                 if ( $id === -1 || !self::$enabled ) {
 390                         return;
 391                 }
 392
 393                 self::$query[$id]['time'] = microtime( true ) - self::$query[$id]['_start'];
 394                 unset( self::$query[$id]['_start'] );
 395         }
 396
 397         /**
 398          * Returns a list of files included, along with their size
 399          *
 400          * @param IContextSource $context
 401          * @return array
 402          */
 403         protected static function getFilesIncluded( IContextSource $context ) {
 404                 $files = get_included_files();
 405                 $fileList = array();
 406                 foreach ( $files as $file ) {
 407                         $size = filesize( $file );
 408                         $fileList[] = array(
 409                                 'name' => $file,
 410                                 'size' => $context->getLanguage()->formatSize( $size ),
 411                         );
 412                 }
 413
 414                 return $fileList;
 415         }
 416
 417         /**
 418          * Returns the HTML to add to the page for the toolbar
 419          *
 420          * @since 1.19
 421          * @param IContextSource $context
 422          * @return string
 423          */
 424         public static function getDebugHTML( IContextSource $context ) {
 425                 global $wgDebugComments;
 426
 427                 $html = '';
 428
 429                 if ( self::$enabled ) {
 430                         MWDebug::log( 'MWDebug output complete' );
 431                         $debugInfo = self::getDebugInfo( $context );
 432
 433                         // Cannot use OutputPage::addJsConfigVars because those are already outputted
 434                         // by the time this method is called.
 435                         $html = ResourceLoader::makeInlineScript(
 436                                 ResourceLoader::makeConfigSetScript( array( 'debugInfo' => $debugInfo ) )
 437                         );
 438                 }
 439
 440                 if ( $wgDebugComments ) {
 441                         $html .= "<!-- Debug output:\n" .
 442                                 htmlspecialchars( implode( "\n", self::$debug ) ) .
 443                                 "\n\n-->";
 444                 }
 445
 446                 return $html;
 447         }
 448
 449         /**
 450          * Generate debug log in HTML for displaying at the bottom of the main
 451          * content area.
 452          * If $wgShowDebug is false, an empty string is always returned.
 453          *
 454          * @since 1.20
 455          * @return string HTML fragment
 456          */
 457         public static function getHTMLDebugLog() {
 458                 global $wgDebugTimestamps, $wgShowDebug;
 459
 460                 if ( !$wgShowDebug ) {
 461                         return '';
 462                 }
 463
 464                 $curIdent = 0;
 465                 $ret = "\n<hr />\n<strong>Debug data:</strong><ul id=\"mw-debug-html\">\n<li>";
 466
 467                 foreach ( self::$debug as $line ) {
 468                         $pre = '';
 469                         if ( $wgDebugTimestamps ) {
 470                                 $matches = array();
 471                                 if ( preg_match( '/^(\d+\.\d+ {1,3}\d+.\dM\s{2})/', $line, $matches ) ) {
 472                                         $pre = $matches[1];
 473                                         $line = substr( $line, strlen( $pre ) );
 474                                 }
 475                         }
 476                         $display = ltrim( $line );
 477                         $ident = strlen( $line ) - strlen( $display );
 478                         $diff = $ident - $curIdent;
 479
 480                         $display = $pre . $display;
 481                         if ( $display == '' ) {
 482                                 $display = "\xc2\xa0";
 483                         }
 484
 485                         if ( !$ident
 486                                 && $diff < 0
 487                                 && substr( $display, 0, 9 ) != 'Entering '
 488                                 && substr( $display, 0, 8 ) != 'Exiting '
 489                         ) {
 490                                 $ident = $curIdent;
 491                                 $diff = 0;
 492                                 $display = '<span style="background:yellow;">' .
 493                                         nl2br( htmlspecialchars( $display ) ) . '</span>';
 494                         } else {
 495                                 $display = nl2br( htmlspecialchars( $display ) );
 496                         }
 497
 498                         if ( $diff < 0 ) {
 499                                 $ret .= str_repeat( "</li></ul>\n", -$diff ) . "</li><li>\n";
 500                         } elseif ( $diff == 0 ) {
 501                                 $ret .= "</li><li>\n";
 502                         } else {
 503                                 $ret .= str_repeat( "<ul><li>\n", $diff );
 504                         }
 505                         $ret .= "<code>$display</code>\n";
 506
 507                         $curIdent = $ident;
 508                 }
 509
 510                 $ret .= str_repeat( '</li></ul>', $curIdent ) . "</li>\n</ul>\n";
 511
 512                 return $ret;
 513         }
 514
 515         /**
 516          * Append the debug info to given ApiResult
 517          *
 518          * @param IContextSource $context
 519          * @param ApiResult $result
 520          */
 521         public static function appendDebugInfoToApiResult( IContextSource $context, ApiResult $result ) {
 522                 if ( !self::$enabled ) {
 523                         return;
 524                 }
 525
 526                 // output errors as debug info, when display_errors is on
 527                 // this is necessary for all non html output of the api, because that clears all errors first
 528                 $obContents = ob_get_contents();
 529                 if ( $obContents ) {
 530                         $obContentArray = explode( '<br />', $obContents );
 531                         foreach ( $obContentArray as $obContent ) {
 532                                 if ( trim( $obContent ) ) {
 533                                         self::debugMsg( Sanitizer::stripAllTags( $obContent ) );
 534                                 }
 535                         }
 536                 }
 537
 538                 MWDebug::log( 'MWDebug output complete' );
 539                 $debugInfo = self::getDebugInfo( $context );
 540
 541                 ApiResult::setIndexedTagName( $debugInfo, 'debuginfo' );
 542                 ApiResult::setIndexedTagName( $debugInfo['log'], 'line' );
 543                 ApiResult::setIndexedTagName( $debugInfo['debugLog'], 'msg' );
 544                 ApiResult::setIndexedTagName( $debugInfo['queries'], 'query' );
 545                 ApiResult::setIndexedTagName( $debugInfo['includes'], 'queries' );
 546                 $result->addValue( null, 'debuginfo', $debugInfo );
 547         }
 548
 549         /**
 550          * Returns the HTML to add to the page for the toolbar
 551          *
 552          * @param IContextSource $context
 553          * @return array
 554          */
 555         public static function getDebugInfo( IContextSource $context ) {
 556                 if ( !self::$enabled ) {
 557                         return array();
 558                 }
 559
 560                 global $wgVersion, $wgRequestTime;
 561                 $request = $context->getRequest();
 562
 563                 // HHVM's reported memory usage from memory_get_peak_usage()
 564                 // is not useful when passing false, but we continue passing
 565                 // false for consistency of historical data in zend.
 566                 // see: https://github.com/facebook/hhvm/issues/2257#issuecomment-39362246
 567                 $realMemoryUsage = wfIsHHVM();
 568
 569                 return array(
 570                         'mwVersion' => $wgVersion,
 571                         'phpEngine' => wfIsHHVM() ? 'HHVM' : 'PHP',
 572                         'phpVersion' => wfIsHHVM() ? HHVM_VERSION : PHP_VERSION,
 573                         'gitRevision' => GitInfo::headSHA1(),
 574                         'gitBranch' => GitInfo::currentBranch(),
 575                         'gitViewUrl' => GitInfo::headViewUrl(),
 576                         'time' => microtime( true ) - $wgRequestTime,
 577                         'log' => self::$log,
 578                         'debugLog' => self::$debug,
 579                         'queries' => self::$query,
 580                         'request' => array(
 581                                 'method' => $request->getMethod(),
 582                                 'url' => $request->getRequestURL(),
 583                                 'headers' => $request->getAllHeaders(),
 584                                 'params' => $request->getValues(),
 585                         ),
 586                         'memory' => $context->getLanguage()->formatSize( memory_get_usage( $realMemoryUsage ) ),
 587                         'memoryPeak' => $context->getLanguage()->formatSize( memory_get_peak_usage( $realMemoryUsage ) ),
 588                         'includes' => self::getFilesIncluded( $context ),
 589                 );
 590         }
 591 }