LegacyLogger.php

Go to the documentation of this file.

<?php
namespace MediaWiki\Logger;
 
use DateTimeZone;
use Error;
use LogicException;
use MediaWiki\Debug\MWDebug;
use MediaWiki\Exception\MWExceptionHandler;
use MediaWiki\WikiMap\WikiMap;
use Monolog\LogRecord;
use Psr\Log\AbstractLogger;
use Psr\Log\LogLevel;
use Throwable;
use Wikimedia\Timestamp\ConvertibleTimestamp;
use Wikimedia\Timestamp\TimestampFormat as TS;
use Wikimedia\UDPTransport;
 
class LegacyLogger extends AbstractLogger {
 
    protected $channel;
 
    private const LEVEL_DEBUG = 100;
    private const LEVEL_INFO = 200;
    private const LEVEL_NOTICE = 250;
    private const LEVEL_WARNING = 300;
    private const LEVEL_ERROR = 400;
    private const LEVEL_CRITICAL = 500;
    private const LEVEL_ALERT = 550;
    private const LEVEL_EMERGENCY = 600;
    private const LEVEL_INFINITY = 999;
 
    protected static $levelMapping = [
        LogLevel::DEBUG => self::LEVEL_DEBUG,
        LogLevel::INFO => self::LEVEL_INFO,
        LogLevel::NOTICE => self::LEVEL_NOTICE,
        LogLevel::WARNING => self::LEVEL_WARNING,
        LogLevel::ERROR => self::LEVEL_ERROR,
        LogLevel::CRITICAL => self::LEVEL_CRITICAL,
        LogLevel::ALERT => self::LEVEL_ALERT,
        LogLevel::EMERGENCY => self::LEVEL_EMERGENCY,
    ];
 
    private $minimumLevel;
 
    private $isDB;
 
    public function __construct( $channel ) {
        global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups, $wgDebugToolbar, $wgDebugRawPage, $wgShowDebug;
 
        $this->channel = $channel;
        $this->isDB = ( $channel === 'rdbms' );
 
        // Calculate minimum level, duplicating some of the logic from log() and shouldEmit()
        if ( !$wgDebugRawPage && wfIsDebugRawPage() ) {
            $this->minimumLevel = self::LEVEL_WARNING;
        } elseif ( $wgDebugLogFile != '' || $wgShowDebug || $wgDebugToolbar ) {
            // Log all messages if there is a debug log file or debug toolbar
            $this->minimumLevel = self::LEVEL_DEBUG;
        } elseif ( isset( $wgDebugLogGroups[$channel] ) ) {
            $logConfig = $wgDebugLogGroups[$channel];
            // Log messages if the config is set, according to the configured level
            if ( is_array( $logConfig ) && isset( $logConfig['level'] ) ) {
                $this->minimumLevel = self::$levelMapping[$logConfig['level']];
            } else {
                $this->minimumLevel = self::LEVEL_DEBUG;
            }
        } else {
            // No other case hit: discard all messages
            $this->minimumLevel = self::LEVEL_INFINITY;
        }
 
        if ( $this->isDB && $wgDBerrorLog && $this->minimumLevel > self::LEVEL_ERROR ) {
            // Log DB errors if there is a DB error log
            $this->minimumLevel = self::LEVEL_ERROR;
        }
    }
 
    public function setMinimumForTest( ?int $level ) {
        if ( !defined( 'MW_PHPUNIT_TEST' ) ) {
            throw new LogicException( 'Not allowed outside tests' );
        }
        // Set LEVEL_INFINITY if given null, or restore the original level.
        $original = $this->minimumLevel;
        $this->minimumLevel = $level ?? self::LEVEL_INFINITY;
        return $original;
    }
 
    public function log( $level, $message, array $context = [] ): void {
        if ( is_string( $level ) ) {
            $level = self::$levelMapping[$level];
        }
        if ( $level < $this->minimumLevel ) {
            return;
        }
 
        $context += LoggerFactory::getContext()->get();
 
        if ( $this->isDB
            && $level === self::LEVEL_DEBUG
            && isset( $context['sql'] )
        ) {
            // Also give the query information to the MWDebug tools
            MWDebug::query(
                $context['sql'],
                $context['method'],
                $context['runtime_ms'] / 1000,
                $context['db_server'],
                $context['rows'],
            );
        }
 
        // If this is a DB-related error, and the site has $wgDBerrorLog
        // configured, rewrite the channel as wfLogDBError instead.
        // Likewise, if the site does not use  $wgDBerrorLog, it should
        // configurable like any other channel via $wgDebugLogGroups
        // or $wgMWLoggerDefaultSpi.
        global $wgDBerrorLog;
        if ( $this->isDB && $level >= self::LEVEL_ERROR && $wgDBerrorLog ) {
            // Format and write DB errors to the legacy locations
            $effectiveChannel = 'wfLogDBError';
        } else {
            $effectiveChannel = $this->channel;
        }
 
        if ( self::shouldEmit( $effectiveChannel, $message, $level, $context ) ) {
            $text = self::format( $effectiveChannel, $message, $context );
            $destination = self::destination( $effectiveChannel, $message, $context );
            $this->maybeLogToStderr( $text );
            self::emit( $text, $destination );
        }
        if ( !isset( $context['private'] ) || !$context['private'] ) {
            // Add to debug toolbar if not marked as "private"
            MWDebug::debugMsg( $message, [ 'channel' => $this->channel ] + $context );
        }
    }
 
