8000 Deprecated error are logged on production · Issue #26267 · symfony/symfony · GitHub
[go: up one dir, main page]
Skip to content

Deprecated error are logged on production #26267

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
soullivaneuh opened this issue Feb 22, 2018 · 14 comments · Fixed by #26504
Closed

Deprecated error are logged on production #26267

soullivaneuh opened this issue Feb 22, 2018 · 14 comments · Fixed by #26504

Comments

@soullivaneuh
Copy link
Contributor
Q A
Bug report? yes
Feature request? no
BC Break report? no
RFC? no
Symfony version 3.4.4

I have a env.php file with the following line to set the error reporting level:

error_reporting(E_ALL & ~E_DEPRECATED & ~E_USER_DEPRECATED & ~E_STRICT);

This file is dumped on the composer autoload thanks to this configuration:

{
    "autoload": {
        "psr-4": { "": "src/" },
        "files": [
            "app/env.php",
            "app/AppKernel.php"
        ]
    },
    "autoload-dev": {
        "psr-4": {
            "Dev\\": "src-dev",
            "Tests\\": "tests/"
        },
        "files": [
            "app/env_dev.php",
            "vendor/symfony/symfony/src/Symfony/Component/VarDumper/Resources/functions/dump.php"
        ]
    },
}

And of course, the composer dump is called with --no-dev on the production server.

Currently, if a exception is thrown on production and deprecated error are triggered, they are logged on the production log file.

So I start with this tiny test:

require_once __DIR__.'/vendor/autoload.php';

var_dump(error_reporting());

trigger_error('This is a deprecation.', E_USER_DEPRECATED);
trigger_error('This is an error.', E_USER_ERROR);

And here is the result:

$ php current/test.php 
int(6143)
PHP Fatal error:  This is an error. in /var/www/project/prod/releases/20180221183905/test.php on line 10

It works. The deprecated error is ignored and the error_reporting value is 6143.

First, we can supposed the error_reporting is changed later. So I tried with this simple controller action:

public function failAction(): void
{
    trigger_error('Error reporting: '.error_reporting(), E_USER_DEPRECATED);
    throw new \Exception('Test exception with error reporting: '.error_reporting());
}

After a call of this action, I have the following log:

$ grep -B1 'Test exception' shared/var/logs/prod-2018-02.log 
[2018-02-22 11:16:37] php.INFO: User Deprecated: Error reporting: 6143 {"exception":"[object] (ErrorException(code: 0): User Deprecated: Error reporting: 6143 at /var/www/project/prod/releases/20180221183905/src/AppBundle/Controller/DefaultController.php:167)"} []
[2018-02-22 11:16:37] request.CRITICAL: Uncaught PHP Exception Exception: "Test exception with error reporting: 6143" at /var/www/project/prod/releases/20180221183905/src/AppBundle/Controller/DefaultController.php line 168 {"exception":"[object] (Exception(code: 0): Test exception with error reporting: 6143 at /var/www/project/prod/releases/20180221183905/src/AppBundle/Controller/DefaultController.php:168)"} []

As you can see, both deprecation and error are logged and the error_reporting value is still the same: 6143

This is why I'm thinking about a bug, because the error reporting level does not change so the deprecation should not be reported.

If you think it is not, I'm curious to know what is the issue. 😄
@nicolas-grekas
Copy link
Member
nicolas-grekas commented Feb 22, 2018 •
edited
Loading

the reporting level affects PHP log system, but what you show here are Symfony logs, which are not affected by the error_reporting level.

@nicolas-grekas
Copy link
Member

Note that you should always silence your deprecations., adding a @ before trigger_error()

@soullivaneuh
Copy link
Contributor Author

but what you show here are Symfony logs, which are not affected by the error_reporting level

What do you mean? When you call a trigger error, you have to set a PHP error level. Why error_reporting does not affect Symfony logs?

Here is my production configuration:

