You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or unsubscribe.
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
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
Using Lua on Kamailio v5.2.1
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 "
KSR.pv.sets("$avp(mos_A_label)", "caller");
KSR.rtpengine.rtpengine_offer(rtpengine_offer_flag)
...
KSR.rtpengine.rtpengine_answer(rtpengine_answer_flag)
KSR.rtpengine.rtpengine_delete0()
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 ")
(paste your debugging data here)
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
(paste your sip traffic here)
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
sipwise/rtpengine#947
pretty sure it isn't an RTPenginhe issue now .
kamailio -vkamailio -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
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, view it on GitHub, or unsubscribe.