Tuesday, January 29, 2013

Using PHP's auto_prepend_file to log all server errors

We recently updated our PHP configuration to move from our applications manually logging errors to having it be done at a server-wide level by taking advantage of PHP's auto_prepend_file feature.

This allows you to catch all errors reported by PHP and ship them off to some sort of logging application.

Below is the ServerLogger class that we used to accomplish this. It'll probably make its way to GitHub eventually but that's a task for another day. To implement this, follow the instructions in the class comments below.

/**
 * This library is meant to used in a auto_prepend_file to enable server-wide
 * tracking of PHP errors.
 * 
 * Installation (You may use your own paths, these are examples):
 * 
 *   - Place ServerLogger.php in /srv/www/server-scripts/ServerLogger.php
 * 
 *   - Create auto_prepend.php /srv/www/server-scripts/auto_prepend.php with:
 * 
 *      
 * @see https://github.com/Graylog2/gelf-php
 */

if(defined('SERVER_LOGGER')) {
  return;
}

define('SERVER_LOGGER', 1);

/**
 * @see https://github.com/Graylog2/gelf-php 
 */
class GELFMessage
{
  /**
   * @var string
   */
  private $version = null;

  /**
   * @var integer
   */
  private $timestamp = null;

  /**
   * @var string
   */
  private $shortMessage = null;

  /**
   * @var string
   */
  private $fullMessage = null;

  /**
   * @var string
   */
  private $facility = null;

  /**
   * @var string
   */
  private $host = null;

  /**
   * @var integer
   */
  private $level = null;

  /**
   * @var string
   */
  private $file = null;

  /**
   * @var integer
   */
  private $line = null;

  /**
   * @var array
   */
  private $data = array();

  /**
   * @param string $version
   * @return GELFMessage
   */
  public function setVersion($version)
  {
    $this->version = $version;
    return $this;
  }

  /**
   * @return string
   */
  public function getVersion()
  {
    return $this->version;
  }

  /**
   * @param integer $timestamp
   * @return GELFMessage
   */
  public function setTimestamp($timestamp)
  {
    $this->timestamp = $timestamp;
    return $this;
  }

  /**
   * @return integer
   */
  public function getTimestamp()
  {
    return $this->timestamp;
  }

  /**
   * @param string $shortMessage
   * @return GELFMessage
   */
  public function setShortMessage($shortMessage)
  {
    $this->shortMessage = $shortMessage;
    return $this;
  }

  /**
   * @return string
   */
  public function getShortMessage()
  {
    return $this->shortMessage;
  }

  /**
   * @param string $fullMessage
   * @return GELFMessage
   */
  public function setFullMessage($fullMessage)
  {
    $this->fullMessage = $fullMessage;
    return $this;
  }

  /**
   * @return string
   */
  public function getFullMessage()
  {
    return $this->fullMessage;
  }

  /**
   * @param string $facility
   * @return GELFMessage
   */
  public function setFacility($facility)
  {
    $this->facility = $facility;
    return $this;
  }

  /**
   * @return string
   */
  public function getFacility()
  {
    return $this->facility;
  }

  /**
   * @param string $host
   * @return GELFMessage
   */
  public function setHost($host)
  {
    $this->host = $host;
    return $this;
  }

  /**
   * @return string
   */
  public function getHost()
  {
    return $this->host;
  }

  /**
   * @param integer $level
   * @return GELFMessage
   */
  public function setLevel($level)
  {
    $this->level = $level;
    return $this;
  }

  /**
   * @return integer
   */
  public function getLevel()
  {
    return $this->level;
  }

  /**
   * @param string $file
   * @return GELFMessage
   */
  public function setFile($file)
  {
    $this->file = $file;
    return $this;
  }

  /**
   * @return string
   */
  public function getFile()
  {
    return $this->file;
  }

  /**
   * @param integer $line
   * @return GELFMessage
   */
  public function setLine($line)
  {
    $this->line = $line;
    return $this;
  }

  /**
   * @return integer
   */
  public function getLine()
  {
    return $this->line;
  }

