7 Replies Latest reply on May 3, 2006 8:23 PM by sean171

JaasSecurityManager try to insert duplicate entry into Timed

wwwluo Mar 29, 2006 3:09 PM

Hi there,

I have a customer site threw the following exception, but it is not reproducable in my development environment. The DefaultCacheTimeout is already set to 0 to disable the security caching, but JBoss seemed trying to cache it anyway according to the stack trace. Could any one look at the stack trace, login-config.xml to tell me what goes wrong, and how to reproduce it and fix?

Our environment:
JBoss 4.0.3, Windows XP SP2, JTDS 1.2

Thanks a lot.

-wei

login-config.xml

 <!-- Login for the PHS Datasource -->
 <application-policy name = "EncryptPhsPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[PHSUserName]</module-option>
 <module-option name = "password">[PHSEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=phsTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>

Stack trace:
java.lang.IllegalStateException: Attempt to insert duplicate entry
 at org.jboss.util.TimedCachePolicy.insert(TimedCachePolicy.java:198)
 at org.jboss.security.plugins.JaasSecurityManager.updateCache(JaasSecurityManager.java:758)
 at org.jboss.security.plugins.JaasSecurityManager.authenticate(JaasSecurityManager.java:524)
 at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:315)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2.getSubject(BaseConnectionManager2.java:663)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:461)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
 at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
 at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:311)
 at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:114)
 at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:105)
 at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1561)
 at org.hibernate.loader.Loader.doQuery(Loader.java:661)
 at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
 at org.hibernate.loader.Loader.loadEntity(Loader.java:1782)
 at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:47)
 at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:41)
 at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:2712)
 at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:365)
 at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:346)
 at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:123)
 at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:177)
 at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:87)
 at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:781)
 at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:753)
 at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:266)
 at org.hibernate.type.EntityType.resolve(EntityType.java:303)
 at org.hibernate.type.OneToOneType.assemble(OneToOneType.java:141)
 at org.hibernate.type.TypeFactory.assemble(TypeFactory.java:398)
 at org.hibernate.cache.entry.CacheEntry.assemble(CacheEntry.java:96)
 at org.hibernate.cache.entry.CacheEntry.assemble(CacheEntry.java:82)
 at org.hibernate.event.def.DefaultLoadEventListener.assembleCacheEntry(DefaultLoadEventListener.java:520)
 at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:474)
 at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:328)
 at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:123)
 at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:177)
 at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:87)
 at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:781)
 at org.hibernate.impl.SessionImpl.get(SessionImpl.java:721)
 at org.hibernate.impl.SessionImpl.get(SessionImpl.java:714)
 at phs.res.ResHome.findByPrimaryKey(ResHome.java:55)
 at psm.caseheader.PHSCaseHeaderEJB.getCaseHeaderData(PHSCaseHeaderEJB.java:76)
 at sun.reflect.GeneratedMethodAccessor355.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
 at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at sun.reflect.GeneratedMethodAccessor123.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)
 at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155)
 at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104)
 at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179)
 at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165)
 at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46)
 at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55)
 at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97)
 at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86)
 at $Proxy332.getCaseHeaderData(Unknown Source)
 at psm.caseheader.CaseHeaderEJB.loadPHSData(CaseHeaderEJB.java:256)
 at psm.caseheader.CaseHeaderEJB.getCaseHeader(CaseHeaderEJB.java:144)
 at sun.reflect.GeneratedMethodAccessor354.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
 at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at sun.reflect.GeneratedMethodAccessor123.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)
 at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155)
 at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104)
 at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179)
 at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165)
 at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46)
 at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55)
 at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97)
 at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86)
 at $Proxy330.getCaseHeader(Unknown Source)
 at psm.casesupplies.ContextHelperBean.getNewHeaderInfo(ContextHelperBean.java:239)
 at org.apache.jsp.psm.header.ContextHead_jsp._jspService(org.apache.jsp.psm.header.ContextHead_jsp:327)
 at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
 at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:322)
 at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
 at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at system.servlet.filters.ProfileFilter.doFilter(ProfileFilter.java:54)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
 at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
 at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at psm.system.HsmSecurityValve.invoke(HsmSecurityValve.java:58)
 at org.apache.catalina.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:481)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
 at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
 at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
 at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
 at java.lang.Thread.run(Thread.java:595)

1. Re: JaasSecurityManager try to insert duplicate entry into T

wwwluo Apr 11, 2006 11:03 AM (in response to wwwluo)

One thing I forget to mention in the original post: we use a different policy for our main application HSM, and multiple similar policy for other data sources. We have multiple data sources in our application, all using the same encrypted username/password.

1. Could this has anything to do with this patch: http://www.jboss.org/?module=bb&op=viewtopic&p=3935282

2. Could it be that JBoss defaults to org.jboss.security.SimplePrinciple (use only username as identity), and TimedCachePolicy is created without the threadSafe flag set to true, and consequently has synchronization issue?

-wei

