4 Replies Latest reply on Jun 9, 2011 11:00 AM by dlofthouse

Concurrent authentication failure after startup caused by misplaced LoginModule logout???

justincranford Jun 8, 2011 9:05 PM

I am experiencing an authentication failure in JBoss 6.0 Final. It only happens if I hit the server with concurrent HTTPS requests immediately after starting up JBoss. If I hit the server with serialized requests after startup then every request succeeds. Then if I hit the server again with the concurrent burst of requests after it warmed up, they all succeed. It only happens if the server's first requests are overlapping, causing overlapping (competing?) JBossSX initializations.

The problem is some kind of weird initialization issue in the login modules. The server log shows DatabaseServerLoginModule authenticating all N requests in parallel, but then DatabaseServerLoginModule and ClientLoginModule do N-1 logouts. Those N-1 requests get sent back to the client as 401 unauthenticated errors, while the one request goes on to succeed with a 200 ok. There are N-1 stack traces saying "Error during authenticate: java.lang.IllegalStateException: Security Context has not been set", but they happen downstream of the N-1 LoginModule logout calls which would have nullified those security contexts.

Q1: How can I fix this concurrent login issue?

Q2: Is it possible for the same user to be authenticated for multiple requests at the same time? (I assume YES, because it works if the server is "warmed" up)

Here is my login-config.xml.

<application-policy name="JustinCranfordSecurityDomain">

<login-module code="org.jboss.security.auth.spi.DatabaseServerLoginModule" flag="sufficient">

<module-option name="multi-threaded">true</module-option>

<module-option name="dsJndiName">java:/MsSqlDS</module-option>

<module-option name="principalsQuery">SELECT password FROM actor WHERE name=?</module-option>

<module-option name="rolesQuery">SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?</module-option>

<module-option name="hashAlgorithm">MD5</module-option>

<module-option name="hashEncoding">base64</module-option>

<module-option name="unauthenticatedIdentity">unauthenticated</module-option>

</login-module>

<login-module code="org.jboss.security.ClientLoginModule" flag="required">

<module-option name="multi-threaded">true</module-option>

<module-option name="restore-login-identity">false</module-option>

</login-module>

</authentication>

<audit>

<provider-module code="org.jboss.security.audit.providers.LogAuditProvider"/>

<provider-module code="com.myorg.JBossSecurityAuditProvider"/>

</audit>

</application-policy>

I am testing the concurrent behaviour of my REST application using a JUnit test class with annotated with @RunWith(Parallelized.class). Each test class instance hits the server with 6 serialized requests. Changing NUM_CLASS_ITERATIONS causes JUnit to run multiple instances of the same test class in parallel.

@RunWith(Parallelized.class)

public class TestRPRestWeb {

private static final int NUM_CLASS_ITERATIONS = 3; // 1 always works, N>=2 only works if server was warmed up by a serialized run

...

}

Here is my trace server log after the server starts up and receives the first 3 requests in parallel. I compared the server log to a single run, and here is the apparent sequence of events:

A: 3 successful DatabaseServerLoginModule authentications

B: 2 logouts by DatabaseServerLoginModule and ClientLoginModule (WHY?!?!?!?!?!?!?!?!?!?)

C: 3 requests move on to try to execute the Resteasy resource method

D: 2 missing security context exceptions versus 1 successful execution.

The 2 null security contexts exceptions are likely due to the 2 logout() calls in B, so the root cause of this concurrency issue seems to be in PicketBox.

