search

sipwise / rtpengine

The Sipwise media proxy for Kamailio
GNU General Public License v3.0
787 stars 370 forks source link

Not obtaining the mos scores per leg by label on A and B leg #947

Closed altanai closed 4 years ago

altanai commented 4 years ago

I defined the call leg label in rtp offer such as rtpengine_offer_flag :
_ICE=remove RTP/AVPF full-rtcp-attribute direction=internal replace-origin replace-session-connection record-call=yes codec-strip-all codec-offer-PCMA codec-offer-PCMU codec-offer-telephone-event label=Aleg_label_

and for answer too RTPEngine answer flag : _ICE=remove RTP/AVPF full-rtcp-attribute direction=internal replace-origin replace-session-connection record-call=yes label=Bleg_label_

I can see the labels in RTP engine's final report Response dump for 'delete' to y.y.y.y:40859: { "created": 1583321677, "created_us": 533873, "last signal": 1583321691, "SSRC": { "781550334": { "average MOS": { "MOS": 34, "round-trip time": 290505, "jitter": 21, "packet loss": 7, "samples": 2 }, "lowest MOS": { "MOS": 27, "round-trip time": 288301, "jitter": 23, "packet loss": 14, "reported at": 1583321698 }, "highest MOS": { "MOS": 42, "round-trip time": 292710, "jitter": 20, "packet loss": 0, "reported at": 1583321703 }, "MOS progression": { "interval": 0, "entries": [ { "MOS": 27, "round-trip time": 288301, "jitter": 23, "packet loss": 14, "reported at": 1583321698 }, { "MOS": 42, "round-trip time": 292710, "jitter": 20, "packet loss": 0, "reported at": 1583321703 } ] } }, "2446676299": { "average MOS": { "MOS": 43, "round-trip time": 161077, "jitter": 3, "packet loss": 0, "samples": 2 }, "lowest MOS": { "MOS": 43, "round-trip time": 31791, "jitter": 7, "packet loss": 0, "reported at": 1583321697 }, "highest MOS": { "MOS": 43, "round-trip time": 31791, "jitter": 7, "packet loss": 0, "reported at": 1583321697 }, "MOS progression": { "interval": 0, "entries": [ { "MOS": 43, "round-trip time": 31791, "jitter": 7, "packet loss": 0, "reported at": 1583321697 }, { "MOS": 43, "round-trip time": 290364, "jitter": 0, "packet loss": 0, "reported at": 1583321701 } ] } } }, "tags": { "KaJTCfE07": { "tag": "KaJTCfE07", "label": "Aleg_label", "created": 1583321677, "in dialogue with": "gK06f2624f", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVPF", "streams": [ { "local port": 60356, "endpoint": { "family": "IPv4", "address": "z.z.z.z", "port": 12040 }, "advertised endpoint": { "family": "IPv4", "address": "z.z.z.z", "port": 37149 }, "last packet": 1583321705, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2446676299, "stats": { "packets": 791, "bytes": 136052, "errors": 0 } }, { "local port": 60357, "endpoint": { "family": "IPv4", "address": "z.z.z.z", "port": 28677 }, "advertised endpoint": { "family": "IPv4", "address": "z.z.z.z", "port": 55785 }, "last packet": 1583321701, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2446676299, "stats": { "packets": 7, "bytes": 524, "errors": 0 } } ], "flags": [ "initialized", "send", "recv" ] } ] }, "gK06f2624f": { "tag": "gK06f2624f", "label": "Bleg_label", "created": 1583321677, "in dialogue with": "KaJTCfE07", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVP", "streams": [ { "local port": 60348, "endpoint": { "family": "IPv4", "address": "x.x.x.x", "port": 27718 }, "advertised endpoint": { "family": "IPv4", "address": "x.x.x.x", "port": 27718 }, "last packet": 1583321705, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 781550334, "stats": { "packets": 843, "bytes": 144996, "errors": 0 } }, { "local port": 60349, "endpoint": { "family": "IPv4", "address": "x.x.x.x", "port": 27719 }, "advertised endpoint": { "family": "IPv4", "address": "x.x.x.x", "port": 27719 }, "last packet": 1583321703, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 781550334, "stats": { "packets": 3, "bytes": 252, "errors": 0 } } ], "flags": [ "initialized", "send", "recv", "ICE controlling" ] } ] } }, "totals": { "RTP": { "packets": 1634, "bytes": 281048, "errors": 0 }, "RTCP": { "packets": 10, "bytes": 776, "errors": 0 } }, "result": "ok" }

