PHP8.1: Monolog\Handler\NullHandler::$level must not be accessed before initialization (git_commit_message)

[sippsolutions]

Q	A
Version	1.13.0
Bug?	yes
New feature?	no
Question?	no
Documentation?	no

I get the error Monolog\Handler\NullHandler::$level must not be accessed before initialization when I try to use the git_commit_message check. Other checks pass.

My configuration (PHP 8.1)

parameters:
  bin_dir: "./vendor/bin"
  git_dir: "."

grumphp:
  stop_on_failure: true
  ignore_unstaged_changes: false
  tasks:
    git_commit_message:
      enforce_no_subject_trailing_period: true
      enforce_single_lined_subject: true
      max_subject_width: 250
      matchers:
        Must contain issue number: /(XYZ-\d+)|(Merge)/

Steps to reproduce:

cd /tmp
mkdir test-grumphp
cd test-grumphp
php -v # use PHP 8.1!
git init
composer init
composer require phpro/grumphp
vim grumphp.yml # use my grumphp.yml
git add .
git commit -m 'XYZ-1 Test'

Result:

git_commit_message
==================

Typed property Monolog\Handler\NullHandler::$level must not be accessed before initialization

With GrumPHP 1.12.0 (and therefore Monolog 2 instead of 3) the check works (see #1014).

[soulcodex]

Hi guys, this issue may be solved? IDK if comes from gitlab or monolog library but for new projects (at least symfony projects) is a problem because it comes out of box with Monolog v3 :(

[veewee]

Sorry, don't have a lot of free time to spend on this atm.

Did a quick test and it looks like it is an amphp/parallel (serialization) issue. If you disable parallel task execution, it works as expected:

grumphp:
  parallel:
    enabled: false

The issue is caused by the GitRepository that is injected inside the commit_msg task. This one contains the gitonomy/gitlib as dependency, which has the logger as a dependency. Therefore, the logger will be serialized in order to make it available in the amp/parallel worker.

Why it is not able to deserialize the logger is a bit of a mistery to me at this point. Since the level is configured at constructor level and added to a property, it should just deserialize into that. I noticed in v3 of monolog, it is a php81 enum. Not sure how the libraries (laravel/serializable-closure + amp/parallel) deal with that - so need to further investigate that.

[soulcodex]

@veewee thank you for your help, I will try some workarounds to fix this, if I catch a good solution I will post it here

Thx

[veewee]

I put some additional effort in this, but sadly no solution yet. What I found out, is that laraval/serializable-closure v1.2.0 is not able to succesfully serialize/unserialize the task.

I added a dump before and after serialization in \GrumPHP\Runner\TaskHandler\Middleware\ParallelProcessingMiddleware.

Before, the task has a log level:

    class Gitonomy\Git\Repository#358 (10) {
      protected $gitDir =>
      string(49) "/Users/verweto/Projects/github/phpro/grumphp/.git"
      protected $workingDir =>
      string(44) "/Users/verweto/Projects/github/phpro/grumphp"
      protected $objects =>
      array(0) {
      }
      protected $referenceBag =>
      NULL
      protected $logger =>
      class Monolog\Logger#345 (8) {
        protected string $name =>
        string(7) "GrumPHP"
        protected array $handlers =>
        array(1) {
          [0] =>
          class Monolog\Handler\NullHandler#1041 (1) {
            private Monolog\Level $level =>
            enum Monolog\Level::Debug : int(100);
          }

Next it is able to detect the enum and add it to the scope. See https://github.com/laravel/serializable-closure/pull/28/files#diff-03128d5182243a61071cf9e21670e9d9583e7f169bf03348b194db997e501236

Yet after deserializing the task, the log level is uninitialized: (that's what is giving you the error)

  class Gitonomy\Git\Repository#59 (10) {
    protected $gitDir =>
    string(49) "/Users/verweto/Projects/github/phpro/grumphp/.git"
    protected $workingDir =>
    string(44) "/Users/verweto/Projects/github/phpro/grumphp"
    protected $objects =>
    array(0) {
    }
    protected $referenceBag =>
    NULL
    protected $logger =>
    class Monolog\Logger#56 (8) {
      protected string $name =>
      string(7) "GrumPHP"
      protected array $handlers =>
      array(1) {
        [0] =>
        class Monolog\Handler\NullHandler#57 (1) {
          private Monolog\Level $level =>
          *uninitialized*
        }
      }

I tried reproducing a simple test case for this issue so that it can be dealt with in the serializable package, but I haven't found a way to reproduce it inside the pest testsuite of that package. Even tried by injecting a custom symfony container to rule that dependency out as well without any luck. So it looks like that package is behaving correctly.

Of course I did not stop there ... Next step was to rule out amp/parallel-functions. So instead of using parallel(), I switched the implementation to a regular coroutine that runs the serialized closure directly.

        $enqueueParallelTask = function () use ($task, $runnerContext, $next, $currentEnv): Promise {
            $run = new SerializableClosure(function () use($task, $runnerContext, $next, $currentEnv) {
                var_dump($task);
                $_ENV = array_merge($currentEnv, $_ENV);
                /** @var TaskResultInterface $result */
                $result = wait($next($task, $runnerContext));

                return $result;
            });
            $serialized = serialize($run);
            //echo $serialized;
            $deserialized = unserialize($serialized, ['allowed_classes' => true]); // also tried adding ->getClosure()

            return coroutine($deserialized)();
        };

This results in the same failure:

Typed property Monolog\Handler\NullHandler::$level must not be accessed before initialization

When I do inspect the serialized version, I can see that there is no level available in the NullHandler, yet it does get detected in the 'scope' of the serializable closure package.

*handlers";a:1:{i:0;O:27:"Monolog\Handler\NullHandler":0:{}}

So at this point I am pretty sure that the issue is somewhere inside laravel/serializable-closure or maybe even in PHP's serialize/unserialize function, yet I am not able to reproduce a simple test case in order to fix the bug.

Not sure on how to get forward with this issue at this moment. Any help is highly appreciated!

[soulcodex]

@veewee nice catch :sunglasses: maybe should be a problem on __sleep() method in the serialized object ?

[veewee]

It might indeed be related to the sleep method in monologs base-handler. Currently not behind my computer for a couple of weeks, so feel free to play around with it.

[Seldaek]

Hey, so I had a look and indeed it seems to be caused by the __sleep override done in https://github.com/Seldaek/monolog/commit/af7c0a7bda396ed83dcfcf28cda8133d687a7b9c (2.0.0) to fix https://github.com/Seldaek/monolog/issues/365.

The problem is get_object_vars only sees protected/public properties and not the private properties from the child classes. I'll fix that on the Monolog end.

[Seldaek]

I'd be happy if someone can confirm using the latest monolog 2.x-dev or 3.x-dev if this is fixed for you.

[Seldaek]

Well Monolog 2.8.0/3.2.0 are out with the fix so hopefully it helps :)

[sippsolutions]

Thank you @Seldaek , I can confirm this fixes the issue :)

[veewee]

Nice, thanks!

Reopened: Maybe best to reflect this bug in our dependencies as well, so this package can't be installed with the known bug.