9 Replies Latest reply on Nov 28, 2012 11:15 AM by jesper.pedersen

    SonicMQ RA in JBoss7 showing lots of IJ000612 warnings

    snazy

      Hi,

       

      Our basic integration of SonicMQ RA (version 8.5) works. The Resource Adapter containing the SonicMQ RA deploys without errors. Additionally we have a small "service", that adds the required JMS destinations to the JNDI environment (startup hook). Both the RA and the "service" use a module containing the required Sonic jar files.

       

      Receiving JMS messages using a Message Driven Bean works fine. Sending JMS messages works as well as receiving JMS messages - either programmatically or via the SonicMQ JMS test tool. As long as no concurrent threads are running...

       

      The JBoss7 version we are using is the latest code from GIT as of 2011/10/28. This version uses IronJacamar 1.0.5.Final. Older versions of AS7 did not work with RAs.

       

      There are two situations where (nearly) the same WARN is logged.

      1. Upon startup when the SonicMQ RA is used first. It prints one IJ000612 warning for each connection in the pool (-> pool min-size)

      2. Occasionally when multiple threads are sending JMS messages concurrently, IJ000612 warnings are logged. It seems, that the http worker thread hangs when such a message is logged.

       

      For situation #2 : using JMeter with many parallel requests a lot of these warnings are logged:

       

       17:25:38,489 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-5) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7df5f91c[state=NORMAL managed connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6 connection handles=0 lastUse=1319815538489 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90 xaResource=XAResourceWrapperImpl@1fb5dddf[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@5cf96bbc pad=false overrideRmValue=false productName=java:/XAConnectionFactory productVersion=java:/XAConnectionFactory jndiName=java:/XAConnectionFactory] txSync=null] 

       

      With tracing enabled, JCA core connection manager tells this (before the message above):

       

      17:25:38,487 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http--0.0.0.0-8080-10) connectionClosed 
      called mc=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6
      17:25:38,487 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http--0.0.0.0-8080-10) unregisterConnection:
      0 handles left
      17:25:38,487 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http--0.0.0.0-8080-10) delisting
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7df5f91c[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6 connection handles=0
      lastUse=1319815538458 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@1fb5dddf[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@5cf96bbc
      pad=false overrideRmValue=false productName=java:/XAConnectionFactory productVersion=java:/XAConnectionFactory
      jndiName=java:/XAConnectionFactory] txSync=null]
      17:25:38,487 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http--0.0.0.0-8080-10)
      isManagedConnectionFree=true mc=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6
      17:25:38,489 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-5) IJ000612:
      Destroying connection that could not be successfully matched:
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7df5f91c[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6 connection handles=0
      lastUse=1319815538489 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@1fb5dddf[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@5cf96bbc
      pad=false overrideRmValue=false productName=java:/XAConnectionFactory productVersion=java:/XAConnectionFactory
      jndiName=java:/XAConnectionFactory] txSync=null]

      ... (somthing else happens in other threads) ...

      17:25:38,489 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-5) IJ000612:
      Destroying connection that could not be successfully matched:
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7df5f91c[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@24f1c9c6 connection handles=0
      lastUse=1319815538489 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@1fb5dddf[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@5cf96bbc
      pad=false overrideRmValue=false productName=java:/XAConnectionFactory productVersion=java:/XAConnectionFactory
      jndiName=java:/XAConnectionFactory] txSync=null]

       

      For situation #1:

      Related to the above (but slightly different messages (productName, productVersion):
      The first request (after JBoss 7 startup) issues exactly as many of these warnings as the configured minimum pool size. For example: min-size=20 forces 20 of the following messages:

       

      17:18:21,545 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-1) IJ000612: 
      Destroying connection that could not be successfully matched:
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7d3e3b95[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@b9f370 connection handles=0
      lastUse=1319815093744 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@301d3e6f[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@4fee0216
      pad=false overrideRmValue=false productName=SonicMQ productVersion=8.5.377 jndiName=java:/XAConnectionFactory] txSync=null]
      17:18:21,547 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-1) IJ000612:
      Destroying connection that could not be successfully matched:
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@12cb1b59[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@547079b2 connection handles=0
      lastUse=1319815093742 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@2445c06d[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@5f5c46b5
      pad=false overrideRmValue=false productName=SonicMQ productVersion=8.5.377 jndiName=java:/XAConnectionFactory] txSync=null]
      17:18:21,550 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http--0.0.0.0-8080-1) IJ000612:
      Destroying connection that could not be successfully matched:
      org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@232645fc[state=NORMAL managed
      connection=com.sonicsw.sonicmq.j2ee.jmsra.impl.JMSSessionManagedConnection@25bcb56b connection handles=0
      lastUse=1319815093740 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@6dbd726 pool internal
      context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@2fb8c90
      xaResource=XAResourceWrapperImpl@82a9728[xaResource=com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper@2429c748
      pad=false overrideRmValue=false productName=SonicMQ productVersion=8.5.377 jndiName=java:/XAConnectionFactory] txSync=null]

      ... (17 more)

       

      I am not sure whether this is caused by ironjacamar or JBoss7 code.

        • 1. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
          jesper.pedersen

          Try and download IronJacamar 1.1.0.Alpha3 and then run the validator (http://docs.jboss.org/ironjacamar/userguide/1.1/en-US/html/validator.html) on the resource adapter.

           

          See if that generates any ERRORs and/or WARNs - if so they need to be fixed first.

           

          It sounds like missing equals/hashCode methods which are mandatory.

          • 2. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
            jesper.pedersen

            Another problem could be that their http://download.oracle.com/javaee/6/api/javax/resource/spi/ManagedConnectionFactory.html#matchManagedConnections%28java.util.Set,%20javax.security.auth.Subject,%20javax.resource.spi.ConnectionRequestInfo%29 method is implemented incorrectly, since it is the return value of that method that generates the IJ-612 WARN.

            • 3. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
              snazy

              There are no hashCode/equals method implementations in any of the Sonic *Connection* classes mentioned in the log messages.

               

              Only com.sonicsw.sonicmq.j2ee.jmsra.impl.XAResourceWrapper implements them (output from JAD):

               

                  public boolean equals(Object obj)
                  {
                      if(this == obj)
                          return true;
                      if(obj == null)
                          return false;
                      if(obj instanceof XAResourceWrapper)
                      {
                          XAResource xaresource = ((XAResourceWrapper)obj).m_res;
                          return m_res.equals(xaresource);
                      }
                      if(obj instanceof XAResource)
                      {
                          XAResource xaresource1 = (XAResource)obj;
                          return m_res.equals(xaresource1);
                      } else
                      {
                          return false;
                      }
                  }
              
                  public int hashCode()
                  {
                      return m_res.hashCode();
                  }
              

               

              The matchmanagedConnections from SonicManagedConnectionFactory looks like this (JAD output):

              public ManagedConnection matchManagedConnections(Set set, Subject subject, ConnectionRequestInfo connectionrequestinfo)
                      throws ResourceException
                  {
                      for(Iterator iterator = set.iterator(); iterator.hasNext();)
                      {
                          Object obj = iterator.next();
                          if(obj instanceof JMSSessionManagedConnection)
                          {
                              JMSSessionManagedConnection jmssessionmanagedconnection = (JMSSessionManagedConnection)obj;
                              if(!jmssessionmanagedconnection.isDestroyed() && jmssessionmanagedconnection.isCRIEqual((JMSConnectionRequestInfo)connectionrequestinfo))
                              {
                                  RAUtils.printDebug("FOUND MATCHING SESSION");
                                  return jmssessionmanagedconnection;
                              }
                          }
                      }
              
                      RAUtils.printDebug("DID NOT FIND MATCHING SESSION");
                      return null;
                  }
              

               

              isCRIEqual delegates to the equals method in JMSConnectionRequestInfo (don't know, why they use a StringBuffer for hashCode implementation...):

               

                  public boolean equals(Object obj)
                  {
                      if(obj instanceof JMSConnectionRequestInfo)
                      {
                          JMSConnectionRequestInfo jmsconnectionrequestinfo = (JMSConnectionRequestInfo)obj;
                          if(jmsconnectionrequestinfo.m_type == m_type && jmsconnectionrequestinfo.m_isXA == m_isXA && jmsconnectionrequestinfo.m_isTransacted == m_isTransacted && jmsconnectionrequestinfo.m_ackMode == m_ackMode && jmsconnectionrequestinfo.m_connectionID == m_connectionID && jmsconnectionrequestinfo.m_poolSessions == m_poolSessions && jmsconnectionrequestinfo.m_preserveSessionsMidTxn == m_preserveSessionsMidTxn)
                              return true;
                      }
                      return false;
                  }
              
                  public int hashCode()
                  {
                      StringBuffer stringbuffer = new StringBuffer();
                      stringbuffer.append(m_isXA);
                      stringbuffer.append(m_isTransacted);
                      stringbuffer.append(m_ackMode);
                      stringbuffer.append(m_connectionID);
                      stringbuffer.append(m_poolSessions);
                      stringbuffer.append(m_preserveSessionsMidTxn);
                      return stringbuffer.toString().hashCode();
                  }
              

               

               

              Can you explain, why and where equals and hashCode implementations are mandatory. Maybe it is possible to write wrapper classes for them (I know, that this is sick, but it might work).

               

              The same warning messages occur with IronJacamar 1.1.0.Alpha3 with latest AS7 code.

               

              The validator says:

              Severity: ERROR
              Section: 19.4.2
              Description: A ResourceAdapter must implement a "public int hashCode()" method.
              Code: com.sonicsw.sonicmq.j2ee.jmsra.impl.sonic.SonicResourceAdapter
              
              Severity: ERROR
              Section: 19.4.2
              Description: A ResourceAdapter must implement a "public boolean equals(Object)" method.
              Code: com.sonicsw.sonicmq.j2ee.jmsra.impl.sonic.SonicResourceAdapter
              
              • 4. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                jesper.pedersen

                Which means that the equally check in JMSConnectionRequestInfo failed, mostly likely due to that the internal state of the object changed while in use.

                 

                DEBUG log should give you a bit more information about the CRI if they implement toString().

                 

                Those two ERRORs are mndatory spec requirements. If that is all then that should be an easy for them, however won't affect the above issue.

                 

                This is a case for Progress, since the managed connections in the connection pool can't be matched we have to destroy it, since we can't reuse it. Your application will work, but under a heavy performance penalty.

                1 of 1 people found this helpful
                • 5. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                  jesper.pedersen

                  Maybe http://download.oracle.com/javaee/6/api/javax/resource/spi/ManagedConnection.html#cleanup%28%29 doesn't reset all necessary states... Progress would know.

                  1 of 1 people found this helpful
                  • 6. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                    snazy

                    Thanks for your help.

                     

                    I tried to check the issue myself - but I do not really know the background, why it does not match/match - which of the parts of the CRI are relevant and which are not. If I have more time, I'll get back and do some more reverse engineering.

                     

                    The RA code seems to be compiled for JDK 1.4.

                     

                    I will forward it to Progress (which is complicated )

                     

                    Nice - this bug seems to give SonicMQ RA a performance penalty in all app servers - and they did not see it.

                    • 7. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                      jesper.pedersen

                      Yeah, it is really a case for Progress.

                       

                      The fix is easy though: Switch to HornetQ

                      It is the faster one out there anyway: http://www.spec.org/jms2007/results/jms2007.html

                      • 8. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                        jesper.pedersen

                        Actually, you never posted your configuration - do you have a value for the <security> element ?

                        • 9. Re: SonicMQ RA in JBoss7 showing lots of IJ000612 warnings
                          jesper.pedersen

                          Actually, that was a stupid question, since I can see its OnePool logging - does <security><application/></security> make a difference in your case ?