3 Replies Latest reply on Feb 10, 2011 5:32 PM by Hugh Bragg

    org.hornetq.core.logging.impl.JULLogDelegate.error() blocking

    Hugh Bragg Newbie

      I'm running HornetQ 2.1.2 standalone as a service on Windows Server 2008 by a domain user account.

      Aparently M$ have made some changes related to this in recent years, one of which is not to allow interactive services due to some security exploits.

      My guess is that this is the cause of my problems because initially I was logging to the console just for debugging convenience and didn't bother stopping it on production. Once I found that this was blocking, I turned console logging off and the problem went away. Recently however I had 2 services running the same client consuming messages remotely from different HornetQ standalone. The sequence of events seem to be:

      1. Some network or service related problem occured causing the hornet JMS consumer to throw a JMSException on a receive(200) call.

      2. A rollback was attempted causing an IllegalStateException.

      3. A new connection attempt was initiated and the createConnection() call blocks for 8 hours.

      4. The client service is restarted and everything continues as usual.

       

      My server configuration the default standalone non-clustered with JNDI disabled.

      The client uses all default settings.

      The stack trace I obtained from jconsole on the JMS thread is:

       

      Name: Thread-2
      State: RUNNABLE
      Total blocked: 125,069  Total waited: 898,727

       

      Stack trace:
      java.io.FileOutputStream.writeBytes(Native Method)
      java.io.FileOutputStream.write(Unknown Source)
      java.io.BufferedOutputStream.write(Unknown Source)
         - locked java.io.BufferedOutputStream@1b4920f8
      java.io.PrintStream.write(Unknown Source)
         - locked java.io.PrintStream@5e1387c6
      sun.nio.cs.StreamEncoder.writeBytes(Unknown Source)
      sun.nio.cs.StreamEncoder.implFlushBuffer(Unknown Source)
      sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
      sun.nio.cs.StreamEncoder.flush(Unknown Source)
         - locked java.io.OutputStreamWriter@5437086a
      java.io.OutputStreamWriter.flush(Unknown Source)
      java.util.logging.StreamHandler.flush(Unknown Source)
         - locked java.util.logging.ConsoleHandler@69099257
      java.util.logging.ConsoleHandler.publish(Unknown Source)
      java.util.logging.Logger.log(Unknown Source)
      java.util.logging.Logger.doLog(Unknown Source)
      java.util.logging.Logger.log(Unknown Source)
      org.hornetq.core.logging.impl.JULLogDelegate.error(JULLogDelegate.java:68)
      org.hornetq.core.logging.Logger.error(Logger.java:169)
      org.hornetq.core.remoting.impl.netty.NettyConnector.createConnection(NettyConnector.java:483)
      org.hornetq.core.client.impl.FailoverManagerImpl.getConnection(FailoverManagerImpl.java:953)
      org.hornetq.core.client.impl.FailoverManagerImpl.getConnectionWithRetry(FailoverManagerImpl.java:834)
      org.hornetq.core.client.impl.FailoverManagerImpl.createSession(FailoverManagerImpl.java:342)
         - locked java.lang.Object@5fb57890
         - locked java.lang.Object@c1dfe1a
      org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSessionInternal(ClientSessionFactoryImpl.java:1123)
         - locked org.hornetq.core.client.impl.ClientSessionFactoryImpl@3f2221f6
      org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSession(ClientSessionFactoryImpl.java:849)
      org.hornetq.jms.client.HornetQConnection.authorize(HornetQConnection.java:565)
      org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:624)
         - locked org.hornetq.jms.client.HornetQConnectionFactory@76c5a2f7
      org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:116)
      org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:111)

       

       

      Can anyone tell me how to stop hornet client calling JUL?

      After all, I'm only interested in the exception so I can make another connection attempt.

       

      Can anyone shed any light on this that might help me fix it?

      I know I'd much rather not use Windows, but there is no choice and I can't see why logging is required here.

        • 1. Re: org.hornetq.core.logging.impl.JULLogDelegate.error() blocking
          Hugh Bragg Newbie

          And once again this morning, same circumstances:

           

          Name: Thread-2
          State: RUNNABLE
          Total blocked: 58,099  Total waited: 75,151

           

          Stack trace:
          java.io.FileOutputStream.writeBytes(Native Method)
          java.io.FileOutputStream.write(Unknown Source)
          java.io.BufferedOutputStream.write(Unknown Source)
             - locked java.io.BufferedOutputStream@3caf7a1f
          java.io.PrintStream.write(Unknown Source)
             - locked java.io.PrintStream@247aa859
          sun.nio.cs.StreamEncoder.writeBytes(Unknown Source)
          sun.nio.cs.StreamEncoder.implFlushBuffer(Unknown Source)
          sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
          sun.nio.cs.StreamEncoder.flush(Unknown Source)
             - locked java.io.OutputStreamWriter@70c27dc4
          java.io.OutputStreamWriter.flush(Unknown Source)
          java.util.logging.StreamHandler.flush(Unknown Source)
             - locked java.util.logging.ConsoleHandler@70cf08b1
          java.util.logging.ConsoleHandler.publish(Unknown Source)
          java.util.logging.Logger.log(Unknown Source)
          java.util.logging.Logger.doLog(Unknown Source)
          java.util.logging.Logger.log(Unknown Source)
          org.hornetq.core.logging.impl.JULLogDelegate.error(JULLogDelegate.java:68)
          org.hornetq.core.logging.Logger.error(Logger.java:169)
          org.hornetq.core.remoting.impl.netty.NettyConnector.createConnection(NettyConnector.java:483)
          org.hornetq.core.client.impl.FailoverManagerImpl.getConnection(FailoverManagerImpl.java:953)
          org.hornetq.core.client.impl.FailoverManagerImpl.getConnectionWithRetry(FailoverManagerImpl.java:834)
          org.hornetq.core.client.impl.FailoverManagerImpl.createSession(FailoverManagerImpl.java:342)
             - locked java.lang.Object@7dabf7cb
             - locked java.lang.Object@29421875
          org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSessionInternal(ClientSessionFactoryImpl.java:1123)
             - locked org.hornetq.core.client.impl.ClientSessionFactoryImpl@17fed8b4
          org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSession(ClientSessionFactoryImpl.java:849)
          org.hornetq.jms.client.HornetQConnection.authorize(HornetQConnection.java:565)
          org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:624)
             - locked org.hornetq.jms.client.HornetQConnectionFactory@3da2cda9
          org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:116)
          org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:111)

           

          What can be happening?

          • 2. Re: org.hornetq.core.logging.impl.JULLogDelegate.error() blocking
            Hugh Bragg Newbie

            So I can reliably reproduce this problem now.

            It happens when I shut down the jms server for an extended period. This connection is over the internet so there is a bigger lag time than with the LAN service which I never see this problem on. It seems that our connection isn't so reliable and sometimes is interrupted for extended periods.

             

            Clebert. I'll post you a self contained package if you like, but the only difference between the receiveNoWait bug example and this is that I use receive(long) instead of receiveNoWait and the setup is slightly different:

             

            {code}

            HornetQConnectionFactory hqcf = HornetQJMSClient

                        .createConnectionFactory(transportConfiguration);

                hqcf.setReconnectAttempts(1);        // No Transparent reattachment

                hqcf.setCallTimeout(60000);

                hqcf.setClientFailureCheckPeriod(60000);

                hqcf.setConnectionTTL(60000);

             

                queueConnection = (QueueConnection)hqcf.createConnection();

            {code}

             

            I tried it with only setReconnectAttempts() and without the other settings as well, but it failed the same way.

             

            I also tried to detect long periods of inactivity and do a full reset there, but this only makes the problem worse.

            • 3. org.hornetq.core.logging.impl.JULLogDelegate.error() blocking
              Hugh Bragg Newbie

              The only solution was to not call receiveNoWait(). This method is broken.

              It is necessary to call Thread.interrupt().

              Instead I use receive(long timeout) with a timeout.