But they are inaccessible from the kamailio using the params ( as mentioned on https://www.kamailio.org/docs/modules/devel/modules/rtpengine.html#rtpengine.p.mos_average_A_pv) and the value to avp variables is 0 for both legs . I assigned these after receiving BYE for a within dialog request .

Steps to reproduce

configuring kamailio config 

modparam("rtpengine", "mos_A_label_pv", "$avp(mos_A_label)")
modparam("rtpengine", "mos_average_A_pv", "$avp(mos_average_A)")
modparam("rtpengine", "mos_B_label_pv", "$avp(mos_B_label)")
modparam("rtpengine", "mos_average_B_pv", "$avp(mos_average_B)")

Assigning labels values to avp headers.sets("$avp(mos_A_label)","Aleg_label") headers.sets("$avp(mos_B_label)","Bleg_label") Fetching values 

    local mos_average_A = headers.get("$avp(mos_average_A)") or 0
    logger.log("info", "mos_average_A " .. mos_average_A)

    local mos_average_B = headers.get("$avp(mos_average_B)") or 0
    logger.log("info", "mos_average_B " .. mos_average_B)

Output 

BYE|5a995e62-6840-43e6-980d-ecaf40326051|mos_average_A 0
BYE|5a995e62-6840-43e6-980d-ecaf40326051|mos_average_B 0

However yet I am able to obtain the overall mos average score the same way configuring kamailio config 

modparam("rtpengine", "mos_average_pv", "$avp(mos_average)")

Fetching values 

local mos_average = headers.get("$avp(mos_average)") or 0
logger.log("info", "mos avg " .. mos_average)

output

BYE|5a995e62-6840-43e6-980d-ecaf40326051| mos avg 3.8

Maybe there is something i am missing , in that case kindly point out what that might be . I can provide detailed RTPengine logs , pcaps and debug level 4 logs from kamailio too is that could help debug what might be causing the mos_average_A and mos_average_B to be nill .

Thank you in anticipation .

rfuchs commented 4 years ago

Are you setting the mos_X_label values before processing the BYE?

Can you post the "final packet stats" from the rtpengine log?

altanai commented 4 years ago

yes I am setting the mos_X_label values before processing the BYE and fetching their values after KSR.rtpengine.rtpengine_delete0() pastebin for full RTPengine logs : https://pastebin.com/PB4Z44Ta

rfuchs commented 4 years ago

So AFAICS there's nothing wrong on the rtpengine side. The issue must be on the Kamailio module side. Unfortunately I'm not all that familiar with the Lua variant of the Kamailio config. Can you try doing the same using regular Kamailio config syntax?

altanai commented 4 years ago

@rfuchs , I have replicated the same on native kamailio cfg and found the same outcome , rtpengine displays the mos score leg wise but the sae is not updated onto the pv's in the code. Please find the code and its output below :

RTP engine params 

...
# ----- rtpengine params -----
modparam("rtpengine", "rtpengine_sock", "udp:<ip:port>")
modparam("rtpengine", "extra_id_pv", "$avp(extra_id)")

modparam("rtpengine", "rtpengine_allow_op", 1)
modparam("rtpengine", "queried_nodes_limit", 4)
modparam("rtpengine", "rtpengine_retr", 2)
modparam("rtpengine", "rtp_inst_pvar", "$avp(RTP_INSTANCE)")
modparam("rtpengine", "setid_default", 1)

modparam("rtpengine", "mos_max_pv", "$avp(mos_max)")
modparam("rtpengine", "mos_average_pv", "$avp(mos_average)")
modparam("rtpengine", "mos_min_pv", "$avp(mos_min)")

modparam("rtpengine", "mos_average_packetloss_pv", "$avp(mos_average_packetloss)")
modparam("rtpengine", "mos_average_jitter_pv", "$avp(mos_average_jitter)")
modparam("rtpengine", "mos_average_roundtrip_pv", "$avp(mos_average_roundtrip)")
modparam("rtpengine", "mos_average_samples_pv", "$avp(mos_average_samples)")

modparam("rtpengine", "mos_min_pv", "$avp(mos_min)")
modparam("rtpengine", "mos_min_at_pv", "$avp(mos_min_at)")
modparam("rtpengine", "mos_min_packetloss_pv", "$avp(mos_min_packetloss)")
modparam("rtpengine", "mos_min_jitter_pv", "$avp(mos_min_jitter)")
modparam("rtpengine", "mos_min_roundtrip_pv", "$avp(mos_min_roundtrip)")

modparam("rtpengine", "mos_A_label_pv", "$avp(mos_A_label)")
modparam("rtpengine", "mos_average_packetloss_A_pv", "$avp(mos_average_packetloss_A)")
modparam("rtpengine", "mos_average_jitter_A_pv", "$avp(mos_average_jitter_A)")
modparam("rtpengine", "mos_average_roundtrip_A_pv", "$avp(mos_average_roundtrip_A)")
modparam("rtpengine", "mos_average_A_pv", "$avp(mos_average_A)")

modparam("rtpengine", "mos_B_label_pv", "$avp(mos_B_label)")
modparam("rtpengine", "mos_average_packetloss_B_pv", "$avp(mos_average_packetloss_B)")
modparam("rtpengine", "mos_average_jitter_B_pv", "$avp(mos_average_jitter_B)")
modparam("rtpengine", "mos_average_roundtrip_B_pv", "$avp(mos_average_roundtrip_B)")
modparam("rtpengine", "mos_average_B_pv", "$avp(mos_average_B)")

handling requests 

request_route {

    xlog("L_INFO"," ------------------ request_route  $rm from $fu (IP:$si:$sp) \n ");

    # per request initial checks
    route(REQINIT);

    # NAT detection
    route(NATDETECT);

    # CANCEL processing
    if (is_method("CANCEL")) {
        xlog("L_INFO"," CANCEL processing \n");
        if (t_check_trans()) {
            route(RELAY);
        }
        exit;
    }

    # handle retransmissions
    if (!is_method("ACK")) {
        xlog("L_INFO"," retransmissions processing \n");
        if(t_precheck_trans()) {
            t_check_trans();
            exit;
        }
        t_check_trans();
    }

    # handle requests within SIP dialogs
    route(WITHINDLG);

    if (is_method("INVITE|SUBSCRIBE")) {
        record_route();
    }

    # account only INVITEs
    if (is_method("INVITE")) {

        xlog("L_INFO"," INVITE processing \n");
        if (has_body("application/sdp")) {
            rtpengine_offer("replace-origin replace-session-connection ICE=remove label=Aleg_label");
        }
    }

    if ($rU==$null) {
        # request with no Username in RURI
        sl_send_reply("484","Address Incomplete");
        exit;
    }

    route(RELAY);
}

handling replies 

# Manage incoming replies
onreply_route[MANAGE_REPLY] {
    xdbg("incoming reply\n");

    if (has_body("application/sdp")){
        rtpengine_answer("replace-origin replace-session-connection ICE=remove label=Bleg_label");
    }

    # if status is not 1xx or 2xx , do natmanage
    if(status=~"[12][0-9][0-9]") {
        route(NATMANAGE);
    }
}

handling dialog termination and population of scores in pvs

route[WITHINDLG] {
    if (!has_totag()) return;

    xlog("L_INFO", " route WITHINDLG \n ");

    if (loose_route()) {

        xlog("L_INFO", " looseroute : sequential requets within dialog \n ");

        route(DLGURI);

        if (is_method("BYE")) {

            xlog("L_INFO", " BYE processing collect mos score \n");

            $avp("mos_A_label")="Aleg_label";
            $avp("mos_B_label")="Bleg_label";

            xlog("L_INFO", " rtpstats - $rtpstat\r\n ");
            append_hf("X-RTP-Statistics: $rtpstat\r\n");

            xlog("L_INFO", " ====================  delete RTPengine \n");
            rtpengine_delete();

            xlog("L_INFO", " mos avg $avp(mos_average) \n ");
            xlog("L_INFO", " mos max $avp(mos_max) \n ");
            xlog("L_INFO", " mos min $avp(mos_min)  \n ");

            xlog("L_INFO", "mos_average_packetloss_pv $avp(mos_average_packetloss)  \n");
            xlog("L_INFO", "mos_average_jitter_pv $avp(mos_average_jitter)  \n ");
            xlog("L_INFO", "mos_average_roundtrip_pv $avp(mos_average_roundtrip) \n ");
            xlog("L_INFO", "mos_average_samples_pv $avp(mos_average_samples) \n ");

            xlog("L_INFO", "mos_min_pv $avp(mos_min) \n ");
            xlog("L_INFO", "mos_min_at_pv $avp(mos_min_at) \n ");
            xlog("L_INFO", "mos_min_packetloss_pv $avp(mos_min_packetloss) \n ");
            xlog("L_INFO", "mos_min_jitter_pv $avp(mos_min_jitter) \n ");
            xlog("L_INFO", "mos_min_roundtrip_pv $avp(mos_min_roundtrip) \n ");

            # xlog( "mos_A_label_pv $avp(mos_A_label) \n ");
            xlog("L_INFO", "mos_average_packetloss_A_pv $avp(mos_average_packetloss_A) \n ");
            xlog("L_INFO", "mos_average_jitter_A_pv $avp(mos_average_jitter_A) \n ");
            xlog("L_INFO", "mos_average_roundtrip_A_pv $avp(mos_average_roundtrip_A) \n ");
            xlog("L_INFO", "mos_average_A_pv $avp(mos_average_A) \n ");

            # xlog( "mos_B_label_pv $avp(mos_B_label) \n ");
            xlog("L_INFO", "mos_average_packetloss_B_pv $avp(mos_average_packetloss_B) \n ");
            xlog("L_INFO", "mos_average_jitter_B_pv $avp(mos_average_jitter_B) \n ");
            xlog("L_INFO", "mos_average_roundtrip_B_pv $avp(mos_average_roundtrip_B) \n ");
            xlog("L_INFO", "mos_average_B_pv $avp(mos_average_B) \n ");

        } else if ( is_method("ACK") ) {
            # ACK is forwarded statelessly
            route(NATMANAGE);
        }
        route(RELAY);
        exit;
    }

    xlog("L_INFO", " loose routing could not be done  \n ");

    if ( is_method("ACK") ) {
        if ( t_check_trans() ) {
            route(RELAY);
            exit;
        } else {
            exit;
        }
    }
    exit;
}

I have pasted only relevant part of program , Please let me know if full code is required

output

24(189) INFO: <script>:  ------------------ request_route  INVITE from sip:user@sipdomain (IP:x.x.x.x:x.x) 
 24(189) INFO: <script>:  NATDetect force rport 
 24(189) INFO: <script>:  NATDetect is frst hop , set contact alias 
 24(189) INFO: <script>:  NATDetect set flag , FLT_NATS  
 24(189) INFO: <script>:  retransmissions processing 
24(189) INFO: <script>:  INVITE processing 
24(189) INFO: <script>:  INVITE has SDP , ask rtpengine to modify it for a new offer 
25(190) INFO: <script>: Got a succesful reply , ask rtpengine to modify answer SDP 
 24(189) INFO: <script>:  ------------------ request_route  ACK from sip:user@sipdomain (IP:x.x.x.x:x.x) 
 24(189) INFO: <script>:  NATDetect force rport 
 24(189) INFO: <script>:  NATDetect is frst hop , set contact alias 
 24(189) INFO: <script>:  NATDetect set flag , FLT_NATS  
 24(189) INFO: <script>:  route WITHINDLG 
 24(189) INFO: <script>:  looseroute : sequential requets within dialog 
 ..

 26(191) INFO: <script>:  ------------------ request_route  BYE from sip:user@sipdomain (IP:x.x.x.x:x.x) 
 26(191) INFO: <script>:  NATDetect force rport 
 26(191) INFO: <script>:  NATDetect is frst hop , set contact alias 
 26(191) INFO: <script>:  NATDetect set flag , FLT_NATS  
 26(191) INFO: <script>:  retransmissions processing 
26(191) INFO: <script>:  route WITHINDLG 
 26(191) INFO: <script>:  looseroute : sequential requets within dialog 
 26(191) INFO: <script>:  BYE processing collect mos score 
26(191) INFO: <script>:  rtpstats - RTP: 290508 bytes, 1689 packets, 0 errors; RTCP: 1892 bytes, 21 packets, 0 errors
 26(191) INFO: <script>:  ====================  delete RTPengine 
26(191) INFO: <script>:  mos avg 4.2 
 26(191) INFO: <script>:  mos max 4.3 
 26(191) INFO: <script>:  mos min 4.0  
 26(191) INFO: <script>: mos_average_packetloss_pv 0
26(191) INFO: <script>: mos_average_jitter_pv 6  
 26(191) INFO: <script>: mos_average_roundtrip_pv 269360 
 26(191) INFO: <script>: mos_average_samples_pv 5 
 26(191) INFO: <script>: mos_min_pv 4.0 
 26(191) INFO: <script>: mos_min_at_pv 0:20 
 26(191) INFO: <script>: mos_min_packetloss_pv 3 
 26(191) INFO: <script>: mos_min_jitter_pv 9 
 26(191) INFO: <script>: mos_min_roundtrip_pv 269711 
 26(191) INFO: <script>: mos_average_packetloss_A_pv <null> 
 26(191) INFO: <script>: mos_average_jitter_A_pv <null> 
 26(191) INFO: <script>: mos_average_roundtrip_A_pv <null> 
 26(191) INFO: <script>: mos_average_A_pv <null> 
 26(191) INFO: <script>: mos_average_packetloss_B_pv <null> 
 26(191) INFO: <script>: mos_average_jitter_B_pv <null> 
 26(191) INFO: <script>: mos_average_roundtrip_B_pv <null> 
 26(191) INFO: <script>: mos_average_B_pv <null>

output fro RTPengine 

[1586852488.825160] DEBUG: [ID="hV9IEel1io" port="60001"]: Calling handler for RTCP packet type 200
[1586852488.825247] DEBUG: [ID="hV9IEel1io" port="60001"]: SR from aac8e02: RTP TS 202720 PC 1267 OC 202720 NTP TS 3795841274/1031105683=3795841274.240073
[1586852488.825414] DEBUG: [ID="hV9IEel1io" port="60001"]: RR from aac8e02 about 7d940c74: FL 0 TL 9 HSR 1476 J 89 LSR 4043548102 DLSR 322434
[1586852488.825435] DEBUG: [ID="hV9IEel1io" port="60001"]: Calculated round-trip time for 7d940c74 is 196598 us
[1586852488.825442] DEBUG: [ID="hV9IEel1io" port="60001"]: Calculated jitter for 7d940c74 is 11 ms
[1586852488.825445] DEBUG: [ID="hV9IEel1io" port="60001"]: Adding opposide side RTT of 64112 us
[1586852488.825450] DEBUG: [ID="hV9IEel1io" port="60001"]: Calculated MOS from RR for aac8e02 is 4.3
[1586852488.825486] DEBUG: [ID="hV9IEel1io" port="60001"]: Calling handler for RTCP packet type 202
[1586852488.825505] DEBUG: [ID="hV9IEel1io" port="60001"]: Forward to sink endpoint: y.y.y.y:44562 (RTP seq 12 TS 179080706)
[1586852488.825294] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43646 TS 202880)
[1586852488.845353] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43647 TS 203040)
[1586852488.865275] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43648 TS 203200)
[1586852488.867411] INFO: Detected command from z.z.z.z:zz as a duplicate
[1586852488.869999] INFO: [ID="hV9IEel1io"]: Received command 'query' from z.z.z.z:zz
[1586852488.870011] DEBUG: [ID="hV9IEel1io"]: Dump for 'query' from z.z.z.z:zz: { "call-id": "hV9IEel1io", "received-from": [ "IP4", "p.p.p.p" ], "from-tag": "FCc2To9a-", "to-tag": "Q27D0KU7j697N", "command": "query" }
[1586852488.870145] INFO: [ID="hV9IEel1io"]: Replying to 'query' from z.z.z.z:zz (elapsed time 0.000119 sec)
[1586852488.870293] DEBUG: [ID="hV9IEel1io"]: Response dump for 'query' to z.z.z.z:zz: { "created": 1586852457, "created_us": 11951, "last signal": 1586852457, "SSRC": { "2106854516": { "average MOS": { "MOS": 42, "round-trip time": 264249, "jitter": 6, "packet loss": 0, "samples": 5 }, "lowest MOS": { "MOS": 42, "round-trip time": 300690, "jitter": 9, "packet loss": 0, "reported at": 1586852472 }, "highest MOS": { "MOS": 43, "round-trip time": 249415, "jitter": 8, "packet loss": 0, "reported at": 1586852466 }, "MOS progression": { "interval": 1, "entries": [ { "MOS": 43, "round-trip time": 249415, "jitter": 8, "packet loss": 0, "reported at": 1586852466 }, { "MOS": 43, "round-trip time": 259277, "jitter": 6, "packet loss": 0, "reported at": 1586852469 }, { "MOS": 42, "round-trip time": 300690, "jitter": 9, "packet loss": 0, "reported at": 1586852472 }, { "MOS": 43, "round-trip time": 261608, "jitter": 4, "packet loss": 0, "reported at": 1586852477 }, { "MOS": 43, "round-trip time": 250258, "jitter": 5, "packet loss": 0, "reported at": 1586852483 } ] } }, "179080706": { "average MOS": { "MOS": 42, "round-trip time": 267174, "jitter": 10, "packet loss": 0, "samples": 18 }, "lowest MOS": { "MOS": 40, "round-trip time": 260869, "jitter": 11, "packet loss": 3, "reported at": 1586852479 }, "highest MOS": { "MOS": 43, "round-trip time": 185944, "jitter": 8, "packet loss": 0, "reported at": 1586852465 }, "MOS progression": { "interval": 2, "entries": [ { "MOS": 43, "round-trip time": 185944, "jitter": 8, "packet loss": 0, "reported at": 1586852465 }, { "MOS": 43, "round-trip time": 259768, "jitter": 10, "packet loss": 0, "reported at": 1586852469 }, { "MOS": 42, "round-trip time": 301000, "jitter": 12, "packet loss": 0, "reported at": 1586852473 }, { "MOS": 42, "round-trip time": 301006, "jitter": 12, "packet loss": 1, "reported at": 1586852474 }, { "MOS": 42, "round-trip time": 301001, "jitter": 10, "packet loss": 0, "reported at": 1586852475 }, { "MOS": 42, "round-trip time": 300998, "jitter": 9, "packet loss": 1, "reported at": 1586852476 }, { "MOS": 42, "round-trip time": 301118, "jitter": 14, "packet loss": 1, "reported at": 1586852477 }, { "MOS": 40, "round-trip time": 260869, "jitter": 11, "packet loss": 3, "reported at": 1586852479 }, { "MOS": 43, "round-trip time": 260980, "jitter": 8, "packet loss": 0, "reported at": 1586852481 }, { "MOS": 43, "round-trip time": 250442, "jitter": 6, "packet loss": 0, "reported at": 1586852483 }, { "MOS": 43, "round-trip time": 260628, "jitter": 7, "packet loss": 0, "reported at": 1586852485 }, { "MOS": 42, "round-trip time": 260689, "jitter": 12, "packet loss": 1, "reported at": 1586852487 } ] } } }, "tags": { "Q27D0KU7j697N": { "tag": "Q27D0KU7j697N", "label": "Bleg_label", "created": 1586852457, "in dialogue with": "FCc2To9a-", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVP", "streams": [ { "local port": 60000, "endpoint": { "family": "IPv4", "address": "f.f.f.f", "port": 25610 }, "advertised endpoint": { "family": "IPv4", "address": "q.q.q.q", "port": 25610 }, "last packet": 1586852488, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 179080706, "stats": { "packets": 1269, "bytes": 218268, "errors": 0 } }, { "local port": 60001, "endpoint": { "family": "IPv4", "address": "f.f.f.f", "port": 25611 }, "advertised endpoint": { "family": "IPv4", "address": "q.q.q.q", "port": 25611 }, "last packet": 1586852488, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 179080706, "stats": { "packets": 19, "bytes": 2108, "errors": 0 } } ], "flags": [ "initialized", "send", "recv", "ICE controlling" ] } ] }, "FCc2To9a-": { "tag": "FCc2To9a-", "label": "Aleg_label", "created": 1586852457, "in dialogue with": "Q27D0KU7j697N", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVP", "streams": [ { "local port": 60020, "endpoint": { "family": "IPv4", "address": "y.y.y.y", "port": 11099 }, "advertised endpoint": { "family": "IPv4", "address": "p.p.p.p", "port": 50471 }, "last packet": 1586852487, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2106854516, "stats": { "packets": 1468, "bytes": 252496, "errors": 0 } }, { "local port": 60021, "endpoint": { "family": "IPv4", "address": "y.y.y.y", "port": 44562 }, "advertised endpoint": { "family": "IPv4", "address": "p.p.p.p", "port": 39460 }, "last packet": 1586852483, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2106854516, "stats": { "packets": 14, "bytes": 1256, "errors": 0 } } ], "flags": [ "initialized", "send", "recv" ] } ] } }, "totals": { "RTP": { "packets": 2737, "bytes": 470764, "errors": 0 }, "RTCP": { "packets": 33, "bytes": 3364, "errors": 0 } }, "result": "ok" }
[1586852488.870775] INFO: [ID="hV9IEel1io"]: Received command 'delete' from z.z.z.z:zz
[1586852488.870816] DEBUG: [ID="hV9IEel1io"]: Dump for 'delete' from z.z.z.z:zz: { "call-id": "hV9IEel1io", "received-from": [ "IP4", "p.p.p.p" ], "from-tag": "FCc2To9a-", "command": "delete" }
[1586852488.870987] INFO: [ID="hV9IEel1io"]: Scheduling deletion of call branch 'FCc2To9a-' (via-branch '') in 30 seconds
[1586852488.871070] INFO: [ID="hV9IEel1io"]: Replying to 'delete' from z.z.z.z:zz (elapsed time 0.000171 sec)
[1586852488.871272] DEBUG: [ID="hV9IEel1io"]: Response dump for 'delete' to z.z.z.z:zz: { "created": 1586852457, "created_us": 11951, "last signal": 1586852457, "SSRC": { "2106854516": { "average MOS": { "MOS": 42, "round-trip time": 264249, "jitter": 6, "packet loss": 0, "samples": 5 }, "lowest MOS": { "MOS": 42, "round-trip time": 300690, "jitter": 9, "packet loss": 0, "reported at": 1586852472 }, "highest MOS": { "MOS": 43, "round-trip time": 249415, "jitter": 8, "packet loss": 0, "reported at": 1586852466 }, "MOS progression": { "interval": 1, "entries": [ { "MOS": 43, "round-trip time": 249415, "jitter": 8, "packet loss": 0, "reported at": 1586852466 }, { "MOS": 43, "round-trip time": 259277, "jitter": 6, "packet loss": 0, "reported at": 1586852469 }, { "MOS": 42, "round-trip time": 300690, "jitter": 9, "packet loss": 0, "reported at": 1586852472 }, { "MOS": 43, "round-trip time": 261608, "jitter": 4, "packet loss": 0, "reported at": 1586852477 }, { "MOS": 43, "round-trip time": 250258, "jitter": 5, "packet loss": 0, "reported at": 1586852483 } ] } }, "179080706": { "average MOS": { "MOS": 42, "round-trip time": 267174, "jitter": 10, "packet loss": 0, "samples": 18 }, "lowest MOS": { "MOS": 40, "round-trip time": 260869, "jitter": 11, "packet loss": 3, "reported at": 1586852479 }, "highest MOS": { "MOS": 43, "round-trip time": 185944, "jitter": 8, "packet loss": 0, "reported at": 1586852465 }, "MOS progression": { "interval": 2, "entries": [ { "MOS": 43, "round-trip time": 185944, "jitter": 8, "packet loss": 0, "reported at": 1586852465 }, { "MOS": 43, "round-trip time": 259768, "jitter": 10, "packet loss": 0, "reported at": 1586852469 }, { "MOS": 42, "round-trip time": 301000, "jitter": 12, "packet loss": 0, "reported at": 1586852473 }, { "MOS": 42, "round-trip time": 301006, "jitter": 12, "packet loss": 1, "reported at": 1586852474 }, { "MOS": 42, "round-trip time": 301001, "jitter": 10, "packet loss": 0, "reported at": 1586852475 }, { "MOS": 42, "round-trip time": 300998, "jitter": 9, "packet loss": 1, "reported at": 1586852476 }, { "MOS": 42, "round-trip time": 301118, "jitter": 14, "packet loss": 1, "reported at": 1586852477 }, { "MOS": 40, "round-trip time": 260869, "jitter": 11, "packet loss": 3, "reported at": 1586852479 }, { "MOS": 43, "round-trip time": 260980, "jitter": 8, "packet loss": 0, "reported at": 1586852481 }, { "MOS": 43, "round-trip time": 250442, "jitter": 6, "packet loss": 0, "reported at": 1586852483 }, { "MOS": 43, "round-trip time": 260628, "jitter": 7, "packet loss": 0, "reported at": 1586852485 }, { "MOS": 42, "round-trip time": 260689, "jitter": 12, "packet loss": 1, "reported at": 1586852487 } ] } } }, "tags": { "FCc2To9a-": { "tag": "FCc2To9a-", "label": "Aleg_label", "created": 1586852457, "in dialogue with": "Q27D0KU7j697N", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVP", "streams": [ { "local port": 60020, "endpoint": { "family": "IPv4", "address": "y.y.y.y", "port": 11099 }, "advertised endpoint": { "family": "IPv4", "address": "p.p.p.p", "port": 50471 }, "last packet": 1586852487, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2106854516, "stats": { "packets": 1468, "bytes": 252496, "errors": 0 } }, { "local port": 60021, "endpoint": { "family": "IPv4", "address": "y.y.y.y", "port": 44562 }, "advertised endpoint": { "family": "IPv4", "address": "p.p.p.p", "port": 39460 }, "last packet": 1586852483, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 2106854516, "stats": { "packets": 14, "bytes": 1256, "errors": 0 } } ], "flags": [ "initialized", "send", "recv" ] } ] }, "Q27D0KU7j697N": { "tag": "Q27D0KU7j697N", "label": "Bleg_label", "created": 1586852457, "in dialogue with": "FCc2To9a-", "medias": [ { "index": 1, "type": "audio", "protocol": "RTP/AVP", "streams": [ { "local port": 60000, "endpoint": { "family": "IPv4", "address": "f.f.f.f", "port": 25610 }, "advertised endpoint": { "family": "IPv4", "address": "q.q.q.q", "port": 25610 }, "last packet": 1586852488, "flags": [ "RTP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 179080706, "stats": { "packets": 1269, "bytes": 218268, "errors": 0 } }, { "local port": 60001, "endpoint": { "family": "IPv4", "address": "f.f.f.f", "port": 25611 }, "advertised endpoint": { "family": "IPv4", "address": "q.q.q.q", "port": 25611 }, "last packet": 1586852488, "flags": [ "RTCP", "filled", "confirmed", "kernelized", "no kernel support" ], "SSRC": 179080706, "stats": { "packets": 19, "bytes": 2108, "errors": 0 } } ], "flags": [ "initialized", "send", "recv", "ICE controlling" ] } ] } }, "totals": { "RTP": { "packets": 2737, "bytes": 470764, "errors": 0 }, "RTCP": { "packets": 33, "bytes": 3364, "errors": 0 } }, "result": "ok" }
[1586852488.885324] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43649 TS 203360)
[1586852488.905392] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43650 TS 203520)
...
[1586852489.025249] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43656 TS 204480)
[1586852489.045317] DEBUG: [ID="hV9IEel1io" port="60000"]: Forward to sink endpoint: y.y.y.y:11099 (RTP seq 43657 TS 204640)
[1586852490.000081] DEBUG: timer run time = 0.000011 sec
[1586852492.000081] DEBUG: timer run time = 0.000013 sec
[1586852492.957470] INFO: New cli connection from o.o.o.o:42598
[1586852492.957499] INFO: Got CLI command: list maxsessions
[1586852493.000076] DEBUG: timer run time = 0.000011 sec
[1586852494.000081] DEBUG: timer run time = 0.000012 sec
[1586852495.000082] DEBUG: timer run time = 0.000013 sec
[1586852496.000082] DEBUG: timer run time = 0.000013 sec
[1586852497.000088] DEBUG: timer run time = 0.000014 sec
[1586852497.843242] INFO: New cli connection from o.o.o.o:42836
[1586852497.843269] INFO: Got CLI command: list maxsessions
[1586852499.000079] DEBUG: timer run time = 0.000012 sec
[1586852500.000089] DEBUG: timer run time = 0.000014 sec
[1586852501.000088] DEBUG: timer run time = 0.000013 sec
[1586852502.976801] INFO: New cli connection from o.o.o.o:43090
[1586852502.976927] INFO: Got CLI command: list maxsessions
[1586852503.000077] DEBUG: timer run time = 0.000011 sec
[1586852504.000083] DEBUG: timer run time = 0.000013 sec
[1586852506.007110] DEBUG: timer run time = 0.000013 sec
[1586852507.864524] INFO: New cli connection from o.o.o.o:43330
[1586852507.864596] INFO: Got CLI command: list maxsessions
[1586852508.000084] DEBUG: timer run time = 0.000015 sec
[1586852508.113568] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: Setting ICE candidate pair ljo6dEXaO4Zs8arx:1:1 as failed
[1586852508.113579] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: scheduling timer object at 1586852508.153354
[1586852508.153424] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: Setting ICE candidate pair ljo6dEXaO4Zs8arx:2:1 as failed
[1586852508.153436] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: scheduling timer object at 1586852508.173435
[1586852508.173503] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: Setting ICE candidate pair ljo6dEXaO4Zs8arx:1:2 as failed
[1586852508.173513] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: scheduling timer object at 1586852508.196220
[1586852508.196292] DEBUG: [ID="hV9IEel1io" tag="FCc2To9a-" index="1"]: Setting ICE candidate pair ljo6dEXaO4Zs8arx:2:2 as failed
[1586852510.000138] DEBUG: timer run time = 0.000015 sec
[1586852512.000080] DEBUG: timer run time = 0.000013 sec
[1586852512.999125] INFO: New cli connection from o.o.o.o:43586
[1586852512.999154] INFO: Got CLI command: list maxsessions
[1586852513.000081] DEBUG: timer run time = 0.000012 sec
[1586852515.000080] DEBUG: timer run time = 0.000012 sec
[1586852517.000081] DEBUG: timer run time = 0.000012 sec
[1586852517.885017] INFO: New cli connection from o.o.o.o:43826
[1586852517.885211] INFO: Got CLI command: list maxsessions
[1586852518.000082] INFO: [ID="hV9IEel1io"]: Call branch 'FCc2To9a-' (label 'Aleg_label', via-branch '') deleted, no more branches remaining
[1586852518.000099] INFO: [ID="hV9IEel1io"]: Final packet stats:
[1586852518.000104] INFO: [ID="hV9IEel1io"]: --- Tag 'FCc2To9a-' (label 'Aleg_label'), created 1:01 ago for branch '', in dialogue with 'Q27D0KU7j697N'
[1586852518.000237] INFO: [ID="hV9IEel1io"]: ------ Media #1 (audio over RTP/AVP) using PCMU/8000
[1586852518.000253] DEBUG: [ID="hV9IEel1io"]: freeing send_timer
[1586852518.000274] INFO: [ID="hV9IEel1io"]: --------- Port    x.x.x.x:60020 <> y.y.y.y:11099, SSRC 7d940c74, 1468 p, 252496 b, 0 e, 31 ts
[1586852518.000276] DEBUG: [ID="hV9IEel1io"]: freeing send_timer
[1586852518.000281] INFO: [ID="hV9IEel1io"]: --------- Port    x.x.x.x:60021 <> y.y.y.y:44562 (RTCP), SSRC 7d940c74, 14 p, 1256 b, 0 e, 35 ts
[1586852518.000292] INFO: [ID="hV9IEel1io"]: --- Tag 'Q27D0KU7j697N' (label 'Bleg_label'), created 1:01 ago for branch '', in dialogue with 'FCc2To9a-'
[1586852518.000299] INFO: [ID="hV9IEel1io"]: ------ Media #1 (audio over RTP/AVP) using PCMU/8000
[1586852518.000301] DEBUG: [ID="hV9IEel1io"]: freeing send_timer
[1586852518.000306] INFO: [ID="hV9IEel1io"]: --------- Port    x.x.x.x:60000 <>   f.f.f.f:25610, SSRC aac8e02, 1278 p, 219816 b, 0 e, 29 ts
[1586852518.000309] DEBUG: [ID="hV9IEel1io"]: freeing send_timer
[1586852518.000328] INFO: [ID="hV9IEel1io"]: --------- Port    x.x.x.x:60001 <>   f.f.f.f:25611 (RTCP), SSRC aac8e02, 19 p, 2108 b, 0 e, 30 ts
[1586852518.000331] INFO: [ID="hV9IEel1io"]: --- SSRC 7d940c74
[1586852518.000334] INFO: [ID="hV9IEel1io"]: ------ Average MOS 4.2, lowest MOS 4.2 (at 0:15), highest MOS 4.3 (at 0:09)
[1586852518.000336] INFO: [ID="hV9IEel1io"]: --- SSRC aac8e02
[1586852518.000339] INFO: [ID="hV9IEel1io"]: ------ Average MOS 4.2, lowest MOS 4.0 (at 0:22), highest MOS 4.3 (at 0:08)
[1586852518.000381] DEBUG: [ID="hV9IEel1io"]: __free_ssrc_handler
[1586852518.000385] DEBUG: [ID="hV9IEel1io"]: __free_ssrc_handler

I do have a probable patch for the issue , please share if i this is indeed an issue to proceed .

Altanaib commented 4 years ago

@rfuchs I earnestly wait for any updates on this .

rfuchs commented 4 years ago

You said you have a patch for this?

altanai commented 4 years ago

Not an RTPengine issue at all. Closing this thread here

anis-bedhiafi commented 4 years ago

You are setting:

$avp("mos_A_label")="Aleg_label"; $avp("mos_B_label")="Bleg_label";

Instead of:

$avp(mos_A_label)="Aleg_label"; $avp(mos_B_label)="Bleg_label";

Omit the double quotes from the variable names

zenichev commented 2 years ago

@altanai thanks for your reporting here, it helped me a lot with the similar issue I had.