10 Replies Latest reply on Jun 25, 2008 12:13 PM by hezimmer

    CMT problem rollback fails

    hezimmer Newbie

      Hi,

      we are using JBoss 4.2.1 and BMP with Hibernate and an Oracle 9.2.0.8. database.
      In our Session-Bean which is in CMT - Mode we have an method like this one:

      public BOPlanKalk savePlanKalk(BOPlanKalk boPlanKalk) throws Exception {
       Plankalk planKalk = boPlanKalk.getPlankalk();
       List<BOPlanAnzKalkPos> listBOplanAnzKalkPos = boPlanKalk.getlistBOPlanAnzKalkPos();
      
       Session hnSession = HibernateUtil.getSession();
       hnSession.saveOrUpdate(planKalk);
      
       Integer planKalkId = planKalk.getPrimaryKey();
      
       for(PlanKalk kalk:listBOplanAnzKalkPos){
       kalk.setPlanKalkid(planKalk.getPlankalkid);
       hnSession.save(kalk);
       }
      
       return boPlanKalk;
       }
      


      Via HibernateUtil.getSession() we get an Session from the Hibernate Sessionfactory which bounds the session to the current JTA-Transaction.

      After leaving the method, Hibernate begins to flush() and starts working against the database. Here the logs:

      17:34:47,484 DEBUG [SQL] insert into PLANKALK (usersid, planversionid, edatum, plankalkid) values (?, ?, ?, ?)
      17:34:47,484 INFO [STDOUT] Hibernate: insert into PLANKALK (usersid, planversionid, edatum, plankalkid) values (?, ?, ?, ?)
      17:34:47,484 DEBUG [AbstractBatcher] Executing batch size: 1
      17:34:47,484 DEBUG [Expectations] success of batch update unknown: 0
      17:34:47,484 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      17:34:47,484 DEBUG [ConnectionManager] skipping aggressive-release due to flush cycle


      The first insert-Statement (above) was successfully processed. Due to an data error the second insert statement will fail (as expected). See below:

      17:34:47,484 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      17:34:47,484 DEBUG [SQL] insert into PLANPROKALKPOS (agenturnetto, frequenz, zeitungid, fixzuschlag, erscheinungstermin, mmzuschlag, kundemwst, agenturbrutto, kundebruttopreis, kundenetto, wmbezeichnung, abschlussrabatt, kundeauflage, gesamttitelkundebrutto, gesamttitelagenturnetto, anzeigenschluss, auflagesplit, gesamttitelkundemwst, ruecktritt, wmdefinition, kundeid, plankalkid, agenturmwst, druckvorlagen, titelgesamtauflage, kundebrutto, tsdpreis, pzuschlagsart, fixzuschlagsplit, gesamttitelkundenetto, mvg, steuerprozentid, waehrungid, zuschlagsart, pzuschlag, preisart, gesamttitelagenturmwst, gesamttitelagenturbrutto, planprokalkposid) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
      17:34:47,484 INFO [STDOUT] Hibernate: insert into PLANPROKALKPOS (agenturnetto, frequenz, zeitungid, fixzuschlag, erscheinungstermin, mmzuschlag, kundemwst, agenturbrutto, kundebruttopreis, kundenetto, wmbezeichnung, abschlussrabatt, kundeauflage, gesamttitelkundebrutto, gesamttitelagenturnetto, anzeigenschluss, auflagesplit, gesamttitelkundemwst, ruecktritt, wmdefinition, kundeid, plankalkid, agenturmwst, druckvorlagen, titelgesamtauflage, kundebrutto, tsdpreis, pzuschlagsart, fixzuschlagsplit, gesamttitelkundenetto, mvg, steuerprozentid, waehrungid, zuschlagsart, pzuschlag, preisart, gesamttitelagenturmwst, gesamttitelagenturbrutto, planprokalkposid) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
      17:34:47,484 WARN [TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1c9aeff[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@12646bb handles=1 lastUse=1213716882546 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@36cb03 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@14a427a xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1fa8 txSync=null]
      java.lang.IllegalArgumentException: Invalid Input Number
       at oracle.sql.NUMBER.toBytes(NUMBER.java:928)
       at oracle.jdbc.dbaccess.DBConversion.DoubleToNumberBytes(DBConversion.java:3065)
       at oracle.jdbc.driver.OraclePreparedStatement.setDouble(OraclePreparedStatement.java:1632)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.setDouble(WrappedPreparedStatement.java:156)
       at org.hibernate.type.DoubleType.set(DoubleType.java:36)
       at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:136)
       at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:107)
       at org.hibernate.persister.entity.AbstractEntityPersister.dehydrate(AbstractEntityPersister.java:1997)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2243)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2660)
       at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:56)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at de.socoto.server.ejb.mediacare.PlanKalkBean.savePlanKalk(PlanKalkBean.java:107)
       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:585)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
       at de.socoto.server.common.utils.SocotoLogInterceptor.pastInvoke(SocotoLogInterceptor.java:40)
       at sun.reflect.GeneratedMethodAccessor221.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
       at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
       at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:166)
       at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:108)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
       at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:278)
       at org.jboss.aop.Dispatcher.invoke(Dispatcher.java:106)
       at org.jboss.aspects.remoting.AOPRemotingInvocationHandler.invoke(AOPRemotingInvocationHandler.java:82)
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:734)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:560)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:369)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:165)
      17:34:47,484 INFO [DoubleType] could not bind value 'NaN' to parameter: 1; Error; - nested throwable: (java.lang.IllegalArgumentException: Invalid Input Number)
      17:34:47,484 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      17:34:47,484 DEBUG [ConnectionManager] skipping aggressive-release due to flush cycle
      17:34:47,484 DEBUG [JDBCExceptionReporter] could not insert: [de.socoto.common.pojo.Planprokalkpos] [insert into PLANPROKALKPOS (agenturnetto, frequenz, zeitungid, fixzuschlag, erscheinungstermin, mmzuschlag, kundemwst, agenturbrutto, kundebruttopreis, kundenetto, wmbezeichnung, abschlussrabatt, kundeauflage, gesamttitelkundebrutto, gesamttitelagenturnetto, anzeigenschluss, auflagesplit, gesamttitelkundemwst, ruecktritt, wmdefinition, kundeid, plankalkid, agenturmwst, druckvorlagen, titelgesamtauflage, kundebrutto, tsdpreis, pzuschlagsart, fixzuschlagsplit, gesamttitelkundenetto, mvg, steuerprozentid, waehrungid, zuschlagsart, pzuschlag, preisart, gesamttitelagenturmwst, gesamttitelagenturbrutto, planprokalkposid) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]
      org.jboss.util.NestedSQLException: Error; - nested throwable: (java.lang.IllegalArgumentException: Invalid Input Number)
       at org.jboss.resource.adapter.jdbc.WrappedConnection.checkException(WrappedConnection.java:557)
       at org.jboss.resource.adapter.jdbc.WrappedStatement.checkException(WrappedStatement.java:563)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.setDouble(WrappedPreparedStatement.java:160)
       at org.hibernate.type.DoubleType.set(DoubleType.java:36)
       at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:136)
       at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:107)
       at org.hibernate.persister.entity.AbstractEntityPersister.dehydrate(AbstractEntityPersister.java:1997)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2243)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2660)
       at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:56)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at de.socoto.server.ejb.mediacare.PlanKalkBean.savePlanKalk(PlanKalkBean.java:107)
       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:585)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
       at de.socoto.server.common.utils.SocotoLogInterceptor.pastInvoke(SocotoLogInterceptor.java:40)
       at sun.reflect.GeneratedMethodAccessor221.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
       at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
       at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:166)
       at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:108)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
       at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:278)
       at org.jboss.aop.Dispatcher.invoke(Dispatcher.java:106)
       at org.jboss.aspects.remoting.AOPRemotingInvocationHandler.invoke(AOPRemotingInvocationHandler.java:82)
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:734)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:560)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:369)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:165)
      Caused by: java.lang.IllegalArgumentException: Invalid Input Number
       at oracle.sql.NUMBER.toBytes(NUMBER.java:928)
       at oracle.jdbc.dbaccess.DBConversion.DoubleToNumberBytes(DBConversion.java:3065)
       at oracle.jdbc.driver.OraclePreparedStatement.setDouble(OraclePreparedStatement.java:1632)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.setDouble(WrappedPreparedStatement.java:156)
       ... 55 more
      17:34:47,500 WARN [JDBCExceptionReporter] SQL Error: 0, SQLState: null
      17:34:47,500 ERROR [JDBCExceptionReporter] Error; - nested throwable: (java.lang.IllegalArgumentException: Invalid Input Number)
      


      So above is the stack from the debug output, very interesting are the following lines:

      17:34:47,500 ERROR [AbstractFlushingEventListener] Could not synchronize database state with session
      org.hibernate.exception.GenericJDBCException: could not insert: [de.socoto.common.pojo.Planprokalkpos]
       at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
       at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
       at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2267)
       at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2660)
       at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:56)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at de.socoto.server.ejb.mediacare.PlanKalkBean.savePlanKalk(PlanKalkBean.java:107)
       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:585)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
       at de.socoto.server.common.utils.SocotoLogInterceptor.pastInvoke(SocotoLogInterceptor.java:40)
       at sun.reflect.GeneratedMethodAccessor221.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
       at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
       at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:166)
       at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:108)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
       at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
       at org.jboss.ej
      
      


      So the problem is that the database operation fails and the connection to database is lost and there's no full rollback of the Hibernate Session. After executing the method above, the first insert-Statement is commited into database. We would expect an rollback and none of the data to be persisted in database. Maybe it could be an problem with the database-driver? (Oracle thin 9.2.0.8) The error message changed after
      an test with another driver Version. Or is it a problem with Hibernate configuration?

      Does anyone have an similar problem or any idea?

      Thanks in advance,
      Heiko

        • 1. Re: CMT problem rollback fails
          hezimmer Newbie

          After some tests with different jdbc-driver versions think that it's not an problem with the underlying jdbc-driver.
          While debugging through the sourcefiles of Jboss and Hibernate i found this in sourcefile (see further below) based on the following stacktrace fragment:

          16:06:55,250 DEBUG [SQL] insert into PLANKALK (usersid, planversionid, edatum, plankalkid) values (?, ?, ?, ?)
          16:06:55,250 INFO [STDOUT] Hibernate: insert into PLANKALK (usersid, planversionid, edatum, plankalkid) values (?, ?, ?, ?)
          16:06:55,250 DEBUG [AbstractBatcher] Executing batch size: 1
          16:06:55,250 DEBUG [Expectations] success of batch update unknown: 0
          16:06:55,250 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
          16:06:55,250 DEBUG [ConnectionManager] skipping aggressive-release due to flush cycle
          16:06:55,250 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
          16:06:55,250 DEBUG [SQL] insert into PLANPROKALKPOS (agenturnetto, frequenz, zeitungid, fixzuschlag, erscheinungstermin, mmzuschlag, kundemwst, agenturbrutto, kundebruttopreis, kundenetto, wmbezeichnung, abschlussrabatt, kundeauflage, gesamttitelkundebrutto, gesamttitelagenturnetto, anzeigenschluss, auflagesplit, gesamttitelkundemwst, ruecktritt, wmdefinition, kundeid, plankalkid, agenturmwst, druckvorlagen, titelgesamtauflage, kundebrutto, tsdpreis, pzuschlagsart, fixzuschlagsplit, gesamttitelkundenetto, mvg, steuerprozentid, waehrungid, zuschlagsart, pzuschlag, preisart, gesamttitelagenturmwst, gesamttitelagenturbrutto, planprokalkposid) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
          16:06:55,250 INFO [STDOUT] Hibernate: insert into PLANPROKALKPOS (agenturnetto, frequenz, zeitungid, fixzuschlag, erscheinungstermin, mmzuschlag, kundemwst, agenturbrutto, kundebruttopreis, kundenetto, wmbezeichnung, abschlussrabatt, kundeauflage, gesamttitelkundebrutto, gesamttitelagenturnetto, anzeigenschluss, auflagesplit, gesamttitelkundemwst, ruecktritt, wmdefinition, kundeid, plankalkid, agenturmwst, druckvorlagen, titelgesamtauflage, kundebrutto, tsdpreis, pzuschlagsart, fixzuschlagsplit, gesamttitelkundenetto, mvg, steuerprozentid, waehrungid, zuschlagsart, pzuschlag, preisart, gesamttitelagenturmwst, gesamttitelagenturbrutto, planprokalkposid) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
          16:06:55,265 WARN [TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@65628e[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@240115 handles=1 lastUse=1213798015140 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@4746c3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@176bcc3 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@296839 txSync=null]
          java.lang.IllegalArgumentException: Invalid Input Number
           at oracle.sql.NUMBER.toBytes(NUMBER.java:926)
           at oracle.jdbc.dbaccess.DBConversion.DoubleToNumberBytes(DBConversion.java:2990)
           at oracle.jdbc.driver.OraclePreparedStatement.setDouble(OraclePreparedStatement.java:1552)
           at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.setDouble(WrappedPreparedStatement.java:156)
           at org.hibernate.type.DoubleType.set(DoubleType.java:36)
           at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:136)
           at org.hibernate.type.NullableType.nullSafeSet(NullableType.java:107)
           at org.hibernate.persister.entity.AbstractEntityPersister.dehydrate(AbstractEntityPersister.java:1997)
           at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2243)
           at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2660)
           at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:56)
           at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
           at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
           at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
           at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
           at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
           at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
           at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
           at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)
           at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:114)
           at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:247)
           at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
           at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
           at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1382)
           at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
           at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
           at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175)
           at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87)
           at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
           at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
           at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)


          which interesting part starts at TxPolixy.invokeInOurTx:

          public Object invokeInOurTx(Invocation invocation, TransactionManager tm) throws Throwable
           {
           for (int i = 0; i < MAX_RETRIES; i++)
           {
           tm.begin();
           Transaction tx = tm.getTransaction();
           try
           {
           try
           {
           return invocation.invokeNext();
           }
           catch (Throwable t)
           {
           handleExceptionInOurTx(invocation, t, tx);
           }
           finally
           {
           endTransaction(tm, tx);
           }
           }
           catch (Exception ex)
           {
           ...
          


          The result from call return invocation.invokeNext(); causes no exception, its the call of savePlanKalk (the session bean method), so the finally block is reached and a call to endTransaction starts, where commit is called, because the transaction status is ok and not marked for rollback.

          public void endTransaction(TransactionManager tm, Transaction tx)
           {
           try
           {
           if (tx != tm.getTransaction())
           {
           throw new IllegalStateException("Wrong tx on thread: expected " + tx + ", actual " + tm.getTransaction());
           }
          
           if (tx.getStatus() == Status.STATUS_MARKED_ROLLBACK)
           {
           tm.rollback();
           }
           else
           {
           // Commit tx
           // This will happen if
           // a) everything goes well
           // b) app. exception was thrown
           tm.commit();
           }
           }
           catch (RollbackException e)
           {
           handleEndTransactionException(e);
           }
           catch (HeuristicMixedException e)
           {
           handleEndTransactionException(e);
           }
           catch (HeuristicRollbackException e)
           {
           handleEndTransactionException(e);
           }
           catch (SystemException e)
           {
           handleEndTransactionException(e);
           }
           }
          
           public void handleEndTransactionException(Exception e)
           {
           throw new RuntimeException(e);
           }
          


          Calling tm.commit() the statements are processed against the database and the exception occurs with the second insert statement.

          In TransactionImple (com.arjuna.ats.internal.jta.transaction.arjunacore) there in method commitAndDisassociate()

          protected void commitAndDisassociate()
           throws javax.transaction.RollbackException,
           javax.transaction.HeuristicMixedException,
           javax.transaction.HeuristicRollbackException,
           java.lang.SecurityException, javax.transaction.SystemException,
           java.lang.IllegalStateException
           {
           if (jtaLogger.logger.isDebugEnabled())
           {
           jtaLogger.logger.debug(DebugLevel.FUNCTIONS, VisibilityLevel.VIS_PUBLIC, com.arjuna.ats.jta.logging.FacilityCode.FAC_JTA, "TransactionImple.commitAndDisassociate");
           }
          
           try
           {
           if (_theTransaction != null)
           {
           switch (_theTransaction.status())
           {
           case ActionStatus.ABORTED:
           case ActionStatus.ABORTING:
           _theTransaction.abort(); // assure thread disassociation
           throw new IllegalStateException(
           jtaLogger.logMesg.getString("com.arjuna.ats.internal.jta.transaction.arjunacore.inactive"));
          
           case ActionStatus.COMMITTED:
           case ActionStatus.COMMITTING: // in case of async commit
           _theTransaction.commit(true); // assure thread disassociation
           throw new IllegalStateException(
           jtaLogger.logMesg.getString("com.arjuna.ats.internal.jta.transaction.arjunacore.inactive"));
           }
          
           switch (_theTransaction.commit(true))
           {
           case ActionStatus.COMMITTED:
           case ActionStatus.COMMITTING: // in case of async commit
           break;
           case ActionStatus.H_MIXED:
           throw new javax.transaction.HeuristicMixedException();
           case ActionStatus.H_HAZARD:
           throw new javax.transaction.HeuristicMixedException();
           case ActionStatus.H_ROLLBACK:
           case ActionStatus.ABORTED:
           case ActionStatus.ABORTING:
           RollbackException rollbackException = new RollbackException(jtaLogger.logMesg.getString("com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted"));
           if(_theTransaction.getDeferredThrowable() != null) {
           rollbackException.initCause(_theTransaction.getDeferredThrowable());
           }
           throw rollbackException;
           default:
           throw new IllegalStateException(
           jtaLogger.logMesg.getString("com.arjuna.ats.internal.jta.transaction.arjunacore.invalidstate"));
           }
           }
           else
           throw new IllegalStateException(
           jtaLogger.logMesg.getString("com.arjuna.ats.internal.jta.transaction.arjunacore.inactive"));
           }
           finally
           {
           TransactionImple.removeTransaction(this);
           }
           }



          switch (_theTransaction.commit(true)) is called and return ActionStatus.Aborting so then the RollbackException is being created.
          Stepping further through the sources i can see that the transaction and the connection to the database are closed, i can't find any rollback.
          I think i will try this with an other simple sample.


          • 2. Re: CMT problem rollback fails
            hezimmer Newbie

            Ok, back again. This error is reproducible.
            For simple test purpose i created two tables:

            create table table1 (table1id number not null primary key,
             nr number);
            
            
            create table table2 (table2id number not null primary key,
             nr number);


            and generated two pojos (Table2 class looks the same):

            /**
             * @hibernate.class table="TABLE1" lazy="false"
             */
            public class Table1
            {
            
             private Integer table1id;
             private Double nr;
            
             /**
             * @hibernate.id generator-class="sequence"
             * @hibernate.generator-param name="sequence" value="PK_TABLE1_SEQ"
             */
             public Integer getTable1id()
             {
             return table1id;
             }
            
             public void setTable1id(Integer table1id)throws ValueNotNullableException
             {
             if(table1id == null)
             {
             throw new ValueNotNullableException(null,"Table1id","Table1id","table1.table1id.valuenotnullable");
             }
            
             this.table1id = table1id;
             }
            
             /**
             * @hibernate.property not-null="false"
             */
             public Double getNr()
             {
             return nr;
             }
            
             public void setNr(Double nr)
             {
             this.nr = nr;
             }
            }
            


            Inside the stateless session bean the test method does the following:

            public void test() {
             Session hnSession = HibernateUtil.getSession();
            
             Table1 test1 = new Table1();
             test1.setNr(1d);
             hnSession.save(test1);
            
            
             Table2 test2 = new Table2();
             test2.setNr(Double.NaN);
             hnSession.save(test2);
            
             return;
             }


            Same environment as the real example, also CMP with Hibernate.
            The data in table1 were saved into db, before the save to table2 fails.

            Here a look at the log:

            17:38:18,359 DEBUG [ConnectionManager] opening JDBC connection
            17:38:18,359 DEBUG [SQL] insert into TABLE1 (nr, table1id) values (?, ?)
            17:38:18,359 INFO [STDOUT] Hibernate: insert into TABLE1 (nr, table1id) values (?, ?)
            17:38:18,359 DEBUG [AbstractBatcher] Executing batch size: 1
            17:38:18,359 DEBUG [Expectations] success of batch update unknown: 0
            17:38:18,359 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            17:38:18,359 DEBUG [ConnectionManager] skipping aggressive-release due to flush cycle
            17:38:18,359 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            17:38:18,359 DEBUG [SQL] insert into TABLE2 (nr, table2id) values (?, ?)
            17:38:18,359 INFO [STDOUT] Hibernate: insert into TABLE2 (nr, table2id) values (?, ?)
            17:38:18,390 WARN [TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@53d29b[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@11a59e3 handles=1 lastUse=1213889794109 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1035b2a context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@15622eb xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@182440f txSync=null]
            java.lang.IllegalArgumentException: Invalid Input Number
             at oracle.sql.NUMBER.toBytes(NUMBER.java:926)
            


            So the AbstractBatcher closes the PreparedStatement after the execution of the first insert - statement. After that a new PreparedStatement was opened and failed while executing the second insert statement.
            After that the data from the first insert statement were persisted into database.
            So i think the problem is the closed PreparedStatement after execution of the first insert. Is that an configuration issue?

            I tried a slightly modification, changed the second insert statement from an insert into table2 to an insert in table1, but with the same wrong data as before:

            public void test() {
             Session hnSession = HibernateUtil.getSession();
            
             Table1 test1 = new Table1();
             test1.setNr(1d);
             hnSession.save(test1);
            
            
             Table1 test2 = new Table1();
             test2.setNr(Double.NaN);
             hnSession.save(test2);
            
             return;
             }
            


            And now nothing is commited into database, the data from insert 1 are not persisted anymore. Take a look at the log output:

            18:00:19,812 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            18:00:19,812 DEBUG [ConnectionManager] opening JDBC connection
            18:00:19,812 DEBUG [SQL] insert into TABLE1 (nr, table1id) values (?, ?)
            18:00:19,828 INFO [STDOUT] Hibernate: insert into TABLE1 (nr, table1id) values (?, ?)
            18:00:19,828 DEBUG [AbstractBatcher] reusing prepared statement
            18:00:19,828 DEBUG [SQL] insert into TABLE1 (nr, table1id) values (?, ?)
            18:00:19,828 INFO [STDOUT] Hibernate: insert into TABLE1 (nr, table1id) values (?, ?)
            18:00:19,828 WARN [TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1af611c[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@d89fb1 handles=1 lastUse=1213891219812 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1035b2a context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@15622eb xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@11094e7 txSync=null]
            java.lang.IllegalArgumentException: Invalid Input Number
             at oracle.sql.NUMBER.toBytes(NUMBER.java:926)


            The PreparedStatement was reused between insert 1 and insert 2, thats because the same statement on the same table, just with other data. So after this exception no data were inserted into database. That's fine.

            Is the above behavior of the AbstractBatcher configurable? So do i have an configuration problem (UpdateBatchsize?) or is this a bug?


            • 3. Re: CMT problem rollback fails
              Jonathan Halliday Master

              What is in your -ds.xml file and does the problem occur on JBoss 4.2.2 also?

              • 4. Re: CMT problem rollback fails
                hezimmer Newbie

                Inside my -ds.xml file i have made the following entry:

                <local-tx-datasource>
                 <jndi-name>/jdbc/TEST</jndi-name>
                 <connection-url>jdbc:oracle:oci:@test.mydomain.de</connection-url>
                 <driver-class>oracle.jdbc.driver.OracleDriver</driver-class>
                <exception-sorter-class-name>org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter</exception-sorter-class-name>
                 <metadata>
                 <type-mapping>Oracle9iDialect</type-mapping>
                 </metadata>
                 </local-tx-datasource>


                The hibernate configuration in hibernate.cfg.xml looks like:

                <hibernate-configuration>
                 <session-factory>
                 <property name="dialect">org.hibernate.dialect.Oracle9Dialect</property>
                 <property name="show_sql">true</property>
                 <property name="use_outer_join">false</property>
                 <property name="connection.url">/jdbc/TEST</property>
                 <property name="jdbc.fetch_size">400</property>
                




                • 5. Re: CMT problem rollback fails
                  Mark Little Master

                   


                  Stepping further through the sources i can see that the transaction and the connection to the database are closed, i can't find any rollback.


                  So what are you expecting to see? There will be no call to JTA.rollback: commit has failed and rolled back within the commit call.

                  • 6. Re: CMT problem rollback fails
                    hezimmer Newbie

                    Don't get me wrong: I expected to get an rollback from container (while working inside tx.commit) down to jdbc level and i found that now by debugging further inside the code.

                    • 7. Re: CMT problem rollback fails
                      Mark Little Master

                      The container isn't going to call rollback: once commit goes off and fails, the TM will call rollback on the registered participants (XAResources). Eventually it'll throw a TransactionRolledBackException from commit.

                      • 8. Re: CMT problem rollback fails
                        hezimmer Newbie

                        Yes that's true.
                        The really problem is that the managed connection
                        on jdbc level is being closed long before
                        LocalManagedTransaction getLocalTransaction().rollback();
                        is called which tries to make an rollback on an non existing
                        jdbc-connection. The jdbc - connection is closed with no
                        rollback or commit, which means that if the auto-commit mode
                        is disabled (as it is in this case) and you close the connection
                        without explicitly committing or rolling back your last changes,
                        then an implicit COMMIT operation is run.

                        • 9. Re: CMT problem rollback fails
                          hezimmer Newbie

                          I stepped further through the code and this is why the connection is being closed to early:

                          Inside WrappedPreparedStatement method setDouble the Exception from underlying jdbc-driver is thrown. In case of this example
                          with Double.NaN as parameter value, Oracle causes an IllegalArgumentException instead of an SQLException.
                          Because of that BaseWrapperManagedConnection method connectionError is called:

                          void connectionError(Throwable t)
                           {
                           if (t instanceof SQLException == false || mcf.isExceptionFatal((SQLException) t))
                           broadcastConnectionError(t);
                           }


                          This Throwable isn't an instance of SQLException so it seems to be an
                          connection error and broadcastConnectionError is called which causes
                          unregisterConnections and so the connection on jdbc level is closed
                          without rollback. Because of that the insert1 statement is commited
                          because oracle jdbc commits (as mentioned in posting before) on close.