19:57:13,577 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,577 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,577 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_1
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_0
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_2
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,578 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,625 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,625 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,625 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
19:57:13,640 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
19:57:13,640 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
19:57:13,640 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
19:57:13,640 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
19:57:13,656 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,656 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,656 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_2
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_1
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request GET /RPWeb/rest/customer/My_Customer_Name_0
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
19:57:13,656 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,656 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,656 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,656 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
19:57:13,656 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] Begin getAppConfigurationEntry(JustinCranfordSecurityDomain), size=12
19:57:13,656 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] Begin getAppConfigurationEntry(JustinCranfordSecurityDomain), size=12
19:57:13,656 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] Begin getAppConfigurationEntry(JustinCranfordSecurityDomain), size=12
19:57:13,671 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] End getAppConfigurationEntry(JustinCranfordSecurityDomain), authInfo=AppConfigurationEntry[]:
[0]
LoginModule Class: org.jboss.security.auth.spi.DatabaseServerLoginModule
ControlFlag: LoginModuleControlFlag: sufficient
Options:
name=multi-threaded, value=true
name=hashAlgorithm, value=MD5
name=principalsQuery, value=SELECT password FROM actor WHERE name=?
name=unauthenticatedIdentity, value=unauthenticated
name=hashEncoding, value=base64
name=dsJndiName, value=java:/MsSqlDS
name=rolesQuery, value=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
[1]
LoginModule Class: org.jboss.security.ClientLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:
name=multi-threaded, value=true
name=restore-login-identity, value=false

19:57:13,671 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] End getAppConfigurationEntry(JustinCranfordSecurityDomain), authInfo=AppConfigurationEntry[]:
[0]
LoginModule Class: org.jboss.security.auth.spi.DatabaseServerLoginModule
ControlFlag: LoginModuleControlFlag: sufficient
Options:
name=multi-threaded, value=true
name=hashAlgorithm, value=MD5
name=principalsQuery, value=SELECT password FROM actor WHERE name=?
name=unauthenticatedIdentity, value=unauthenticated
name=hashEncoding, value=base64
name=dsJndiName, value=java:/MsSqlDS
name=rolesQuery, value=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
[1]
LoginModule Class: org.jboss.security.ClientLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:
name=multi-threaded, value=true
name=restore-login-identity, value=false

