Strange behaviour of MDB and EJB

[Amit M Tank]

Hi,

I have an MDB that calls a Stateless Session bean , the Stateless session bean has Transaction attribute of Not Supported. The onMessage() of the MDB calls Stateless SB method that takes lot of time to perform. There are no errors thrown in the MDB and Session Bean but the same message gets redelivered to the Queue and is relayed back to the MDB. I did a small POC and I am able to replicate the issue. But I don't have any clue how to fix this issue.



Here is the code of MDB

import javax.annotation.Resource;
import javax.ejb.ActivationConfigProperty;
import javax.ejb.EJB;
import javax.ejb.MessageDriven;
import javax.ejb.MessageDrivenContext;
import javax.ejb.TransactionAttribute;
import javax.ejb.TransactionAttributeType;
import javax.ejb.TransactionManagement;
import javax.ejb.TransactionManagementType;
import javax.jms.Message;
import javax.jms.MessageListener;

import weblogic.javaee.TransactionTimeoutSeconds;

@MessageDriven(activationConfig = { @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue") }, mappedName = "DBLOCK.Queue")
@TransactionManagement(TransactionManagementType.CONTAINER)
@TransactionAttribute(TransactionAttributeType.REQUIRED)
@TransactionTimeoutSeconds(200)
public class ProcessMessage implements MessageListener {

  private static final Logger LOGGER = LoggerHelper
  .getLogger(ProcessMessage.class);
  
  @EJB
  private StateLessSessionLocal stateLessSessionLocal;
  
  @Resource
  private MessageDrivenContext context = null;
  
  @Override
  public void onMessage(Message arg0) {
    // TODO Auto-generated method stub
    long time = System.currentTimeMillis();
    if (LOGGER.isLoggable(Level.FINEST)) 
      LOGGER.finest("In the onMessage of ProcessMessage:");
    
    stateLessSessionLocal.timePass();

    
    if (LOGGER.isLoggable(Level.FINEST)) {
      LOGGER.finest("### Completed onMessage of ProcessMessage: ###" + (System.currentTimeMillis() - time));
    }
      
    
    
  }

}

Here is the code of Stateless Session Bean

import javax.annotation.Resource;
import javax.ejb.EJBContext;
import javax.ejb.Local;
import javax.ejb.MessageDrivenContext;
import javax.ejb.SessionContext;
import javax.ejb.Stateless;
import javax.ejb.TransactionAttribute;
import javax.ejb.TransactionAttributeType;
import javax.ejb.TransactionManagement;
import javax.ejb.TransactionManagementType;




@Local(StateLessSessionLocal.class)
@Stateless(name = "StateLessSessionBean", mappedName = "StateLessSessionBean")
@TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED)
@TransactionManagement(TransactionManagementType.CONTAINER)
public class StateLessSessionBean {
  
  private static final Logger LOGGER = LoggerHelper
  .getLogger(StateLessSessionBean.class);
  
  
  @Resource
  private SessionContext context = null;
  
  public void timePass() {
    try {
      long time = System.currentTimeMillis();
      if (LOGGER.isLoggable(Level.FINEST)) 
        LOGGER.finest("In the timePass of StateLessSessionBean:");
      Thread.sleep(600000);
      if (LOGGER.isLoggable(Level.FINEST)) 
        LOGGER.finest("completed timePass of StateLessSessionBean:" + (System.currentTimeMillis() - time));
    } catch (Exception e) {
      
    }
  }

}

[H Paul]

1.

@TransactionManagement(TransactionManagementType.CONTAINER)   
@TransactionAttribute(TransactionAttributeType.REQUIRED)   
@TransactionTimeoutSeconds(200)  

If the MDB is Container type, should it not has the server/EJB container transaction timeout?
Is @TransactionTimeoutSeconds(200) a weblogic way to override the server side?

2.
Basically, I did a simple experiment like your with trial RAD 7: MDB call SLB that has Thread.sleep(200000) in it;
and observed in log (I have log, check your server log). I noticed the message was redelivered 5 times. (because it was configured 5 times for re-delivery on RAD server side)
BUT then if you restart the EJB Listerner again, JMS Provider will continue to deliver that same message.
Why? (see the articles/links I mentioned below.)

When I set Thread.sleep(120000) in SLSB, it was re-delivered only 2 times and that'all.
When I set Thread.sleep(110000) in SLSB, there is NO issue.


Unless, I misread the log, here is what I understand:

1. JMS Provider ----->jms message----->EJB container/AppSrv---jms message + timeout period----> MDB -----> SESSION BEAN (can take whatever it takes)

2. There is a transaction time out between EJB container/server and the MDB (Here is the issue. The default value for MDB on RAD is 120s)

[8/26/11 17:10:02:515 PDT] 00000004 TimeoutManage I   WTRN0006W: Transaction 00000132089088D30000000200000005B96D83ED5F33E3DB3212CA0FDFAFE7F4FFBEFE6900000132089088D30000000200000005B96D83ED5F33E3DB3212CA0FDFAFE7F4FFBEFE6900000001 has timed out after 120 seconds.
[8/26/11 17:10:02:515 PDT] 00000004 TimeoutManage I   WTRN0124I: When the timeout occurred the thread with which the transaction is, or was most recently, associated was Thread[SIBJMSRAThreadPool : 0,5,main]. The stack trace of this thread when the timeout occurred was: 
	java.lang.Thread.sleep(Native Method)
	java.lang.Thread.sleep(Thread.java:850)
	test.ejb.SLBSession.executeBL(SLBSession.java:24)
	test.ejb.MDBListener.onMessage(MDBListener.java:35)
	com.ibm.ejs.container.MessageEndpointHandler.invokeMdbMethod(MessageEndpointHandler.java:1092)
	com.ibm.ejs.container.MessageEndpointHandler.invoke(MessageEndpointHandler.java:777)
	$Proxy29.onMessage(Unknown Source)
	com.ibm.ws.sib.api.jmsra.impl.JmsJcaEndpointInvokerImpl.invokeEndpoint(JmsJcaEndpointInvokerImpl.java:233)
	com.ibm.ws.sib.ra.inbound.impl.SibRaDispatcher.dispatch(SibRaDispatcher.java:887)
	com.ibm.ws.sib.ra.inbound.impl.SibRaSingleProcessListener$SibRaWork.run(SibRaSingleProcessListener.java:527)
	com.ibm.ejs.j2c.work.WorkProxy.run(WorkProxy.java:399)
	com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1527)
	

