Authentication exceptions logged before having the chance to get handled #27440

spantaleev · 2018-05-31T08:55:44Z

Symfony version(s) affected: 4.1.0

Description

Seems like ever since #25366, authentication exceptions are first logged, and then handled gracefully (redirecting to a login entrypoint).

If an unauthenticated user hits a route they cannot access (e.g. a homepage route with this firewall rule - { path: ^/, role: ROLE_ADMIN }), what currently happens is:

step 1: Symfony\Component\Security\Http\Firewall\AccessListener rightfully throws an AccessDeniedException exception
step 2: because of its new and high priority level (of 2048 since [HttpKernel] Decouple exception logging from rendering #25366), Symfony\Component\HttpKernel\EventListener\ExceptionListener decides to log this exception: Uncaught PHP Exception AccessDeniedException .... Logging such a CRITICAL error has the bad side-effect of causing Monolog to send me an email.
step 3: because of its (now-comparatively-low) priority level of 1, Symfony\Component\Security\Http\Firewall\ExceptionListener gets triggered. It converts the exception to a (redirect) Response (to the login page), and the website appears to work. However, it's way too late already, as "step 2" (above) already logged the error and sent me an exception email.

Possible Solution

Symfony\Component\Security\Http\Firewall\ExceptionListener can be executed with a higher priority than Symfony\Component\HttpKernel\EventListener\ExceptionListener, so that graceful handling of authentication exceptions can happen before logging.

Changing Symfony\Component\Security\Http\Firewall\ExceptionListener, so that the KernelEvents::EXCEPTION priority is higher (from 1 to 2049) works around the problem.

The text was updated successfully, but these errors were encountered:

senaria · 2018-06-04T10:53:32Z

The exact same problem you described also happens for access denied exceptions.

lyrixx · 2018-06-05T08:55:56Z

I confirm this issue (I did not see it earlier, so I dig a bit :/ )

Here are the logs for the different version of Symfony:

With SF 3.4
===========

[2018-06-05 10:44:22] request.INFO: Matched route "homepage". {"route":"homepage","route_parameters":{"_controller":"AppBundle\\Controller\\DefaultController::indexAction","_route":"homepage"},"request_uri":"http://127.0.0.1:8000/","method":"GET"} []
[2018-06-05 10:44:22] security.INFO: An AuthenticationException was thrown; redirecting to authentication entry point. {"exception":"[object] (Symfony\\Component\\Security\\Core\\Exception\\AuthenticationCredentialsNotFoundException(code: 0): A Token was not found in the TokenStorage. at /tmp/security/vendor/symfony/symfony/src/Symfony/Component/Security/Http/Firewall/AccessListener.php:51)"} []
[2018-06-05 10:44:22] security.DEBUG: Calling Authentication entry point. [] []


With SF 4.0
===========

[2018-06-05 10:51:56] request.INFO: Matched route "homepage". {"route":"homepage","route_parameters":{"_controller":"AppBundle\\Controller\\DefaultController::indexAction","_route":"homepage"},"request_uri":"http://127.0.0.1:8000/","method":"GET"} []
[2018-06-05 10:51:56] security.INFO: An AuthenticationException was thrown; redirecting to authentication entry point. {"exception":"[object] (Symfony\\Component\\Security\\Core\\Exception\\AuthenticationCredentialsNotFoundException(code: 0): A Token was not found in the TokenStorage. at /tmp/security/vendor/symfony/symfony/src/Symfony/Component/Security/Http/Firewall/AccessListener.php:51)"} []
[2018-06-05 10:51:56] security.DEBUG: Calling Authentication entry point. [] []


With SF 4.1
===========
[2018-06-05 10:53:01] request.INFO: Matched route "homepage". {"route":"homepage","route_parameters":{"_route":"homepage","_controller":"AppBundle\\Controller\\DefaultController::indexAction"},"request_uri":"http://127.0.0.1:8000/","method":"GET"} []
[2018-06-05 10:53:01] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Security\Core\Exception\AuthenticationCredentialsNotFoundException: "A Token was not found in the TokenStorage." at /tmp/security/vendor/symfony/symfony/src/Symfony/Component/Security/Http/Firewall/AccessListener.php line 51 {"exception":"[object] (Symfony\\Component\\Security\\Core\\Exception\\AuthenticationCredentialsNotFoundException(code: 0): A Token was not found in the TokenStorage. at /tmp/security/vendor/symfony/symfony/src/Symfony/Component/Security/Http/Firewall/AccessListener.php:51)"} []
[2018-06-05 10:53:01] security.INFO: An AuthenticationException was thrown; redirecting to authentication entry point. {"exception":"[object] (Symfony\\Component\\Security\\Core\\Exception\\AuthenticationCredentialsNotFoundException(code: 0): A Token was not found in the TokenStorage. at /tmp/security/vendor/symfony/symfony/src/Symfony/Component/Security/Http/Firewall/AccessListener.php:51)"} []
[2018-06-05 10:53:01] security.DEBUG: Calling Authentication entry point. [] []

nicolas-grekas · 2018-06-05T09:50:43Z

Ping @ro0NL FYI.
Would anyone like to have a look and send a PR?

ThomasTr · 2018-06-06T08:19:20Z

It seems that excluded_http_codes also doesen't work.

With this config:

monolog:
    handlers:
        main:
            type:                fingers_crossed
            excluded_http_codes: [403, 404]
            action_level:        critical
            handler:             grouped
        grouped:
            type:    group
            members: [streamed, deduplicated]
        streamed:
            type:  stream
            path:  '%kernel.logs_dir%/%kernel.environment%.log'
            level: debug
        deduplicated:
            type:    deduplication
            handler: swift
        swift:
            type:         swift_mailer
            from_email:   'thomas.trautner@bmgmis.de'
            to_email:     'thomas.trautner@bmgmis.de'
            subject:      'An Error Occurred! %%message%%'
            level:        debug
            formatter:    monolog.formatter.html
            content_type: text/html

I still get 403 "Access denied" errors.

ro0NL · 2018-06-06T08:22:13Z

In general i'd like to raise the security exception listener to 2049, sure. But it's quite significant.. and im afraid it affects some users.

We could lower the logging a bit from 2048 to maybe just 10 or so, so the security listener would get 11. But conceptually it's the same problem... changing priorities is tricky.

Another solution would be to introduce a pointer interface to mark exceptions skipped from logging.

lyrixx · 2018-06-06T09:12:36Z

Another solution would be to introduce a pointer interface to mark exceptions skipped from logging.

Like it ;)

