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