merged branch kaiwa/loglevel (PR #1073)

Commits
-------

cdf4b6a Checked log levels
a45d3ee Reverted last commit
529381b ControllerNotFound: Changed log level from info to error. Also moved throw exception code block up, to prevent the message from beeing logged multiple times.
7c29e88 Changed log level of "Matched route ..." message from info to debug
dca09fd Changed log level of "Using Controller ..." message from info to debug

Discussion
----------

Log levels

Just wanted to ask if the log level INFO is still correct for these messages?

As there are only four log levels left (DEBUG, INFO, WARNING, ERROR), DEBUG might be the more appropriate level for these messages now.

Let me give an example: An application is logging user actions (maybe to database) in order to assure comprehensibility, e. g. "User %s deleted post %d", "User %s written a message to user %s". These are not warnings of course, so the only suitable log level is INFO.
But they will be thrown together with these very common (at least two per request?) "Using controller..." and "Matched route..." messages when choosing INFO as log level.

---------------------------------------------------------------------------

by Seldaek at 2011/05/24 07:13:18 -0700

Agreed, this stuff is framework debug information.

---------------------------------------------------------------------------

by fabpot at 2011/05/24 08:53:24 -0700

Why do you want to change these two specific ones? The framework uses the INFO level at other places too. Is it a good idea to say that the framework only logs with DEBUG?

---------------------------------------------------------------------------

by stof at 2011/05/24 09:12:53 -0700

Doctrine logs at the INFO level too and I think it is useful to keep it as INFO. Being able to see the queries without having all DEBUG messages of the event dispatcher and security components is useful IMO.

---------------------------------------------------------------------------

by Seldaek at 2011/05/25 02:30:24 -0700

Yeah, that's true, maybe we just need to reintroduce (again, meh:) NOTICE between INFO and WARNING.

@kaiwa Of course the other way could be that you just add your DB handler to the app logger stack. That could be done in a onCoreRequest listener or such, basically you'd have to call `->pushHandler($yourDBHandler)` on the `monolog.logger.app` service. That way your messages will flow to it, but it won't receive noise from the framework stuff since those log on monolog.logger.request and other log channels.

---------------------------------------------------------------------------

by fabpot at 2011/05/25 02:48:26 -0700

@Seldaek: I don't think we need another level. We just need to come up with a standard rules about the usage of each level. Adapted from log4j:

* ERROR: Other runtime errors or unexpected conditions.
* WARN: Use of deprecated APIs, poor use of API, 'almost' errors, other runtime that are undesirable or unexpected, but not necessarily "wrong" (unable to write to the profiler DB, ).
* INFO: Interesting runtime events (security infos like the fact the user is logged-in or not, SQL logs, ...).
* DEBUG: Detailed information on the flow through the system (route match, security flow infos like the fact that a token was found or that remember-me cookie is found, ...).

What do you think?

---------------------------------------------------------------------------

by stloyd at 2011/05/25 02:53:38 -0700

+1 for this standard (also this PR can be merged then), but we should review code for other "wrong" log levels usage (if everyone accept this standard)

---------------------------------------------------------------------------

by fabpot at 2011/05/25 02:55:07 -0700

I won't merge this PR before all occurrences of the logger calls have been reviewed carefully and changed to the right level.

---------------------------------------------------------------------------

by kaiwa at 2011/05/25 02:58:44 -0700

@fabpot: Just noticed these two occurring for every request in my log file. You are right, there are other places where this changes must be applied if we will change the log level.

@stof: Hmm, i see. It is not possible to set the logger separately for each bundle, is it? That maybe would solve the problem. If somebody is interested in seeing the queries, he could set the log handler level to DEBUG for doctrine bundle, but still use INFO for the framwork itself. Plus he could even define a different output file or a completely different handler.

I'm not sure if something like that is possible already (?) or realizable at all... just came into my mind.

---------------------------------------------------------------------------

by Seldaek at 2011/05/25 03:01:07 -0700

Just FYI, from Monolog\Logger (which has CRITICAL and ALERT):

     * Debug messages
    const DEBUG = 100;

     * Messages you usually don't want to see
    const INFO = 200;

     * Exceptional occurences that are not errors
     * This is typically the logging level you want to use
    const WARNING = 300;

     * Errors
    const ERROR = 400;

     * Critical conditions (component unavailable, etc.)
    const CRITICAL = 500;

     * Action must be taken immediately (entire service down)
     * Should trigger alert by sms, email, etc.
    const ALERT = 550;

The values kind of match http error codes too, 4xx are expected errors that are not really important (404s etc) and 5xx are server errors that you'd better fix ASAP. I'm ok with the descriptions, but I think alert and critical should be included too. I'll probably update Monolog docblocks to match whatever ends up in the docs.

---------------------------------------------------------------------------

by Seldaek at 2011/05/25 03:03:21 -0700

@kaiwa you can do a lot, but not from the default monolog configuration entry, I'm not sure if we can really make that fully configurable without having a giant config mess. Please refer to my [comment above](https://github.com/symfony/symfony/pull/1073#issuecomment-1234316) to see how you could solve it. Maybe @fabpot has an idea how to make this more usable though.

---------------------------------------------------------------------------

by stof at 2011/05/25 03:19:43 -0700

@Seldaek the issue is that the different logging channels are only know in the compiler pass, not in the DI extension. So changing the level in the extension is really hard IMO.
Thus, the handlers are shared between the different logging channels (needed to open the log file only once for instance, or to send a single mail instead of one per channel) and the level is handled in the handlers, not the logger.

I'm +1 for the standard, by adding the distinction between 400 and 500 status calls using ERROR and CRITICAL (which is already the case in the code).

@kaiwa do you have time to review the calls to the logger between DEBUG and INFO or do you prefer I do it ? For instance, the Security component currently logs all message at DEBUG level and some of them should be INFO.

---------------------------------------------------------------------------

by kaiwa at 2011/05/25 04:31:04 -0700

@stof ok i'll do that

---------------------------------------------------------------------------

by kaiwa at 2011/05/25 12:22:51 -0700

Need some help :) I came across `ControllerNameParser::handleControllerNotFoundException()` which leads to redundant log messages currently:

