"Duplicate throwable nesting" warnings

[caissa]

Hi,

I am getting the following warnings in my jboss server.log, and was wondering if someone can suggest ways of tracking down the problem. The warnings are:

WARN [org.jboss.util.NestedThrowable] Duplicate throwable nesting of same base type: class org.jboss.mq.SpyJMSException is assignable from: class org.jboss.mq.SpyJMSExeption

Here's what I am doing:

I have a Stateless Session Bean sending messages to a topic. Before it sends a message, it creates a temporary topic, for use as a synchronous reply (using setJMSReplyTo()). It creates a replyReceiver (subscriber) to the temporary topic, publishes the message and then waits for replies on the temporary topic (using replyTopic.receive(timeout)). If it gets what it expects, it repeats the process after closing the replyReceiver and deleting the temporary topic.

The SLSB method creates a single TopicConnection and TopicSession, sends N messages as above, then closes the Session/Connection. I am using the "ConnectionFactory" factory and the method that sends the messages is marked "NotSupported" for transactions.

Frankly, the warnings are the only problem; the messages are sent fine, the replies on the temp topics are received fine, but when I close the TopicConnection, I get N warnings (one per message sent).

I have turned on TRACE debugging for org.jboss.mq and org.jboss.jms, but there is no JBoss debug output once I am sending messages (I see lots of mq debug during startup, etc.). The only mq debug I get is before I send a message and then again after the warnings:

DEBUG [org.jboss.mq.security.SecurityManager] No SecurityMetadata was a vailable for JMS_TT4 using defauly security config

[then I get my own debug, send/receive, etc., getting ready to close topic connection]
[then the warnings]
[topic connection successfully closed]

DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run()
DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run()
DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up

I am using jboss 3.2.6 on RedHat AS3.0, with MySql 4.0.16 for persistence, and UIL2 (obviously).

What does the warning mean exactly? I am catching all JMSExceptions, so if there's a SpyJMSException shouldn't I be getting it? Clearly I am doing something wrong, but I am having trouble getting more info. Any help would be much appreciated! I can post code snippets if necessary, but I don't have a standalone test case, alas.

Thanks!

[caissa]

Well, I found my own solution.

First, I didn't have TRACE logging enabled correctly; all I was getting was DEBUG. In addition to adding the category tags for org.jboss.mq, etc. in the log4j.xml (as noted in the FAQ) I also had to comment out the Threshold tag in my file appender section (setting it to TRACE didn't work...I obviously don't really grok log4j.). Now I could see the exceptions.

During the topicConnection.close() method JBoss was trying to delete the temporary topics. But, trying to be a good citizen, I had already deleted them myself after each send/receive, and so it was throwing an exception because there were no destinations for it to delete. This seemed a little odd to me because, a) my deletes didn't fail so I would assume JBoss would recognize that they are gone, and b) the exceptions were completely hidden by the warnings -- they were only visible with trace logging on! Not sure how useful that is, but I guess the important part was that something was deleting the topics, so the warnings were just that.

Anyway, I simply commented out my deletes, letting JBoss take care of it, and now all is well. No more warnings.

Frankly, I suspect that I am misusing JMS here, anyway (using asynchronous messaging for a synchronous purpose) and so will be looking into switching this out for JMX remoting or straight RMI sometime in the future. Still, it works for now.

Cheers!

[adrian.brock]

The warning is for the developers. It says there is unnecessary wrapping
of exceptions. something like the following, but obviously not as direct:
throw new SpyJMSException(new SpyJMSException...)

What does the logged exception look like?

What does your code look like for the deletes?

Are you sure you are not trying to delete the temporary before
you closed the consumer that was trying to receive from it?

[caissa]

What does the logged exception look like?

Well, the patch is out already so I'll have to fat-finger in what I have from a hard copy. I suspect you'll actually need more than this, but here is the first bit:

