fix re-setting properties on BytesMessage #1042

me3x · 2019-11-21T14:15:27Z

Sleuth JMS instrumentation cleared all properties on ActiveMQBytesMessage and was unable to put them back.

fix MessageNotWriteableException - Message body is read-only while re-setting properties on BytesMessage

please squash commits with merge

fix MessageNotWriteableException Message body is read-only while re-setting properties on BytesMessage

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

jeqo

@me3x thanks for this PR! I've added some comments to do some small refactoring. But before moving forward, this issue with BytesMessage is specific to ActiveMQ as far as I remember. If we introduce this changes, we have to make sure is not impacting users that are using other JMS providers. Have you had the opportunity to check it with other providers?

On my side, I'll try to find time to do this check with IBM MQ or Oracle JMS and validate if it works before/after this changes.

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

Co-Authored-By: Jorge Quilcate Otoya <quilcate.jorge@gmail.com>

me3x · 2019-11-25T10:17:27Z

I only tested with ActiveMQ. Please check.

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

me3x · 2019-11-25T12:06:57Z

@jeqo could you please help me to fix a test? I believe it shouldn't be failing. It probably relies on clearing properties even if there's no need to clear.

ITJmsTracingMessageConsumer>ITJms_1_1_TracingMessageConsumer.receive_customSampler:300

jeqo · 2019-11-25T22:22:38Z

Hey @me3x thanks for the fixes!

I've test it further and actually that test case is preventing to break functionality here. Let me explain:

That case is a non-traced producer sending a message, and a traced consumer with a sampler based on queue name.
traced consumer should be able to extract context from producer (null in this case) and inject context for further processing.
as in the current implementation we are returning when disjoint before reset properties, properties are kept as read-only, failing to inject context later. Check by debugging a breaking point on MessagePropagation:45

Based on this I recommend to remove disjoint flag as we need to reset properties anyway, simplifying loop logic.

jeqo · 2019-11-25T23:19:15Z

btw, I've test it with Oracle WebLogic JMS and works before (doesn't have a similar bug as ActiveMQ) and works after. So, I think we are good to merge on that side.

jeqo · 2019-11-25T23:31:06Z

@me3x , could you re-enable this IT that was validating this issue: ITJms_1_1_TracingMessageConsumer:253

If that one goes green we should be good to merge.

we need to always reset properties

me3x · 2019-11-27T09:57:30Z

I removed disjoint check. It's a little bit weird design to rely on properties being writable for this scenario, but let's merge without it.

me3x · 2019-11-27T10:02:20Z

@jeqo Should we have similar test with BytesMessage. It failed only without instance of condition. In case of ActiveMQBytesMessage, setObjectProperty will not work after I call bytesMessage.reset();

jeqo

@me3x just got the unit test enabled to validate this fix. I left some comments as well. Thanks for your patience :)

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

me3x · 2019-11-28T08:49:56Z

@jeqo do you have any idea why it started to fail? [ERROR] ITJmsTracingMessageConsumer>ITJms_1_1_TracingMessageConsumer.receive_resumesTrace_bytes:255->ITJms_1_1_TracingMessageConsumer.receive_resumesTrace:275 expected:<"463ac35c9f6413ad-8fdeb02e21ce5744-1"> but was:

jeqo · 2019-11-28T11:53:16Z

@me3x take a look to the last bytesMessage.reset() on PropertyFilter#resetBytesMessageProperties, it is closing the message again; triggering failure later when injecting context at the end:

  void handleReceive(Message message) {
    if (message == null || tracing.isNoop()) return;
    MessageConsumerRequest request = new MessageConsumerRequest(message, destination(message));

    TraceContextOrSamplingFlags extracted =
      jmsTracing.extractAndClearProperties(extractor, request, message);
    Span span = jmsTracing.nextMessagingSpan(sampler, request, extracted);

    if (!span.isNoop()) {
      span.name("receive").kind(Span.Kind.CONSUMER);
      Destination destination = destination(message);
      if (destination != null) jmsTracing.tagQueueOrTopic(request, span);
      if (remoteServiceName != null) span.remoteServiceName(remoteServiceName);

      // incur timestamp overhead only once
      long timestamp = tracing.clock(span.context()).currentTimeMicroseconds();
      span.start(timestamp).finish(timestamp);
    }
    injector.inject(span.context(), request);
  }

