0

My sample application makes use of

  • spring-boot-starter-activemq (2.3.1)
  • spring-boot-starter-web (2.3.1)
  • pring-cloud-starter-sleuth (2.2.3)

On the published message I see the X-Parent-Span-Id, X-Trace-Id and b3 properties rightly set. However the logs in the JMS Listener (AMQ consumer) have a different parentId (X-B3-ParentSpanId).

Why do the logs on the AMQ consumer side not have the same parentId as present in the message?

Note - The traceId shows up fine.

Flow

Server 1 --> Server 2 (AMQ producer) ---> AMQ consumer

Server1 logs

{"@timestamp":"2020-07-26T18:42:19.258+01:00","@version":"1","message":"Received greet request","logger_name":"com.spike.server.HelloController","thread_name":"http-nio-8080-exec-9","level":"INFO","level_value":20000,"traceId":"e4ac9c00ba990cf2","spanId":"e4ac9c00ba990cf2","spanExportable":"true","X-Span-Export":"true","X-B3-SpanId":"e4ac9c00ba990cf2","X-B3-TraceId":"e4ac9c00ba990cf2"}

Server 2 (AMQ producer) logs

{"@timestamp":"2020-07-26T18:42:19.262+01:00","@version":"1","message":"Received audit request","logger_name":"com.spike.upstream.AuditController","thread_name":"http-nio-8081-exec-9","level":"INFO","level_value":20000,"traceId":"e4ac9c00ba990cf2","spanId":"aed4a3863c141dde","spanExportable":"true","X-Span-Export":"true","X-B3-SpanId":"aed4a3863c141dde","X-B3-ParentSpanId":"e4ac9c00ba990cf2","X-B3-TraceId":"e4ac9c00ba990cf2","parentId":"e4ac9c00ba990cf2"}

AMQ consumer logs

{"@timestamp":"2020-07-26T18:42:19.270+01:00","@version":"1","message":"Received message: hello world","logger_name":"com.spike.consumer.Consumer","thread_name":"DefaultMessageListenerContainer-1","level":"INFO","level_value":20000,"traceId":"e4ac9c00ba990cf2","spanId":"9f7928f65ee2479d","spanExportable":"true","X-Span-Export":"true","X-B3-SpanId":"9f7928f65ee2479d","X-B3-ParentSpanId":"70f25884c40b2dc7","X-B3-TraceId":"e4ac9c00ba990cf2","parentId":"70f25884c40b2dc7"}
Ajay
  • 465
  • 1
  • 9
  • 22
  • Can you please sketch the graph of spans and explain why do you think it's wrong? – Marcin Grzejszczak Jul 26 '20 at 17:31
  • @MarcinGrzejszczak the parentId in my JMS Listener logs don't have any correlation with the last producer span. I was hoping for them to match similar to a span id on a client side (caller) matching the parent id in the destination rest controller (callee). – Ajay Jul 26 '20 at 17:38
  • I'm not making use of Zipkin, how do you recommend I share the span graph to help you better understand? – Ajay Jul 26 '20 at 17:39
  • Copy the ids from the logs. This is how i debug such issues – Marcin Grzejszczak Jul 26 '20 at 17:41
  • @MarcinGrzejszczak I've updated the description with my 3 server log lines. – Ajay Jul 26 '20 at 17:48
  • @MarcinGrzejszczak could you please provide your perspective regarding this? – Ajay Jul 29 '20 at 22:24

1 Answers1

0

I think I got what you're asking about. So the mismatch in parent Ids is related to the fact that between the consumer and the producer we introduce a "jms" service and if the broker was correlated you would have seen how long it takes exactly in the broker. Check out the following images in Imgur https://i.stack.imgur.com/NwkAh.jpg

Marcin Grzejszczak
  • 10,624
  • 1
  • 16
  • 32