You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by Claudio Tagliola <cl...@imc.nl> on 2016/01/21 17:18:38 UTC

ActiveMQBytesMessage decompress throws DataFormatException incorrect header check

We are trying to upgrade our ActiveMQ dependency from 5.8.0 to something newer. In our environment, we use an embedded broker with useCompression set to true. After the upgrade to any version after 5.9.1, we see some unfortunate side effects on a test client which is listening on a topic where ActiveMQBytesMessages are posted. The following exception is thrown while running a test suite which publishes around 100k ActiveMQBytesMessages on a non persistent topic. It is very reproducible on about 95% of all runs, but only once or maybe a few times per run:

11:04:21.075 [ActiveMQ Session Task-1] ERROR  o.a.activemq.ActiveMQMessageConsumer - ID:hostname-43481-1453197809985-15:1:12:1 Exception while processing message: ID:hostname-57271-1453197780850-6:2:1:3:95106
java.lang.RuntimeException: Failed to deserialize a message (ActiveMQBytesMessage {commandId = 3702, responseRequired = false, messageId = ID:office388-44548-1453286940386-5:1:1:3:1229, originalDestination = null, originalTransactionId = null, producerId = ID:office388-44548-1453286940386-5:1:1:3, destination = topic://com.foo.bar, transactionId = null, expiration = 1453287566063, timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064, brokerOutTime = 1453286966064, correlationId = null, replyTo = null, persistent = false, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = true, userID = null, content = org.apache.activemq.util.ByteSequence@7ec950bb, marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e, dataStructure = null, redeliveryCounter = 0, size = 0, properties = {mapped=1453286966034, received=1453286965865, source=3, published=1453286959733, type=TEST, class=2884, party=TEST}, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut = null, dataOut = null, dataIn = null }).
        at com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57) ~[foobar.jar:amq513-SNAPSHOT]
        at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1393) ~[activemq-client.jar:5.13.0]
        at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131) [activemq-client.jar:5.13.0]
        at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202) [activemq-client.jar:5.13.0]
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) [activemq-client.jar:5.13.0]
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) [activemq-client.jar:5.13.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_45]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
Caused by: javax.jms.JMSException: java.util.zip.DataFormatException: incorrect header check
        at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72) ~[activemq-client.jar:5.13.0]
        at org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:884) ~[activemq-client.jar:5.13.0]
        at org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:198) ~[activemq-client.jar:5.13.0]
        at com.foo.bar.JmsSerializerHelper.deserialize(JmsSerializerHelper.java:52) ~[foobar-client.jar:1761]
        at com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53) ~[foobar.jar:amq513-SNAPSHOT]
        ... 8 common frames omitted
Caused by: java.io.IOException: java.util.zip.DataFormatException: incorrect header check
        at org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:902) ~[activemq-client.jar:5.13.0]
        at org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:876) ~[activemq-client.jar:5.13.0]
        ... 11 common frames omitted
Caused by: java.util.zip.DataFormatException: incorrect header check
        at java.util.zip.Inflater.inflateBytes(Native Method) ~[na:1.8.0_45]
        at java.util.zip.Inflater.inflate(Inflater.java:259) ~[na:1.8.0_45]
        at java.util.zip.Inflater.inflate(Inflater.java:280) ~[na:1.8.0_45]
        at org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:898) ~[activemq-client.jar:5.13.0]
        ... 12 common frames omitted

In one occasion, a different cause was shown:

Caused by: java.lang.NegativeArraySizeException: null
        at org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:897) ~[activemq-client.jar:5.13.0]

I have reproduced this with 5.10.0, 5.10.1, 5.10.2, 5.11.3 and 5.13.0. It is not reproducible on 5.8.0 (our current version) and 5.9.1. The stacktrace on 5.10.0 is slightly different:

java.lang.RuntimeException: Failed to deserialize a message (ActiveMQBytesMessage {commandId = 3702, responseRequired = false, messageId = ID:office388-44548-1453286940386-5:1:1:3:1229, originalDestination = null, originalTransactionId = null, producerId = ID:office388-44548-1453286940386-5:1:1:3, destination = topic://com.foo.bar, transactionId = null, expiration = 1453287566063, timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064, brokerOutTime = 1453286966064, correlationId = null, replyTo = null, persistent = false, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = true, userID = null, content = org.apache.activemq.util.ByteSequence@7ec950bb, marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e, dataStructure = null, redeliveryCounter = 0, size = 0, properties = {mapped=1453286966034, received=1453286965865, source=3, published=1453286959733, type=TEST, class=2884, party=TEST}, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut = null, dataOut = null, dataIn = null })
    at com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57) ~[classes/:na]
    at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1390) ~[activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131) [activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202) [activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) [activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) [activemq-client-5.10.0.jar:5.10.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_66]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_66]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]