nicolas-grekas · 2018-06-07T17:24:54Z

Or log exceptions at -64?

ro0NL · 2018-06-08T07:38:48Z

@nicolas-grekas the intend was to log at high prio, so that it works independent from userland listeners. Those are typically defined with prio > 0 (and most likely < 2048 :)). The issue is it potentially disables logging, hence the PR to decouple it.

That said, i think we should revert it :) given the conflict with the security exception listener. However i'd prefer to meet in the middle, e.g.

security at 513
log/collect at 512
render at 0

ro0NL · 2018-06-08T09:01:22Z

Moreover, we could trigger a deprecation in case there are userland listeners with prio between 0 and 512, in effort to change the prio in 5.0

lyrixx · 2018-06-08T10:06:52Z

@ro0NL There are legit use case to be between 0 & 512 ; In our app we have a LocaleListener

And on another app there is API Platform (so many listeners)

ro0NL · 2018-06-09T07:42:14Z

@lyrixx it would affect exception listeners only ...
@nicolas-grekas rendering happens at -128 in fact :) so i misunderstood your -64 suggestion i guess.

we can log exceptions with with prio 0 (security is prio 1). This creates a range from 0 to -128 for userland listeners to overwrite rendering and preserve standard logging.

This PR was squashed before being merged into the 4.1 branch (closes #27562). Discussion ---------- [HttpKernel] Log/Collect exceptions at prio 0 | Q | A | ------------- | --- | Branch? | 4.1 | Bug fix? | yes | New feature? | no | BC breaks? | no, fixes one | Deprecations? | no | Tests pass? | yes  | Fixed tickets | #27440 | License | MIT | Doc PR | symfony/symfony-docs#...  So that it runs after the security exception listener, which runs at prio 1. Im not sure what to do with the (wrong) changelog entry for 4.1.0 at this point.. should we add a new entry for 4.1.1? Commits ------- 85b832b [HttpKernel] Log/Collect exceptions at prio 0

xabbuh added Security Bug HttpKernel labels May 31, 2018

carsonbot added the Status: Needs Review label May 31, 2018

xabbuh mentioned this issue May 31, 2018

[FrameworkBundle][BC Break] Adding http_exception_listener introduces BC break to exception handling #27212

Closed

ro0NL mentioned this issue Jun 6, 2018

[HttpKernel] Preserve security exceptions #27515

Closed

This was referenced Jun 9, 2018

[HttpKernel] Log/Collect exceptions at prio 0 #27562

Merged

[4.1] AccessDeniedException in production log (dev log too) #27531

Closed

fabpot closed this as completed Jun 10, 2018

xabbuh mentioned this issue Jun 15, 2018

AccessDeniedException is logged as a CRITICAL whenever authentication is required #27608

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Authentication exceptions logged before having the chance to get handled #27440

Authentication exceptions logged before having the chance to get handled #27440

spantaleev commented May 31, 2018

senaria commented Jun 4, 2018 •

edited

Loading

lyrixx commented Jun 5, 2018

nicolas-grekas commented Jun 5, 2018

ThomasTr commented Jun 6, 2018 •

edited

Loading

ro0NL commented Jun 6, 2018

lyrixx commented Jun 6, 2018

nicolas-grekas commented Jun 7, 2018

ro0NL commented Jun 8, 2018 •

edited

Loading

ro0NL commented Jun 8, 2018

lyrixx commented Jun 8, 2018

ro0NL commented Jun 9, 2018

Authentication exceptions logged before having the chance to get handled #27440

Authentication exceptions logged before having the chance to get handled #27440

Comments

spantaleev commented May 31, 2018

senaria commented Jun 4, 2018 • edited Loading

lyrixx commented Jun 5, 2018

nicolas-grekas commented Jun 5, 2018

ThomasTr commented Jun 6, 2018 • edited Loading

ro0NL commented Jun 6, 2018

lyrixx commented Jun 6, 2018

nicolas-grekas commented Jun 7, 2018

ro0NL commented Jun 8, 2018 • edited Loading

ro0NL commented Jun 8, 2018

lyrixx commented Jun 8, 2018

ro0NL commented Jun 9, 2018

senaria commented Jun 4, 2018 •

edited

Loading

ThomasTr commented Jun 6, 2018 •

edited

Loading

ro0NL commented Jun 8, 2018 •

edited

Loading