Spring concurrent session control not working, use

I use Spring 3.2 and Spring-security 3.1 along with jsf + primefaces and hibernate4 on Tomcat7

I wanted to add a concurrency control to limit users' session to one, and show and error message if he/she tries to login the second time. The problem is. I can login both in chrome and firefox. It does not prevent multiple login. You can see my security configuration. And logs produced at the time of first login and second login What is wrong is going on ?

<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"       xmlns:security="http://www.springframework.org/schema/security"
xsi:schemaLocation="http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans-3.1.xsd
http://www.springframework.org/schema/security
http://www.springframework.org/schema/security/spring-security-3.1.xsd">

<security:http pattern="/resources/**" security="none" />
<security:http pattern="/authentication/**" security="none" />

<security:http auto-config='true'
    access-decision-manager-ref="accessDecisionManager">
    <security:intercept-url pattern="/pages/**"
        access="PRV_LOGIN" />
    <security:access-denied-handler
        error-page="/error/error.jsf" />
    <security:logout logout-success-url="/" logout-url="/logout"
        delete-cookies="JSESSIONID" />
    <security:form-login login-page='/login'
        login-processing-url="/logincheck" default-target-url="/home"
        always-use-default-target="true" />
    <security:session-management
        invalid-session-url="/login">
        <security:concurrency-control
            error-if-maximum-exceeded="true" max-sessions="1" expired-url="/login"
            session-registry-ref="sessionRegistry" />
    </security:session-management>
</security:http>

<security:authentication-manager>
    <security:authentication-provider
        user-service-ref="userSessionDetailsUtil">
        <security:password-encoder ref="passwordEncoderUtil">
            <security:salt-source user-property="username" />
        </security:password-encoder>
    </security:authentication-provider>
</security:authentication-manager>

<!-- Security(Authentication, Encoding) implementations -->
<bean id="userSessionDetailsUtil" class="com.i2i.copycat.service.util.UserSessionDetailsUtil">
</bean>

<bean id="passwordEncoderUtil" class="com.i2i.copycat.service.util.PasswordEncoderUtil">
    <property name="passwordEncoder" ref="springShaPasswordEncoder"></property>
</bean>

<!-- Spring Security's sha capable password encoder -->
<bean id="springShaPasswordEncoder"
    class="org.springframework.security.authentication.encoding.ShaPasswordEncoder">
    <constructor-arg value="256" />
</bean>

<!-- Custom Privilege Names to be accepted -->
<bean id="accessDecisionManager"
    class="org.springframework.security.access.vote.AffirmativeBased">
    <property name="decisionVoters">
        <bean class="org.springframework.security.access.vote.RoleVoter">
            <property name="rolePrefix" value="PRV_" />
        </bean>
    </property>
</bean>
<!-- Concurrent Session Control Beans -->

<bean id="sessionRegistry"
    class="org.springframework.security.core.session.SessionRegistryImpl" />

First Login

