inpsyde / Wonolog

Monolog-based logging package for WordPress.
https://inpsyde.github.io/Wonolog/
MIT License
172 stars 17 forks source link

[Bug]: error_levels not respected in log_php_errors() #80

Open frugan-dev opened 1 month ago

frugan-dev commented 1 month ago

Description of the bug

I'm using this configuration:

if (\defined('Inpsyde\Wonolog\LOG')) {

            // my code

            Wonolog\bootstrap($myDefaultHandler, Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR)
                ->log_php_errors( E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED & ~E_USER_NOTICE )
                ->use_handler($myEmailHandler)
                ->use_processor(static function (array $record) {

                    // my code

                    return $record;
                })
            ;
}

but i don't see any PHP-ERROR errors in the logs.

I also tried removing error levels log_php_errors(null) or changing to log_php_errors(E_ALL), but the logs don't track errors like PHP-ERROR.

Vice versa if I remove the second argument Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR, my error levels E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED & ~E_USER_NOTICE are not respected, because i see this in the logs:

[2024-07-19 10:46:10] PHP-ERROR.NOTICE: Function register_rest_route was called incorrectly. The REST API route definition...
[2024-07-19 10:46:22] PHP-ERROR.NOTICE: Unparenthesized `a ? b : c ? d : e` is deprecated. Use either `(a ? b : c) ? d : e` or `a ? b : (c ? d : e)`...

Am I doing something wrong in the configuration?

Reproduction instructions

.

Expected behavior

I expect to see PHP-ERROR errors in the logs, based on the error levels E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED & ~E_USER_NOTICE passed as arguments of log_php_errors().

Environment info

Relevant log output

No response

Additional context

No response

Code of Conduct

gmazzap commented 1 month ago

To log PHP errors, either you don't pass the second argument or you also pass Wonolog\LOG_PHP_ERRORS.

It is expected that if you pass only Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR then no PHP errors are logged.

Regarding the levels, Wonolog does not handle that logic, PHP does that.

In fact, the value you pass to ->log_php_errors() is directly passed to set_error_handler() as second parameter, see https://github.com/inpsyde/Wonolog/blob/a1cc3192df1d788f2335d009385a362df5414af4/src/Controller.php#L105

So the issue is that you have: WP_DEBUG_LOG=/my-custom-path/debug.log.

That means you're telling WP that's your log file.

Because the Wonolog logger is not registered for deprecated notices (due to second argument), it's WP that ends up writing those logs because of this: https://github.com/WordPress/WordPress/blob/cd610922d012929786bf04d8a58cfea6b51ce7a4/wp-includes/load.php#L602-L603

frugan-dev commented 1 month ago

Hi @gmazzap, thanks for your detailed response.

To log PHP errors, either you don't pass the second argument or you also pass Wonolog\LOG_PHP_ERRORS.

It is expected that if you pass only Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR then no PHP errors are logged.

However, in the documentation the example shows the case in which Wonolog\LOG_PHP_ERRORS is not passed as second argument, but PHP errors are still logged by explicitly calling Wonolog\bootstrap( ... )->log_php_errors(). Does this only apply when using Wonolog\USE_DEFAULT_NONE? What changes if instead of calling the method log_php_errors() via the bootstrap function, you call it later with Wonolog\bootstrap( ... )->log_php_errors()?

frugan-dev commented 1 month ago

I've looked into the code a little deeper, and I expect this to work (i.e. logs are traced) respecting the $error_types passed as an argument.

Wonolog\bootstrap($myDefaultHandler, Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR)
    ->log_php_errors( E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED & ~E_USER_NOTICE )
;

The reason this doesn't happen is that, by calling the method ->log_php_errors( ... ) manually, the PHP_ERROR channel isn't registered. In fact, the channel PHP_ERROR registration by add_filter() occurs AFTER the filter Channels::FILTER_CHANNELS is applied by the setup() method here.

Since it doesn't seem possible to delay the initialization of the setup() method using Wonolog\bootstrap(), wouldn't it be better to add a bitmask flag (i.e. Wonolog\DISABLE_SETUP) to disable the automatic setup, giving the possibility to run the setup method manually at the end of everything else, like this?

Wonolog\bootstrap($myDefaultHandler, Wonolog\USE_DEFAULT_HOOK_LISTENERS | Wonolog\USE_DEFAULT_PROCESSOR | Wonolog\DISABLE_SETUP)
    ->log_php_errors( E_ALL & ~E_NOTICE & ~E_STRICT & ~E_DEPRECATED & ~E_USER_NOTICE )
    ->setup()
;
gmazzap commented 1 month ago

Thank you for your investigation.

This is probably regression added at some point because I remember this used to work. The regression might not have been noticed before because Monolog v1 is not used much today.

We are moving our efforts to Monolog v2 and the next v3.

TBH I would like to solve it in a way that would work transparently, without asking the consumer to pass another flag.

I'm thinking of something like:

  1. We add to Channels an add_channel() method that would directly append the channel to the $channels array if it is not there yet.
  2. Controller::log_php_errors() would use this new method instead of relying on the filter to push the new channel

PS: Have you considered switching to Monolog v2? It's still in beta... but is pretty stable by now and we might move to stable soon. The configuration is different in that version and this problem would not exist.

frugan-dev commented 1 month ago

Hi @gmazzap, your solution seems more elegant, I look forward to trying it as soon as possible!

I hadn't considered v2, but if you say it's stable enough, I'll try to upgrade soon.

Thank you, and congrats on the project!