"Acknowledgment missed" in ebms.log

[Dag Høidahl]

Hello,

We are seeing message "Acknowldegement missed" (sic) in the ebms.log
file. What does it mean, and why does it appear?

Here is an excerpt of embs.log:


2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <Incoming
ebxml message received: 20100426-0...@10.47.18.94>
2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <Inbound
agreement checking for interop>
2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <The
message has received before: 20100426-0...@10.47.18.94>
2010-04-26 10:59:10 [-Processor23] <ERROR> <cecid.ebms.spa>
<Acknowldegement missed. Internal server error or the acknowledgement
is generating for message: 20100426-0...@10.47.18.94>
2010-04-26 10:59:10 [-Processor23] <DEBUG> <cecid.ebms.spa> <Error in
processing incoming message>
hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException:
Acknowldegement missed. Internal server error or the acknowledgement
is generating for message: 20100426-0...@10.47.18.94
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processDuplicateAckRequestedMessage(InboundMessageProcessor.java:
460)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessage(InboundMessageProcessor.java:
174)
at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(MessageServiceHandler.java:
276)
at
hk.hku.cecid.ebms.spa.listener.EbmsInboundListener.processRequest(EbmsInboundListener.java:
59)
at
hk.hku.cecid.ebms.spa.listener.EbmsAdaptor.processRequest(EbmsAdaptor.java:
42)
at
hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAdaptor.java:
132)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(HttpDispatcher.java:
126)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doPost(HttpDispatcher.java:
277)
at
javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at
javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:
269)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:
188)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:
213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:
172)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:
433)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:
127)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:
117)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:
108)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:
174)
at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
875)
at org.apache.coyote.http11.Http11BaseProtocol
$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:
665)
at
org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:
528)
at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:
81)
at org.apache.tomcat.util.threads.ThreadPool
$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Unknown Source)

Regards,
Dag Høidahl

--
You received this message because you are subscribed to the Google Groups "Hermes 2.0 Discussion List" group.
To post to this group, send email to cecid-...@googlegroups.com.
To unsubscribe from this group, send email to cecid-hermes...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/cecid-hermes2?hl=en.

[Franz Wong]

When a message is received (1st round) and acknowledgement is request,
Hermes will generate an acknowledgement and send it out.

Afterward, the same message is received again (2 to n-th round) (i.e.
duplicate message), Hermes will retrieve the acknowledgement generated
in 1st round (from database) and send it out.

The error logged occurs when Hermes failed to retrieve the
acknowledgement. Hermes may be still generating the acknowledgement
for the 1st round or there may be some other problems.

Regards,
Franz

On Apr 26, 5:10 pm, Dag Høidahl <dag.hoid...@gmail.com> wrote:
> Hello,
>
> We are seeing message "Acknowldegement missed" (sic) in the ebms.log
> file. What does it mean, and why does it appear?
>
> Here is an excerpt of embs.log:
>
> 2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <Incoming

> ebxml message received: 20100426-093402-32...@10.47.18.94>

> 2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <Inbound
> agreement checking for interop>
> 2010-04-26 10:59:10 [-Processor23] <INFO > <cecid.ebms.spa> <The

> message has received before: 20100426-093402-32...@10.47.18.94>

> 2010-04-26 10:59:10 [-Processor23] <ERROR> <cecid.ebms.spa>
> <Acknowldegement missed. Internal server error or the acknowledgement

> is generating for message: 20100426-093402-32...@10.47.18.94>

> 2010-04-26 10:59:10 [-Processor23] <DEBUG> <cecid.ebms.spa> <Error in
> processing incoming message>
> hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException:
> Acknowldegement missed. Internal server error or the acknowledgement

> is generating for message: 20100426-093402-32...@10.47.18.94

[Dag Høidahl]

Thanks for the explanation.

So how do we determine the cause of this? Our partner is not getting
their receipts, so we need find a way to fix the issue.

Regards,
Dag Høidahl

> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processDuplicateAckRe­questedMessage(InboundMessageProcessor.java:
> > 460)
> >                at
> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessag­e(InboundMessageProcessor.java:
> > 174)
> >                at
> > hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(M­essageServiceHandler.java:
> > 276)
> >                at
> > hk.hku.cecid.ebms.spa.listener.EbmsInboundListener.processRequest(EbmsInbou­ndListener.java:

> > 59)
> >                at
> > hk.hku.cecid.ebms.spa.listener.EbmsAdaptor.processRequest(EbmsAdaptor.java:
> > 42)
> >                at

> > hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAda­ptor.java:
> > 132)
> >                at
> > hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(Http­Dispatcher.java:
> > 126)
> >                at
> > hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doPost(HttpDispatch­er.java:

> > 277)
> >                at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
> >                at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
> >                at

> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio­nFilterChain.java:
> > 269)
> >                at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterC­hain.java:
> > 188)
> >                at
> > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.j­ava:
> > 213)
> >                at
> > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.j­ava:
> > 172)
> >                at
> > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBas­e.java:

> > 433)
> >                at
> > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:
> > 127)
> >                at
> > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:
> > 117)
> >                at

> > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.jav­a:

> > 108)
> >                at
> > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:
> > 174)
> >                at
> > org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
> > 875)
> >                at org.apache.coyote.http11.Http11BaseProtocol
> > $Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:
> > 665)
> >                at

> > org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.ja­va:
> > 528)
> >                at
> > org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerW­orkerThread.java:

[Franz Wong]

From the ebms.log, can you notice any other errors?

There is a record in the database for the acknowledgement generated.
Can you find that?

If you now send the message again, can the acknowledgement be
generated and sent successfully?

I need to gather more information as this is not a common case.

Regards,
Franz

[Dag Høidahl]

Hello,

I've got a previous error on one message that later yields an
"acknowledgment missed". There seems to be a deadlock occurring:

2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Incoming
ebxml message received: 20100503-1...@10.47.18.94>
2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Inbound
agreement checking for interop>
2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <It is an
order message: 20100503-1...@10.47.18.94>
2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Store the
incoming message: 20100503-1...@10.47.18.94>
2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Sending
async reply message: 20100503-1...@153.110.160.149>
2010-05-03 15:03:17 [Thread-2028 ] <INFO > <cecid.ebms.spa> <Ebxml
Message (20100503-1...@10.47.18.94) is stored in inbox with
order number: 7773>
2010-05-03 15:03:17 [-Processor17] <ERROR> <cecid.ebms.spa> <Cannot
generate acknowledgement for message:
20100503-1...@10.47.18.94>
2010-05-03 15:03:17 [-Processor17] <DEBUG> <cecid.ebms.spa> <Error in
processing incoming message>
hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Cannot
generate acknowledgement for message:
20100503-1...@10.47.18.94
by hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException:
Error in processing outgoing message
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processOrderMessage(InboundMessageProcessor.java:
930)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessage(InboundMessageProcessor.java:
271)

at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(MessageServiceHandler.java:
276)
at
hk.hku.cecid.ebms.spa.listener.EbmsInboundListener.processRequest(EbmsInboundListener.java:

59)
at
hk.hku.cecid.ebms.spa.listener.EbmsAdaptor.processRequest(EbmsAdaptor.java:
42)
at

hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAdaptor.java:
132)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(HttpDispatcher.java:
126)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doPost(HttpDispatcher.java:

277)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:
269)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:
188)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:
213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:
172)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:

433)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:
127)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:
117)
at

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:

108)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:
174)
at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
875)
at org.apache.coyote.http11.Http11BaseProtocol
$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:
665)
at

org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:
528)
at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:

81)
at org.apache.tomcat.util.threads.ThreadPool
$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Unknown Source)