>[2011-05-25 20:53:16] request.INFO: Unable to find controller "AppBaseBundle:Blog" - class "App\BaseBundle\Controller\BlogController" does not exist.

>[2011-05-25 20:53:16] request.ERROR: InvalidArgumentException: Unable to find controller "AppBaseBundle:Blog" - class "App\BaseBundle\Controller\BlogController" does not exist. (uncaught exception) at /home/ruth/symfony3/src/Symfony/Bundle/FrameworkBundle/Controller/ControllerNameParser.php line 87

Is it necessary to call `$this->logger->info($log);` if the InvalidArgumentException will be logged anyway?

---------------------------------------------------------------------------

by stof at 2011/05/25 12:39:22 -0700

Well, the issue is that the ControllerNameParser logs messages and then uses them to throw an exception. I guess the logging call should be removed as it is redundant with the one of the ExceptionListener. @fabpot thoughts ?

---------------------------------------------------------------------------

by kaiwa at 2011/05/27 11:39:25 -0700

I checked all debug, info and log calls. Sometimes it is hard to distinguish between the levels, so it would be great if someone reviews @cdf4b6a. @stof, maybe you want to take a look?

---------------------------------------------------------------------------

by kaiwa at 2011/05/31 12:52:07 -0700

@stof, thanks for your comments. I added some replies above, please let me know your suggestions.

---------------------------------------------------------------------------

by stof at 2011/05/31 14:04:22 -0700

@kaiwa As I said before, all the security logging calls should be DEBUG (most of them) or INFO (the one syaing that authentication succeeded for instance), but not WARN or ERROR as the exception don't go outside the firewall.

11 files changed, 22 insertions, 19 deletions

