Clustered HornetQ and paging with STOMP v2.4.0Beta1
bra Aug 29, 2013 6:56 PMI've a 2.4.0Beta1 setup of four machines, fully meshed into a cluster.
When I send some messages into a topic, into server A and had (it's disconnected at the time of mass sending of the messages) a durable subscriber to server D, server A creates a paging directory with this:
# ls -la /data/hornetq/paging/0d519f59-1083-11e3-887b-4198a5760958/
total 5
drwxr-xr-x 2 messagebus messagebus 4 Aug 29 10:14 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 0 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
and server D has a directory with these:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/
total 13256
drwxr-xr-x 2 messagebus messagebus 10 Aug 29 10:17 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 1508743 Aug 29 10:18 000000007.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Until this is reached, the producer on server A has just been disconnected (lost connection with server A):
DEBUG:stomp.py:Sending a heartbeat message
ERROR:stomp.py:Lost connection
DEBUG:stomp.py:Receiver loop ended
ERROR:stomp.py:Error sending frame: [Errno 32] Broken pipe
A top on this machine (server A) says:
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
45464 messagebus 83 20 0 1555M 1211M uwait 1 57:32 718.80% java
and it's so slow, that I can see each characters printed into the log file, with the speed like when I would type them.
BTW, I can see this in server A's log after its client has disconnected:
08:17:49,779 WARN [org.hornetq.core.server] HQ222068: connection closed org.hornetq.core.protocol.stomp.StompConnection@3638ffab
08:17:49,778 ERROR [org.hornetq.core.server] HQ224055: Bridge Failed to ack: java.lang.NullPointerException
at org.hornetq.core.journal.impl.TimedBuffer.checkSize(TimedBuffer.java:241) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.AbstractSequentialFile.fits(AbstractSequentialFile.java:216) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.switchFileIfNecessary(JournalImpl.java:3137) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.appendRecord(JournalImpl.java:2761) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.appendUpdateRecord(JournalImpl.java:853) [hornetq-journal.jar:]
at org.hornetq.core.persistence.impl.journal.JournalStorageManager.storeAcknowledge(JournalStorageManager.java:947) [hornetq-server.jar:]
at org.hornetq.core.server.impl.QueueImpl.acknowledge(QueueImpl.java:991) [hornetq-server.jar:]
at org.hornetq.core.server.cluster.impl.BridgeImpl.sendAcknowledged(BridgeImpl.java:495) [hornetq-server.jar:]
at org.hornetq.core.client.impl.ClientSessionImpl.callSendAck(ClientSessionImpl.java:1400) [hornetq-core-client.jar:]
at org.hornetq.core.client.impl.ClientSessionImpl.commandConfirmed(ClientSessionImpl.java:1380) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.ChannelImpl.clearUpTo(ChannelImpl.java:672) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:601) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:547) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:523) [hornetq-core-client.jar:]
at org.hornetq.core.client.impl.ClientSessionFactoryImpl$DelegatingBufferHandler.bufferReceived(ClientSessionFactoryImpl.java:1660) [hornetq-core-client.jar:]
at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.messageReceived(HornetQChannelHandler.java:72) [hornetq-core-client.jar:]
at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:281) [netty.jar:]
at org.hornetq.core.remoting.impl.netty.HornetQFrameDecoder2.messageReceived(HornetQFrameDecoder2.java:122) [hornetq-core-client.jar:]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303) [netty.jar:]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty.jar:]
at org.jboss.netty.channel.socket.oio.OioWorker.process(OioWorker.java:71) [netty.jar:]
at org.jboss.netty.channel.socket.oio.AbstractOioWorker.run(AbstractOioWorker.java:73) [netty.jar:]
at org.jboss.netty.channel.socket.oio.OioWorker.run(OioWorker.java:51) [netty.jar:]
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty.jar:]
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty.jar:]
at org.jboss.netty.util.VirtualExecutorService$ChildExecutorRunnable.run(VirtualExecutorService.java:175) [netty.jar:]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]
at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
08:23:02,629 ERROR [org.hornetq.core.client] HQ214017: Caught unexpected Throwable: java.lang.OutOfMemoryError: Java heap space
08:22:12,798 WARNING [org.jboss.netty.channel.socket.oio.OioServerSocketPipelineSink] Failed to accept a connection.: java.lang.OutOfMemoryError: Java heap space
HornetQ on server A remains unusable, eating all CPU resources it can.
After this, I consume all(?) messages with the client connected to server D, until it won't receive more. The paging directory on server D is like above after this.
When I restart server A (kill -9), it has this in paging (001.page disappeared):
# ls -la /data/hornetq/paging/0d519f59-1083-11e3-887b-4198a5760958/
total 4
drwxr-xr-x 2 messagebus messagebus 3 Aug 29 10:28 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
and after its restart and cluster reconnect, server D starts to grow its page files:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/
total 21194
drwxr-xr-x 2 messagebus messagebus 13 Aug 29 10:29 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 8707346 Aug 29 10:29 000000010.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
to the point where is starts to log a lot of:
08:30:36,374 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=1216144,priority=4, bodySize=690,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@7259f725, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@7070d8c9, Xrealm=dynamic, JMSType=null, Xstatustype=STOP, content-length=219, Xsystem=wired, destination=jms.topic.radius}]]@11054539
08:30:36,390 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=1216145,priority=4, bodySize=612,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@4229eac3, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@4df3ca24, Xrealm=fixip, JMSType=null, Xstatustype=STOP, content-length=153, Xsystem=wired, destination=jms.topic.radius}]]@1079781751
After the flow of these logs entries cease, paging starts to grow again (without anything in the logs):
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/; date
total 31603
drwxr-xr-x 2 messagebus messagebus 18 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 7624395 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:34:21 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 32028
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 81344 Aug 29 10:34 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:34:28 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33665
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6085914 Aug 29 10:35 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:35:07 CEST 2013
And now server D eats the CPU:
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
46239 messagebus 83 20 0 1606M 1152M uwait 6 18:45 693.80% java
And more the CPU it uses, the less the speed of growth in page files:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33832
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6899174 Aug 29 10:37 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:37:04 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33832
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6900393 Aug 29 10:37 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:37:13 CEST 2013
In this state, I can't connect to the server with the consumer application.
When I restart (kill -9) server D, it starts with a millions of:
08:38:57,020 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,316 found and discarded
08:38:57,023 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,321 found and discarded
08:38:57,027 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,326 found and discarded
08:38:57,030 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,331 found and discarded
08:38:57,035 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,336 found and discarded
08:38:57,039 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,341 found and discarded
08:38:57,042 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,346 found and discarded
lines.
After these:
08:44:01,889 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 1,741,604 found and discarded
08:44:01,891 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 1,741,608 found and discarded
08:44:02,452 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:0.0.0.0} with 0.0.0.0
08:44:02,455 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.port:61616} with 61616
08:44:02,456 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:localhost} with localhost
08:44:02,458 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.batch.port:5455} with 5455
08:44:02,460 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:172.28.60.5} with 172.28.60.5
08:44:02,462 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:172.28.60.6} with 172.28.60.6
08:44:02,464 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:10.20.88.5} with 10.20.88.5
08:44:02,465 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:10.20.88.6} with 10.20.88.6
08:44:02,600 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.DLQ
08:44:02,621 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.ExpiryQueue
08:44:02,628 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.radius
08:44:02,635 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.topic.radius
08:44:02,648 INFO [org.hornetq.jms.server] HQ121005: Invalid "host" value "0.0.0.0" detected for "netty" connector. Switching to "mq00k". If this new address is incorrect please manually configure the connector to use the proper one.
08:44:02,714 ERROR [org.hornetq.core.server] HQ224005: Unable to deply node [connection-factory: null]: HornetQIllegalStateException[errorType=ILLEGAL_STATE message=HQ129005: Connector {0} not found on the main configuration file]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCFPOJO(JMSServerManagerImpl.java:1367) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCF(JMSServerManagerImpl.java:1314) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.access$1300(JMSServerManagerImpl.java:105) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl$5.runException(JMSServerManagerImpl.java:1175) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.runAfterActive(JMSServerManagerImpl.java:1835) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.createConnectionFactory(JMSServerManagerImpl.java:1161) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deployConnectionFactory(JMSServerDeployer.java:181) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.createAndBindObject(JMSServerDeployer.java:108) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deploy(JMSServerDeployer.java:95) [hornetq-jms-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.deploy(XmlDeployer.java:182) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.FileDeploymentManager.registerDeployer(FileDeploymentManager.java:130) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.start(XmlDeployer.java:212) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.activated(JMSServerManagerImpl.java:244) [hornetq-jms-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.callActivateCallbacks(HornetQServerImpl.java:1410) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1633) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.access$1400(HornetQServerImpl.java:170) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation.run(HornetQServerImpl.java:2121) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:426) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:483) [hornetq-jms-server.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
at org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59) [jboss-mc.jar:]
at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150) [jboss-mc.jar:]
at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBean(AbstractKernelDeployer.java:319) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBeans(AbstractKernelDeployer.java:297) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deploy(AbstractKernelDeployer.java:130) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.xml.BeanXMLDeployer.deploy(BeanXMLDeployer.java:96) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:236) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:206) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:154) [hornetq-bootstrap.jar:]
at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:115) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:69) [hornetq-bootstrap.jar:]
08:44:02,813 ERROR [org.hornetq.core.server] HQ224005: Unable to deply node [connection-factory: null]: HornetQIllegalStateException[errorType=ILLEGAL_STATE message=HQ129005: Connector {0} not found on the main configuration file]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCFPOJO(JMSServerManagerImpl.java:1367) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCF(JMSServerManagerImpl.java:1314) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.access$1300(JMSServerManagerImpl.java:105) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl$5.runException(JMSServerManagerImpl.java:1175) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.runAfterActive(JMSServerManagerImpl.java:1835) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.createConnectionFactory(JMSServerManagerImpl.java:1161) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deployConnectionFactory(JMSServerDeployer.java:181) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.createAndBindObject(JMSServerDeployer.java:108) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deploy(JMSServerDeployer.java:95) [hornetq-jms-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.deploy(XmlDeployer.java:182) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.FileDeploymentManager.registerDeployer(FileDeploymentManager.java:130) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.start(XmlDeployer.java:212) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.activated(JMSServerManagerImpl.java:244) [hornetq-jms-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.callActivateCallbacks(HornetQServerImpl.java:1410) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1633) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.access$1400(HornetQServerImpl.java:170) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation.run(HornetQServerImpl.java:2121) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:426) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:483) [hornetq-jms-server.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
at org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59) [jboss-mc.jar:]
at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150) [jboss-mc.jar:]
at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBean(AbstractKernelDeployer.java:319) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBeans(AbstractKernelDeployer.java:297) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deploy(AbstractKernelDeployer.java:130) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.xml.BeanXMLDeployer.deploy(BeanXMLDeployer.java:96) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:236) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:206) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:154) [hornetq-bootstrap.jar:]
at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:115) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:69) [hornetq-bootstrap.jar:]
08:44:03,026 INFO [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 0.0.0.0:61616 for CORE protocol
after this, the cluster stands up and starts a flood of:
08:45:35,367 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806207,priority=4, bodySize=700,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@4b1788f4, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@762071af, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=227, Xsystem=wired, destination=jms.topic.radius}]]@1275581631
08:45:35,418 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806208,priority=4, bodySize=722,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@23ec1e48, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@62b81b64, Xrealm=dynamic, JMSType=null, Xstatustype=INTERIM_UPDATE, content-length=231, Xsystem=wired, destination=jms.topic.radius}]]@621704414
08:45:35,442 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806214,priority=4, bodySize=673,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@581aadd3, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@3f8a24d5, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=200, Xsystem=wired, destination=jms.topic.radius}]]@108543114
08:45:35,468 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806220,priority=4, bodySize=637,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@3fce8b57, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@111e1d7b, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=164, Xsystem=wired, destination=jms.topic.radius}]]@1344372484
From there, publishing to server A and consuming from server D doesn't work. To get out this situation, I have to delete journal and paging, restart the servers, and everything starts to work again.
I don't use transactions, just simple STOMP sends. HornetQ runs on FreeBSD 9/amd64,
# java -version
openjdk version "1.7.0_25"
OpenJDK Runtime Environment (build 1.7.0_25-b15)
OpenJDK 64-Bit Server VM (build 23.21-b01, mixed mode)
I use the distribution shipped run.sh, without any JVM tuning.
Is this the same (just in larger scale) as in the case of OP?
BTW, when I stop the other three machines (and delete the hornetq data dir, but still using the same cluster config) and start the durable subscriber (to make the subscription), then stop it, sending some messages till this:
I've a 2.4.0Beta1 setup of four machines, fully meshed into a cluster.
When I send some messages into a topic, into server A and had (it's disconnected at the time of mass sending of the messages) a durable subscriber to server D, server A creates a paging directory with this:
# ls -la /data/hornetq/paging/0d519f59-1083-11e3-887b-4198a5760958/
total 5
drwxr-xr-x 2 messagebus messagebus 4 Aug 29 10:14 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 0 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
and server D has a directory with these:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/
total 13256
drwxr-xr-x 2 messagebus messagebus 10 Aug 29 10:17 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 1508743 Aug 29 10:18 000000007.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Until this is reached, the producer on server A has just been disconnected (lost connection with server A):
DEBUG:stomp.py:Sending a heartbeat message
ERROR:stomp.py:Lost connection
DEBUG:stomp.py:Receiver loop ended
ERROR:stomp.py:Error sending frame: [Errno 32] Broken pipe
A top on this machine (server A) says:
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
45464 messagebus 83 20 0 1555M 1211M uwait 1 57:32 718.80% java
and it's so slow, that I can see each characters printed into the log file, with the speed like when I would type them.
BTW, I can see this in server A's log after its client has disconnected:
08:17:49,779 WARN [org.hornetq.core.server] HQ222068: connection closed org.hornetq.core.protocol.stomp.StompConnection@3638ffab
08:17:49,778 ERROR [org.hornetq.core.server] HQ224055: Bridge Failed to ack: java.lang.NullPointerException
at org.hornetq.core.journal.impl.TimedBuffer.checkSize(TimedBuffer.java:241) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.AbstractSequentialFile.fits(AbstractSequentialFile.java:216) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.switchFileIfNecessary(JournalImpl.java:3137) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.appendRecord(JournalImpl.java:2761) [hornetq-journal.jar:]
at org.hornetq.core.journal.impl.JournalImpl.appendUpdateRecord(JournalImpl.java:853) [hornetq-journal.jar:]
at org.hornetq.core.persistence.impl.journal.JournalStorageManager.storeAcknowledge(JournalStorageManager.java:947) [hornetq-server.jar:]
at org.hornetq.core.server.impl.QueueImpl.acknowledge(QueueImpl.java:991) [hornetq-server.jar:]
at org.hornetq.core.server.cluster.impl.BridgeImpl.sendAcknowledged(BridgeImpl.java:495) [hornetq-server.jar:]
at org.hornetq.core.client.impl.ClientSessionImpl.callSendAck(ClientSessionImpl.java:1400) [hornetq-core-client.jar:]
at org.hornetq.core.client.impl.ClientSessionImpl.commandConfirmed(ClientSessionImpl.java:1380) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.ChannelImpl.clearUpTo(ChannelImpl.java:672) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:601) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:547) [hornetq-core-client.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:523) [hornetq-core-client.jar:]
at org.hornetq.core.client.impl.ClientSessionFactoryImpl$DelegatingBufferHandler.bufferReceived(ClientSessionFactoryImpl.java:1660) [hornetq-core-client.jar:]
at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.messageReceived(HornetQChannelHandler.java:72) [hornetq-core-client.jar:]
at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:281) [netty.jar:]
at org.hornetq.core.remoting.impl.netty.HornetQFrameDecoder2.messageReceived(HornetQFrameDecoder2.java:122) [hornetq-core-client.jar:]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443) [netty.jar:]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303) [netty.jar:]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty.jar:]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty.jar:]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty.jar:]
at org.jboss.netty.channel.socket.oio.OioWorker.process(OioWorker.java:71) [netty.jar:]
at org.jboss.netty.channel.socket.oio.AbstractOioWorker.run(AbstractOioWorker.java:73) [netty.jar:]
at org.jboss.netty.channel.socket.oio.OioWorker.run(OioWorker.java:51) [netty.jar:]
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty.jar:]
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty.jar:]
at org.jboss.netty.util.VirtualExecutorService$ChildExecutorRunnable.run(VirtualExecutorService.java:175) [netty.jar:]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]
at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
08:23:02,629 ERROR [org.hornetq.core.client] HQ214017: Caught unexpected Throwable: java.lang.OutOfMemoryError: Java heap space
08:22:12,798 WARNING [org.jboss.netty.channel.socket.oio.OioServerSocketPipelineSink] Failed to accept a connection.: java.lang.OutOfMemoryError: Java heap space
HornetQ on server A remains unusable, eating all CPU resources it can.
After this, I consume all(?) messages with the client connected to server D, until it won't receive more. The paging directory on server D is like above after this.
When I restart server A (kill -9), it has this in paging (001.page disappeared):
# ls -la /data/hornetq/paging/0d519f59-1083-11e3-887b-4198a5760958/
total 4
drwxr-xr-x 2 messagebus messagebus 3 Aug 29 10:28 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
and after its restart and cluster reconnect, server D starts to grow its page files:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/
total 21194
drwxr-xr-x 2 messagebus messagebus 13 Aug 29 10:29 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 8707346 Aug 29 10:29 000000010.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
to the point where is starts to log a lot of:
08:30:36,374 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=1216144,priority=4, bodySize=690,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@7259f725, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@7070d8c9, Xrealm=dynamic, JMSType=null, Xstatustype=STOP, content-length=219, Xsystem=wired, destination=jms.topic.radius}]]@11054539
08:30:36,390 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=1216145,priority=4, bodySize=612,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@4229eac3, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@4df3ca24, Xrealm=fixip, JMSType=null, Xstatustype=STOP, content-length=153, Xsystem=wired, destination=jms.topic.radius}]]@1079781751
After the flow of these logs entries cease, paging starts to grow again (without anything in the logs):
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/; date
total 31603
drwxr-xr-x 2 messagebus messagebus 18 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 7624395 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:34:21 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 32028
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 81344 Aug 29 10:34 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:34:28 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33665
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6085914 Aug 29 10:35 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:35:07 CEST 2013
And now server D eats the CPU:
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
46239 messagebus 83 20 0 1606M 1152M uwait 6 18:45 693.80% java
And more the CPU it uses, the less the speed of growth in page files:
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33832
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6899174 Aug 29 10:37 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:37:04 CEST 2013
# ls -la /data/hornetq/paging/0305354d-1083-11e3-a54e-673d6e1c1ca6/ ; date
total 33832
drwxr-xr-x 2 messagebus messagebus 19 Aug 29 10:34 .
drwxr-xr-x 3 messagebus messagebus 3 Aug 29 10:14 ..
-rw-r--r-- 1 messagebus messagebus 10485575 Aug 29 10:14 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485756 Aug 29 10:15 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485374 Aug 29 10:15 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485148 Aug 29 10:15 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485639 Aug 29 10:16 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485207 Aug 29 10:17 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485603 Aug 29 10:28 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485478 Aug 29 10:29 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485520 Aug 29 10:29 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 10:32 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485504 Aug 29 10:32 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485225 Aug 29 10:33 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485564 Aug 29 10:33 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485161 Aug 29 10:34 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485449 Aug 29 10:34 000000015.page
-rw-r--r-- 1 messagebus messagebus 6900393 Aug 29 10:37 000000016.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 10:14 address.txt
Thu Aug 29 10:37:13 CEST 2013
In this state, I can't connect to the server with the consumer application.
When I restart (kill -9) server D, it starts with a millions of:
08:38:57,020 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,316 found and discarded
08:38:57,023 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,321 found and discarded
08:38:57,027 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,326 found and discarded
08:38:57,030 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,331 found and discarded
08:38:57,035 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,336 found and discarded
08:38:57,039 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,341 found and discarded
08:38:57,042 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 982,346 found and discarded
lines.
After these:
08:44:01,889 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 1,741,604 found and discarded
08:44:01,891 WARN [org.hornetq.journal] HQ142015: Uncommitted transaction with id 1,741,608 found and discarded
08:44:02,452 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:0.0.0.0} with 0.0.0.0
08:44:02,455 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.port:61616} with 61616
08:44:02,456 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:localhost} with localhost
08:44:02,458 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.batch.port:5455} with 5455
08:44:02,460 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:172.28.60.5} with 172.28.60.5
08:44:02,462 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:172.28.60.6} with 172.28.60.6
08:44:02,464 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:10.20.88.5} with 10.20.88.5
08:44:02,465 DEBUG [org.hornetq.core.client] replacing ${hornetq.remoting.netty.host:10.20.88.6} with 10.20.88.6
08:44:02,600 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.DLQ
08:44:02,621 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.ExpiryQueue
08:44:02,628 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.queue.radius
08:44:02,635 INFO [org.hornetq.core.server] HQ221003: trying to deploy queue jms.topic.radius
08:44:02,648 INFO [org.hornetq.jms.server] HQ121005: Invalid "host" value "0.0.0.0" detected for "netty" connector. Switching to "mq00k". If this new address is incorrect please manually configure the connector to use the proper one.
08:44:02,714 ERROR [org.hornetq.core.server] HQ224005: Unable to deply node [connection-factory: null]: HornetQIllegalStateException[errorType=ILLEGAL_STATE message=HQ129005: Connector {0} not found on the main configuration file]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCFPOJO(JMSServerManagerImpl.java:1367) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCF(JMSServerManagerImpl.java:1314) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.access$1300(JMSServerManagerImpl.java:105) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl$5.runException(JMSServerManagerImpl.java:1175) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.runAfterActive(JMSServerManagerImpl.java:1835) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.createConnectionFactory(JMSServerManagerImpl.java:1161) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deployConnectionFactory(JMSServerDeployer.java:181) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.createAndBindObject(JMSServerDeployer.java:108) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deploy(JMSServerDeployer.java:95) [hornetq-jms-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.deploy(XmlDeployer.java:182) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.FileDeploymentManager.registerDeployer(FileDeploymentManager.java:130) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.start(XmlDeployer.java:212) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.activated(JMSServerManagerImpl.java:244) [hornetq-jms-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.callActivateCallbacks(HornetQServerImpl.java:1410) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1633) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.access$1400(HornetQServerImpl.java:170) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation.run(HornetQServerImpl.java:2121) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:426) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:483) [hornetq-jms-server.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
at org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59) [jboss-mc.jar:]
at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150) [jboss-mc.jar:]
at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBean(AbstractKernelDeployer.java:319) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBeans(AbstractKernelDeployer.java:297) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deploy(AbstractKernelDeployer.java:130) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.xml.BeanXMLDeployer.deploy(BeanXMLDeployer.java:96) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:236) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:206) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:154) [hornetq-bootstrap.jar:]
at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:115) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:69) [hornetq-bootstrap.jar:]
08:44:02,813 ERROR [org.hornetq.core.server] HQ224005: Unable to deply node [connection-factory: null]: HornetQIllegalStateException[errorType=ILLEGAL_STATE message=HQ129005: Connector {0} not found on the main configuration file]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCFPOJO(JMSServerManagerImpl.java:1367) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.internalCreateCF(JMSServerManagerImpl.java:1314) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.access$1300(JMSServerManagerImpl.java:105) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl$5.runException(JMSServerManagerImpl.java:1175) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.runAfterActive(JMSServerManagerImpl.java:1835) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.createConnectionFactory(JMSServerManagerImpl.java:1161) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deployConnectionFactory(JMSServerDeployer.java:181) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.createAndBindObject(JMSServerDeployer.java:108) [hornetq-jms-server.jar:]
at org.hornetq.jms.server.impl.JMSServerDeployer.deploy(JMSServerDeployer.java:95) [hornetq-jms-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.deploy(XmlDeployer.java:182) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.FileDeploymentManager.registerDeployer(FileDeploymentManager.java:130) [hornetq-server.jar:]
at org.hornetq.core.deployers.impl.XmlDeployer.start(XmlDeployer.java:212) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.activated(JMSServerManagerImpl.java:244) [hornetq-jms-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.callActivateCallbacks(HornetQServerImpl.java:1410) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1633) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.access$1400(HornetQServerImpl.java:170) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation.run(HornetQServerImpl.java:2121) [hornetq-server.jar:]
at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:426) [hornetq-server.jar:]
at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:483) [hornetq-jms-server.jar:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
at org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59) [jboss-mc.jar:]
at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150) [jboss-mc.jar:]
at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-mc.jar:]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-mc.jar:]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774) [jboss-mc.jar:]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBean(AbstractKernelDeployer.java:319) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deployBeans(AbstractKernelDeployer.java:297) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.deploy(AbstractKernelDeployer.java:130) [jboss-mc.jar:]
at org.jboss.kernel.plugins.deployment.xml.BeanXMLDeployer.deploy(BeanXMLDeployer.java:96) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:236) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.deploy(HornetQBootstrapServer.java:206) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:154) [hornetq-bootstrap.jar:]
at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83) [jboss-mc.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:115) [hornetq-bootstrap.jar:]
at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:69) [hornetq-bootstrap.jar:]
08:44:03,026 INFO [org.hornetq.core.server] HQ221020: Started Netty Acceptor version 3.6.6.Final-90e1eb2 0.0.0.0:61616 for CORE protocol
after this, the cluster stands up and starts a flood of:
08:45:35,367 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806207,priority=4, bodySize=700,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@4b1788f4, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@762071af, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=227, Xsystem=wired, destination=jms.topic.radius}]]@1275581631
08:45:35,418 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806208,priority=4, bodySize=722,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@23ec1e48, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@62b81b64, Xrealm=dynamic, JMSType=null, Xstatustype=INTERIM_UPDATE, content-length=231, Xsystem=wired, destination=jms.topic.radius}]]@621704414
08:45:35,442 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806214,priority=4, bodySize=673,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@581aadd3, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@3f8a24d5, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=200, Xsystem=wired, destination=jms.topic.radius}]]@108543114
08:45:35,468 WARN [org.hornetq.core.server] HQ222058: Duplicate message detected through the bridge - message will not be routed. Message information:
ServerMessage[messageID=2147806220,priority=4, bodySize=637,expiration=0, durable=true, address=jms.topic.radius,properties=TypedProperties[{_HQ_BRIDGE_DUP=[B@3fce8b57, JMSCorrelationID=null, _HQ_ROUTE_TO=[B@111e1d7b, Xrealm=dynamic, JMSType=null, Xstatustype=START, content-length=164, Xsystem=wired, destination=jms.topic.radius}]]@1344372484
From there, publishing to server A and consuming from server D doesn't work. To get out this situation, I have to delete journal and paging, restart the servers, and everything starts to work again.
I don't use transactions, just simple STOMP sends. HornetQ runs on FreeBSD 9/amd64,
# java -version
openjdk version "1.7.0_25"
OpenJDK Runtime Environment (build 1.7.0_25-b15)
OpenJDK 64-Bit Server VM (build 23.21-b01, mixed mode)
I use the distribution shipped run.sh, without any JVM tuning.
Is this the same (just in larger scale) as in the case of OP?
BTW, when I stop the other three machines (and delete the hornetq data dir, but still using the same cluster config) and start the durable subscriber (to make the subscription), then stop it, sending some messages:
# ls -l /data/hornetq/paging/*/
total 36539
-rw-r--r-- 1 messagebus messagebus 10485174 Aug 29 11:08 000000001.page
-rw-r--r-- 1 messagebus messagebus 10485662 Aug 29 11:08 000000002.page
-rw-r--r-- 1 messagebus messagebus 10485698 Aug 29 11:09 000000003.page
-rw-r--r-- 1 messagebus messagebus 10485749 Aug 29 11:09 000000004.page
-rw-r--r-- 1 messagebus messagebus 10485635 Aug 29 11:09 000000005.page
-rw-r--r-- 1 messagebus messagebus 10485230 Aug 29 11:10 000000006.page
-rw-r--r-- 1 messagebus messagebus 10485576 Aug 29 11:10 000000007.page
-rw-r--r-- 1 messagebus messagebus 10485466 Aug 29 11:10 000000008.page
-rw-r--r-- 1 messagebus messagebus 10485650 Aug 29 11:11 000000009.page
-rw-r--r-- 1 messagebus messagebus 10485203 Aug 29 11:11 000000010.page
-rw-r--r-- 1 messagebus messagebus 10485383 Aug 29 11:11 000000011.page
-rw-r--r-- 1 messagebus messagebus 10485193 Aug 29 11:12 000000012.page
-rw-r--r-- 1 messagebus messagebus 10485455 Aug 29 11:12 000000013.page
-rw-r--r-- 1 messagebus messagebus 10485407 Aug 29 11:12 000000014.page
-rw-r--r-- 1 messagebus messagebus 10485169 Aug 29 11:12 000000015.page
-rw-r--r-- 1 messagebus messagebus 10485305 Aug 29 11:13 000000016.page
-rw-r--r-- 1 messagebus messagebus 10485643 Aug 29 11:13 000000017.page
-rw-r--r-- 1 messagebus messagebus 1931571 Aug 29 11:13 000000018.page
-rw-r--r-- 1 messagebus messagebus 17 Aug 29 11:08 address.txt
then stop the producer and start the consumer, it can consume some messages and stop.
Heart beats goes, the connection remains up, but nothing comes.
Restarting the consumer doesn't help.
Restarting the broker doesn't help.
Is paging ready for the prime time, or it's just me, who screws up something badly?
Thanks,
ps: it may be relevant, that I'm using a selector with the durable subscription.