APM transactions displayed in wrong time order

[vsmelov (Vladimir Smelov)]

I checked this problem on both versions

Kibana version:
6.7.1 and 6.5.3

Elasticsearch version:
6.7.1 and 6.5.3

APM Server version:
6.7.1 and 6.5.3

APM Agent language and version:
python
elastic-apm==4.0.2

Original install method (e.g. download page, yum, deb, from source, etc.) and version:
docker-compose

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):

I have 3 components and 2 types of events.

ComponentA:
- publish event1
ComponentB:
- receive event1, process it (for ~200ms) and publish event2
ComponentC:
- receive event1 and process it
- receive event2 and process it

Expected APM plot:

Actual:

I see two problems here

1. (mian) C:recv_event2 started before B:recv_event1 finished and published event2 (what is impossible)
2. B:recv_event1 and C:recv_event1 started immediately at the same time point as event1 (what is impossible because event1 first should be published/finished and then processed by others)

If I check Elastic log messages it is fine

1. C:recv_event2 happened after the end of B:recv_event1
2. B:recv_event1 and C:recv_event1 timestamp is bigger than event1 timestamp

Why do I see wrong APM plot?

Code implementation
I create APM transaction when I publish event1 and forward transaction_id with event.
So in component B and C I use

msg = parse(socket.recv())
apm.begin_transaction('B:recv_event2', trace_parent=TraceParent.from_string(msg['apm_id']))

[sqren (Søren Louv Jansen)]

Hi Vladimir,

Thanks for reaching out. This does indeed look like a bug.
For me to look further into this, it would be very helpful to see the response from the backend.

If possible, please open your browsers Dev Tools and find the response for the XHR request containing /traces/ in the url eg:

<host>/apm/traces/88cf30e3cf1b935d976238b0d92ec81a?start=2019-04-24T11%3A01%3A31.927Z&end=2019-04-25T11%3A01%3A31.927Z

You are welcome to send it to me as a private message if you don't want to post it publicly.

[vsmelov (Vladimir Smelov)]

here is request-response
https://pastebin.com/9EkyuwJP

it's too big so I cannot post it here

[roncohen]

@vsmelov thanks for the data!

Could you help us understand a bit more about your use case? What kind of transport mechanism do you use when you say that an event is "published"? Are you using some kind of event bus?

[vsmelov (Vladimir Smelov)]

I use ZMQ sockets

componentA publishes message like {'apm_id': 'xxx', 'data': 'event1'} to socket and log transaction to APM
componentB receive event1 from socket, process it for 200ms, log transaction to APM and publishes {'apm_id': 'xxx', 'data': 'event2'}to socket
componentC receive event1 from socket and log transaction to APM
componentC receive event2 from socket and log transaction to APM

I can write some very simplified python-code for this use-case and post it if necessary.
Because now these components are parts of our big application.

But it still does not clear for me, why I see correct logs in elasticsearch but wrong visualisation.

[vsmelov (Vladimir Smelov)]

So why can it happen? Can we use any workaround?

[roncohen]

Thanks for hanging in there @vsmelov.
We've identified the issue and will fix it in one of the upcoming releases.
You can follow along here: https://github.com/elastic/kibana/issues/35800