PHP fatal error log handler with optional debug stack trace workaround

a-php-fatal-error-log-with-stack-trace-workaround.md

PHP Fatal with a mini stack trace workaround

Often you get a fatal error to deal with but where the problem code is not always very clear where the problem is.

This is especially difficult for fatal errors like "NOTICE: PHP message: PHP Fatal error: Allowed memory size of 134217728 bytes exhausted.

When memory errors any debugging can easily influence the location the fatal is triggered.

Everything on the Internet states that you cant get a stack trace for a fatal. The most common suggested solution is to use a custom shutdown function to at least handle the fatal in some way maybe log it.

The following is a workaround that uses a debug function for storing a trace every time it is called and then in the shutdown function we retrieve the last trace that was stored and write it all to a fatal specific error log.

The russian-roulette.php file is an example demo that every time you run it will put a bullet in the gun class spin it and pull the trigger and if the shot returned is a bullet trigger a fatal.

Generating logs as per the below.

2018-07-05 11:46:38: Fatal Error: Oops, sorry you dead! in /var/www/public/russian-roulette.php on line 118
        Last Debug Trace:
        1) /var/www/public/russian-roulette.php(172): debug_track_trace()
        2) /var/www/public/russian-roulette.php(117): Gun->pullTrigger()
        3) /var/www/public/russian-roulette.php(183): spin_and_pull_trigger()

2018-07-05 12:12:37: Fatal Error: Oops, sorry you dead! in /var/www/public/russian-roulette.php on line 118
        Last Debug Trace:
        1) /var/www/public/russian-roulette.php(172): debug_track_trace()
        2) /var/www/public/russian-roulette.php(117): Gun->pullTrigger()
        3) /var/www/public/russian-roulette.php(183): spin_and_pull_trigger()

2018-07-05 12:12:40: Fatal Error: Oops, sorry you dead! in /var/www/public/russian-roulette.php on line 118
        Last Debug Trace:
        1) /var/www/public/russian-roulette.php(172): debug_track_trace()
        2) /var/www/public/russian-roulette.php(117): Gun->pullTrigger()
        3) /var/www/public/russian-roulette.php(183): spin_and_pull_trigger()

This does not log any trace unless you add debug_track_trace() and rather than giving you detailed logging gives you a way of reproducing a fatal with some temporary debug code added

debug-functions.php

<?php

/**
 * A function that can be registered with register_shutdown_function() that will
 * help log fatal errors.
 *
 * @return void
 */
function log_fatal_on_shutdown() {

    // Was there error
    if ( ! $err = error_get_last()) {
        return;
    }

    // List all fatal error types
    $fatals = array(
        E_USER_ERROR      => 'Fatal Error',
        E_ERROR           => 'Fatal Error',
        E_PARSE           => 'Parse Error',
        E_CORE_ERROR      => 'Core Error',
        E_CORE_WARNING    => 'Core Warning',
        E_COMPILE_ERROR   => 'Compile Error',
        E_COMPILE_WARNING => 'Compile Warning'
    );

    // Check if we dealing with a fatal
    if (!isset($fatals[ $err['type'] ])) {
        return;
    }

    // Build Fatal Error Message
    $msg   = $fatals[$err['type']] . ': ' . $err['message'] . ' in ';
    $msg  .= $err['file'] . ' on line ' . $err['line'];

    // Build log message
    $date = date('Y-m-d H:i:s');
    $log  = "{$date}: {$msg}";

    // Get last debug trace
    $trace = debug_track_trace(true);
    $trace = empty($trace) ? PHP_EOL : PHP_EOL . "\tLast Debug Trace:" . PHP_EOL . $trace  . PHP_EOL . PHP_EOL;

    $path = '/var/log/php-';
    file_put_contents($path . 'fatals.' . date('Ymd') . '.log', $log . $trace, FILE_APPEND | LOCK_EX);
}

/**
 * Debug helper that allows us track traces, used in log_fatal_on_shutdown() to
 * log the last trace.
 *
 * @param  boolean
 *
 * @return string
 */
function debug_track_trace($getLast = false) {
    static $lastTrace = null;

    if ($getLast) {
        return $lastTrace;
    }

    $lastTrace = simple_call_trace(10, false);
    return $lastTrace;
}

/**
 * Provide a mini Call Stack Trace.
 *
 * @param  integer $last
 *
 * @return string
 */
function simple_call_trace($limit = 0, $formatted = true) {
    $e = new Exception();
    $trace = explode("\n", $e->getTraceAsString());

    array_shift($trace); // remove call to this method
    array_pop($trace);   // remove {main}

    $length = count($trace);
    $result = array();

    for ($i = 0; $i < $limit; $i++) {
        if ($length == $i) {
            break;
        }

        // replace '#someNum' with '$i)', set the right ordering
        $result[] = ($i + 1)  . ')' . substr($trace[$i], strpos($trace[$i], ' '));
    }

    // Collaps to a string and add some indenting
    $output = "\t" . implode("\n\t", $result);
  
    if ($formatted === false) {
        return $output;
    }

    return "<pre>" . $output . '</pre>';
}

russian-roulette.php

<?php

// Include debug functions
include "debug-functions.php";

// Register our shutdown handler
register_shutdown_function('log_fatal_on_shutdown');

/**
 * Helper function to setup the gun and pull the trigger.
 */
function spin_and_pull_trigger() {

    // Prepare
    $gun = (new Gun);
    $gun->emptySlots();
    $gun->addBullet();
    
    // Spin
    $spinForce = mt_rand(2,100);
    $gun->spin($spinForce);

    // Pull trigger
    if ($gun->pullTrigger() === Gun::GUN_BULLET) {
        trigger_error("Oops, sorry you dead!", E_USER_ERROR);
    }

    print "You live\n";
}

/**
 * Gun class that allow for loading of bullets and pull the trigger.
 */
class Gun
{
    const GUN_MAX    = 6;
    const GUN_EMPTY  = 'EMPTY';
    const GUN_BULLET = 'BULLET';

    protected $slots = [];

    public function __construct()
    {
        debug_track_trace();
        $this->emptySlots();
    }
  
    public function emptySlots()
    {
        debug_track_trace();
        $this->slots = array_fill(0, static::GUN_MAX, static::GUN_EMPTY);
    }

    public function addBullet()
    {        
        // Look for an open slot
        foreach ($this->slots as $key => $slot) {
            debug_track_trace();
            if ($slot == static::GUN_EMPTY) {
                $this->slots[$key] = static::GUN_BULLET;
                return true;
            }
        }

        return true;
    }
  
    public function spin($spinForce)
    {        
        print "SPIN={$spinForce}" . PHP_EOL . PHP_EOL;
        foreach (range(0,$spinForce, 1) as $step) {
            debug_track_trace();
            $slot = array_pop($this->slots);
            array_unshift($this->slots, $slot);
            print "TICK..TICK..{$step}..";
        }
        print PHP_EOL . PHP_EOL;
    }

    public function pullTrigger()
    {
        debug_track_trace();
        $shot = array_shift($this->slots);
        $this->slots[] = static::GUN_EMPTY;
        print "Shot={$shot}\n";
        print "Gun Slots:\n";
        print_r($this->slots);
        return $shot;
    }
}

// Take a chance
spin_and_pull_trigger();