  /**
   * @param string $key
   * @param mixed $value
   * @return GELFMessage
   */
  public function setAdditional($key, $value)
  {
    $this->data["_" . trim($key)] = $value;
    return $this;
  }

  /**
   * @return mixed
   */
  public function getAdditional($key)
  {
    return isset($this->data["_" . trim($key)]) ? $this->data[$key] : null;
  }

  /**
   * @return array
   */
  public function toArray()
  {
    $messageAsArray = array(
        'version' => $this->getVersion(),
        'timestamp' => $this->getTimestamp(),
        'short_message' => $this->getShortMessage(),
        'full_message' => $this->getFullMessage(),
        'facility' => $this->getFacility(),
        'host' => $this->getHost(),
        'level' => $this->getLevel(),
        'file' => $this->getFile(),
        'line' => $this->getLine(),
    );

    foreach ($this->data as $key => $value) {
      $messageAsArray[$key] = $value;
    }

    return $messageAsArray;
  }

}

/**
 * @see https://github.com/Graylog2/gelf-php 
 */
class GELFMessagePublisher
{
  /**
   * @var integer
   */

  const CHUNK_SIZE_WAN = 1420;

  /**
   * @var integer
   */
  const CHUNK_SIZE_LAN = 8154;

  /**
   * @var integer
   */
  const GRAYLOG2_DEFAULT_PORT = 12201;

  /**
   * @var string
   */
  const GRAYLOG2_PROTOCOL_VERSION = '1.0';

  /**
   * @var string
   */
  protected $hostname = null;

  /**
   * @var integer
   */
  protected $port = null;

  /**
   * @var integer
   */
  protected $chunkSize = null;

  /**
   * Creates a new publisher that sends errors to a Graylog2 server via UDP
   *
   * @throws InvalidArgumentException
   * @param string $hostname
   * @param integer $port
   * @param integer $chunkSize
   */
  public function __construct($hostname, $port = self::GRAYLOG2_DEFAULT_PORT, $chunkSize = self::CHUNK_SIZE_WAN)
  {
    // Check whether the parameters are set correctly
    if (!$hostname) {
      throw new InvalidArgumentException('$hostname must be set');
    }

    if (!is_numeric($port)) {
      throw new InvalidArgumentException('$port must be an integer');
    }

    if (!is_numeric($chunkSize)) {
      throw new InvalidArgumentException('$chunkSize must be an integer');
    }

    $this->hostname = $hostname;
    $this->port = $port;
    $this->chunkSize = $chunkSize;
  }

  /**
   * Publishes a GELFMessage, returns false if an error occured during write
   *
   * @throws UnexpectedValueException
   * @param unknown_type $message
   * @return boolean
   */
  public function publish(GELFMessage $message)
  {
    // Check if required message parameters are set
    if (!$message->getShortMessage() || !$message->getHost()) {
      throw new UnexpectedValueException(
              'Missing required data parameter: "version", "short_message" and "host" are required.'
      );
    }

    // Set Graylog protocol version
    $message->setVersion(self::GRAYLOG2_PROTOCOL_VERSION);

    // Encode the message as json string and compress it using gzip
    $preparedMessage = $this->getPreparedMessage($message);

    // Open a udp connection to graylog server
    $socket = $this->getSocketConnection();

    // Several udp writes are required to publish the message
    if ($this->isMessageSizeGreaterChunkSize($preparedMessage)) {
      // A unique id which consists of the microtime and a random value
      $messageId = $this->getMessageId();

      // Split the message into chunks
      $messageChunks = $this->getMessageChunks($preparedMessage);
      $messageChunksCount = count($messageChunks);

      // Send chunks to graylog server
      foreach (array_values($messageChunks) as $messageChunkIndex => $messageChunk) {
        $bytesWritten = $this->writeMessageChunkToSocket(
                $socket, $messageId, $messageChunk, $messageChunkIndex, $messageChunksCount
        );

        if (false === $bytesWritten) {
          // Abort due to write error
          return false;
        }
      }
    } else {
      // A single write is enough to get the message published
      if (false === $this->writeMessageToSocket($socket, $preparedMessage)) {
        // Abort due to write error
        return false;
      }
    }

    // This increases stability a lot if messages are sent in a loop
    // A value of 20 means 0.02 ms
    usleep(20);

    // Message successful sent
    return true;
  }