Caused by:
hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Error in
processing outgoing message
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessage(OutboundMessageProcessor.java:
129)
at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processOutboundMessage(MessageServiceHandler.java:
283)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.sendAsyncMessage(InboundMessageProcessor.java:
1644)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processOrderMessage(InboundMessageProcessor.java:
924)
... 24 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
97)
at
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO.storeOutboxMessage(MessageServerDataSourceDAO.java:
93)
at
hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.storeOutgoingMessage(OutboundMessageProcessor.java:
287)
at
hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessage(OutboundMessageProcessor.java:
121)
... 27 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing
hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
97)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:
588)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:
548)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:
528)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
626)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
610)
at
hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO.addOutbox(OutboxDataSourceDAO.java:
39)
at hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO
$2.doTransaction(MessageServerDataSourceDAO.java:89)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
89)
... 30 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing update: INSERT INTO outbox (message_id, retried) VALUES
(?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
110)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
89)
... 38 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error
occurred when executing update at row 0 of the specified parameter
array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
96)
... 39 more
Caused by:
com.mysql.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock
found when trying to get lock; try restarting transaction
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:941)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:
1332)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1604)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1519)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1504)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
92)
... 39 more


Regards,
Dag

On Apr 29, 3:55 am, Franz Wong <franzw...@gmail.com> wrote:
> From the ebms.log, can you notice any other errors?
>
> There is a record in the database for the acknowledgement generated.
> Can you find that?
>
> If you now send the message again, can the acknowledgement be
> generated and sent successfully?
>
> I need to gather more information as this is not a common case.
>
> Regards,
> Franz

[Franz Wong]

Let me clarify some a bit. Correct me if I am wrong.

There are totally 3 errors.

1st : An error occurred.

2nd : Another error occurred (i.e. the ack missed) (yielded by 1st error) (26/Apr)

3rd : The deadlock occurs. (3/May)

As a rough guess, the deadlock may come from the 1st error which locks the database.

It would be better if the log of the 1st error is provided.

Franz

2010/5/3 Dag Høidahl <dag.h...@gmail.com>

[Dag Høidahl]

No, as far as I can tell, this is what we see:

1. The deadlock occurs, which prevents the first acknowledgment from
being saved in the database (and also from being sent, probably)
2. The "acknowledgment missed" error is logged when our partner
resends their message which it has not received any acknowledgment
for.

Sorry if I have been unclear.

So we don't know what kind of situation/error can lead to a deadlock.
If we can avoid that, the problem is probably solved.

What kind of error may lead to a lock on the database?

Regards,
Dag

On May 4, 5:52 am, Franz Wong <franzw...@gmail.com> wrote:
> Let me clarify some a bit. Correct me if I am wrong.
>
> There are totally 3 errors.
>
> 1st : An error occurred.
> 2nd : Another error occurred (i.e. the ack missed) (yielded by 1st error)
> (26/Apr)
> 3rd : The deadlock occurs. (3/May)
>
> As a rough guess, the deadlock may come from the 1st error which locks the
> database.
>
> It would be better if the log of the 1st error is provided.
>
> Franz
>

> 2010/5/3 Dag Høidahl <dag.hoid...@gmail.com>

>
>
>
> > Hello,
>
> > I've got a previous error on one message that later yields an
> > "acknowledgment missed". There seems to be a deadlock occurring:
>
> > 2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Incoming

> > ebxml message received: 20100503-150742-10...@10.47.18.94>

> > 2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Inbound
> > agreement checking for interop>
> > 2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <It is an

> > order message: 20100503-150742-10...@10.47.18.94>

> > 2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Store the

> > incoming message: 20100503-150742-10...@10.47.18.94>

> > 2010-05-03 15:03:16 [-Processor17] <INFO > <cecid.ebms.spa> <Sending

> > async reply message: 20100503-150316-86...@153.110.160.149>

> > 2010-05-03 15:03:17 [Thread-2028 ] <INFO > <cecid.ebms.spa> <Ebxml

> > Message (20100503-150742-10...@10.47.18.94) is stored in inbox with

> > order number: 7773>
> > 2010-05-03 15:03:17 [-Processor17] <ERROR> <cecid.ebms.spa> <Cannot
> > generate acknowledgement for message:

> > 20100503-150742-10...@10.47.18.94>

> > 2010-05-03 15:03:17 [-Processor17] <DEBUG> <cecid.ebms.spa> <Error in
> > processing incoming message>
> > hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Cannot
> > generate acknowledgement for message:

> > 20100503-150742-10...@10.47.18.94