I think we can remove this reset and let JMS to close the message before sending it.

me3x · 2019-11-28T12:35:33Z

I tried and it didn't work without reset. It failed on JmsListener ... unable to read, because body was in write mode.

jeqo · 2019-11-28T13:55:09Z

instrumentation/jms/src/main/java/brave/jms/TracingConsumer.java

@@ -62,6 +63,9 @@ void handleReceive(Message message) {
      span.start(timestamp).finish(timestamp);
    }
    injector.inject(span.context(), request);
+    if (message instanceof BytesMessage) {
+      (BytesMessage message).reset();


@me3x sorry if I wasn't clear enough. This part is not compiling, and actually not needed. I believe jms will take care of the message itself; no need to reset ourselves. I've give a try removing this and verifying ITs locally and all's green :)

Instrumentation should left the message in the same state it started. I tried to read body in JmsListener and it failed.

jeqo · 2019-11-28T14:28:39Z

Could you add a test to show this? As you can see we have this issues based on jms design choices and bug with activemq bytes message, and we are trying to work around it. Maybe we are not considering the scenario of readOnly msgs enough, which can lead to a deeper discussion (potentially other Issue/PR). But we are currently supporting jms clients with this implementation and we are fixing specific issue with activemq messages, so I don’t think closing message for these should be added.

…

On Thu, 28 Nov 2019 at 15:02, Matúš Hennel ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In instrumentation/jms/src/main/java/brave/jms/TracingConsumer.java <#1042 (comment)>: > @@ -62,6 +63,9 @@ void handleReceive(Message message) { span.start(timestamp).finish(timestamp); } injector.inject(span.context(), request); + if (message instanceof BytesMessage) { + (BytesMessage message).reset(); Instrumentation should left the message in the same state it started. I tried to read body in JmsListener and it failed. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1042?email_source=notifications&email_token=ABPE6XO3BAMXZZBJYH6NMDDQV7FPRA5CNFSM4JQC6T4KYY3PNVWWK3TUL52HS4DFWFIHK3DMKJSXC5LFON2FEZLWNFSXPKTDN5WW2ZLOORPWSZGOCNKIGZY#discussion_r351795256>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABPE6XJRKLRUH5ZVG5NOSH3QV7FPRANCNFSM4JQC6T4A> .

me3x · 2019-11-29T14:57:52Z

I don't have a test, but here is a stack trace:

Caused by: javax.jms.MessageNotReadableException: Message body is write-only
	at org.apache.activemq.command.ActiveMQBytesMessage.checkWriteOnlyBody(ActiveMQBytesMessage.java:867) ~[activemq-client-5.15.10.jar:5.15.10]
	at org.apache.activemq.command.ActiveMQBytesMessage.initializeReading(ActiveMQBytesMessage.java:872) ~[activemq-client-5.15.10.jar:5.15.10]
	at org.apache.activemq.command.ActiveMQBytesMessage.getBodyLength(ActiveMQBytesMessage.java:203) ~[activemq-client-5.15.10.jar:5.15.10]
	at com.cs.ifs.oxygen.common.JmsUtils.getBytesMessagePayloadAsString(JmsUtils.java:27) ~[classes/:na]
	... proxies and transactions ...

	at com.cs.ifs.oxygen.am.CoreRefDataListener.onMessage(CoreRefDataListener.java:60) ~[classes/:na]

jeqo · 2019-11-29T15:24:19Z

@me3x I won't be able to help much if we don't have a test-case to check this scenario, I'm sorry.

If we want to cover this case where this change is needed, we need test cases first to prove that works and doesn't affect other scenarios.

If we need to review how we are handling JMS messages and if we need to reset them or not at the end, I'd prefer to take this on another PR and only solve issue with ActiveMQ Bytes Message here first.

me3x · 2019-11-29T16:18:46Z

from javax.jms.BytesMessage:

If {@code clearBody} is called on a message in read-only mode,
the message body is cleared and the message is in write-only mode.
If a client attempts to read a message in write-only mode, a
{@code MessageNotReadableException} is thrown.

me3x · 2019-11-29T16:21:35Z

I removed body reset. I'll create another PR

jeqo · 2019-11-29T19:10:22Z

@me3x I've second thoughts about my previous comments. I realize now that we are only "touching" message content on this PR and not in the existing implementation where we deal with properties only, then we have to solve the read-only issue here. Sorry for the confusion.

To have temporal bytesMessage handling on the same place, we can move changes upper to TracingConsumer instead of PropertyFilter. Here is a draft with some comments:

  void handleReceive(Message message) {
    if (message == null || tracing.isNoop()) return;
    MessageConsumerRequest request = new MessageConsumerRequest(message, destination(message));

    byte[] body = null;
    if (message instanceof BytesMessage) {
      try {
        BytesMessage bytesMessage = (BytesMessage) message;
        body = new byte[(int) bytesMessage.getBodyLength()];
        //bytesMessage.reset(); // do we need this reset() before reading?
        bytesMessage.readBytes(body);
        bytesMessage.clearBody(); // any exception after this can lead to loose message
      } catch (Throwable t) {
        propagateIfFatal(t);
        //log(t, "error getting property {0} from message {1}", name, message);
        return;
      }
    }

    TraceContextOrSamplingFlags extracted =
      jmsTracing.extractAndClearProperties(extractor, request, message);
    // ....current code
    injector.inject(span.context(), request);

    if (message instanceof BytesMessage) {
      try {
        BytesMessage bytesMessage = (BytesMessage) message;
        bytesMessage.writeBytes(body);
        bytesMessage.reset();
      } catch (Throwable t) {
        propagateIfFatal(t);
        //log(t, "error getting property {0} from message {1}", name, message);
        //return;
      }
    }
  }

This will also mean we can rollback some of the changes on PropertyFilter back: mainly property names enumeration was enough (we are not using disjoint anymore).

Lastly, I'm worried about the impact of this changes as we are carrying the technical debt of an ActiveMQ bug, as well as touching message content. I'm asking other contributors (@openzipkin/brave) to give feedback here.

There are different options from my point of view: (1) add this workaround and maintain it until activemq client is fixed. (2) move this workaround to a new module (e.g. activemq) which will only impact/help ActiveMQ users (3) have this workaround on another repo (e.g. inside openzipkin-contrib) until bug is fixed.

Sorry if this is late in the review process.

me3x · 2019-12-02T09:21:02Z

@jeqo We should read properties immediately after clearing the body and than we can write body back. We don't have to wait. Clearing it is the only way to put the message to write mode, but it will remain writable until reset.

jeqo · 2019-12-02T10:44:23Z

@me3x right, so we can do the write back right after the clearBody isn't it? This is much better. What do you think on moving things to TracingConsumer?

We can test if possible reduce the filter even further by adding (message instanceof BytesMessage && message.getClass().getName().equals("org.apache.activemq.command.ActiveMQBytesMessage")), so we can go for option 1 and keep the fix as part of the current module. I'll test this today.

me3x · 2019-12-02T12:17:16Z

@jeqo It's a good idea. I found that it's used also in class JmsTracing and TracingMessageListener, so there are 3 places. Do we have ActiveMQBytesMessage class available? If not, maybe it could be part of some recovery after exception?

me3x · 2019-12-02T12:18:32Z

@jeqo I mean current behavior is the worst possible, because we loose user's properties completely.

me3x · 2019-12-02T12:20:28Z

we could rethrow MessageNotWriteableException and handle it with clearing the body

codefromthecrypt

I appreciate a pragmatic approach to this, but this solution is dangerous to the app. Some changes requested:

revert the loop logic change as it is less efficient than before and not sure what if anything was needed to change there
consider how to make this optional. For example, is there any signal used in activeMQ message only (besides type name)?
see if you can fix or nudge the underlying problem to get it resolved. Spaghetti causes problems not just here but the whole world working around the bug. Sometimes you can get someone to fix the actual problem and give hope for the future

codefromthecrypt · 2020-01-24T08:53:49Z

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

    } catch (Throwable t) {
      propagateIfFatal(t);
      log(t, "error getting property names from {0}", message, null);
      return;
    }
