Bug 793961 (JBEPP-1032)

Summary: CustomMembershipLoginModule should end lifecycle in case of an error
Product: [JBoss] JBoss Enterprise Portal Platform 5 Reporter: Martin Weiler <mweiler>
Component: PortalAssignee: Boleslaw Dawidowicz <bdawidow>
Status: CLOSED NEXTRELEASE QA Contact:
Severity: high Docs Contact:
Priority: high    
Version: unspecifiedCC: epp-bugs, krokodylowy3
Target Milestone: ---   
Target Release: 5.2.0.DEV03   
Hardware: Unspecified   
OS: Unspecified   
URL: http://jira.jboss.org/jira/browse/JBEPP-1032
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
EPP 5.1.0 + LDAP + CustomMembershipLoginModule
Last Closed: 2011-08-16 11:45:27 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
JBEPP-1032.patch none

Description Martin Weiler 2011-07-28 08:35:37 UTC 
Help Desk Ticket Reference: https://na7.salesforce.com/500A0000007qCf9
Steps to Reproduce: In gatein-jboss-beans.xml, enable CustomMembershipLoginModule with a non-existing membershipType value: 
<module-option name="membershipType">xxx</module-option>
project_key: JBEPP

A misconfiguration of the CustomMembershipLoginModule (eg. an incorrect/missing membershipType value), the addUserToPlatformUsers method fails with the following error:

javax.naming.InvalidNameException: Can not create membership record for jduke1 because membership type is null
	at org.exoplatform.services.organization.idm.MembershipDAOImpl.linkMembership(MembershipDAOImpl.java:131)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.addUserToPlatformUsers(CustomMembershipLoginModule.java:156)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.login(CustomMembershipLoginModule.java:102)

As a consequence, the RequestLifeCycle.end() method won't be called, which results in an unclosed db connection:

INFO  [CachedConnectionManager] Closing a connection for you.  Please close them yourself: org.jboss.resource.adapter.jdbc.jdk6.WrappedConnectionJDK6@7e138f1b
java.lang.Throwable: STACKTRACE
...
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.begin(CustomMembershipLoginModule.java:170)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.addUserToPlatformUsers(CustomMembershipLoginModule.java:152)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.login(CustomMembershipLoginModule.java:102)

The end(orgService) call should be made in a finally() block.
Comment 1 Martin Weiler 2011-07-28 08:37:02 UTC 
Attaching a patch proposal.
Comment 2 Martin Weiler 2011-07-28 08:37:02 UTC 
Attachment: Added: JBEPP-1032.patch
Comment 3 Krashan Brahmanjara 2011-08-16 09:36:38 UTC 
Another one transaction error. 
Transactions are not rolled back so Identity operation errors occurs.

2011-08-16 09:33:54,543 WARN  [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) SQL Error: 0, SQLState: 23505
2011-08-16 09:33:54,543 ERROR [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) Batch entry 0 insert into jbid_io_rel (FROM_IDENTITY, NAME, TO_IDENTITY, REL_TYPE, ID) values (22, 130, 559, 2, 566) was aborted.  Call getNextException to see the cause.
2011-08-16 09:33:54,544 WARN  [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) SQL Error: 0, SQLState: 23505
2011-08-16 09:33:54,544 ERROR [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) ERROR: duplicate key value violates unique constraint "jbid_io_rel_from_identity_key"
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
	at $Proxy290.flush(Unknown Source)
	at org.picketlink.idm.impl.repository.FallbackIdentityStoreRepository.createRelationship(FallbackIdentityStoreRepository.java:860)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
	at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
	at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
	at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.defaultLogin(JaasSecurityManagerBase.java:553)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.authenticate(JaasSecurityManagerBase.java:487)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.isValid(JaasSecurityManagerBase.java:365)
	at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:160)
	at org.jboss.web.tomcat.security.JBossWebRealm.authenticate(JBossWebRealm.java:399)
	at org.apache.catalina.authenticator.FormAuthenticator.authenticate(FormAuthenticator.java:258)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:417)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
	at java.lang.Thread.run(Thread.java:662)
Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into jbid_io_rel (FROM_IDENTITY, NAME, TO_IDENTITY, REL_TYPE, ID) values (22, 130, 559, 2, 566) was aborted.  Call getNextException to see the cause.
	at org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2548)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1344)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:343)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2687)
	at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:476)
	at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
	at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
	at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:269)
	... 46 more
