Hardcore Debug Logger

README.md

HardCore Debug Logger

jump to usage

A bit of history

Sometimes, a segfaults happen, but you don't know where, and your PHP installation does not have tools to find it. Or sometime, you think PHP is hanging, but you don't know where. You may use xdebug, but you don't want to click so many times on the "next call" button.

To addresses theses issues, I used to use this hack.

The code is pretty small but it could appear really weird. Don't worry, I will explain it.

1. We register a tick function. A tick is an event emitted by PHP when a very low-level (tickable) statements is executed. This function will be executed on each PHP Tick and will print the last executed line.

2. We tell PHP to fire an event for all possible tick.

3. Profit... Thanks to that, it's possible to find the last successfully executed line.

But, what I did not know, is that it worked because of a PHP Bug: declare(ticks=1) is not supposed to leak to other files. This has been fixed in PHP 7.0 and so my hack does not work anymore.

Let's use a bigger cleaner hack

So If I want to continue to use this debug method, I need to put by hand declare(ticks=1) on every PHP files... Boring! I could write a simple tools that will do that for me but I don't want to modify all my vendors.

So I decided to use PHP Stream Wrapper and Stream Filter. Theses PHP features are not really well known, but they are very powerful. I encourage you to read more about it.

This new implementation replaces the default file and phar stream wrapper implementation of PHP to be able to automatically add declare(ticks=1) on each PHP file. But this is done only in memory, not physically on the disk.

Usage

To use it, copy the HardCoreDebugLogger.php file somewhere on your disk and then add the following lines in your code

require '/path/to/HardCoreDebugLogger.php'

HardCoreDebugLogger::register();

By default, the traces will be displayed on STDOUT, but you can change it to save it a file:

require '/path/to/HardCoreDebugLogger.php'

HardCoreDebugLogger::register('/tmp/trace.txt');

Credit

Writing a Stream Wrapper is boring, so I would like to credit Anthony Ferrara for his work on php-preprocessor

a.php

<?php

declare(ticks=1);

require __DIR__.'/HardCoreDebugLogger.php';
HardCoreDebugLogger::register();

function foobar()
{
    $c = 1;
}

require __DIR__.'/b.php';

foobar();

b.php

<?php

function bingo()
{
    $e = 1;
}

bingo();

HardCoreDebugLogger.php

<?php

const STREAM_OPEN_FOR_INCLUDE = 128;

final class HardCoreDebugLogger
{
    public static function register(string $output = 'php://stdout')
    {
        register_tick_function(function () use ($output) {
            $bt = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 1);
            $last = reset($bt);
            $info = sprintf("%.4f %s +%d\n", microtime(true), $last['file'], $last['line']);
            file_put_contents($output, $info, FILE_APPEND);
        });

        HardCoreFilter::register();
        HardCore::register();
    }
}

final class HardCore
{
    const PROTOCOLS = ['file', 'phar'];

    public static function register()
    {
        foreach (self::PROTOCOLS as $protocol) {
            stream_wrapper_unregister($protocol);
            stream_wrapper_register($protocol, self::class);
        }
    }

    public static function unregister()
    {
        foreach (self::PROTOCOLS as $protocol) {
            set_error_handler(function () {
            });
            stream_wrapper_restore($protocol);
            restore_error_handler();
        }
    }

    public function __construct()
    {
    }

    public function dir_closedir(): bool
    {
        closedir($this->resource);

        return true;
    }

    public function dir_opendir(string $path, int $options): bool
    {
        $this->resource = $this->wrapCallWithContext('opendir', $path);

        return false !== $this->resource;
    }

    public function dir_readdir()
    {
        return readdir($this->resource);
    }

    public function dir_rewinddir(): bool
    {
        rewinddir($this->resource);

        return true;
    }

    public function mkdir(string $path, int $mode, int $options): bool
    {
        $recursive = (bool) ($options & STREAM_MKDIR_RECURSIVE);

        return $this->wrapCallWithContext('mkdir', $path, $mode, $recursive);
    }

    public function rename(string $path_from, string $path_to): bool
    {
        return $this->wrapCallWithContext('rename', $path_from, $path_to);
    }

    public function rmdir(string $path, int $options): bool
    {
        return $this->wrapCallWithContext('rmdir', $path);
    }

    public function stream_cast(int $cast_as)
    {
        return $this->resource;
    }

    public function stream_close()
    {
        fclose($this->resource);
    }

    public function stream_eof(): bool
    {
        return feof($this->resource);
    }

    public function stream_flush(): bool
    {
        return fflush($this->resource);
    }

    public function stream_lock(int $operation): bool
    {
        return flock($this->resource, $operation);
    }

