ERROR: Unhandled Exception in event router

[AVERRI]

Dear members,

I'm getting the following error when processing SMS messages:

10:00:41,301 ERROR [EventRouterImpl] Unhandled Exception in event
router:
javax.transaction.SystemException: Failed to commit tx.
[com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted]
[com.arjuna.ats.interna
l.jta.transaction.arjunacore.commitwhenaborted] Can't commit because
the transaction is in aborted state
at
org.mobicents.slee.runtime.transaction.TransactionManagerImpl.commit
(TransactionManagerImpl.java:352)
at org.mobicents.slee.runtime.EventRouterImpl.routeQueuedEvent
(EventRouterImpl.java:1111)
at org.mobicents.slee.runtime.EventRouterImpl.access$100
(EventRouterImpl.java:64)
at org.mobicents.slee.runtime.EventRouterImpl$EventExecutor.run
(EventRouterImpl.java:121)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask
(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)

I'm using:

- Mobicents v1.2.6.GA;
- SMPP RA v1.2.6.GA;
- My custom SBB (please, see bellow);
- SMPPSim v2.6 (to simulate SMSC);

The scenario is simple: The SBB process an external custom event,
sends a SMS and process it's response.

This error is causing the loss of SUBMIT_SM_RESPONSE events.

Please, I need help to understand the mentioned exception.

Regards,
A. Verri

[Bartosz Baranowski]

Is there any other exception shown in console?

--
Bartosz Baranowski
JBoss R & D
==================================
Word of criticism meant to improve is always step forward.

[AVERRI]

Hi Bartosz,

There aren't other exceptions in console. But I've noticed that there
is a WARN message in console regarding arjuna:

09:40:05,040 WARN [loggerI18N]
[com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.startupWarning]
[com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.startupWarning]
You have chosen to enable multiple last resources in the transaction
manager. This is transactionally unsafe and should not be relied upon.



BTW, sorry, I forget to print my custom SBB code:

#########################################################
SmppProcessorSBB
#########################################################


package br.com.sixbell;

import br.com.sixbell.gateway.smpp.SmsMessageEvent;
import java.io.IOException;
import javax.jms.Connection;
import javax.jms.ConnectionFactory;
import javax.jms.Destination;
import javax.jms.JMSException;
import javax.jms.MessageProducer;
import javax.jms.ObjectMessage;
import javax.jms.Session;
import javax.naming.Context;
import javax.naming.InitialContext;
import javax.naming.NamingException;
import javax.slee.ActivityContextInterface;
import javax.slee.RolledBackContext;
import javax.slee.Sbb;
import javax.slee.SbbContext;
import javax.slee.CreateException;
import javax.slee.serviceactivity.ServiceActivity;
import javax.slee.serviceactivity.ServiceActivityFactory;
import javax.slee.serviceactivity.ServiceStartedEvent;

import net.java.slee.resource.smpp.ShortMessage;
import net.java.slee.resource.smpp.SmppProvider;
import net.java.slee.resource.smpp.ActivityContextInterfaceFactory;

import net.java.slee.resource.smpp.ClientTransaction;
import net.java.slee.resource.smpp.Dialog;
import net.java.slee.resource.smpp.ResponseEvent;
import org.apache.log4j.Logger;