diff --git a/Core/Authentication/Provider/UserAuthenticationProvider.php b/Core/Authentication/Provider/UserAuthenticationProvider.php
index 8183c62..41ab65b 100644
--- a/Core/Authentication/Provider/UserAuthenticationProvider.php
+++ b/Core/Authentication/Provider/UserAuthenticationProvider.php
@@ -80,7 +80,7 @@ abstract class UserAuthenticationProvider implements AuthenticationProviderInter
             return $authenticatedToken;
         } catch (UsernameNotFoundException $notFound) {
             if ($this->hideUserNotFoundExceptions) {
-                throw new BadCredentialsException('Bad credentials', 0, $notFound);
+                throw new BadCredentialsException(sprintf('Bad credentials for user "%s"', $username), 0, $notFound);
             }
 
             throw $notFound;
diff --git a/Http/Firewall/AbstractAuthenticationListener.php b/Http/Firewall/AbstractAuthenticationListener.php
index c35ab35..bf61057 100644
--- a/Http/Firewall/AbstractAuthenticationListener.php
+++ b/Http/Firewall/AbstractAuthenticationListener.php
@@ -183,7 +183,7 @@ abstract class AbstractAuthenticationListener implements ListenerInterface
     private function onFailure(GetResponseEvent $event, Request $request, AuthenticationException $failed)
     {
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Authentication request failed: %s', $failed->getMessage()));
+            $this->logger->info(sprintf('Authentication request failed: %s', $failed->getMessage()));
         }
 
         $this->securityContext->setToken(null);
@@ -221,7 +221,10 @@ abstract class AbstractAuthenticationListener implements ListenerInterface
     private function onSuccess(GetResponseEvent $event, Request $request, TokenInterface $token)
     {
         if (null !== $this->logger) {
-            $this->logger->debug('User has been authenticated successfully');
+            $this->logger->info(sprintf(
+                'User "%s" has been authenticated successfully',
+                $token->getUsername()
+            ));
         }
 
         $this->securityContext->setToken($token);
diff --git a/Http/Firewall/AbstractPreAuthenticatedListener.php b/Http/Firewall/AbstractPreAuthenticatedListener.php
index 93c161a..332e3f8 100644
--- a/Http/Firewall/AbstractPreAuthenticatedListener.php
+++ b/Http/Firewall/AbstractPreAuthenticatedListener.php
@@ -76,7 +76,7 @@ abstract class AbstractPreAuthenticatedListener implements ListenerInterface
             $token = $this->authenticationManager->authenticate(new PreAuthenticatedToken($user, $credentials, $this->providerKey));
 
             if (null !== $this->logger) {
-                $this->logger->debug(sprintf('Authentication success: %s', $token));
+                $this->logger->info(sprintf('Authentication success: %s', $token));
             }
             $this->securityContext->setToken($token);
 
@@ -88,7 +88,7 @@ abstract class AbstractPreAuthenticatedListener implements ListenerInterface
             $this->securityContext->setToken(null);
 
             if (null !== $this->logger) {
-                $this->logger->debug(sprintf("Cleared security context due to exception: %s", $failed->getMessage()));
+                $this->logger->info(sprintf("Cleared security context due to exception: %s", $failed->getMessage()));
             }
         }
     }
diff --git a/Http/Firewall/BasicAuthenticationListener.php b/Http/Firewall/BasicAuthenticationListener.php
index 72df041..9669853 100644
--- a/Http/Firewall/BasicAuthenticationListener.php
+++ b/Http/Firewall/BasicAuthenticationListener.php
@@ -67,7 +67,7 @@ class BasicAuthenticationListener implements ListenerInterface
         }
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Basic Authentication Authorization header found for user "%s"', $username));
+            $this->logger->info(sprintf('Basic Authentication Authorization header found for user "%s"', $username));
         }
 
         try {
@@ -77,7 +77,7 @@ class BasicAuthenticationListener implements ListenerInterface
             $this->securityContext->setToken(null);
 
             if (null !== $this->logger) {
-                $this->logger->debug(sprintf('Authentication request failed: %s', $failed->getMessage()));
+                $this->logger->info(sprintf('Authentication request failed for user "%s": %s', $username, $failed->getMessage()));
             }
 
             if ($this->ignoreFailure) {
diff --git a/Http/Firewall/ContextListener.php b/Http/Firewall/ContextListener.php
index dccbd5c..950429a 100644
--- a/Http/Firewall/ContextListener.php
+++ b/Http/Firewall/ContextListener.php
@@ -139,7 +139,7 @@ class ContextListener implements ListenerInterface
                 // let's try the next user provider
             } catch (UsernameNotFoundException $notFound) {
                 if (null !== $this->logger) {
-                    $this->logger->debug(sprintf('Username "%s" could not be found.', $user->getUsername()));
+                    $this->logger->warn(sprintf('Username "%s" could not be found.', $user->getUsername()));
                 }
 
                 return null;
diff --git a/Http/Firewall/DigestAuthenticationListener.php b/Http/Firewall/DigestAuthenticationListener.php
index f2e1f9e..5c529da 100644
--- a/Http/Firewall/DigestAuthenticationListener.php
+++ b/Http/Firewall/DigestAuthenticationListener.php
@@ -114,7 +114,7 @@ class DigestAuthenticationListener implements ListenerInterface
         }
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Authentication success for user "%s" with response "%s"', $digestAuth->getUsername(), $digestAuth->getResponse()));
+            $this->logger->info(sprintf('Authentication success for user "%s" with response "%s"', $digestAuth->getUsername(), $digestAuth->getResponse()));
         }
 
         $this->securityContext->setToken(new UsernamePasswordToken($user, $user->getPassword(), $this->providerKey));
@@ -125,7 +125,7 @@ class DigestAuthenticationListener implements ListenerInterface
         $this->securityContext->setToken(null);
 
         if (null !== $this->logger) {
-            $this->logger->debug($authException);
+            $this->logger->info($authException);
         }
 
         $event->setResponse($this->authenticationEntryPoint->start($request, $authException));
