Logger.php

<?php

declare(strict_types=1);

namespace SimpleSAML;

use Exception;
use SimpleSAML\Assert\Assert;
use SimpleSAML\Logger\ErrorLogLoggingHandler;
use SimpleSAML\Logger\FileLoggingHandler;
use SimpleSAML\Logger\LoggingHandlerInterface;
use SimpleSAML\Logger\StandardErrorLoggingHandler;
use SimpleSAML\Logger\SyslogLoggingHandler;

use function array_key_exists;
use function array_pop;
use function array_shift;
use function array_unshift;
use function bin2hex;
use function class_exists;
use function class_implements;
use function defined;
use function error_reporting;
use function explode;
use function gmdate;
use function in_array;
use function intval;
use function is_null;
use function openssl_random_pseudo_bytes;
use function php_sapi_name;
use function register_shutdown_function;
use function str_replace;
use function strtolower;
use function substr;

/**
 * The main logger class for SimpleSAMLphp.
 *
 * @package SimpleSAMLphp
 */
class Logger
{
    /**
     * @var \SimpleSAML\Logger\LoggingHandlerInterface|null
     */
    private static ?LoggingHandlerInterface $loggingHandler = null;

    /**
     * @var bool
     */
    private static bool $initializing = false;

    /**
     * @var integer|null
     */
    private static ?int $logLevel = null;

    /**
     * @var boolean
     */
    private static bool $captureLog = false;

    /**
     * @var string[]
     */
    private static array $capturedLog = [];

    /**
     * Array with messages logged before the logging handler was initialized.
     *
     * @var array
     */
    private static array $earlyLog = [];

    /**
     * List of log levels.
     *
     * This list is used to restore the log levels after some log levels have been disabled.
     *
     * @var array
     */
    private static array $logLevelStack = [];

    /**
     * The current mask of log levels disabled.
     *
     * Note: this mask is not directly related to the PHP error reporting level.
     *
     * @var int
     */
    private static int $logMask = 0;

    /**
     * This constant defines the string we set the track ID to while we are fetching the track ID from the session
     * class. This is used to prevent infinite recursion.
     *
     * @var string
     */
    public const NO_TRACKID = '_NOTRACKIDYET_';

    /**
     * This variable holds the track ID we have retrieved from the session class. It can also be NULL, in which case
     * we haven't fetched the track ID yet, or self::NO_TRACKID, which means that we are fetching the track ID now.
     *
     * @var string
     */
    private static string $trackid = self::NO_TRACKID;

    /**
     * This variable holds the format used to log any message. Its use varies depending on the log handler used (for
     * instance, you cannot control here how dates are displayed when using syslog or errorlog handlers), but in
     * general the options are:
     *
     * - %date{<format>}: the date and time, with its format specified inside the brackets. See the PHP documentation
     *   of the date() function for more information on the format. If the brackets are omitted, the standard
     *   format is applied. This can be useful if you just want to control the placement of the date, but don't care
     *   about the format.
     *
     * - %process: the name of the SimpleSAMLphp process. Remember you can configure this in the 'logging.processname'
     *   option. The SyslogLoggingHandler will just remove this.
     *
     * - %level: the log level (name or number depending on the handler used). Please note different logging handlers
     *   will print the log level differently.
     *
     * - %stat: if the log entry is intended for statistical purposes, it will print the string 'STAT ' (bear in mind
     *   the trailing space).
     *
     * - %trackid: the track ID, an identifier that allows you to track a single session.
     *
     * - %srcip: the IP address of the client. If you are behind a proxy, make sure to modify the
     *   $_SERVER['REMOTE_ADDR'] variable on your code accordingly to the X-Forwarded-For header.
     *
     * - %msg: the message to be logged.
     *
     * @var string The format of the log line.
     */
    private static string $format = '%date{M j H:i:s} %process %level %stat[%trackid] %msg';

    /**
     * This variable tells if we have a shutdown function registered or not.
     *
     * @var bool
     */
    private static bool $shutdownRegistered = false;

    /**
     * This variable tells if we are shutting down.
     *
     * @var bool
     */
    private static bool $shuttingDown = false;

    /** @var int */
    public const EMERG = 0;

    /** @var int */
    public const ALERT = 1;

    /** @var int */
    public const CRIT = 2;

    /** @var int */
    public const ERR = 3;

    /** @var int */
    public const WARNING = 4;

    /** @var int */
    public const NOTICE = 5;

    /** @var int */
    public const INFO = 6;

    /** @var int */
    public const DEBUG = 7;


    /**
     * Log an emergency message.
     *
     * @param string $string The message to log.
     */
    public static function emergency(string $string): void
    {
        self::log(self::EMERG, $string);
    }