> >        by hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException:
> > Error in processing outgoing message
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
> > executing update at row 0 of the specified parameter array
> >        by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
> > Deadlock found when trying to get lock; try restarting transaction
> >        at
>

> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processOrderMessage(I­nboundMessageProcessor.java:
> > 930)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessag­e(InboundMessageProcessor.java:
> > 271)

> >        at
>
> > hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(M­essageServiceHandler.java:
> > 276)
> >        at
>
> > hk.hku.cecid.ebms.spa.listener.EbmsInboundListener.processRequest(EbmsInbou­ndListener.java:

> > 59)
> >        at
> > hk.hku.cecid.ebms.spa.listener.EbmsAdaptor.processRequest(EbmsAdaptor.java:
> > 42)
> >        at
>

> > hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAda­ptor.java:
> > 132)
> >        at
>
> > hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(Http­Dispatcher.java:
> > 126)
> >        at
>
> > hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doPost(HttpDispatch­er.java:

> > 277)
> >        at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
> >        at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
> >        at
>

> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio­nFilterChain.java:
> > 269)
> >        at
>
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterC­hain.java:
> > 188)
> >        at
>
> > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.j­ava:
> > 213)
> >        at
>
> > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.j­ava:
> > 172)
> >        at
>
> > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBas­e.java:

> > 433)
> >        at
> > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:
> > 127)
> >        at
> > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:
> > 117)
> >        at
>

> > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.jav­a:

> > 108)
> >        at
> > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:
> > 174)
> >        at
> > org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
> > 875)
> >        at org.apache.coyote.http11.Http11BaseProtocol
> > $Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:
> > 665)
> >        at
>

> > org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.ja­va:
> > 528)
> >        at
>
> > org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerW­orkerThread.java:

> > 81)
> >        at org.apache.tomcat.util.threads.ThreadPool
> > $ControlRunnable.run(ThreadPool.java:689)
> >        at java.lang.Thread.run(Unknown Source)
> > Caused by:
> > hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Error in
> > processing outgoing message
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
> > executing update at row 0 of the specified parameter array
> >        by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
> > Deadlock found when trying to get lock; try restarting transaction
> >        at
>

> > hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessa­ge(OutboundMessageProcessor.java:
> > 129)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processOutboundMessage(­MessageServiceHandler.java:
> > 283)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.sendAsyncMessage(Inbo­undMessageProcessor.java:
> > 1644)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processOrderMessage(I­nboundMessageProcessor.java:

> > 924)
> >        ... 24 more
> > Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
> > executing
> > hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1e46f7b
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
> > executing update at row 0 of the specified parameter array
> >        by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
> > Deadlock found when trying to get lock; try restarting transaction
> >        at
>

> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProces­s.java:
> > 97)
> >        at
>
> > hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO.storeOutboxMessage(Mes­sageServerDataSourceDAO.java:
> > 93)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.storeOutgoingMessage­(OutboundMessageProcessor.java:
> > 287)
> >        at
>
> > hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessa­ge(OutboundMessageProcessor.java:

> > 121)
> >        ... 27 more
> > Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
> > executing
> > hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@f63c1c
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
> > update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
> > executing update at row 0 of the specified parameter array
> >        by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
> > Deadlock found when trying to get lock; try restarting transaction
> >        at
>

> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProces­s.java:
> > 97)
> >        at
>
> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDA­O.java:
> > 588)
> >        at
>
> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDA­O.java:
> > 548)
> >        at
>
> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDA­O.java:

> > 528)
> >        at
> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
> > 626)
> >        at
> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
> > 610)
> >        at
>

> > hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO.addOutbox(OutboxDataSourceDAO­.java:

> > 39)
> >        at hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO
> > $2.doTransaction(MessageServerDataSourceDAO.java:89)
> >        at
>

> > hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProces­s.java:

> > 89)
> >        ... 30 more
> > Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
> > executing update: INSERT INTO outbox (message_id, retried) VALUES
> > (?,?)
> >        by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
> > executing update at row 0 of the specified parameter array
> >        by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
> > Deadlock found when trying to get lock; try restarting transaction
> >        at
>

