[Freeswitch-users] Low rtp-timeout-sec hangs up call in ringing state - expected behaviour?

Tue Apr 28 07:33:55 PDT 2009

The scenario I was referring to was actually an outbound call from a
locally registered SIP phone to a cellphone. The same thing happens
whether I use a SIP or PRI trunk. After 6 s it hangs up.

I get SDP on 183 no matter whether I'm calling a cellphone or a fixed
line. I also get ringing indication. The 183+sdp is passed on to the
Nokia and after 6 s the call is hung up. Both the SIP and PRI trunks
claim to send early media but there seems to be no audio/RTP. If I
answer the call in 6 s it's not dropped because the media path was
established before RTP timeout.

The same thing happens on latest trunk.
I added the debug line at 1520 and did make && /etc/init.d/freeswitch
stop && make install && /etc/init.d/freeswitch start but the debug line
didn't show up anywhere in the CLI.

Is my upstream provider doing something wrong in sending early media in
these cases? Seems pretty odd. It can be avoided by setting a higher
rtp-timeout-sec but it will still be an absolute timeout on ringing.

A transcript of the log:

send 1293 bytes to udp/[1.1.1.1]:5060 at 13:55:56.451865:

------------------------------------------------------------------------
   INVITE sip:21651019 at domain.appsvrslip11.prigw.com SIP/2.0
   Via: SIP/2.0/UDP 2.2.2.2;rport;branch=z9hG4bKm3t6teHv30rBK
   Route: <sip:21651019 at 1.1.1.1>
   Max-Forwards: 69
   From: "someone" <sip:23695000 at 2.2.2.2>;tag=m2SepeSZ63e3g
   To: <sip:21651019 at domain.appsvrslip11.prigw.com>
   Call-ID: 23302ac7-ae9f-122c-198f-001ec9e8d9bc
   CSeq: 114345142 INVITE
   Contact: <sip:mod_sofia at 2.2.2.2:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-13175M
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE,
NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, presence, dialog, call-info, sla,
include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 383
   P-Asserted-Identity: "someone" <sip:23695000 at 2.2.2.2>

   v=0
   o=FreeSWITCH 3718974841365302606 4309079514688066219 IN IP4 2.2.2.2
   s=FreeSWITCH
   c=IN IP4 2.2.2.2
   t=0 0
   m=audio 52706 RTP/AVP 9 8 0 3 101 13
   a=rtpmap:9 G722/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:3 GSM/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=rtpmap:13 CN/8000
   a=ptime:20
   m=video 52752 RTP/AVP 99
   a=rtpmap:99 H264/90000

------------------------------------------------------------------------
2009-04-28 15:55:56 [DEBUG] sofia.c:2912 sofia_handle_sip_i_state()
Channel
sofia/external-eth1/21651019 at domain.appsvrslip11.prigw.com;fs_path=sip:21651019 at 1.1.1.1 entering state [calling][0]
recv 305 bytes from udp/[1.1.1.1]:5060 at 13:55:56.482864:

------------------------------------------------------------------------
   SIP/2.0 100 Trying
   From: "someone"<sip:23695000 at 2.2.2.2>;tag=m2SepeSZ63e3g
   To: <sip:21651019 at domain.appsvrslip11.prigw.com>
   Call-ID: 23302ac7-ae9f-122c-198f-001ec9e8d9bc
   CSeq: 114345142 INVITE
   Via: SIP/2.0/UDP 2.2.2.2;rport=5060;branch=z9hG4bKm3t6teHv30rBK
   Content-Length: 0

------------------------------------------------------------------------
recv 1035 bytes from udp/[1.1.1.1]:5060 at 13:55:58.296906:

------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   From: "someone"<sip:23695000 at 2.2.2.2>;tag=m2SepeSZ63e3g
   To:
<sip:21651019 at domain.appsvrslip11.prigw.com>;tag=20134330840200942815366
   Call-ID: 23302ac7-ae9f-122c-198f-001ec9e8d9bc
   CSeq: 114345142 INVITE
   Via: SIP/2.0/UDP 2.2.2.2;rport=5060;branch=z9hG4bKm3t6teHv30rBK
   content-type: application/sdp
   contact: <sip:1.1.1.1:5060;nt_end_pt=YM0
