Repeated calls to LoginModule for EJB authentication

[kuzmiigo]

Hello!

I use login() and commit() method of my custom LoginModule to log successful and failed logins. If was fine when I used the security domain with that LoginModule for webapps only. When I made EJB session beans to use the same security domains, the log gets "User logged in" entries every time a session bean's method is called, i.e. LoginModule's login()/commit() methods are called every time an EJB bean's method is called.

Probably, it is inevitable, but can I distinguish (in login()/commit() methods) when it is "the fist/real" login (user entered info into the login form), or it is "repeated" login done by container using cached credentials?

Thank you,

Igor Kuzmitshov

[anil.saldhana]

For every ejb invocation, a security check is made. If the user is already authenticated, then his subject is picked from the security cache, if not a jaas login happens.

[kuzmiigo]

Thank you, Anil.

Although the subject is taken from the cache, I see that LoginModules's commit() method is called anyway. As I add "User logged in" to audit log in commit(), there are too much false "login" records in the log. I see two solutions:

1. To check whether login()/commit() are called for the first time (real login), or with the cached subject. Is it possible to distinguish these cases?

2. To add "login" records to the audit log in some other place. Where it should be placed?

Best regards,

Igor Kuzmitshov

[anil.saldhana]

Ur login modules commit is only called when your jaas login process is successful. When the subject is retrieved from the cache, there is no jaas login and no login module lifecycle invoked.

It is possible that components in different security domains may be invoking the jaas login.

Why don't you try to enable trace level loggng as outlined in the security faq (look at the beginning of this security forum).

[brownjamese]

Anil:

By cache are you refering to the cache maintained by JaasSecurityManagerService? ... configured through (in JBossAS 4.0.4GA) /deploy/security-service.xml? .. with the default configuration:

!-- JAAS security manager and realm mapping -->
 <mbean code="org.jboss.security.plugins.JaasSecurityManagerService" name="jboss.security:service=JaasSecurityManager">
 <attribute name="ServerMode">true</attribute>
 <attribute name="SecurityManagerClassName">org.jboss.security.plugins.JaasSecurityManager</attribute>
 <attribute name="DefaultUnauthenticatedPrincipal">anonymous</attribute>
 <attribute name="DefaultCacheTimeout">0</attribute>
 <attribute name="DefaultCacheResolution">0</attribute>
 </mbean>

The reason I ask is that we are encountering the same issue with a custom login module that extends AbstractServerLoginModule implementing only initialize, and login. Thus allowing the super's commit and logout to handle things.

-- James

[brownjamese]

Interesting and odd log entries - especially since I don't know what a good "run" should look like. I followed the security FAQ and added the necessary log4j config entries. After trundling through the info, I still see:
* multiple access to the login module's login() method; and
* inserts into the cache with different subject reference Id

For example, I see the actual login:

2007-02-08 14:58:03,121 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] Begin isValid, principal:U174791, cache info: null
2007-02-08 14:58:03,322 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] End isValid, true
2007-02-08 14:58:03,322 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm] User: U174791 is authenticated
2007-02-08 14:58:03,332 TRACE [org.jboss.security.SecurityAssociation] pushSubjectContext, subject=Subject:
 Principal: Roles(members:xxx,yyy,zzz)
 Principal: U174791
, sc=org.jboss.security.SecurityAssociation$SubjectContext@7c7d85{principal=U174791,subject=18143033}

Then access to the next URL, where the "hit" on the web app checks (and finds) the subject in cache:

2007-02-08 14:59:09,777 DEBUG [org.apache.catalina.core.ContainerBase.[jboss.web].[localhost]] Checking for SSO cookie
2007-02-08 14:59:09,777 DEBUG [org.apache.catalina.core.ContainerBase.[jboss.web].[localhost]] Checking for cached principal for D5612028A309EA8A4A5889D393B6251A
2007-02-08 14:59:09,777 DEBUG [org.apache.catalina.core.ContainerBase.[jboss.web].[localhost]] Found cached principal 'U174791' with auth type 'FORM'

But then access from web-app to EJB to EJB in another ear (all with same jaas policy configured) produces:

2007-02-08 14:59:09,907 TRACE [org.jboss.security.SecurityAssociation] getPrincipal, principal=U174791
2007-02-08 14:59:09,907 TRACE [org.jboss.security.SecurityAssociation] pushSubjectContext, subject=null, sc=org.jboss.security.SecurityAssociation$SubjectContext@7aed3a{principal=U174791,subject=null}
2007-02-08 14:59:09,928 TRACE [org.jboss.security.SecurityAssociation] pushRunAsIdentity, runAs=null
2007-02-08 14:59:09,958 TRACE [org.jboss.security.SecurityAssociation] getPrincipal, principal=U174791
2007-02-08 14:59:09,958 TRACE [org.jboss.security.plugins.JaasSecurityManager$DomainInfo] destroy, subject=Subject:
 Principal: Roles(members:xxx,yyy,zzz)
 Principal: U174791
, this=org.jboss.security.plugins.JaasSecurityManager$DomainInfo@b05409[Subject(23167560).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.SimplePrincipal@22316052(U174791),credential.class=java.lang.String@23438274,expirationTime=1170961028413], activeUsers=0
2007-02-08 14:59:09,958 TRACE [org.jboss.security.plugins.JaasSecurityManager$DomainInfo] logout, subject=Subject:
 Principal: Roles(members:xxx,yyy,zzz)
 Principal: U174791
, this=org.jboss.security.plugins.JaasSecurityManager$DomainInfo@b05409[Subject(23167560).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.SimplePrincipal@22316052(U174791),credential.class=java.lang.String@23438274,expirationTime=1170961028413]
2007-02-08 14:59:09,968 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] Begin isValid, principal:U174791, cache info: null
2007-02-08 14:59:09,968 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] defaultLogin, principal=U174791
2007-02-08 14:59:09,968 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] Begin getAppConfigurationEntry(acol-core-policy), size=10
2007-02-08 14:59:09,968 TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] End getAppConfigurationEntry(acol-core-policy), authInfo=AppConfigurationEntry[]:
[0]
LoginModule Class: ca.acol.core.security.login.JBossLoginModule
ControlFlag: LoginModuleControlFlag: sufficient
Options:name=auth_ds, value=auth

2007-02-08 14:59:10,048 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] defaultLogin, lc=javax.security.auth.login.LoginContext@1be9101, subject=Subject(2223107).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.SimplePrincipal@22316052(U174791)
2007-02-08 14:59:10,048 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] updateCache, inputSubject=Subject(2223107).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.SimplePrincipal@22316052(U174791)
2007-02-08 14:59:10,048 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] Inserted cache info: org.jboss.security.plugins.JaasSecurityManager$DomainInfo@31ac05[Subject(17676813).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.SimplePrincipal@22316052(U174791),credential.class=java.lang.String@23438274,expirationTime=1170961148415]
2007-02-08 14:59:10,048 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] End isValid, true
2007-02-08 14:59:10,048 TRACE [org.jboss.security.SecurityAssociation] pushSubjectContext, subject=Subject:
 Principal: Roles(members:xxx,yyy,zzz)
 Principal: U174791
, sc=org.jboss.security.SecurityAssociation$SubjectContext@11492ed{principal=U174791,subject=28983194}
2007-02-08 14:59:10,048 TRACE [org.jboss.security.SecurityAssociation] pushRunAsIdentity, runAs=null

Just to clarify wars/jars/ears involved:

.ear
- .war - struts-based web application
- .jar - contains application-specific EJBs

payment.ear
- payment.jar - real-time payment interface

.war invokes .jar to perform custom workflow, including payment. Thus .jar calls EJBs in .jar.

Various incantations of security-domain have been used all with the same application policy. Log snippets above are from with .war and payment.jar with the security-domain set to acol-core-policy. I have tried adding the same security policy to .jar, but that just increases the number of re-authentication calls.

-- James
-

[brownjamese]

Resolved the issue and answered my own question. In our case it was directly related to the JassSecurityManager configuration which had been changed to 0 for both DefaultCacheTimeout and DefaultCacheResolution. The interesting question that I am left with however, is why do I see the following in the logs if caching is, in essence, disabled:

14:59:10,048 TRACE [org.jboss.security.plugins.JaasSecurityManager.acol-core-policy] Inse
rted cache info: org.jboss.security.plugins.JaasSecurityManager$DomainInfo@31ac05[Subject(
17676813
).principals=org.jboss.security.SimpleGroup@28014118(Roles(members:xxx,yyy,zzz))org.jboss.security.S
implePrincipal@22316052(U174791),credential.class=java.lang.String@23438274,expirationTime=117096114
8415]

A quick peak at JassSecurityManager and the inner DomainInfo leads me to believe that there could be optimizations if DefaultCacheTimeout (aka lifetime) == 0.

-- James