> ...
>
> read more »

[Dag Høidahl]

Hello again.

Here is some additional info that might be relevant.
We are using these libraries in corvus/WEB-INF/lib:
* mysql-connector-java-5.0.8-bin.jar
* commons-pool-1.4.jar

This is the configuration for daofactory in ebms.module.xml:
<component id="daofactory" name="System DAO Factory">
<class>hk.hku.cecid.piazza.commons.dao.ds.SimpleDSDAOFactory</
class>
<parameter name="driver" value="com.mysql.jdbc.Driver" />
<parameter name="url" value="jdbc:mysql://127.0.0.1:3306/ebms" />
<parameter name="username" value="corvus" />
<parameter name="password" value="corvus" />
<parameter name="pooling" value="true" />
<parameter name="maxActive" value="30" />
<parameter name="maxIdle" value="10" />
<parameter name="maxWait" value="-1" />
<parameter name="testOnBorrow" value="true" />
<parameter name="testOnReturn" value="false" />
<parameter name="testWhileIdle" value="false" />
<parameter name="validationQuery" value="SELECT now()" />
<parameter name="config">hk/hku/cecid/ebms/spa/conf/
ebms.mysql.dao.xml</parameter>
</component>

Regards,
Dag

[Dag Høidahl]

Hello again.

We have restarted the database and Tomcat to try to single out the
cause of the deadlocks, but I'm not sure if we got anything useful.

The logs show many occurences of "Missing acknowledgment" due to
earlier errors. It took a little less than an hour before we got the
first deadlock. Before that, there were no unusual exceptions.

We do have some exceptions occuring because we have a monitor which is
periodically polling the HTTP port of the web service to verify that
it is not down. These are the only exceptions that are logged before
we see the deadlock (except the exceptions that come as consequences
of earlier deadlocks).

Below is an example of the "polling exceptions". Could this be a
cause of deadlocks?

Regards,
Dag

2010-05-04 14:45:43 [-Processor23] <ERROR> <SOAP fault exception
trace>
hk.hku.cecid.piazza.commons.soap.SOAPFaultException: Invalid SOAP
message: Unable to create envelope from given source:
by com.sun.xml.messaging.saaj.SOAPExceptionImpl: Unable to create
envelope from given source:
by javax.xml.transform.TransformerException:
org.xml.sax.SAXParseException: Premature end of file.
by org.xml.sax.SAXParseException: Premature end of file.
at
hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAdaptor.java:
119)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(HttpDispatcher.java:
126)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doGet(HttpDispatcher.java:
266)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:627)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:
269)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:
188)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:
213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:
172)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:

433)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:
127)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:
117)
at

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:

108)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:
174)
at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
875)
at org.apache.coyote.http11.Http11BaseProtocol
$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:
665)
at

org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:
528)
at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:

81)
at org.apache.tomcat.util.threads.ThreadPool
$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Unknown Source)

Caused by: com.sun.xml.messaging.saaj.SOAPExceptionImpl: Unable to
create envelope from given source:
at
com.sun.xml.messaging.saaj.soap.EnvelopeFactory.createEnvelope(EnvelopeFactory.java:
148)
at
com.sun.xml.messaging.saaj.soap.ver1_1.SOAPPart1_1Impl.createEnvelopeFromSource(SOAPPart1_1Impl.java:
102)
at
com.sun.xml.messaging.saaj.soap.SOAPPartImpl.getEnvelope(SOAPPartImpl.java:
156)
at
hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAdaptor.java:
116)
... 19 more
Caused by: javax.xml.transform.TransformerException:
org.xml.sax.SAXParseException: Premature end of file.
at
org.apache.xalan.transformer.TransformerIdentityImpl.transform(TransformerIdentityImpl.java:
502)
at
com.sun.xml.messaging.saaj.util.transform.EfficientStreamingTransformer.transform(EfficientStreamingTransformer.java:
423)
at
com.sun.xml.messaging.saaj.soap.EnvelopeFactory.createEnvelope(EnvelopeFactory.java:
136)
... 22 more
Caused by: org.xml.sax.SAXParseException: Premature end of file.
at
com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(Unknown
Source)
at org.xml.sax.helpers.XMLFilterImpl.parse(Unknown Source)
at
org.apache.xalan.transformer.TransformerIdentityImpl.transform(TransformerIdentityImpl.java:
485)
... 24 more