Caused by: javax.jms.JMSException: java.lang.NegativeArraySizeException
    at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72) ~[activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:890) ~[activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:199) ~[activemq-client-5.10.0.jar:5.10.0]
    at com.foo.ba.rJmsSerializerHelper.deserialize(JmsSerializerHelper.java:52) ~[foundations-rpc-client-70.1761.jar:70.1761]
    at com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53) ~[classes/:na]
    ... 8 common frames omitted
Caused by: java.io.IOException: java.lang.NegativeArraySizeException
    at org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:908) ~[activemq-client-5.10.0.jar:5.10.0]
    at org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:882) ~[activemq-client-5.10.0.jar:5.10.0]
    ... 11 common frames omitted
Caused by: java.lang.NegativeArraySizeException: null
    at org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:903) ~[activemq-client-5.10.0.jar:5.10.0]
    ... 12 common frames omitted

This points me towards AMQ-4887<https://issues.apache.org/jira/browse/AMQ-4887> and AMQ-5381<https://issues.apache.org/jira/browse/AMQ-5381> which correlate with the versions when it starts failing and the code changes that have been made in ActiveMQBytesMessage.

Halting the process with a debugger does not give me much extra information, there is content in the Inflater buffer, but the native method Inflater.inflateBytes just throws the exception. Both client and server are running on the same machine, same JDK. Running with 1.8.0_66 has the same effect. What I did see was that the actual compressed bytes at that point were different between what the server sent and what the client received, which points to client side buffer corruption. Both the compress on the server side as well as the decompress methods were always called from the same thread, so there does not seem to be a multi-threaded race condition at that location, although it might be somewhere else in the stack.

Disabling compression on the server side will make the error go away. I have not found any other flag that has effect on this yet.

I could not find any recent issues logged, is this something other people also encountered? I'm currently trying to isolate the code and create a test setup, but that's quite an undertaking so please bear with me.

Thank you,
Claudio

________________________________

The information in this e-mail is intended only for the person or entity to which it is addressed.

It may contain confidential and /or privileged material. If someone other than the intended recipient should receive this e-mail, he / she shall not be entitled to read, disseminate, disclose or duplicate it.

If you receive this e-mail unintentionally, please inform us immediately by "reply" and then delete it from your system. Although this information has been compiled with great care, neither IMC Financial Markets & Asset Management nor any of its related entities shall accept any responsibility for any errors, omissions or other inaccuracies in this information or for the consequences thereof, nor shall it be bound in any way by the contents of this e-mail or its attachments. In the event of incomplete or incorrect transmission, please return the e-mail to the sender and permanently delete this message and any attachments.

Messages and attachments are scanned for all known viruses. Always scan attachments before opening them.

Re: ActiveMQBytesMessage decompress throws DataFormatException incorrect header check

Posted by Claudio Tagliola <cl...@imc.nl>.
I've isolated the scenario with a small Server/Client class, I've
created a ticket and added them there:
https://issues.apache.org/jira/browse/AMQ-6142

The culprit is the fact the server is listening in on a topic over the
VM transport on an embedded broker. By listening in, the pending message
is decompressed again and in some occasion, this corrupts the byte array
for clients which are connected over tcp. This is a regression from
5.8.0/5.9.1 to later, presumably caused by AMQ-4887.

HTH,


