Hi,

The source for this string to int conversion error was found, it was just a minor glitch in an if statement! Man, I feel stupid...

Anyways, the problem about calls not going through still persists. This I located to the rtpengine_offer() call in a branch route. The sdp is not changed and this results in Kamailio forking away until it can't. In my test case there is a webrtc client calling another webrtc client. Here I use Kamailio 4.1.5, rtpengine and rtpproxy-ng module.

My branch route looks like this:

branch_route[MANAGE_RTPENGINE_BRANCH] {

xlog("L_INFO", "MANAGE_RTPENGINE_BRANCH: new branch [$T_branch_idx] to $ru\n");

xlog("L_INFO", "MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = $avp(rtpengine_offer_flags) and mline = $avp(mline)");

if ($avp(rtpengine_offer_flags) != "") {

xlog("L_INFO","MANAGE_RTPENGINE_BRANCH: rtpengine_offer with $avp(rtpengine_offer_flags)");

rtpproxy_offer($avp(rtpengine_offer_flags));

t_on_reply("RTPPROXY_REPLY");

} else {

xlog("L_ERR","MANAGE_RTPENGINE_BRANCH but rtp_offer_flags is EMPTY! ");

}

And this is what I get in the kamailio log:

Aug 20 21:47:58 u363id562 kamailio[28376]: ALERT: <script>: UA_FAILURE: SAVPF found, setting flags using RTP/AVP in offer and RTP/SAVPF in answer

Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: UA_FAILURE: hooked to RTPPROXY_REPLY reply_route and MANAGE_RTPENGINE_BRANCH branch_route, offer flags: froc-sp

Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...

Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [1] to sip:661@testers.com

Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = froc-sp and mline = m=audio 49466 RTP/SAVPF 111 103 104 0 8 106 105 13 126

Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp

Aug 20 21:47:58 u363id562 kamailio[28379]: ALERT: <script>: UA_FAILURE: SAVPF found, setting flags using RTP/AVP in offer and RTP/SAVPF in answer

Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: UA_FAILURE: hooked to RTPPROXY_REPLY reply_route and MANAGE_RTPENGINE_BRANCH branch_route, offer flags: froc-sp

Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...

Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [2] to sip:661@testers.com

Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = froc-sp and mline = m=audio 49466 RTP/SAVPF 111 103 104 0 8 106 105 13 126

Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp

... and so on

And this is what's happening in syslog between catching a 488, the rtpengine_offer call and the next 488:

Here 1.1.1.1 is the public ip of my Kamailio machine and 2.2.2.2 is the ip behind which my clients reside.

I haven't been able to spot the problem, maybe You will.

Aug 20 22:01:08 u363id562 kamailio[28610]: ALERT: <script>: UA_FAILURE: SAVPF found, setting flags using RTP/AVP in offer and RTP/SAVPF in answer

Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: UA_FAILURE: hooked to RTPPROXY_REPLY reply_route and MANAGE_RTPENGINE_BRANCH branch_route, offer flags: froc-sp

Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...

Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [1] to sip:661@testers.com

Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = froc-sp and mline = m=audio 55155 RTP/SAVPF 111 103 104 0 8 106 105 13 126

Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp

Aug 20 22:01:08 u363id562 rtpengine[32233]: Got valid command from 127.0.0.1:57017: offer - { "sdp": "v=0#015#012o=- 3706977575786663946 2 IN IP4 127.0.0.1#015#012s=-#015#012t=0 0#015#012a=group:BUNDLE audio#015#012a=msid-semantic: WMS C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz#015#012m=audio 55155 RTP/SAVPF 111 103 104 0 8 106 105 13 126#015#012c=IN IP4 2.2.2.2#015#012a=rtcp:55155 IN IP4 2.2.2.2#015#012a=candidate:2999745851 1 udp 2122260223 192.168.56.1 55154 typ host generation 0#015#012a=candidate:2999745851 2 udp 2122260223 192.168.56.1 55154 typ host generation 0#015#012a=candidate:3350409123 ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: ... 1 udp 2122194687 192.168.0.101 55155 typ host generation 0#015#012a=candidate:3350409123 2 udp 2122194687 192.168.0.101 55155 typ host generation 0#015#012a=candidate:4233069003 1 tcp 1518280447 192.168.56.1 0 typ host generation 0#015#012a=candidate:4233069003 2 tcp 1518280447 192.168.56.1 0 typ host generation 0#015#012a=candidate:2301678419 1 tcp 1518214911 192.168.0.101 0 typ host generation 0#015#012a=candidate:2301678419 2 tcp 1518214911 192.168.0.101 0 typ host generation 0#015#012a=candidate:1190865175 1 udp 1685987071 91. ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: ... 145.67.22 55155 typ srflx raddr 192.168.0.101 rport 55155 generation 0#015#012a=candidate:1190865175 2 udp 1685987071 2.2.2.2 55155 typ srflx raddr 192.168.0.101 rport 55155 generation 0#015#012a=ice-ufrag:A/jaPavOgPBuvQLE#015#012a=ice-pwd:cDlvtQt87wG8uuOhrEmhg9dX#015#012a=ice-options:google-ice#015#012a=fingerprint:sha-256 CF:30:A7:7F:71:11:D4:5E:B0:E7:E3:F9:D8:C2:F4:60:2A:D0:76:46:F8:3A:97:01:C9:0C:5A:F7:B8:7D:C1:43#015#012a=setup:actpass#015#012a=mid:audio#015#012a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level#015#012a=extmap:3 http: ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: ... //www.webrtc.org/experiments/rtp-hdrext/abs-send-time#015#012a=sendrecv#015#012a=rtcp-mux#015#012a=rtpmap:111 opus/48000/2#015#012a=fmtp:111 minptime=10#015#012a=rtpmap:103 ISAC/16000#015#012a=rtpmap:104 ISAC/32000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:106 CN/32000#015#012a=rtpmap:105 CN/16000#015#012a=rtpmap:13 CN/8000#015#012a=rtpmap:126 telephone-event/8000#015#012a=maxptime:60#015#012a=ssrc:772277070 cname:BwsjKefqgs/g3RSF#015#012a=ssrc:772277070 msid:C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz b7ec3c91-c3a2-4ede-adbf-ada31cb9504f#015#012a=ssrc:772277070 msla ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: ... bel:C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz#015#012a=ssrc:772277070 label:b7ec3c91-c3a2-4ede-adbf-ada31cb9504f#015#012", "ICE": "remove", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/AVP", "call-id": "ug2htprt2erjsat1e6rc", "received-from": [ "IP4", "2.2.2.2" ], "from-tag": "vf9jdb7362", "command": "offer" }

Aug 20 22:01:08 u363id562 rtpengine[32233]: Unknown flag encountered: 'force'

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Creating new call

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Returning to SIP proxy: d3:sdp762:v=0#015#012o=- 3706977575786663946 2 IN IP4 1.1.1.1#015#012s=-#015#012t=0 0#015#012a=msid-semantic: WMS C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz#015#012m=audio 10624 RTP/AVP 111 103 104 0 8 106 105 13 126#015#012c=IN IP4 1.1.1.1#015#012a=rtpmap:111 opus/48000/2#015#012a=fmtp:111 minptime=10#015#012a=rtpmap:103 ISAC/16000#015#012a=rtpmap:104 ISAC/32000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:106 CN/32000#015#012a=rtpmap:105 CN/16000#015#012a=rtpmap:13 CN/8000#015#012a=rtpmap:126 telephone-event/8000#015#012a=maxptime:60#015#012a=ss ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ... rc:772277070 cname:BwsjKefqgs/g3RSF#015#012a=ssrc:772277070 msid:C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz b7ec3c91-c3a2-4ede-adbf-ada31cb9504f#015#012a=ssrc:772277070 mslabel:C4FrYLUUCeWV8DP6OQlzG3XOBCZrnmVlTWuz#015#012a=ssrc:772277070 label:b7ec3c91-c3a2-4ede-adbf-ada31cb9504f#015#012a=sendrecv#015#012a=rtcp:10625#015#012a=rtcp-mux#015#0126:result2:oke

Aug 20 22:01:08 u363id562 rtpengine[32233]: Got valid command from 127.0.0.1:49781: delete - { "call-id": "ug2htprt2erjsat1e6rc", "received-from": [ "IP4", "2.2.2.2" ], "from-tag": "vf9jdb7362", "command": "delete" }

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Deleting full call

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Final packet stats:

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] --- Tag '', created 0:00 ago, in dialogue with '(none)'

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ------ Media #1, port 10626 <> 2.2.2.2:55155, 0 p, 0 b, 0 e

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] --- Tag 'vf9jdb7362', created 0:00 ago, in dialogue with ''

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ------ Media #1, port 10624 <> [::]:0 , 0 p, 0 b, 0 e

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Returning to SIP proxy: d7:createdi1408557668e11:last signali1408557668e4:tagsd10:vf9jdb7362d3:tag10:vf9jdb73627:createdi1408557668e16:in dialogue with0:6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti10624e8:endpointd6:family4:IPv67:address2:::4:porti0ee19:advertised endpointd6:family4:IPv67:address2:::4:porti0ee11:last packeti1408557668e5:flagsl3:RTP4:RTCPe5:statsd7:packetsi0e5:bytesi0e6:errorsi0eeed10:local porti10625e8:endpointd6:family4:IPv67:address2:::4:porti0 ...

Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ... ee19:advertised endpointd6:family4:IPv67:address2:::4:porti0ee11:last packeti1408557668e5:flagsl4:RTCP13:fallback RTCPe5:statsd7:packetsi0e5:bytesi0e6:errorsi0eeee5:flagsl8:rtcp-muxeeeee6:totalsd3:RTPd7:packetsi0e5:bytesi0e6:errorsi0ee4:RTCPd7:packetsi0e5:bytesi0e6:errorsi0eee6:result2:oke