    public function stream_metadata(string $path, int $option, $value): bool
    {
        return $this->wrapCall(function (string $path, int $option, $value) {
            $result = false;
            switch ($option) {
                case STREAM_META_TOUCH:
                    if (empty($value)) {
                        $result = touch($path);
                    } else {
                        $result = touch($path, $value[0], $value[1]);
                    }
                    break;
                case STREAM_META_OWNER_NAME:
                case STREAM_META_OWNER:
                    $result = chown($path, $value);
                    break;
                case STREAM_META_GROUP_NAME:
                case STREAM_META_GROUP:
                    $result = chgrp($path, $value);
                    break;
                case STREAM_META_ACCESS:
                    $result = chmod($path, $value);
                    break;
            }

            return $result;
        }, $path, $option, $value);
    }

    public function stream_open(string $path, string $mode, int $options, string &$opened_path = null): bool
    {
        $useIncludePath = (bool) ($options & STREAM_USE_PATH);

        $this->resource = $this->wrapCallWithContext('fopen', $path, $mode, $useIncludePath);

        $including = (bool) ($options & STREAM_OPEN_FOR_INCLUDE);
        if ($including && false !== $this->resource) {
            HardCoreFilter::append($this->resource, $path);
        }

        return false !== $this->resource;
    }

    public function stream_read(int $count): string
    {
        return fread($this->resource, $count);
    }

    public function stream_seek(int $offset, int $whence = SEEK_SET): bool
    {
        return fseek($this->resource, $offset, $whence);
    }

    public function stream_set_option(int $option, int $arg1, int $arg2): bool
    {
        switch ($option) {
            case STREAM_OPTION_BLOCKING:
                return stream_set_blocking($this->resource, $arg1);
            case STREAM_OPTION_READ_TIMEOUT:
                return stream_set_timeout($this->resource, $arg1, $arg2);
            case STREAM_OPTION_WRITE_BUFFER:
                return stream_set_write_buffer($this->resource, $arg1);
            case STREAM_OPTION_READ_BUFFER:
                return stream_set_read_buffer($this->resource, $arg1);
        }
    }

    public function stream_stat(): array
    {
        $stats = fstat($this->resource);

        unset($stats['size']);

        return $stats;
    }

    public function stream_tell(): int
    {
        return ftell($this->resource);
    }

    public function stream_truncate(int $new_size): bool
    {
        return ftruncate($this->resource, $new_size);
    }

    public function stream_write(string $data): int
    {
        return fwrite($this->resource, $data);
    }

    public function unlink(string $path): bool
    {
        return $this->wrapCallWithContext('unlink', $path);
    }

    public function url_stat(string $path, int $flags)
    {
        $result = @$this->wrapCall('stat', $path);
        if (false === $result) {
            $result = null;
        }

        return $result;
    }

    private function wrapCallWithContext(callable $function, ...$args)
    {
        if ($this->context) {
            $args[] = $this->context;
        }

        return $this->wrapCall($function, ...$args);
    }

    private function wrapCall(callable $function, ...$args)
    {
        try {
            foreach (self::PROTOCOLS as $protocol) {
                set_error_handler(function () {
                });
                stream_wrapper_restore($protocol);
                restore_error_handler();
            }

            return $function(...$args);
        } catch (\Throwable $e) {
            return false;
        } finally {
            foreach (self::PROTOCOLS as $protocol) {
                stream_wrapper_unregister($protocol);
                stream_wrapper_register($protocol, self::class);
            }
        }
    }
}

class HardCoreFilter extends php_user_filter
{
    const NAME = 'php-hardcode-filter';

    protected $buffer = '';

    public static function append($resource, string $path)
    {
        $ext = pathinfo($path, PATHINFO_EXTENSION);
        stream_filter_append(
            $resource,
            self::NAME,
            STREAM_FILTER_READ,
            [
                'ext' => $ext,
                'path' => $path,
            ]
        );
    }

    public static function register()
    {
        stream_filter_register(self::NAME, static::class);
    }

    public function filter($in, $out, &$consumed, bool $closing): int
    {
        while ($bucket = stream_bucket_make_writeable($in)) {
            $this->buffer .= $bucket->data;
            $consumed += $bucket->datalen;
        }
        if ($closing) {
            $buffer = $this->doFilter($this->buffer, $this->params['path'], $this->params['ext']);
            $bucket = stream_bucket_new($this->stream, $buffer);
            stream_bucket_append($out, $bucket);
        }

        return PSFS_PASS_ON;
    }