-
-    while (names.hasMoreElements()) {


why is this logic changed? was there a problem? Using collections.list will add allocate an array, and changing this logic makes it hard to tell what change is actually a problem or in focus.

codefromthecrypt · 2020-01-24T08:55:00Z

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java

+    }
+  }
+
+  private static void resetBytesMessageProperties( Message message, List<Object> out ) {


this will cause a lot of overhead as we are subject to OOM. as this is a bug in activemq, we need to be more specific than this.

codefromthecrypt · 2020-03-11T02:34:05Z

@jeqo if I recall correctly, there's a fix to this upstream now?

jeqo · 2020-03-11T07:06:59Z

@adriancole still waiting for the next ActiveMQ client release to be available.

I will create a PR with the changes and notes about target versions on README, and close this one.

codefromthecrypt · 2020-07-15T08:38:36Z

we should close this now with ActiveMQ release fixing this internally correct? meanwhile it is nearing a year old :D

codefromthecrypt · 2023-12-15T11:47:25Z

closing as out-of-date and seems possible addressed upstream. If not the case, please re-open

me3x added 10 commits November 21, 2019 15:15

fix re-setting properties on BytesMessage

416675d

fix MessageNotWriteableException Message body is read-only while re-setting properties on BytesMessage

fix formatting and put back Throwable propagation

e6e4be6

propagate ActiveMQBytesMessage body reset failure

b89740e

fix exception propagation

167f234

avoid resetting properties if not necessary

7c3ad06

remove lambda

087ce51

fix test

22c915c

fix test

407bb69

fix test

8f4e201

avoid resetting properties if not necessary

8a405c8

me3x mentioned this pull request Nov 22, 2019

Cannot set "b3" on a BytesMessage with body set to read-only (ActiveMQ 5.x) #967

Closed

jcchavezs reviewed Nov 22, 2019

View reviewed changes

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

jcchavezs reviewed Nov 22, 2019

View reviewed changes

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

add comment

c0e2584

jeqo reviewed Nov 23, 2019

View reviewed changes

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

me3x and others added 2 commits November 25, 2019 10:54

better comment

37e893d

Co-Authored-By: Jorge Quilcate Otoya <quilcate.jorge@gmail.com>

changes proposed by code review

94e5e0a

fix the logic

507ebc1

jcchavezs reviewed Nov 25, 2019

View reviewed changes

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Show resolved Hide resolved

early termination, fix formatting

29704fb

remove disjoint check

72f32a2

we need to always reset properties

enable jms failing test

38fcf7e

jeqo requested changes Nov 27, 2019

View reviewed changes

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

instrumentation/jms/src/main/java/brave/jms/PropertyFilter.java Outdated Show resolved Hide resolved

changes proposed by code review

02ac2c9

me3x added 2 commits November 28, 2019 13:44

reset bytes message after context reinjection

3463b20

reset moved after context reinjection

edfa2e5

jeqo reviewed Nov 28, 2019

View reviewed changes

reset message after reinjectoin

c7e5c3e

remove body reset

6b1db4a

jeqo mentioned this pull request Dec 2, 2019

move workaround to tracing consumer me3x/brave#1

Closed

codefromthecrypt requested changes Jan 24, 2020

View reviewed changes

jeqo mentioned this pull request Mar 13, 2020

Bump ActiveMQ client #1112

Merged

raduarsenii mentioned this pull request Nov 25, 2021

Brave JMS instrumentation does not work properly when ActiveMQ BytesMessage is received #1310

Closed

codefromthecrypt closed this Dec 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix re-setting properties on BytesMessage #1042

fix re-setting properties on BytesMessage #1042

me3x commented Nov 21, 2019 •

edited

jeqo left a comment

me3x commented Nov 25, 2019

me3x commented Nov 25, 2019

jeqo commented Nov 25, 2019

jeqo commented Nov 25, 2019

jeqo commented Nov 25, 2019

me3x commented Nov 27, 2019

me3x commented Nov 27, 2019

jeqo left a comment

me3x commented Nov 28, 2019

jeqo commented Nov 28, 2019 •

edited

me3x commented Nov 28, 2019

jeqo Nov 28, 2019

me3x Nov 28, 2019

jeqo commented Nov 28, 2019 via email

me3x commented Nov 29, 2019 •

edited

jeqo commented Nov 29, 2019

me3x commented Nov 29, 2019

me3x commented Nov 29, 2019

jeqo commented Nov 29, 2019 •

edited

me3x commented Dec 2, 2019 •

edited

jeqo commented Dec 2, 2019 •

edited by anuraaga

me3x commented Dec 2, 2019

me3x commented Dec 2, 2019

me3x commented Dec 2, 2019

codefromthecrypt left a comment

codefromthecrypt Jan 24, 2020

codefromthecrypt Jan 24, 2020

codefromthecrypt commented Mar 11, 2020

jeqo commented Mar 11, 2020

codefromthecrypt commented Jul 15, 2020

codefromthecrypt commented Dec 15, 2023

fix re-setting properties on BytesMessage #1042

fix re-setting properties on BytesMessage #1042

Conversation

me3x commented Nov 21, 2019 • edited

jeqo left a comment

Choose a reason for hiding this comment

me3x commented Nov 25, 2019

me3x commented Nov 25, 2019

jeqo commented Nov 25, 2019

jeqo commented Nov 25, 2019

jeqo commented Nov 25, 2019

me3x commented Nov 27, 2019

me3x commented Nov 27, 2019

jeqo left a comment

Choose a reason for hiding this comment

me3x commented Nov 28, 2019

jeqo commented Nov 28, 2019 • edited

me3x commented Nov 28, 2019

jeqo Nov 28, 2019

Choose a reason for hiding this comment

me3x Nov 28, 2019

Choose a reason for hiding this comment

jeqo commented Nov 28, 2019 via email

me3x commented Nov 29, 2019 • edited

jeqo commented Nov 29, 2019

me3x commented Nov 29, 2019

me3x commented Nov 29, 2019

jeqo commented Nov 29, 2019 • edited

me3x commented Dec 2, 2019 • edited

jeqo commented Dec 2, 2019 • edited by anuraaga

me3x commented Dec 2, 2019

me3x commented Dec 2, 2019

me3x commented Dec 2, 2019

codefromthecrypt left a comment

Choose a reason for hiding this comment

codefromthecrypt Jan 24, 2020

Choose a reason for hiding this comment

codefromthecrypt Jan 24, 2020

Choose a reason for hiding this comment

codefromthecrypt commented Mar 11, 2020

jeqo commented Mar 11, 2020

codefromthecrypt commented Jul 15, 2020

codefromthecrypt commented Dec 15, 2023

me3x commented Nov 21, 2019 •

edited

jeqo commented Nov 28, 2019 •

edited

me3x commented Nov 29, 2019 •

edited

jeqo commented Nov 29, 2019 •

edited

me3x commented Dec 2, 2019 •

edited

jeqo commented Dec 2, 2019 •

edited by anuraaga