    /**
     * Log a critical message.
     *
     * @param string $string The message to log.
     */
    public static function critical(string $string): void
    {
        self::log(self::CRIT, $string);
    }


    /**
     * Log an alert.
     *
     * @param string $string The message to log.
     */
    public static function alert(string $string): void
    {
        self::log(self::ALERT, $string);
    }


    /**
     * Log an error.
     *
     * @param string $string The message to log.
     */
    public static function error(string $string): void
    {
        self::log(self::ERR, $string);
    }


    /**
     * Log a warning.
     *
     * @param string $string The message to log.
     */
    public static function warning(string $string): void
    {
        self::log(self::WARNING, $string);
    }


    /**
     * We reserve the notice level for statistics, so do not use this level for other kind of log messages.
     *
     * @param string $string The message to log.
     */
    public static function notice(string $string): void
    {
        self::log(self::NOTICE, $string);
    }


    /**
     * Info messages are a bit less verbose than debug messages. This is useful to trace a session.
     *
     * @param string $string The message to log.
     */
    public static function info(string $string): void
    {
        self::log(self::INFO, $string);
    }


    /**
     * Debug messages are very verbose, and will contain more information than what is necessary for a production
     * system.
     *
     * @param string $string The message to log.
     */
    public static function debug(string $string): void
    {
        self::log(self::DEBUG, $string);
    }


    /**
     * Statistics.
     *
     * @param string $string The message to log.
     */
    public static function stats(string $string): void
    {
        self::log(self::NOTICE, $string, self::$logLevel >= self::NOTICE);
    }


    /**
     * Set the logger to capture logs.
     *
     * @param boolean $val Whether to capture logs or not. Defaults to TRUE.
     */
    public static function setCaptureLog(bool $val = true): void
    {
        self::$captureLog = $val;
    }


    /**
     * Get the captured log.
     * @return array
     */
    public static function getCapturedLog(): array
    {
        return self::$capturedLog;
    }


    /**
     * Clears the captured log.
     */
    public static function clearCapturedLog(): void
    {
        self::$capturedLog = [];
    }


    /**
     * Set the track identifier to use in all logs.
     *
     * @param string $trackId The track identifier to use during this session.
     */
    public static function setTrackId(string $trackId): void
    {
        self::$trackid = $trackId;
        self::flush();
    }


    /**
     * Flush any pending log messages to the logging handler.
     *
     */
    public static function flush(): void
    {
        foreach (self::$earlyLog as $msg) {
            self::log($msg['level'], $msg['string'], $msg['statsLog']);
        }
        self::$earlyLog = [];
    }


    /**
     * Flush any pending deferred logs during shutdown.
     *
     * This method is intended to be registered as a shutdown handler, so that any pending messages that weren't sent
     * to the logging handler at that point, can still make it. It is therefore not intended to be called manually.
     *
     */
    public static function shutdown(): void
    {
        if (self::$trackid === self::NO_TRACKID) {
            try {
                $s = Session::getSessionFromRequest();
            } catch (Exception $e) {
                // loading session failed. We don't care why, at this point we have a transient session, so we use that
                $s = Session::getSessionFromRequest();
            }
            self::$trackid = $s->getTrackID();
        }
        self::$shuttingDown = true;
        self::flush();
    }


    /**
     * Evaluate whether errors of a certain error level are masked or not.
     *
     * @param int $errno The level of the error to check.
     *
     * @return bool True if the error is masked, false otherwise.
     */
    public static function isErrorMasked(int $errno): bool
    {
        return ($errno & self::$logMask) || !($errno & error_reporting());
    }


    /**
     * Disable error reporting for the given log levels.
     *
     * Every call to this function must be followed by a call to popErrorMask().
     *
     * @param int $mask The log levels that should be masked.
     */
    public static function maskErrors(int $mask): void
    {
        $currentEnabled = error_reporting();
        self::$logLevelStack[] = [$currentEnabled, self::$logMask];

        $currentEnabled &= ~$mask;
        error_reporting($currentEnabled);
        self::$logMask |= $mask;
    }


    /**
     * Pop an error mask.
     *
     * This function restores the previous error mask.
     *
     */
    public static function popErrorMask(): void
    {
        $lastMask = array_pop(self::$logLevelStack);
        error_reporting($lastMask[0]);
        self::$logMask = $lastMask[1];
    }


    /**
     * Returns the current logging handler
     *
     * @return LoggingHandlerInterface
     */
    public static function getLoggingHandler(): ?LoggingHandlerInterface
    {
        return self::$loggingHandler;
    }


    /**
     * Sets the current logging handler
     *
     * @param LoggingHandlerInterface|null $loggingHandler The logging handler to set
     */
    public static function setLoggingHandler(?LoggingHandlerInterface $loggingHandler): void
    {
        self::$initializing   = false;
        self::$loggingHandler = $loggingHandler;
    }

