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