[Freeswitch-users] Bazzare Duplicated UUID Error Issue

10 Jun 2013

      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

[Freeswitch-users] Bazzare Duplicated UUID Error Issue

David Allen