10 Replies Latest reply on Jun 9, 2005 10:42 AM by gobrien

    Sending one message, receiving two?

    tietyt

      I hope this isn't a generic J2EE thing but right now I"m experiencing this problem where I send one message through a servlet and my MDB receives every message twice. This is a queue. This is the output:

      11:06:28,359 INFO [STDOUT] write Sending message: This is message 1
      11:06:28,375 INFO [STDOUT] write Sending message: This is message 2
      11:06:28,390 INFO [STDOUT] write Sending message: This is message 3
      11:06:28,390 INFO [STDOUT] write Sending message: This is message 4
      11:06:28,390 INFO [STDOUT] write Sending message: This is message 5
      11:06:28,406 INFO [STDOUT] write Sending message: This is message 6
      11:06:28,406 INFO [STDOUT] write Sending message: This is message 7
      11:06:28,421 INFO [STDOUT] write Sending message: This is message 8
      11:06:28,421 INFO [STDOUT] write Sending message: This is message 9
      11:06:28,437 INFO [STDOUT] write Sending message: This is message 10
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 7
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 7
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 2
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 2
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 6
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 6
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 3
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 3
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 10
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 10
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 9
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 9
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 4
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 4
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 8
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 8
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 1
      11:06:28,437 INFO [TestMessageBean] onMessage I got this message: This is message 1
      11:06:28,453 INFO [TestMessageBean] onMessage I got this message: This is message 5
      11:06:28,453 INFO [TestMessageBean] onMessage I got this message: This is message 5
      


      When I add a this.toString() to the MDB's output i can see that it is using 2 instances of beans BUT I usually see the same bean handling the same message twice.

      Here's the ejb-jar.xml
      <message-driven>
       <description>Just a Test</description>
       <display-name>JustATest</display-name>
       <ejb-name>TestMessageEJB</ejb-name>
       <ejb-class>com.webreach.pm.as.TestMessageBean</ejb-class>
       <transaction-type>Container</transaction-type>
       <acknowledge-mode>Auto-acknowledge</acknowledge-mode>
       <message-driven-destination>
       <destination-type>javax.jms.Queue</destination-type>
       </message-driven-destination>
       </message-driven>
      


      Here's the jboss.xml:
      <jboss>
       <enterprise-beans>
       <message-driven>
       <ejb-name>TestMessageEJB</ejb-name>
       <destination-jndi-name>queue/TestMessageQueue</destination-jndi-name>
       </message-driven>
       </enterprise-beans>
      </jboss>
      


      And here's the code that's sending the message:

      
      try {
      
       Destination destination = getServiceLocator().getDestination("java:comp/env/jms/TestMessageQueue");
       ConnectionFactory connectionFactory = getServiceLocator().getConnectionFactory("UIL2ConnectionFactory");
      
      
       javax.jms.Connection connection = connectionFactory.createConnection();
       javax.jms.Session session = connection.createSession(false,
       Session.AUTO_ACKNOWLEDGE);
       MessageProducer messageProducer = session.createProducer(destination);
      
       TextMessage message = session.createTextMessage();
      
       for (int i = 0; i < 10; i++) {
       message.setText("This is message " + (i + 1));
       System.out.println("Sending message: " +
       message.getText());
       messageProducer.send(message);
       }
      
       } catch (Exception e) {
       e.printStackTrace();
       }
      
      


      Is there a way to ensure that only one instance handles a message?

        • 1. Re: Sending one message, receiving two?
          tietyt

          oh yeah, here's the code that's receiving the message:

          
          public void onMessage(Message message) {
          
           try {
           log.info(this.toString() + " got this message: " + ((TextMessage) message).getText());
           } catch (Exception e) {
           e.printStackTrace();
           }
           }
          
          


          Here's a the output showing the instances of the MDB's:

          
          11:57:27,046 INFO [STDOUT] write Sending message: This is message 1
          11:57:27,062 INFO [STDOUT] write Sending message: This is message 2
          11:57:27,062 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 1
          11:57:27,062 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 1
          11:57:27,062 INFO [STDOUT] write Sending message: This is message 3
          11:57:27,062 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 2
          11:57:27,062 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 2
          11:57:27,078 INFO [STDOUT] write Sending message: This is message 4
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 3
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 3
          11:57:27,078 INFO [STDOUT] write Sending message: This is message 5
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 4
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 4
          11:57:27,078 INFO [STDOUT] write Sending message: This is message 6
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 5
          11:57:27,078 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 5
          11:57:27,093 INFO [STDOUT] write Sending message: This is message 7
          11:57:27,093 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 6
          11:57:27,093 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 6
          11:57:27,093 INFO [STDOUT] write Sending message: This is message 8
          11:57:27,093 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 7
          11:57:27,093 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 7
          11:57:27,109 INFO [STDOUT] write Sending message: This is message 9
          11:57:27,109 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 8
          11:57:27,109 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 8
          11:57:27,109 INFO [STDOUT] write Sending message: This is message 10
          11:57:27,109 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 9
          11:57:27,109 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 9
          11:57:27,125 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 10
          11:57:27,125 INFO [TestMessageBean] onMessage TestMessageBean@14f8b9a got this message: This is message 10
          
          


          It looks like this time only one bean was used.

          • 2. Re: Sending one message, receiving two?
            tietyt

            let me add that the producer is in a servlet that is on the same computer as JBoss (maybe i already said that).

            Thanks for any help.

            • 3. Re: Sending one message, receiving two?

               

              "tieTYT" wrote:
              oh yeah, here's the code that's receiving the message:
              
              public void onMessage(Message message) {
              
               try {
               log.info(this.toString() + " got this message: " + ((TextMessage) message).getText());
               } catch (Exception e) {
               e.printStackTrace();
               }
               }
              
              



              Use:
               log.info(this + " got this message: " + message);
              


              Then goto the top of this forum and "READ THIS FIRST" for debugging hints


              • 4. Re: Sending one message, receiving two?
                tietyt

                 

                16:17:35,593 DEBUG [SpyDestinationObjectFactory] getObjectInstance SpyDestinationObjectFactory->getObjectInsta
                nce()
                16:17:35,593 DEBUG [SpyConnectionFactoryObjectFactory] getObjectInstance Extracting SpyConnectionFactory from
                reference
                16:17:35,609 DEBUG [SpyConnectionFactoryObjectFactory] getObjectInstance The GenericConnectionFactory is: Gene
                ricConnectionFactory[server=org.jboss.mq.il.uil2.UILServerIL@274608 connectionProperties={UIL_ADDRESS_KEY=192.
                168.1.10, UIL_CHUNKSIZE_KEY=1000000, UIL_TCPNODELAY_KEY=yes, ClientILService=org.jboss.mq.il.uil2.UILClientILS
                ervice, UIL_PORT_KEY=8315, UIL_BUFFERSIZE_KEY=2048, PingPeriod=60000}]
                16:17:35,640 DEBUG [SocketManager] run Begin ReadTask.run
                16:17:35,640 DEBUG [SocketManager] run Begin WriteTask.run
                16:17:35,640 DEBUG [SocketManager] run Begin WriteTask.run
                16:17:35,640 DEBUG [SocketManager] run Begin ReadTask.run
                16:17:35,656 DEBUG [SocketManager] run Created ObjectOutputStream
                16:17:35,656 DEBUG [SocketManager] run Created ObjectOutputStream
                16:17:35,656 DEBUG [SocketManager] run Created ObjectInputStream
                16:17:35,656 DEBUG [SocketManager] run Created ObjectInputStream
                16:17:35,656 DEBUG [UILClientILService] start Starting
                16:17:35,656 DEBUG [ServerSocketManagerHandler] handleMsg Setting up the UILClientIL Connection
                16:17:35,656 DEBUG [ServerSocketManagerHandler] handleMsg The UILClientIL Connection is set up
                16:17:35,765 INFO [STDOUT] write Sending message: This is message 1
                16:17:35,781 INFO [STDOUT] write Sending message: This is message 2
                16:17:35,796 INFO [STDOUT] write Sending message: This is message 3
                16:17:35,796 INFO [STDOUT] write Sending message: This is message 4
                16:17:35,796 INFO [STDOUT] write Sending message: This is message 5
                16:17:35,812 INFO [STDOUT] write Sending message: This is message 6
                16:17:35,812 INFO [STDOUT] write Sending message: This is message 7
                16:17:35,828 INFO [STDOUT] write Sending message: This is message 8
                16:17:35,828 INFO [STDOUT] write Sending message: This is message 9
                16:17:35,843 INFO [STDOUT] write Sending message: This is message 10
                16:17:35,859 INFO [TestMessageBean] onMessage com.webreach.pm.as.TestMessageBean@16d079a got this message: Sp
                yTextMessage {
                Header {
                 jmsDestination : QUEUE.TestMessageQueue
                 jmsDeliveryMode : 2
                 jmsExpiration : 0
                 jmsPriority : 4
                 jmsMessageID : ID:3-111818625584310
                 jmsTimeStamp : 1118186255843
                 jmsCorrelationID: null
                 jmsReplyTo : null
                 jmsType : null
                 jmsRedelivered : false
                 jmsProperties : {}
                 jmsPropReadWrite: false
                 msgReadOnly : true
                 producerClientId: ID:3
                }
                Body {
                 text :This is message 10
                }
                }
                16:17:35,859 INFO [TestMessageBean] onMessage com.webreach.pm.as.TestMessageBean@16d079a got this message: Sp
                yTextMessage {
                Header {
                 jmsDestination : QUEUE.TestMessageQueue
                 jmsDeliveryMode : 2
                 jmsExpiration : 0
                 jmsPriority : 4
                 jmsMessageID : ID:3-111818625584310
                 jmsTimeStamp : 1118186255843
                 jmsCorrelationID: null
                 jmsReplyTo : null
                 jmsType : null
                 jmsRedelivered : false
                 jmsProperties : {}
                 jmsPropReadWrite: false
                 msgReadOnly : true
                 producerClientId: ID:3
                }
                Body {
                 text :This is message 10
                }
                }
                16:17:35,859 INFO [TestMessageBean] onMessage com.webreach.pm.as.TestMessageBean@3a78ad got this message: Spy
                TextMessage {
                Header {
                 jmsDestination : QUEUE.TestMessageQueue
                 jmsDeliveryMode : 2
                 jmsExpiration : 0
                 jmsPriority : 4
                 jmsMessageID : ID:3-11181862557963
                 jmsTimeStamp : 1118186255796
                 jmsCorrelationID: null
                 jmsReplyTo : null
                 jmsType : null
                 jmsRedelivered : false
                 jmsProperties : {}
                 jmsPropReadWrite: false
                 msgReadOnly : true
                 producerClientId: ID:3
                }
                Body {
                 text :This is message 3
                }
                }
                16:17:35,859 INFO [TestMessageBean] onMessage com.webreach.pm.as.TestMessageBean@3a78ad got this message: Spy
                TextMessage {
                Header {
                 jmsDestination : QUEUE.TestMessageQueue
                 jmsDeliveryMode : 2
                 jmsExpiration : 0
                 jmsPriority : 4
                 jmsMessageID : ID:3-11181862557963
                 jmsTimeStamp : 1118186255796
                 jmsCorrelationID: null
                 jmsReplyTo : null
                 jmsType : null
                 jmsRedelivered : false
                 jmsProperties : {}
                 jmsPropReadWrite: false
                 msgReadOnly : true
                 producerClientId: ID:3
                }
                Body {
                 text :This is message 3
                }
                }
                

                and so on.....

                I added those log4j tags into the right file but it doesn't seem to change the output. I'll try to research that. In the meantime i tweaked the file so it shows all debug information and that's the result of this.

                • 5. Re: Sending one message, receiving two?
                  tietyt

                  OK I got the Trace log. This is real big so I just started a page or so above the time where the MDB gets the first message and stopped after a few messages were received. Tell me if this isn't enough information:

                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.GetIDMsg13046161[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.GetIDMsg13046161[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.PingMsg22178007[msgType: m_ping, msgID: -2147483644, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg22178007[msgType: m_ping, msgID: -2147483644, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_getID, msgID: -2147483645
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.PingMsg22178007[msgType: m_ping, msgID: -2147483644, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.GetIDMsg23136580[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 9
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_ping, msgID: -2147483644
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : getID
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg27750365[msgType: m_ping, msgID: -2147483644, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1118189842093
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.PingMsg19645447[msgType: m_pong, msgID: -2147483643, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.PingMsg19645447[msgType: m_pong, msgID: -2147483643, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg19645447[msgType: m_pong, msgID: -2147483643, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_pong, msgID: -2147483643
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg5428820[msgType: m_pong, msgID: -2147483643, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.sm.jdbc.JDBCStateManager] Client id 'ID:3' is logged in.
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : getID
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.GetIDMsg23136580[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.GetIDMsg23136580[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.UILClientILService] Begin handleMsg, msgType: 24
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.GetIDMsg23136580[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 9
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.Connection] PONG serverTime=1118189842093 Connection@14252445[token=ConnectionToken:null/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.UILClientILService] End handleMsg
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_getID, msgID: -2147483645
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Found replyMap msg: org.jboss.mq.il.uil2.msgs.GetIDMsg13046161[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msg reply: org.jboss.mq.il.uil2.msgs.GetIDMsg13046161[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.GetIDMsg13046161[msgType: m_getID, msgID: -2147483645, error: null]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.Connection] ClientID established Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]
                  2005-06-07 17:17:22,093 TRACE [org.jboss.mq.SpySession] New session SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]
                  2005-06-07 17:17:22,109 TRACE [org.jboss.mq.SpyMessageProducer] New message producer SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                  2005-06-07 17:17:22,109 TRACE [org.jboss.mq.SpySession] Adding producer SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                  2005-06-07 17:17:22,125 INFO [STDOUT] Sending message: This is message 1
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.SpyMessageProducer] Sending message SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                  SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421401
                   jmsTimeStamp : 1118189842140
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: true
                   msgReadOnly : false
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 1
                  }
                  }
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.SpySession] Sending message to server ID:3-11181898421401 SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.Connection] SendToServer message=ID:3-11181898421401 Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.AddMsg13078018[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.AddMsg13078018[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_addMessage, msgID: -2147483642
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.AddMsg20735572[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 2
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421401
                   jmsTimeStamp : 1118189842140
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: true
                   msgReadOnly : false
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 1
                  }
                  }
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                   Principal: guest
                   Principal: Roles(members:j2ee,guest,john)
                  ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] About to add message 1 msg=0 hard NOT_STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 transaction=null
                  2005-06-07 17:17:22,140 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 1 msg=0 hard NOT_STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 transaction=null
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 1 msg=0 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 transaction=null
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.server.BasicQueue] addMessage 1 msg=0 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 null org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.server.BasicQueue] internalAddMessage 1 msg=0 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.server.BasicQueue] queueMessageForSending Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] 1 msg=0 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=30035636 org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.AddMsg20735572[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.AddMsg20735572[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 2
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.AddMsg20735572[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_addMessage, msgID: -2147483642
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.Connection] Async deliver requests=[ReceiveRequest[message=ID:3-11181898421401 subscription=-2147483648] Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Found replyMap msg: org.jboss.mq.il.uil2.msgs.AddMsg13078018[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.Connection] Processing request=ReceiveRequest[message=ID:3-11181898421401 subscription=-2147483648 Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msg reply: org.jboss.mq.il.uil2.msgs.AddMsg13078018[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.AddMsg13078018[msgType: m_addMessage, msgID: -2147483642, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.Connection] Delivering messageid=0 to consumer=SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,156 INFO [STDOUT] Sending message: This is message 2
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.SpyConnectionConsumer] Add message=ID:3-11181898421401 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.SpyMessageProducer] Sending message SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                  SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421562
                   jmsTimeStamp : 1118189842156
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: true
                   msgReadOnly : false
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 2
                  }
                  }
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.SpyConnectionConsumer] run() got message message=ID:3-11181898421401 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.SpySession] Sending message to server ID:3-11181898421562 SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.Connection] SendToServer message=ID:3-11181898421562 Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.AddMsg27035453[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.AddMsg27035453[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] Waiting for serverSesionPool SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSessionPool] getting a server session
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSessionPool] using server session: org.jboss.jms.asf.StdServerSession@1539d49
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] Waited serverSesion=org.jboss.jms.asf.StdServerSession@1539d49 session=SpySession@18621578[tx=true txid=null XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]] SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpySession] Add message msgid=ID:3-11181898421401 SpySession@18621578[tx=true txid=null XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] Starting the ServerSession=org.jboss.jms.asf.StdServerSession@1539d49 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSession] starting invokes on server session
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.Connection] Receive subscription=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] wait=-1
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a subId=-2147483648
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                   Principal: guest
                   Principal: Roles(members:j2ee,guest,john)
                  ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] receive Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] wait=false org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] run() receivedNoWait got no messageSpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.Connection] Receive subscription=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] wait=0
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_addMessage, msgID: -2147483641
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.AddMsg21023091[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 0
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a subId=-2147483648
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 2
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                   Principal: guest
                   Principal: Roles(members:j2ee,guest,john)
                  ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] receive Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] wait=true org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSession] running...
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421562
                   jmsTimeStamp : 1118189842156
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: true
                   msgReadOnly : false
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 2
                  }
                  }
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] addReceiver Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpySession] Run messages=1 SpySession@18621578[tx=true txid=null XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                   Principal: guest
                   Principal: Roles(members:j2ee,guest,john)
                  ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854775808
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] About to add message 2 msg=1 hard NOT_STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 transaction=null
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] run() waiting for message SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpySession] Setting current tx xid=-9223372036854775808 previous: null SpySession@18621578[tx=true txid=null XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyMessageConsumer] consumer() acking message in tx message=ID:3-11181898421401 SpyMessageConsumer@8084664[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] listening=true receiving=false sessionConsumer=true waitingForMessage=false messages=0 listener=org.jboss.jms.asf.StdServerSession@1539d49 session=SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyXAResourceManager] Adding acked message xid=-9223372036854775808 ID:3-11181898421401
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 2 msg=1 hard NOT_STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 transaction=null
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyMessageConsumer] consumer() before onMessage=ID:3-11181898421401 SpyMessageConsumer@8084664[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] listening=true receiving=false sessionConsumer=true waitingForMessage=false messages=0 listener=org.jboss.jms.asf.StdServerSession@1539d49 session=SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSession] onMessage running (pool, session, xaSession, useLocalTX): , SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]], SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]], false
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl[FormatId=257, GlobalId=webreachdmz01/20, BranchQual=1, localId=20], flags=0 SpyXAResource[session=SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854775808, xid=XidImpl[FormatId=257, GlobalId=webreachdmz01/20, BranchQual=1, localId=20]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpySession] Setting current tx xid=XidImpl[FormatId=257, GlobalId=webreachdmz01/20, BranchQual=1, localId=20] previous: -9223372036854775808 SpySession@18621578[tx=true txid=-9223372036854775808 XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.jms.asf.StdServerSession] XAResource 'SpyXAResource[session=SpySession@18621578[tx=true txid=XidImpl[FormatId=257, GlobalId=webreachdmz01/20, BranchQual=1, localId=20] XA RUNNING connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]]' enlisted.
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 2 msg=1 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 transaction=null
                  2005-06-07 17:17:22,171 TRACE [org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message: SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421401
                   jmsTimeStamp : 1118189842140
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: false
                   msgReadOnly : true
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 1
                  }
                  }
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] addMessage 2 msg=1 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 null org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] internalAddMessage 2 msg=1 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.BasicQueue] queueMessageForSending Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] 2 msg=1 hard STORED PERSISTENT queue=QUEUE.TestMessageQueue priority=4 lateClone=false hashCode=32844677 org.jboss.mq.server.PersistentQueue@14e3d95{id=QUEUE.TestMessageQueue}
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.AddMsg21023091[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.AddMsg21023091[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 2
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.AddMsg21023091[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_addMessage, msgID: -2147483641
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Found replyMap msg: org.jboss.mq.il.uil2.msgs.AddMsg27035453[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msg reply: org.jboss.mq.il.uil2.msgs.AddMsg27035453[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.Connection] Async deliver requests=[ReceiveRequest[message=ID:3-11181898421562 subscription=-2147483648] Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.Connection] Processing request=ReceiveRequest[message=ID:3-11181898421562 subscription=-2147483648 Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.Connection] Delivering messageid=0 to consumer=SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] Add message=ID:3-11181898421562 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                  2005-06-07 17:17:22,171 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.AddMsg27035453[msgType: m_addMessage, msgID: -2147483641, error: null]
                  2005-06-07 17:17:22,171 INFO [STDOUT] Sending message: This is message 3
                  2005-06-07 17:17:22,187 TRACE [org.jboss.mq.SpyMessageProducer] Sending message SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                  SpyTextMessage {
                  Header {
                   jmsDestination : QUEUE.TestMessageQueue
                   jmsDeliveryMode : 2
                   jmsExpiration : 0
                   jmsPriority : 4
                   jmsMessageID : ID:3-11181898421873
                   jmsTimeStamp : 1118189842187
                   jmsCorrelationID: null
                   jmsReplyTo : null
                   jmsType : null
                   jmsRedelivered : false
                   jmsProperties : {}
                   jmsPropReadWrite: true
                   msgReadOnly : false
                   producerClientId: ID:3
                  }
                  Body {
                   text :This is message 3
                  }
                  }
                  


                  • 6. Re: Sending one message, receiving two?
                    tietyt

                    omg... is that a Log4j conflict? When I do System.out.println instead of log.info I don't see double results. What's up with that (besides me being a dumbass)?

                    • 7. Re: Sending one message, receiving two?

                       

                      "tieTYT" wrote:
                      OK I got the Trace log. This is real big so I just started a page or so above the time where the MDB gets the first message and stopped after a few messages were received. Tell me if this isn't enough information:


                      No, that is not enough information, it doesn't even show your log.info
                      you added to the MDB?????

                      Message 1 - has got to the point where it is about to invoke the EJB
                      2005-06-07 17:17:22,171 TRACE [org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message: SpyTextMessage {
                      Header {
                       jmsDestination : QUEUE.TestMessageQueue
                       jmsDeliveryMode : 2
                       jmsExpiration : 0
                       jmsPriority : 4
                       jmsMessageID : ID:3-11181898421401
                       jmsTimeStamp : 1118189842140
                       jmsCorrelationID: null
                       jmsReplyTo : null
                       jmsType : null
                       jmsRedelivered : false
                       jmsProperties : {}
                       jmsPropReadWrite: false
                       msgReadOnly : true
                       producerClientId: ID:3
                      }
                      Body {
                       text :This is message 1
                      }
                      }
                      


                      Message 2 has got to the point where the ConnectionConsumer is doing the read ahead
                      2005-06-07 17:17:22,171 TRACE [org.jboss.mq.SpyConnectionConsumer] Add message=ID:3-11181898421562 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a destination=QUEUE.TestMessageQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6742d0 connection=Connection@12716179[token=ConnectionToken:ID:1/8fb3d6c946ff131386c233fbbf84ee5a rcvstate=STARTED]]
                      


                      And message 3 is just in the process of being sent by the producer
                      2005-06-07 17:17:22,171 INFO [STDOUT] Sending message: This is message 3
                      2005-06-07 17:17:22,187 TRACE [org.jboss.mq.SpyMessageProducer] Sending message SpyMessageProducer@342828[ dest=QUEUE.TestMessageQueue delivery=persist priority=4 ttl=0 disableMessageID=false disableTS=false session=SpySession@20942907[tx=false ack=AUTO txid=null RUNNING connection=Connection@14252445[token=ConnectionToken:ID:3/13b4ca0ce43f059ed183a45362b3cd77 rcvstate=STOPPED]]]
                      SpyTextMessage {
                      Header {
                       jmsDestination : QUEUE.TestMessageQueue
                       jmsDeliveryMode : 2
                       jmsExpiration : 0
                       jmsPriority : 4
                       jmsMessageID : ID:3-11181898421873
                       jmsTimeStamp : 1118189842187
                       jmsCorrelationID: null
                       jmsReplyTo : null
                       jmsType : null
                       jmsRedelivered : false
                       jmsProperties : {}
                       jmsPropReadWrite: true
                       msgReadOnly : false
                       producerClientId: ID:3
                      }
                      Body {
                       text :This is message 3
                      }
                      }
                      


                      • 8. Re: Sending one message, receiving two?

                         

                        "tieTYT" wrote:
                        omg... is that a Log4j conflict? When I do System.out.println instead of log.info I don't see double results. What's up with that (besides me being a dumbass)?


                        Search: Appender Additivity and also attempting to reconfigure log4j
                        when JBoss has already trapped System.out/err, there is something in the FAQ
                        about application specific log4j configs.

                        • 9. Re: Sending one message, receiving two?
                          tietyt

                          thanks for all the help.

                          • 10. Re: Sending one message, receiving two?
                            gobrien

                            Instead of:-

                            TextMessage message = session.createTextMessage();
                            
                             for (int i = 0; i < 10; i++) {
                             message.setText("This is message " + (i + 1));
                             System.out.println("Sending message: " +
                             message.getText());
                             messageProducer.send(message);
                             }
                            

                            try this:-

                            TextMessage message = null;
                             for (int i = 0; i < 10; i++) {
                             message =session.createTextMessage();
                             message.setText("This is message " + (i + 1));
                             System.out.println("Sending message: " +
                             message.getText());
                             messageProducer.send(message);
                             }