On 21-01-16 17:23, Timothy Bish wrote:
> There have been no reports of such an error, if you can isolate the case
> into a JUnit test I'd recommend opening a new JIRA issue and attaching
> it there.
>
> On 01/21/2016 11:18 AM, Claudio Tagliola wrote:
>> We are trying to upgrade our ActiveMQ dependency from 5.8.0 to
>> something newer. In our environment, we use an embedded broker with
>> useCompression set to true. After the upgrade to any version after
>> 5.9.1, we see some unfortunate side effects on a test client which is
>> listening on a topic where ActiveMQBytesMessages are posted. The
>> following exception is thrown while running a test suite which
>> publishes around 100k ActiveMQBytesMessages on a non persistent topic.
>> It is very reproducible on about 95% of all runs, but only once or
>> maybe a few times per run:
>>
>> 11:04:21.075 [ActiveMQ Session Task-1] ERROR
>> o.a.activemq.ActiveMQMessageConsumer -
>> ID:hostname-43481-1453197809985-15:1:12:1 Exception while processing
>> message: ID:hostname-57271-1453197780850-6:2:1:3:95106
>> java.lang.RuntimeException: Failed to deserialize a message
>> (ActiveMQBytesMessage {commandId = 3702, responseRequired = false,
>> messageId = ID:office388-44548-1453286940386-5:1:1:3:1229,
>> originalDestination = null, originalTransactionId = null, producerId =
>> ID:office388-44548-1453286940386-5:1:1:3, destination =
>> topic://com.foo.bar, transactionId = null, expiration = 1453287566063,
>> timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064,
>> brokerOutTime = 1453286966064, correlationId = null, replyTo = null,
>> persistent = false, type = null, priority = 4, groupID = null,
>> groupSequence = 0, targetConsumerId = null, compressed = true, userID
>> = null, content = org.apache.activemq.util.ByteSequence@7ec950bb,
>> marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e,
>> dataStructure = null, redeliveryCounter = 0, size = 0, properties =
>> {mapped=1453286966034, received=1453286965865, source=3,
>> published=1453286959733, type=TEST, class=2884, party=TEST},
>> readOnlyProperties = true, readOnlyBody = true, droppable = false,
>> jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut =
>> null, dataOut = null, dataIn = null }).
>>         at
>> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57)
>> ~[foobar.jar:amq513-SNAPSHOT]
>>         at
>> org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1393)
>> ~[activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
>> [activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
>> [activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>> [activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>> [activemq-client.jar:5.13.0]
>>         at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> [na:1.8.0_45]
>>         at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> [na:1.8.0_45]
>>         at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
>> Caused by: javax.jms.JMSException: java.util.zip.DataFormatException:
>> incorrect header check
>>         at
>> org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72)
>> ~[activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:884)
>> ~[activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:198)
>> ~[activemq-client.jar:5.13.0]
>>         at
>> com.foo.bar.JmsSerializerHelper.deserialize(JmsSerializerHelper.java:52)
>> ~[foobar-client.jar:1761]
>>         at
>> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53)
>> ~[foobar.jar:amq513-SNAPSHOT]
>>         ... 8 common frames omitted
>> Caused by: java.io.IOException: java.util.zip.DataFormatException:
>> incorrect header check
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:902)
>> ~[activemq-client.jar:5.13.0]
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:876)
>> ~[activemq-client.jar:5.13.0]
>>         ... 11 common frames omitted
>> Caused by: java.util.zip.DataFormatException: incorrect header check
>>         at java.util.zip.Inflater.inflateBytes(Native Method)
>> ~[na:1.8.0_45]
>>         at java.util.zip.Inflater.inflate(Inflater.java:259)
>> ~[na:1.8.0_45]
>>         at java.util.zip.Inflater.inflate(Inflater.java:280)
>> ~[na:1.8.0_45]
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:898)
>> ~[activemq-client.jar:5.13.0]
>>         ... 12 common frames omitted
>>
>> In one occasion, a different cause was shown:
>>
>> Caused by: java.lang.NegativeArraySizeException: null
>>         at
>> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:897)
>> ~[activemq-client.jar:5.13.0]
>>
>> I have reproduced this with 5.10.0, 5.10.1, 5.10.2, 5.11.3 and 5.13.0.
>> It is not reproducible on 5.8.0 (our current version) and 5.9.1. The
>> stacktrace on 5.10.0 is slightly different:
>>
>> java.lang.RuntimeException: Failed to deserialize a message
>> (ActiveMQBytesMessage {commandId = 3702, responseRequired = false,
>> messageId = ID:office388-44548-1453286940386-5:1:1:3:1229,
>> originalDestination = null, originalTransactionId = null, producerId =
>> ID:office388-44548-1453286940386-5:1:1:3, destination =
>> topic://com.foo.bar, transactionId = null, expiration = 1453287566063,
>> timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064,
>> brokerOutTime = 1453286966064, correlationId = null, replyTo = null,
>> persistent = false, type = null, priority = 4, groupID = null,
>> groupSequence = 0, targetConsumerId = null, compressed = true, userID
>> = null, content = org.apache.activemq.util.ByteSequence@7ec950bb,
>> marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e,
>> dataStructure = null, redeliveryCounter = 0, size = 0, properties =
>> {mapped=1453286966034, received=1453286965865, source=3,
>> published=1453286959733, type=TEST, class=2884, party=TEST},
>> readOnlyProperties = true, readOnlyBody = true, droppable = false,
>> jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut =
>> null, dataOut = null, dataIn = null })
>>     at
>> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57)
>> ~[classes/:na]
>>     at
>> org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1390)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
>> [activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
>> [activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>> [activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>> [activemq-client-5.10.0.jar:5.10.0]
>>     at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> [na:1.8.0_66]
>>     at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> [na:1.8.0_66]
>>     at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]
>> Caused by: javax.jms.JMSException: java.lang.NegativeArraySizeException
>>     at
>> org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:890)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:199)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     at
>> com.foo.ba.rJmsSerializerHelper.deserialize(JmsSerializerHelper.java:52)
>> ~[foundations-rpc-client-70.1761.jar:70.1761]
>>     at
>> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53)
>> ~[classes/:na]
>>     ... 8 common frames omitted
>> Caused by: java.io.IOException: java.lang.NegativeArraySizeException
>>     at
>> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:908)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     at
>> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:882)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     ... 11 common frames omitted
>> Caused by: java.lang.NegativeArraySizeException: null
>>     at
>> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:903)
>> ~[activemq-client-5.10.0.jar:5.10.0]
>>     ... 12 common frames omitted
>>
>> This points me towards
>> AMQ-4887<https://issues.apache.org/jira/browse/AMQ-4887> and
>> AMQ-5381<https://issues.apache.org/jira/browse/AMQ-5381> which
>> correlate with the versions when it starts failing and the code
>> changes that have been made in ActiveMQBytesMessage.
>>
>> Halting the process with a debugger does not give me much extra
>> information, there is content in the Inflater buffer, but the native
>> method Inflater.inflateBytes just throws the exception. Both client
>> and server are running on the same machine, same JDK. Running with
>> 1.8.0_66 has the same effect. What I did see was that the actual
>> compressed bytes at that point were different between what the server
>> sent and what the client received, which points to client side buffer
>> corruption. Both the compress on the server side as well as the
>> decompress methods were always called from the same thread, so there
>> does not seem to be a multi-threaded race condition at that location,
>> although it might be somewhere else in the stack.
>>
>> Disabling compression on the server side will make the error go away.
>> I have not found any other flag that has effect on this yet.
>>
>> I could not find any recent issues logged, is this something other
>> people also encountered? I'm currently trying to isolate the code and
>> create a test setup, but that's quite an undertaking so please bear
>> with me.
>>
>> Thank you,
>> Claudio
>>
>> ________________________________
>>
>> The information in this e-mail is intended only for the person or
>> entity to which it is addressed.
>>
>> It may contain confidential and /or privileged material. If someone
>> other than the intended recipient should receive this e-mail, he / she
>> shall not be entitled to read, disseminate, disclose or duplicate it.
>>
>> If you receive this e-mail unintentionally, please inform us
>> immediately by "reply" and then delete it from your system. Although
>> this information has been compiled with great care, neither IMC
>> Financial Markets & Asset Management nor any of its related entities
>> shall accept any responsibility for any errors, omissions or other
>> inaccuracies in this information or for the consequences thereof, nor
>> shall it be bound in any way by the contents of this e-mail or its
>> attachments. In the event of incomplete or incorrect transmission,
>> please return the e-mail to the sender and permanently delete this
>> message and any attachments.
>>
>> Messages and attachments are scanned for all known viruses. Always
>> scan attachments before opening them.
>>
>