/**
* This class is responsible for processing SMS events.
* @author averri
*/
public abstract class SmppProcessorSBB implements Sbb {

private static Logger log = Logger.getLogger
(SmppProcessorSBB.class);

private static final String SMS_DELIVERED_QUEUE_NAME = "queue/sms-
delivered";

private SbbContext sbbContext;

private SmppProvider smppProvider;

private ActivityContextInterfaceFactory smppAcif;

private ConnectionFactory connectionFactory;

public SmppProcessorSBB() {
}// end constructor

/**
* Sends a JMS message to the queue.
*/
public void sendJmsMessage(long messageId, boolean success) {

MessageProducer msgProducer = null;
Session session = null;
Connection conn = null;

try {
conn = connectionFactory.createConnection();
session = conn.createSession(false,
Session.AUTO_ACKNOWLEDGE);
Destination destination = (Destination) new InitialContext
()
.lookup(SMS_DELIVERED_QUEUE_NAME);

msgProducer = session.createProducer(destination);
ObjectMessage msg = session.createObjectMessage();

msg.setLongProperty("smsId", getSmsId());
msg.setBooleanProperty("success", success);

msgProducer.send(msg);

log.info("### Message sent to the queue. smsId=" +
messageId);

} catch (Exception ex) {
log.error("### Could not send JMS. smsId=" + messageId,
ex);

} finally {
try {
if(msgProducer!=null) {
msgProducer.close();
}
} catch (JMSException ex) {
log.warn("### Could not close message producer.", ex);
}
try {
if(session!=null) {
session.close();
}
} catch (JMSException ex) {
log.warn("### Could not close session.", ex);
}
try {
if(conn!=null) {
conn.close();
}
} catch (JMSException ex) {
log.warn("### Could not close connection.", ex);
}
}// end finally

}// end method

/**
*
* @param sbbContext
*/
public void setSbbContext(SbbContext sbbContext) {
this.sbbContext = sbbContext;
try {
Context env = (Context) new InitialContext();

smppProvider = (SmppProvider) env.lookup(
"java:comp/env/slee/resources/smpp/3.4/
smppinterface");

smppAcif = (ActivityContextInterfaceFactory) env.lookup(
"java:comp/env/slee/resources/smpp/3.4/
factoryprovider");

connectionFactory = (ConnectionFactory) env.lookup
("ConnectionFactory");

//timerFacility = (TimerFacility) myEnv.lookup("slee/
facilities/timer");

} catch (NamingException ne) {
log.fatal("### Could not set SBB context:", ne);
}
log.trace("### setSbbContext");
}// end method

/**
* Called when this service has started.
* @param event
* @param aci
*/
public void onServiceStartedEvent(ServiceStartedEvent event,
ActivityContextInterface aci) {

try {
Context env = (Context) new InitialContext().lookup
("java:comp/env");

ServiceActivity sa = ((ServiceActivityFactory) env.lookup(
"slee/serviceactivity/factory")).getActivity();

if (sa.equals(aci.getActivity())) {
log.info("### SBB Started.");
}

} catch (Exception ex) {
log.error("### onServiceStartedEvent failed.", ex);
}

}// end method

/**
* Event handler for externally triggered event.
* @param event
* @param aci
*/
public void onSendSms(SmsMessageEvent msgEvent,
ActivityContextInterface aci) {
log.trace("### onSendSms captured.");
setSmsId(msgEvent.getMessageId());
sendSms(msgEvent);
}// end method

/**
* Event handler for SUBMIT_SM message reply (from SMSC).
* @param response
* @param aci
*/
public void onSubmit_sm_resp(ResponseEvent response,
ActivityContextInterface aci) {
log.info("### SUMBIT_SM_RESP smsId=" + getSmsId());
boolean success = (response.getMessage().getStatus()==0) ?
true : false;
sendJmsMessage(getSmsId(), success);
//aci.detach(sbbContext.getSbbLocalObject());
}// end method

/**
* Send a SMS to the SMSC binded to the smppProvider.
*/
public void sendSms(SmsMessageEvent msgEvt) {

Dialog dialog = smppProvider.getDialog("4477665544", "0020");
ShortMessage sms = dialog.createMessage();
sms.setText(msgEvt.getContent());

//sms.setOriginator("2188114364");
//sms.setRecipient("2181370588");

ClientTransaction tx = dialog.createSubmitSmTransaction();

try {
ActivityContextInterface ac =
smppAcif.getActivityContextInterface(tx);
ac.attach(sbbContext.getSbbLocalObject());

} catch (Exception ex) {
log.error("### SUMBIT_SM fails for smsId=" +
msgEvt.getMessageId(), ex);
return;
}

try {
tx.send(sms);
log.info("### SUMBIT_SM smsId=" + msgEvt.getMessageId());

} catch (IOException ex) {
log.error("### Could not send smsId=" + msgEvt.getMessageId
(), ex);
}
}// end method

public abstract void setSmsId(long value);

public abstract long getSmsId();

}// end class

[Vicky Kak]

Just read this one
http://www.jboss.org/community/wiki/Multiple1PC

It seems that your SBB code is trying to enlist multiple one phase participants which could be possible when your sbb code is trying to get multiple DB connections via JCA datasource of type local-tx-datasource, it is unsafe and the referenced article explains the reason.

PS: I have not looked at the code details

-Vicky

[AVERRI]

Vicky,

thank you for information.

Unforturnately, changing the transactional behavior (putting
allowMultipleLastResources=NO, in jbossjta) did not solve the problem.

I did a sample test: from 2000 SMS sent by my custom SBB, the RA could
process 1962 replies from SMSC. This represents 1,9% of loss.

Anybody has another tip? How can we debug it?

Regards,
A. Verri


On Oct 9, 2:14 pm, Vicky Kak <vicky....@gmail.com> wrote:
> Just read this onehttp://www.jboss.org/community/wiki/Multiple1PC

>
> It seems that your SBB code is trying to enlist multiple one phase
> participants which could be possible when your sbb code is trying to get
> multiple DB connections via JCA datasource of type local-tx-datasource, it
> is unsafe and the referenced article explains the reason.
>
> PS: I have not looked at the code details
>
> -Vicky
>

[AVERRI]

Dear members,

At the moment, I didn't find any response to the problem I exposed.

How can I execute the 'sendJmsMessage' method inside a new
transaction?

Regards,
A. Verri

[Vicky Kak]

It should be allowMultipleLastResources=YES and not no.

Vicky

[AVERRI]

Dear Vicky,

I've changed the allowMultipleLastResources to 'YES'.

The problem still persists.

What is going wrong? Could someone please check my SBB code to see if
there is something wrong?

I think that it is a bug with SMPP RA.

[aayush]

For isolating the jms related code in a different transaction,

lookup the transaction manager like this: tm = (TransactionManager)
new InitialContext().lookup("java:/TransactionManager");

and encapsulate the jms code between calls to tm.begin() and tm.commit
().

Another way can be to delegate the jms code to a child sbb and make
sbb local object calls to it. IIRC, all calls on the sbblocal object
are mandatory transactional methods handled by the container.

aayush.

[Bartosz Baranowski]

On Sun, Oct 11, 2009 at 4:43 AM, aayush <abhatnag...@gmail.com> wrote:

For isolating the jms related code in a different transaction,

lookup the transaction manager like this: tm = (TransactionManager)
new InitialContext().lookup("java:/TransactionManager");

and encapsulate the jms code between calls to tm.begin() and tm.commit
().

I strngly doubt that this will work, since all Sbb calls are transactional. I think this problem surfaced long time ago and it can be solved with some xml tweak for tx manager. Not sure what was the trick but it should be in google, will try to look it up if there is no sollution by monday :)

Another way can be to delegate the jms code to a child sbb and make
sbb local object calls to it.  IIRC, all calls on the sbblocal object
are mandatory transactional methods handled by the container.

indeed. 

aayush.

On Oct 11, 6:32 am, AVERRI <alexandreve...@gmail.com> wrote:
> Dear Vicky,
>
> I've changed the allowMultipleLastResources to 'YES'.
>
> The problem still persists.
>
> What is going wrong? Could someone please check my SBB code to see if
> there is something wrong?
>
> I think that it is a bug with SMPP RA.

[aayush bhatnagar]

where to perform that tweak ? somewhere in jboss as ?

--
aayush
======
http://www.linkedin.com/in/abhatnagar19

[aayush bhatnagar]

Bartosz, maybe we can consider re-opening this issue here for this problem: http://code.google.com/p/mobicents/issues/detail?id=30

I also face this error sometimes, but it happens suddenly without any warning..so cant predict it. But it definitely makes the call fail. I faced this error it in my applications as well as in MSPS. 

[AVERRI]

Dear members,

the problem I mentioned occurs even if you remove the JMS code from
SBB event handler method.

I've noticed that the more concurrency, the more exceptions.

For example, the event handler bellow is not getting invoked due the
related exception.

###########################################
SBB code fragment
###########################################

/**
* Event handler for SUBMIT_SM message reply (from SMSC).
* @param response
* @param aci
*/
public void onSubmit_sm_resp(ResponseEvent response,
ActivityContextInterface aci) {
log.info("### SUMBIT_SM_RESP smsId=" + getSmsId());

}// end method

[AVERRI]

Hi,

At the moment, the problem still persists. It looks like a ghost.

I've found a related thread on java.net:

http://forums.java.net/jive/message.jspa?messageID=259549

Dear members, let's catch the ghost.

[aayush bhatnagar]

the ghost is this old issue on the issue tracker:  http://code.google.com/p/mobicents/issues/detail?id=30

[AVERRI]

Dear members,

I've found that the problem could be related to the transaction ID
generation algorithm, used by SMPP RA.

For example, consider the "SmppDialogImpl.class", the line 134 is
using a simple static variable "GENERATOR++" to generate transaction
ids. The problem is that the post increment operation is not atomic
and I didn't find any synchronization on the code that use it. If two
different transactions has the same id so we are in trouble.

[AVERRI]

I've recompiled the SMPP RA but the problem still persists.

[aayush bhatnagar]

I think its more of  the SLEE container problem. 

The SMPP RA is dealing with the transactions at the protocol level (SMPP transactions). While the error we are getting is related to JBOSS's JAVA transactions. 

[AVERRI]

Hi Bartosz,

unfortunately, there is no solution at this time. Could you please
help us to look up for the mentioned trick?

Regards,
A.Verri

On Oct 11, 11:15 am, Bartosz Baranowski <baran...@gmail.com> wrote:

[Bartosz Baranowski]

Sorry. A bit sick here
Googled for known issues we had. And there was actually something similar. It should be solved by what Vicky posted.
Actaully one of our examples requries it to run: http://groups.google.com/group/mobicents-public/web/converged-application-demo?version=7

Aayush: [pssobily we should, I will contact someone keen on jta in jboss, maybe he can answer. Since issue 30 we did not face this kind of behaviour. I have debuged this code. What happens is that TX goes suddenly to commited state. even though it did not reach "commit()"

[aayush bhatnagar]

On Wed, Oct 14, 2009 at 14:28, Bartosz Baranowski <bara...@gmail.com> wrote:

Sorry. A bit sick here

Take care and get well soon ! 

[AVERRI]

Is it possible to update the JBossJTA for Mobicents v1.2.6.GA ???

[Bartosz Baranowski]

Mobicents is built on top of jboss. So whatever You change in jboss should work - unless API changes.

[AVERRI]

I've tried to update JBossJTA, without success.

The tested versions was:
jboss-jta-4.3.0.GA
jboss-jta-4.4.0.GA

I've changed the files jbossjta.jar and jbossjta-integration.jar,
located at JBOSS_HOME/server/default/lib. The JBoss didn't start with
this approach.

I'm still looking for a solution to this BIG problem.

Regards,
A. Verri

On Oct 14, 4:54 pm, Bartosz Baranowski <baran...@gmail.com> wrote:
> Mobicents is built on top of jboss. So whatever You change in jboss should
> work - unless API changes.
>

[gabriel]

Hi everybody, and Verri, did you solve the problem? I have a similar
one...
When I send a submit_sm and previously attach it to the activity
context, as the
examples shows:
...
ActivityContextInterface ac = smppAcif.getActivityContextInterface
(tx);
ac.attach(sbbContext.getSbbLocalObject());
...
tx.send(sms);
...

I get the following error:

09:10:31,384 INFO [XACacheXAManager] Failed to commit XACache writes
in tx[TransactionImple < ac, BasicAction: 7f000101:c2c5:4b177098:35e
status: ActionStatus.COMMITTING >.
Reason: Entry version verification failed for Map[runtimeCache-
activitycontext:583c10bfdbd326ba:-270543d0:125538fcf5a:-7f77].
Reason: Committing entry is not newer version than the actual entry's
version.
entry key[acState]
committing entry version[0]
committing entry value[Active Activity Context]
actual entry version[1].
actual entry value[Ending Activity Context]
09:10:31,389 WARN [loggerI18N]
[com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror]
[com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror]
XAResourceRecord.commit - xa error XAException.XA_HEURRB
09:10:31,562 WARN [arjLoggerI18N]
[com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4]
TwoPhaseCoordinator.afterCompletion - returned failure for
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@1181a6d
09:10:31,564 ERROR [EventRouterImpl] Unhandled Exception in event
router:
javax.transaction.SystemException: Failed to commit tx. null

The problem is that the error happen randomly. I have googled a lot
but I just found this thread:
http://forums.java.net/jive/thread.jspa?messageID=301533
talking about it, I tried the solution given but the problem still
happen.
When I do not attach anything (do not use
smppAcif.getActivityContextInterface(tx);) everything works fine.

Thanks in advance and any help will be great.

Regards,
Gabriel.

[Eduardo Martins]

Try 2.0.0.BETA2 :-)

-- Eduardo

-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-:-
http://emmartins.blogspot.com
http://www.redhat.com/solutions/telco