upgrading 0.8.0 Null authentication SecureContextImpl

I am trying to migrate from Acegi 0.7.0 to 0.8.0 and have come up against a problem with obtaining authentication details.

I believe the root of the problem lies with the context, in the session is:-

ACEGI_SECURITY_CONTEXT net.sf.acegisecurity.context.security.SecureContex tImpl@5a74a7: Null authentication

i.e. the authentication is Null

Therefore:

SecureContext secureContext = (SecureContext)ContextHolder.getContext();
Authentication auth = secureContext.getAuthentication();

will always return null for auth.

The logger returns:

[net.sf.acegisecurity.providers.dao.event.LoggerLis tener] - <Authentication success for user: wally; details: 127.0.0.1>

and in the session I get:

ACEGI_SECURITY_AUTHENTICATION net.sf.acegisecurity.providers.UsernamePasswordAut henticationToken@c58002: Username: com.somedomain.security.UserDet@572717; Password: [PROTECTED]; Authenticated: false; Details: 127.0.0.1; Granted Authorities: ROLE_USER
ACEGI_SECURITY_LAST_USERNAME wally

Thus indicating that the user is logged in.

I am only using httpSessionContextIntegrationFilter and authenticationProcessingFilter since all authorization is done (rightly or wrongly) with the front end (Tapestry).

Any ideas would be gratefully received.

Some relevant config:

<bean id="filterChainProxy" class="net.sf.acegisecurity.util.FilterChainProxy" >
<property name="filterInvocationDefinitionSource">
<value>
CONVERT_URL_TO_LOWERCASE_BEFORE_COMPARISON
PATTERN_TYPE_APACHE_ANT
/**=httpSessionContextIntegrationFilter,authenticat ionProcessingFilter
</value>
</property>
</bean>


<bean id="httpSessionContextIntegrationFilter" class="net.sf.acegisecurity.context.HttpSessionCon textIntegrationFilter">
<property name="context"><value>net.sf.acegisecurity.context .security.SecureContextImpl</value></property>
</bean>

Quote:

---

Originally Posted by pg

<bean id="filterChainProxy" class="net.sf.acegisecurity.util.FilterChainProxy" >
<property name="filterInvocationDefinitionSource">
<value>
CONVERT_URL_TO_LOWERCASE_BEFORE_COMPARISON
PATTERN_TYPE_APACHE_ANT
/**=httpSessionContextIntegrationFilter,authenticat ionProcessingFilter
</value>
</property>
</bean>

---

That looks fine. Could you please post a full DEBUG log of an attempt to authenticate, from the original redirection to the login page through to where the j_acegi_security_check processes the request.

The requested debug is huge and I was unable to post the whole thing for the requested period so I have had to edit it. I hope I have not thrown away anything useful. Thanks for the help, heres the debug:

2005-03-14 09:59:03,304 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/app?service=page/login'; to: '/app?service=page/login'>
2005-03-14 09:59:03,305 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/app?service=page/login'; pattern is /**; matched=true>
2005-03-14 09:59:03,305 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:03,306 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:03,372 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=page/Login at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:03,382 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:03,383 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=page/Login at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:03,384 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=page/Login reached end of additional filter chain; proceeding with original chain>
2005-03-14 09:59:03,444 DEBUG [org.apache.tapestry.ApplicationServlet] - <Retrieved com.bluestoneworks.tapestry.AppEngine@9ded20[name=<Unknown specification>,dirty=false,locale=en_US,stateful=t rue,visit=com.bluestoneworks.tapestry.AppVisit@b70 f41,activePageNames=<null>] from session 95FE777F7D8E692060CA4A016EB65C9C.>
2005-03-14 09:59:03,449 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <Begin service /fleet/app>
2005-03-14 09:59:10,648 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <End service>
2005-03-14 09:59:10,649 DEBUG [org.apache.tapestry.ApplicationServlet] - <Storing com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] into session as org.apache.tapestry.engine:fleet>
2005-03-14 09:59:10,649 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,649 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <ContextHolder set to null as request processing completed>
2005-03-14 09:59:10,676 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fhtml%2fpracticalbrowsersniffer.js'; to: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fhtml%2fpracticalbrowsersniffer.js'>
2005-03-14 09:59:10,677 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fhtml%2fpracticalbrowsersniffer.js'; pattern is /**; matched=true>
2005-03-14 09:59:10,678 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:10,678 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:10,678 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fhtml%2FPracticalBrowserSniffer.js at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:10,679 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,679 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fhtml%2FPracticalBrowserSniffer.js at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:10,680 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fhtml%2FPracticalBrowserSniffer.js reached end of additional filter chain; proceeding with original chain>
2005-03-14 09:59:10,680 DEBUG [org.apache.tapestry.ApplicationServlet] - <Retrieved com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] from session 95FE777F7D8E692060CA4A016EB65C9C.>
2005-03-14 09:59:10,680 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <Begin service /fleet/app>
2005-03-14 09:59:10,682 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <getResource(/org/apache/tapestry/html/PracticalBrowserSniffer.js)>
2005-03-14 09:59:10,684 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <Found as jar:file:/usr/local/jakarta-tomcat-5.5.7/webapps/fleet/WEB-INF/lib/tapestry-3.0.2.jar!/org/apache/tapestry/html/PracticalBrowserSniffer.js>
2005-03-14 09:59:10,696 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,699 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,701 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <End service>
2005-03-14 09:59:10,703 DEBUG [org.apache.tapestry.ApplicationServlet] - <Storing com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] into session as org.apache.tapestry.engine:fleet>
2005-03-14 09:59:10,704 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,712 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2ftapestry-logo.gif'; to: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2ftapestry-logo.gif'>
2005-03-14 09:59:10,720 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2ftapestry-logo.gif'; pattern is /**; matched=true>
2005-03-14 09:59:10,720 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:10,721 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:10,721 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Ftapestry-logo.gif at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:10,722 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,722 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Ftapestry-logo.gif at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:10,723 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Ftapestry-logo.gif reached end of additional filter chain; proceeding with original chain>
2005-03-14 09:59:10,724 DEBUG [org.apache.tapestry.ApplicationServlet] - <Retrieved com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] from session 95FE777F7D8E692060CA4A016EB65C9C.>
2005-03-14 09:59:10,724 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <Begin service /fleet/app>
2005-03-14 09:59:10,725 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <getResource(/org/apache/tapestry/contrib/inspector/tapestry-logo.gif)>
2005-03-14 09:59:10,726 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <Found as jar:file:/usr/local/jakarta-tomcat-5.5.7/webapps/fleet/WEB-INF/lib/tapestry-contrib-3.0.2.jar!/org/apache/tapestry/contrib/inspector/tapestry-logo.gif>
2005-03-14 09:59:10,727 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,729 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,731 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <ContextHolder set to null as request processing completed>
2005-03-14 09:59:10,733 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <End service>
2005-03-14 09:59:10,733 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2finspector-rollover.gif'; to: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2finspector-rollover.gif'>
2005-03-14 09:59:10,734 DEBUG [org.apache.tapestry.ApplicationServlet] - <Storing com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] into session as org.apache.tapestry.engine:fleet>
2005-03-14 09:59:10,736 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,736 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <ContextHolder set to null as request processing completed>
2005-03-14 09:59:10,738 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/app?service=asset&sp=s%2forg%2fapache%2ftapestry%2 fcontrib%2finspector%2finspector-rollover.gif'; pattern is /**; matched=true>
2005-03-14 09:59:10,742 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:10,743 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:10,744 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Finspector-rollover.gif at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:10,745 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,753 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Finspector-rollover.gif at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:10,754 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app?service=asset&sp=S%2Forg%2Fapache%2Ftapestry%2 Fcontrib%2Finspector%2Finspector-rollover.gif reached end of additional filter chain; proceeding with original chain>
2005-03-14 09:59:10,755 DEBUG [org.apache.tapestry.ApplicationServlet] - <Retrieved com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] from session 95FE777F7D8E692060CA4A016EB65C9C.>
2005-03-14 09:59:10,756 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <Begin service /fleet/app>
2005-03-14 09:59:10,757 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <getResource(/org/apache/tapestry/contrib/inspector/inspector-rollover.gif)>
2005-03-14 09:59:10,761 DEBUG [org.apache.tapestry.util.DefaultResourceResolver] - <Found as jar:file:/usr/local/jakarta-tomcat-5.5.7/webapps/fleet/WEB-INF/lib/tapestry-contrib-3.0.2.jar!/org/apache/tapestry/contrib/inspector/inspector-rollover.gif>
2005-03-14 09:59:10,778 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,781 DEBUG [org.apache.tapestry.util.pool.Pool] - <Cleared>
2005-03-14 09:59:10,785 DEBUG [org.apache.tapestry.engine.AbstractEngine] - <End service>
2005-03-14 09:59:10,786 DEBUG [org.apache.tapestry.ApplicationServlet] - <Storing com.bluestoneworks.tapestry.AppEngin....tapestry.AppVisit@b70f41,activePageNames=<null>] into session as org.apache.tapestry.engine:fleet>
2005-03-14 09:59:10,788 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:10,789 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <ContextHolder set to null as request processing completed>
2005-03-14 09:59:16,092 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/j_acegi_security_check'; to: '/j_acegi_security_check'>
2005-03-14 09:59:16,093 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/j_acegi_security_check'; pattern is /**; matched=true>
2005-03-14 09:59:16,095 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:16,096 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:16,097 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </j_acegi_security_check at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:16,098 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:16,100 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </j_acegi_security_check at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:16,101 DEBUG [net.sf.acegisecurity.ui.AbstractProcessingFilter] - <Request is to process authentication>
2005-03-14 09:59:16,105 DEBUG [net.sf.acegisecurity.providers.ProviderManager] - <Authentication attempt using net.sf.acegisecurity.providers.dao.DaoAuthenticati onProvider>
2005-03-14 09:59:16,105 DEBUG [net.sf.ehcache.store.MemoryStore] - <userCacheCache: MemoryStore miss for wally>
2005-03-14 09:59:16,106 DEBUG [net.sf.ehcache.Cache] - <userCache cache - Miss>
2005-03-14 09:59:16,106 DEBUG [net.sf.acegisecurity.providers.dao.cache.EhCacheBa sedUserCache] - <Cache hit: false; username: wally>
2005-03-14 09:59:16,110 DEBUG [org.springframework.orm.hibernate.SessionFactoryUt ils] - <Opening Hibernate session>
2005-03-14 09:59:16,615 DEBUG [net.sf.hibernate.impl.SessionImpl] - <opened session>
2005-03-14 09:59:16,646 DEBUG [net.sf.hibernate.impl.SessionImpl] - <find:
from com.bluestoneworks.bus.AppUser a where a.name = ?
>
2005-03-14 09:59:16,651 DEBUG [net.sf.hibernate.engine.QueryParameters] - <parameters: [wally]>
2005-03-14 09:59:16,652 DEBUG [net.sf.hibernate.engine.QueryParameters] - <named parameters: {}>
2005-03-14 09:59:16,703 DEBUG [net.sf.hibernate.hql.QueryTranslator] - <compiling query>
2005-03-14 09:59:16,743 DEBUG [net.sf.hibernate.impl.SessionImpl] - <flushing session>
2005-03-14 09:59:16,743 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushing entities and processing referenced collections>
2005-03-14 09:59:16,744 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Processing unreferenced collections>
2005-03-14 09:59:16,744 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Scheduling collection removes/(re)creates/updates>
2005-03-14 09:59:16,744 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects>
2005-03-14 09:59:16,744 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections>
2005-03-14 09:59:16,744 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Dont need to execute flush>
2005-03-14 09:59:16,745 DEBUG [net.sf.hibernate.hql.QueryTranslator] - <HQL:
from com.bluestoneworks.bus.AppUser a where a.name = ?
>
2005-03-14 09:59:16,745 DEBUG [net.sf.hibernate.hql.QueryTranslator] - <SQL: select appuser0_.id as id, appuser0_.name as name, appuser0_.password as password, appuser0_.enabled as enabled from app_user appuser0_ where (appuser0_.name=? )>
2005-03-14 09:59:16,746 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <about to open: 0 open PreparedStatements, 0 open ResultSets>
2005-03-14 09:59:16,747 DEBUG [net.sf.hibernate.SQL] - <select appuser0_.id as id, appuser0_.name as name, appuser0_.password as password, appuser0_.enabled as enabled from app_user appuser0_ where (appuser0_.name=? )>
2005-03-14 09:59:16,747 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <preparing statement>
2005-03-14 09:59:16,767 DEBUG [net.sf.hibernate.type.StringType] - <binding 'wally' to parameter: 1>
2005-03-14 09:59:16,783 DEBUG [net.sf.hibernate.loader.Loader] - <processing result set>
2005-03-14 09:59:16,784 DEBUG [net.sf.hibernate.type.IntegerType] - <returning '50' as column: id>
2005-03-14 09:59:16,786 DEBUG [net.sf.hibernate.loader.Loader] - <result row: 50>
2005-03-14 09:59:16,787 DEBUG [net.sf.hibernate.loader.Loader] - <Initializing object from ResultSet: 50>
2005-03-14 09:59:16,791 DEBUG [net.sf.hibernate.loader.Loader] - <Hydrating entity: com.bluestoneworks.bus.AppUser#50>
2005-03-14 09:59:16,793 DEBUG [net.sf.hibernate.type.StringType] - <returning 'wally' as column: name>
2005-03-14 09:59:16,793 DEBUG [net.sf.hibernate.type.StringType] - <returning 'wally' as column: password>
2005-03-14 09:59:16,794 DEBUG [net.sf.hibernate.type.BooleanType] - <returning 'true' as column: enabled>
2005-03-14 09:59:16,800 DEBUG [net.sf.hibernate.loader.Loader] - <done processing result set (1 rows)>
2005-03-14 09:59:16,801 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <done closing: 0 open PreparedStatements, 0 open ResultSets>
2005-03-14 09:59:16,801 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <closing statement>
2005-03-14 09:59:16,802 DEBUG [net.sf.hibernate.loader.Loader] - <total objects hydrated: 1>
2005-03-14 09:59:16,808 DEBUG [net.sf.hibernate.impl.SessionImpl] - <resolving associations for [com.bluestoneworks.bus.AppUser#50]>
2005-03-14 09:59:16,812 DEBUG [net.sf.hibernate.impl.SessionImpl] - <creating collection wrapper:[com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,826 DEBUG [net.sf.hibernate.impl.SessionImpl] - <done materializing entity [com.bluestoneworks.bus.AppUser#50]>
2005-03-14 09:59:16,826 DEBUG [net.sf.hibernate.impl.SessionImpl] - <initializing non-lazy collections>
2005-03-14 09:59:16,827 DEBUG [net.sf.hibernate.impl.SessionImpl] - <initializing collection [com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,827 DEBUG [net.sf.hibernate.impl.SessionImpl] - <checking second-level cache>
2005-03-14 09:59:16,828 DEBUG [net.sf.hibernate.impl.SessionImpl] - <collection not cached>
2005-03-14 09:59:16,828 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <about to open: 0 open PreparedStatements, 0 open ResultSets>
2005-03-14 09:59:16,829 DEBUG [net.sf.hibernate.SQL] - <select roles0_.app_user_id as app_user2___, roles0_.id as id__, roles0_.id as id0_, roles0_.app_user_id as app_user2_0_, roles0_.role as role0_ from app_user_role roles0_ where roles0_.app_user_id=?>
2005-03-14 09:59:16,829 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <preparing statement>
2005-03-14 09:59:16,830 DEBUG [net.sf.hibernate.type.IntegerType] - <binding '50' to parameter: 1>
2005-03-14 09:59:16,831 DEBUG [net.sf.hibernate.loader.Loader] - <result set contains (possibly empty) collection: [com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,832 DEBUG [net.sf.hibernate.impl.SessionImpl] - <uninitialized collection: initializing>
2005-03-14 09:59:16,835 DEBUG [net.sf.hibernate.loader.Loader] - <processing result set>
2005-03-14 09:59:16,836 DEBUG [net.sf.hibernate.type.IntegerType] - <returning '78' as column: id0_>
2005-03-14 09:59:16,837 DEBUG [net.sf.hibernate.loader.Loader] - <result row: 78>
2005-03-14 09:59:16,837 DEBUG [net.sf.hibernate.loader.Loader] - <Initializing object from ResultSet: 78>
2005-03-14 09:59:16,839 DEBUG [net.sf.hibernate.loader.Loader] - <Hydrating entity: com.bluestoneworks.bus.AppUserRole#78>
2005-03-14 09:59:16,840 DEBUG [net.sf.hibernate.type.IntegerType] - <returning '50' as column: app_user2_0_>
2005-03-14 09:59:16,840 DEBUG [net.sf.hibernate.type.StringType] - <returning 'USER' as column: role0_>
2005-03-14 09:59:16,841 DEBUG [net.sf.hibernate.type.IntegerType] - <returning '50' as column: app_user2___>
2005-03-14 09:59:16,841 DEBUG [net.sf.hibernate.loader.Loader] - <found row of collection: [com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,842 DEBUG [net.sf.hibernate.impl.SessionImpl] - <reading row>
2005-03-14 09:59:16,842 DEBUG [net.sf.hibernate.type.IntegerType] - <returning '78' as column: id__>
2005-03-14 09:59:16,843 DEBUG [net.sf.hibernate.impl.SessionImpl] - <loading [com.bluestoneworks.bus.AppUserRole#78]>
2005-03-14 09:59:16,843 DEBUG [net.sf.hibernate.impl.SessionImpl] - <attempting to resolve [com.bluestoneworks.bus.AppUserRole#78]>
2005-03-14 09:59:16,845 DEBUG [net.sf.hibernate.impl.SessionImpl] - <resolved object in session cache [com.bluestoneworks.bus.AppUserRole#78]>
2005-03-14 09:59:16,846 DEBUG [net.sf.hibernate.loader.Loader] - <done processing result set (1 rows)>
2005-03-14 09:59:16,846 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <done closing: 0 open PreparedStatements, 0 open ResultSets>
2005-03-14 09:59:16,846 DEBUG [net.sf.hibernate.impl.BatcherImpl] - <closing statement>
2005-03-14 09:59:16,847 DEBUG [net.sf.hibernate.loader.Loader] - <total objects hydrated: 1>
2005-03-14 09:59:16,847 DEBUG [net.sf.hibernate.impl.SessionImpl] - <resolving associations for [com.bluestoneworks.bus.AppUserRole#78]>
2005-03-14 09:59:16,847 DEBUG [net.sf.hibernate.impl.SessionImpl] - <loading [com.bluestoneworks.bus.AppUser#50]>
2005-03-14 09:59:16,847 DEBUG [net.sf.hibernate.impl.SessionImpl] - <attempting to resolve [com.bluestoneworks.bus.AppUser#50]>
2005-03-14 09:59:16,848 DEBUG [net.sf.hibernate.impl.SessionImpl] - <resolved object in session cache [com.bluestoneworks.bus.AppUser#50]>
2005-03-14 09:59:16,848 DEBUG [net.sf.hibernate.impl.SessionImpl] - <done materializing entity [com.bluestoneworks.bus.AppUserRole#78]>
2005-03-14 09:59:16,849 DEBUG [net.sf.hibernate.impl.SessionImpl] - <1 collections were found in result set>
2005-03-14 09:59:16,849 DEBUG [net.sf.hibernate.impl.SessionImpl] - <collection fully initialized: [com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,850 DEBUG [net.sf.hibernate.impl.SessionImpl] - <1 collections initialized>
2005-03-14 09:59:16,850 DEBUG [net.sf.hibernate.impl.SessionImpl] - <collection initialized>
2005-03-14 09:59:16,850 DEBUG [org.springframework.orm.hibernate.HibernateTemplat e] - <Eagerly flushing Hibernate session>
2005-03-14 09:59:16,851 DEBUG [net.sf.hibernate.impl.SessionImpl] - <flushing session>
2005-03-14 09:59:16,854 DEBUG [net.sf.hibernate.engine.Cascades] - <processing cascades for: com.bluestoneworks.bus.AppUser>
2005-03-14 09:59:16,865 DEBUG [net.sf.hibernate.engine.Cascades] - <cascading to collection: com.bluestoneworks.bus.AppUser.roles>
2005-03-14 09:59:16,869 DEBUG [net.sf.hibernate.engine.Cascades] - <cascading to saveOrUpdate()>
2005-03-14 09:59:16,869 DEBUG [net.sf.hibernate.impl.SessionImpl] - <saveOrUpdate() persistent instance>
2005-03-14 09:59:16,869 DEBUG [net.sf.hibernate.engine.Cascades] - <done processing cascades for: com.bluestoneworks.bus.AppUser>
2005-03-14 09:59:16,870 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushing entities and processing referenced collections>
2005-03-14 09:59:16,894 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Collection found: [com.bluestoneworks.bus.AppUser.roles#50], was: [com.bluestoneworks.bus.AppUser.roles#50]>
2005-03-14 09:59:16,895 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Processing unreferenced collections>
2005-03-14 09:59:16,895 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Scheduling collection removes/(re)creates/updates>
2005-03-14 09:59:16,896 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects>
2005-03-14 09:59:16,896 DEBUG [net.sf.hibernate.impl.SessionImpl] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections>
2005-03-14 09:59:16,896 DEBUG [net.sf.hibernate.impl.Printer] - <listing entities:>
2005-03-14 09:59:16,897 DEBUG [net.sf.hibernate.impl.Printer] - <com.bluestoneworks.bus.AppUser{password=wally, enabled=true, roles=[AppUserRole#78], name=wally, id=50}>
2005-03-14 09:59:16,898 DEBUG [net.sf.hibernate.impl.Printer] - <com.bluestoneworks.bus.AppUserRole{appUser=AppUse r#50, role=USER, id=78}>
2005-03-14 09:59:16,898 DEBUG [net.sf.hibernate.impl.SessionImpl] - <executing flush>
2005-03-14 09:59:16,899 DEBUG [net.sf.hibernate.impl.SessionImpl] - <post flush>
2005-03-14 09:59:16,899 DEBUG [org.springframework.orm.hibernate.SessionFactoryUt ils] - <Closing Hibernate session>
2005-03-14 09:59:16,900 DEBUG [net.sf.hibernate.impl.SessionImpl] - <closing session>
2005-03-14 09:59:16,900 DEBUG [net.sf.hibernate.impl.SessionImpl] - <disconnecting session>
2005-03-14 09:59:16,907 DEBUG [net.sf.hibernate.impl.SessionImpl] - <transaction completion>
2005-03-14 09:59:16,912 DEBUG [net.sf.acegisecurity.providers.dao.cache.EhCacheBa sedUserCache] - <Cache put: wally>
2005-03-14 09:59:16,913 DEBUG [net.sf.ehcache.Cache] - <wally now: 1110794356913>
2005-03-14 09:59:16,914 DEBUG [net.sf.ehcache.Cache] - <wally Creation Time: 1110794356912 Next To Last Access Time: 0>
2005-03-14 09:59:16,914 DEBUG [net.sf.ehcache.Cache] - <wally mostRecentTime: 1110794356912>
2005-03-14 09:59:16,915 DEBUG [net.sf.ehcache.Cache] - <wally Age to Idle: 500000 Age Idled: 1>
2005-03-14 09:59:16,915 DEBUG [net.sf.ehcache.Cache] - <userCache: Is element with key wally expired?: false>
2005-03-14 09:59:16,916 DEBUG [org.springframework.web.context.support.XmlWebAppl icationContext] - <Publishing event in context [org.springframework.web.context.support.XmlWebAppl icationContext;hashCode=5166152]: net.sf.acegisecurity.providers.dao.event.Authentic ationSuccessEvent[source=net.sf.acegisecurity.providers.UsernamePass wordAuthenticationToken@f450c4: Username: wally; Password: [PROTECTED]; Authenticated: false; Details: 127.0.0.1; Not granted any authorities]>
2005-03-14 09:59:16,917 INFO [net.sf.acegisecurity.providers.dao.event.LoggerLis tener] - <Authentication success for user: wally; details: 127.0.0.1>
2005-03-14 09:59:16,918 DEBUG [net.sf.acegisecurity.ui.AbstractProcessingFilter] - <Authentication success: net.sf.acegisecurity.providers.UsernamePasswordAut henticationToken@36d2b3: Username: com.bluestoneworks.security.UserDet@42e9fb; Password: [PROTECTED]; Authenticated: false; Details: 127.0.0.1; Granted Authorities: ROLE_USER>
2005-03-14 09:59:16,918 DEBUG [net.sf.acegisecurity.ui.AbstractProcessingFilter] - <Redirecting to target URL from HTTP Session (or default): /fleet/app>
2005-03-14 09:59:16,919 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:16,919 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <ContextHolder set to null as request processing completed>
2005-03-14 09:59:16,922 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Converted URL to lowercase, from: '/app'; to: '/app'>
2005-03-14 09:59:16,923 DEBUG [net.sf.acegisecurity.intercept.web.PathBasedFilter InvocationDefinitionMap] - <Candidate is: '/app'; pattern is /**; matched=true>
2005-03-14 09:59:16,923 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'httpSessionContextIntegrationFilter'>
2005-03-14 09:59:16,923 DEBUG [org.springframework.beans.factory.support.DefaultL istableBeanFactory] - <Returning cached instance of singleton bean 'authenticationProcessingFilter'>
2005-03-14 09:59:16,923 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app at position 1 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.context.HttpSessionContextIn tegrationFilter@386ac2'>
2005-03-14 09:59:16,923 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Obtained from ACEGI_SECURITY_CONTEXT a valid Context and set to ContextHolder: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>
2005-03-14 09:59:16,923 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app at position 2 of 2 in additional filter chain; firing Filter: 'net.sf.acegisecurity.ui.webapp.AuthenticationProc essingFilter@e8e6aa'>
2005-03-14 09:59:16,924 DEBUG [net.sf.acegisecurity.util.FilterChainProxy] - </app reached end of additional filter chain; proceeding with original chain>

These lines concern me:

Quote:

---

2005-03-14 09:59:16,918 DEBUG [net.sf.acegisecurity.ui.AbstractProcessingFilter] - <Authentication success: net.sf.acegisecurity.providers.UsernamePasswordAut henticationToken@36d2b3: Username: com.bluestoneworks.security.UserDet@42e9fb; Password: [PROTECTED]; Authenticated: false; Details: 127.0.0.1; Granted Authorities: ROLE_USER>
2005-03-14 09:59:16,918 DEBUG [net.sf.acegisecurity.ui.AbstractProcessingFilter] - <Redirecting to target URL from HTTP Session (or default): /fleet/app>
2005-03-14 09:59:16,919 DEBUG [net.sf.acegisecurity.context.HttpSessionContextInt egrationFilter] - <Context stored to HttpSession: 'net.sf.acegisecurity.context.security.SecureConte xtImpl@955d1c: Null authentication'>

---

If you check the code for AbstractProcessingFilter, you can see the issue:

Code:

---

    protected void successfulAuthentication(HttpServletRequest request,
        HttpServletResponse response, Authentication authResult)
        throws IOException {
        if (logger.isDebugEnabled()) {
            logger.debug("Authentication success: " + authResult.toString());
        }

        SecureContext sc = SecureContextUtils.getSecureContext();
        sc.setAuthentication(authResult);

        if (logger.isDebugEnabled()) {
            logger.debug(
                "Updated ContextHolder to contain the following Authentication: '"
                + authResult + "'");
        }

        String targetUrl = (String) request.getSession().getAttribute(ACEGI_SECURITY_TARGET_URL_KEY);
        request.getSession().removeAttribute(ACEGI_SECURITY_TARGET_URL_KEY);

        if (alwaysUseDefaultTargetUrl == true) {
            targetUrl = null;
        }

        if (targetUrl == null) {
            targetUrl = request.getContextPath() + defaultTargetUrl;
        }

        if (logger.isDebugEnabled()) {
            logger.debug(
                "Redirecting to target URL from HTTP Session (or default): "
                + targetUrl);
        }

---

As shown, the "updated ContextHolder to contain the following Authentication" log message never happened. Equally odd is the ContextHolder is definitely contain a non-null SecureContextImpl, as proven by the final log message.

Can you check your classpath doesn't contain any old Acegi Security JARs. If there aren't any, try building from Acegi Security CVS and inserting some more logging around the two lines which should be setting the Authentication into the ContextHolder (SecureContext sc = .... and sc.setAuthentication(authResult)).

Thanks Ben, sorry for wasting your time, it was a stupid error on my behalf, I had left an old Acegi Security jar file on the classpath.