Groovy Closure Execution Oddity

Question

I have a class that essentially consumes JMS messages, and then proceeds to call a closure with those messages. The message listener is running in a separate thread.

import groovy.util.logging.Slf4j
import javax.jms.*

@Slf4j
class JMSProducer {

    Connection connection
    List<Queue> queues
    private Session session
    private List<MessageConsumer> messageConsumers

    @Override
    void init() {
        connection.start()
        session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE)
        messageConsumers = queues.collect { session.createConsumer(it) }
    }

    @Override
    void produce(final Closure closure) {

        def listener = new MessageListener() {
            @Override
            void onMessage(Message message) {
                if (message instanceof ObjectMessage) {
                    try {
                        log.info("Calling");
                        closure.call(message.object);
                        log.info("Called");
                    } catch(e) {
                        log.error("Error")
                    } finally {
                        log.info("Finally");
                    }
                } else {
                    log.error("Unrecognized message")
                }
            }
        }
        messageConsumers.each {
            it.messageListener = listener
        }
    }
}

The problem I have with the above code is that I see "Calling", "Called" and "Finally" for all the messages I put into the queue, but the closure itself is only called a fraction of that.

//Assume 5 messages have been put into queue, and 
// JMSProducer has been configured to read from queue*

new JMSProducer().produce { message ->
    log.info("Received Message");        
}

The "Received Message" is only logging twice (even though I see "Calling"/"Called"/"Finally" five times each).

It's almost as if the closure is being ignored or skipped over.

When I run this inside of my IDE I do not have this problem, only when running ./gradlew clean test from the command line.

Ultimately it seems like a race condition, but I don't see how I can log before and after the closure execution, and not see logging that should occur inside of the closure.

---

As an update, I added code to log out the closure object at runtime and I'm seeing the following output (the code has been changed slightly in debugging, but the problem persists):

2016-01-12 14:56:04 INFO  JMSProducer - Calling: StreamUtil$2@1edef6f9
2016-01-12 14:56:04 INFO  JMSProducer - Calling:JMSProducerTest$_verifyJMSProducer_closure1@fa11e9d
2016-01-12 14:56:04 INFO  JMSProducer - Called
2016-01-12 14:56:04 INFO  JMSProducer - Finally
2016-01-12 14:56:04 INFO  JMSProducer - Called
2016-01-12 14:56:04 INFO  JMSProducer - Finally
2016-01-12 14:56:04 INFO  JMSProducer - Calling: StreamUtil$2@1edef6f9
2016-01-12 14:56:04 INFO  JMSProducer - Calling: JMSProducerTest$_verifyJMSProducer_closure1@fa11e9d
2016-01-12 14:56:04 INFO  JMSProducer - Called
2016-01-12 14:56:04 INFO  JMSProducer - Finally
2016-01-12 14:56:04 INFO  JMSProducer - Called
2016-01-12 14:56:04 INFO  JMSProducer - Finally
2016-01-12 14:56:04 INFO  JMSProducer - Calling: JMSProducerTest$_verifyJMSProducer_closure1@fa11e9d
2016-01-12 14:56:04 INFO  JMSProducer - Called
2016-01-12 14:56:04 INFO  JMSProducer - Finally

It looks like callback isn't the same thing consistently. And only when I get StreamUtil$2@1edef6f9 is the callback executing.

Answer 1

Okay, so apparently there was a race condition in JMS, and a previous test was was somehow able to override the message listener (but only for a portion of the iterations). Not entirely certain how that occurred, but is something to do with asynchronous tests and JUnit.