login-config.xml

 <application-policy name="hsm">
 <authentication>
 <login-module code="security.providers.authentication.jboss.JBossASLoginModuleImpl" flag="required">
 <module-option name = "applicationName">PHS</module-option>
 <module-option name = "authenticationServiceUrl">http://servername:port/security/servlet</module-option>
 <module-option name = "loginApplicationName">HSM</module-option>
 </login-module>
 </authentication>
 </application-policy>

 <!-- Login for the HBIC Datasource -->
 <application-policy name = "EncryptHbicPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[HBICUserName]</module-option>
 <module-option name = "password">[HBICEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=hbiCentralTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the HBI Datasource -->
 <application-policy name = "EncryptHbiPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[HBIUserName]</module-option>
 <module-option name = "password">[HBIEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=hbiTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the PHS Datasource -->
 <application-policy name = "EncryptPhsPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[PHSUserName]</module-option>
 <module-option name = "password">[PHSEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=phsTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the PMM Datasource -->
 <application-policy name = "EncryptPmmPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[PMMUserName]</module-option>
 <module-option name = "password">[PMMEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=pmmTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the PSM Datasource -->
 <application-policy name = "EncryptPsmPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[PSMUserName]</module-option>
 <module-option name = "password">[PSMEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=hsmTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the PT Datasource -->
 <application-policy name = "EncryptPtPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[PTUserName]</module-option>
 <module-option name = "password">[PTEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=ptTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>
 <!-- Login for the Report Datasource -->
 <application-policy name = "EncryptReportPassword">
 <authentication>
 <login-module code = "org.jboss.resource.security.SecureIdentityLoginModule"
 flag = "required">
 <module-option name = "username">[ReportUserName]</module-option>
 <module-option name = "password">[ReportEncryptedPassword]</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=LocalTxCM,name=reportTxDataSource</module-option>
 </login-module>
 </authentication>
 </application-policy>

2. Re: JaasSecurityManager try to insert duplicate entry into T

starksm64 Apr 11, 2006 11:26 PM (in response to wwwluo)

1. No.
2. The TimedCache is created with thread-safe set to true, and the update is done within a synchronized block holding the cache monitor. If the principal is seen to already be in the cache the existing value is removed so its not clear how a race condition can exist.

Are you using a custom cache or accessing the cache directly through jndi such that there is access outside of the JaasSecurityManager?
Actions
3. Re: JaasSecurityManager try to insert duplicate entry into T

wwwluo Apr 12, 2006 4:13 PM (in response to wwwluo)

Scott,

Thanks for your help.

We are not using a custom cache or accessing the cache via JNDI. It's worth noting that the hsm policy, which is used by the application to authenticate Browser users, uses a custom principal and sets its principal via SecurityAssociationValve.userPrincipal.set(myIdentity). We did a walk-through of this code with a JBoss consultant a few months ago. This should not matter at all because our analysis shows that the stack trace is only generated by one of datasources. Always the second one accessed within a transaction.

We have also done a bunch of automated testing and it seems that the error does not occur if the databases are on the same server.

I did look into the source code of TimedCachePolicy and JaasSecurityManager before my last post. What really puzzled me was the synchronized block of domainCache for inserting entry should guarantee it should never try to insert duplicate entries, unless the peek() and remove() check code before insertion was somehow bypassed, which seemed only possible if there is a JDK bug for HashMap implementation of containKey() and get(). But I checked its source code, they are using the same algorithms under hood. So this will lead to a question of how does TimedCachePolicy get instantiated? I noticed it has other contructors with threadSafe flag defaults to false, but searching the whole JBoss source code base yields no direct calling of its constructors.

-Wei
Actions

4. Re: JaasSecurityManager try to insert duplicate entry into T

starksm64 Apr 12, 2006 7:43 PM (in response to wwwluo)

security\src\main\org\jboss\security\plugins\JaasSecurityManagerService.java has the creation:

 /** This is the InvocationHandler callback for the Context interface that
 was created by out getObjectInstance() method. All this does is create
 a new TimedCache instance.
 */
 public Object invoke(Object obj, Method method, Object[] args) throws Throwable
 {
 TimedCachePolicy cachePolicy = new TimedCachePolicy(defaultCacheTimeout,
 true, defaultCacheResolution);
 cachePolicy.create();
 cachePolicy.start();
 return cachePolicy;
 }

5. Re: JaasSecurityManager try to insert duplicate entry into T

wwwluo Apr 20, 2006 10:44 AM (in response to wwwluo)

Scott,

Given that TimedCachePolicy is created thread-safe, the code try to insert into it are wrapped in synchronized block and it is always try to remove existing entry with same principal before insertion, but we still got IllegalStateException for "Attempt to insert duplicate entry", there must be other thing sneaked behind and changed the cache with principal of same name. Could you help identify what it could be?

So far, it happened only under scenario of different data sources reside on physically different servers, using the same set of encrypted username/password. But the severity of this problem is escalated, since we suspect it might actually cause JDBC connection leak.

Thanks for your help.

-Wei
Actions
6. Re: JaasSecurityManager try to insert duplicate entry into T

starksm64 Apr 21, 2006 11:10 AM (in response to wwwluo)

I did find a race condition that needs to be synchronized in the JaasSecurityManagerService which could result in this error. Really nothing to do with where the data sources reside other than how this affects the timing issues that cause the race condition.

http://jira.jboss.com/jira/browse/JBAS-3141
Actions
7. Re: JaasSecurityManager try to insert duplicate entry into T

sean171 May 3, 2006 8:23 PM (in response to wwwluo)

It's not clear how the fix can actually solve the problem even if two JaasSecurityManager can be created for the same SecurityDomain, each with its own TimedCahePolicy object

In order for this exception to occur, there must be some code calling TimedCachePolicy.insert() inbetween outside a synchronized block. Yet JaasSecurityManager.updateCache() seems to be the only caller of that method by searching the codebase, which makes that condition unlikely to occur.

Scott, could you comment a bit more on that racing condition identified?

Thanks,
Sean
Actions

Go to original post