19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] initialize
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] initialize
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] initialize
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Security domain: JustinCranfordSecurityDomain
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Security domain: JustinCranfordSecurityDomain
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Security domain: JustinCranfordSecurityDomain
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Saw unauthenticatedIdentity=unauthenticated
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Saw unauthenticatedIdentity=unauthenticated
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Saw unauthenticatedIdentity=unauthenticated
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Password hashing activated: algorithm = MD5, encoding = base64, charset = {default}, callback = null, storeCallback = null
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Password hashing activated: algorithm = MD5, encoding = base64, charset = {default}, callback = null, storeCallback = null
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Password hashing activated: algorithm = MD5, encoding = base64, charset = {default}, callback = null, storeCallback = null
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] DatabaseServerLoginModule, dsJndiName=java:/MsSqlDS
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] DatabaseServerLoginModule, dsJndiName=java:/MsSqlDS
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] DatabaseServerLoginModule, dsJndiName=java:/MsSqlDS
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] principalsQuery=SELECT password FROM actor WHERE name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] principalsQuery=SELECT password FROM actor WHERE name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] principalsQuery=SELECT password FROM actor WHERE name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] rolesQuery=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] rolesQuery=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendResume=true
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] rolesQuery=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendResume=true
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendResume=true
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] login
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] login
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] login
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,671 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,687 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT password FROM actor WHERE name=?, with username: systemadmin
19:57:13,703 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT password FROM actor WHERE name=?, with username: systemadmin
19:57:13,765 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT password FROM actor WHERE name=?, with username: systemadmin
19:57:13,781 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Obtained user password
19:57:13,781 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Obtained user password
19:57:13,781 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Obtained user password
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] User 'systemadmin' authenticated, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] User 'systemadmin' authenticated, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] User 'systemadmin' authenticated, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] commit, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] commit, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] commit, loginOk=true
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] getRoleSets using rolesQuery: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] getRoleSets using rolesQuery: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] getRoleSets using rolesQuery: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, with username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, with username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, with username: systemadmin
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Assign user to role SystemAdministrator
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Assign user to role SystemAdministrator
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Assign user to role SystemAdministrator
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
19:57:13,796 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] logout
19:57:13,796 TRACE [org.jboss.web.tomcat.security.JBossWebRealm] User: systemadmin is authenticated
19:57:13,796 TRACE [org.jboss.security.ClientLoginModule] Security domain: JustinCranfordSecurityDomain
19:57:13,796 TRACE [org.jboss.security.ClientLoginModule] Enabling multi-threaded mode
19:57:13,796 TRACE [org.jboss.security.ClientLoginModule] Enabling restore-login-identity mode
19:57:13,796 TRACE [org.jboss.security.ClientLoginModule] logout
19:57:13,812 TRACE [org.jboss.web.tomcat.security.JBossWebRealm] User: systemadmin is authenticated
19:57:13,812 TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] logout
19:57:13,812 TRACE [org.jboss.security.ClientLoginModule] Security domain: JustinCranfordSecurityDomain
19:57:13,812 TRACE [org.jboss.security.ClientLoginModule] Enabling multi-threaded mode
19:57:13,812 TRACE [org.jboss.security.ClientLoginModule] Enabling restore-login-identity mode
19:57:13,812 TRACE [org.jboss.security.ClientLoginModule] logout
19:57:13,812 TRACE [org.jboss.web.tomcat.security.JBossWebRealm] User: systemadmin is authenticated
19:57:13,812 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Authenticated 'systemadmin' with type 'BASIC'
19:57:13,812 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling accessControl()
19:57:13,827 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,827 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
19:57:13,827 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Successfully passed all security constraints
19:57:13,812 ERROR [org.jboss.web.tomcat.security.JBossWebRealm] Error during authenticate: java.lang.IllegalStateException: Security Context has not been set
at org.jboss.web.tomcat.security.SecurityAssociationActions$SetPrincipalInfoAction.run(SecurityAssociationActions.java:70) [:6.0.0.Final]
at java.security.AccessController.doPrivileged(Native Method) [:1.6.0_24]
at org.jboss.web.tomcat.security.SecurityAssociationActions.setPrincipalInfo(SecurityAssociationActions.java:270) [:6.0.0.Final]
at org.jboss.web.tomcat.security.JBossWebRealm.authenticate(JBossWebRealm.java:403) [:6.0.0.Final]
at org.apache.catalina.authenticator.BasicAuthenticator.authenticate(BasicAuthenticator.java:180) [:6.0.0.Final]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:559) [:6.0.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.event(CatalinaContext.java:285) [:1.1.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.invoke(CatalinaContext.java:261) [:1.1.0.Final]
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:88) [:6.0.0.Final]
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:100) [:6.0.0.Final]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [:6.0.0.Final]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [:6.0.0.Final]
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) [:6.0.0.Final]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [:6.0.0.Final]
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:53) [:6.0.0.Final]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [:6.0.0.Final]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:951) [:6.0.0.Final]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_24]

19:57:13,812 ERROR [org.jboss.web.tomcat.security.JBossWebRealm] Error during authenticate: java.lang.IllegalStateException: Security Context has not been set
at org.jboss.web.tomcat.security.SecurityAssociationActions$SetPrincipalInfoAction.run(SecurityAssociationActions.java:70) [:6.0.0.Final]
at java.security.AccessController.doPrivileged(Native Method) [:1.6.0_24]
at org.jboss.web.tomcat.security.SecurityAssociationActions.setPrincipalInfo(SecurityAssociationActions.java:270) [:6.0.0.Final]
at org.jboss.web.tomcat.security.JBossWebRealm.authenticate(JBossWebRealm.java:403) [:6.0.0.Final]
at org.apache.catalina.authenticator.BasicAuthenticator.authenticate(BasicAuthenticator.java:180) [:6.0.0.Final]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:559) [:6.0.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.event(CatalinaContext.java:285) [:1.1.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.invoke(CatalinaContext.java:261) [:1.1.0.Final]
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:88) [:6.0.0.Final]
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:100) [:6.0.0.Final]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [:6.0.0.Final]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [:6.0.0.Final]
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) [:6.0.0.Final]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [:6.0.0.Final]
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:53) [:6.0.0.Final]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [:6.0.0.Final]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:951) [:6.0.0.Final]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_24]

19:57:13,827 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
19:57:13,827 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
19:57:13,827 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
19:57:13,827 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
19:57:13,827 TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null

1. Re: Concurrent authentication failure after startup caused by misplaced LoginModule logout???

justincranford Jun 9, 2011 9:32 AM (in response to justincranford)