2011-08-16 09:33:54,556 ERROR [org.exoplatform.services.organization.idm.CustomMembershipLoginModule] (http-10.80.0.6-8080-4) Failed to add user xxxxx to group /platform/users.
org.picketlink.idm.common.exception.IdentityException: Cannot create relationship: 
	at org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreImpl.createRelationship(HibernateIdentityStoreImpl.java:1028)
	at org.picketlink.idm.impl.repository.FallbackIdentityStoreRepository.createRelationship(FallbackIdentityStoreRepository.java:860)
	at org.picketlink.idm.impl.api.session.managers.RoleManagerImpl.createRole(RoleManagerImpl.java:284)
	at org.picketlink.idm.impl.api.session.managers.RoleManagerImpl.createRole(RoleManagerImpl.java:318)
	at org.exoplatform.services.organization.idm.MembershipDAOImpl.linkMembership(MembershipDAOImpl.java:176)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.addUserToPlatformUsers(CustomMembershipLoginModule.java:156)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.login(CustomMembershipLoginModule.java:102)
	at pl.ingnn.picketlink.organization.impl.B2BCustomMembershipLoginModule.login(B2BCustomMembershipLoginModule.java:76)
	at sun.reflect.GeneratedMethodAccessor1204.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
	at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
	at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
	at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.defaultLogin(JaasSecurityManagerBase.java:553)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.authenticate(JaasSecurityManagerBase.java:487)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.isValid(JaasSecurityManagerBase.java:365)
	at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:160)
	at org.jboss.web.tomcat.security.JBossWebRealm.authenticate(JBossWebRealm.java:399)
	at org.apache.catalina.authenticator.FormAuthenticator.authenticate(FormAuthenticator.java:258)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:417)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
	at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
	at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:276)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
	at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1029)
	at sun.reflect.GeneratedMethodAccessor1478.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:342)
	at $Proxy290.flush(Unknown Source)
	at org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreImpl.createRelationship(HibernateIdentityStoreImpl.java:1018)
	... 35 more
Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into jbid_io_rel (FROM_IDENTITY, NAME, TO_IDENTITY, REL_TYPE, ID) values (22, 130, 559, 2, 566) was aborted.  Call getNextException to see the cause.
	at org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2548)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1344)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:343)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2687)
	at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:476)
	at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
	at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
	at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:269)
	... 46 more
