feature #13418 [DX] Attempt to improve logging messages with paramete…

…rs (iltar)

This PR was squashed before being merged into the 2.7 branch (closes #13418).

Discussion
----------

[DX] Attempt to improve logging messages with  parameters

| Q             | A
| ------------- | ---
| Bug fix?      | no
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | #12594 (comment)
| License       | MIT
| Doc PR        | n/a

This PR is a follow-up of #12594 `[DX] [HttpKernel] Use "context" argument when logging route in RouterListener`.

I have attempted to improve the log messages, as well as updating the usage context. I wasn't sure if the log messages should end with a `.` or not, if so I can update all messages to confirm a standard.

Commits
-------

ea80c9b [DX] Attempt to improve logging messages with  parameters

src/Symfony/Component/EventDispatcher/Debug/TraceableEventDispatcher.php

@@ -146,7 +146,7 @@ public function getNotCalledListeners()
             $allListeners = $this->getListeners();
         } catch (\Exception $e) {
             if (null !== $this->logger) {
-                $this->logger->info(sprintf('An exception was thrown while getting the uncalled listeners (%s)', $e->getMessage()), array('exception' => $e));
+                $this->logger->info('An exception was thrown while getting the uncalled listeners.', array('exception' => $e));
             }
 
             // unable to retrieve the uncalled listeners

src/Symfony/Component/HttpKernel/Controller/ControllerResolver.php

@@ -51,7 +51,7 @@ public function getController(Request $request)
     {
         if (!$controller = $request->attributes->get('_controller')) {
             if (null !== $this->logger) {
-                $this->logger->warning('Unable to look for the controller as the "_controller" parameter is missing');
+                $this->logger->warning('Unable to look for the controller as the "_controller" parameter is missing.');
             }
 
             return false;

src/Symfony/Component/HttpKernel/EventListener/RouterListener.php

@@ -140,7 +140,7 @@ public function onKernelRequest(GetResponseEvent $event)
             }
 
             if (null !== $this->logger) {
-                $this->logger->info(sprintf('Matched route "%s"', $parameters['_route']), array(
+                $this->logger->info(sprintf('Matched route "%s".', $parameters['_route']), array(
                     'route_parameters' => $parameters,
                     'request_uri' => $request->getUri(),
                 ));

src/Symfony/Component/HttpKernel/Profiler/Profiler.php

@@ -117,7 +117,7 @@ public function saveProfile(Profile $profile)
         }
 
         if (!($ret = $this->storage->write($profile)) && null !== $this->logger) {
-            $this->logger->warning('Unable to store the profiler information.');
+            $this->logger->warning('Unable to store the profiler information.', array('configured_storage' => get_class($this->storage)));
         }
 
         return $ret;

src/Symfony/Component/HttpKernel/Tests/Controller/ControllerResolverTest.php

@@ -20,7 +20,7 @@ class ControllerResolverTest extends \PHPUnit_Framework_TestCase
     public function testGetControllerWithoutControllerParameter()
     {
         $logger = $this->getMock('Psr\Log\LoggerInterface');
-        $logger->expects($this->once())->method('warning')->with('Unable to look for the controller as the "_controller" parameter is missing');
+        $logger->expects($this->once())->method('warning')->with('Unable to look for the controller as the "_controller" parameter is missing.');
         $resolver = $this->createControllerResolver($logger);
 
         $request = Request::create('/');

src/Symfony/Component/Security/Acl/Voter/AclVoter.php

@@ -64,7 +64,7 @@ public function vote(TokenInterface $token, $object, array $attributes)
 
             if (null === $object) {
                 if (null !== $this->logger) {
-                    $this->logger->debug(sprintf('Object identity unavailable. Voting to %s', $this->allowIfObjectIdentityUnavailable ? 'grant access' : 'abstain'));
+                    $this->logger->debug(sprintf('Object identity unavailable. Voting to %s.', $this->allowIfObjectIdentityUnavailable ? 'grant access' : 'abstain'));
                 }
 
                 return $this->allowIfObjectIdentityUnavailable ? self::ACCESS_GRANTED : self::ACCESS_ABSTAIN;
@@ -79,7 +79,7 @@ public function vote(TokenInterface $token, $object, array $attributes)
                 $oid = $object;
             } elseif (null === $oid = $this->objectIdentityRetrievalStrategy->getObjectIdentity($object)) {
                 if (null !== $this->logger) {
-                    $this->logger->debug(sprintf('Object identity unavailable. Voting to %s', $this->allowIfObjectIdentityUnavailable ? 'grant access' : 'abstain'));
+                    $this->logger->debug(sprintf('Object identity unavailable. Voting to %s.', $this->allowIfObjectIdentityUnavailable ? 'grant access' : 'abstain'));
                 }
 
                 return $this->allowIfObjectIdentityUnavailable ? self::ACCESS_GRANTED : self::ACCESS_ABSTAIN;
@@ -96,13 +96,13 @@ public function vote(TokenInterface $token, $object, array $attributes)
 
                 if (null === $field && $acl->isGranted($masks, $sids, false)) {
                     if (null !== $this->logger) {
-                        $this->logger->debug('ACL found, permission granted. Voting to grant access');
+                        $this->logger->debug('ACL found, permission granted. Voting to grant access.');
                     }
 
                     return self::ACCESS_GRANTED;
                 } elseif (null !== $field && $acl->isFieldGranted($field, $masks, $sids, false)) {
                     if (null !== $this->logger) {
-                        $this->logger->debug('ACL found, permission granted. Voting to grant access');
+                        $this->logger->debug('ACL found, permission granted. Voting to grant access.');
                     }
 
                     return self::ACCESS_GRANTED;

src/Symfony/Component/Security/Http/Authentication/DefaultAuthenticationFailureHandler.php

@@ -92,7 +92,7 @@ public function onAuthenticationFailure(Request $request, AuthenticationExceptio
 
         if ($this->options['failure_forward']) {
             if (null !== $this->logger) {
-                $this->logger->debug(sprintf('Forwarding to %s', $this->options['failure_path']));
+                $this->logger->debug('Authentication failure, forward triggered.', array('failure_path' => $this->options['failure_path']));
             }
 
             $subRequest = $this->httpUtils->createRequest($request, $this->options['failure_path']);
@@ -102,7 +102,7 @@ public function onAuthenticationFailure(Request $request, AuthenticationExceptio
         }
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Redirecting to %s', $this->options['failure_path']));
+            $this->logger->debug('Authentication failure, redirect triggered.', array('failure_path' => $this->options['failure_path']));
         }
 
         $request->getSession()->set(Security::AUTHENTICATION_ERROR, $exception);

src/Symfony/Component/Security/Http/Authentication/SimpleAuthenticationHandler.php

@@ -57,7 +57,7 @@ public function onAuthenticationSuccess(Request $request, TokenInterface $token)
     {
         if ($this->simpleAuthenticator instanceof AuthenticationSuccessHandlerInterface) {
             if ($this->logger) {
-                $this->logger->debug(sprintf('Using the %s object as authentication success handler', get_class($this->simpleAuthenticator)));
+                $this->logger->debug('Selected an authentication success handler.', array('handler' => get_class($this->simpleAuthenticator)));
             }
 
             $response = $this->simpleAuthenticator->onAuthenticationSuccess($request, $token);
@@ -71,7 +71,7 @@ public function onAuthenticationSuccess(Request $request, TokenInterface $token)
         }
 
         if ($this->logger) {
-            $this->logger->debug('Fallback to the default authentication success handler');
+            $this->logger->debug('Fallback to the default authentication success handler.');
         }
 
         return $this->successHandler->onAuthenticationSuccess($request, $token);
@@ -84,7 +84,7 @@ public function onAuthenticationFailure(Request $request, AuthenticationExceptio
     {
         if ($this->simpleAuthenticator instanceof AuthenticationFailureHandlerInterface) {
             if ($this->logger) {
-                $this->logger->debug(sprintf('Using the %s object as authentication failure handler', get_class($this->simpleAuthenticator)));
+                $this->logger->debug('Selected an authentication failure handler.', array('handler' => get_class($this->simpleAuthenticator)));
             }
 
             $response = $this->simpleAuthenticator->onAuthenticationFailure($request, $exception);
@@ -98,7 +98,7 @@ public function onAuthenticationFailure(Request $request, AuthenticationExceptio
         }
 
         if ($this->logger) {
-            $this->logger->debug('Fallback to the default authentication failure handler');
+            $this->logger->debug('Fallback to the default authentication failure handler.');
         }
 
         return $this->failureHandler->onAuthenticationFailure($request, $exception);

src/Symfony/Component/Security/Http/EntryPoint/DigestAuthenticationEntryPoint.php

@@ -54,7 +54,7 @@ public function start(Request $request, AuthenticationException $authException =
         }
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('WWW-Authenticate header sent to user agent: "%s"', $authenticateHeader));
+            $this->logger->debug('WWW-Authenticate header sent.', array('header' => $authenticateHeader));
         }
 
         $response = new Response();

src/Symfony/Component/Security/Http/Firewall/AbstractAuthenticationListener.php

@@ -193,7 +193,7 @@ abstract protected function attemptAuthentication(Request $request);
     private function onFailure(Request $request, AuthenticationException $failed)
     {
         if (null !== $this->logger) {
-            $this->logger->info(sprintf('Authentication request failed: %s', $failed->getMessage()));
+            $this->logger->info('Authentication request failed.', array('exception' => $failed));
         }
 
         $token = $this->tokenStorage->getToken();
@@ -213,7 +213,7 @@ private function onFailure(Request $request, AuthenticationException $failed)
     private function onSuccess(Request $request, TokenInterface $token)
     {
         if (null !== $this->logger) {
-            $this->logger->info(sprintf('User "%s" has been authenticated successfully', $token->getUsername()));
+            $this->logger->info('User has been authenticated successfully.', array('username' => $token->getUsername()));
         }
 
         $this->tokenStorage->setToken($token);

src/Symfony/Component/Security/Http/Firewall/AbstractPreAuthenticatedListener.php

@@ -56,10 +56,6 @@ final public function handle(GetResponseEvent $event)
     {
         $request = $event->getRequest();
 
-        if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Checking secure context token: %s', $this->tokenStorage->getToken()));
-        }
-
         try {
             list($user, $credentials) = $this->getPreAuthenticatedData($request);
         } catch (BadCredentialsException $exception) {
@@ -68,21 +64,25 @@ final public function handle(GetResponseEvent $event)
             return;
         }
 
+        if (null !== $this->logger) {
+            $this->logger->debug('Checking current security token.', array('token' => (string) $this->tokenStorage->getToken()));
+        }
+
         if (null !== $token = $this->tokenStorage->getToken()) {
             if ($token instanceof PreAuthenticatedToken && $this->providerKey == $token->getProviderKey() && $token->isAuthenticated() && $token->getUsername() === $user) {
                 return;
             }
         }
 
         if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Trying to pre-authenticate user "%s"', $user));
+            $this->logger->debug('Trying to pre-authenticate user.', array('username' => (string) $user));
         }
 
         try {
             $token = $this->authenticationManager->authenticate(new PreAuthenticatedToken($user, $credentials, $this->providerKey));
 
             if (null !== $this->logger) {
-                $this->logger->info(sprintf('Authentication success: %s', $token));
+                $this->logger->info('Pre-authentication successful.', array('token' => (string) $token));
             }
             $this->tokenStorage->setToken($token);
 
@@ -107,7 +107,7 @@ private function clearToken(AuthenticationException $exception)
             $this->tokenStorage->setToken(null);
 
             if (null !== $this->logger) {
-                $this->logger->info(sprintf("Cleared security context due to exception: %s", $exception->getMessage()));
+                $this->logger->info('Cleared security token due to an exception.', array('exception' => $exception));
             }
         }
     }

src/Symfony/Component/Security/Http/Firewall/AnonymousAuthenticationListener.php

@@ -59,11 +59,11 @@ public function handle(GetResponseEvent $event)
             $this->tokenStorage->setToken($token);
 
             if (null !== $this->logger) {
-                $this->logger->info('Populated TokenStorage with an anonymous Token');
+                $this->logger->info('Populated the TokenStorage with an anonymous Token.');
             }
         } catch (AuthenticationException $failed) {
             if (null !== $this->logger) {
-                $this->logger->info(sprintf('Anonymous authentication failed: %s', $failed->getMessage()));
+                $this->logger->info('Anonymous authentication failed.', array('exception' => $failed));
             }
         }
     }

src/Symfony/Component/Security/Http/Firewall/BasicAuthenticationListener.php

@@ -67,7 +67,7 @@ public function handle(GetResponseEvent $event)
         }
 
         if (null !== $this->logger) {
-            $this->logger->info(sprintf('Basic Authentication Authorization header found for user "%s"', $username));
+            $this->logger->info('Basic authentication Authorization header found for user.', array('username' => $username));
         }
 
         try {
@@ -80,7 +80,7 @@ public function handle(GetResponseEvent $event)
             }
 
             if (null !== $this->logger) {
-                $this->logger->info(sprintf('Authentication request failed for user "%s": %s', $username, $failed->getMessage()));
+                $this->logger->info('Basic authentication failed for user.', array('username' => $username, 'exception' => $failed));
             }
 
             if ($this->ignoreFailure) {

src/Symfony/Component/Security/Http/Firewall/ChannelListener.php

@@ -44,11 +44,11 @@ public function handle(GetResponseEvent $event)
     {
         $request = $event->getRequest();
 
-        list($attributes, $channel) = $this->map->getPatterns($request);
+        list(, $channel) = $this->map->getPatterns($request);
 
         if ('https' === $channel && !$request->isSecure()) {
             if (null !== $this->logger) {
-                $this->logger->info('Redirecting to HTTPS');
+                $this->logger->info('Redirecting to HTTPS.');
             }
 
             $response = $this->authenticationEntryPoint->start($request);
@@ -60,7 +60,7 @@ public function handle(GetResponseEvent $event)
 
         if ('http' === $channel && $request->isSecure()) {
             if (null !== $this->logger) {
-                $this->logger->info('Redirecting to HTTP');
+                $this->logger->info('Redirecting to HTTP.');
             }
 
             $response = $this->authenticationEntryPoint->start($request);

src/Symfony/Component/Security/Http/Firewall/ContextListener.php

@@ -34,6 +34,7 @@ class ContextListener implements ListenerInterface
 {
     private $tokenStorage;
     private $contextKey;
+    private $sessionKey;
     private $logger;
     private $userProviders;
     private $dispatcher;
@@ -54,12 +55,13 @@ public function __construct(TokenStorageInterface $tokenStorage, array $userProv
         $this->tokenStorage = $tokenStorage;
         $this->userProviders = $userProviders;
         $this->contextKey = $contextKey;
+        $this->sessionKey = '_security_'.$contextKey;
         $this->logger = $logger;
         $this->dispatcher = $dispatcher;
     }
 
     /**
-     * Reads the SecurityContext from the session.
+     * Reads the Security Token from the session.
      *
      * @param GetResponseEvent $event A GetResponseEvent instance
      */
@@ -73,7 +75,7 @@ public function handle(GetResponseEvent $event)
         $request = $event->getRequest();
         $session = $request->hasPreviousSession() ? $request->getSession() : null;
 
-        if (null === $session || null === $token = $session->get('_security_'.$this->contextKey)) {
+        if (null === $session || null === $token = $session->get($this->sessionKey)) {
             $this->tokenStorage->setToken(null);
 
             return;
@@ -82,14 +84,14 @@ public function handle(GetResponseEvent $event)
         $token = unserialize($token);
 
         if (null !== $this->logger) {
-            $this->logger->debug('Read SecurityContext from the session');
+            $this->logger->debug('Read existing security token from the session.', array('key' => $this->sessionKey));
         }
 
         if ($token instanceof TokenInterface) {
             $token = $this->refreshUser($token);
         } elseif (null !== $token) {
             if (null !== $this->logger) {
-                $this->logger->warning(sprintf('Session includes a "%s" where a security token is expected', is_object($token) ? get_class($token) : gettype($token)));
+                $this->logger->warning('Expected a security token from the session, got something else.', array('key' => $this->sessionKey, 'received' => $token));
             }
 
             $token = null;
@@ -113,10 +115,6 @@ public function onKernelResponse(FilterResponseEvent $event)
             return;
         }
 
-        if (null !== $this->logger) {
-            $this->logger->debug('Write SecurityContext in the session');
-        }
-
         $request = $event->getRequest();
         $session = $request->getSession();
 
@@ -126,10 +124,14 @@ public function onKernelResponse(FilterResponseEvent $event)
 
         if ((null === $token = $this->tokenStorage->getToken()) || ($token instanceof AnonymousToken)) {
             if ($request->hasPreviousSession()) {
-                $session->remove('_security_'.$this->contextKey);
+                $session->remove($this->sessionKey);
             }
         } else {
-            $session->set('_security_'.$this->contextKey, serialize($token));
+            $session->set($this->sessionKey, serialize($token));
+
+            if (null !== $this->logger) {
+                $this->logger->debug('Stored the security token in the session.', array('key' => $this->sessionKey));
+            }
         }
     }
 
@@ -149,25 +151,21 @@ protected function refreshUser(TokenInterface $token)
             return $token;
         }
 
-        if (null !== $this->logger) {
-            $this->logger->debug(sprintf('Reloading user from user provider.'));
-        }
-
         foreach ($this->userProviders as $provider) {
             try {
                 $refreshedUser = $provider->refreshUser($user);
                 $token->setUser($refreshedUser);
 
                 if (null !== $this->logger) {
-                    $this->logger->debug(sprintf('Username "%s" was reloaded from user provider.', $refreshedUser->getUsername()));
+                    $this->logger->debug('User was reloaded from a user provider.', array('username' => $refreshedUser->getUsername(), 'provider' => get_class($provider)));
                 }
 
                 return $token;
             } catch (UnsupportedUserException $unsupported) {
                 // let's try the next user provider
             } catch (UsernameNotFoundException $notFound) {
                 if (null !== $this->logger) {
-                    $this->logger->warning(sprintf('Username "%s" could not be found.', $notFound->getUsername()));
+                    $this->logger->warning('Username could not be found in the selected user provider.', array('username' => $notFound->getUsername(), 'provider' => get_class($provider)));
                 }
 
                 return;