Merged Traces

[memaskal]

I have a Spring Boot 2.4.5 project with Spring Integration and Spring Cloud 2020.0.2. The application consumes from a JMS queue, validates the request, and uses additionally two queues for further processing. I use the message-driven channel adapter as shown below to read messages from the incoming-requests queue and send them to my channel "received-message-channel". After validation, an internal queue is used (int-jms:channel) to do additional processing before I produce the final output, to another JMS queue using directly the JMS template from a service activator.

This application is part of a pipeline thus I use sleuth to trace the requests. I use the BraveTracer to acquire the current span (created by Sleuth's Channel Interceptor instrumentation for spring-integration) and add custom tags to spans identifying the request type etc...

<int-jms:message-driven-channel-adapter
	connection-factory="connectionFactory"
	destination-name="input-queue"
	channel="received-message-channel"
	concurrent-consumers="1"
	max-concurrent-consumers="5"
	acknowledge="transacted"
	error-channel="errorChannel"
/>

<int-jms:channel
      id="internalQueueChannel"
      queue-name="internal-queue"
      connection-factory="connectionFactory"
      acknowledge="transacted"
      concurrency="1-5"
/>

<bean id="connectionFactory" class="org.springframework.jms.connection.CachingConnectionFactory">
  <property name="targetConnectionFactory">
	  <bean class="org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory">
		  <property name="user" value="${spring.artemis.user}" />
		  <property name="password" value="${spring.artemis.password}" />
		  <property name="brokerURL" value="${spring.artemis.brokerUrl}" />
	  </bean>
  </property>
</bean>

Moreover, I use sampling and I only report some of the channels (to avoid all the spans from being reported) using patterns:

  spring.sleuth.sampler.percentage=0.1
  spring.sleuth.integration.patterns=received-message-channel, anotherChannel, finalChannel

The problem that I see using Zipkin/Jaeger UI is a single trace containing almost all of my spans, or in other words, multiple traces merged. As shown in the image below, 7K+ spans are reported under the same trace Id. These spans are nested in arbitrary ways, not even preserving their natural ordering. Some warning logs exist invalid parent span IDs=e0c87fcfe5a4e980; skipping clock skew adjustment, under some of these spans.

This was the trace's final stats when all spans were reported:
Trace StartMay 6 2021, 14:56:17.303 Duration 32m 27s Services 3 Depth 16 Total Spans 9104

[marcingrzejszczak]

Hi! Are you sure that they are reported in an invalid way? What I mean is that if we're producing the traces / spans properly in Sleuth but Jaeger/Zipkin fails to render them accordingly then it's not sth we can fix on our side. Can you double check that the issue is on our side? Also, could you please create a small project that replicates the issue (preferably in Java and Maven) ?

[memaskal]

Hi, I will try to provide a way to replicate the issue, but in the meantime, do you suggest a way to check that the spans are reported correctly? This is why I tried both Zipkin and Jaeger to eliminate UI render problems but in any case, with your suggestion, I can check on that.

[marcingrzejszczak]

You could go to zipkin and download the whole json it received. Then you'd have to analyze if the parent-child relationship is maintained between the reported spans. If there are no spans missing (e.g. There is a span with parent id X but there's no span with id X).

[memaskal]

I think that I traced the issue, with the JMS instrumentation of sleuth. When a JMS message is created from an un-instrumented application (i.e. Jmeter) the issue occurs, whereas when using instrumented applications to produce the JMS messages, it does not happen.

I created an example app here. You can use the Jmeter script to recreate the issue and see that under the same trace, thousands of spans appear or run the Integration test I created which works as expected and each trace has the correct spans under it.

[marcingrzejszczak]

If you start with an uninstrumented application then Sleuth will create a new trace for each such message which makes perfect sense. What would be the expected behaviour in your opinion?

[memaskal]

Yes, this is the expected behavior in my opinion too, but it does not work!

Maybe I was not clear in my previous message. Run the sample app with Jmeter as the JMS producer to reproduce this issue.