My environment:
- Java 6
- Servlet 2.5
- Weblogic 12.1
- Spring MVC 4.3.4.RELEASE
- Spring Security 4.2.0.RELEASE
I've implemented a CustomAuthenticationProvider in order to authenticate users against an Oracle db: users are actually db users, so I try a connection to the db to check user/password, and if the result is positive than I load authorities.
The configuration works good except after a login error. If the user type the wrong username or password, than the application shows an error message in the same page, but a further correct try does not let the user log-in. Instead is redirected to login page. If the user tries again, than the problem persists. After a minute the same try, without page reloading, is successfull.
As I said, the problem occurs only after a login error. If the user types his credentials correctly at the first try or after a logout, no problem occurs. If he does it after a login error, than the problem shows up. Also, nothing wrong happens on my development environment (local app-server and various browser) but the problem shows up everytime on staging environemnt (same app-server but centralized and IE9-IE10-Edge). I really don't understand what makes the difference.
I put many logs on my CustomAuthenticationProvider and I can see than in both cases (positive and negative login) username and password have been successfully accepted, and a UsernamePasswordAuthenticationToken has been created. Then, the user should be redirected to the default-target-url that is my application root / (I set always-use-default-target = true). For a reason that I don't understand, when the problem occurs the redirect fails, as Spring Security think user is not authorized yet to acess a secure path and it redirects him to login page again.
I've checked the request with the login form submission for both cases and they are actually identical, except for the JSESSIONID that is passed. But the login is successful I can see from the response header that JSESSIONID cookie has been set, in the negative case there's not "set cookie".
Why there is this difference of behaviour despite the fact that username and password submitted are the same?! What can make a difference? My guess is that a wrong login attempt leave something dirty behind. Something that affects the next try. Whan can it be? And why this problem occurs only on my local environment? What am I missing?
This is the implementation of the CustomAuthenticationProvider:
@Component
public class CustomAuthenticationProvider extends AbstractUserDetailsAuthenticationProvider {
private Logger log = LogManager.getLogger(CustomAuthenticationProvider.class);
@Autowired
private UserService userService;
@Autowired
private SecurityService securityService;
@Autowired
private Messages messages;
@Value("${login.test.mode}")
private String testMode;
@Value("${login.test.mode.userid}")
private String testModeUserid;
public Authentication authenticate(Authentication authentication) throws AuthenticationException {
String username = authentication.getName();
String password = (String) authentication.getCredentials();
log.debug("##### SECURITY ##### Test mode status: " + testMode);
// test mode uses its own configured user, ignoring login credentials, if username is empty
if (Constants.FLAG_YES.equals(testMode) && StringUtils.isEmpty(username)) {
username = testModeUserid;
}
GddbUserDetails gddbUserDetails = userService.findGddbUserDetailsByUsername(username);
UserRole userRole = userService.findUserRolesByUsername(username);
if (gddbUserDetails == null) {
log.debug("##### SECURITY ##### Utente non trovato in anagrafica GDDB: " + username);
throw new BadCredentialsException(messages.get("user.not.found.gddb"));
} else {
log.debug("##### SECURITY ##### OK Utente trovato in anagrafica GDDB: " + username);
}
// perform checks only if test mode is disabled
if (!Constants.FLAG_YES.equals(testMode)) {
// GDDB state check
if (!Constants.USER_STATO_ACTIVE.equals(gddbUserDetails.getStato())) {
log.debug("##### SECURITY ##### Utente presente in anagrafica GDDB ma disabilitato: " + username);
throw new BadCredentialsException(messages.get("user.not.enabled.gddb"));
} else {
log.debug("##### SECURITY ##### Utente presente in anagrafica GDDB e abilitato: " + username);
}
// dbetichette user existence check
if (userRole == null) {
log.debug("##### SECURITY ##### Utente non presente in anagrafica DBEtichette: " + username);
throw new BadCredentialsException(messages.get("user.not.enabled.locally"));
} else {
log.debug("##### SECURITY ##### Utente presente in anagrafica DBEtichette: " + username);
}
// dbetichette user activation check
if (!Constants.FLAG_YES.equals(userRole.getActive())) {
log.debug("##### SECURITY ##### Utente disabilitato in anagrafica DBEtichette: " + username);
throw new BadCredentialsException(messages.get("user.not.enabled.locally"));
} else {
log.debug("##### SECURITY ##### Utente abilitato in anagrafica DBEtichette: " + username);
}
// oracle user password check
String usernamePasswordCheckResult = securityService.checkUserPassword(username, password);
log.debug("##### SECURITY ##### usernamePasswordCheckResult: " + usernamePasswordCheckResult);
if (Constants.SECURITY_ACCOUNT_LOCKED.equals(usernamePasswordCheckResult)) {
log.debug("##### SECURITY ##### Utente presente su DB ma bloccato: " + username);
throw new BadCredentialsException(messages.get("user.blocked"));
} else if (Constants.SECURITY_PASSWORD_EXPIRED.equals(usernamePasswordCheckResult)) {
log.debug("##### SECURITY ##### Password dell'utente scaduta: " + username);
throw new BadCredentialsException(messages.get("user.password.expired"));
} else if (Constants.SECURITY_INVALID_USERNAME_PASSWORD.equals(usernamePasswordCheckResult)) {
log.debug("##### SECURITY ##### Tentativo di accesso fallito per errata password: " + username);
throw new BadCredentialsException(messages.get("user.password.wrong"));
} else if (!Constants.SECURITY_VALID_USERNAME_PASSWORD.equals(usernamePasswordCheckResult)) {
log.debug("##### SECURITY ##### Tentativo di accesso fallito per motivo sconosciuto: " + username
+ " ( usernamePasswordCheckResult = " + usernamePasswordCheckResult + " )");
throw new BadCredentialsException(messages.get("user.login.error.other"));
} else {
log.debug("##### SECURITY ##### Tentativo di accesso eseguito con successo: " + usernamePasswordCheckResult + " - " + username);
}
}
CustomUser user = userService.createCustomUser(gddbUserDetails, userRole);
log.debug("##### SECURITY ##### Creazione custom user: " + user);
Collection<? extends GrantedAuthority> authorities = user.getAuthorities();
UsernamePasswordAuthenticationToken userToken = new UsernamePasswordAuthenticationToken(user, password, authorities);
log.debug("##### SECURITY ##### Creazione userToken: " + userToken);
return userToken;
}
@Override
protected UserDetails retrieveUser(String s, UsernamePasswordAuthenticationToken token) throws AuthenticationException {
UserDetails user = (UserDetails) token.getPrincipal();
log.debug("##### SECURITY ##### retrieveUser: " + user);
return user;
}
@Override
public boolean supports(Class<?> aClass) {
return true;
}
@Override
protected void additionalAuthenticationChecks(UserDetails userDetails, UsernamePasswordAuthenticationToken token) throws AuthenticationException {
log.debug("##### SECURITY ##### additionalAuthenticationChecks - userDetails " + userDetails);
log.debug("##### SECURITY ##### additionalAuthenticationChecks - token " + token);
}
}
This is my Spring Security configuration file:
<?xml version="1.0" encoding="UTF-8"?>
<beans:beans xmlns:beans="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns="http://www.springframework.org/schema/security"
xsi:schemaLocation="http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans.xsd
http://www.springframework.org/schema/security
http://www.springframework.org/schema/security/spring-security.xsd">
<http auto-config="true">
<intercept-url pattern="/assets/**" access="permitAll()"/>
<intercept-url pattern="/pages/**" access="permitAll()"/>
<intercept-url pattern="/login" access="permitAll()"/>
<intercept-url pattern="/loginApp" access="permitAll()"/>
<intercept-url pattern="/loginFailed" access="permitAll()"/>
<intercept-url pattern="/logout" access="permitAll()"/>
<intercept-url pattern="/logoutSuccess" access="permitAll()"/>
<intercept-url pattern="/changepwd" access="permitAll()"/>
<intercept-url pattern="/admin/**" access="hasRole('ROLE_ADMIN')"/>
<intercept-url pattern="/relabel/**" access="hasRole('ROLE_ADMIN') or hasRole('ROLE_WAREHOUSE_OP') or hasRole('ROLE_QA')"/>
<intercept-url pattern="/**" access="hasRole('ROLE_DATA_ENTRY') or hasRole('ROLE_APPROVER') or hasRole('VIEWER') or hasRole('ROLE_ADMIN') or hasRole('ROLE_WAREHOUSE_OP') or hasRole('ROLE_QA')"/>
<form-login login-page="/login"
default-target-url="/"
authentication-failure-url="/loginFailed"
login-processing-url="/loginApp"
username-parameter="username"
password-parameter="password"
always-use-default-target="true"
/>
<logout logout-success-url="/logoutSuccess" logout-url="/logout"/>
<access-denied-handler error-page="/403"/>
<csrf disabled="true" />
</http>
<authentication-manager>
<authentication-provider ref="customAuthenticationProvider"/>
</authentication-manager>
Every suggestion is appreciated. Thank you all, dolfiz
EDIT: I made spring security logs working and it appears that for some reason the session has been cleared after the authentication, so the forward to login page. These are the logs:
[DEBUG] 2017-02-17 17:01:41.317 org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter - Authentication success. Updating SecurityContextHolder to contain: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@e2fe4b0e: Principal: CustomUser{username='MAROTAN1', password='null', email='antonio.marotta@novartis.com', firstName='Antonio', lastName='Marotta', graceTime='null', authorities=[Role{name='ROLE_ADMIN'}], accountNonExpired=true, accountNonLocked=true, credentialsNonExpired=true, enabled=true}; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@b364: RemoteIpAddress: 10.166.243.87; SessionId: QYWPYnpbth0y139v2gz7r6hCm0cHpsfmxq8DFqsvv3XM1kT6YcP2!2062762872!1487347291632; Granted Authorities: Role{name='ROLE_ADMIN'}
[DEBUG] 2017-02-17 17:01:41.317 org.springframework.security.web.DefaultRedirectStrategy - Redirecting to '/dbetichette/'
[DEBUG] 2017-02-17 17:01:41.317 org.springframework.security.web.context.HttpSessionSecurityContextRepository - HttpSession is now null, but was not null at start of request; session was invalidated, so do not create a new session
[DEBUG] 2017-02-17 17:01:41.317 org.springframework.security.web.context.SecurityContextPersistenceFilter - SecurityContextHolder now cleared, as request processing completed
[DEBUG] 2017-02-17 17:01:41.321 org.springframework.security.web.FilterChainProxy - / at position 1 of 12 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
[DEBUG] 2017-02-17 17:01:41.321 org.springframework.security.web.context.HttpSessionSecurityContextRepository - No HttpSession currently exists
[DEBUG] 2017-02-17 17:01:41.322 org.springframework.security.web.context.HttpSessionSecurityContextRepository - No SecurityContext was available from the HttpSession: null. A new one will be created.
[DEBUG] 2017-02-17 17:01:41.322 org.springframework.security.web.FilterChainProxy - / at position 2 of 12 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
[DEBUG] 2017-02-17 17:01:41.322 org.springframework.security.web.FilterChainProxy - / at position 3 of 12 in additional filter chain; firing Filter: 'HeaderWriterFilter'
[DEBUG] 2017-02-17 17:01:41.323 org.springframework.security.web.FilterChainProxy - / at position 4 of 12 in additional filter chain; firing Filter: 'LogoutFilter'
[DEBUG] 2017-02-17 17:01:41.323 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/logout'
[DEBUG] 2017-02-17 17:01:41.323 org.springframework.security.web.FilterChainProxy - / at position 5 of 12 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
[DEBUG] 2017-02-17 17:01:41.323 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Request 'GET /' doesn't match 'POST /loginApp
[DEBUG] 2017-02-17 17:01:41.323 org.springframework.security.web.FilterChainProxy - / at position 6 of 12 in additional filter chain; firing Filter: 'BasicAuthenticationFilter'
[DEBUG] 2017-02-17 17:01:41.324 org.springframework.security.web.FilterChainProxy - / at position 7 of 12 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
[DEBUG] 2017-02-17 17:01:41.324 org.springframework.security.web.FilterChainProxy - / at position 8 of 12 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
[DEBUG] 2017-02-17 17:01:41.324 org.springframework.security.web.FilterChainProxy - / at position 9 of 12 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
[DEBUG] 2017-02-17 17:01:41.324 org.springframework.security.web.authentication.AnonymousAuthenticationFilter - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@6faa3d44: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@ffff4c9c: RemoteIpAddress: 10.166.243.87; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.FilterChainProxy - / at position 10 of 12 in additional filter chain; firing Filter: 'SessionManagementFilter'
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.session.SessionManagementFilter - Requested session ID QYWPYnpbth0y139v2gz7r6hCm0cHpsfmxq8DFqsvv3XM1kT6YcP2!2062762872 is invalid.
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.FilterChainProxy - / at position 11 of 12 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.FilterChainProxy - / at position 12 of 12 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/assets/**'
[DEBUG] 2017-02-17 17:01:41.325 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/pages/**'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/login'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/loginApp'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/loginFailed'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/logout'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/logoutSuccess'
[DEBUG] 2017-02-17 17:01:41.326 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/changepwd'
[DEBUG] 2017-02-17 17:01:41.327 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/admin/**'
[DEBUG] 2017-02-17 17:01:41.327 org.springframework.security.web.util.matcher.AntPathRequestMatcher - Checking match of request : '/'; against '/relabel/**'
[DEBUG] 2017-02-17 17:01:41.327 org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Secure object: FilterInvocation: URL: /; Attributes: [hasRole('ROLE_DATA_ENTRY') or hasRole('ROLE_APPROVER') or hasRole('VIEWER') or hasRole('ROLE_ADMIN') or hasRole('ROLE_WAREHOUSE_OP') or hasRole('ROLE_QA')]
[DEBUG] 2017-02-17 17:01:41.327 org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@6faa3d44: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@ffff4c9c: RemoteIpAddress: 10.166.243.87; SessionId: null; Granted Authorities: ROLE_ANONYMOUS
[DEBUG] 2017-02-17 17:01:41.328 org.springframework.security.access.vote.AffirmativeBased - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@14b4feab, returned: -1
[DEBUG] 2017-02-17 17:01:41.329 org.springframework.security.web.access.ExceptionTranslationFilter - Access is denied (user is anonymous); redirecting to authentication entry point
org.springframework.security.access.AccessDeniedException: Access is denied
I guess that the important line is:
[DEBUG] 2017-02-17 17:01:41.317 org.springframework.security.web.context.HttpSessionSecurityContextRepository - HttpSession is now null, but was not null at start of request; session was invalidated, so do not create a new session
Why is this happening only sometimes and only on some enviroments?