5 Replies Latest reply on Oct 18, 2016 10:31 AM by jbertram

    HQ224016 message in the logs

    dev151

      Hi all,

       

      Our customer reported us that their calculation process from time to time gets blocked on the server waiting long hours before complete application server must be restarted.

      Architecture is quite complicated: Felix is used as an OSGi server hosting several bundles. One of them delivers "inbuild" HornetQ server which is initialized by Activator when bundle starts.

      Another one delivers HornetQ service. My understanding of the system is that there is one global request queue for posting messages and several result queues one for each java process which is responsible for calculations.

      If calculation process is idle it takes message from global request queue, does some processing and returns result by sending some message to it's result queue.

      In general it works fine, but from time to time in logs one can find:

      2016-09-19 20:33:38,331 [log4j] [org.hornetq.core.server] HQ224016: Caught exception

      2016-09-19 20:33:38,331 [log4j] [org.hornetq.core.server] HQ224016: Caught exception

      And nothing more about this issue can be found.

       

      I tried to reproduce this problem and by sending couple of millions of request I managed to generate is once.

       

      Libraries used in bunlde containing HornetQ server:

      hornetq-bootstrap-2.4.7.Final.jar

      hornetq-jms-server-2.4.7.Final.jar

      hornetq-core-client-2.4.7.Final.jar

      hornetq-commons-2.4.7.Final.jar

      hornetq-journal-2.4.7.Final.jar

      hornetq-native-2.4.7.Final.jar

      hornetq-jms-client-2.4.7.Final.jar

      hornetq-server-2.4.7.Final.jar

       

      Libraries used in bunlde containing HornetQ service:

      hornetq-core-client-2.4.7.Final.jar

      hornetq-commons-2.4.7.Final.jar

      hornetq-journal-2.4.7.Final.jar

      hornetq-native-2.4.7.Final.jar

      hornetq-jms-2.2.21.Final.jar

      hornetq-core-2.2.21.Final.jar

       

      What can be true nature of this issue, because message "Caught exception" is not very verbose?

      What can I do or try to get more detailed message (stacktrace maybe)?

      Or event better: how to fix this issue?

      Any help is appreciated.

        • 1. Re: HQ224016 message in the logs
          jbertram

          I just ran a test with HornetQ 2.4.7 that exercises this bit of logging and it logged both the message from the exception as well as the full stack-trace.  I'm not sure why you aren't seeing it.  Is anything altering the log?

          • 2. Re: HQ224016 message in the logs
            dev151

            Hello Justin,

             

            I did additional checks:

            1. The log is not altered. One of the log files is console output of application server. Second log file is business logger file, messages logged here come from OSGi message bus.

            Both files have same short message logged: "[log4j] [org.hornetq.core.server] HQ224016: Caught exception" only.

             

            2. In messaging server bundle project I found resource files: hornetq-beans.xml, hornetq-configuration.xml, hornetq-jms.xml, hornetq-users.xml, jndi.properties. Nothing related to logging is there.
            There is also logging.properties file which seems to be original logger configuration delivered with HornetQ libraries:

            #

            # JBoss, Home of Professional Open Source.

            # ... copyright lines truncated here ...

            # 02110-1301 USA, or see the FSF site: http://www.fsf.org.

            #

             

            # Additional logger names to configure (root logger is always configured)

            # Root logger option

            loggers=org.jboss.logging,org.hornetq.core.server,org.hornetq.utils,org.hornetq.journal,org.hornetq.jms,org.hornetq.integration.bootstrap

             

            # Root logger level

            logger.level=INFO

            # HornetQ logger levels

            logger.org.hornetq.core.server.level=INFO

            logger.org.hornetq.journal.level=INFO

            logger.org.hornetq.utils.level=INFO

            logger.org.hornetq.jms.level=INFO

            logger.org.hornetq.integration.bootstrap.level=INFO

            # Root logger handlers

            logger.handlers=FILE,CONSOLE

             

            # Console handler configuration

            handler.CONSOLE=org.jboss.logmanager.handlers.ConsoleHandler

            handler.CONSOLE.properties=autoFlush

            handler.CONSOLE.level=FINE

            handler.CONSOLE.autoFlush=true

            handler.CONSOLE.formatter=PATTERN

             

            # File handler configuration

            handler.FILE=org.jboss.logmanager.handlers.FileHandler

            handler.FILE.level=FINE

            handler.FILE.properties=autoFlush,fileName

            handler.FILE.autoFlush=true

            handler.FILE.fileName=logs/hornetq.log

            handler.FILE.formatter=PATTERN

             

            # Formatter pattern configuration

            formatter.PATTERN=org.jboss.logmanager.formatters.PatternFormatter

            formatter.PATTERN.properties=pattern

            formatter.PATTERN.pattern=%d{HH:mm:ss,SSS} %-5p [%c] %s%E%n

             

             

            There is no 'hornetq.log' file in the system. Not sure if this configuration is executed at all inside the OSGi server. I found on disk after application serer startup cached files:

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-core-client-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-commons-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-journal-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-jms-2.2.21.Final.jar

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-core-2.2.21.Final.jar

            ./APP_SERVER/server/felix-cache/bundle43/version0.0/bundle.jar-embedded/hornetq-native-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-server-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-core-client-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-jms-client-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-commons-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-journal-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-bootstrap-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-native-2.4.7.Final.jar

            ./APP_SERVER/server/felix-cache/bundle42/version0.0/bundle.jar-embedded/hornetq-jms-server-2.4.7.Final.jar

            but there is no 'logging.properties' nearby.

             

            3. During the application server startup additional HornetQ related entries can be found, maybe there is something relevant to this issue:

            [B_WARN ] 2016-09-19 10:50:52,027 [log4j] [org.hornetq.core.server] HQ222018: AIO was not located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

            [B_WARN ] 2016-09-19 10:50:52,028 [log4j] [org.hornetq.core.server] HQ222018: AIO was not located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

            [INFO   ] 2016-09-19 10:50:52,347 [log4j] [org.hornetq.core.server] HQ221000: live server is starting with configuration HornetQ Configuration (clustered=false,backup=false,sharedStore=true,journalDirectory=../data/journal,bindingsDirectory=../data/bindings,largeMessagesDirectory=../data/large-messages,pagingDirectory=../data/paging)

            [INFO   ] 2016-09-19 10:50:52,347 [log4j] [org.hornetq.core.server] HQ221000: live server is starting with configuration HornetQ Configuration (clustered=false,backup=false,sharedStore=true,journalDirectory=../data/journal,bindingsDirectory=../data/bindings,largeMessagesDirectory=../data/large-messages,pagingDirectory=../data/paging)

            [B_WARN ] 2016-09-19 10:50:52,356 [log4j] [org.hornetq.core.server] HQ222007: Security risk! HornetQ is running with the default cluster admin user and default password. Please see the HornetQ user guide, cluster chapter, for instructions on how to change this.

            [B_WARN ] 2016-09-19 10:50:52,356 [log4j] [org.hornetq.core.server] HQ222007: Security risk! HornetQ is running with the default cluster admin user and default password. Please see the HornetQ user guide, cluster chapter, for instructions on how to change this.

            [INFO   ] 2016-09-19 10:50:52,622 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.DLQ

            [INFO   ] 2016-09-19 10:50:52,622 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.DLQ

            [INFO   ] 2016-09-19 10:50:52,791 [log4j] [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 localhost:5455 for CORE protocol

            [INFO   ] 2016-09-19 10:50:52,791 [log4j] [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 localhost:5455 for CORE protocol

            [INFO   ] 2016-09-19 10:50:52,792 [log4j] [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 localhost:5445 for CORE protocol

            [INFO   ] 2016-09-19 10:50:52,792 [log4j] [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 localhost:5445 for CORE protocol

            [INFO   ] 2016-09-19 10:50:52,793 [log4j] [org.hornetq.core.server] HQ221007: Server is now live

            [INFO   ] 2016-09-19 10:50:52,794 [log4j] [org.hornetq.core.server] HQ221007: Server is now live

            [INFO   ] 2016-09-19 10:50:52,795 [log4j] [org.hornetq.core.server] HQ221001: HornetQ Server version 2.3.2.Snapshot (Killer Bee, 123) [81d0a311-7b21-11e6-879e-1d904eb2ef52]

            [INFO   ] 2016-09-19 10:50:52,794 [log4j] [org.hornetq.core.server] HQ221001: HornetQ Server version 2.3.2.Snapshot (Killer Bee, 123) [81d0a311-7b21-11e6-879e-1d904eb2ef52]

            [INFO   ] 2016-09-19 10:50:52,932 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestNodeManager

            [INFO   ] 2016-09-19 10:50:52,932 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestNodeManager

            [INFO   ] 2016-09-19 10:50:52,995 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultNodeManager

            [INFO   ] 2016-09-19 10:50:52,995 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultNodeManager

            [INFO   ] 2016-09-19 10:50:53,008 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestCalculation

            [INFO   ] 2016-09-19 10:50:53,008 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestCalculation

            [INFO   ] 2016-09-19 10:50:53,061 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultCalculation1

            [INFO   ] 2016-09-19 10:50:53,061 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultCalculation1

            [INFO   ] 2016-09-19 10:50:53,073 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestDataService

            [INFO   ] 2016-09-19 10:50:53,073 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.requestDataService

            [INFO   ] 2016-09-19 10:50:53,127 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultDataService

            [INFO   ] 2016-09-19 10:50:53,127 [log4j] [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.resultDataService

             

            Any thoughts on this?

            • 3. Re: HQ224016 message in the logs
              jbertram

              It certainly seems odd that all the log entries are repeated.  I don't think there's much more for me to investigate without a reproducible test-case.

               

              BTW, I recommend you move to Apache ActiveMQ Artemis ASAP as the HornetQ codebase was donated to Apache a few years back and is now the Apache ActiveMQ Artemis broker.  The HornetQ project itself hasn't been touched in a few years.

              • 4. Re: HQ224016 message in the logs
                dev151

                Hello Justin,

                 

                Thanks for the advice, but for the budget and organizational reasons migration to different messaging library is not an option at the moment.

                 

                In the mean time I managed to log more detailed message and stack trace:

                HQ119027: Could not find reference on consumer ID=0, messageId = 6,518 queue = jms.queue.resultNodeManager

                HornetQIllegalStateException[errorType=ILLEGAL_STATE message=HQ119027: Could not find reference on consumer ID=0, messageId = 6,518 queue = jms.queue.resultNodeManager]

                        at org.hornetq.core.server.impl.ServerConsumerImpl.acknowledge(ServerConsumerImpl.java:760)

                        at org.hornetq.core.server.impl.ServerSessionImpl.acknowledge(ServerSessionImpl.java:685)

                        at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:297)

                        at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:641)

                        at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:523)

                        at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:502)

                        at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:669)

                        at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.channelRead(HornetQChannelHandler.java:73)

                        at io.netty.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:338)

                        at io.netty.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:324)

                        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:153)

                        at io.netty.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:338)

                        at io.netty.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:324)

                        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:785)

                        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:122)

                        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:485)

                        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:452)

                        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:346)

                        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:101)

                        at java.lang.Thread.run(Unknown Source)

                 

                Secondly, after this error appeared in the logs I can find frequent messages logged from standard error output :

                [STDERR] Oct 13, 2016 9:17:28 AM org.hornetq.core.client.impl.ClientProducerCreditsImpl acquireCredits

                [STDERR] WARN: HQ212054: Destination address=jms.queue.resultNodeManager is blocked. If the system is configured to block make sure you consume messages on this configuration.

                 

                Any idea what can be the real reason of this issue and suggestions how to fix it?

                • 5. Re: HQ224016 message in the logs
                  jbertram

                  I'm not sure what the problem could be at this point.  As I indicated, HornetQ 2.4.7.Final is several years old at this point and much work has been done since it's release so it's hard to trouble-shoot at this point.