2011-08-16 09:33:54,674 WARN  [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) SQL Error: 0, SQLState: 25P02
2011-08-16 09:33:54,674 ERROR [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) ERROR: current transaction is aborted, commands ignored until end of transaction block
2011-08-16 09:33:54,682 INFO  [org.exoplatform.services.organization.idm.MembershipDAOImpl] (http-10.80.0.6-8080-4) Identity operation error: 
org.hibernate.exception.GenericJDBCException: could not execute query
	at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:126)
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:114)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
	at org.hibernate.loader.Loader.doList(Loader.java:2236)
	at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2162)
	at org.hibernate.loader.Loader.list(Loader.java:2122)
	at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:117)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1598)
	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
	at org.picketlink.idm.impl.store.hibernate.HibernateIdentityStoreImpl.resolveRelationships(HibernateIdentityStoreImpl.java:1242)
	at org.picketlink.idm.impl.repository.FallbackIdentityStoreRepository.resolveRelationships(FallbackIdentityStoreRepository.java:1041)
	at org.picketlink.idm.impl.api.session.managers.RoleManagerImpl.findRoles(RoleManagerImpl.java:870)
	at org.picketlink.idm.impl.api.session.managers.RoleManagerImpl.findRoles(RoleManagerImpl.java:912)
	at org.exoplatform.services.organization.idm.MembershipDAOImpl.findMembershipsByUser(MembershipDAOImpl.java:675)
	at org.exoplatform.services.organization.auth.OrganizationAuthenticatorImpl.createIdentity(OrganizationAuthenticatorImpl.java:95)
	at org.exoplatform.services.organization.idm.CustomMembershipLoginModule.login(CustomMembershipLoginModule.java:105)
	at pl.ingnn.picketlink.organization.impl.B2BCustomMembershipLoginModule.login(B2BCustomMembershipLoginModule.java:76)
	at sun.reflect.GeneratedMethodAccessor1204.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
	at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
	at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
	at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.defaultLogin(JaasSecurityManagerBase.java:553)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.authenticate(JaasSecurityManagerBase.java:487)
	at org.jboss.security.plugins.auth.JaasSecurityManagerBase.isValid(JaasSecurityManagerBase.java:365)
	at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:160)
	at org.jboss.web.tomcat.security.JBossWebRealm.authenticate(JBossWebRealm.java:399)
	at org.apache.catalina.authenticator.FormAuthenticator.authenticate(FormAuthenticator.java:258)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:417)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
	at java.lang.Thread.run(Thread.java:662)
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1608)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1343)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:194)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:470)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:369)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
	at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:91)
	at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:342)
	at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:209)
	at org.hibernate.loader.Loader.getResultSet(Loader.java:1811)
	at org.hibernate.loader.Loader.doQuery(Loader.java:696)
	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:258)
	at org.hibernate.loader.Loader.doList(Loader.java:2233)
	... 41 more
2011-08-16 09:33:54,740 WARN  [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) SQL Error: 0, SQLState: 25P02
2011-08-16 09:33:54,741 ERROR [org.hibernate.util.JDBCExceptionReporter] (http-10.80.0.6-8080-4) ERROR: current transaction is aborted, commands ignored until end of transaction block
Comment 4 boleslaw.dawidowicz 2011-08-16 10:03:03 UTC 
Link: Added: This issue depends GTNPORTAL-2026
Comment 5 Thomas Heute 2011-09-22 07:04:30 UTC 
Release Notes Docs Status: Added: Not Yet Documented
Comment 7 Jared MORGAN 2011-11-28 03:50:02 UTC 
Release Notes Docs Status: Removed: Not Yet Documented Added: Needs More Info
Release Notes Text: Added: CAUSE:

CONSEQUENCE:

FIX:

RESULT:
Primary SME: Added: bdaw
NEEDINFO Due Date: Added: 30/Nov/11
NEEDINFO: Removed: Nobody Added: Subject Matter Expert
Comment 8 boleslaw.dawidowicz 2011-11-28 10:25:51 UTC 
Release Notes Text: Removed: CAUSE:

CONSEQUENCE:

FIX:

RESULT: Added: CAUSE: Transaction commit related to IDM database operations is not placed in final() block. 

CONSEQUENCE: Any misconfiguration or operation failure can cause database connection tom remain in unclosed state 

FIX: Transaction commit related to IDM database operations placed in final() block. 

RESULT: Properly closed database connections in case of misconfiguration or IDM operation failure
Comment 9 Jared MORGAN 2011-12-01 02:00:42 UTC 
Release Notes Docs Status: Removed: Needs More Info Added: Documented as Resolved Issue
Release Notes Text: Removed: CAUSE: Transaction commit related to IDM database operations is not placed in final() block. 

CONSEQUENCE: Any misconfiguration or operation failure can cause database connection tom remain in unclosed state 

FIX: Transaction commit related to IDM database operations placed in final() block. 

RESULT: Properly closed database connections in case of misconfiguration or IDM operation failure  Added: A bug was discovered where a transaction commit related to IDM database operations was not placed within a final() block. Any misconfiguration, or operation failure, could cause the database connection to remain open. The fix ensures the transaction commit related to IDM database operations is placed within a final() block, which fixes the issue.
NEEDINFO Due Date: Removed: 30/Nov/11 
NEEDINFO: Removed: Subject Matter Expert Added: Nobody