users@glassfish.java.net

RE: JACC Intermittent problem

From: Vincent Deschênes <vdeschenes_at_stelvio.com>
Date: Mon, 1 Feb 2010 13:26:17 -0500

Thanks Ronald,

 

I did changed the log level, here is what it give:

 

Is this the "domain that failed" log you were talking about ?

 

[#|2010-02-01T11:56:04.314-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;ClassName
=com.sun.enterprise.security.provider.BasePolicyWrapper$2;MethodName=run;|Domain that failed(ProtectionDomain
(file:/AllianzAssessment/EJB_jar <no signer certificates>)

 

 

---
[#|2010-02-01T11:56:04.272-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.enterprise.security.jmac.callback|_
ThreadID=34;_ThreadName=Thread-1;ClassName=com.sun.enterprise.security.jmac.callback.BaseContainerCallbackHandler;MethodName=process
PasswordValidation;|JMAC: In PasswordValidationCallback Processor|#]
[#|2010-02-01T11:56:04.272-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.enterprise.security.auth.login|_Thr
eadID=34;_ThreadName=Thread-1;ClassName=com.sun.enterprise.security.auth.login.LoginContextDriver;MethodName=jmacLogin;|jmac login
user [username] into realm: StelvioJDBCRealm using JAAS module: StelvioJDBCRealm|#]
[#|2010-02-01T11:56:04.272-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.appserv.security|_ThreadID=34;_Thre
adName=Thread-1;ClassName=com.sun.appserv.security.AppservPasswordLoginModule;MethodName=initialize;|Login module initialized: class
com.stelvio.security.authentication.StelvioLoginModule|#]
[#|2010-02-01T11:56:04.309-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.appserv.security|_ThreadID=34;_Thre
adName=Thread-1;ClassName=com.sun.appserv.security.AppservPasswordLoginModule;MethodName=login;|JAAS login complete.|#]
[#|2010-02-01T11:56:04.310-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.appserv.security|_ThreadID=34;_Thre
adName=Thread-1;ClassName=com.sun.appserv.security.AppservPasswordLoginModule;MethodName=commit;|JAAS authentication committed.|#]
[#|2010-02-01T11:56:04.310-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.enterprise.security.auth.login|_Thr
eadID=34;_ThreadName=Thread-1;ClassName=com.sun.enterprise.security.auth.login.LoginContextDriver;MethodName=jmacLogin;|jmac
Password login succeeded for : username|#]
[#|2010-02-01T11:56:04.310-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.enterprise.security.jmac.callback|_
ThreadID=34;_ThreadName=Thread-1;ClassName=com.sun.enterprise.security.jmac.callback.BaseContainerCallbackHandler;MethodName=process
PasswordValidation;|JMAC: authentication succeeded for user = |#]
[#|2010-02-01T11:56:04.312-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;ClassName
=com.sun.enterprise.security.provider.BasePolicyWrapper;MethodName=doImplies;|JACC Policy Provider, failed Permission Check at :
java.lang.Exception
      at com.sun.enterprise.security.provider.BasePolicyWrapper.doImplies(BasePolicyWrapper.java:404)
      at com.sun.enterprise.security.provider.BasePolicyWrapper.implies(BasePolicyWrapper.java:246)
      at org.glassfish.ejb.security.application.EJBSecurityManager.authorize(EJBSecurityManager.java:712)
      at com.sun.ejb.containers.BaseContainer.authorize(BaseContainer.java:2249)
      at com.sun.ejb.EjbInvocation.authorizeWebService(EjbInvocation.java:639)
      at com.sun.enterprise.security.authorize.EJBPolicyContextDelegate.authorize(EJBPolicyContextDelegate.java:93)
      at com.sun.enterprise.security.jmac.provider.config.PipeHelper.authorize(PipeHelper.java:252)
      at com.sun.enterprise.security.webservices.CommonServerSecurityPipe.processRequest(CommonServerSecurityPipe.java:181)
      at com.sun.enterprise.security.webservices.CommonServerSecurityPipe.process(CommonServerSecurityPipe.java:127)
      at com.sun.xml.ws.api.pipe.helper.PipeAdapter.processRequest(PipeAdapter.java:115)
      at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:629)
      at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:588)
      at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:573)
      at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:470)
      at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:295)
      at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:515)
      at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:285)
      at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:143)
      at org.glassfish.webservices.Ejb3MessageDispatcher.handlePost(Ejb3MessageDispatcher.java:116)
      at org.glassfish.webservices.Ejb3MessageDispatcher.invoke(Ejb3MessageDispatcher.java:87)
      at org.glassfish.webservices.EjbWebServiceServlet.dispatchToEjbEndpoint(EjbWebServiceServlet.java:196)
      at org.glassfish.webservices.EjbWebServiceServlet.service(EjbWebServiceServlet.java:127)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
      at com.sun.grizzly.http.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:195)
...
      at java.lang.Thread.run(Thread.java:619)
|#]
[#|2010-02-01T11:56:04.313-0500|INFO|glassfishv3.0|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;|JACC
Policy Provider: Failed Permission Check, context(AllianzAssessment/EJB_jar)- permission((javax.security.jacc.EJBMethodPermission
FepInterfaceService preAllocateAssessment,ServiceEndpoint,com.stelvio.WebService.fep.PreAllocateAssessmentRequest))|#]
[#|2010-02-01T11:56:04.314-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;ClassName
=com.sun.enterprise.security.provider.BasePolicyWrapper$2;MethodName=run;|Domain that failed(ProtectionDomain
(file:/AllianzAssessment/EJB_jar <no signer certificates>)
 null
 (principals org.glassfish.security.common.PrincipalImpl "aalmtlp2",
org.glassfish.security.common.Group "GCRassessorAllocation",
org.glassfish.security.common.Group "GCRcostcontrol",
org.glassfish.security.common.Group "GCRpublic",
org.glassfish.security.common.PrincipalImpl "username")
 java.security.Permissions_at_1117f0 (
 ...
)
)|#]
[#|2010-02-01T11:56:04.317-0500|FINE|glassfishv3.0|javax.enterprise.system.core.security.com.sun.enterprise.security.webservices|_Th
readID=34;_ThreadName=Thread-1;ClassName=com.sun.enterprise.security.webservices.CommonServerSecurityPipe;MethodName=processResponse
;|ws.status_secure_response|#]
---
 
I personally do not really understand where is the problem from these logs. Could there be an intermittent persmission problem on
the ejb.jar package file on the server?
 
Thanks.
 
VD
 
ps. Yes I think Stelvio is as in passo de Stelvio, company founder has Italian origin.
 
From: Ronald.Monzillo_at_Sun.COM [mailto:Ronald.Monzillo_at_Sun.COM] 
Sent: Thursday, January 28, 2010 6:08 PM
To: users_at_glassfish.dev.java.net
Subject: Re: JACC Intermittent problem
 
On 01/28/10 16:55, Vincent Deschênes wrote: 
We have an application that is serving web service from ejb.
 
When testing our web service we have intermittent authorization error with log like this:
 
INFO|glassfishv3.0|javax.enterprise.system.core.security|_ThreadID=35;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission
Check, context(applicationName/EJB_jar)- permission((javax.security.jacc.EJBMethodPermission FepInterfaceService
preAllocateAssessment,ServiceEndpoint,com.stelvio.WebService.fep.PreAllocateAssessmentRequest))|#]
 
The exact same request can pass many times and suddenly give this error once or twice and then it will continue to work.
 
We have tried both JACC provider (default and simple) with the same result.
 
Anyone has an idea ?
Vincent,
Since both providers are effected, my hunch is that there may be a problem in the authentication state, perhaps a 
problem with the protection domain cache, the realm, or the role mapping system.
In any event, if you set the security logging level to FINE, and configure the default policy provider, 
then the provider will also log the failing protection domain; which will let us see what principals are 
being applied in the access decision.
asadmin list-logger-levels
asadmin set-log-level javax.enterprise.system.core.security=FINE 
unfortunately, a lot more stuff will appear in the log. hopefully you will still be able to reproduce the problem.
the interesting log message will come from line 411 of BasePolicyWrapper.java
if (logger.isLoggable(Level.FINE)) {
           logger.fine("Domain that failed(" + domain2 + ")");
}
if setting the security logger to FINE, is too intrusive, and you think you can change the isLoggable call to check for Level.INFO,
rebuild the provider, and replace the corresponding module, you might want to give that a try.
In any event, please let me know if you are able to make any progress with either of the above approaches.
If you get the failure, and can show me the protection domain, and the associated granted.policy file, I may be
able to see what is going wrong.
Ron
ps; Stevio as in passo de Stelvio? 
 
Thanks.
 
 
VD