hibernate exception handling masked original exception if roll back fails

From: grouper-users-request grouper-users-request On Behalf Of Julio Polo
Sent: Tuesday, December 09, 2014 3:47 PM
To: grouper-users
Subject: [grouper-users] SAVEPOINT does not exist

We seem to encounter this SAVEPOINT error when we hit Grouper hard. Is this a Hibernate bug where the failure to create the SAVEPOINT should have been caught prior to the rollback attempt to use it?
We are running Grouper 2.1.005
The error occurred during a call to the Grouper web service to add several members at once to a group. A couple of those members were not added due to this error. Here's the full error stack for the first instance of this error (there were four such errors in a two-minute span):

2014-12-08 19:49:22,256: [http-0.0.0.0-(port)-10] INFO EventLog.info(156) - < _app_username - (ip addr) > - [(redacted),'_app_username','person'] add member: group='hawaii.edu:auto:sis:registration:LEE:HWST:107:54672:201530:enrolled' list='members' subject='(redacted)'/'person'/'UH core LDAP' (58ms)
2014-12-08 19:49:22,326: [http-0.0.0.0-(port)-10] INFO EventLog.info(156) - < _app_username - (ip addr) > - [(redacted),'_app_username','person'] add member: group='hawaii.edu:auto:sis:registration:LEE:HWST:107:54672:201530:enrolled' list='members' subject='(redacted'/'person'/'UH core LDAP' (39ms)
2014-12-08 19:49:22,472: [http-0.0.0.0-(port)-15] INFO EventLog.info(156) - < _app_username - (ip addr) > - [(redacted),'_app_username','person'] add member: group='hawaii.edu:menu:sis:registration:201530:enrolled:WOA:SSCI:300' list='members' subject='(redacted)'/'group'/'g:gsa' (293ms)
2014-12-08 19:49:22,723: [http-0.0.0.0-(port)-15] INFO EventLog.info(156) - < _app_username - (ip addr) > - [(redacted),'_app_username','person'] add member: group='hawaii.edu:menu:sis:registration:201530:enrolled:WOA:SSCI:300' list='members' subject='(redacted)'/'group'/'g:gsa' (214ms)
2014-12-08 19:49:22,821: [http-0.0.0.0-(port)-10] ERROR WsAddMemberResult.assignResultCodeException(251) - < _app_username - (ip addr) > - WsSubjectLookup[
subject=Subject id: (redacted), sourceId: UH core LDAP, name: (redacted),
subjectFindResult=SUCCESS,subjectId=(redacted)], java.lang.RuntimeException: Problem rolling back savepoint
java.lang.RuntimeException: Problem rolling back savepoint
at edu.internet2.middleware.grouper.hibernate.HibernateSession._internal_hibernateSessionCatch(HibernateSession.java:464)
at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:581)
at edu.internet2.middleware.grouper.ws.GrouperServiceLogic$1.callback(GrouperServiceLogic.java:298)
at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO$1.callback(Hib3TransactionDAO.java:66)
at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:571)
at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO.transactionCallback(Hib3TransactionDAO.java:56)
at edu.internet2.middleware.grouper.hibernate.GrouperTransaction.callbackGrouperTransaction(GrouperTransaction.java:87)
at edu.internet2.middleware.grouper.ws.GrouperServiceLogic.addMember(GrouperServiceLogic.java:234)
at edu.internet2.middleware.grouper.ws.coresoap.GrouperService.addMember(GrouperService.java:1262)
at edu.internet2.middleware.grouper.ws.rest.GrouperServiceRest.addMember(GrouperServiceRest.java:315)
at edu.internet2.middleware.grouper.ws.rest.method.GrouperWsRestPutGroup$1.service(GrouperWsRestPutGroup.java:63)
at edu.internet2.middleware.grouper.ws.rest.method.GrouperWsRestPut$1.service(GrouperWsRestPut.java:110)
at edu.internet2.middleware.grouper.ws.rest.method.GrouperRestHttpMethod$3.service(GrouperRestHttpMethod.java:104)
at edu.internet2.middleware.grouper.ws.rest.GrouperRestServlet.service(GrouperRestServlet.java:199)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:723)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at edu.internet2.middleware.grouper.ws.GrouperServiceJ2ee.doFilter(GrouperServiceJ2ee.java:659)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:615)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:662)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: SAVEPOINT 3d56b48f_14a2c6437d5_69c1 does not exist
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
at com.mysql.jdbc.Util.getInstance(Util.java:381)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1031)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3376)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3308)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2537)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1564)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1485)
at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4615)
at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:829)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.hibernate.jdbc.BorrowedConnectionProxy.invoke(BorrowedConnectionProxy.java:74)
at com.sun.proxy.$Proxy8.rollback(Unknown Source)
at edu.internet2.middleware.grouper.hibernate.HibernateSession._internal_hibernateSessionCatch(HibernateSession.java:462)
... 30 more

Is this a bug or shall we just throw more memory at the problem?
Julio Polo
University of Hawaii