Re: Truncated messages in 5.16.1 when using Postman

[Tim Bain <tb...@alumni.duke.edu>]

Andrew,

Let me make sure I'm understanding the specific question. I think you're
saying that messages are traversing the broker as expected, but that
logging of messages larger than 64KB is now outputting the message bodies
in debug log lines in a way that is different from the behavior under 15.13
and earlier versions. In both behaviors, the debug logs show only a few
characters of the message body, and your concern is that ActiveMQ
previously ellispized the full message and now appears to ellipsize only
the first 64KB of the content even if the message body is much larger. Do I
have that right?

If so, I don't know that I'd consider this change to be a bug, since the
exact format of debug logs is essentially a private API (so no guarantees
anyand the new behavior isn't inherently incorrect. I could also see a
performance benefit to only reading the first chunk of a very large
message, though I'm not currently able to check the source and the commit
history to see if that's actually the reason for the change.

If you'd like to see the previous behavior restored, you (or your customer)
could submit an enhancement request in JIRA, and could make an argument for
why the old approach was enough better to justify the cost of traversing
large messages in their entirety in order to ellipsize the full message.
Then members of the development community could weigh in on whether it's a
positive or negative change.

For my two cents, I'd say that ellipsizing only a chunk is fine, but in
that case we should also put an ellipsis at the end of the message content,
to indicate that what's shown is not the end of the message. That would
retain the performance benefits of the current approach, but would not give
the impression that the message has been truncated.

Tim


On Tue, Jun 15, 2021, 5:35 AM Andrew Pomponio <AP...@perforce.com>
wrote:

> Dear ActiveMQ Community,
>
> An update on the issue, we've done continued testing and found that this
> issue starts as far back as 5.15.14 and is also present in 5.16.2.
>
> On 6/12/21, 7:56 AM, "Andrew Pomponio" <AP...@perforce.com> wrote:
>
>     Dear ActiveMQ Community,
>
>     I am reaching out on behalf of a customer of ours experiencing what
> appears to be a bug (or new default limitation) in an upgraded version of
> AMQ from the version they are currently using. We have tested this behavior
> in our lab environment and are able to replicate what they are seeing using
> the following environmental components;
>
>     ActiveMQ 5.15.11 (works) and 5.16.1 (does not work)
>     Postman 8.6.1
>     72k sized payload (the exact limitations appears to be 65536 bytes)
>
>     The following test is to be run once on 5.15 and then on 5.16.
>
>     First, create a payload of random gibberish by executing the following;
>
>     dd bs=1024 count=71 </dev/random >payload-test72k.txt
>
>     cat the file and copy the contents (gibberish) into the <ns2:Data>
> tags like so;
>
>     <ns2:NormalizedMessage xmlns:ns2="http://private" xmlns:ns4="
> http://differentprivate"><ns2:BaseDescriptor><ns2:MsgID>AVSN#I64534#ajz123403252016#2016-03-25T13:15:55</ns2:MsgID><ns2:MsgType>INTF</ns2:MsgType><ns2:MsgMode>INBOUND</ns2:MsgMode><ns2:SourceTimeStamp>2021-04-28T15:28:57.294Z</ns2:SourceTimeStamp><ns2:SourceApplicationID>over
> 9000</ns2:SourceApplicationID><ns2:SourceUserID>over
> 9000</ns2:SourceUserID><ns2:SequenceTimeStamp>2021-04-28T15:28:57.294Z</ns2:SequenceTimeStamp>
> </ns2:BaseDescriptor><ns2:RoutingDescriptor><ns4:RoutingInfo><ns4:ApplicationName>over
> 9000</ns4:ApplicationName><ns4:ApplicationCode>over
> 9000</ns4:ApplicationCode><ns4:ApplicationVersion>1.0</ns4:ApplicationVersion><ns4:PublishTimeStamp>2021-04-28T15:28:57.294Z</ns4:PublishTimeStamp><ns4:Status>true</ns4:Status><ns4:StatusDescription>DocumentUploadRequest</ns4:StatusDescription>
> </ns4:RoutingInfo>
> </ns2:RoutingDescriptor><ns2:lolDescriptor><ns2:lolReferenceID>MEDDOCINT042803</ns2:lolReferenceID><ns2:AliaslolReferenceIDs><ns2:lolReferenceID>MEDDOCINT042803</ns2:lolReferenceID>
> </ns2:AliaslolReferenceIDs><ns2:lolFolderID>0</ns2:lolFolderID><ns2:ClientFileID></ns2:ClientFileID><ns2:nopeCompany><ns2:VantiveCode>QO</ns2:VantiveCode><ns2:nahbroCustID>0</ns2:nahbroCustID>
> </ns2:nopeCompany> </ns2:lolDescriptor><ns2:Payload><ns2:Data>[…]
> �M��pt=��/�s
>     .7u�a��F�{�S���Zt��R�^&�(/k�*!y���\��}I�i
>                       ��
>     �؍I�����ՙ�y1
>     ��2��˧v�i�
>               ���-F�ʅ�"��5�ԍ;C�+V[…]</ns2:Data> </ns2:Payload>
> </ns2:NormalizedMessage>
>
>     Copy the above XML into the raw body of Postman. The XML and payload
> you copy and pasted from payload-test72k.txt is going to
> http://localhost:8161/api/message/orders.input/. With ActiveMQ running in
> debug mode, using Postman, with basic authorization login, click POST. You
> should receive an output of message sent, though the message will not show
> up in the UI of AMQ. We do not need it to for the purposes of this
> experiment.
>
>     Back in a terminal from the bin directory in AMQ;
>
>     tail -200 ../data/activemq.log
>
>     You then can see in the log entries two different examples of the
> message, one that shows the full body of text being sent to ActiveMQ, and
> another that shows a condensed summary of the message being sent.
>
>     2021-06-10 07:50:44,510 | DEBUG | Sent! to destination:
> topic://orders.input. message: ActiveMQTextMessage {commandId = 0,
> responseRequired = false, messageId =
> ID:apomponio-56497-1623331633553-4:1:1:1:6, originalDestination = null,
> originalTransactionId = null, producerId = null, destination =
> topic://orders.input., transactionId = null, expiration = 0, timestamp =
> 1623333044509, arrival = 0, brokerInTime = 0, brokerOutTime = 0,
> correlationId = null, replyTo = null, persistent = true, type = null,
> priority = 5, groupID = null, groupSequence = 0, targetConsumerId = null,
> compressed = false, userID = null, content = null, marshalledProperties =
> null, dataStructure = null, redeliveryCounter = 0, size = 0, properties =
> null, readOnlyProperties = false, readOnlyBody = false, droppable = false,
> jmsXGroupFirstForConsumer = false, text = <ns2:NormalizedMessage xmlns:ns2="
> http://priv...�T�T�Z5� �]
>     } | org.apache.activemq.web.WebClient | qtp632475595-35
>
>     In the example above from the 5.16 server, we see in the text = field
> the start of our message, and right after http://priv we see … followed
> by the portion of gibberish where the message ends in the log. In our 5.15
> logs we see http://priv...zedMessage> showing us the partial ending XML
> tag of </ns2:NormalizedMessage> which is the expected behavior.
>
>     In 5.15.11, the full length of the body message shows up in the
> activemq.log file, but in 5.16.1 that same message sent exactly the same
> way is truncated around the 64k size.
>
>     Is this a known default limitation introduced in 5.16? If so, how do
> we increase it?
>
>     If this is anticipated to be a bug, what additional information, if
> any, do you need from us?
>
>
>
> This e-mail may contain information that is privileged or confidential. If
> you are not the intended recipient, please delete the e-mail and any
> attachments and notify us immediately.
>
>