<p></p>

<h3>Description</h3>
<p>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<br>
Note : the overall average, max and min values appear fine</p>
<h3>Troubleshooting</h3>
<p>Opened Kamailio in debug mode and saw that labels are being set  , yet appearing as null</p>
<p>Snipets</p>
<pre><code>tagsd8:91e08b04d3:tag8:91e08b045:label6:caller7:createdi1590686836e16:in dialogue with13:tKtpK3BHjFavK6:mediasld5:indexi1e4:type5:audio8:protocol8:RTP/AVPF7
..
looking for label '<null>'
</code></pre>
<p>Full logs below  in the "Log Messages" section</p>
<h4>Reproduction</h4>
<p>Using Lua on Kamailio v5.2.1</p>
<ol>
<li>Add labels in RTPengine offer , ensuring the traffic is AVPF</li>
</ol>
<pre><code>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 "

</code></pre>
<ol start="2">
<li>set the mos label</li>
</ol>
<pre><code> KSR.pv.sets("$avp(mos_A_label)", "caller");
</code></pre>
<ol start="3">
<li>Make call and do RTPengine offer and answer like usual</li>
</ol>
<pre><code>KSR.rtpengine.rtpengine_offer(rtpengine_offer_flag)
...
KSR.rtpengine.rtpengine_answer(rtpengine_answer_flag)
</code></pre>
<ol start="3">
<li>On BYE , do rtpengihne delete</li>
</ol>
<pre><code>KSR.rtpengine.rtpengine_delete0()
</code></pre>
<ol start="4">
<li>gather PV values for legs</li>
</ol>
<pre><code>        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 ")
</code></pre>
<h4>Debugging Data</h4>

<pre><code>(paste your debugging data here)
</code></pre>
<h4>Log Messages</h4>

<p>Log from kamailio from BYE untill printing overall average mos score</p>
<pre><code> 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
</code></pre>
<p>Logs from the same trace printing A leg values as nill , I'm using get getvn<br>
such as</p>
<pre><code>KSR.log("info", "mos_average_B  " .. KSR.pv.getvn("$avp(mos_average_B)", 0) .. "\n ")
</code></pre>
<p>the traces thus show all values as 0</p>
<pre><code>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
 
</code></pre>
<p>All IPs are local network so I didn't bother masking them</p>
<h4>SIP Traffic</h4>

<pre><code>(paste your sip traffic here)
</code></pre>
<h3>Possible Solutions</h3>

<p>I did manage to extract the leg  A values by first commenting out pase_call stats for overall and leg B</p>
<pre><code> //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);
</code></pre>
<p>and then commenting out the check between the label and well another label  , which is where I figured it was breaking the loop</p>
<pre><code>         //if (str_cmp(&check, &label))
                //      continue;
</code></pre>
<p>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</p>
<p>Initially though it an RTPengine issue and raised a bug there too<br>
<a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="579086509" data-permission-text="Title is private" data-url="https://github.com/sipwise/rtpengine/issues/947" data-hovercard-type="issue" data-hovercard-url="/sipwise/rtpengine/issues/947/hovercard" href="https://github.com/sipwise/rtpengine/issues/947">sipwise/rtpengine#947</a><br>
pretty sure it isn't an RTPenginhe issue now .</p>
<h3>Additional Information</h3>
<ul>
<li><strong>Kamailio Version</strong> - output of <code>kamailio -v</code></li>
</ul>
<pre><code>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

</code></pre>
<ul>
<li><strong>Operating System</strong>:</li>
</ul>

<pre><code>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
</code></pre>

<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/2340">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/ABO7UZNPIA32UQPJU3CK25LRT2SVFANCNFSM4NNJ6F3Q">unsubscribe</a>.<img src="https://github.com/notifications/beacon/ABO7UZP4TY4LNAE6A3JNRETRT2SVFA5CNFSM4NNJ6F32YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4JK23WTA.gif" height="1" width="1" alt="" /></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/2340",
"url": "https://github.com/kamailio/kamailio/issues/2340",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>