3. After timeout occured, EJBcontainer give back the same message to JMS Provider.

4. As long as JMS Provider has message it deliver to EJB container who in turn give it to MDB
and the loop continue as long as N times ( 5 times in my test because it was configured 5)
Unless instructed otherwise -configuration setting- , JMS Provider will continue to deliver that same message
to EJB container.

Now try :
1. increase transaction time out at EJB container/server level OR at specific MDB level (Bean level)
what is the max then? depends on how long your SLSB take? play with these values

2. OR review the logic in SLSB or re-design the flow to decrease the time it take to finish.

3. OR do more re-search in term of all the configuration settings at Queue/JMS Provider and/or EJB container and/or MDB
to see which value can influence the outcome.

4. OR there is more for which I do not know...

BTW: while doing the experiment, I found an article about this issue but it's for IBM websphere
but the key concept should be similar in your web logic server/JMS provider. Check if it has these settings and play with it.

How WebSphere Application Server V6 handles poison messages

http://www.ibm.com/developerworks/websphere/library/techarticles/0803_titheridge/0803_titheridge.html
and this Programming WebLogic JMS which is your case ( I have not read it)

http://download.oracle.com/docs/cd/E13222_01/wls/docs100/jms/manage_apps.html#1234674

Go luck to you.

Edit: forgot to include Experiment code + log

MDB

    public void onMessage(Message message) {
        // TODO Auto-generated method stub
        System.out.println("onMessage called");
        new SLBSession().executeBL(message.toString()); 
        System.out.println("onMessage exit");
    }

SLSB
	public void executeBL(String string) {
		// TODO Auto-generated method stub
        System.out.println("executeBL called" + string);
        try {
			Thread.sleep(200000);
		} catch (InterruptedException e) {
			// TODO Auto-generated catch block
			e.printStackTrace();
		}
	}


Log observed:

  
[8/26/11 17:08:02:515 PDT] 00000020 SystemOut     O onMessage called     <<<<<<<<<<<<
[8/26/11 17:08:02:515 PDT] 00000020 SystemOut     O executeBL called

  JMSRedelivered:   true                        <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    JMSXDeliveryCount: 5			<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    JMSXAppID: Service Integration Bus
    JMS_IBM_System_MessageID: 4AF613B50EC12A29_5000003
    JMSXUserID: 
#### JMS Example Running #####
[8/26/11 17:10:02:515 PDT] 00000004 TimeoutManage I   WTRN0006W: Transaction 00000132089088D30000000200000005B96D83ED5F33E3DB3212CA0FDFAFE7F4FFBEFE6900000132089088D30000000200000005B96D83ED5F33E3DB3212CA0FDFAFE7F4FFBEFE6900000001 has timed out after 120 seconds.
[8/26/11 17:10:02:515 PDT] 00000004 TimeoutManage I   WTRN0124I: When the timeout occurred the thread with which the transaction is, or was most recently, associated was Thread[SIBJMSRAThreadPool : 0,5,main]. The stack trace of this thread when the timeout occurred was: 
	java.lang.Thread.sleep(Native Method)
	java.lang.Thread.sleep(Thread.java:850)
	test.ejb.SLBSession.executeBL(SLBSession.java:24)
	test.ejb.MDBListener.onMessage(MDBListener.java:35)
	com.ibm.ejs.container.MessageEndpointHandler.invokeMdbMethod(MessageEndpointHandler.java:1092)
	com.ibm.ejs.container.MessageEndpointHandler.invoke(MessageEndpointHandler.java:777)
	$Proxy29.onMessage(Unknown Source)
	com.ibm.ws.sib.api.jmsra.impl.JmsJcaEndpointInvokerImpl.invokeEndpoint(JmsJcaEndpointInvokerImpl.java:233)
	com.ibm.ws.sib.ra.inbound.impl.SibRaDispatcher.dispatch(SibRaDispatcher.java:887)
	com.ibm.ws.sib.ra.inbound.impl.SibRaSingleProcessListener$SibRaWork.run(SibRaSingleProcessListener.java:527)
	com.ibm.ejs.j2c.work.WorkProxy.run(WorkProxy.java:399)
	com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1527)

[8/26/11 17:11:22:515 PDT] 00000020 SystemOut     O onMessage exit      <<<<<<<<<<<<<<<