BPEL ATM example

[stone_42]

Hello,

I have two questions regarding the atm example:
- The atm example is running and the test case completes. But if I try to call the operations connect() and logon() from one client process, and after that, from another client process, e.g. deposit(), logoff() and disconnect() (with the same sessionID and customerName), there is strange behavior: My second process needs lots of time, and after depositing or withdrawing, the balance is always zero. I looked to the server log, and found the following entries:

2006-01-10 13:07:56,015 DEBUG [org.jbpm.bpel.service.messager.PortHandler] listening for response: JMS_TQ2
2006-01-10 13:08:56,015 DEBUG [org.jbpm.bpel.service.messager.PortHandler] response timeout expired: JMS_TQ2

This seems to be the reason for the long execution time of my second client process.
What do I do wrong?

The second question is about jbpm bpel on mysql (I use version 4.1.14).
I can create the db-schema without a problem and deploy the atm example, but when I run the testcase of the atm example, the server throws a huge stacktrace, beginning with the following:

org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
 at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:91)
 at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:79)
 at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
 at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:200)
 at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:91)
 at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:86)
 at org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:169)
 at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2162)
 at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2117)
 at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2373)
 at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:84)
 at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:243)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:227)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296)
 at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
 at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:905)
 at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:345)
 at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
 at org.jbpm.bpel.service.messager.StartListener.onMessage(StartListener.java:124)
 at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:707)
 at java.lang.Thread.run(Thread.java:595)
Caused by: java.sql.BatchUpdateException: Incorrect arguments to mysql_stmt_execute
 at com.mysql.jdbc.ServerPreparedStatement.executeBatch(ServerPreparedStatement.java:828)
 at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:487)
 at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
 at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:193)
 ... 18 more
13:21:11,265 ERROR [StartListener] could not deliver request
org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
 at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:91)
 at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:79)
 at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
 at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:200)
 at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:91)
 at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:86)
 at org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:169)
 at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2162)
 at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2117)
 at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2373)
 at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:84)
 at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:243)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:227)
 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141)
 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296)
 at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
 at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:905)
 at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:345)
 at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
 at org.jbpm.bpel.service.messager.StartListener.onMessage(StartListener.java:124)
 at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:707)
 at java.lang.Thread.run(Thread.java:595)
Caused by: java.sql.BatchUpdateException: Incorrect arguments to mysql_stmt_execute
 at com.mysql.jdbc.ServerPreparedStatement.executeBatch(ServerPreparedStatement.java:828)
 at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:487)
 at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
 at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:193)
 ... 18 more
13:21:11,531 INFO [DefaultLoadEventListener] Error performing load command
org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [org.jbpm.graph.exe.Token#6]
 at org.hibernate.ObjectNotFoundException.throwIfNull(ObjectNotFoundException.java:27)
 at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:128)
 at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:161)
 at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:87)
 at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:809)
 at org.hibernate.impl.SessionImpl.load(SessionImpl.java:731)
 at org.hibernate.impl.SessionImpl.load(SessionImpl.java:724)
 at org.jbpm.bpel.service.messager.RequestListener.onMessage(RequestListener.java:95)
 at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:707)
 at java.lang.Thread.run(Thread.java:595)

I run the atm example also on a HSQLDB and on Oracle 10 with Hibernate Oracle9Dialect (after renaming some foreign keys in the mapping files whose names were too long for oracle), and it worked. Interesting, create-schema worked on mysql without any exception, on HSQLDB and Oracle there was an exception in the server log, but the server returned 200 and the ant task completed successfully.

Regards,
Martin

[stone_42]

Hello again,

I have an addition to my first question. After playing some time with the example, i cannot reproduce the problem any more. Just some restarting of JBoss, clearing the JBPM Database, and it worked. While playing with it, sometimes there was the following exception, perhaps it can help find my error:

15:32:34,593 WARN [SpyMessageConsumer] Message consumer closing due to error in listening thread.
javax.jms.JMSException: Invalid transaction id.
 at org.jboss.mq.SpyXAResourceManager.ackMessage(SpyXAResourceManager.java:95)
 at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:672)
 at java.lang.Thread.run(Thread.java:595)

Thanks a lot,
Martin

[aguizar]

Regarding the first question, the invalid transaction id error you found appears at random and kills the consumer (created by the receive activity) that would serve the request. Meanwhile, the consumer created by the port handler to receive the reply times out and returns a fault to the caller.

I have not figured out what causes the transaction ID to become invalid. Gotta spend some more time with JMS. Could you file a JIRA issue?

[aguizar]

On the schema creation problems: is this the error in the server log for Hypersonic and Oracle?

18:11:55,812 ERROR [[/jbpm-bpel]] DBSchemaServlet: caught an exception
java.sql.SQLException: Table not found: BPEL_ALARMDEFINITION in statement [alter table BPEL_ALARMDEFINITION]
 at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
 at org.hsqldb.jdbc.jdbcStatement.fetchResult(Unknown Source)
 at org.hsqldb.jdbc.jdbcStatement.executeUpdate(Unknown Source)
 at org.jboss.resource.adapter.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:161)
 at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:299)
 at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:282)
 at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:192)
 at org.hibernate.tool.hbm2ddl.SchemaExport.create(SchemaExport.java:135)
 at org.jbpm.bpel.web.deploy.DBSchemaServlet.createSchema(DBSchemaServlet.java:48)
 at org.jbpm.bpel.web.deploy.DBSchemaServlet.doGet(DBSchemaServlet.java:30)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
 at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
 at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
 at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
 at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
 at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
 at java.lang.Thread.run(Thread.java:595)
18:11:55,812 INFO [[/jbpm-bpel]] DBSchemaServlet: 169 more exceptions caught

This is not a harmful error. You can find some comments about it in Problem in create-schema of jBPM BPEL.

About MySQL, I tested the example against MySQL Server 5.0 and Connector/J 3.1.12. It worked, so I feel inclined to think it is a matter of upgrading the driver or the database.

[stone_42]

Thank you for your help.

about the schema creation problem:
At first, the error in the server log is as you guessed:

18:11:55,812 ERROR [[/jbpm-bpel]] DBSchemaServlet: caught an exception
java.sql.SQLException: Table not found: BPEL_ALARMDEFINITION in statement [alter table BPEL_ALARMDEF
INITION]
[...]

When I repeat the schema-creation, the error differs.
On Hypersonic, it is:

java.sql.SQLException: Constraint not found FK_ACTIVITY_COMPOSITE in table: JBPM_NODE in statement [alter table JBPM_NODE drop constraint FK_ACTIVITY_COMPOSITE]
 at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
 at org.hsqldb.jdbc.jdbcStatement.fetchResult(Unknown Source)
 at org.hsqldb.jdbc.jdbcStatement.executeUpdate(Unknown Source)
 at org.jboss.resource.adapter.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:161)
 at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:299)
[...]

On Oracle, it is:

java.sql.SQLException: ORA-02275: such a referential constraint already exists in the table
 at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:145)
 at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331)
 at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:288)
 at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:743)
 at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:207)
 at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1111)
 at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1278)
 at oracle.jdbc.driver.OracleStatement.executeUpdateInternal(OracleStatement.java:1855)
 at oracle.jdbc.driver.OracleStatement.executeUpdate(OracleStatement.java:1820)
 at org.jboss.resource.adapter.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:161)
 at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:299)

Regarding my problem with MySQL: I used MySQL Connector/J 3.1.7. Now I'm using Connector/J 3.1.12 and it works.

Regards,
Martin