2005-02-13 14:28:54,660 TRACE [org.jboss.mq.Connection] DeleteDestination dest=TOPIC.JMS_TT3 Connection@22270043[token=ConnectionToken:ID:8/50a5cd14262170cc7fd80d5d5edf8b36 rcvstate=STOPPED]
2005-02-13 14:28:54,660 TRACE [org.jboss.mq.TracingInterceptor] CALLED : deleteTemporaryDestination
2005-02-13 14:28:54,660 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : TOPIC_JMS_TT3
2005-02-13 14:28:54,661 TRACE [org.jboss.mq.TracingInterceptor] EXCEPTION : deleteTemporaryDestination:
javax.jms.InvalidDestinationException: That destination does not exist! null
at org.jboss.mq.server.JMSDestinationManager.deleteTemporaryDestination(JMSDestinationManager.java:724)
at org.jboss.mq.server.JMSServerInterceptorSupport.deleteTemporaryDestination(JMSServerInterceptorSupport.java:174)
at org.jboss.mq.security.ServerSecurityInterceptor.deleteTemporaryDestination(ServerSecurityInterceptor.java:217)
at org.jboss.mq.server.TracingInterceptor.deleteTemporaryDestination(TracingInterceptor.java:405)
at org.jboss.mq.server.JMSServerInvoker.deleteTemporaryDestination(JMSServerInvoker.java:174)
at org.jboss.mq.il.jvm.JVMServerIL.deleteTemporaryDestination(JVMServerIL.java:177)
at org.jboss.mq.Connection.deleteTemporaryDestination(Connection.java:490)
at org.jboss.mq.SpyTemporaryTopic.delete(SpyTemporaryTopic.java:69)
at org.jboss.resource.adapter.jms.JmsSessionFactoryImpl.close(JmsSessionFactoryImpl.java:300)

What does your code look like for the deletes?

Are you sure you are not trying to delete the temporary before
you closed the consumer that was trying to receive from it?

Well, my SessionBean creates the conection and then the session, and passes the session to a helper object (POJO). This object essentially does the following:

TemporaryTopic replyTopic = null;
TopicSubscriber replyReceiver = null;
try {
 replyTopic = topicSession.createTemporaryTopic();
 replyReceiver = topicSession.createSubscriber(replyTopic);

 // Set replyTopic as the JMSReplyTo for the original message
 // and publish it to the main topic (code not shown)

 // Wait for the first reply
 Message replyMsg = replyReceiver.receive(timeout1);
 // Process first reply

 // Assuming first reply was ok, wait for the second reply
 replyMsg = replyReceiver.receive(timeout2);
 // Process second reply

} catch (...) {
} finally {
 try {
 if (replyReceiver != null) {
 replyreceiver.close();
 }
 if (replyTopic != null) {
 replyTopic.delete();
 }
 } catch (JMSException e) {
 // log, etc.
 throw e;
 }
}

Once this method completes, we close the publisher (for the main topic) and then close the session and finally the connection, all in my SLSB. Does this seem reasonable?

[adrian.brock]

Your code is reasonable.

I have raised this a "bug" report.
http://jira.jboss.com/jira/browse/JBAS-1485

The only real issue is the unnecessary double attempt to delete the temporaries.
It does not cause any problems.

I will need to try it myself to see why it does the double wrapping of the exception,
I don't see it in the information you posted.

[adrian.brock]

P.S. I consider this an anti-pattern.

It is better practice for the session bean to initiate the request,
but to actually receive the reply in the client.

That way you are not blocking threads in the server waiting for asynchronous
responses.

It also doesn't work in a transaction.
The send/publish really happens at the transaction commit
so the receive would always fail.

[caissa]

P.S. I consider this an anti-pattern.

It is better practice for the session bean to initiate the request,
but to actually receive the reply in the client.

That way you are not blocking threads in the server waiting for asynchronous
responses.

Hmmm...thanks. I'll need to think about the ramifications of this for my use case. The fact that JMS messages are being sent as a result of the EJB call is an implementation detail that I am deliberately hiding from the session bean client. For the session bean to do it's work I need to know that a) the messages were received and b) whether the receiver was able to do what it is supposed to. I've considered making the messages truly asynchronous (fire and forget from the SLSB, no reply topic at all), but I would need to do a lot of bookeeping to gather the ack/nack information and react to it.

Anyway, you probably don't care about any of that. I appreciate the advice, though.

It also doesn't work in a transaction.
The send/publish really happens at the transaction commit
so the receive would always fail.

Right. That's why I have the session bean method that sends these messages marked NotSupported and am using ConnectionFactory for this particualr bean, as opposed to java:/JmsXA (which we use in other beans that don't require an ack/nack over temporary destinations).

As I said before, maybe I shouldn't even use JMS for this at all; perhaps an RMI or JMX call would be more suitable, as the ack/nack really makes the operation synchronous. But I guess these would both still block the server threads, as you point out, and could never be in a transaction either...