Hi David, Can you confirm if your deployment was suffering from this problem prior to the upgrade? Perhaps some of these articles might be of relevance (just a quick google search); http://lists.freeswitch.org/pipermail/freeswitch-users/2010-July/060428.html This might not be a bug within FS, and could just be a backwards incompatible configuration - either way I'd suggest raising a JIRA ticket so that it gets the necessary attention. Thanks Cal On Mon, Jun 10, 2013 at 7:46 AM, David Allen <thedjallen@gmail.com> wrote:
Hi,
I recently upgraded from the 1.0 GIT Head to 1.2.10+git~20130607T172913Z~658c4d732d (git 658c4d7 2013-06-07 17:29:13Z) and have encounted a weird problem on inbound calls from a SIP UA (Eg. Asterisk) to be bridged and sent out to an up stream sip peer are being rejected due to a Duplicate UUID and Freeswitch responses with 503 Maximum Calls in Progress. The problem appears to happen after the digest authentication takes place as below:
------------------------------------------------------------------------ recv 769 bytes from udp/[10.20.10.90]:5060 at 06:37:37.298978: ------------------------------------------------------------------------ INVITE sip:99992912@10.20.10.10 SIP/2.0 Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK0e4d9102;rport From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10> Contact: <sip:1677288@10.20.10.90:5060> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 102 INVITE User-Agent: Asterisk PBX (digium) Max-Forwards: 70 Date: Mon, 10 Jun 2013 06:38:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 213
v=0 o=root 3216 3216 IN IP4 10.20.10.90 s=session c=IN IP4 10.20.10.90 t=0 0 m=audio 10000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ send 311 bytes to udp/[10.20.10.90]:5060 at 06:37:37.299263: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK0e4d9102;rport=5060 From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 102 INVITE User-Agent: SipTesting Content-Length: 0
------------------------------------------------------------------------ 2013-06-10 16:37:37.296945 [NOTICE] switch_channel.c:1027 New Channel sofia/external/1677288@10.20.10.10 [ 23dbb80216dc65a178bef5315cbc687d@10.20.10.10] 2013-06-10 16:37:37.296945 [DEBUG] switch_core_session.c:999 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.296945 [DEBUG] switch_core_session.c:999 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.296945 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_NEW 2013-06-10 16:37:37.296945 [DEBUG] switch_core_state_machine.c:433 (sofia/external/1677288@10.20.10.10) State NEW 2013-06-10 16:37:37.316945 [DEBUG] sofia.c:5689 Channel sofia/external/ 1677288@10.20.10.10 entering state [received][100] 2013-06-10 16:37:37.316945 [DEBUG] sofia.c:5700 Remote SDP: v=0 o=root 3216 3216 IN IP4 10.20.10.90 s=session c=IN IP4 10.20.10.90 t=0 0 m=audio 10000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G729:18:8000:20:8000] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G729:18:8000:30:8000] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G729:18:8000:40:8000] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G729:18:8000:60:8000] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[GSM:3:8000:20:13200] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:3119 Set Codec sofia/external/1677288@10.20.10.10 PCMA/8000 20 ms 160 samples 64000 bits 2013-06-10 16:37:37.316945 [DEBUG] switch_core_codec.c:111 sofia/external/ 1677288@10.20.10.10 Original read codec set to PCMA:8 2013-06-10 16:37:37.316945 [DEBUG] sofia_glue.c:5307 Set 2833 dtmf send/recv payload to 101 2013-06-10 16:37:37.316945 [DEBUG] sofia.c:5934 (sofia/external/ 1677288@10.20.10.10) State Change CS_NEW -> CS_INIT 2013-06-10 16:37:37.316945 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_INIT 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:454 (sofia/external/1677288@10.20.10.10) State INIT 2013-06-10 16:37:37.316945 [DEBUG] mod_sofia.c:87 sofia/external/ 1677288@10.20.10.10 SOFIA INIT 2013-06-10 16:37:37.316945 [DEBUG] mod_sofia.c:127 (sofia/external/ 1677288@10.20.10.10) State Change CS_INIT -> CS_ROUTING 2013-06-10 16:37:37.316945 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:454 (sofia/external/1677288@10.20.10.10) State INIT going to sleep 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_ROUTING 2013-06-10 16:37:37.316945 [DEBUG] switch_channel.c:2110 (sofia/external/ 1677288@10.20.10.10) Callstate Change DOWN -> RINGING 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:470 (sofia/external/1677288@10.20.10.10) State ROUTING 2013-06-10 16:37:37.316945 [DEBUG] mod_sofia.c:150 sofia/external/ 1677288@10.20.10.10 SOFIA ROUTING 2013-06-10 16:37:37.316945 [DEBUG] switch_core_state_machine.c:117 sofia/external/1677288@10.20.10.10 Standard ROUTING 2013-06-10 16:37:37.316945 [INFO] mod_dialplan_xml.c:558 Processing 1677288 <1677288>->99992912 in context public Dialplan: sofia/external/1677288@10.20.10.10 parsing [public->unloop] continue=false Dialplan: sofia/external/1677288@10.20.10.10 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/1677288@10.20.10.10 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/1677288@10.20.10.10 parsing [public->check_auth] continue=true Dialplan: sofia/external/1677288@10.20.10.10 Regex (FAIL) [check_auth] ${sip_authorized}() =~ /^true$/ break=never Dialplan: sofia/external/1677288@10.20.10.10 ANTI-Action respond(407) Dialplan: sofia/external/1677288@10.20.10.10 parsing [public->transfer_to_default] continue=false Dialplan: sofia/external/1677288@10.20.10.10 Absolute Condition [transfer_to_default] Dialplan: sofia/external/1677288@10.20.10.10 Action transfer(${destination_number} XML default) 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:167 (sofia/external/1677288@10.20.10.10) State Change CS_ROUTING -> CS_EXECUTE 2013-06-10 16:37:37.326961 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:470 (sofia/external/1677288@10.20.10.10) State ROUTING going to sleep 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_EXECUTE 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:477 (sofia/external/1677288@10.20.10.10) State EXECUTE 2013-06-10 16:37:37.326961 [DEBUG] mod_sofia.c:243 sofia/external/ 1677288@10.20.10.10 SOFIA EXECUTE 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:209 sofia/external/1677288@10.20.10.10 Standard EXECUTE EXECUTE sofia/external/1677288@10.20.10.10 respond(407) 2013-06-10 16:37:37.326961 [DEBUG] mod_sofia.c:2666 Responding with 407 [(null)] 2013-06-10 16:37:37.326961 [NOTICE] mod_sofia.c:2725 Hangup sofia/external/ 1677288@10.20.10.10 [CS_EXECUTE] [CALL_REJECTED] 2013-06-10 16:37:37.326961 [DEBUG] switch_channel.c:3129 Send signal sofia/external/1677288@10.20.10.10 [KILL] 2013-06-10 16:37:37.326961 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.326961 [DEBUG] switch_core_session.c:2732 sofia/external/1677288@10.20.10.10 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:477 (sofia/external/1677288@10.20.10.10) State EXECUTE going to sleep 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_HANGUP 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:678 (sofia/external/1677288@10.20.10.10) State HANGUP 2013-06-10 16:37:37.326961 [DEBUG] mod_sofia.c:504 Channel sofia/external/ 1677288@10.20.10.10 hanging up, cause: CALL_REJECTED 2013-06-10 16:37:37.326961 [DEBUG] mod_sofia.c:600 Challenging call 2013-06-10 16:37:37.326961 [DEBUG] mod_sofia.c:638 Responding to INVITE with: 407 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:48 sofia/external/1677288@10.20.10.10 Standard HANGUP, cause: CALL_REJECTED 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:678 (sofia/external/1677288@10.20.10.10) State HANGUP going to sleep 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:689 (sofia/external/1677288@10.20.10.10) Callstate Change RINGING -> HANGUP 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:446 (sofia/external/1677288@10.20.10.10) State Change CS_HANGUP -> CS_REPORTING 2013-06-10 16:37:37.326961 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] send 803 bytes to udp/[10.20.10.90]:5060 at 06:37:37.331025: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK0e4d9102;rport=5060 From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10>;tag=ge05D2HSyNegQ Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 102 INVITE User-Agent: SipTesting Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="10.20.10.10", nonce="3d9a75c8-d198-11e2-a1fd-9f60ee575d4e", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1677288@10.20.10.10) Running State Change CS_REPORTING 2013-06-10 16:37:37.326961 [DEBUG] switch_core_state_machine.c:761 (sofia/external/1677288@10.20.10.10) State REPORTING recv 403 bytes from udp/[10.20.10.90]:5060 at 06:37:37.333826: ------------------------------------------------------------------------ ACK sip:99992912@10.20.10.10 SIP/2.0 Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK0e4d9102;rport From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10>;tag=ge05D2HSyNegQ Contact: <sip:1677288@10.20.10.90:5060> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 102 ACK User-Agent: Asterisk PBX (digium) Max-Forwards: 70 Content-Length: 0
------------------------------------------------------------------------ recv 1020 bytes from udp/[10.20.10.90]:5060 at 06:37:37.334446: ------------------------------------------------------------------------ INVITE sip:99992912@10.20.10.10 SIP/2.0 Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK2bcc3b6b;rport From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10> Contact: <sip:1677288@10.20.10.90:5060> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 103 INVITE User-Agent: Asterisk PBX (digium) Max-Forwards: 70 Proxy-Authorization: Digest username="1677288", realm="10.20.10.10", algorithm=MD5, uri="sip:99992912@10.20.10.10", nonce="3d9a75c8-d198-11e2-a1fd-9f60ee575d4e", response="5c9facef9ebcc380f74ec52816892694", qop=auth, cnonce="1930827a", nc=00000001 Date: Mon, 10 Jun 2013 06:38:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 213
v=0 o=root 3216 3217 IN IP4 10.20.10.90 s=session c=IN IP4 10.20.10.90 t=0 0 m=audio 10000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ send 311 bytes to udp/[10.20.10.90]:5060 at 06:37:37.334699: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK2bcc3b6b;rport=5060 From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 103 INVITE User-Agent: SipTesting Content-Length: 0
------------------------------------------------------------------------ 2013-06-10 16:37:37.326961 [CRIT] switch_core_session.c:2185 Duplicate UUID! send 695 bytes to udp/[10.20.10.90]:5060 at 06:37:37.334857: ------------------------------------------------------------------------ SIP/2.0 503 Maximum Calls In Progress Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK2bcc3b6b;rport=5060 From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10>;tag=HQSyFX2vUy42j Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 103 INVITE Retry-After: 300 User-Agent: SipTesting Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ recv 403 bytes from udp/[10.20.10.90]:5060 at 06:37:37.337584: ------------------------------------------------------------------------ ACK sip:99992912@10.20.10.10 SIP/2.0 Via: SIP/2.0/UDP 10.20.10.90:5060;branch=z9hG4bK2bcc3b6b;rport From: "1677288" <sip:1677288@10.20.10.10>;tag=as753afbc5 To: <sip:99992912@10.20.10.10>;tag=HQSyFX2vUy42j Contact: <sip:1677288@10.20.10.90:5060> Call-ID: 23dbb80216dc65a178bef5315cbc687d@10.20.10.10 CSeq: 103 ACK User-Agent: Asterisk PBX (digium) Max-Forwards: 70 Content-Length: 0
------------------------------------------------------------------------ 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:92 sofia/external/1677288@10.20.10.10 Standard REPORTING, cause: CALL_REJECTED 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:761 (sofia/external/1677288@10.20.10.10) State REPORTING going to sleep 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1677288@10.20.10.10) State Change CS_REPORTING -> CS_DESTROY 2013-06-10 16:37:37.336949 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/1677288@10.20.10.10 [BREAK] 2013-06-10 16:37:37.336949 [DEBUG] switch_core_session.c:1542 Session 546 (sofia/external/1677288@10.20.10.10) Locked, Waiting on external entities 2013-06-10 16:37:37.336949 [NOTICE] switch_core_session.c:1560 Session 546 (sofia/external/1677288@10.20.10.10) Ended 2013-06-10 16:37:37.336949 [NOTICE] switch_core_session.c:1564 Close Channel sofia/external/1677288@10.20.10.10 [CS_DESTROY] 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:565 (sofia/external/1677288@10.20.10.10) Callstate Change HANGUP -> DOWN 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:568 (sofia/external/1677288@10.20.10.10) Running State Change CS_DESTROY 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:578 (sofia/external/1677288@10.20.10.10) State DESTROY 2013-06-10 16:37:37.336949 [DEBUG] mod_sofia.c:397 sofia/external/ 1677288@10.20.10.10 SOFIA DESTROY 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:99 sofia/external/1677288@10.20.10.10 Standard DESTROY 2013-06-10 16:37:37.336949 [DEBUG] switch_core_state_machine.c:578 (sofia/external/1677288@10.20.10.10) State DESTROY going to sleep
The only thing that I do is that I do bridge the incoming and outgoing on the same channel. I have made sure that the maximum amount of sessions has been increased and I can see any reason why the UUID would be duplicated as I have been able to replicate the same call from a SPA504G and the call has progressed without any issues. If any one has any ideas on what may be causing this it would be appreciated.
Thanks David
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org