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.

[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?

[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?

[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.

[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?

[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.