<div dir="ltr">Hi,<div><br></div><div>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...</div><div><br></div><div>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.</div>
<div><br></div><div>My branch route looks like this:</div><div><br></div><div><div>branch_route[MANAGE_RTPENGINE_BRANCH] {</div><div><br></div><div> xlog("L_INFO", "MANAGE_RTPENGINE_BRANCH: new branch [$T_branch_idx] to $ru\n");</div>
<div> xlog("L_INFO", "MANAGE_RTPENGINE_BRANCH: rtpengine_offer_flags = $avp(rtpengine_offer_flags) and mline = $avp(mline)");</div><div><br></div><div> if ($avp(rtpengine_offer_flags) != "") {</div>
<div> xlog("L_INFO","MANAGE_RTPENGINE_BRANCH: rtpengine_offer with $avp(rtpengine_offer_flags)");</div><div> rtpproxy_offer($avp(rtpengine_offer_flags));</div><div><br></div>
<div> t_on_reply("RTPPROXY_REPLY");</div><div> } else {</div><div> xlog("L_ERR","MANAGE_RTPENGINE_BRANCH but rtp_offer_flags is EMPTY! "); </div><div> }</div>
<div>}</div></div><div><br></div><div><br></div><div>And this is what I get in the kamailio log:</div><div><br></div><div><div>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</div>
<div>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</div><div>Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...</div>
<div>Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [1] to <a href="mailto:sip%3A661@testers.com">sip:661@testers.com</a></div><div>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</div>
<div>Aug 20 21:47:58 u363id562 kamailio[28376]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp</div><div>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</div>
<div>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</div><div>Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...</div>
<div>Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [2] to <a href="mailto:sip%3A661@testers.com">sip:661@testers.com</a></div><div>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</div>
<div>Aug 20 21:47:58 u363id562 kamailio[28379]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp</div><div>... and so on</div></div><div><br></div><div><br></div><div>And this is what's happening in syslog between catching a 488, the rtpengine_offer call and the next 488:</div>
<div>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.</div><div>I haven't been able to spot the problem, maybe You will.</div><div><div><br></div><div>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</div>
<div>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</div><div>Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: RELAY: hooked to manage_failure, now relaying...</div>
<div>Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: new branch [1] to <a href="mailto:sip%3A661@testers.com">sip:661@testers.com</a></div><div>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</div>
<div>Aug 20 22:01:08 u363id562 kamailio[28610]: INFO: <script>: MANAGE_RTPENGINE_BRANCH: rtpengine_offer with froc-sp</div><div>Aug 20 22:01:08 u363id562 rtpengine[32233]: Got valid command from <a href="http://127.0.0.1:57017">127.0.0.1:57017</a>: 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 ...</div>
<div>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. ...</div>
<div>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: ...</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: ... //<a href="http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time#015#012a=sendrecv#015#012a=rtcp-mux#015#012a=rtpmap:111">www.webrtc.org/experiments/rtp-hdrext/abs-send-time#015#012a=sendrecv#015#012a=rtcp-mux#015#012a=rtpmap:111</a> 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 ...</div>
<div>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" }</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: Unknown flag encountered: 'force'</div><div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Creating new call</div><div>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 ...</div>
<div>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</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: Got valid command from <a href="http://127.0.0.1:49781">127.0.0.1:49781</a>: delete - { "call-id": "ug2htprt2erjsat1e6rc", "received-from": [ "IP4", "2.2.2.2" ], "from-tag": "vf9jdb7362", "command": "delete" }</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Deleting full call</div><div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] Final packet stats:</div><div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] --- Tag '', created 0:00 ago, in dialogue with '(none)'</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ------ Media #1, port 10626 <> <a href="http://2.2.2.2:55155">2.2.2.2:55155</a>, 0 p, 0 b, 0 e</div><div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] --- Tag 'vf9jdb7362', created 0:00 ago, in dialogue with ''</div>
<div>Aug 20 22:01:08 u363id562 rtpengine[32233]: [ug2htprt2erjsat1e6rc] ------ Media #1, port 10624 <> [::]:0 , 0 p, 0 b, 0 e</div><div>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 ...</div>
<div>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</div>
<div>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</div></div><div><br></div><div><br></div><div>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...</div>
<div><br></div><div><br></div><div>cheers,</div><div>Olli</div><div><br></div><div class="gmail_extra"><br><br><div class="gmail_quote">2014-08-19 11:13 GMT+03:00 Olli Heiskanen <span dir="ltr"><<a href="mailto:ohjelmistoarkkitehti@gmail.com" target="_blank">ohjelmistoarkkitehti@gmail.com</a>></span>:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div dir="ltr">Hi,<div><br></div><div>A little follow-up on this: </div>
<div><br></div><div>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: <a href="http://lists.sip-router.org/pipermail/sr-dev/2014-July/024507.html" target="_blank">http://lists.sip-router.org/pipermail/sr-dev/2014-July/024507.html</a></div>
<div><br></div><div>The same problem occurs with Kamailio 4.1.5 and rtpproxy-ng. My current setup uses Kamailio 4.2 (devel) and rtpengine. </div><div><br></div><div>If anyone has a way around this, I'd appreciate very much to hear it! This prevents any calls from being setup.</div>
<div><br></div><div>cheers,</div><div>Olli</div><div><br></div>
</div><div class="gmail_extra"><br><br><div class="gmail_quote">2014-08-15 18:40 GMT+03:00 Olli Heiskanen <span dir="ltr"><<a href="mailto:ohjelmistoarkkitehti@gmail.com" target="_blank">ohjelmistoarkkitehti@gmail.com</a>></span>:<div>
<div class="h5"><br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div dir="ltr"><div>Hello,</div><div><br></div><div>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. </div>
<div><br></div><div>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.</div><div><br></div>
<div>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:</div><div>(first I print the rtpengine_offer_flags to make sure what is passed to the function.</div>
<div><br></div><div>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</div>
<div>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</div>
<div>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)</div><div>Aug 15 15:04:16 u363id562 rtpengine[32159]: Got valid command from <a href="http://127.0.0.1:44292" target="_blank">127.0.0.1:44292</a>: delete - { "call-id": "k7bft3u75p5e42ib039r", "received-from": [ "IP4", "client_public_address" ], "from-tag": "74dovi97bi", "command": "delete" }</div>
<div>Aug 15 15:04:16 u363id562 rtpengine[32159]: [k7bft3u75p5e42ib039r] Call-ID to delete not found</div><div>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</div>
<div><br></div><div>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?</div><div><br></div><div>I set the variable like this: </div>
<div>$avp(rtpengine_offer_flags) = "rtcp-mux-demux trust-address replace-origin replace-session-connection ICE=remove RTP/AVP";</div><div><br></div><div>cheers,</div><div>Olli</div></div>
</blockquote></div></div></div><br></div>
</blockquote></div><br></div></div>