monolog:
    handlers:
        # Buffer the logs. Use them only on errors.
        main:
            type: fingers_crossed
            action_level: error
            handler: buffer
            # @see https://github.com/symfony/symfony/pull/23707
            activation_strategy: AppBundle\Monolog\Handler\FingersCrossed\HttpExcludeActivationStrategy
            channels: ['!nexy_crypt']
        console:
            type: console
            process_psr_3_messages: false
        # Buffer the logs before send it. This is useful for async notification.
        buffer:
            type: buffer
            handler: bridge
        bridge:
            type: group
            members: [file, mail, slack]
        file:
            type: rotating_file
            max_files: 12
            date_format: 'Y-m'
            path: '%kernel.logs_dir%/%kernel.environment%.log'
            level: debug
        mail:
            type: swift_mailer
            from_email: noreply@domain.com
            to_email: sullivan@domain.com
            subject: App error
            level: debug
        slack:
            type: slackwebhook
            webhook_url: '%slack_endpoint%'
            channel: '#errors'
            level: error
            include_extra: true

Note that you should always silence your deprecations., adding a @ before trigger_error()

Well, maybe. But this is not the issue. It's just a sample, I have a bench of deprecation errors thrown by vendor libraries and Symfony itself, like this one:

[2018-02-01 09:59:14] php.INFO: User Deprecated: The "nelmio_api_doc.form.extension.description_form_type_extension" service is private, checking for its existence is deprecated since Symfony 3.2 and will fail in 4.0. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The \"nelmio_api_doc.form.extension.description_form_type_extension\" service is private, checking for its existence is deprecated since Symfony 3.2 and will fail in 4.0. at /var/www/n-admin/prod/releases/20180201082825/vendor/symfony/symfony/src/Symfony/Component/DependencyInjection/Container.php:224)"} []

@soullivaneuh
Copy link
Contributor Author
soullivaneuh commented Feb 23, 2018 •
edited
Loading

Ok I foudn why I have the deprecated, I have this part on the framework section:

framework:
    php_errors:
        log: true

But that still does not make sense to me. PHP errors should be logged respecting the error_reporting level of it, am I wrong?

If I remove it, I indeed don't have the deprecation, but not event the other level like warnings.

@soullivaneuh
Copy link
Contributor Author
soullivaneuh commented Feb 23, 2018 •
edited
Loading

The problem is caused by this code part:

symfony/src/Symfony/Component/HttpKernel/EventListener/DebugHandlersListener.php

Lines 55 to 56 in c12c078

$this->levels = null === $levels ? E_ALL : $levels;
$this->throwAt = \is_int($throwAt) ? $throwAt : (null === $throwAt ? null : ($throwAt ? E_ALL : null));

In a nutshell, if no error level is provided, it will take E_ALL as default.

So I think we have two issues here:

  1. log and throw keys of php_errors configuration should accept error level instead of true in order to allows more configuration
  2. If no error level is provided to DebugHandlersListener, it should fallback to the value of error_reporting, not E_ALL. If this is not possible for some reasons, it should be at least configurable on the framework level.

What do you think?

TIP: Here is a workaround using the compiler pass:

/**
 * {@inheritdoc}
 */
public function process(ContainerBuilder $container)
{
    $container->getDefinition('debug.debug_handlers_listener')
        ->replaceArgument(2, error_reporting());
}

@Simperfit
Copy link
Contributor

That could be a good way of handling it, we have to look if it's possible to use the error_reporting value.

+1.

@nicolas-grekas
Copy link
Member

error_reporting() holds a runtime value. It should not be used to configure a service/event.
The current logic makes sense to me: you configure the service using regular static config, and runtime is taken care of in ErrorHandler.

@soullivaneuh
Copy link
Contributor Author

It should not be used to configure a service/event.

On this particular case (PHP error logging on Symfony log), I don't see why it should not be used. 🤔

The current logic makes sense to me: you configure the service using regular static config

In any case, we just can't change it from the configuration for now.

@nicolas-grekas
Copy link
Member
nicolas-grekas commented Mar 1, 2018 •
edited
Loading

$container->getDefinition('debug.debug_handlers_listener')->replaceArgument(2, error_reporting());

I would not recommend to configure the logged errors based on runtime configuration. e.g. error_reporting() goes to zero just with an @. You can never be sure where its value comes from at runtime, by definition of "runtime value".

But I understand you'd like to configure the 3rd argument of "debug.debug_handlers_listener".
What about enhancing the configuration so that it allows so? Could be just allow passing a bitfield to framework.php_errors.log, or adding a parameter like debug.error_handler.log_at, to complement the existing debug.error_handler.throw_at.

