<!-- 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