[SR-Users] automatic string to int conversion for rtpengine flags failed - rtpproxy_offer() does not change sdp when called in branch_route
Olli Heiskanen
ohjelmistoarkkitehti at gmail.com
Wed Aug 20 20:24:24 CEST 2014
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 at 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 at 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 at 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 at 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 at 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
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20140820/d40dc2cb/attachment.html>
More information about the sr-users
mailing list