Red Hat Bugzilla – Bug 1191580
INFO IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: Trying to return an unknown connection2!
Last modified: 2015-05-14 11:25:16 EDT
Description of problem: There are several occurrences in log during tests of INFO [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http-dhcp180-94.mw.lab.eng.bos.redhat.com/10.16.180.94:8080-3) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: Trying to return an unknown connection2! org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@70046c94 and stacktrace follows (see link to log) It usually happens in later phase of tests when user is logging in. It happens with both h2 and other databases. Portal behaves as expected so no other issues, just the INFO. Additional info: There is link to log: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EPP/view/EPP/view/6.2/view/UI%20Database%20Support/job/epp6_ui_selenium_tests_db_db2-105/5/consoleFull
Attaching a piece of the log from Jenkins: Starting firefox: FirefoxBinary(/qa/hudson_workspace/workspace/epp6_ui_selenium_tests_db_db2-105/browsers/linux-x86_64/firefox-28.0/firefox-bin); nativeEvents: false; version: 28.0 window size: (1440, 782) new window size: (1000, 1000) [15:27:09] STARTED: navigation.Test_POR_24_03_002_CheckNavigationListByUserWhoDoesNotHaveRightToEditAnyGroupNavigation.testPOR_24_03_002_CheckNavigationListByUserWhoDoesNotHaveRightToEditAnyGroupNavigation() Check Navigation List By User Who Does Not Have Right To Edit Any Group Navigation --Opening location http://dhcp180-94.mw.lab.eng.bos.redhat.com:8080/portal -- --Signing in as root-- --Go to New Staff-- --Create new user using "New Staff" portlet-- --Closing message dialog-- --Go to Users and groups management-- -- Choose Group Management tab-- --Select category (Organization/Management)-- --Adding users to group-- --Signing in as test_por_24_03_002-- --Signing in as root-- --Go to Users and groups management-- --Deleting user test_por_24_03_002-- confirmation: Are you sure you want to delete test_por_24_03_002 user? [15:28:27] SUCCESS: navigation.Test_POR_24_03_002_CheckNavigationListByUserWhoDoesNotHaveRightToEditAnyGroupNavigation.testPOR_24_03_002_CheckNavigationListByUserWhoDoesNotHaveRightToEditAnyGroupNavigation() Starting firefox: FirefoxBinary(/qa/hudson_workspace/workspace/epp6_ui_selenium_tests_db_db2-105/browsers/linux-x86_64/firefox-28.0/firefox-bin); nativeEvents: false; version: 28.0 window size: (1440, 782) new window size: (1000, 1000) [15:28:30] STARTED: navigation.Test_POR_24_03_003_CheckDoNotShowGroupEditorMenu.testPOR_24_03_003_CheckDoNotShowGroupEditorMenu() Check Do Not Show Group Editor Menu --Opening location http://dhcp180-94.mw.lab.eng.bos.redhat.com:8080/portal -- --Signing in as root-- [0m15:28:33,083 INFO [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http-dhcp180-94.mw.lab.eng.bos.redhat.com/10.16.180.94:8080-2) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: Trying to return an unknown connection2! org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@635be449 at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.unregisterConnection(CachedConnectionManagerImpl.java:347) at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed(TxConnectionListener.java:460) at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:584) at org.jboss.jca.adapters.jdbc.WrappedConnection.close(WrappedConnection.java:265) at org.hibernate.service.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection(DatasourceConnectionProviderImpl.java:148) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.releaseConnection(AbstractSessionImpl.java:312) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:241) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.close(LogicalConnectionImpl.java:168) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:186) at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.close(TransactionCoordinatorImpl.java:292) at org.hibernate.internal.SessionImpl.close(SessionImpl.java:354) at org.hibernate.internal.SessionImpl.managedClose(SessionImpl.java:422) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.afterAfterCompletion(JdbcTransaction.java:147) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:189) at org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreSessionImpl.commitHibernateTransaction(HibernateIdentityStoreSessionImpl.java:205) [picketlink-idm-hibernate-1.4.5.Final-redhat-2.jar:1.4.5.Final-redhat-2] at org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreSessionImpl.commitTransaction(HibernateIdentityStoreSessionImpl.java:136) [picketlink-idm-hibernate-1.4.5.Final-redhat-2.jar:1.4.5.Final-redhat-2] at org.picketlink.idm.impl.repository.RepositoryIdentityStoreSessionImpl.commitTransaction(RepositoryIdentityStoreSessionImpl.java:125) [picketlink-idm-core-1.4.5.Final-redhat-2.jar:1.4.5.Final-redhat-2] at org.picketlink.idm.impl.api.session.SimpleTransactionImpl.commit(SimpleTransactionImpl.java:49) [picketlink-idm-core-1.4.5.Final-redhat-2.jar:1.4.5.Final-redhat-2] at org.exoplatform.services.organization.idm.PicketLinkIDMOrganizationServiceImpl.endRequest(PicketLinkIDMOrganizationServiceImpl.java:197) [exo.portal.component.identity-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.container.component.RequestLifeCycle.doEnd(RequestLifeCycle.java:71) [exo.kernel.container-2.4.11-GA-redhat-1.jar:2.4.11-GA-redhat-1] at org.exoplatform.container.component.RequestLifeCycleStack.end(RequestLifeCycleStack.java:102) [exo.kernel.container-2.4.11-GA-redhat-1.jar:2.4.11-GA-redhat-1] at org.exoplatform.container.component.RequestLifeCycle.end(RequestLifeCycle.java:163) [exo.kernel.container-2.4.11-GA-redhat-1.jar:2.4.11-GA-redhat-1] at org.exoplatform.web.WebAppController.service(WebAppController.java:354) [exo.portal.component.web.controller-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.portal.application.PortalController.onService(PortalController.java:110) [exo.portal.webui.portal-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.container.web.AbstractHttpServlet.service(AbstractHttpServlet.java:132) [exo.kernel.container-2.4.11-GA-redhat-1.jar:2.4.11-GA-redhat-1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final-redhat-1.jar:1.0.2.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.web.filter.ExtensibleFilter$ExtensibleFilterChain.doFilter(ExtensibleFilter.java:96) [exo.portal.component.web.api-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.gatein.portal.installer.PortalSetupFilter.doFilter(PortalSetupFilter.java:72) [exo.portal.component.web.api-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.web.filter.ExtensibleFilter$ExtensibleFilterChain.doFilter(ExtensibleFilter.java:92) [exo.portal.component.web.api-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.web.filter.ExtensibleFilter.doFilter(ExtensibleFilter.java:71) [exo.portal.component.web.api-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.web.filter.GenericFilter.doFilter(GenericFilter.java:70) [exo.portal.component.web.api-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.web.CacheUserProfileFilter.doFilter(CacheUserProfileFilter.java:67) [exo.portal.component.web.security-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.frameworks.jcr.web.ThreadLocalSessionProviderInitializedFilter.doFilter(ThreadLocalSessionProviderInitializedFilter.java:122) [exo.jcr.framework.web-1.15.11-GA-redhat-1.jar:1.15.11-GA-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.web.login.ConversationStateUpdateFilter.doFilter(ConversationStateUpdateFilter.java:66) [exo.portal.component.web.security-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.gatein.web.security.impersonation.ImpersonationFilter.doFilter(ImpersonationFilter.java:84) [exo.portal.component.web.security-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.services.security.web.SetCurrentIdentityFilter.doFilter(SetCurrentIdentityFilter.java:88) [exo.core.component.security.core-2.5.11-GA-redhat-1.jar:2.5.11-GA-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.web.login.RememberMeFilter.doFilter(RememberMeFilter.java:121) [exo.portal.component.web.security-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.exoplatform.web.login.RememberMeFilter.doFilter(RememberMeFilter.java:54) [exo.portal.component.web.security-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.gatein.security.oauth.webapi.OAuthDelegateFilter.doFilter(OAuthDelegateFilter.java:58) [exo.portal.component.web.oauth-web-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.gatein.sso.integration.SSODelegateFilter.doFilter(SSODelegateFilter.java:60) [sso-integration-1.4.3.Final-redhat-1.jar:1.4.3.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.exoplatform.container.web.PortalContainerFilter.doFilter(PortalContainerFilter.java:78) [exo.kernel.container-2.4.11-GA-redhat-1.jar:2.4.11-GA-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.gatein.portal.init.PortalCheckInitFilter.doFilter(PortalCheckInitFilter.java:66) [exo.portal.component.portal-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:231) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:420) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.gatein.sso.integration.SSODelegateValve.invoke(SSODelegateValve.java:159) [sso-integration-1.4.3.Final-redhat-1.jar:1.4.3.Final-redhat-1] at org.gatein.portal.security.jboss.PortalClusteredSSOSupportValve.invoke(PortalClusteredSSOSupportValve.java:94) [exo.portal.component.web.security-jboss-3.8.13.Final-redhat-2.jar:3.8.13.Final-redhat-2] at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.5.0.Final-redhat-17.jar:7.5.0.Final-redhat-17] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.4.Final-redhat-1.jar:7.5.4.Final-redhat-1] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_67]
Vlasto, is this happening on every login?
Peter, no it is not happening every login. It is happening more likely in later phase of tests, so many logins works fine (without the INFO) and then it happens more frequently after some time when portal in used. So unfortunately I don't have any deterministic steps to reproduce this, but AFAIK it happens in every test.
I can confirm that the IJ000311 message disappears from the log when the portal is using picketlink-idm without this commit (thanks Thomas!) https://github.com/picketlink/picketlink-idm/commit/72a9ef4e82ff1ed3911f6adb686805b1659ca560 Filed upstream bug https://issues.jboss.org/browse/PLIDM-50
In the mean time I could gather a little bit more info about this issue. Observation 1: The number of IJ000311 occurences in the console output of the job depends quite heavily on the Jenkins node running the task: While dev204-virt1 RHEL7 [1] produces ~30 occurrences of IJ000311 in the log, another node dev127-virt1 [2] RHEL6 produces zero to 1 occurrence for the same job. Tomáš was not able to tell me if RHEL6 vs. 7 is the only relevant difference between the two. Hence all following info is bound to node dev204-virt1 Observation 2: There is no single occurence of IJ000311 if lazyStartOfHibernateTransaction is set to false in gatein/gatein.ear/portal.war/WEB-INF/conf/organization/picketlink-idm/picketlink-idm-config.xml of the portal tree.
Correction of Observation 1 from Comment#6 above: Even on dev204-virt1, the issue cannot be reproduced always. I saw identical builds on dev204-virt1 one of which had zero IJ000311 occurences whereas another one had ~30 occurences of IJ000311.
Created attachment 1008329 [details] run-7-consoleText-shortened.txt Attached the console output of https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/epp6_ui_selenium_tests_db_mysql55-ppalaga-dev204-virt1/7/ with detailed logging for org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreImpl org.exoplatform.services.organization.idm.PicketLinkIDMOrganizationServiceImpl and org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager Note that PicketLinkIDMOrganizationServiceImpl contains my additional logging https://github.com/ppalaga/picketlink-idm/commit/bb506feb167603f712b22615ed2321a483fea30b
Created attachment 1008341 [details] standalone.xml used in run-7
Jesper Pedersen from Ironjacamar recommended to set log level to TRACE for com.arjuna and org.jboss.jca which I did in run#10 https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/epp6_ui_selenium_tests_db_mysql55-ppalaga-dev204-virt1/10/ The uncomressed log file has 7.6GB, compressed 186MB https://www.dropbox.com/s/i7fhc6l4i9616ml/run-10-console-jca-arjuna-trace.txt.bz2?dl=0
Created attachment 1008975 [details] standalone.xml used in run#10 Attaching standalone.xml used in run#10
The root cause for the occurrence of the IJ000311 message in the log is the same as in https://bugzilla.redhat.com/show_bug.cgi?id=1208033#c8 - i.e. that we are returning the connection in a context different from the context where we have registered it. Same as in Bug#1208033 this situation is harmless as far as we do not use JTA transactions. Indeed, for JTA, we recommend lazyStartOfHibernateTransaction=false : https://docs.jboss.org/author/display/GTNPORTAL38/JTA+integration One may ask why this issue does not occur for every portal request? This can be explained by the fact that internally, CachedConnectionManagerImpl.unregisterConnection() behaves differently in case (a) there were no connections at all registered in the present context and (b) there were one or more connections registered in the present context but they were returned already. (a) conns == null happens typically (in the course of epp6_ui_selenium_tests* jobs) and outputs no message at all https://github.com/ironjacamar/ironjacamar/blob/ironjacamar-1.0.31.Final/core/src/main/java/org/jboss/jca/core/connectionmanager/ccm/CachedConnectionManagerImpl.java#L324-L325 Whereas (b) happens sometimes and the IJ000311 message is being logged. If (a) and (b) were handled equally, like this https://github.com/ppalaga/ironjacamar/commit/f3a246bbd1cf098ef61855f0fc1b97e8adfc4285#diff-fed416dbad8c9a830576e7488d4cc547R333 There would be no message in the log. JCA team rejected this change as there may be a userTx in game (that we do not have) and (a) and (b) make a real difference in that case.
I corrected few typos in Peter's doc text. Please update the corresponding text in the Release Notes.