    /**
     * Sets the log level.
     *
     * @param int $level One of the Logger class constants.
     */
    public static function setLogLevel(int $level): void
    {
        self::$logLevel = $level;
    }

    /**
     * Defer a message for later logging.
     *
     * @param int     $level The log level corresponding to this message.
     * @param string  $message The message itself to log.
     * @param boolean $stats Whether this is a stats message or a regular one.
     */
    private static function defer(int $level, string $message, bool $stats): void
    {
        // save the message for later
        self::$earlyLog[] = ['level' => $level, 'string' => $message, 'statsLog' => $stats];

        // register a shutdown handler if needed
        if (!self::$shutdownRegistered) {
            register_shutdown_function([self::class, 'shutdown']);
            self::$shutdownRegistered = true;
        }
    }


    /**
     * @param string|null $handler
     * @throws \Exception
     */
    private static function createLoggingHandler(?string $handler = null): void
    {
        self::$initializing = true;

        // a set of known logging handlers
        $known_handlers = [
            'syslog'   => SyslogLoggingHandler::class,
            'file'     => FileLoggingHandler::class,
            'errorlog' => ErrorLogLoggingHandler::class,
            'stderr' => StandardErrorLoggingHandler::class,
        ];

        // get the configuration
        $config = Configuration::getInstance();

        // setting minimum log_level
        self::$logLevel = $config->getOptionalInteger('logging.level', self::INFO);

        // get the metadata handler option from the configuration
        if (is_null($handler)) {
            $handler = $config->getOptionalString(
                'logging.handler',
                php_sapi_name() === 'cli' || defined('STDIN') ? 'stderr' : 'syslog'
            );
        }

        if (!array_key_exists($handler, $known_handlers) && class_exists($handler)) {
            if (!in_array(LoggingHandlerInterface::class, class_implements($handler), true)) {
                throw new Exception("The logging handler '$handler' is invalid.");
            }
        } else {
            $handler = strtolower($handler);
            if (!array_key_exists($handler, $known_handlers)) {
                throw new Exception(
                    "Invalid value for the 'logging.handler' configuration option. Unknown handler '" . $handler . "'."
                );
            }
            $handler = $known_handlers[$handler];
        }

        self::$format = $config->getOptionalString('logging.format', self::$format);

        try {
            /** @var \SimpleSAML\Logger\LoggingHandlerInterface */
            self::$loggingHandler = new $handler($config);
            self::$loggingHandler->setLogFormat(self::$format);
            self::$initializing = false;
        } catch (Exception $e) {
            self::$loggingHandler = new ErrorLogLoggingHandler($config);
            self::$initializing = false;
            self::log(self::CRIT, $e->getMessage(), false);
        }
    }


    /**
     * @param int $level
     * @param string $string
     * @param bool $statsLog
     */
    private static function log(int $level, string $string, bool $statsLog = false): void
    {
        if (self::$initializing) {
            // some error occurred while initializing logging
            self::defer($level, $string, $statsLog);
            return;
        } elseif (php_sapi_name() === 'cli' || defined('STDIN')) {
            $_SERVER['REMOTE_ADDR'] = "CLI";
            if (self::$trackid === self::NO_TRACKID) {
                self::$trackid = 'CL' . bin2hex(openssl_random_pseudo_bytes(4));
            }
        }

        if (!isset(self::$loggingHandler)) {
            // Initialize logging
            self::createLoggingHandler();
        }

        if (self::$captureLog) {
            $sample = microtime(false);
            list($msecs, $mtime) = explode(' ', $sample);

            $time = intval($mtime);
            $usec = substr($msecs, 2, 3);

            $ts = gmdate('H:i:s', $time) . '.' . $usec . 'Z';
            self::$capturedLog[] = $ts . ' ' . $string;
        }

        if (self::$logLevel >= $level || $statsLog) {
            $formats = ['%trackid', '%msg', '%srcip', '%stat'];
            $replacements = [self::$trackid, $string, $_SERVER['REMOTE_ADDR']];

            $stat = '';
            if ($statsLog) {
                $stat = 'STAT ';
            }
            $replacements[] = $stat;

            if (self::$trackid === self::NO_TRACKID && !self::$shuttingDown) {
                // we have a log without track ID and we are not still shutting down, so defer logging
                self::defer($level, $string, $statsLog);
                return;
            } elseif (self::$trackid === self::NO_TRACKID) {
                // shutting down without a track ID, prettify it
                array_shift($replacements);
                array_unshift($replacements, 'N/A');
            }

            // we either have a track ID or we are shutting down, so just log the message
            $string = str_replace($formats, $replacements, self::$format);
            self::$loggingHandler->log($level, $string);
        }
    }
}