6 Replies Latest reply on Feb 9, 2007 12:07 PM by James Brown

    Repeated calls to LoginModule for EJB authentication

    Igor Kuzmitshov Newbie


      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

        • 1. Re: Repeated calls to LoginModule for EJB authentication
          Anil Saldanha Master

          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.

          • 2. Re: Repeated calls to LoginModule for EJB authentication
            Igor Kuzmitshov Newbie

            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

            • 3. Re: Repeated calls to LoginModule for EJB authentication
              Anil Saldanha Master

              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).

              • 4. Re: Repeated calls to LoginModule for EJB authentication
                James Brown Newbie


                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>

                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

                • 5. Re: Repeated calls to LoginModule for EJB authentication
                  James Brown Newbie

                  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[]:
                  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:

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

                  - 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

                  • 6. Re: Repeated calls to LoginModule for EJB authentication
                    James Brown Newbie

                    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(

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

                    -- James