+~K!-.f0vfc830~P68.cio~H9zwgW0VyisWTdcaM26c610Xbo1.nfS.5NQt3mO~~70!-.f0vft815;nt_server_host=1.1.1.1>
   supported: 100rel
   x-nt-party-id: -/
   allow: ACK
   allow: BYE
   allow: CANCEL
   allow: INVITE
   allow: OPTIONS
   allow: INFO
   allow: SUBSCRIBE
   allow: REFER
   allow: NOTIFY
   allow: PRACK
   server:  CS2000_NGSS/9.0
   Content-Length: 300

   v=0
   o=IWSPM 573585738 573585738 IN IP4 84.20.97.100
   s=-
   e=unknown at invalid.net
   t=0 0
   m=audio 45954 RTP/AVP 8 0 18 101
   c=IN IP4 84.20.97.100
   a=ptime:20
   a=fmtp:18 annexb=no
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   m=video 0 RTP/AVP 99
   c=IN IP4 2.2.2.2
   a=rtpmap:99 H264/90000

------------------------------------------------------------------------
2009-04-28 15:55:58 [DEBUG] sofia.c:2912 sofia_handle_sip_i_state()
Channel
sofia/external-eth1/21651019 at domain.appsvrslip11.prigw.com;fs_path=sip:21651019 at 1.1.1.1 entering state [proceeding][183]
2009-04-28 15:55:58 [DEBUG] sofia.c:2919 sofia_handle_sip_i_state()
Remote SDP:
v=0
o=IWSPM 573585738 573585738 IN IP4 84.20.97.100
s=-
e=unknown at invalid.net
t=0 0
m=audio 45954 RTP/AVP 8 0 18 101
c=IN IP4 84.20.97.100
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
m=video 0 RTP/AVP 99
c=IN IP4 2.2.2.2
a=rtpmap:99 H264/90000

2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2931 sofia_glue_negotiate_sdp()
Audio Codec Compare [PCMA:8:8000:20]/[G722:9:8000:20]
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2931 sofia_glue_negotiate_sdp()
Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:20]
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:1912
sofia_glue_tech_set_codec() Set Codec
sofia/external-eth1/21651019 at domain.appsvrslip11.prigw.com;fs_path=sip:21651019 at 1.1.1.1 PCMA/8000 20 ms 160 samples
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2891 sofia_glue_negotiate_sdp()
Set 2833 dtmf payload to 101
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2146 sofia_glue_activate_rtp()
AUDIO RTP
[sofia/external-eth1/21651019 at domain.appsvrslip11.prigw.com;fs_path=sip:21651019 at 1.1.1.1] 2.2.2.2 port 52706 -> 84.20.97.100 port 45954 codec: 8 ms: 20
2009-04-28 15:55:58 [DEBUG] switch_rtp.c:906 switch_rtp_create()
Starting timer [soft] 160 bytes per 20ms
2009-04-28 15:55:58 [NOTICE] sofia_glue.c:2573 sofia_glue_tech_media()
Pre-Answer
sofia/external-eth1/21651019 at domain.appsvrslip11.prigw.com;fs_path=sip:21651019 at 1.1.1.1!
2009-04-28 15:55:58 [DEBUG] switch_channel.c:1736
switch_channel_perform_mark_pre_answered() Send signal
sofia/internal/mikael-nokia at fs.voip.domain [BREAK]
2009-04-28 15:55:58 [DEBUG] switch_ivr_originate.c:1972
switch_ivr_originate() sofia/internal/mikael-nokia at fs.voip.domain
receive message [PROGRESS]
2009-04-28 15:55:58 [INFO] mod_sofia.c:1377 sofia_receive_message()
Asked to send early media by sofia/internal/mikael-nokia at fs.voip.domain
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2931 sofia_glue_negotiate_sdp()
Audio Codec Compare [PCMA:8:8000:20]/[G722:9:8000:20]
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2931 sofia_glue_negotiate_sdp()
Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:20]
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:1912
sofia_glue_tech_set_codec() Set Codec
sofia/internal/mikael-nokia at fs.voip.domain PCMA/8000 20 ms 160 samples
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2891 sofia_glue_negotiate_sdp()
Set 2833 dtmf payload to 98
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2146 sofia_glue_activate_rtp()
AUDIO RTP [sofia/internal/mikael-nokia at fs.voip.domain] 10.100.4.192 port
58072 -> 10.247.3.253 port 49152 codec: 8 ms: 20
2009-04-28 15:55:58 [DEBUG] switch_rtp.c:906 switch_rtp_create()
Starting timer [soft] 160 bytes per 20ms
2009-04-28 15:55:58 [DEBUG] sofia_glue.c:2325 sofia_glue_activate_rtp()
Set comfort noise payload to 13
2009-04-28 15:55:58 [NOTICE] sofia_glue.c:2573 sofia_glue_tech_media()
Pre-Answer sofia/internal/mikael-nokia at fs.voip.domain!
2009-04-28 15:55:58 [INFO] mod_sofia.c:1420 sofia_receive_message() Ring
SDP:
v=0
o=FreeSWITCH 1240868886 1240868887 IN IP4 10.100.4.192
s=FreeSWITCH
c=IN IP4 10.100.4.192
t=0 0
m=audio 58072 RTP/AVP 8 98 13
a=rtpmap:8 PCMA/8000
a=rtpmap:98 telephone-event/8000
a=fmtp:98 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

