CODEWITHSUNDEEP
springloggingspring-securitylog4j
Bryan Larson
Bryan Larson

Reputation: 505

Spring Security authentication logging

I am using Spring Security 3.1 to authenticate users for a website. When a login fails because spring security is unable to connect to the database, I get the following statement in my log:

2012-07-12 11:42:45,419 [ajp-bio-8009-exec-1] DEBUG      org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter - Authentication request failed: org.springframework.security.authentication.AuthenticationServiceException: Could not get JDBC Connection; nested exception is java.sql.SQLException: Connections could not be acquired from the underlying database!

My question is, why is this a DEBUG statement instead of an ERROR? I have to wade through a whole lot of debug statements just to find the actual error.

EDIT

Here is my authentication manager:

<bean id="securityDataSource" class="org.springframework.jndi.JndiObjectFactoryBean">
    <property name="jndiName" value="java:comp/env/securityDS"/>
    <property name="resourceRef" value="true"/>
</bean>

<bean id="encoder" class="org.springframework.security.crypto.password.StandardPasswordEncoder" />

<security:authentication-manager>
    <security:authentication-provider>
        <security:password-encoder ref="encoder" />
        <security:jdbc-user-service 
            data-source-ref="securityDataSource"
            authorities-by-username-query="SELECT username, authority FROM login WHERE username = ?"
            users-by-username-query="SELECT username, password, enabled FROM login WHERE username = ?"
        />        
    </security:authentication-provider>
</security:authentication-manager>

Upvotes: 5

Views: 31146

Answers (2)

AlonL
AlonL

Reputation: 6690

My solution:

@Component
public class AuthenticationEventListener implements ApplicationListener<AbstractAuthenticationEvent> {

   private static Logger logger = Logger.getLogger(AuthenticationEventListener.class);

   @Override
   public void onApplicationEvent(AbstractAuthenticationEvent authenticationEvent) {
      if (authenticationEvent instanceof InteractiveAuthenticationSuccessEvent) {
         // ignores to prevent duplicate logging with AuthenticationSuccessEvent
         return;
      }
      Authentication authentication = authenticationEvent.getAuthentication();
      String auditMessage = "Login attempt with username: " + authentication.getName() + "\t\tSuccess: " + authentication.isAuthenticated();
      logger.info(auditMessage);
   }

}

No other configurations are required.

Upvotes: 18

sourcedelica
sourcedelica

Reputation: 24040

That message is printed out in AbstractAuthenticationProcessingFilter.unsuccessfulAuthentication:

protected void unsuccessfulAuthentication(HttpServletRequest request, HttpServletResponse response,
        AuthenticationException failed) throws IOException, ServletException {
    SecurityContextHolder.clearContext();

    if (logger.isDebugEnabled()) {
        logger.debug("Authentication request failed: " + failed.toString());

There are a number of ways an authentication can fail, including based on user input. For example, in AbstractUserDetailsAuthenticationProvider.authenticate, a BadCredentialsException could be thrown if the username is not found:

        try {
            user = retrieveUser(username, (UsernamePasswordAuthenticationToken) authentication);
        } catch (UsernameNotFoundException notFound) {
            logger.debug("User '" + username + "' not found");

            if (hideUserNotFoundExceptions) {
                throw new BadCredentialsException(messages.getMessage(
                        "AbstractUserDetailsAuthenticationProvider.badCredentials", "Bad credentials"));
            } else {
                throw notFound;
            }
        }

Since there could be legitimate reasons why an authentication can fail, it doesn't make sense for AbstractAuthenticationProcessingFilter to log an error. If there is a system error the error should have been logged further downstream.

I suspect that the problem is in DaoAuthenticationProvider (see my comment inline):

protected final UserDetails retrieveUser(String username, UsernamePasswordAuthenticationToken authentication)
        throws AuthenticationException {
    UserDetails loadedUser;

    try {
        loadedUser = this.getUserDetailsService().loadUserByUsername(username);
    }
    catch (DataAccessException repositoryProblem) {
        // *** ERROR SHOULD BE LOGGED HERE ***
        throw new AuthenticationServiceException(repositoryProblem.getMessage(), repositoryProblem);
    }

Perhaps an error should be logged here - you can log a JIRA with Spring to request that. Though maybe they are assuming that everyone is going to provide a custom UserDetailsService and will catch/log their own exceptions there. If you are using JdbcDaoImpl it does not. I think JdbcDaoImpl is intended to be an example and is not robust. Per the docs:

The good news is that we provide a number of UserDetailsService implementations, including one that uses an in-memory map (InMemoryDaoImpl) and another that uses JDBC (JdbcDaoImpl). Most users tend to write their own, though, with their implementations often simply sitting on top of an existing Data Access Object (DAO) that represents their employees, customers, or other users of the application.

Upvotes: 10

Related Questions