includes/debug/logger/LegacyLogger.php

   1 <?php
   2 /**
   3  * This program is free software; you can redistribute it and/or modify
   4  * it under the terms of the GNU General Public License as published by
   5  * the Free Software Foundation; either version 2 of the License, or
   6  * (at your option) any later version.
   7  *
   8  * This program is distributed in the hope that it will be useful,
   9  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  10  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  11  * GNU General Public License for more details.
  12  *
  13  * You should have received a copy of the GNU General Public License along
  14  * with this program; if not, write to the Free Software Foundation, Inc.,
  15  * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
  16  * http://www.gnu.org/copyleft/gpl.html
  17  *
  18  * @file
  19  */
  20
  21 namespace MediaWiki\Logger;
  22
  23 use DateTimeZone;
  24 use Exception;
  25 use WikiMap;
  26 use MWDebug;
  27 use MWExceptionHandler;
  28 use Psr\Log\AbstractLogger;
  29 use Psr\Log\LogLevel;
  30 use UDPTransport;
  31
  32 /**
  33  * PSR-3 logger that mimics the historic implementation of MediaWiki's former
  34  * wfErrorLog logging implementation.
  35  *
  36  * This logger is configured by the following global configuration variables:
  37  * - `$wgDebugLogFile`
  38  * - `$wgDebugLogGroups`
  39  * - `$wgDBerrorLog`
  40  * - `$wgDBerrorLogTZ`
  41  *
  42  * See documentation in DefaultSettings.php for detailed explanations of each
  43  * variable.
  44  *
  45  * @see \MediaWiki\Logger\LoggerFactory
  46  * @since 1.25
  47  * @copyright © 2014 Wikimedia Foundation and contributors
  48  */
  49 class LegacyLogger extends AbstractLogger {
  50
  51         /**
  52          * @var string $channel
  53          */
  54         protected $channel;
  55
  56         /**
  57          * Convert \Psr\Log\LogLevel constants into int for sane comparisons
  58          * These are the same values that Monlog uses
  59          *
  60          * @var array $levelMapping
  61          */
  62         protected static $levelMapping = [
  63                 LogLevel::DEBUG => 100,
  64                 LogLevel::INFO => 200,
  65                 LogLevel::NOTICE => 250,
  66                 LogLevel::WARNING => 300,
  67                 LogLevel::ERROR => 400,
  68                 LogLevel::CRITICAL => 500,
  69                 LogLevel::ALERT => 550,
  70                 LogLevel::EMERGENCY => 600,
  71         ];
  72
  73         /**
  74          * @var array
  75          */
  76         protected static $dbChannels = [
  77                 'DBQuery' => true,
  78                 'DBConnection' => true
  79         ];
  80
  81         /**
  82          * @param string $channel
  83          */
  84         public function __construct( $channel ) {
  85                 $this->channel = $channel;
  86         }
  87
  88         /**
  89          * Logs with an arbitrary level.
  90          *
  91          * @param string|int $level
  92          * @param string $message
  93          * @param array $context
  94          * @return null
  95          */
  96         public function log( $level, $message, array $context = [] ) {
  97                 global $wgDBerrorLog;
  98
  99                 if ( is_string( $level ) ) {
 100                         $level = self::$levelMapping[$level];
 101                 }
 102                 if ( $this->channel === 'DBQuery'
 103                         && isset( $context['method'] )
 104                         && isset( $context['master'] )
 105                         && isset( $context['runtime'] )
 106                 ) {
 107                         // Also give the query information to the MWDebug tools
 108                         $enabled = MWDebug::query(
 109                                 $message,
 110                                 $context['method'],
 111                                 $context['master'],
 112                                 $context['runtime']
 113                         );
 114                         if ( $enabled ) {
 115                                 // If we the toolbar was enabled, return early so that we don't
 116                                 // also log the query to the main debug output.
 117                                 return;
 118                         }
 119                 }
 120
 121                 // If this is a DB-related error, and the site has $wgDBerrorLog
 122                 // configured, rewrite the channel as wfLogDBError instead.
 123                 // Likewise, if the site does not use  $wgDBerrorLog, it should
 124                 // configurable like any other channel via $wgDebugLogGroups
 125                 // or $wgMWLoggerDefaultSpi.
 126                 if ( isset( self::$dbChannels[$this->channel] )
 127                         && $level >= self::$levelMapping[LogLevel::ERROR]
 128                         && $wgDBerrorLog
 129                 ) {
 130                         // Format and write DB errors to the legacy locations
 131                         $effectiveChannel = 'wfLogDBError';
 132                 } else {
 133                         $effectiveChannel = $this->channel;
 134                 }
 135
 136                 if ( self::shouldEmit( $effectiveChannel, $message, $level, $context ) ) {
 137                         $text = self::format( $effectiveChannel, $message, $context );
 138                         $destination = self::destination( $effectiveChannel, $message, $context );
 139                         self::emit( $text, $destination );
 140                 }
 141                 if ( !isset( $context['private'] ) || !$context['private'] ) {
 142                         // Add to debug toolbar if not marked as "private"
 143                         MWDebug::debugMsg( $message, [ 'channel' => $this->channel ] + $context );
 144                 }
 145         }
 146
 147         /**
 148          * Determine if the given message should be emitted or not.
 149          *
 150          * @param string $channel
 151          * @param string $message
 152          * @param string|int $level \Psr\Log\LogEvent constant or Monolog level int
 153          * @param array $context
 154          * @return bool True if message should be sent to disk/network, false
 155          * otherwise
 156          */
 157         public static function shouldEmit( $channel, $message, $level, $context ) {
 158                 global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups;
 159
 160                 if ( is_string( $level ) ) {
 161                         $level = self::$levelMapping[$level];
 162                 }
 163
 164                 if ( $channel === 'wfLogDBError' ) {
 165                         // wfLogDBError messages are emitted if a database log location is
 166                         // specfied.
 167                         $shouldEmit = (bool)$wgDBerrorLog;
 168
 169                 } elseif ( $channel === 'wfDebug' ) {
 170                         // wfDebug messages are emitted if a catch all logging file has
 171                         // been specified. Checked explicitly so that 'private' flagged
 172                         // messages are not discarded by unset $wgDebugLogGroups channel
 173                         // handling below.
 174                         $shouldEmit = $wgDebugLogFile != '';
 175
 176                 } elseif ( isset( $wgDebugLogGroups[$channel] ) ) {
 177                         $logConfig = $wgDebugLogGroups[$channel];
 178
 179                         if ( is_array( $logConfig ) ) {
 180                                 $shouldEmit = true;
 181                                 if ( isset( $logConfig['sample'] ) ) {
 182                                         // Emit randomly with a 1 in 'sample' chance for each message.
 183                                         $shouldEmit = mt_rand( 1, $logConfig['sample'] ) === 1;
 184                                 }
 185
 186                                 if ( isset( $logConfig['level'] ) ) {
 187                                         $shouldEmit = $level >= self::$levelMapping[$logConfig['level']];
 188                                 }
 189                         } else {
 190                                 // Emit unless the config value is explictly false.
 191                                 $shouldEmit = $logConfig !== false;
 192                         }
 193
 194                 } elseif ( isset( $context['private'] ) && $context['private'] ) {
 195                         // Don't emit if the message didn't match previous checks based on
 196                         // the channel and the event is marked as private. This check
 197                         // discards messages sent via wfDebugLog() with dest == 'private'
 198                         // and no explicit wgDebugLogGroups configuration.
 199                         $shouldEmit = false;
 200                 } else {
 201                         // Default return value is the same as the historic wfDebug
 202                         // method: emit if $wgDebugLogFile has been set.
 203                         $shouldEmit = $wgDebugLogFile != '';
 204                 }
 205
 206                 return $shouldEmit;
 207         }
 208
 209         /**
 210          * Format a message.
 211          *
 212          * Messages to the 'wfDebug' and 'wfLogDBError' channels receive special formatting to mimic the
 213          * historic output of the functions of the same name. All other channel values are formatted
 214          * based on the historic output of the `wfDebugLog()` global function.
 215          *
 216          * @param string $channel
 217          * @param string $message
 218          * @param array $context
 219          * @return string
 220          */
 221         public static function format( $channel, $message, $context ) {
 222                 global $wgDebugLogGroups, $wgLogExceptionBacktrace;
 223
 224                 if ( $channel === 'wfDebug' ) {
 225                         $text = self::formatAsWfDebug( $channel, $message, $context );
 226
 227                 } elseif ( $channel === 'wfLogDBError' ) {
 228                         $text = self::formatAsWfLogDBError( $channel, $message, $context );
 229
 230                 } elseif ( $channel === 'profileoutput' ) {
 231                         // Legacy wfLogProfilingData formatitng
 232                         $forward = '';
 233                         if ( isset( $context['forwarded_for'] ) ) {
 234                                 $forward = " forwarded for {$context['forwarded_for']}";
 235                         }
 236                         if ( isset( $context['client_ip'] ) ) {
 237                                 $forward .= " client IP {$context['client_ip']}";
 238                         }
 239                         if ( isset( $context['from'] ) ) {
 240                                 $forward .= " from {$context['from']}";
 241                         }
 242                         if ( $forward ) {
 243                                 $forward = "\t(proxied via {$context['proxy']}{$forward})";
 244                         }
 245                         if ( $context['anon'] ) {
 246                                 $forward .= ' anon';
 247                         }
 248                         if ( !isset( $context['url'] ) ) {
 249                                 $context['url'] = 'n/a';
 250                         }
 251
 252                         $log = sprintf( "%s\t%04.3f\t%s%s\n",
 253                                 gmdate( 'YmdHis' ), $context['elapsed'], $context['url'], $forward );
 254
 255                         $text = self::formatAsWfDebugLog(
 256                                 $channel, $log . $context['output'], $context );
 257
 258                 } elseif ( !isset( $wgDebugLogGroups[$channel] ) ) {
 259                         $text = self::formatAsWfDebug(
 260                                 $channel, "[{$channel}] {$message}", $context );
 261
 262                 } else {
 263                         // Default formatting is wfDebugLog's historic style
 264                         $text = self::formatAsWfDebugLog( $channel, $message, $context );
 265                 }
 266
 267                 // Append stacktrace of exception if available
 268                 if ( $wgLogExceptionBacktrace && isset( $context['exception'] ) ) {
 269                         $e = $context['exception'];
 270                         $backtrace = false;
 271
 272                         if ( $e instanceof Exception ) {
 273                                 $backtrace = MWExceptionHandler::getRedactedTrace( $e );
 274
 275                         } elseif ( is_array( $e ) && isset( $e['trace'] ) ) {
 276                                 // Exception has already been unpacked as structured data
 277                                 $backtrace = $e['trace'];
 278                         }
 279
 280                         if ( $backtrace ) {
 281                                 $text .= MWExceptionHandler::prettyPrintTrace( $backtrace ) .
 282                                         "\n";
 283                         }
 284                 }
 285
 286                 return self::interpolate( $text, $context );
 287         }
 288
 289         /**
 290          * Format a message as `wfDebug()` would have formatted it.
 291          *
 292          * @param string $channel
 293          * @param string $message
 294          * @param array $context
 295          * @return string
 296          */
 297         protected static function formatAsWfDebug( $channel, $message, $context ) {
 298                 $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message );
 299                 if ( isset( $context['seconds_elapsed'] ) ) {
 300                         // Prepend elapsed request time and real memory usage with two
 301                         // trailing spaces.
 302                         $text = "{$context['seconds_elapsed']} {$context['memory_used']}  {$text}";
 303                 }
 304                 if ( isset( $context['prefix'] ) ) {
 305                         $text = "{$context['prefix']}{$text}";
 306                 }
 307                 return "{$text}\n";
 308         }
 309
 310         /**
 311          * Format a message as `wfLogDBError()` would have formatted it.
 312          *
 313          * @param string $channel
 314          * @param string $message
 315          * @param array $context
 316          * @return string
 317          */
 318         protected static function formatAsWfLogDBError( $channel, $message, $context ) {
 319                 global $wgDBerrorLogTZ;
 320                 static $cachedTimezone = null;
 321
 322                 if ( !$cachedTimezone ) {
 323                         $cachedTimezone = new DateTimeZone( $wgDBerrorLogTZ );
 324                 }
 325
 326                 $d = date_create( 'now', $cachedTimezone );
 327                 $date = $d->format( 'D M j G:i:s T Y' );
 328
 329                 $host = wfHostname();
 330                 $wiki = WikiMap::getWikiIdFromDomain( WikiMap::getCurrentWikiDomain() );
 331
 332                 $text = "{$date}\t{$host}\t{$wiki}\t{$message}\n";
 333                 return $text;
 334         }
 335
 336         /**
 337          * Format a message as `wfDebugLog() would have formatted it.
 338          *
 339          * @param string $channel
 340          * @param string $message
 341          * @param array $context
 342          * @return string
 343          */
 344         protected static function formatAsWfDebugLog( $channel, $message, $context ) {
 345                 $time = wfTimestamp( TS_DB );
 346                 $wiki = WikiMap::getWikiIdFromDomain( WikiMap::getCurrentWikiDomain() );
 347                 $host = wfHostname();
 348                 $text = "{$time} {$host} {$wiki}: {$message}\n";
 349                 return $text;
 350         }
 351
 352         /**
 353          * Interpolate placeholders in logging message.
 354          *
 355          * @param string $message
 356          * @param array $context
 357          * @return string Interpolated message
 358          */
 359         public static function interpolate( $message, array $context ) {
 360                 if ( strpos( $message, '{' ) !== false ) {
 361                         $replace = [];
 362                         foreach ( $context as $key => $val ) {
 363                                 $replace['{' . $key . '}'] = self::flatten( $val );
 364                         }
 365                         $message = strtr( $message, $replace );
 366                 }
 367                 return $message;
 368         }
 369
 370         /**
 371          * Convert a logging context element to a string suitable for
 372          * interpolation.
 373          *
 374          * @param mixed $item
 375          * @return string
 376          */
 377         protected static function flatten( $item ) {
 378                 if ( $item === null ) {
 379                         return '[Null]';
 380                 }
 381
 382                 if ( is_bool( $item ) ) {
 383                         return $item ? 'true' : 'false';
 384                 }
 385
 386                 if ( is_float( $item ) ) {
 387                         if ( is_infinite( $item ) ) {
 388                                 return ( $item > 0 ? '' : '-' ) . 'INF';
 389                         }
 390                         if ( is_nan( $item ) ) {
 391                                 return 'NaN';
 392                         }
 393                         return (string)$item;
 394                 }
 395
 396                 if ( is_scalar( $item ) ) {
 397                         return (string)$item;
 398                 }
 399
 400                 if ( is_array( $item ) ) {
 401                         return '[Array(' . count( $item ) . ')]';
 402                 }
 403
 404                 if ( $item instanceof \DateTime ) {
 405                         return $item->format( 'c' );
 406                 }
 407
 408                 if ( $item instanceof Exception ) {
 409                         return '[Exception ' . get_class( $item ) . '( ' .
 410                                 $item->getFile() . ':' . $item->getLine() . ') ' .
 411                                 $item->getMessage() . ']';
 412                 }
 413
 414                 if ( is_object( $item ) ) {
 415                         if ( method_exists( $item, '__toString' ) ) {
 416                                 return (string)$item;
 417                         }
 418
 419                         return '[Object ' . get_class( $item ) . ']';
 420                 }
 421
 422                 if ( is_resource( $item ) ) {
 423                         return '[Resource ' . get_resource_type( $item ) . ']';
 424                 }
 425
 426                 return '[Unknown ' . gettype( $item ) . ']';
 427         }
 428
 429         /**
 430          * Select the appropriate log output destination for the given log event.
 431          *
 432          * If the event context contains 'destination'
 433          *
 434          * @param string $channel
 435          * @param string $message
 436          * @param array $context
 437          * @return string
 438          */
 439         protected static function destination( $channel, $message, $context ) {
 440                 global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups;
 441
 442                 // Default destination is the debug log file as historically used by
 443                 // the wfDebug function.
 444                 $destination = $wgDebugLogFile;
 445
 446                 if ( isset( $context['destination'] ) ) {
 447                         // Use destination explicitly provided in context
 448                         $destination = $context['destination'];
 449
 450                 } elseif ( $channel === 'wfDebug' ) {
 451                         $destination = $wgDebugLogFile;
 452
 453                 } elseif ( $channel === 'wfLogDBError' ) {
 454                         $destination = $wgDBerrorLog;
 455
 456                 } elseif ( isset( $wgDebugLogGroups[$channel] ) ) {
 457                         $logConfig = $wgDebugLogGroups[$channel];
 458
 459                         if ( is_array( $logConfig ) ) {
 460                                 $destination = $logConfig['destination'];
 461                         } else {
 462                                 $destination = strval( $logConfig );
 463                         }
 464                 }
 465
 466                 return $destination;
 467         }
 468
 469         /**
 470          * Log to a file without getting "file size exceeded" signals.
 471          *
 472          * Can also log to UDP with the syntax udp://host:port/prefix. This will send
 473          * lines to the specified port, prefixed by the specified prefix and a space.
 474          *
 475          * @param string $text
 476          * @param string $file Filename
 477          */
 478         public static function emit( $text, $file ) {
 479                 if ( substr( $file, 0, 4 ) == 'udp:' ) {
 480                         $transport = UDPTransport::newFromString( $file );
 481                         $transport->emit( $text );
 482                 } else {
 483                         \Wikimedia\suppressWarnings();
 484                         $exists = file_exists( $file );
 485                         $size = $exists ? filesize( $file ) : false;
 486                         if ( !$exists ||
 487                                 ( $size !== false && $size + strlen( $text ) < 0x7fffffff )
 488                         ) {
 489                                 file_put_contents( $file, $text, FILE_APPEND );
 490                         }
 491                         \Wikimedia\restoreWarnings();
 492                 }
 493         }
 494
 495 }