28 May
2020
28 May
'20
11:13 p.m.
<!--
Kamailio Project uses GitHub Issues only for bugs in the code or feature requests. Please
use this template only for bug reports.
If you have questions about using Kamailio or related to its configuration file, ask on
sr-users mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
If you have questions about developing extensions to Kamailio or its existing C code, ask
on sr-dev mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
Please try to fill this template as much as possible for any issue. It helps the
developers to troubleshoot the issue.
If there is no content to be filled in a section, the entire section can be removed.
You can delete the comments from the template sections when filling.
You can delete next line and everything above before submitting (it is a comment).
-->
### Description
Extract media stats per leg from RTPengine but in spite of labels being present in
RTPengine logs the values are not extracted in their respective PV's
Note : the overall average, max and min values appear fine
### Troubleshooting
Opened Kamailio in debug mode and saw that labels are being set , yet appearing as null
Snipets
```
tagsd8:91e08b04d3:tag8:91e08b045:label6:caller7:createdi1590686836e16:in dialogue
with13:tKtpK3BHjFavK6:mediasld5:indexi1e4:type5:audio8:protocol8:RTP/AVPF7
..
looking for label '<null>'
```
Full logs below in the "Log Messages" section
#### Reproduction
Using Lua on Kamailio v5.2.1
1. Add labels in RTPengine offer , ensuring the traffic is AVPF
```
local rtpengine_codecs_flag = " codec-strip-all codec-offer-PCMA codec-offer-pcma
"
local rtpengine_offer_flag = "ICE=remove RTP/AVPF full-rtcp-attribute
direction=external direction=external replace-origin replace-session-connection
record-call=yes " .. rtpengine_codecs_flag .. " label=caller "
local rtpengine_answer_flag = "ICE=remove RTP/AVPF full-rtcp-attribute
direction=external direction=external replace-origin replace-session-connection
record-call=yes label=callee "
```
2. set the mos label
```
KSR.pv.sets("$avp(mos_A_label)", "caller");
```
3. Make call and do RTPengine offer and answer like usual
```
KSR.rtpengine.rtpengine_offer(rtpengine_offer_flag)
...
KSR.rtpengine.rtpengine_answer(rtpengine_answer_flag)
```
3. On BYE , do rtpengihne delete
```
KSR.rtpengine.rtpengine_delete0()
```
4. gather PV values for legs
```
KSR.log("info", "mos_A_label " ..
KSR.pv.getvn("$avp(mos_A_label)", 1) .. "\n ")
KSR.log("info", "mos_average_packetloss_A " ..
KSR.pv.getvn("$avp(mos_average_packetloss_A)", 0) .. "\n ")
KSR.log("info", "mos_average_jitter_A " ..
KSR.pv.getvn("$avp(mos_average_jitter_A)", 0) .. "\n ")
KSR.log("info", "mos_average_roundtrip_A " ..
KSR.pv.getvn("$avp(mos_average_roundtrip_A)", 0) .. "\n ")
KSR.log("info", "mos_average_A " ..
KSR.pv.getvn("$avp(mos_average_A)", 0) .. "\n ")
```
#### Debugging Data
<!--
If you got a core dump, use gdb to extract troubleshooting data - full backtrace,
local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile
bt full
info locals
list
If you are familiar with gdb, feel free to attach more of what you consider to
be relevant.
-->
```
(paste your debugging data here)
```
#### Log Messages
<!--
Check the syslog file and if there are relevant log messages printed by Kamailio, add them
next, or attach to issue, or provide a link to download them (e.g., to a pastebin site).
-->
Log from kamailio from BYE untill printing overall average mos score
```
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log(): >>> delete
RTPengine
4(11084) DEBUG: rtpengine [rtpengine.c:2912]: select_rtpp_node_old(): rtpengine hash
table lookup find node=udp:192.168.1.109:2222 for calllen=49
callid=103103ZjIzOGM1MWRlYjQxZDhjYWQ4YTlhN2I3ODg0YWNmN2I viabranch=
4(11084) DEBUG: rtpengine [rtpengine.c:2452]: rtpp_function_call(): proxy reply:
d7:createdi1590686836e10:created_usi219955e11:last
signali1590686836e4:SSRCd10:2899397750d11:average MOSd3:MOSi43e15:round-trip
timei14365e6:jitteri0e11:packet lossi0e7:samplesi3ee10:lowest MOSd3:MOSi43e15:round-trip
timei12630e6:jitteri1e11:packet lossi0e11:reported ati1590686846ee11:highest
MOSd3:MOSi44e15:round-trip timei7559e6:jitteri0e11:packet lossi0e11:reported
ati1590686849ee15:MOS progressiond8:intervali0e7:entriesld3:MOSi43e15:round-trip
timei12630e6:jitteri1e11:packet lossi0e11:reported ati1590686846eed3:MOSi44e15:round-trip
timei7559e6:jitteri0e11:packet lossi0e11:reported ati1590686849eed3:MOSi43e15:round-trip
timei22908e6:jitteri0e11:packet lossi0e11:reported
ati1590686855eeeee10:3469957276d11:average MOSd3:MOSi43e15:round-trip
timei17045e6:jitteri0e11:packet lossi0e7:samplesi5ee10:lowest MOSd3:MOSi43e15:round-trip
timei10048e6:jitteri0e11:packet lossi0e11:reported ati1590686844ee11:highest
MOSd3:MOSi44e15:round-trip timei7134e6:jitteri0e11:packet lossi0e11:reported
ati1590686848ee15:MOS progressiond8:intervali1e7:entriesld3:MOSi43e15:round-trip
timei10048e6:jitteri0e11:packet lossi0e11:reported ati1590686844eed3:MOSi44e15:round-trip
timei7134e6:jitteri0e11:packet lossi0e11:reported ati1590686848eed3:MOSi43e15:round-trip
timei22738e6:jitteri0e11:packet lossi0e11:reported ati1590686852eed3:MOSi43e15:round-trip
timei22566e6:jitteri0e11:packet lossi0e11:reported ati1590686853eed3:MOSi43e15:round-trip
timei22739e6:jitteri0e11:packet lossi0e11:reported
ati1590686854eeeeee4:tagsd8:91e08b04d3:tag8:91e08b045:label6:caller7:createdi1590686836e16:in
dialogue
with13:tKtpK3BHjFavK6:mediasld5:indexi1e4:type5:audio8:protocol8:RTP/AVPF7:streamsld10:local
porti31052e8:endpointd6:family4:IPv47:address13:192.168.1.1084:porti58004ee19:advertised
endpointd6:family4:IPv47:address13:192.168.1.1084:porti58004ee11:last
packeti1590686855e5:flagsl3:RTP6:filled9:confirmed10:kernelized17:no kernel
supporte4:SSRCi2899397750e5:statsd7:packetsi928e5:bytesi157696e6:errorsi12eeed10:local
porti31053e8:endpointd6:family4:IPv47:address13:192.168.1.1084:porti58005ee19:advertised
endpointd6:family4:IPv47:address13:192.168.1.1084:porti58005ee11:last
packeti1590686855e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel
supporte4:SSRCi2899397750e5:statsd7:packetsi5e5:bytesi400e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeee13:tKtpK3BHjFavKd3:tag13:tKtpK3BHjFavK5:label6:callee7:createdi1590686836e16:in
dialogue
with8:91e08b046:mediasld5:indexi1e4:type5:audio8:protocol8:RTP/AVPF7:streamsld10:local
porti31044e8:endpointd6:family4:IPv47:address13:192.168.1.1094:porti27984ee19:advertised
endpointd6:family4:IPv47:address13:192.168.1.1094:porti27984ee11:last
packeti1590686855e5:flagsl3:RTP6:filled9:confirmed10:kernelized17:no kernel
support3:ICEe4:SSRCi3469957276e5:statsd7:packetsi653e5:bytesi112316e6:errorsi0eeed10:local
porti31045e8:endpointd6:family4:IPv47:address13:192.168.1.1094:porti27985ee19:advertised
endpointd6:family4:IPv47:address13:192.168.1.1094:porti27985ee11:last
packeti1590686854e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel
support3:ICEe4:SSRCi3469957276e5:statsd7:packetsi6e5:bytesi652e6:errorsi0eeee5:flagsl11:initialized4:send4:recv3:ICE15:ICE
controllingeeeee6:totalsd3:RTPd7:packetsi1581e5:bytesi270012e6:errorsi12ee4:RTCPd7:packetsi11e5:bytesi1052e6:errorsi0eee6:result2:oke
4(11084) DEBUG: rtpengine [rtpengine.c:2536]: rtpp_function_call(): rtpengine hash table
remove entry for callen=49 callid=103103ZjIzOGM1MWRlYjQxZDhjYWQ4YTlhN2I3ODg0YWNmN2I
viabranch=
4(11084) DEBUG: rtpengine [rtpengine.c:3129]: parse_call_stats_1(): rtpengine: looking
for label '<null>'
4(11084) DEBUG: rtpengine [rtpengine.c:3135]: parse_call_stats_1(): rtpengine: XXX got
tags
4(11084) DEBUG: rtpengine [rtpengine.c:3138]: parse_call_stats_1(): rtpengine: XXX got
tag
4(11084) DEBUG: rtpengine [rtpengine.c:3143]: parse_call_stats_1(): rtpengine: XXX got
label caller
4(11084) DEBUG: rtpengine [rtpengine.c:3138]: parse_call_stats_1(): rtpengine: XXX got
tag
4(11084) DEBUG: rtpengine [rtpengine.c:3143]: parse_call_stats_1(): rtpengine: XXX got
label callee
4(11084) DEBUG: rtpengine [rtpengine.c:3129]: parse_call_stats_1(): rtpengine: looking
for label '<null>'
4(11084) DEBUG: rtpengine [rtpengine.c:3135]: parse_call_stats_1(): rtpengine: XXX got
tags
4(11084) DEBUG: rtpengine [rtpengine.c:3138]: parse_call_stats_1(): rtpengine: XXX got
tag
4(11084) DEBUG: rtpengine [rtpengine.c:3143]: parse_call_stats_1(): rtpengine: XXX got
label caller
4(11084) DEBUG: rtpengine [rtpengine.c:3138]: parse_call_stats_1(): rtpengine: XXX got
tag
4(11084) DEBUG: rtpengine [rtpengine.c:3143]: parse_call_stats_1(): rtpengine: XXX got
label callee
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_average)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_average)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos average 4.3
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log(): mos average 4.3
```
Logs from the same trace printing A leg values as nill , I'm using get getvn
such as
```
KSR.log("info", "mos_average_B " ..
KSR.pv.getvn("$avp(mos_average_B)", 0) .. "\n ")
```
the traces thus show all values as 0
```
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log(): mos_A_label 1
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_average_packetloss_A)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_average_packetloss_A)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos_average_packetloss_A 0
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log():
mos_average_packetloss_A 0
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_average_jitter_A)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_average_jitter_A)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos_average_jitter_A 0
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log(): mos_average_jitter_A
0
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_average_roundtrip_A)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_average_roundtrip_A)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos_average_roundtrip_A 0
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log():
mos_average_roundtrip_A 0
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_average_A)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_average_A)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos_average_A 0
4(11084) INFO: <core> [core/kemi.c:143]: sr_kemi_core_log(): mos_average_A 0
4(11084) DEBUG: app_lua [app_lua_sr.c:1024]: lua_sr_pv_get_valx(): pv set:
$avp(mos_B_label)
4(11084) DEBUG: <core> [core/pvapi.c:395]: pv_cache_lookup(): pvar
[$avp(mos_B_label)] found in cache
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[0] for:
log is str: info
4(11084) DEBUG: app_lua [app_lua_sr.c:1651]: sr_kemi_lua_exec_func_ex(): param[1] for:
log is str: mos_B_label 1
```
All IPs are local network so I didn't bother masking them
#### SIP Traffic
<!--
If the issue is exposed by processing specific SIP messages, grab them with ngrep or save
in a pcap file, then add them next, or attach to issue, or provide a link to download them
(e.g., to a pastebin site).
-->
```
(paste your sip traffic here)
```
### Possible Solutions
<!--
If you found a solution or workaround for the issue, describe it. Ideally, provide a pull
request with a fix.
-->
I did manage to extract the leg A values by first commenting out pase_call stats for
overall and leg B
```
//parse_call_stats_1(&global_mos_stats, dict, msg);
parse_call_stats_1(&side_A_mos_stats, dict, msg);
//parse_call_stats_1(&side_B_mos_stats, dict, msg);
```
and then commenting out the check between the label and well another label , which is
where I figured it was breaking the loop
```
//if (str_cmp(&check, &label))
// continue;
```
I understand this isn't an acceptable approach and I looking forward to learning
whether this really is a bug or a bad setting on my end
Initially though it an RTPengine issue and raised a bug there too
https://github.com/sipwise/rtpengine/issues/947
pretty sure it isn't an RTPenginhe issue now .
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
```
kamailio -v
version: kamailio 5.2.1 (x86_64/linux) b71938-dirty
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE,
USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC,
DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER,
USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144 MAX_URI_SIZE 1024, BUF_SIZE 65535,
DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: b71938 -dirty
compiled on 13:06:02 May 28 2020 with gcc 7.5.0
```
* **Operating System**:
<!--
Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04,
CentOS 7.1, ...), MacOS, xBSD, Solaris, ...;
Kernel details (output of `uname -a`)
-->
```
Linux altanai-Inspiron-15-5578 4.15.0-62-generic #69-Ubuntu SMP Wed Sep 4 20:55:53 UTC
2019 x86_64 x86_64 x86_64 GNU/Linux
```
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2340