You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by jayh <lo...@hotmail.com> on 2019/04/02 19:30:58 UTC
Error occured while processing sync command: ActiveMQTextMessage
Can anyone please help me understand this error which has only just started
showing up out of nowhere on a production server.
This is the current version of AMQ (5.15.9) and was also seen in the
previous version 5.15.8. Its a local broker with a JMS bridge to a remote
server connecting and consuming a mix of topics and queues which are
presented locally for internal use. The server config is unchanged when this
issue first showed up.
It was first noticed through the increase in memory usage for storage of the
DB files. On closer inspection it looked like clients where disconnecting
and reconnecting with no error on the client and only the following logged
on the server side;
2019-03-29 01:50:15,134 | INFO | JmsConnector handling loss of connection
[ActiveMQConnection
{id=ID:xs-43093-1553805148029-2:2,clientId=ID:xs-43093-1553805148029-1:2,started=true}]
| org.apache.activemq.network.jms.JmsConnector | ActiveMQ Session Task-348
A deeper dig into the TRACE logs tonight while the server was slightly less
busy relieved the following logged. I've also noted the connection count is
now sat at more than 170 where as there are only 20 something consumers
actually connected right now.
2019-04-02 19:29:20,360 | TRACE | ID:xs-39837-1553964750839-4:140:2 sending
message:
ActiveMQTextMessage {commandId = 3319310, responseRequired = false, mes
sageId = ID:xs-39837-1553964750839-4:140:2:1:1, originalDestination = null,
originalTransactionId = null, producerId =
ID:xs-39837-1553964750839-4:140:2:1,
destination = topic://CLIENT_ALL, transactionId = null, expiration = 0,
timestamp =
1554229760360, arrival = 0, brokerInTime = 1554229755115, brokerOutTime = 15
54229755118, correlationId = null, replyTo = null, persistent = true, type =
null, priority =
4, groupID = null, groupSequence = 0, targetConsumerId = null,
compressed = true, userID = null, content =
org.apache.activemq.util.ByteSequence@2a02b7e9,
marshalledProperties = org.apache.activemq.util.ByteSequence@7d
db0ca1, dataStructure = null, redeliveryCounter = 0, size = 0, properties =
null,
readOnlyProperties = true, readOnlyBody = true, droppable = false,
jmsXGroupFirstForConsumer
= false, text =
[{"XP_MSG":{"time":"1554229754000","area_id":...r":"TEST"}}]} |
org.apache.activemq.ActiveMQSession | ActiveMQ Session Task-4447
2019-04-02 19:29:20,360 | TRACE | Running task iteration 0 -
vm://xs.dev.local#279 |
org.apache.activemq.thread.PooledTaskRunner | ActiveMQ VMTransport:
vm://xs.dev.local#279-1
2019-04-02 19:29:20,400 | DEBUG | Error occured while processing sync
command:
ActiveMQTextMessage {commandId = 7, responseRequired = true, messageId =
ID:xs-39837-
1553964750839-4:140:2:1:1, originalDestination = null, originalTransactionId
= null,
producerId = ID:xs-39837-1553964750839-4:140:2:1, destination =
topic://CLIENT_ALL, transactionId
= null, expiration = 0, timestamp = 1554229760360, arrival = 0, brokerInTime
= 1554229760361,
brokerOutTime = 1554229755118, correlationId = null, replyTo = null,
persistent = true, type
= null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
null, compressed
= true, userID = null, content =
org.apache.activemq.util.ByteSequence@2a02b7e9,
marshalledProperties = org.apache.activemq.util.ByteSequence@7ddb0ca1,
dataStructure = null,
redeliveryCounter = 0, size = 1595, properties = null, readOnlyProperties =
true,
readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false,
text =
[{"XP_MSG":{"time":"1554229754000","area_id":...r":"TEST"}}]}, exception:
java.io.EOFException |
org.apache.activemq.broker.TransportConnection.Service | ActiveMQ
VMTransport: vm://xs.dev.local#279-1
java.io.EOFException
at
java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)[:1.8.0_201]
at
java.io.DataInputStream.readUTF(DataInputStream.java:589)[:1.8.0_201]
at
java.io.DataInputStream.readUTF(DataInputStream.java:564)[:1.8.0_201]
at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
(MarshallingSupport.java:97)[activemq-client-5.15.9.jar:5.15.9]
at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
(MarshallingSupport.java:78)[activemq-client-5.15.9.jar:5.15.9]
at org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
(MarshallingSupport.java:70)[activemq-client-5.15.9.jar:5.15.9]
at
org.apache.activemq.command.Message.unmarsallProperties(Message.java:252)
[activemq-client-5.15.9.jar:5.15.9]
at
org.apache.activemq.command.Message.getProperty(Message.java:202)[activemq-
client-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.policy.RetainedMessageSubscriptionRecoveryPolicy.add
(RetainedMessageSubscriptionRecoveryPolicy.java:53)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.Topic.dispatch(Topic.java:756)[activemq-broker-
5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.Topic.doMessageSend(Topic.java:556)[activemq-
broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.Topic.send(Topic.java:484)[activemq-broker-
5.15.9.jar:5.15.9]
at org.apache.activemq.broker.region.DestinationFilter.send
(DestinationFilter.java:138)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:508)
[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:459)
[activemq-broker-5.15.9.jar:5.15.9]
at org.apache.activemq.broker.jmx.ManagedRegionBroker.send
(ManagedRegionBroker.java:293)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
broker-5.15.9.jar:5.15.9]
at org.apache.activemq.broker.CompositeDestinationBroker.send
(CompositeDestinationBroker.java:96)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:293)
[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
broker-5.15.9.jar:5.15.9]
at org.apache.activemq.security.AuthorizationBroker.send
(AuthorizationBroker.java:226)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
broker-5.15.9.jar:5.15.9]
at org.apache.activemq.broker.TransportConnection.processMessage
(TransportConnection.java:578)[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:768)
[activemq-client-5.15.9.jar:5.15.9]
at org.apache.activemq.broker.TransportConnection.service
(TransportConnection.java:336)[activemq-broker-5.15.9.jar:5.15.9]
at org.apache.activemq.broker.TransportConnection$1.onCommand
(TransportConnection.java:200)[activemq-broker-5.15.9.jar:5.15.9]
at org.apache.activemq.transport.ResponseCorrelator.onCommand
(ResponseCorrelator.java:116)[activemq-client-5.15.9.jar:5.15.9]
at
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
[activemq-client-5.15.9.jar:5.15.9]
at
org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:275)
[activemq-broker-5.15.9.jar:5.15.9]
at
org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
[activemq-client-5.15.9.jar:5.15.9]
at
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
[activemq-client-5.15.9.jar:5.15.9]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[:1.8.0_201]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[:1.8.0_201]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_201]
Consumers are on the same local host using stomp (current version) via ruby.
The clients don't appear to exhibit any errors when this happens, but my
dequeued message rate is millions per day so it's not very easy to check. I
have an identical AMQ deployment on another test VM consuming and processing
the same data and that system does not have the same issues.
Can anyone point me in the right direction as to how to start diagnosing
this issue. I suspect in the next 24hours or so I'm going to have an OOM
crash so may restart the broker tonight and clear the storage DB manually.
--
Sent from: http://activemq.2283324.n4.nabble.com/ActiveMQ-User-f2341805.html
Re: Error occured while processing sync command:
ActiveMQTextMessage
Posted by jayh <lo...@hotmail.com>.
Had some more time to look, and even with just 2 consumers connected I still
see *11* of those disconnections for no reason where the consumer is on the
localhost and connected via localhost.
Digging into the JMX I see hundreds of 'Dynamic Destination Producers'
created but that's about it. No further forward, and still not seen a single
issue on the identical test VM :(
Any idea why its *always* 11 of these disconnections, and then 11 new
connections?!
--
Sent from: http://activemq.2283324.n4.nabble.com/ActiveMQ-User-f2341805.html
Re: Error occured while processing sync command:
ActiveMQTextMessage
Posted by jayh <lo...@hotmail.com>.
The broker believes there are now 189+ connections, and my connection count
it up to 216. Looking this morning with advisory topics enabled I see 100's
of 'dead' connections to temp topics all showing;
No connection could be found for ID ID:xs-39837-1553964750839-3:71
I thought about the clients but there local (127.0.0.1) to the broker - I
was able to free up some memory last night by stopping a few of the clients
and deleting there subscription's - no more errors till this morning and I'm
back up to 60% usage.
The weird things is I *always* and *only* get 11 of these error messages at
a time no matter how many clients are connected... Until I can do a full
broker restart tonight or over the weekend (depending on loading) I can't
see if that's an artefact of previous problems or if the number 11 is
actually significant.
Thanks for your ideas - I'll try and have a look this evening - as of this
morning my test vm is still quite happy with no errors. Just one thought;
could this be IO related?! While the clients don't appear to report anything
this machine is very busy with DB writes etc, I wonder if the client is
tripping over something silently.
Do you have 170 TCP connections, or is it just the broker that believes
that there are that many?
The fact that the broker is seeing an EOFException means that the client is
closing the connection, so I'd focus on your consumers. I know you said you
don't think they're having errors, but that's what this looks like to me,
so I'd focus on that.
A packet sniffer like Wireshark might help you to confirm that assumption,
though it might be harder if you can't reproduce the problem on demand...
Tim
--
Sent from: http://activemq.2283324.n4.nabble.com/ActiveMQ-User-f2341805.html
Re: Error occured while processing sync command: ActiveMQTextMessage
Posted by Tim Bain <tb...@alumni.duke.edu>.
Do you have 170 TCP connections, or is it just the broker that believes
that there are that many?
The fact that the broker is seeing an EOFException means that the client is
closing the connection, so I'd focus on your consumers. I know you said you
don't think they're having errors, but that's what this looks like to me,
so I'd focus on that.
A packet sniffer like Wireshark might help you to confirm that assumption,
though it might be harder if you can't reproduce the problem on demand...
Tim
On Tue, Apr 2, 2019, 1:31 PM jayh <lo...@hotmail.com> wrote:
> Can anyone please help me understand this error which has only just started
> showing up out of nowhere on a production server.
>
> This is the current version of AMQ (5.15.9) and was also seen in the
> previous version 5.15.8. Its a local broker with a JMS bridge to a remote
> server connecting and consuming a mix of topics and queues which are
> presented locally for internal use. The server config is unchanged when
> this
> issue first showed up.
>
> It was first noticed through the increase in memory usage for storage of
> the
> DB files. On closer inspection it looked like clients where disconnecting
> and reconnecting with no error on the client and only the following logged
> on the server side;
>
> 2019-03-29 01:50:15,134 | INFO | JmsConnector handling loss of connection
> [ActiveMQConnection
>
> {id=ID:xs-43093-1553805148029-2:2,clientId=ID:xs-43093-1553805148029-1:2,started=true}]
> | org.apache.activemq.network.jms.JmsConnector | ActiveMQ Session Task-348
>
> A deeper dig into the TRACE logs tonight while the server was slightly less
> busy relieved the following logged. I've also noted the connection count is
> now sat at more than 170 where as there are only 20 something consumers
> actually connected right now.
>
> 2019-04-02 19:29:20,360 | TRACE | ID:xs-39837-1553964750839-4:140:2 sending
> message:
> ActiveMQTextMessage {commandId = 3319310, responseRequired = false, mes
> sageId = ID:xs-39837-1553964750839-4:140:2:1:1, originalDestination =
> null,
> originalTransactionId = null, producerId =
> ID:xs-39837-1553964750839-4:140:2:1,
> destination = topic://CLIENT_ALL, transactionId = null, expiration = 0,
> timestamp =
> 1554229760360, arrival = 0, brokerInTime = 1554229755115, brokerOutTime =
> 15
> 54229755118, correlationId = null, replyTo = null, persistent = true, type
> =
> null, priority =
> 4, groupID = null, groupSequence = 0, targetConsumerId = null,
> compressed = true, userID = null, content =
> org.apache.activemq.util.ByteSequence@2a02b7e9,
> marshalledProperties = org.apache.activemq.util.ByteSequence@7d
> db0ca1, dataStructure = null, redeliveryCounter = 0, size = 0, properties =
> null,
> readOnlyProperties = true, readOnlyBody = true, droppable = false,
> jmsXGroupFirstForConsumer
> = false, text =
> [{"XP_MSG":{"time":"1554229754000","area_id":...r":"TEST"}}]} |
> org.apache.activemq.ActiveMQSession | ActiveMQ Session Task-4447
> 2019-04-02 19:29:20,360 | TRACE | Running task iteration 0 -
> vm://xs.dev.local#279 |
> org.apache.activemq.thread.PooledTaskRunner | ActiveMQ VMTransport:
> vm://xs.dev.local#279-1
> 2019-04-02 19:29:20,400 | DEBUG | Error occured while processing sync
> command:
> ActiveMQTextMessage {commandId = 7, responseRequired = true, messageId =
> ID:xs-39837-
> 1553964750839-4:140:2:1:1, originalDestination = null,
> originalTransactionId
> = null,
> producerId = ID:xs-39837-1553964750839-4:140:2:1, destination =
> topic://CLIENT_ALL, transactionId
> = null, expiration = 0, timestamp = 1554229760360, arrival = 0,
> brokerInTime
> = 1554229760361,
> brokerOutTime = 1554229755118, correlationId = null, replyTo = null,
> persistent = true, type
> = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
> null, compressed
> = true, userID = null, content =
> org.apache.activemq.util.ByteSequence@2a02b7e9,
> marshalledProperties = org.apache.activemq.util.ByteSequence@7ddb0ca1,
> dataStructure = null,
> redeliveryCounter = 0, size = 1595, properties = null, readOnlyProperties =
> true,
> readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false,
> text =
> [{"XP_MSG":{"time":"1554229754000","area_id":...r":"TEST"}}]}, exception:
> java.io.EOFException |
> org.apache.activemq.broker.TransportConnection.Service | ActiveMQ
> VMTransport: vm://xs.dev.local#279-1
> java.io.EOFException
> at
>
> java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)[:1.8.0_201]
> at
> java.io.DataInputStream.readUTF(DataInputStream.java:589)[:1.8.0_201]
> at
> java.io.DataInputStream.readUTF(DataInputStream.java:564)[:1.8.0_201]
> at
> org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
> (MarshallingSupport.java:97)[activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
> (MarshallingSupport.java:78)[activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.util.MarshallingSupport.unmarshalPrimitiveMap
> (MarshallingSupport.java:70)[activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.command.Message.unmarsallProperties(Message.java:252)
> [activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.command.Message.getProperty(Message.java:202)[activemq-
> client-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.region.policy.RetainedMessageSubscriptionRecoveryPolicy.add
>
> (RetainedMessageSubscriptionRecoveryPolicy.java:53)[activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.region.Topic.dispatch(Topic.java:756)[activemq-broker-
> 5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.region.Topic.doMessageSend(Topic.java:556)[activemq-
> broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.region.Topic.send(Topic.java:484)[activemq-broker-
> 5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.region.DestinationFilter.send
> (DestinationFilter.java:138)[activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:508)
> [activemq-broker-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:459)
> [activemq-broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.send
> (ManagedRegionBroker.java:293)[activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
> broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.CompositeDestinationBroker.send
> (CompositeDestinationBroker.java:96)[activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:293)
> [activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
> broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
> broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.security.AuthorizationBroker.send
> (AuthorizationBroker.java:226)[activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)[activemq-
> broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.TransportConnection.processMessage
> (TransportConnection.java:578)[activemq-broker-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:768)
> [activemq-client-5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.TransportConnection.service
> (TransportConnection.java:336)[activemq-broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.broker.TransportConnection$1.onCommand
> (TransportConnection.java:200)[activemq-broker-5.15.9.jar:5.15.9]
> at org.apache.activemq.transport.ResponseCorrelator.onCommand
> (ResponseCorrelator.java:116)[activemq-client-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> [activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:275)
> [activemq-broker-5.15.9.jar:5.15.9]
> at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> [activemq-client-5.15.9.jar:5.15.9]
> at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> [activemq-client-5.15.9.jar:5.15.9]
> at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> [:1.8.0_201]
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> [:1.8.0_201]
> at java.lang.Thread.run(Thread.java:748)[:1.8.0_201]
>
> Consumers are on the same local host using stomp (current version) via
> ruby.
> The clients don't appear to exhibit any errors when this happens, but my
> dequeued message rate is millions per day so it's not very easy to check. I
> have an identical AMQ deployment on another test VM consuming and
> processing
> the same data and that system does not have the same issues.
>
> Can anyone point me in the right direction as to how to start diagnosing
> this issue. I suspect in the next 24hours or so I'm going to have an OOM
> crash so may restart the broker tonight and clear the storage DB manually.
>
>
>
>
> --
> Sent from:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-User-f2341805.html
>