    private function doFilter($buffer, $path, $ext): string
    {
        if ('php' !== $ext) {
            return $buffer;
        }

        if (0 !== strpos($buffer, "<?php\n")) {
            return $buffer;
        }

        $buffer = str_replace("<?php\n", "<?php\ndeclare(ticks=1);\n", $buffer);

        return $buffer;
    }
}

segfault.php

<?php

require __DIR__.'/HardCoreDebugLogger.php';
declare(ticks=1); // We need tick in this file
HardCoreDebugLogger::register();

function a()
{
    b();
}

function b()
{
     c();
}

function c()
{
    $a = 1 + 2;

    "".(new Crash());
}

class Crash
{
    public function __tostring()
    {
        return "".$this;
    }
}

a();

Needs a HOWTO file :D

Needs a HOWTO file :D
Here's how to use it https://jolicode.com/blog/find-segfaults-in-php-like-a-boss

This just saved my day! 😱

Love it. 👍

Doesn't work unfortunately (using PHP 7.4). It's causing a parse error:

Fatal error: Uncaught ParseError: syntax error, unexpected end of file in /app/vendor/symfony/framework-bundle/Test/KernelTestCase.php:142

Any idea what could be wrong? The original file has correct syntax of course.

What's the content of the file after editing ? (You need to edit this gist to make it work

Not sure what you're asking, the script doesn't actually edit the files... Also which file do you mean? In case you mean the return value of HardCoreFilter::doFilter() then nothing suspicious there, I dumped it and the buffer contains the original contents + declare ticks...

My suspicions:

1. Most likely there is a problem with HardCoreFilter::filter() changing the length of the file. I believe that the new length is not taken into account so a few characters at the end of the file will be cut off. To confirm this I added some newlines into the KernelTestCase.php (enough to cover the length of the added declare) and indeed the error moved into a different file because now it only cuts off useless whitespace.
2. This script likely won't work if there is <?php declare(strict_types = 1); - not quite sure how declare should look when you need both strict_types and ticks. But anyway the KernelTestCase.php file does NOT have strict types. But it's something to look into and fix after the first bug.

Line 285: $bucket = stream_bucket_new($this->stream, $buffer); .... $this->stream is never defined anywhere?

This seems potentially cool but it definitely does not function in 8.1. I'm not familiar enough with the methods involved to get it working anyway and I've already chased down 6 errors in it. (I know it probably worked fine in the past, but now, they're errors.)

@peter-at-bpt did you make it work?

Hi all, I have fixed the script for php 7.4+

Hello @lyrixx
Thanks for this script, it helps me a lot to find origin of a segmentation fault with PHP 8.2.0-dev.
BTW, I've some deprecation messages that may be fixed easily

Deprecated: Creation of dynamic property HardCore::$resource is deprecated

Deprecated: Creation of dynamic property HardCore::$context is deprecated

I've added into HardCore class following entries

    private $resource;

    public $context;

Got another error : Fatal error: Uncaught TypeError: HardCore::stream_metadata(): Return value must be of type bool, null returned

Reason is https://gist.github.com/lyrixx/56dfc48fb7e807dd2a229813da89a0dc#file-hardcoredebuglogger-php-L115 signature (return type hint is bool) while closure used on wrapCall does not return any boolean !

Tests run with PHP 8.2.0RC4

llaville mentioned in a bug report for another project that the stack trace being logged has the wrong line number and points at a blank line: https://github.com/doctrine/dbal/blob/3.4.5/src/Driver/PDO/SQLite/Driver.php#L31

$buffer = str_replace("<?php\n", "<?php\ndeclare(ticks=1);\n", $buffer); the original string had 1 newline. The replacement string has 2 newlines. So line 31 in the renamed file is actually line 30

A fix would be to use "<?php declare(ticks=1);\n" instead

(Aside: I don't need this personally. For anyone who does run into this use case - Checking the first outputs of token_get_all against the token type constants (T_*) would also allow checking for other edge cases, e.g. a file that already has a declare)

#!/usr/bin/env php
<?php

<?php // filename.php

Sometimes, a segfaults happen, but you don't know where, and your PHP installation does not have tools to find it.

I didn't realize you could override the file stream wrapper. Neat - there have been times where this would have been useful.

gdb is useful on platforms where it is available, for segfaults, though agreed it doesn't work in all cases (e.g. no idea how to set it up on a web server for a spurious issue, for example).

Or sometime, you think PHP is hanging, but you don't know where. You may use xdebug, but you don't want to click so many times on the "next call" button.

and https://github.com/adsr/phpspy - this is a relatively new tool, if your PHP installation and your permissions allow for it

Thanks for the reports 👍

Do anyone have a link to a gist that is up-to-date?