2

Our application, running in a WebLogic 12c, is retrieving messages from a queuing system, where the queue we are retrieving messages from is configured as a FIFO. We are using Spring to configure the retrieval functionality and both the container (org.springframework.jms.listener.DefaultMessageListenerContainer) and the messages listener (org.springframework.jms.core.support.JmsGatewaySupport) are singletons. Furthermore, that container has configured a WorkManager by default as task executor. To guarantee that the messages are processed in the expected order (the order how they are sent to the queue), we use a ReentrantLock in the listener, and we were expecting that messages were retrieved and processed one by one. The listener code is the following one:

public class JmsReceiveAdapterImpl extends JmsGatewaySupport implements SessionAwareMessageListener {
    private final ReentrantLock lock = new ReentrantLock(true);
    [...]
    public void onMessage(Message rcvMessage, Session session) throws JMSException {
        lock.lock();
        logger.warn("Lock has been acquired by thread: " + Thread.currentThread().getId());
        try {
            [...]
        } finally {
            logger.warn("Lock is going to be released by thread: " + Thread.currentThread().getId());
            lock.unlock();
        }
    }
}

Even though two messages are placed on the queue in the correct order, and they are consumed in that order (recall that the queue is a FIFO one), somehow the two message are processed in parallel by the application as it is shown in the following log chunk:

    Lock has been acquired by thread: 28
    Backout count: 1
    Message 1 / 1 received from XXX Message ID1 received.
    Lock has been acquired by thread: 54 
    Backout count: 1
    Message 1 / 1 received from XXX Message ID2 received.
    ***** ERROR *****
    Lock is going to be released by thread: 54
    Lock is going to be released by thread: 28

Why are we obtaining this behaviour? Any idea?

Thank you so much in advanced.

Vince
  • 14,470
  • 7
  • 39
  • 84
Marcos Antonio
  • 83
  • 1
  • 8
  • 7
    Considering that the chance that `ReentrantLock` is not working are close to zero, I would suggest you to output `this` to the log, to reassure that your class is a singleton. – user3707125 Jun 18 '15 at 15:54
  • 1
    Also check that you don't invoke `await()` on some conditions created from this lock. – talex Jun 18 '15 at 16:14
  • You could make the lock static if you want to be absolutely sure, but from a design perspective that would be a disaster – Yosef Weiner Jun 18 '15 at 17:08
  • You ought to use logger.debug() instead of logger.warn(). If you chose warn() because debug() messages aren't showing up in your log, then it might be worth your while to learn how to configure log4j: https://logging.apache.org/log4j/2.x/manual/configuration.html – Solomon Slow Jun 18 '15 at 19:09
  • Thanks to all of you. user3707125: I'm going to check that the listener is a singleton and no more than one instance is alive in the application. talex: No, await() is not invoked anywhere. SkinnyJ: It is something I would use as a last resource. James: In fact, the logger is a custom one which I have adapted to be displayed in the post for privacy reasons. Perhaps that has provoke the confusion. Anyway, thanks for your link. – Marcos Antonio Jun 18 '15 at 20:19

1 Answers1

3

Change 

logger.warn("Lock has been acquired by thread: " + Thread.currentThread().getId());

To 

logger.warn("Lock has been acquired by thread: " + Thread.currentThread().getId() + " And Object " + System.identityHashCode(this));

What you are going to probably see is that the System.identityHashCode will be two different numbers. If it were the same object the identityHashCode would be identical. If they are different, that means they are different objects.

What that tells you is that there are more than one ReentrantLock instance and will not support mutual exclusion on the difference instances.

John Vint
  • 39,695
  • 7
  • 78
  • 108