________________________________

The information in this e-mail is intended only for the person or entity to which it is addressed.

It may contain confidential and /or privileged material. If someone other than the intended recipient should receive this e-mail, he / she shall not be entitled to read, disseminate, disclose or duplicate it.

If you receive this e-mail unintentionally, please inform us immediately by "reply" and then delete it from your system. Although this information has been compiled with great care, neither IMC Financial Markets & Asset Management nor any of its related entities shall accept any responsibility for any errors, omissions or other inaccuracies in this information or for the consequences thereof, nor shall it be bound in any way by the contents of this e-mail or its attachments. In the event of incomplete or incorrect transmission, please return the e-mail to the sender and permanently delete this message and any attachments.

Messages and attachments are scanned for all known viruses. Always scan attachments before opening them.

Re: ActiveMQBytesMessage decompress throws DataFormatException incorrect header check

Posted by Timothy Bish <ta...@gmail.com>.
There have been no reports of such an error, if you can isolate the case
into a JUnit test I'd recommend opening a new JIRA issue and attaching
it there.

On 01/21/2016 11:18 AM, Claudio Tagliola wrote:
> We are trying to upgrade our ActiveMQ dependency from 5.8.0 to
> something newer. In our environment, we use an embedded broker with
> useCompression set to true. After the upgrade to any version after
> 5.9.1, we see some unfortunate side effects on a test client which is
> listening on a topic where ActiveMQBytesMessages are posted. The
> following exception is thrown while running a test suite which
> publishes around 100k ActiveMQBytesMessages on a non persistent topic.
> It is very reproducible on about 95% of all runs, but only once or
> maybe a few times per run:
>
> 11:04:21.075 [ActiveMQ Session Task-1] ERROR 
> o.a.activemq.ActiveMQMessageConsumer -
> ID:hostname-43481-1453197809985-15:1:12:1 Exception while processing
> message: ID:hostname-57271-1453197780850-6:2:1:3:95106
> java.lang.RuntimeException: Failed to deserialize a message
> (ActiveMQBytesMessage {commandId = 3702, responseRequired = false,
> messageId = ID:office388-44548-1453286940386-5:1:1:3:1229,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:office388-44548-1453286940386-5:1:1:3, destination =
> topic://com.foo.bar, transactionId = null, expiration = 1453287566063,
> timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064,
> brokerOutTime = 1453286966064, correlationId = null, replyTo = null,
> persistent = false, type = null, priority = 4, groupID = null,
> groupSequence = 0, targetConsumerId = null, compressed = true, userID
> = null, content = org.apache.activemq.util.ByteSequence@7ec950bb,
> marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e,
> dataStructure = null, redeliveryCounter = 0, size = 0, properties =
> {mapped=1453286966034, received=1453286965865, source=3,
> published=1453286959733, type=TEST, class=2884, party=TEST},
> readOnlyProperties = true, readOnlyBody = true, droppable = false,
> jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut =
> null, dataOut = null, dataIn = null }).
>        at
> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57)
> ~[foobar.jar:amq513-SNAPSHOT]
>        at
> org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1393)
> ~[activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
> [activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
> [activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> [activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> [activemq-client.jar:5.13.0]
>        at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [na:1.8.0_45]
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [na:1.8.0_45]
>        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
> Caused by: javax.jms.JMSException: java.util.zip.DataFormatException:
> incorrect header check
>        at
> org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72)
> ~[activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:884)
> ~[activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:198)
> ~[activemq-client.jar:5.13.0]
>        at
> com.foo.bar.JmsSerializerHelper.deserialize(JmsSerializerHelper.java:52)
> ~[foobar-client.jar:1761]
>        at
> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53)
> ~[foobar.jar:amq513-SNAPSHOT]
>        ... 8 common frames omitted
> Caused by: java.io.IOException: java.util.zip.DataFormatException:
> incorrect header check
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:902)
> ~[activemq-client.jar:5.13.0]
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:876)
> ~[activemq-client.jar:5.13.0]
>        ... 11 common frames omitted
> Caused by: java.util.zip.DataFormatException: incorrect header check
>        at java.util.zip.Inflater.inflateBytes(Native Method)
> ~[na:1.8.0_45]
>        at java.util.zip.Inflater.inflate(Inflater.java:259)
> ~[na:1.8.0_45]
>        at java.util.zip.Inflater.inflate(Inflater.java:280)
> ~[na:1.8.0_45]
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:898)
> ~[activemq-client.jar:5.13.0]
>        ... 12 common frames omitted
>
> In one occasion, a different cause was shown:
>
> Caused by: java.lang.NegativeArraySizeException: null
>        at
> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:897)
> ~[activemq-client.jar:5.13.0]
>
> I have reproduced this with 5.10.0, 5.10.1, 5.10.2, 5.11.3 and 5.13.0.
> It is not reproducible on 5.8.0 (our current version) and 5.9.1. The
> stacktrace on 5.10.0 is slightly different:
>
> java.lang.RuntimeException: Failed to deserialize a message
> (ActiveMQBytesMessage {commandId = 3702, responseRequired = false,
> messageId = ID:office388-44548-1453286940386-5:1:1:3:1229,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:office388-44548-1453286940386-5:1:1:3, destination =
> topic://com.foo.bar, transactionId = null, expiration = 1453287566063,
> timestamp = 1453286966063, arrival = 0, brokerInTime = 1453286966064,
> brokerOutTime = 1453286966064, correlationId = null, replyTo = null,
> persistent = false, type = null, priority = 4, groupID = null,
> groupSequence = 0, targetConsumerId = null, compressed = true, userID
> = null, content = org.apache.activemq.util.ByteSequence@7ec950bb,
> marshalledProperties = org.apache.activemq.util.ByteSequence@3e90d35e,
> dataStructure = null, redeliveryCounter = 0, size = 0, properties =
> {mapped=1453286966034, received=1453286965865, source=3,
> published=1453286959733, type=TEST, class=2884, party=TEST},
> readOnlyProperties = true, readOnlyBody = true, droppable = false,
> jmsXGroupFirstForConsumer = false} ActiveMQBytesMessage{ bytesOut =
> null, dataOut = null, dataIn = null })
>    at
> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:57)
> ~[classes/:na]
>    at
> org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1390)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
> [activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
> [activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> [activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> [activemq-client-5.10.0.jar:5.10.0]
>    at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [na:1.8.0_66]
>    at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [na:1.8.0_66]
>    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]
> Caused by: javax.jms.JMSException: java.lang.NegativeArraySizeException
>    at
> org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:890)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:199)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    at
> com.foo.ba.rJmsSerializerHelper.deserialize(JmsSerializerHelper.java:52)
> ~[foundations-rpc-client-70.1761.jar:70.1761]
>    at
> com.foo.bar.PersistEntityMessageHandlerServiceListener.onMessage(PersistEntityMessageHandlerServiceListener.java:53)
> ~[classes/:na]
>    ... 8 common frames omitted
> Caused by: java.io.IOException: java.lang.NegativeArraySizeException
>    at
> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:908)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    at
> org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:882)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    ... 11 common frames omitted
> Caused by: java.lang.NegativeArraySizeException: null
>    at
> org.apache.activemq.command.ActiveMQBytesMessage.decompress(ActiveMQBytesMessage.java:903)
> ~[activemq-client-5.10.0.jar:5.10.0]
>    ... 12 common frames omitted
>
> This points me towards
> AMQ-4887<https://issues.apache.org/jira/browse/AMQ-4887> and
> AMQ-5381<https://issues.apache.org/jira/browse/AMQ-5381> which
> correlate with the versions when it starts failing and the code
> changes that have been made in ActiveMQBytesMessage.
>
> Halting the process with a debugger does not give me much extra
> information, there is content in the Inflater buffer, but the native
> method Inflater.inflateBytes just throws the exception. Both client
> and server are running on the same machine, same JDK. Running with
> 1.8.0_66 has the same effect. What I did see was that the actual
> compressed bytes at that point were different between what the server
> sent and what the client received, which points to client side buffer
> corruption. Both the compress on the server side as well as the
> decompress methods were always called from the same thread, so there
> does not seem to be a multi-threaded race condition at that location,
> although it might be somewhere else in the stack.
>
> Disabling compression on the server side will make the error go away.
> I have not found any other flag that has effect on this yet.
>
> I could not find any recent issues logged, is this something other
> people also encountered? I'm currently trying to isolate the code and
> create a test setup, but that's quite an undertaking so please bear
> with me.
>
> Thank you,
> Claudio
>
> ________________________________
>
> The information in this e-mail is intended only for the person or
> entity to which it is addressed.
>
> It may contain confidential and /or privileged material. If someone
> other than the intended recipient should receive this e-mail, he / she
> shall not be entitled to read, disseminate, disclose or duplicate it.
>
> If you receive this e-mail unintentionally, please inform us
> immediately by "reply" and then delete it from your system. Although
> this information has been compiled with great care, neither IMC
> Financial Markets & Asset Management nor any of its related entities
> shall accept any responsibility for any errors, omissions or other
> inaccuracies in this information or for the consequences thereof, nor
> shall it be bound in any way by the contents of this e-mail or its
> attachments. In the event of incomplete or incorrect transmission,
> please return the e-mail to the sender and permanently delete this
> message and any attachments.
>
> Messages and attachments are scanned for all known viruses. Always
> scan attachments before opening them.
>


-- 
Tim Bish
twitter: @tabish121
blog: http://timbish.blogspot.com/