2012-06-16 13:18:22,325 231156 [080-exec-9] DEBUG ..hibernate.internal.SessionImpl           - Opened session at timestamp: 5487992431767552
2012-06-16 13:18:22,342 231173 [080-exec-9] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Obtaining JDBC connection
2012-06-16 13:18:22,343 231174 [080-exec-9] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Obtained JDBC connection
2012-06-16 13:18:22,343 231174 [080-exec-9] DEBUG ..transaction.spi.AbstractTransactionImpl  - begin
2012-06-16 13:18:22,343 231174 [080-exec-9] DEBUG ..internal.jdbc.JdbcTransaction            - initial autocommit status: true
2012-06-16 13:18:22,343 231174 [080-exec-9] DEBUG ..internal.jdbc.JdbcTransaction            - disabling autocommit
2012-06-16 13:18:22,346 231177 [080-exec-9] DEBUG ..service.util.UserSessionDetailsUtil      - Loading user by name[admin]
2012-06-16 13:18:22,347 231178 [080-exec-9] DEBUG ..copycat.domain.User                      - [User][Operation:getMatchingUnique() ][Session:1630011351][Transaction:151891478]User
2012-06-16 13:18:22,351 231182 [080-exec-9] DEBUG ..copycat.domain.User                      - [User][Operation:addRestrictionToCriteria() ][Session:1630011351][Transaction:151891478]User
2012-06-16 13:18:22,497 231328 [080-exec-9] DEBUG ..org.hibernate.SQL                        - 
2012-06-16 13:18:22,546 231377 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:18:22,552 231383 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.User#2]
2012-06-16 13:18:22,563 231394 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.User#2]
2012-06-16 13:18:22,567 231398 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Loading entity: [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:18:22,567 231398 [080-exec-9] DEBUG ..org.hibernate.SQL                        

2012-06-16 13:18:22,568 231399 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:18:22,568 231399 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:18:22,569 231400 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:18:22,577 231408 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:18:22,585 231416 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:18:22,585 231416 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Done entity load
2012-06-16 13:18:22,586 231417 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Loading entity: [com.i2i.copycat.domain.Group#1]
2012-06-16 13:18:22,586 231417 [080-exec-9] DEBUG ..org.hibernate.SQL                        - 
2012-06-16 13:18:22,588 231419 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:18:22,588 231419 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.Group#1]
2012-06-16 13:18:22,590 231421 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.Group#1]
2012-06-16 13:18:22,592 231423 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.Group#1]
2012-06-16 13:18:22,597 231428 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.Group#1]
2012-06-16 13:18:22,597 231428 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Done entity load
2012-06-16 13:18:22,597 231428 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.User#2]
2012-06-16 13:18:22,597 231428 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.User#2]
2012-06-16 13:18:22,597 231428 [080-exec-9] DEBUG ..engine.internal.StatefulPersistenceContext - Initializing non-lazy collections
2012-06-16 13:18:22,602 231433 [080-exec-9] DEBUG ..service.bean.CopycatUserDetails          - [getPrivileges() ][User:[Sk: 2][Name: ADMIN][UserType:[Code: SYS][Type: SYSTEM]][Group:[Sk: 1][Name: SYSTEM_ADMIN]]]
2012-06-16 13:18:22,604 231435 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Loading collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:18:22,605 231436 [080-exec-9] DEBUG ..org.hibernate.SQL                        
2012-06-16 13:18:22,606 231437 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result set contains (possibly empty) collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:18:22,611 231442 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:18:22,611 231442 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:18:22,612 231443 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Found row of collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:18:22,613 231444 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:18:22,613 231444 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:18:22,613 231444 [080-exec-9] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:18:22,614 231445 [080-exec-9] DEBUG ..loading.internal.CollectionLoadContext   - 1 collections were found in result set for role: com.i2i.copycat.domain.User.privileges
2012-06-16 13:18:22,614 231445 [080-exec-9] DEBUG ..loading.internal.CollectionLoadContext   - Collection fully initialized: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:18:22,614 231445 [080-exec-9] DEBUG ..loading.internal.CollectionLoadContext   - 1 collections initialized for role: com.i2i.copycat.domain.User.privileges
2012-06-16 13:18:22,614 231445 [080-exec-9] DEBUG ..engine.internal.StatefulPersistenceContext - Initializing non-lazy collections
2012-06-16 13:18:22,614 231445 [080-exec-9] DEBUG ..hibernate.loader.Loader                  - Done loading collection
2012-06-16 13:18:22,615 231446 [080-exec-9] DEBUG ..service.bean.CopycatUserDetails          - [getPrivileges() ]...[DONE]
2012-06-16 13:18:22,615 231446 [080-exec-9] DEBUG ..transaction.spi.AbstractTransactionImpl  - committing
2012-06-16 13:18:22,617 231448 [080-exec-9] DEBUG ..internal.jdbc.JdbcTransaction            - committed JDBC Connection
2012-06-16 13:18:22,617 231448 [080-exec-9] DEBUG ..internal.jdbc.JdbcTransaction            - re-enabling autocommit
2012-06-16 13:18:22,618 231449 [080-exec-9] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Releasing JDBC connection
2012-06-16 13:18:22,619 231450 [080-exec-9] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Released JDBC connection
2012-06-16 13:18:22,619 231450 [080-exec-9] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:18:22,619 231450 [080-exec-9] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:18:22,619 231450 [080-exec-9] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:18:22,619 231450 [080-exec-9] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection

Second Login

2012-06-16 13:21:38,352 427183 [080-exec-7] DEBUG ..hibernate.internal.SessionImpl           - Opened session at timestamp: 5487993234845696
2012-06-16 13:21:38,354 427185 [080-exec-7] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Obtaining JDBC connection
2012-06-16 13:21:38,354 427185 [080-exec-7] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Obtained JDBC connection
2012-06-16 13:21:38,354 427185 [080-exec-7] DEBUG ..transaction.spi.AbstractTransactionImpl  - begin
2012-06-16 13:21:38,355 427186 [080-exec-7] DEBUG ..internal.jdbc.JdbcTransaction            - initial autocommit status: true
2012-06-16 13:21:38,355 427186 [080-exec-7] DEBUG ..internal.jdbc.JdbcTransaction            - disabling autocommit
2012-06-16 13:21:38,355 427186 [080-exec-7] DEBUG ..service.util.UserSessionDetailsUtil      - Loading user by name[admin]
2012-06-16 13:21:38,356 427187 [080-exec-7] DEBUG ..copycat.domain.User                      - [User][Operation:getMatchingUnique() ][Session:2031763761][Transaction:716060180]User
2012-06-16 13:21:38,356 427187 [080-exec-7] DEBUG ..copycat.domain.User                      - [User][Operation:addRestrictionToCriteria() ][Session:2031763761][Transaction:716060180]User
2012-06-16 13:21:38,357 427188 [080-exec-7] DEBUG ..org.hibernate.SQL                        - 
2012-06-16 13:21:38,365 427196 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:21:38,365 427196 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.User#2]
2012-06-16 13:21:38,366 427197 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.User#2]
2012-06-16 13:21:38,367 427198 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Loading entity: [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:21:38,368 427199 [080-exec-7] DEBUG ..org.hibernate.SQL                        - 
2012-06-16 13:21:38,369 427200 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:21:38,370 427201 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:21:38,370 427201 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:21:38,370 427201 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:21:38,371 427202 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.UserType#SYS]
2012-06-16 13:21:38,371 427202 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Done entity load
2012-06-16 13:21:38,371 427202 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Loading entity: [com.i2i.copycat.domain.Group#1]
2012-06-16 13:21:38,372 427203 [080-exec-7] DEBUG ..org.hibernate.SQL                        - 
2012-06-16 13:21:38,373 427204 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:21:38,374 427205 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.Group#1]
2012-06-16 13:21:38,374 427205 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.Group#1]
2012-06-16 13:21:38,375 427206 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.Group#1]
2012-06-16 13:21:38,375 427206 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.Group#1]
2012-06-16 13:21:38,375 427206 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Done entity load
2012-06-16 13:21:38,376 427207 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.User#2]
2012-06-16 13:21:38,376 427207 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.User#2]
2012-06-16 13:21:38,376 427207 [080-exec-7] DEBUG ..engine.internal.StatefulPersistenceContext - Initializing non-lazy collections
2012-06-16 13:21:38,377 427208 [080-exec-7] DEBUG ..service.bean.CopycatUserDetails          - [getPrivileges() ][User:[Sk: 2][Name: ADMIN][UserType:[Code: SYS][Type: SYSTEM]][Group:[Sk: 1][Name: SYSTEM_ADMIN]]]
2012-06-16 13:21:38,377 427208 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Loading collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:21:38,377 427208 [080-exec-7] DEBUG ..org.hibernate.SQL                        - 

2012-06-16 13:21:38,379 427210 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result set contains (possibly empty) collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:21:38,379 427210 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result set row: 0
2012-06-16 13:21:38,380 427211 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Result row: EntityKey[com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:21:38,380 427211 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Found row of collection: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:21:38,383 427214 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Resolving associations for [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:21:38,383 427214 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Adding entity to second-level cache: [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:21:38,384 427215 [080-exec-7] DEBUG ..engine.internal.TwoPhaseLoad             - Done materializing entity [com.i2i.copycat.domain.Privilege#LOGIN]
2012-06-16 13:21:38,384 427215 [080-exec-7] DEBUG ..loading.internal.CollectionLoadContext   - 1 collections were found in result set for role: com.i2i.copycat.domain.User.privileges
2012-06-16 13:21:38,384 427215 [080-exec-7] DEBUG ..loading.internal.CollectionLoadContext   - Collection fully initialized: [com.i2i.copycat.domain.User.privileges#2]
2012-06-16 13:21:38,384 427215 [080-exec-7] DEBUG ..loading.internal.CollectionLoadContext   - 1 collections initialized for role: com.i2i.copycat.domain.User.privileges
2012-06-16 13:21:38,385 427216 [080-exec-7] DEBUG ..engine.internal.StatefulPersistenceContext - Initializing non-lazy collections
2012-06-16 13:21:38,385 427216 [080-exec-7] DEBUG ..hibernate.loader.Loader                  - Done loading collection
2012-06-16 13:21:38,385 427216 [080-exec-7] DEBUG ..service.bean.CopycatUserDetails          - [getPrivileges() ]...[DONE]
2012-06-16 13:21:38,385 427216 [080-exec-7] DEBUG ..transaction.spi.AbstractTransactionImpl  - committing
2012-06-16 13:21:38,385 427216 [080-exec-7] DEBUG ..internal.jdbc.JdbcTransaction            - committed JDBC Connection
2012-06-16 13:21:38,386 427217 [080-exec-7] DEBUG ..internal.jdbc.JdbcTransaction            - re-enabling autocommit
2012-06-16 13:21:38,386 427217 [080-exec-7] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Releasing JDBC connection
2012-06-16 13:21:38,386 427217 [080-exec-7] DEBUG ..jdbc.internal.LogicalConnectionImpl      - Released JDBC connection
2012-06-16 13:21:38,387 427218 [080-exec-7] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:21:38,387 427218 [080-exec-7] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:21:38,387 427218 [080-exec-7] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection
2012-06-16 13:21:38,387 427218 [080-exec-7] DEBUG ..internal.proxy.ConnectionProxyHandler    - HHH000163: Logical connection releasing its physical connection

I don't see any logs stating that the Spring Security FilterChainProxy is being invoked. Did you just leave these logs out or are you authenticating the user yourself? Typically the registration of the session is performed by UsernamePasswordAuthenticationFilter or some other subclass of AbstractAuthenticationProcessingFilter. If you are authenticating the user yourself, then you need to ensure to invoke ConcurrentSessionControlStrategy#onAuthentication.

It appears you are using a custom UserDetailsService which probably means that you are returning a custom UserDetails. It is critical to implement UserDetails#hashCode and UserDetails#equals properly in order for SessionRegistryImpl to work since it is backed by a ConcurrentMap.

If you have a clustered deployment, the SessionRegistryImpl will not work since the cluster does not share memory with other nodes in the environment. In this instance, you would need to provide your own SessionRegistry implementation.

PS: It appears you are only protecting /pages/** which is not generally recommended. Instead it is recommended that you explicitly grant access to pages and by default restrict access.