Homer 10 - Call Flow - Sorting Issues/Wrong Order

[tony1661]

I am noticing an issue in Homer 10's Call Flow dashboard. It seems that the Call Flow is not in the correct order which is making troubleshooting difficult.

I have a Freeswitch server (FusionPBX) with the portable helpify agent running heplify -hs homer-stack-ip:9060

If I search by the Call-ID in the SIP headers, I see all SIP messages associated with the call. See below:

Obviously the INVITE would have occurred before the 407 however that is not what Grafana shows.

Based on the HEP Flow panel, the messages should be sorted oldest to newest.

If I look into each message I see that the INVITE has a later date than the 407.

INVITE Date

407 Date

The issue is similar to what is being experienced in Homer 7's web-ui which leads me to think the issue may be related to Heplify. In Homer 7, when searching for a call, the results are also in the wrong order, however when I click on the Session ID to view the ladder, it is in the correct order.

Is it possible that the ladder in Homer 7 is referencing a different timestamp that is also being referenced in Homer 10?

[github-actions]

Please star this repository to motivate the developers and to get higher priority! ⭐

[tony1661]

I've tested using captagent instead of heplify and the issue persists in Homer 10.

[tony1661]

To add to this issue, I took a packet capture of a call that has the SIP messages displayed in the wrong order in Homer 10.

It seems that in the HEP packets, the Unix Timestamp doesn't change. See below:

The last two messages (BYE and 200 OK) have a different timestamp and in Homer they do indeed appear at the bottom of the ladder but they appear in a different order in the ladder than they do in the packet capture.

It may be worth adding the Timestamp μs to the equation.

[lmangani]

Thanks for the report @tony1661 we're investigating and will make sure this is part of the next grafana-flow release
@AlexeyOplachko could you check this after the holidays?

[tony1661]

@AlexeyOplachko let me know if I can help in any way. I can provide logs, pcaps etc.

I have this on a production freeswitch server with heplify and captagent both running.

Hundreds of calls a day that we can look at.

[lmangani]

Hi @tony1661 we're back next week and we' ll most definitely address this

[RFbkak37y3kIY]

pushed fix for grafana-plugin, metrico/grafana-flow#47

used field [tsNs] for increased sorting accuracy SIP messages

[tony1661]

Hi all,

I saw there were some code merged. If I pull the latest docker images, will I be able to test this?

[lmangani]

As long as its using plugin version 10.0.10 you can also update an existing setup

[lmangani]

@tony1661 here's how

[tony1661]

@lmangani Thanks for your quick response. I tested and the issue seems to still be there. Is there anything I can provide to help? Logs etc

[AlexeyOplachko]

For starters can you please verify that your grafana indeed got new plugin version please?
your_grafana_url/plugins/qxip-flow-panel

On our side we'll try to replicate this issue today and see if we need anything else from you

[tony1661]

Hi @AlexeyOplachko ,

I have verified that I have 10.0.10 installed. See below:

[tony1661]

Anything I can help with?

[lmangani]

@AlexeyOplachko please provide an update

[AlexeyOplachko]

Anything I can help with?

@tony1661
Can you please provide screenshots of Message details with all the info in them, on two messages that are in incorrect order.


And also can you please check if Sort Items is set.

[tony1661]

Hi @AlexeyOplachko sorry for the delay on this.

The Sort items is set to "Sort by Time: Oldest first".

Here is what the call flow looks like:

Here is the first message (INVITE):

Here is the second message (200 OK):

Here is the fourth message (that is supposed to be second - 100 Trying):

[AlexeyOplachko]

Hi @tony1661, thanks for reply, seems like this is not a sorting issue, but an issue with data.

If you look closely, message with 100 Trying has timestamp almost 4 minutes later than 200 OK.
And all three timestamps(one in labels, one in Time field, and nanosecond one) show matching data that supports this.

[tony1661]

@AlexeyOplachko Yea something seems off with the data. The issue happens on multiple HEP clients (heplify and captagent)

I have some screenshots from pcaps above that may assist.

I am running freeswitch (via FusionPBX)

[Dletta]

@AlexeyOplachko Could you check if you ended up fixing this issue?

[tony1661]

@Dletta are you also experiencing this issue?

[AlexeyOplachko]

@AlexeyOplachko Could you check if you ended up fixing this issue?

Yes, from standpoint of our frontend there is no way for it to sort incorrectly, so it's only an issue with data

[Dletta]

@tony1661

I am not experiencing the same issue. I work with Alexey and wanted to make sure we don't let this issue go stale, :)

[tony1661]

@AlexeyOplachko Could you check if you ended up fixing this issue?

Yes, from standpoint of our frontend there is no way for it to sort incorrectly, so it's only an issue with data

What can I do to assist? I've used multiple HEP agents and get the same results. Homer 7 does not have the issue with the same data source

[tony1661]

Hi @lmangani is there any progress on this? I really want to be able to move over to Homer 10 if possible 🙂

[kYroL01]

Hi @tony1661
We tried to replicate your issue in our lab using Homer and various HEP agents (heplify, captangent, etc.) but could not reproduce the problem.
From our experience, this issue could be related with the server timestamp where the traffic is flowing

I am running freeswitch (via FusionPBX)

Consider that heplify and captagent don't change the timestamp, as they are passive actors, they just show what they see.
2 things:

1. Can you check the timestamp and the order of the incoming traffic before the agents ?
2. Can you check the timestamp and the order of the HEP packets arriving to heplify-server ?

This can help

[tony1661]

@kYroL01 thanks for your reply.

The strange thing is homer 7 does not have the issue.

I have my Freeswitch/Fusion PBX server with heplify or captagent pointed to a server running docker. If I start the homer 7 containers and test, calls look good. Once I shut them down and start Homer 10, the issue starts.

What data should I be looking at? Should I be looking at packet captures?

[kYroL01]

IMHO you should check the data between the agent and the heplify server, and between heplify server and the database.

It's better to find any concrete evidence between Homer 7 and Homer 10 to help you, otherwise, as we cannot reproduce the issue, it's really hard for us to use only the screenshots.

[tony1661]

@kYroL01 will do. I will try to see what I can find. I did provide some details on the info I found in the pcaps above. I will try to find some better reference data

[covalschi]

Noticing similar behaviour, sending HEP3 using siptrace.so on Kamailio 5.4.6 be668987e9296232a00fa7bba82bc72abd72a743 (June 2021), 100% UDP, using setflag to mark the transaction to capture
Capturing with heplify-server 1.59.7 via qryn 3.2.31 into ClickHouse 24.9.2.42, peaking with ~7000 messages/second
Running Grafana 11.2, plugin v10.2.0

Please check this PNG export from the plugin - messages are offset by mere microseconds, however such offset vastly impacts the representation of the SIP flow. This is not the case for all of the calls, however I didn't find any pattern in the occurencies of the issue, which happens quiet often - including off-peak hours.