Aug 20 22:01:08 u363id562 kamailio[28613]: ALERT: <script>: UA_FAILURE: SAVPF found, setting flags using RTP/AVP in offer and RTP/SAVPF in answer

Can you guys spot the problem from these logs? I've been stuck with this for a while, I must be doing something wrong but don't know what...

cheers,

Olli

2014-08-19 11:13 GMT+03:00 Olli Heiskanen <ohjelmistoarkkitehti@gmail.com>:

Hi,

A little follow-up on this:

The problem only happens when I call rtpengine_offer() inside a branch_route. If I call rtpengine_offer() in the failure_route (after 488) this conversion error does not happen, but then I get the double sdp issue indicated here: http://lists.sip-router.org/pipermail/sr-dev/2014-July/024507.html

The same problem occurs with Kamailio 4.1.5 and rtpproxy-ng. My current setup uses Kamailio 4.2 (devel) and rtpengine.

If anyone has a way around this, I'd appreciate very much to hear it! This prevents any calls from being setup.

cheers,
Olli

2014-08-15 18:40 GMT+03:00 Olli Heiskanen <ohjelmistoarkkitehti@gmail.com>:

Hello,

As outcome to my earlier sdp/rtp challenges I've upgraded my Asterisk version to 11.11.0 and still use a realtime integration with Kamailio. Now I face a somewhat different problem. With my setup I also changed from jssip client to a sip.js client in my websocket implementation. I cloned the latest rtpengine from git today.