diff --git a/Http/Firewall/ExceptionListener.php b/Http/Firewall/ExceptionListener.php
index bedbe4a..5755c2d 100644
--- a/Http/Firewall/ExceptionListener.php
+++ b/Http/Firewall/ExceptionListener.php
@@ -88,7 +88,7 @@ class ExceptionListener
             $token = $this->context->getToken();
             if (!$this->authenticationTrustResolver->isFullFledged($token)) {
                 if (null !== $this->logger) {
-                    $this->logger->info('Access denied (user is not fully authenticated); redirecting to authentication entry point');
+                    $this->logger->debug('Access denied (user is not fully authenticated); redirecting to authentication entry point');
                 }
 
                 try {
@@ -100,7 +100,7 @@ class ExceptionListener
                 }
             } else {
                 if (null !== $this->logger) {
-                    $this->logger->info('Access is denied (and user is neither anonymous, nor remember-me)');
+                    $this->logger->debug('Access is denied (and user is neither anonymous, nor remember-me)');
                 }
 
                 try {
diff --git a/Http/Firewall/RememberMeListener.php b/Http/Firewall/RememberMeListener.php
index cd49ef1..9b144b6 100644
--- a/Http/Firewall/RememberMeListener.php
+++ b/Http/Firewall/RememberMeListener.php
@@ -88,7 +88,7 @@ class RememberMeListener implements ListenerInterface
             }
         } catch (AuthenticationException $failed) {
             if (null !== $this->logger) {
-                $this->logger->debug(
+                $this->logger->warn(
                     'SecurityContext not populated with remember-me token as the'
                    .' AuthenticationManager rejected the AuthenticationToken returned'
                    .' by the RememberMeServices: '.$failed->getMessage()
diff --git a/Http/Firewall/SwitchUserListener.php b/Http/Firewall/SwitchUserListener.php
index c3c46e5..8e45508 100644
--- a/Http/Firewall/SwitchUserListener.php
+++ b/Http/Firewall/SwitchUserListener.php
@@ -88,7 +88,7 @@ class SwitchUserListener implements ListenerInterface
                 $this->securityContext->setToken($this->attemptSwitchUser($request));
             } catch (AuthenticationException $e) {
                 if (null !== $this->logger) {
-                    $this->logger->debug(sprintf('Switch User failed: "%s"', $e->getMessage()));
+                    $this->logger->warn(sprintf('Switch User failed: "%s"', $e->getMessage()));
                 }
             }
         }
@@ -120,7 +120,7 @@ class SwitchUserListener implements ListenerInterface
         $username = $request->get($this->usernameParameter);
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Attempt to switch to user "%s"', $username));
+            $this->logger->info(sprintf('Attempt to switch to user "%s"', $username));
         }
 
         $user = $this->provider->loadUserByUsername($username);
diff --git a/Http/Firewall/UsernamePasswordFormAuthenticationListener.php b/Http/Firewall/UsernamePasswordFormAuthenticationListener.php
index a6b6968..816cae4 100644
--- a/Http/Firewall/UsernamePasswordFormAuthenticationListener.php
+++ b/Http/Firewall/UsernamePasswordFormAuthenticationListener.php
@@ -56,7 +56,7 @@ class UsernamePasswordFormAuthenticationListener extends AbstractAuthenticationL
     {
         if ($this->options['post_only'] && 'post' !== strtolower($request->getMethod())) {
             if (null !== $this->logger) {
-                $this->logger->debug(sprintf('Authentication method not supported: %s.', $request->getMethod()));
+                $this->logger->err(sprintf('Authentication method not supported: %s.', $request->getMethod()));
             }
 
             return null;
diff --git a/Http/RememberMe/AbstractRememberMeServices.php b/Http/RememberMe/AbstractRememberMeServices.php
index a7c63ef..74acdef 100644
--- a/Http/RememberMe/AbstractRememberMeServices.php
+++ b/Http/RememberMe/AbstractRememberMeServices.php
@@ -122,15 +122,15 @@ abstract class AbstractRememberMeServices implements RememberMeServicesInterface
             throw $theft;
         } catch (UsernameNotFoundException $notFound) {
             if (null !== $this->logger) {
-                $this->logger->debug('User for remember-me cookie not found.');
+                $this->logger->info('User for remember-me cookie not found.');
             }
         } catch (UnsupportedUserException $unSupported) {
             if (null !== $this->logger) {
-                $this->logger->debug('User class for remember-me cookie not supported.');
+                $this->logger->err('User class for remember-me cookie not supported.');
             }
         } catch (AuthenticationException $invalid) {
             if (null !== $this->logger) {
-                $this->logger->debug('Remember-Me authentication failed: '.$invalid->getMessage());
+                $this->logger->err('Remember-Me authentication failed: '.$invalid->getMessage());
             }
         }