    public static function shouldEmit( $channel, $message, $level, $context ) {
        global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups;
 
        if ( is_string( $level ) ) {
            $level = self::$levelMapping[$level];
        }
 
        if ( $channel === 'wfLogDBError' ) {
            // wfLogDBError messages are emitted if a database log location is
            // specified.
            $shouldEmit = (bool)$wgDBerrorLog;
 
        } elseif ( $channel === 'wfDebug' ) {
            // wfDebug messages are emitted if a catch all logging file has
            // been specified. Checked explicitly so that 'private' flagged
            // messages are not discarded by unset $wgDebugLogGroups channel
            // handling below.
            $shouldEmit = $wgDebugLogFile != '';
 
        } elseif ( isset( $wgDebugLogGroups[$channel] ) ) {
            $logConfig = $wgDebugLogGroups[$channel];
 
            if ( is_array( $logConfig ) ) {
                $shouldEmit = true;
                if ( isset( $logConfig['sample'] ) ) {
                    // Emit randomly with a 1 in 'sample' chance for each message.
                    $shouldEmit = mt_rand( 1, $logConfig['sample'] ) === 1;
                }
 
                if ( isset( $logConfig['level'] ) ) {
                    $shouldEmit = $level >= self::$levelMapping[$logConfig['level']];
                }
            } else {
                // Emit unless the config value is explicitly false.
                $shouldEmit = $logConfig !== false;
            }
 
        } elseif ( isset( $context['private'] ) && $context['private'] ) {
            // Don't emit if the message didn't match previous checks based on
            // the channel and the event is marked as private. This check
            // discards messages sent via wfDebugLog() with dest == 'private'
            // and no explicit wgDebugLogGroups configuration.
            $shouldEmit = false;
        } else {
            // Default return value is the same as the historic wfDebug
            // method: emit if $wgDebugLogFile has been set.
            $shouldEmit = $wgDebugLogFile != '';
        }
 
        return $shouldEmit;
    }
 
    public static function format( $channel, $message, $context ) {
        global $wgDebugLogGroups, $wgLogExceptionBacktrace;
 
        if ( $channel === 'wfDebug' ) {
            $text = self::formatAsWfDebug( $channel, $message, $context );
 
        } elseif ( $channel === 'wfLogDBError' ) {
            $text = self::formatAsWfLogDBError( $channel, $message, $context );
 
        } elseif ( !isset( $wgDebugLogGroups[$channel] ) ) {
            $text = self::formatAsWfDebug(
                $channel, "[{$channel}] {$message}", $context );
 
        } else {
            // Default formatting is wfDebugLog's historic style
            $text = self::formatAsWfDebugLog( $channel, $message, $context );
        }
 
        // Append stacktrace of throwable if available
        if ( $wgLogExceptionBacktrace && isset( $context['exception'] ) ) {
            $e = $context['exception'];
            $backtrace = false;
 
            if ( $e instanceof Throwable ) {
                $backtrace = MWExceptionHandler::getRedactedTrace( $e );
 
            } elseif ( is_array( $e ) && isset( $e['trace'] ) ) {
                // Throwable has already been unpacked as structured data
                $backtrace = $e['trace'];
            }
 
            if ( $backtrace ) {
                $text .= MWExceptionHandler::prettyPrintTrace( $backtrace ) .
                    "\n";
            }
        }
 
        return self::interpolate( $text, $context );
    }
 
    protected static function formatAsWfDebug( $channel, $message, $context ) {
        $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message );
        if ( isset( $context['seconds_elapsed'] ) ) {
            // Prepend elapsed request time and real memory usage with two
            // trailing spaces.
            $text = "{$context['seconds_elapsed']} {$context['memory_used']}  {$text}";
        }
        if ( isset( $context['prefix'] ) ) {
            $text = "{$context['prefix']}{$text}";
        }
        return "{$text}\n";
    }
 
    protected static function formatAsWfLogDBError( $channel, $message, $context ) {
        global $wgDBerrorLogTZ;
        static $cachedTimezone = null;
 
        if ( !$cachedTimezone ) {
            $cachedTimezone = new DateTimeZone( $wgDBerrorLogTZ );
        }
 
        $d = date_create( 'now', $cachedTimezone );
        $date = $d->format( 'D M j G:i:s T Y' );
 
        $host = wfHostname();
        $wiki = WikiMap::getCurrentWikiId();
 
        $text = "{$date}\t{$host}\t{$wiki}\t{$message}\n";
        return $text;
    }
 
    protected static function formatAsWfDebugLog( $channel, $message, $context ) {
        $time = ConvertibleTimestamp::now( TS::DB );
        $wiki = WikiMap::getCurrentWikiId();
        $host = wfHostname();
        $text = "{$time} {$host} {$wiki}: {$message}\n";
        return $text;
    }
 
    public static function interpolate( $message, array $context ) {
        if ( str_contains( $message, '{' ) ) {
            $replace = [];
            foreach ( $context as $key => $val ) {
                $replace['{' . $key . '}'] = self::flatten( $val );
            }
            $message = strtr( $message, $replace );
        }
        return $message;
    }
 
    protected static function flatten( $item ) {
        if ( $item === null ) {
            return '[Null]';
        }
 
        if ( is_bool( $item ) ) {
            return $item ? 'true' : 'false';
        }
 
        if ( is_float( $item ) ) {
            if ( is_infinite( $item ) ) {
                return ( $item > 0 ? '' : '-' ) . 'INF';
            }
            if ( is_nan( $item ) ) {
                return 'NaN';
            }
            return (string)$item;
        }
 
        if ( is_scalar( $item ) ) {
            return (string)$item;
        }
 
        if ( is_array( $item ) ) {
            return '[Array(' . count( $item ) . ')]';
        }
 
        if ( $item instanceof \DateTime ) {
            return $item->format( 'c' );
        }
 
        if ( $item instanceof Throwable ) {
            $which = $item instanceof Error ? 'Error' : 'Exception';
            return '[' . $which . ' ' . get_class( $item ) . '( ' .
                $item->getFile() . ':' . $item->getLine() . ') ' .
                $item->getMessage() . ']';
        }
 
        if ( is_object( $item ) ) {
            if ( method_exists( $item, '__toString' ) ) {
                return (string)$item;
            }
 
            return '[Object ' . get_class( $item ) . ']';
        }
 
        // phpcs:ignore MediaWiki.Usage.ForbiddenFunctions.is_resource
        if ( is_resource( $item ) ) {
            return '[Resource ' . get_resource_type( $item ) . ']';
        }
 
        return '[Unknown ' . get_debug_type( $item ) . ']';
    }
 
    protected static function destination( $channel, $message, $context ) {
        global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups;
 
        // Default destination is the debug log file as historically used by
        // the wfDebug function.
        $destination = $wgDebugLogFile;
 
        if ( isset( $context['destination'] ) ) {
            // Use destination explicitly provided in context
            $destination = $context['destination'];
 
        } elseif ( $channel === 'wfDebug' ) {
            $destination = $wgDebugLogFile;
 
        } elseif ( $channel === 'wfLogDBError' ) {
            $destination = $wgDBerrorLog;
 
        } elseif ( isset( $wgDebugLogGroups[$channel] ) ) {
            $logConfig = $wgDebugLogGroups[$channel];
 
            if ( is_array( $logConfig ) ) {
                $destination = $logConfig['destination'];
            } else {
                $destination = strval( $logConfig );
            }
        }
 
        return $destination;
    }
 
    public static function emit( $text, $file ) {
        if ( str_starts_with( $file, 'udp:' ) ) {
            $transport = UDPTransport::newFromString( $file );
            $transport->emit( $text );
        } else {
            // phpcs:ignore Generic.PHP.NoSilencedErrors.Discouraged
            $exists = @file_exists( $file );
            // phpcs:ignore Generic.PHP.NoSilencedErrors.Discouraged
            $size = $exists ? @filesize( $file ) : false;
            if ( !$exists ||
                ( $size !== false && $size + strlen( $text ) < 0x7fffffff )
            ) {
                // phpcs:ignore Generic.PHP.NoSilencedErrors.Discouraged
                @file_put_contents( $file, $text, FILE_APPEND );
            }
        }
    }
 
    private function maybeLogToStderr( string $text ): void {
        if ( getenv( 'MW_LOG_STDERR' ) ) {
            error_log( trim( $text ) );
        }
    }
 
}