El mar, 28-04-2009 a las 07:50 -0500, Anthony Minessale escribió:
> Are you geting 183+sdp from the nokia?
> the media timer only operates once media is established and only 
> counts against you if the channel is being read from and that does
> not 
> happen until you get a 183 or 200 w/sdp
> 
> try putting a debug line in switch_rtp.c around 1520
> printf("MISSED PACKETS %u/%u\n", rtp_session->missed_count,
> rtp_session->max_missed_packets);  
> 
> but try updating first there was a recent fix that may have prevented
> a timer surge at the beginning of calls.
> 
> 
> On Tue, Apr 28, 2009 at 6:20 AM, Mikael Aleksander Bjerkeland
> <mikael at bjerkeland.com> wrote:
>         Hi,
>         
>         I have been testing inbound calls to a Nokia phone with
>         handover to a
>         cellphone number if I get MEDIA_TIMEOUT on the B leg of the
>         call, and
>         had to set rtp-timeout to a very low 6 seconds in order to get
>         "fast"
>         handover. This introduces an interesting side-effect that
>         hangs up calls
>         even in the ringing state after 6 seconds. Is this the desired
>         behaviour
>         of rtp-timeout-sec? My initial guess was that rtp-timeout-sec
>         should
>         only be valid for established calls where the two endpoints
>         have
>         exchanged rtp at some point but have stopped exchanging media.
>         As far as
>         I know a phone call in ringing state has not shared any RTP
>         with the
>         other endpoint until it gets early media or is answered.
>         Should
>         rtp-timeout-sec really be valid even when ringing?
>         
>         It seems to me that setting rtp-timeout-sec to 60 seconds
>         would add an
>         absolute time limit on ringing phone calls to 60 seconds,
>         which I
>         believe is not the actual purpose of this limit. Could anyone
>         please
>         share their thoughts on this matter?
>         
>         
>         Thanks,
>         Mikael
>         
>         
>         
>         
>         
>         _______________________________________________
>         Freeswitch-users mailing list
>         Freeswitch-users at lists.freeswitch.org
>         http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>         UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>         http://www.freeswitch.org
> 
> 
> 
> -- 
> Anthony Minessale II
> 
> FreeSWITCH http://www.freeswitch.org/
> ClueCon http://www.cluecon.com/
> 
> AIM: anthm
> MSN:anthony_minessale at hotmail.com
> GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
> IRC: irc.freenode.net #freeswitch
> 
> FreeSWITCH Developer Conference
> sip:888 at conference.freeswitch.org
> iax:guest at conference.freeswitch.org/888
> googletalk:conf+888 at conference.freeswitch.org
> pstn:213-799-1400
> _______________________________________________
> Freeswitch-users mailing list
> Freeswitch-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org