Fixed this through trial and error. Correct me if I am wrong, by JBoss login modules default to sharing credentials with all threads. To sandbox credential processing within each request thread, you must set multi-threaded=true and restore-login-identity=true for all modules in your <application-policy> in login-config.xml. I tested this on JBoss 6.0 Final, and setting either of these values to the default false causes my parallel JUnit client to fail tests. When I set both flags to true in both modules, my parallel JUnit client with 100 concurrent threads passed 100%.

Here is my updated <application-policy> which works for parallel processing, either immediately after JBoss startup or after the server has been warned up. Issue is resolved. I just wish JBoss documentation was a little more clear on this matter.

<application-policy name="JustinCranfordSecurityDomain">
<authentication>
   <login-module code="org.jboss.security.auth.spi.DatabaseServerLoginModule" flag="sufficient">
    <module-option name="multi-threaded">true</module-option>
    <module-option name="restore-login-identity">true</module-option>
    <module-option name="dsJndiName">java:/MsSqlDS</module-option>
    <module-option name="principalsQuery">SELECT password FROM actor WHERE name=?</module-option>
    <module-option name="rolesQuery">SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?</module-option>
    <module-option name="hashAlgorithm">MD5</module-option>
    <module-option name="hashEncoding">base64</module-option>
    <module-option name="unauthenticatedIdentity">unauthenticated</module-option>
   </login-module>
   <login-module code="org.jboss.security.ClientLoginModule" flag="required">
     <module-option name="multi-threaded">true</module-option>
     <module-option name="restore-login-identity">true</module-option>
   </login-module>
</authentication>
<audit>
   <provider-module code="org.jboss.security.audit.providers.LogAuditProvider"/>
   <provider-module code="com.mycom.JBossSecurityAuditProvider"/>
   </audit>
</application-policy>
Actions
2. Re: Concurrent authentication failure after startup caused by misplaced LoginModule logout???

dlofthouse Jun 9, 2011 10:07 AM (in response to justincranford)

You should not be using the ClientLoginModule on the server side in that way - it is that module most likely causing your problems,
Actions
3. Re: Concurrent authentication failure after startup caused by misplaced LoginModule logout???

justincranford Jun 9, 2011 10:57 AM (in response to dlofthouse)

Can you explain? This is different from what I read in the docs. According to the JBoss security doc, ClientLoginModule is required to propagate the authenticated principals to my business logic. Only then can I do a PolicyContext lookup on the server-side, like so...

/** JACC PolicyContext keys for current Subject & HttpServletRequest */
private static final String SUBJECT_CONTEXT_KEY = "javax.security.auth.Subject.container";
private static final String WEB_REQUEST_KEY     = "javax.servlet.http.HttpServletRequest";

public static final String getAuthenticatedUser() throws Throwable {
try {
   Subject caller = (Subject)PolicyContext.getContext(SUBJECT_CONTEXT_KEY);
   Set<Principal> principals = caller.getPrincipals();
   for (Principal principal: principals) {
    String principalName = principal.getName();
    if (!principalName.equals("Roles")) {
     return principalName;
    }
   }
} catch(Throwable t) {
   t.printStackTrace();
   throw t;
}
return null;
}
public static final HttpServletRequest getHttpServletRequest() throws Throwable {
try {
     return (HttpServletRequest)PolicyContext.getContext(WEB_REQUEST_KEY);
} catch(Throwable t) {
   t.printStackTrace();
   throw t;
}
}

It is my understand the "ClientLoginModule" name is really just an unfortunate, confusing name for "server-side credential propagation". For actual client-side authentication, this would be handled by some other "client" LoginModule, not "ClientLoginModule" itself. Is my understanding correct?
Actions
4. Re: Concurrent authentication failure after startup caused by misplaced LoginModule logout???

dlofthouse Jun 9, 2011 11:00 AM (in response to justincranford)

Do you have a link for the information you are following?

The ClientLoginModule is not suitable for use on the server side as when it is called it pushed an identity onto the current thread, logout is not called on that thread so the ClientLoginModule leaves behind whatever it pushed.
Actions

Go to original post