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