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
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
participants (2)
-
Cal Leeming [Simplicity Media Ltd]
-
David Allen