I had to revert my Asterisk settings a bit, Asterisk was taking over with sdp handling, I don't know if this is relevant but that's why I got calls seemingly working before.

When getting the 488 Not Acceptable, I arm a branch route and call rtpengine_offer there. When trying to call rtpengine_offer, I get the following log:
(first I print the rtpengine_offer_flags to make sure what is passed to the function.

Aug 15 15:04:16 u363id562 kamailio[32178]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = rtcp-mux-demux trust-address replace-origin replace-session-connection ICE=remove RTP/AVP

Aug 15 15:04:16 u363id562 kamailio[32178]: WARNING: <core> [rvalue.c:1016]: rval_get_int(): automatic string to int conversion for "rtcp-mux-demux trust-address replace-origin replace-session-connection ICE=remove RTP/AVP" failed

Aug 15 15:04:16 u363id562 kamailio[32178]: WARNING: <core> [rvalue.c:1920]: rval_expr_eval_int(): rval expression conversion to int failed (1128,32-1128,32)
Aug 15 15:04:16 u363id562 rtpengine[32159]: Got valid command from 127.0.0.1:44292: delete - { "call-id": "k7bft3u75p5e42ib039r", "received-from": [ "IP4", "client_public_address" ], "from-tag": "74dovi97bi", "command": "delete" }

Aug 15 15:04:16 u363id562 rtpengine[32159]: [k7bft3u75p5e42ib039r] Call-ID to delete not found
Aug 15 15:04:16 u363id562 rtpengine[32159]: Returning to SIP proxy: d7:warning38:Call-ID not found or tags didn't match6:result2:oke

After this I see another 488 and the loop swirls on until Kamailio runs out of forking capacity. Can You guys explain why is this happening?

I set the variable like this:

$avp(rtpengine_offer_flags) = "rtcp-mux-demux trust-address replace-origin replace-session-connection ICE=remove RTP/AVP";

cheers,
Olli