[Franz Wong]

Do you mean after you restarted database and tomcat, the ack missed still coming out? Do you have any other software which connects to the database used by hermes? e.g. Some database viewer.

Currently, no known error which will cause database deadlock. I am still trying to investigate your issue. And I need more information.

1. Version of MySQL
2. Version of Hermes2 (i.e. release date)
3. Log of MySQL
4. The web service polled

Thanks.
Franz

2010/5/5 Dag Høidahl <dag.h...@gmail.com>

[Dag Høidahl]

Actually, upon closer inspection it turns out that this time it was
not an acknowledgment but an outbound message that was not sent due to
deadlock:

2010-05-04 14:46:02 [-Processor24] <INFO > <cecid.ebms.spa> <Outbound
payload received - cpaId: cpa:relacom-canaldigital.no, service:
urn:canaldigital.no:WorkOrder$1.0, serviceType:null, action:
CloseWorkOrder, convId: 3194, fromPartyId: uri:relacom.no,
fromPartyType: URI, toPartyId: uri:canaldigital.no, toPartyType: URI,
refToMessageId: null>
2010-05-04 14:46:02 [-Processor24] <INFO > <cecid.ebms.spa>
<Genereating message id: 20100504-1...@153.110.160.149>
2010-05-04 14:46:02 [-Processor24] <ERROR> <cecid.ebms.spa> <Error in
passing ebms Request to msh outbound>

hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Error in
processing outgoing message
by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing

hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1ee1602

by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing

hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@d3b095

by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at

hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessage(OutboundMessageProcessor.java:
129)
at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processOutboundMessage(MessageServiceHandler.java:
283)
at

hk.hku.cecid.ebms.spa.service.EbmsMessageSenderService.serviceRequested(EbmsMessageSenderService.java:
181)
at sun.reflect.GeneratedMethodAccessor60.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at hk.hku.cecid.piazza.commons.util.Instance.invoke(Instance.java:
158)
at
hk.hku.cecid.piazza.commons.soap.WebServicesAdaptor.processRequest(WebServicesAdaptor.java:
143)

at
hk.hku.cecid.piazza.commons.soap.SOAPHttpAdaptor.processRequest(SOAPHttpAdaptor.java:
132)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.processRequest(HttpDispatcher.java:
126)
at
hk.hku.cecid.piazza.commons.servlet.http.HttpDispatcher.doPost(HttpDispatcher.java:
277)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)

Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO::Process@1ee1602

by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing

hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@d3b095

by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at

hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
97)
at
hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO.storeOutboxMessage(MessageServerDataSourceDAO.java:
93)
at
hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.storeOutgoingMessage(OutboundMessageProcessor.java:
287)
at

hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.generateAndStoreEbxmlMessage(OutboundMessageProcessor.java:
352)
at
hk.hku.cecid.ebms.spa.handler.OutboundMessageProcessor.processOutgoingMessage(OutboundMessageProcessor.java:
111)

... 27 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing

hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO::Process@d3b095

by hk.hku.cecid.piazza.commons.dao.DAOException: Error in executing
update: INSERT INTO outbox (message_id, retried) VALUES (?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at

hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
97)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:
588)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:
548)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.executeUpdate(DataSourceDAO.java:

528)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
626)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceDAO.create(DataSourceDAO.java:
610)
at

hk.hku.cecid.ebms.spa.dao.OutboxDataSourceDAO.addOutbox(OutboxDataSourceDAO.java:

39)
at hk.hku.cecid.ebms.spa.dao.MessageServerDataSourceDAO
$2.doTransaction(MessageServerDataSourceDAO.java:89)
at

hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
89)
... 31 more

Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error in
executing update: INSERT INTO outbox (message_id, retried) VALUES
(?,?)
by hk.hku.cecid.piazza.commons.dao.DAOException: Error occurred when
executing update at row 0 of the specified parameter array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at

hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
110)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceProcess.start(DataSourceProcess.java:
89)

... 39 more
Caused by: hk.hku.cecid.piazza.commons.dao.DAOException: Error

occurred when executing update at row 0 of the specified parameter
array
by com.mysql.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
at

hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
96)
... 40 more
Caused by:

com.mysql.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock
found when trying to get lock; try restarting transaction

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:941)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:
1332)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1604)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1519)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:
1504)
at
hk.hku.cecid.piazza.commons.dao.ds.DataSourceUpdate.doTransaction(DataSourceUpdate.java:
92)

... 40 more


We do have other software connected to the ebms database. This is our
own software, which sometimes will change the state of message in the
message table in order to make Hermes resend it to the private process
if this fails. This never touches the outbox table, though.

Here is the answers to your list of information:
1. MySQL version 5.1.40-community
2. Hermes version: hermes2_installer_20090731.jar
3. Assuming you mean the <host>.err file from the MySQL data
directory, I'm mailing this to your mail address.
4. We're polling /corvus/httpd/ebms/inbound every 5 minutes to verify
that the webservice is up. Also, we're polling that URL and /corvus/
httpd/ebms/receiver_list every 15 seconds.


Thanks,
Dag

On May 5, 9:46 am, Franz Wong <franzw...@gmail.com> wrote:
> Do you mean after you restarted database and tomcat, the ack missed still
> coming out? Do you have any other software which connects to the database
> used by hermes? e.g. Some database viewer.
>
> Currently, no known error which will cause database deadlock. I am still
> trying to investigate your issue. And I need more information.
>
> 1. Version of MySQL
> 2. Version of Hermes2 (i.e. release date)
> 3. Log of MySQL
> 4. The web service polled
>
> Thanks.
> Franz

[Franz Wong]

I have setup an environment similar to yours. Unfortunately, the deadlock does not appear. Actually the outbox is not touched very frequently. I also wonder why that table is locked.

However, I would like to talk about somethings about resending a message with same message ID.

When the message with same message ID is received more than once, it will find the previously generated acknowledgment. In your case, the acknowledgment cannot be generated at the first time message received (which is not a normal case). Therefore, the acknowledgment missed problem occurs. If you want to receive that message again, you need to remove the corresponding record in message, inbox and repository table.

Franz

2010/5/5 Dag Høidahl <dag.h...@gmail.com>

Actually, upon closer inspection it turns out that this time it was

[Franz Wong]

For MySQL, there is a command "show innodb status" [1]. This command can show the information about the deadlock. I hope you can provide that information to me.

Franz

[1] http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/

[Dag Høidahl]

Last thursday we added an index to the status column in the ebms.message table. In other installations, we have found this to decrease the CPU load of MySQL by at least an order of magnitude, but we had forgotten to do it on this site.

Since introducing the index, we haven’t seen any deadlocks. Since the problem is gone for now (for good, hopefully), we don’t have anything to debug anymore.

We appreciate your help.

Regards, Dag

On 7. mai 2010, at 08:23, Franz Wong wrote:

For MySQL, there is a command "show innodb status" [1]. This command can show the information about the deadlock. I hope you can provide that information to me.

Franz

[1] http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/

On Fri, May 7, 2010 at 11:15 AM, Franz Wong <fran...@gmail.com> wrote:

I have setup an environment similar to yours. Unfortunately, the deadlock does not appear. Actually the outbox is not touched very frequently. I also wonder why that table is locked.

However, I would like to talk about somethings about resending a message with same message ID.

When the message with same message ID is received more than once, it will find the previously generated acknowledgment. In your case, the acknowledgment cannot be generated at the first time message received (which is not a normal case). Therefore, the acknowledgment missed problem occurs. If you want to receive that message again, you need to remove the corresponding record in message, inbox and repository table.

Franz

2010/5/5 Dag Høidahl <dag.h...@gmail.com>

[Ronnie Kwok]

It's good to hear that the issue is resolved.

Regards,
ronnie

2010/5/10 Dag Høidahl <dag.h...@fix.no>