CMT problem rollback fails

[hezimmer]

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

[hezimmer]

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.

[hezimmer]

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?

[jhalliday]

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

[hezimmer]

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>

[marklittle]

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.

[hezimmer]

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.

[marklittle]

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.

[hezimmer]

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.

[hezimmer]

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.

[hezimmer]

i opened an jira - issue

http://jira.jboss.com/jira/browse/JBAS-5678