  /**
   * @param GELFMessage $message
   * @return string
   */
  protected function getPreparedMessage(GELFMessage $message)
  {
    return gzcompress(json_encode($message->toArray()));
  }

  /**
   * @return resource
   */
  protected function getSocketConnection()
  {
    return stream_socket_client(sprintf('udp://%s:%d', gethostbyname($this->hostname), $this->port));
  }

  /**
   * @param string $preparedMessage
   * @return boolean
   */
  protected function isMessageSizeGreaterChunkSize($preparedMessage)
  {
    return (strlen($preparedMessage) > $this->chunkSize);
  }

  /**
   * @return float
   */
  protected function getMessageId()
  {
    return (float) (microtime(true) . mt_rand(0, 10000));
  }

  /**
   * @param string $preparedMessage
   * @return array
   */
  protected function getMessageChunks($preparedMessage)
  {
    return str_split($preparedMessage, $this->chunkSize);
  }

  /**
   * @param float $messageId
   * @param string $data
   * @param integer $sequence
   * @param integer $sequenceSize
   * @throws InvalidArgumentException
   * @return string
   */
  protected function prependChunkInformation($messageId, $data, $sequence, $sequenceSize)
  {
    if (!is_string($data) || $data === '') {
      throw new InvalidArgumentException('Data must be a string and not be empty.');
    }

    if (!is_integer($sequence) || !is_integer($sequenceSize)) {
      throw new InvalidArgumentException('Sequence number and size must be integer.');
    }

    if ($sequenceSize <= 0) {
      throw new InvalidArgumentException('Sequence size must be greater than 0.');
    }

    if ($sequence > $sequenceSize) {
      throw new InvalidArgumentException('Sequence size must be greater than sequence number.');
    }

    return pack('CC', 30, 15) . substr(md5($messageId, true), 0, 8) . pack('CC', $sequence, $sequenceSize) . $data;
  }

  /**
   * @param resource $socket
   * @param float $messageId
   * @param string $messageChunk
   * @param integer $messageChunkIndex
   * @param integer $messageChunksCount
   * @return integer|boolean
   */
  protected function writeMessageChunkToSocket($socket, $messageId, $messageChunk, $messageChunkIndex, $messageChunksCount)
  {
    return fwrite(
                    $socket, $this->prependChunkInformation($messageId, $messageChunk, $messageChunkIndex, $messageChunksCount)
    );
  }

  /**
   * @param resource $socket
   * @param string $preparedMessage
   * @return integer|boolean
   */
  protected function writeMessageToSocket($socket, $preparedMessage)
  {
    return fwrite($socket, $preparedMessage);
  }

}

class ServerLogger
{
  public static function configure($hostname, $port = GELFMessagePublisher::GRAYLOG2_DEFAULT_PORT, $chunkSize = GELFMessagePublisher::CHUNK_SIZE_WAN)
  {
    if(self::$instance !== null) {
      throw new RuntimeException('You can only call configure() once.');
    }
    
    $publisher = new GELFMessagePublisher($hostname, $port, $chunkSize);
    
    self::$instance = new ServerLogger($publisher);
  }
  
  public static function configureSettings(array $settings)
  {
    if(isset($settings['additional'])) {
      foreach($settings['additional'] as $key => $value) {
        self::$settings['additional'][$key] = $value;
      }
      
      unset($settings['additional']);
    }
    
    foreach($settings as $key => $value) {
      self::$settings[$key] = $value;
    }
  }

  public static function logException(Exception $exception)
  {
    if(!self::$instance) {
      throw new InvalidArgumentException('Must call ServerLogger::configure() first.');
    }
    
    self::$instance->listenToException($exception);
  }
  
  public function listenToError($errno , $errstr, $errfile = '', $errline = 0, array $errcontext = array())
  {
    if(!self::$settings['enable']) {
      return;
    }
    
    if($this->errorsHandled < self::$settings['maximum_errors']) {
      $this->errorsHandled++;
      
      if(!self::$settings['report_ignored'] && error_reporting() === 0) {
        return;
      }
      
      $message = $this->getBaseMessage();
      $message->setShortMessage('error: '.$errstr);
      
      $message->setAdditional('error_number', $errno);
      
      if($errfile) {
        $message->setFile($errfile);
      }
      
      if($errline) {
        $message->setLine($errline);
      }
      
      if(isset($_SESSION, $_REQUEST)) {
        $message->setAdditional('session_and_request', array_merge_recursive($_SESSION, $_REQUEST));
      }
      
      $this->publisher->publish($message);
    }
  }
  
  public function listenToException(Exception $exception)
  {
    if(!self::$settings['enable']) {
      return;
    }
    
    $message = $this->getBaseMessage();
    $message->setShortMessage('exception: '.$exception->getMessage());
    $message->setFile($exception->getFile());
    $message->setLine($exception->getLine());
    $message->setFullMessage($exception->getTraceAsString());
    $message->setAdditional('exception_class', get_class($exception));
    $message->setAdditional('exception_code', $exception->getCode());

    $this->publisher->publish($message);
  }
  
  public function listenToShutdown()
  {
    if(!self::$settings['enable']) {
      return;
    }
    
    $this->reservedMemory = null;
    
    if(($error = error_get_last()) && !$this->wasReported($error)) {
      $message = $this->getBaseMessage();
      $message->setShortMessage('error: '.$error['message']);
      
      unset($error['message']);

      foreach($error as $k => $v) {
        $message->setAdditional($k, $v);
      }

      $this->publisher->publish($message);
    }
  }
  
  /**
   * @return GELFMessage 
   */
  private function getBaseMessage()
  {
    $message = new GELFMessage();
    
    if($host = gethostname()) {
      $message->setHost($host);
    }
    
    $message->setFacility(self::$settings['facility']);
    
    foreach(self::$settings['additional'] as $k => $v) {
      $message->setAdditional($k, $v);
    }
    
    if(isset($_GET)) {
      $message->setAdditional('$_GET', json_encode($_GET));
    }
    
    if(isset($_POST)) {
      $message->setAdditional('$_POST', json_encode($_POST));
    }
    
    foreach(self::$settings['additional_server_keys'] as $k) {
      $server = array();

      if(isset($_SERVER[$k])) {
        $server[$k] = $_SERVER[$k];
      }

      if(count($server)) {
        $message->setAdditional('$_SERVER (abridged)', json_encode($server));
      }
    }
    
    return $message;
  }
  
  private function wasReported($error)
  {
    // 417 = bitmask: E_ERROR + E_CORE_ERROR + E_COMPILE_ERROR + E_USER_ERROR
    
    return $this->errorsHandled > 0 && ($error['type'] & 417) > 0;
  }
  
  private function __construct(GELFMessagePublisher $publisher)
  {
    $this->publisher = $publisher;
    $this->reservedMemory = str_repeat('1', self::$settings['reserved_memory']);
    
    set_error_handler(array($this, 'listenToError'));
    
    set_exception_handler(array($this, 'listenToException'));
    
    register_shutdown_function(array($this, 'listenToShutdown'));
  }
  
  private static $settings = array(
    'facility'                => 'php server logger',
    'enable'                  => true,
    'maximum_errors'          => 100,
    'reserved_memory'         => 524288,
    'report_ignored'          => false,
    'additional'              => array(),
    'additional_server_keys'  => array('HTTP_HOST', 'HTTP_X_FORWARDED_HOST', 'HTTP_X_FORWARDED_PROTOCOL', 'REQUEST_URI')
  ); 
  
  private static $instance = null;
  private $publisher;
  private $reservedMemory = null;
  private $errorsHandled = 0;
}

No comments:

Post a Comment