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