@Simperfit Simperfit mentioned this issue Mar 13, 2018
Merged
@soullivaneuh
Copy link
Contributor Author

If I can configure error level for reporting, with runtime value or not, I'm fine with it. 👍

@fabpot fabpot closed this as completed Mar 27, 2018
fabpot added a commit that referenced this issue Mar 27, 2018
@fabpot
feature #26504 [FrameworkBundle] framework.php_errors.log now accept …
44a6f60 
…a log level (Simperfit)

This PR was merged into the 4.1-dev branch.

Discussion
----------

[FrameworkBundle] framework.php_errors.log now accept a log level

| Q             | A
| ------------- | ---
| Branch?       | master
| Bug fix?      | no
| New feature?  | yes <!-- don't forget to update src/**/CHANGELOG.md files -->
| BC breaks?    | no     <!-- see https://symfony.com/bc -->
| Deprecations? | no <!-- don't forget to update UPGRADE-*.md files -->
| Tests pass?   | yes    <!-- please add some, will be required by reviewers -->
| Fixed tickets | #26267   <!-- #-prefixed issue number(s), if any -->
| License       | MIT
| Doc PR        |  todo <!-- required for new features -->

We are testing that `framework.php_errors.log` is either a bool or an int (set the value of the log level you want).
This fixes #26267, so it gives a way to not log some level on production.

Commits
-------

664f821 [FrameworkBundle] framework.php_errors.log now accept a log level
@mareksuscak
Copy link

Ok I foudn why I have the deprecated, I have this part on the framework section:

framework:
    php_errors:
        log: true

But that still does not make sense to me. PHP errors should be logged respecting the error_reporting level of it, am I wrong?

If I remove it, I indeed don't have the deprecation, but not event the other level like warnings.

That likely stemmed from the framework bundle flex recipe which makes me wonder if it really should be the default.

It bit us when we moved to latest Symfony and hundreds of deprecation logs started appearing in the logs for every single request. The performance was terrible. Moreover, according to the framework bundle reference, the default option should always reflect the debug mode option.

cc @fabpot

MKodde referenced this issue in OpenConext/Stepup-AzureMFA Jan 22, 2020
@MKodde
Show NOTICES and up
6e63c4d 
For now disabled the framework php_erros log property to false. And
setting the monolog logger to log notices and upwards. Only when an
error occurs.
@acantepie
Copy link

In my case framework.php_errors.log setted to false does nothing...

My solution after upgrade an old project from SF 3.4 to 4.4:

Disable LoggerDataCollector :

    Symfony\Component\HttpKernel\DataCollector\LoggerDataCollector:
        tags:
            - {name: data_collector}
        bind:
            $logger: null

Exclude php channel from your monolog handlers :

monolog:
    handlers:
        symfony:
            type: stream
            channels: ["!php"]

Transform instantly hundreds of deprecations to zero.

@gggeek
Copy link
gggeek commented Apr 15, 2021 •
edited
Loading

@acantepie filtering out a specific channel / level in monolog is a workaround imho, as there is no 'nice' way to specifically target 'only php E_USER_DEPRECATED' errors. Your configuration will happily hide away eg. warnings generated by using trigger_error(E_USER_WARNING). Whether that is acceptable, it is up to every app to decide.

The commit referenced above seems a better solution, assuming that it works ;-)

@gggeek
Copy link
gggeek commented Apr 15, 2021 •
edited
Loading

ps: I managed to get this monolog config working, on Sf 3, to filter as little as possible besides E_USER_DEPRECATED:

e_user_deprecated_filter:
    type: filter
    accepted_levels: ['info']
    channels: ['php']
    handler: blackhole
    bubble: false

... other loggers
 
# keep this last
blackhole:
    type: "null"

@watarukashii watarukashii mentioned this issue Feb 25, 2022
Closed
@watarukashii watarukashii mentioned this issue Mar 11, 2022
Merged
15 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[FrameworkBundle] framework.php_errors.log now accept a log level Simperfit/symfony
7 participants
@fabpot @nicolas-grekas @gggeek @mareksuscak @soullivaneuh @Simperfit @acantepie
0