VoIP Mailing List Archives

[keith at laaks.com]

Hi, Hope someone knows how I am able to get around this one. Here goes... Did an upgrade to trunk (from a July vintage build) last week and noticed calls out to a provider were now failing after about 30 seconds or so - post answer. Tried latest (15183) - same thing. Analysing, I see that I have multiple UPDATE messages now being sent to the provider, but no response being sent back to FS. So FS times out and eventually kills the call. Interestingly, it only drops the A-leg; the B-leg remains up till the B party hangs up. I cant recall seeing these UPDATE messages before... The intent of the UPDATE seems to be to send the callee name & number to the B-leg. If its the provider's sip stack that's broken w.r.t. handling UPDATE - is there any way to get around it by doing something in my config to ensure these UPDATE's are not 'triggered' ? Some traces below. Any suggestions welcomed... Best Regards Keith Pretoria, South Africa. -------------------------------------------------------------------------------------------------------------------------------------------------- send 1048 bytes to udp/[196.10.11.12]:5060 at 13:24:04.249269: ------------------------------------------------------------------------ INVITE sip:27835551111@196.10.11.12 SIP/2.0 Via: SIP/2.0/UDP 10.17.10.10;rport;branch=z9hG4bKyQepDXQ5H8g5m Max-Forwards: 67 From: "Keith PhoneADSL" <G729@8000h ([email]G729@8000h[/email])@20i 2009-10-21 15:24:08.510671 [DEBUG] switch_ivr_originate.c:2326 sofia/inetticky/27878050000@196.222.3.4 receive message [PROGRESS] 2009-10-21 15:24:08.510671 [INFO] switch_ivr_originate.c:2326 Sending early media 2009-10-21 15:24:08.510671 [DEBUG] sofia_glue.c:3144 Audio Codec Compare [G729:18:8000:0]/[G729:18:8000:20] 2009-10-21 15:24:08.510671 [DEBUG] sofia_glue.c:2102 Set Codec sofia/inetticky/27878050000@196.222.3.4 G729/8000 20 ms 160 samples 2009-10-21 15:24:08.510671 [DEBUG] sofia_glue.c:3104 Set 2833 dtmf payload to 101 2009-10-21 15:24:08.510671 [DEBUG] sofia_glue.c:2336 AUDIO RTP [sofia/inetticky/27878050000@196.222.3.4] 196.222.3.4 port 16840 -> 41.242.6.167 port 62936 codec: 18 ms: 20 2009-10-21 15:24:08.510671 [DEBUG] switch_rtp.c:1155 Starting timer [soft] 160 bytes per 20ms 2009-10-21 15:24:08.511769 [NOTICE] sofia_glue.c:2771 Pre-Answer sofia/inetticky/27878050000@196.222.3.4 (27878050000@196.222.3.4)! 2009-10-21 15:24:08.511769 [INFO] mod_sofia.c:1582 Ring SDP: v=0 o=FreeSWITCH 1256114608 1256114609 IN IP4 196.222.3.4 s=FreeSWITCH c=IN IP4 196.222.3.4 t=0 0 m=audio 16840 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-10-21 15:24:08.511769 [DEBUG] switch_core_session.c:712 Send signal sofia/vvrf/27835551111 [BREAK] 2009-10-21 15:24:08.511769 [DEBUG] switch_core_session.c:653 Send signal sofia/inetticky/27878050000@196.222.3.4 [BREAK] 2009-10-21 15:24:08.511769 [DEBUG] sofia.c:407 sofia/vvrf/27835551111 receive message [DISPLAY] 2009-10-21 15:24:08.511769 [DEBUG] switch_ivr_originate.c:2368 Originate Resulted in Success: [sofia/vvrf/27835551111] 2009-10-21 15:24:08.511769 [DEBUG] switch_channel.c:182 sofia/vvrf/27835551111 receive message [AUDIO_SYNC] 2009-10-21 15:24:08.511769 [DEBUG] switch_channel.c:182 sofia/inetticky/27878050000@196.222.3.4 receive message [AUDIO_SYNC] 2009-10-21 15:24:08.512832 [DEBUG] switch_ivr_bridge.c:975 sofia/vvrf/27835551111 receive message [BRIDGE] 2009-10-21 15:24:08.512832 [DEBUG] switch_core_session.c:653 Send signal sofia/vvrf/27835551111 [BREAK] 2009-10-21 15:24:08.512832 [DEBUG] switch_ivr_bridge.c:982 sofia/inetticky/27878050000@196.222.3.4 receive message [BRIDGE] send 973 bytes to udp/[41.242.6.167]:62928 at 13:24:08.512974: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 41.242.6.167:56675;branch=z9hG4bK2234c0462cdad03fc318bd6c7438282;rport=629282009-10-21 15:24:08.512832 [DEBUG] switch_core_session.c:653 Send signal sofia/inetticky/27878050000@196.222.3.4 [BREAK] 2009-10-21 15:24:08.512832 [DEBUG] switch_ivr_bridge.c:1026 (sofia/vvrf/27835551111) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2009-10-21 15:24:08.512832 [DEBUG] switch_core_session.c:985 Send signal sofia/vvrf/27835551111 [BREAK] 2009-10-21 15:24:08.512832 [DEBUG] switch_core_state_machine.c:306 (sofia/vvrf/27835551111) Running State Change CS_EXCHANGE_MEDIA 2009-10-21 15:24:08.512832 [DEBUG] switch_core_state_machine.c:343 (sofia/vvrf/27835551111) State EXCHANGE_MEDIA 2009-10-21 15:24:08.512832 [DEBUG] mod_sofia.c:436 SOFIA LOOPBACK From: "Keith PhoneADSL" <4252084844@192_168_1_65 ([email]4252084844@192_168_1_65[/email]) CSeq: 3 INVITE Contact: <27878050000@196.222.3.4 (27878050000@196.222.3.4): v=0 o=FreeSWITCH 1256114608 1256114610 IN IP4 196.222.3.4 s=FreeSWITCH c=IN IP4 196.222.3.4 t=0 0 m=audio 16840 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-10-21 15:24:14.204823 [DEBUG] switch_core_session.c:712 Send signal sofia/vvrf/27835551111 [BREAK] 2009-10-21 15:24:14.204823 [DEBUG] switch_core_session.c:653 Send signal sofia/inetticky/27878050000@196.222.3.4 [BREAK] 2009-10-21 15:24:14.204823 [NOTICE] switch_ivr_bridge.c:378 Channel [sofia/inetticky/27878050000@196.222.3.4] has been answered 2009-10-21 15:24:14.204823 [DEBUG] switch_channel.c:182 sofia/inetticky/27878050000@196.222.3.4 receive message [AUDIO_SYNC] send 983 bytes to udp/[41.242.6.167]:62928 at 13:24:14.205173: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 41.242.6.167:56675;branch=z9hG4bK2234c0462cdad03fc318bd6c7438282;rport=62928 From: "Keith PhoneADSL" <4252084844@192_168_1_65 ([email]4252084844@192_168_1_65[/email]) CSeq: 3 INVITE Contact: <4252084844@192_168_1_65 ([email]4252084844@192_168_1_65[/email]) CSeq: 3 ACK Contact: <[url=sip:27878050000@41.242.6.167:56675]sip:27878050000@41.242.6.167:56675[/url]> Proxy-Authorization: Digest username="27878050000", realm="196.222.3.4", qop=auth, algorithm=MD5, uri="sip:0835551111@196.222.3.4", nonce="0092f192-be45-11de-a2c1-a70e5037c20e", nc=00000001, cnonce="ab2d49987adb74997fc6b236fc16d23", response="445ae74c1f910e45d9aa1043402b4dbb" Max-Forwards: 70 User-Agent: C455 IP021910000000 Content-Length: 0 ------------------------------------------------------------------------ 2009-10-21 15:24:14.533538 [DEBUG] sofia.c:3493 Channel sofia/inetticky/27878050000@196.222.3.4 entering state [ready][200] 2009-10-21 15:24:14.545161 [DEBUG] switch_core_session.c:712 Send signal sofia/vvrf/27835551111 [BREAK] 2009-10-21 15:24:14.545161 [DEBUG] switch_core_session.c:712 Send signal sofia/inetticky/27878050000@196.222.3.4 [BREAK] 2009-10-21 15:24:14.565231 [DEBUG] switch_ivr_bridge.c:122 sofia/vvrf/27835551111 receive message [DISPLAY] 2009-10-21 15:24:14.565231 [DEBUG] switch_ivr_bridge.c:122 sofia/inetticky/27878050000@196.222.3.4 receive message [DISPLAY] send 947 bytes to udp/[196.10.11.12]:5060 at 13:24:14.727678: ------------------------------------------------------------------------ UPDATE sip:196.10.11.12:5060 SIP/2.0 Via: SIP/2.0/UDP 10.17.10.10;rport;branch=z9hG4bK0907gKScctXac Max-Forwards: 70 From: "Keith PhoneADSL" <[url=sip:878050000@10.17.10.10]sip:878050000@10.17.10.10[/url]>;tag=Upa3NvXpBB1eF To: <[url=sip:27835551111@196.10.11.12]sip:27835551111@196.10.11.12[/url]>;tag=GR52RWG346-34 Call-ID: d821359d-38e7-122d-a38e-002264cc9b93 CSeq: 121947387 UPDATE Contact: <[url=sip:gw+vprov@10.17.10.10:5060]sip:gw+vprov@10.17.10.10:5060[/url];transport=udp;gw=vprov> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-15183M Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY Supported: timer, precondition, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 247 P-Asserted-Identity: "unknown" <27835551111> v=0 o=FreeSWITCH 1256118582 1256118583 IN IP4 10.17.10.10 s=FreeSWITCH c=IN IP4 10.17.10.10 t=0 0 m=audio 12862 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 ------------------------------------------------------------------------ send 947 bytes to udp/[196.10.11.12]:5060 at 13:24:15.728255: ------------------------------------------------------------------------ UPDATE sip:196.10.11.12:5060 SIP/2.0 Via: SIP/2.0/UDP 10.17.10.10;rport;branch=z9hG4bK0907gKScctXac Max-Forwards: 70 From: "Keith PhoneADSL" <[url=sip:878050000@10.17.10.10]sip:878050000@10.17.10.10[/url]>;tag=Upa3NvXpBB1eF To: <[url=sip:27835551111@196.10.11.12]sip:27835551111@196.10.11.12[/url]>;tag=GR52RWG346-34 Call-ID: d821359d-38e7-122d-a38e-002264cc9b93 CSeq: 121947387 UPDATE Contact: <[url=sip:gw+vprov@10.17.10.10:5060]sip:gw+vprov@10.17.10.10:5060[/url];transport=udp;gw=vprov> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-15183M Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY Supported: timer, precondition, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 247 P-Asserted-Identity: "unknown" <27835551111> v=0 o=FreeSWITCH 1256118582 1256118583 IN IP4 10.17.10.10 s=FreeSWITCH c=IN IP4 10.17.10.10 t=0 0 m=audio 12862 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 [Many more copies of the UPDATE's continue ... then ] 2009-10-21 15:24:46.228024 [DEBUG] sofia.c:3493 Channel sofia/vvrf/27835551111 entering state [terminated][408] 2009-10-21 15:24:46.228024 [NOTICE] sofia.c:4039 Hangup sofia/vvrf/27835551111 [CS_EXCHANGE_MEDIA] [RECOVERY_ON_TIMER_EXPIRE] 2009-10-21 15:24:46.228024 [DEBUG] switch_channel.c:1896 Send signal sofia/vvrf/27835551111 [KILL]

[brian at freeswitch.org]

This will be fixed soon. Watch SVN.

/b

On Oct 21, 2009, at 11:45 AM, Keith Laaks wrote:

[mike at jerris.com]

This should now be fixed in latest svn trunk.

Mike

On Oct 21, 2009, at 12:45 PM, Keith Laaks wrote: