Uploaded image for project: 'Grouper'
  1. Grouper
  2. GRP-1095

hibernate exception handling masked original exception if roll back fails

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Minor
    • 2.1.6, 2.2.1.patch, 2.2.2, 2.3.0
    • 2.1.5, 2.2.1
    • API
    • None

    Description

      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

      Attachments

        Activity

          People

            chris.hyzer@at.internet2.edu Chris Hyzer (upenn.edu)
            chris.hyzer@at.internet2.edu Chris Hyzer (upenn.edu)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: