<!--
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
_______________________________________________
Kamailio (SER) - Development Mailing List
sr-dev@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev

Reply via email to