[Freeswitch-users] SIP CANCEL Problems

11 Aug 2010

      Hi List

I'm having problems when a calling extension hangs up before called 
extension answers.
Called extension keeps ringing for quite a while after calling party 
hangs up, giving called party plenty of time to pick up and listen to 
dead audio.

Here's the set-up

Ext 1000 ----
                    |
                    |---- NAT Router ----- FS on Public IP
                    |
Ext 1002 ----

Both Extensions are on same LAN behind same NAT router, using different 
SIP ports:
Ext 1000: 41000
Ext 1002: 41002

FreeSwitch is installed from GIT and conf files are basically unchanged, 
except IPs.

I've pasted a complete trace of transaction below, but I think of 
relevance is that FreeSwitch receives 5 CANCEL packets from Ext 1000 
over a 7 second period before it decides to send the CANCEL on to ext 1002.

Seven seconds is a long time for a phone to be ringing.

Any ideas  on what / where to tweak to get FreeSwitch to respond after 
first CANCEL would be appreciated.

Thanks in advance

John

Complete trace of transaction follows:

freeswitch@internal> recv 993 bytes from udp/[95.xxx.yyy.231]:41000 at 
19:01:03.892139:
    ------------------------------------------------------------------------
    INVITE sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-141b2a92
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Remote-Party-ID: "1000" 
<sip:1000@93.aaa.bbb.186>;screen=yes;party=calling
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 101 INVITE
    Max-Forwards: 70
    Contact: "1000" <sip:1000@95.xxx.yyy.231:41000>
    Expires: 240
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 399
    Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
    Supported: replaces
    Content-Type: application/sdp

    v=0
    o=- 423343 423343 IN IP4 95.xxx.yyy.231
    s=-
    c=IN IP4 95.xxx.yyy.231
    t=0 0
    m=audio 16384 RTP/AVP 0 2 4 8 18 96 97 98 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:2 G726-32/8000
    a=rtpmap:4 G723/8000
    a=rtpmap:8 PCMA/8000
    a=rtpmap:18 G729a/8000
    a=rtpmap:96 G726-40/8000
    a=rtpmap:97 G726-24/8000
    a=rtpmap:98 G726-16/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=ptime:30
    a=sendrecv
    ------------------------------------------------------------------------
send 318 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:03.892641:
    ------------------------------------------------------------------------
    SIP/2.0 100 Trying
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-141b2a92
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 101 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Content-Length: 0

    ------------------------------------------------------------------------
2010-08-11 21:01:03.892755 [DEBUG] sofia.c:6000 IP 95.xxx.yyy.231 
Rejected by acl "domains". Falling back to Digest auth.
send 805 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:03.901957:
    ------------------------------------------------------------------------
    SIP/2.0 407 Proxy Authentication Required
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-141b2a92
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=mr2Kt3U0cB2FF
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 101 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Accept: application/sdp
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Proxy-Authenticate: Digest realm="93.aaa.bbb.186", 
nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0", algorithm=MD5, qop="auth"
    Content-Length: 0

    ------------------------------------------------------------------------
recv 401 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:03.981956:
    ------------------------------------------------------------------------
    ACK sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-141b2a92
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=mr2Kt3U0cB2FF
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 101 ACK
    Max-Forwards: 70
    Contact: "1000" <sip:1000@95.xxx.yyy.231:41000>
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 1229 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:04.018603:
    ------------------------------------------------------------------------
    INVITE sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Remote-Party-ID: "1000" 
<sip:1000@93.aaa.bbb.186>;screen=yes;party=calling
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="100a38311f3ee9f12c5fb78e61fdf14d",qop=auth,nc=00000001,cnonce="54f72ed1"
    Contact: "1000" <sip:1000@95.xxx.yyy.231:41000>
    Expires: 240
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 399
    Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
    Supported: replaces
    Content-Type: application/sdp

    v=0
    o=- 423343 423343 IN IP4 95.xxx.yyy.231
    s=-
    c=IN IP4 95.xxx.yyy.231
    t=0 0
    m=audio 16384 RTP/AVP 0 2 4 8 18 96 97 98 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:2 G726-32/8000
    a=rtpmap:4 G723/8000
    a=rtpmap:8 PCMA/8000
    a=rtpmap:18 G729a/8000
    a=rtpmap:96 G726-40/8000
    a=rtpmap:97 G726-24/8000
    a=rtpmap:98 G726-16/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=ptime:30
    a=sendrecv
    ------------------------------------------------------------------------
send 318 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:04.019014:
    ------------------------------------------------------------------------
    SIP/2.0 100 Trying
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Content-Length: 0

    ------------------------------------------------------------------------
2010-08-11 21:01:04.018556 [DEBUG] sofia.c:6000 IP 95.xxx.yyy.231 
Rejected by acl "domains". Falling back to Digest auth.
2010-08-11 21:01:04.021204 [NOTICE] switch_channel.c:779 New Channel 
sofia/internal/1000@93.aaa.bbb.186 [ca21d98e-a57a-11df-8499-6130e0d7e4c0]
2010-08-11 21:01:04.022284 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_NEW
2010-08-11 21:01:04.022284 [DEBUG] switch_core_state_machine.c:320 
(sofia/internal/1000@93.aaa.bbb.186) State NEW
2010-08-11 21:01:04.023433 [DEBUG] sofia.c:4318 Channel 
sofia/internal/1000@93.aaa.bbb.186 entering state [received][100]
2010-08-11 21:01:04.023433 [DEBUG] sofia.c:4329 Remote SDP:
v=0
o=- 423343 423343 IN IP4 95.xxx.yyy.231
s=-
c=IN IP4 95.xxx.yyy.231
t=0 0
m=audio 16384 RTP/AVP 0 2 4 8 18 96 97 98 101
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30

2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[G729:18:8000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[GSM:3:8000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[G7221:115:32000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[G7221:107:16000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[G722:9:8000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[PCMU:0:8000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3847 Audio Codec Compare 
[PCMU:0:8000:30]/[PCMA:8:8000:20]
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3895 Substituting codec 
PCMU@30i@8000h
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:2444 Set Codec 
sofia/internal/1000@93.aaa.bbb.186 PCMU/8000 30 ms 240 samples
2010-08-11 21:01:04.023433 [DEBUG] sofia_glue.c:3943 Set 2833 dtmf 
send/recv payload to 101
2010-08-11 21:01:04.023433 [DEBUG] sofia.c:4476 
(sofia/internal/1000@93.aaa.bbb.186) State Change CS_NEW -> CS_INIT
2010-08-11 21:01:04.023433 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_INIT
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/1000@93.aaa.bbb.186) State INIT
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:83 
sofia/internal/1000@93.aaa.bbb.186 SOFIA INIT
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:119 
(sofia/internal/1000@93.aaa.bbb.186) State Change CS_INIT -> CS_ROUTING
2010-08-11 21:01:04.024600 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/1000@93.aaa.bbb.186) State INIT going to sleep
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_ROUTING
2010-08-11 21:01:04.024600 [DEBUG] switch_channel.c:1512 
(sofia/internal/1000@93.aaa.bbb.186) Callstate Change DOWN -> RINGING
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/1000@93.aaa.bbb.186) State ROUTING
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:142 
sofia/internal/1000@93.aaa.bbb.186 SOFIA ROUTING
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:77 
sofia/internal/1000@93.aaa.bbb.186 Standard ROUTING
2010-08-11 21:01:04.024600 [INFO] mod_dialplan_xml.c:331 Processing 
1000->1002 in context default
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing [default->unloop] 
continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (PASS) [unloop] 
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [unloop] 
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->tod_example] continue=true
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Date/Time Match (FAIL) 
[tod_example] break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->holiday_example] continue=true
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Date/Time Match (FAIL) 
[holiday_example] break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->global-intercept] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[global-intercept] destination_number(1002) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->group-intercept] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->intercept-ext] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing [default->redial] 
continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [redial] 
destination_number(1002) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing [default->global] 
continue=true
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [global] 
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [global] 
${sip_has_crypto}() =~ 
/^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Absolute Condition [global]
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 

Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->snom-demo-2] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [snom-demo-2] 
destination_number(1002) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->snom-demo-1] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [snom-demo-1] 
destination_number(1002) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [eavesdrop] 
destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [eavesdrop] 
destination_number(1002) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->call_return] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [call_return] 
destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->del-group] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [del-group] 
destination_number(1002) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->add-group] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) [add-group] 
destination_number(1002) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->call-group-simo] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->call-group-order] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (FAIL) 
[extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ 
break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 parsing 
[default->Local_Extension] continue=false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Regex (PASS) 
[Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/ 
break=on-false
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(dialed_extension=1002)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
export(dialed_extension=1002)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action bind_meta_app(1 b s 
execute_extension::dx XML features)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action bind_meta_app(2 b s 
record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 

Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action bind_meta_app(3 b s 
execute_extension::cf XML features)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(ringback=${us-ring})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action set(call_timeout=30)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(hangup_after_bridge=true)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(continue_on_fail=true)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 

Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var 
callgroup)})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action answer()
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action sleep(1000)
Dialplan: sofia/internal/1000@93.aaa.bbb.186 Action 
bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:119 
(sofia/internal/1000@93.aaa.bbb.186) State Change CS_ROUTING -> CS_EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/1000@93.aaa.bbb.186) State ROUTING going to sleep
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:348 
(sofia/internal/1000@93.aaa.bbb.186) State EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] mod_sofia.c:235 
sofia/internal/1000@93.aaa.bbb.186 SOFIA EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:157 
sofia/internal/1000@93.aaa.bbb.186 Standard EXECUTE
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-spymap/1000/ca21d98e-a57a-11df-8499-6130e0d7e4c0) 

EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-last_dial/1000/1002)
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-last_dial/global/ca21d98e-a57a-11df-8499-6130e0d7e4c0) 

EXECUTE sofia/internal/1000@93.aaa.bbb.186 set(dialed_extension=1002)
2010-08-11 21:01:04.026839 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET [dialed_extension]=[1002]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 export(dialed_extension=1002)
2010-08-11 21:01:04.026839 [DEBUG] mod_dptools.c:938 EXPORT 
[dialed_extension]=[1002]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 bind_meta_app(1 b s 
execute_extension::dx XML features)
2010-08-11 21:01:04.027981 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*1 execute_extension::dx XML features
EXECUTE sofia/internal/1000@93.aaa.bbb.186 bind_meta_app(2 b s 
record_session::/usr/local/freeswitch/recordings/1000.2010-08-11-21-01-04.wav) 

2010-08-11 21:01:04.027981 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*2 
record_session::/usr/local/freeswitch/recordings/1000.2010-08-11-21-01-04.wav 

EXECUTE sofia/internal/1000@93.aaa.bbb.186 bind_meta_app(3 b s 
execute_extension::cf XML features)
2010-08-11 21:01:04.027981 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*3 execute_extension::cf XML features
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
set(ringback=%(2000,4000,440.0,480.0))
2010-08-11 21:01:04.027981 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET 
[ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
set(transfer_ringback=local_stream://moh)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET 
[transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 set(call_timeout=30)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET [call_timeout]=[30]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 set(hangup_after_bridge=true)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 set(continue_on_fail=true)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-call_return/1002/1000)
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-last_dial_ext/1002/ca21d98e-a57a-11df-8499-6130e0d7e4c0) 

EXECUTE sofia/internal/1000@93.aaa.bbb.186 
set(called_party_callgroup=techsupport)
2010-08-11 21:01:04.030434 [DEBUG] mod_dptools.c:854 
sofia/internal/1000@93.aaa.bbb.186 SET 
[called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1000@93.aaa.bbb.186 
hash(insert/93.aaa.bbb.186-last_dial/techsupport/ca21d98e-a57a-11df-8499-6130e0d7e4c0) 

EXECUTE sofia/internal/1000@93.aaa.bbb.186 bridge(user/1002@93.aaa.bbb.186)
2010-08-11 21:01:04.032457 [DEBUG] switch_ivr_originate.c:1979 variable 
string 0 = [presence_id=1002@93.aaa.bbb.186]
2010-08-11 21:01:04.033462 [NOTICE] switch_channel.c:779 New Channel 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 
[ca23b600-a57a-11df-849a-6130e0d7e4c0]
2010-08-11 21:01:04.040579 [DEBUG] mod_sofia.c:3892 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State Change CS_NEW -> 
CS_INIT
2010-08-11 21:01:04.040579 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:04.040579 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change CS_INIT
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State INIT
2010-08-11 21:01:04.041592 [DEBUG] mod_sofia.c:83 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 SOFIA INIT
2010-08-11 21:01:04.041592 [DEBUG] mod_sofia.c:119 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State Change CS_INIT -> 
CS_ROUTING
2010-08-11 21:01:04.041592 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State INIT going to sleep
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change 
CS_ROUTING
2010-08-11 21:01:04.041592 [DEBUG] switch_channel.c:1512 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Callstate Change DOWN -> 
RINGING
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State ROUTING
2010-08-11 21:01:04.041592 [DEBUG] mod_sofia.c:142 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 SOFIA ROUTING
2010-08-11 21:01:04.041592 [DEBUG] switch_ivr_originate.c:66 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State Change CS_ROUTING 
-> CS_CONSUME_MEDIA
2010-08-11 21:01:04.041592 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State ROUTING going to sleep
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change 
CS_CONSUME_MEDIA
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:360 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State CONSUME_MEDIA
2010-08-11 21:01:04.041592 [DEBUG] switch_core_state_machine.c:360 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State CONSUME_MEDIA going 
to sleep
send 1219 bytes to udp/[95.xxx.yyy.231]:41002 at 19:01:04.042665:
    ------------------------------------------------------------------------
    INVITE sip:1002@95.xxx.yyy.231:41002 SIP/2.0
    Via: SIP/2.0/UDP 93.aaa.bbb.186;rport;branch=z9hG4bKyvX4D3Z0yHZ5e
    Max-Forwards: 69
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    To: <sip:1002@95.xxx.yyy.231:41002>
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 INVITE
    Contact: <sip:mod_sofia@93.aaa.bbb.186:5060>
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Type: application/sdp
    Content-Disposition: session
    Content-Length: 318
    X-FS-Support: update_display
    Remote-Party-ID: "Extension 1000" 
<sip:1000@93.aaa.bbb.186>;party=calling;screen=yes;privacy=off

    v=0
    o=FreeSWITCH 1281531490 1281531491 IN IP4 93.aaa.bbb.186
    s=FreeSWITCH
    c=IN IP4 93.aaa.bbb.186
    t=0 0
    m=audio 21774 RTP/AVP 0 18 9 8 101 13
    a=rtpmap:0 PCMU/8000
    a=rtpmap:18 G729/8000
    a=rtpmap:9 G722/8000
    a=rtpmap:8 PCMA/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=rtpmap:13 CN/8000
    a=ptime:30
    ------------------------------------------------------------------------
2010-08-11 21:01:04.041592 [DEBUG] sofia.c:4318 Channel 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 entering state [calling][0]
recv 301 bytes from udp/[95.xxx.yyy.231]:41002 at 19:01:04.120370:
    ------------------------------------------------------------------------
    SIP/2.0 100 Trying
    To: <sip:1002@95.xxx.yyy.231:41002>
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 INVITE
    Via: SIP/2.0/UDP 93.aaa.bbb.186;branch=z9hG4bKyvX4D3Z0yHZ5e
    Server: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 397 bytes from udp/[95.xxx.yyy.231]:41002 at 19:01:04.264793:
    ------------------------------------------------------------------------
    SIP/2.0 180 Ringing
    To: <sip:1002@95.xxx.yyy.231:41002>;tag=dd77407622bd885i0
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 INVITE
    Via: SIP/2.0/UDP 93.aaa.bbb.186;branch=z9hG4bKyvX4D3Z0yHZ5e
    Server: Linksys/SPA941-5.1.8
    Remote-Party-ID: "1002" 
<sip:1002@93.aaa.bbb.186>;screen=yes;party=called
    Content-Length: 0

    ------------------------------------------------------------------------
2010-08-11 21:01:04.264258 [INFO] sofia.c:662 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 Update Callee ID to "1002" 
<1002>
2010-08-11 21:01:04.273760 [DEBUG] sofia.c:4318 Channel 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 entering state 
[proceeding][180]
2010-08-11 21:01:04.273760 [NOTICE] sofia.c:4390 Ring-Ready 
sofia/internal/sip:1002@95.xxx.yyy.231:41002!
2010-08-11 21:01:04.276790 [INFO] switch_ivr_originate.c:1079 Sending 
early media
2010-08-11 21:01:04.276790 [DEBUG] sofia_glue.c:2684 AUDIO RTP 
[sofia/internal/1000@93.aaa.bbb.186] 93.aaa.bbb.186 port 29380 -> 
95.xxx.yyy.231 port 16384 codec: 0 ms: 30
2010-08-11 21:01:04.276790 [DEBUG] switch_rtp.c:1413 Starting timer 
[soft] 240 bytes per 30ms
2010-08-11 21:01:04.278977 [DEBUG] sofia_glue.c:2894 Set 2833 dtmf send 
payload to 101
2010-08-11 21:01:04.278977 [DEBUG] sofia_glue.c:2899 Set 2833 dtmf 
receive payload to 101
2010-08-11 21:01:04.278977 [DEBUG] mod_sofia.c:2144 Ring SDP:
v=0
o=FreeSWITCH 1281523884 1281523885 IN IP4 93.aaa.bbb.186
s=FreeSWITCH
c=IN IP4 93.aaa.bbb.186
t=0 0
m=audio 29380 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

2010-08-11 21:01:04.278977 [NOTICE] mod_sofia.c:2147 Pre-Answer 
sofia/internal/1000@93.aaa.bbb.186!
2010-08-11 21:01:04.278977 [DEBUG] switch_channel.c:2397 
(sofia/internal/1000@93.aaa.bbb.186) Callstate Change RINGING -> EARLY
2010-08-11 21:01:04.278977 [DEBUG] switch_core_session.c:658 Send signal 
sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.278977 [DEBUG] switch_ivr_originate.c:1128 Raw Codec 
Activation Success L16@8000hz 1 channel 30ms
2010-08-11 21:01:04.278977 [DEBUG] switch_core_codec.c:116 
sofia/internal/1000@93.aaa.bbb.186 Push codec L16:10
2010-08-11 21:01:04.278977 [DEBUG] switch_ivr_originate.c:1193 Play 
Ringback Tone [%(2000,4000,440.0,480.0)]
send 1118 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:04.279808:
    ------------------------------------------------------------------------
    SIP/2.0 183 Session Progress
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    Contact: <sip:1002@93.aaa.bbb.186:5060;transport=udp>
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Accept: application/sdp
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Type: application/sdp
    Content-Disposition: session
    Content-Length: 247
    Remote-Party-ID: "1002" 
<sip:1002@93.aaa.bbb.186>;party=calling;privacy=off;screen=no

    v=0
    o=FreeSWITCH 1281523884 1281523885 IN IP4 93.aaa.bbb.186
    s=FreeSWITCH
    c=IN IP4 93.aaa.bbb.186
    t=0 0
    m=audio 29380 RTP/AVP 0 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=silenceSupp:off - - - -
    a=ptime:30
    ------------------------------------------------------------------------
2010-08-11 21:01:04.280443 [DEBUG] sofia.c:4313 Channel 
sofia/internal/1000@93.aaa.bbb.186 skipping state [early][183]
2010-08-11 21:01:04.405197 [DEBUG] switch_rtp.c:2527 Correct ip/port 
confirmed.
recv 578 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:07.276699:
    ------------------------------------------------------------------------
    CANCEL sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:4100000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="314faae6a65e754939bf9f5678a2fd60",qop=auth,nc=00000002,cnonce="54f72ed1"
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 578 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:07.764599:
    ------------------------------------------------------------------------
    CANCEL sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:4100000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="314faae6a65e754939bf9f5678a2fd60",qop=auth,nc=00000002,cnonce="54f72ed1"
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 578 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:08.765910:
    ------------------------------------------------------------------------
    CANCEL sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:4100000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="314faae6a65e754939bf9f5678a2fd60",qop=auth,nc=00000002,cnonce="54f72ed1"
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 578 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:10.764272:
    ------------------------------------------------------------------------
    CANCEL sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:4100000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="314faae6a65e754939bf9f5678a2fd60",qop=auth,nc=00000002,cnonce="54f72ed1"
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
recv 576 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:14.762786:
    ------------------------------------------------------------------------
    CANCEL sip:1002@93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Max-Forwards: 70
    Proxy-Authorization: Digest 
username="1000",realm="93.aaa.bbb.186",nonce="ca0e3c26-a57a-11df-8498-6130e0d7e4c0",uri="sip:1002@93.aaa.bbb.186",algorithm=MD5,response="314faae6a65e754939bf9f5678a2fd60",qop=auth,nc=00000002,cnonce="54f72ed1"
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
send 284 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:14.763018:
    ------------------------------------------------------------------------
    SIP/2.0 200 OK
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 CANCEL
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:14.763162:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
2010-08-11 21:01:14.762892 [DEBUG] sofia.c:4318 Channel 
sofia/internal/1000@93.aaa.bbb.186 entering state [terminated][487]
2010-08-11 21:01:14.762892 [DEBUG] switch_channel.c:2309 
(sofia/internal/1000@93.aaa.bbb.186) Callstate Change EARLY -> HANGUP
2010-08-11 21:01:14.762892 [NOTICE] sofia.c:4932 Hangup 
sofia/internal/1000@93.aaa.bbb.186 [CS_EXECUTE] [ORIGINATOR_CANCEL]
2010-08-11 21:01:14.762892 [DEBUG] switch_channel.c:2325 Send signal 
sofia/internal/1000@93.aaa.bbb.186 [KILL]
2010-08-11 21:01:14.762892 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.785078 [DEBUG] switch_core_codec.c:140 
sofia/internal/1000@93.aaa.bbb.186 Restore previous codec PCMU:0.
2010-08-11 21:01:14.785078 [DEBUG] switch_channel.c:2309 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Callstate Change RINGING 
-> HANGUP
2010-08-11 21:01:14.785078 [NOTICE] switch_ivr_originate.c:3282 Hangup 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 [CS_CONSUME_MEDIA] 
[ORIGINATOR_CANCEL]
2010-08-11 21:01:14.785078 [DEBUG] switch_channel.c:2325 Send signal 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 [KILL]
2010-08-11 21:01:14.785078 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:14.785078 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change 
CS_HANGUP
2010-08-11 21:01:14.785078 [DEBUG] switch_ivr_originate.c:3425 Originate 
Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2010-08-11 21:01:14.785078 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State HANGUP
2010-08-11 21:01:14.785078 [DEBUG] mod_sofia.c:447 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 Overriding SIP cause 487 
with 487 from the other leg
2010-08-11 21:01:14.785078 [DEBUG] mod_sofia.c:453 Channel 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 hanging up, cause: 
ORIGINATOR_CANCEL
2010-08-11 21:01:14.785078 [ERR] switch_ivr_originate.c:2623 Cannot 
create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2010-08-11 21:01:14.785078 [DEBUG] switch_ivr_originate.c:3431 Originate 
Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2010-08-11 21:01:14.785078 [INFO] mod_dptools.c:2393 Originate Failed.  
Cause: ORIGINATOR_CANCEL
2010-08-11 21:01:14.788208 [DEBUG] switch_core_session.c:1905 
sofia/internal/1000@93.aaa.bbb.186 skip receive message 
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2010-08-11 21:01:14.788208 [DEBUG] switch_core_state_machine.c:348 
(sofia/internal/1000@93.aaa.bbb.186) State EXECUTE going to sleep
2010-08-11 21:01:14.788208 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_HANGUP
2010-08-11 21:01:14.788208 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/1000@93.aaa.bbb.186) State HANGUP
2010-08-11 21:01:14.788208 [DEBUG] mod_sofia.c:447 
sofia/internal/1000@93.aaa.bbb.186 Overriding SIP cause 487 with 487 
from the other leg
2010-08-11 21:01:14.788208 [DEBUG] mod_sofia.c:453 Channel 
sofia/internal/1000@93.aaa.bbb.186 hanging up, cause: ORIGINATOR_CANCEL
2010-08-11 21:01:14.797311 [DEBUG] mod_sofia.c:506 Sending CANCEL to 
sofia/internal/sip:1002@95.xxx.yyy.231:41002
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:46 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 Standard HANGUP, cause: 
ORIGINATOR_CANCEL
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State HANGUP going to sleep
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:333 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State Change CS_HANGUP -> 
CS_REPORTING
2010-08-11 21:01:14.797311 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change 
CS_REPORTING
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State REPORTING
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:53 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 Standard REPORTING, cause: 
ORIGINATOR_CANCEL
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State REPORTING going to 
sleep
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:327 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State Change CS_REPORTING 
-> CS_DESTROY
2010-08-11 21:01:14.797311 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002@95.xxx.yyy.231:41002 [BREAK]
2010-08-11 21:01:14.797311 [DEBUG] switch_core_session.c:1202 Session 16 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Locked, Waiting on 
external entities
2010-08-11 21:01:14.797311 [NOTICE] switch_core_session.c:1220 Session 
16 (sofia/internal/sip:1002@95.xxx.yyy.231:41002) Ended
2010-08-11 21:01:14.797311 [NOTICE] switch_core_session.c:1222 Close 
Channel sofia/internal/sip:1002@95.xxx.yyy.231:41002 [CS_DESTROY]
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:427 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Callstate Change HANGUP 
-> DOWN
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:430 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) Running State Change 
CS_DESTROY
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State DESTROY
2010-08-11 21:01:14.797311 [DEBUG] mod_sofia.c:358 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 SOFIA DESTROY
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:60 
sofia/internal/sip:1002@95.xxx.yyy.231:41002 Standard DESTROY
2010-08-11 21:01:14.797311 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/sip:1002@95.xxx.yyy.231:41002) State DESTROY going to sleep
send 376 bytes to udp/[95.xxx.yyy.231]:41002 at 19:01:14.798471:
    ------------------------------------------------------------------------
    CANCEL sip:1002@95.xxx.yyy.231:41002 SIP/2.0
    Via: SIP/2.0/UDP 93.aaa.bbb.186;rport;branch=z9hG4bKyvX4D3Z0yHZ5e
    Max-Forwards: 69
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    To: <sip:1002@95.xxx.yyy.231:41002>
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 CANCEL
    Reason: FreeSWITCH;cause=487;text="ORIGINATOR_CANCEL"
    Content-Length: 0

    ------------------------------------------------------------------------
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:46 
sofia/internal/1000@93.aaa.bbb.186 Standard HANGUP, cause: ORIGINATOR_CANCEL
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/1000@93.aaa.bbb.186) State HANGUP going to sleep
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:333 
(sofia/internal/1000@93.aaa.bbb.186) State Change CS_HANGUP -> CS_REPORTING
2010-08-11 21:01:14.801620 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_REPORTING
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/1000@93.aaa.bbb.186) State REPORTING
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:53 
sofia/internal/1000@93.aaa.bbb.186 Standard REPORTING, cause: 
ORIGINATOR_CANCEL
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/1000@93.aaa.bbb.186) State REPORTING going to sleep
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:327 
(sofia/internal/1000@93.aaa.bbb.186) State Change CS_REPORTING -> 
CS_DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/1000@93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_session.c:1202 Session 15 
(sofia/internal/1000@93.aaa.bbb.186) Locked, Waiting on external entities
2010-08-11 21:01:14.801620 [NOTICE] switch_core_session.c:1220 Session 
15 (sofia/internal/1000@93.aaa.bbb.186) Ended
2010-08-11 21:01:14.801620 [NOTICE] switch_core_session.c:1222 Close 
Channel sofia/internal/1000@93.aaa.bbb.186 [CS_DESTROY]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:427 
(sofia/internal/1000@93.aaa.bbb.186) Callstate Change HANGUP -> DOWN
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:430 
(sofia/internal/1000@93.aaa.bbb.186) Running State Change CS_DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/1000@93.aaa.bbb.186) State DESTROY
2010-08-11 21:01:14.801620 [DEBUG] mod_sofia.c:358 
sofia/internal/1000@93.aaa.bbb.186 SOFIA DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:60 
sofia/internal/1000@93.aaa.bbb.186 Standard DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/1000@93.aaa.bbb.186) State DESTROY going to sleep
recv 335 bytes from udp/[95.xxx.yyy.231]:41002 at 19:01:14.875581:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    To: <sip:1002@95.xxx.yyy.231:41002>;tag=dd77407622bd885i0
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 INVITE
    Via: SIP/2.0/UDP 93.aaa.bbb.186;branch=z9hG4bKyvX4D3Z0yHZ5e
    Server: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
send 337 bytes to udp/[95.xxx.yyy.231]:41002 at 19:01:14.875798:
    ------------------------------------------------------------------------
    ACK sip:1002@95.xxx.yyy.231:41002 SIP/2.0
    Via: SIP/2.0/UDP 93.aaa.bbb.186;rport;branch=z9hG4bKyvX4D3Z0yHZ5e
    Max-Forwards: 69
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    To: <sip:1002@95.xxx.yyy.231:41002>;tag=dd77407622bd885i0
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 ACK
    Content-Length: 0

    ------------------------------------------------------------------------
recv 319 bytes from udp/[95.xxx.yyy.231]:41002 at 19:01:14.887136:
    ------------------------------------------------------------------------
    SIP/2.0 200 OK
    To: <sip:1002@95.xxx.yyy.231:41002>;tag=dd77407622bd885i0
    From: "Extension 1000" <sip:1000@93.aaa.bbb.186>;tag=paN5XSX76veNp
    Call-ID: a1834f63-201d-122e-719b-a4badbdfa48e
    CSeq: 440568 CANCEL
    Via: SIP/2.0/UDP 93.aaa.bbb.186;branch=z9hG4bKyvX4D3Z0yHZ5e
    Server: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:15.263994:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:16.264001:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:18.264000:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:22.264012:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:26.264005:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:30.264009:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
recv 331 bytes from udp/[95.xxx.yyy.231]:41002 at 19:01:30.347502:
    ------------------------------------------------------------------------
    NOTIFY sip:93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41002;branch=z9hG4bK-adf19f8b
    From: "1002" <sip:1002@93.aaa.bbb.186>;tag=6c504ae2eadd96bfo0
    To: <sip:93.aaa.bbb.186>
    Call-ID: bf54057e-64adbcd3@192.168.1.40
    CSeq: 70 NOTIFY
    Max-Forwards: 70
    Event: keep-alive
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
send 637 bytes to udp/[95.xxx.yyy.231]:41002 at 19:01:30.347847:
    ------------------------------------------------------------------------
    SIP/2.0 200 OK
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41002;branch=z9hG4bK-adf19f8b
    From: "1002" <sip:1002@93.aaa.bbb.186>;tag=6c504ae2eadd96bfo0
    To: <sip:93.aaa.bbb.186>;tag=QKeyZmeB4547H
    Call-ID: bf54057e-64adbcd3@192.168.1.40
    CSeq: 70 NOTIFY
    Contact: <sip:93.aaa.bbb.186>
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:34.268007:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:38.268010:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
recv 331 bytes from udp/[95.xxx.yyy.231]:41000 at 19:01:39.777149:
    ------------------------------------------------------------------------
    NOTIFY sip:93.aaa.bbb.186 SIP/2.0
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-4494dffc
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=9ddc56accbaeed50o0
    To: <sip:93.aaa.bbb.186>
    Call-ID: 8acf935c-c8ed5860@192.168.1.34
    CSeq: 71 NOTIFY
    Max-Forwards: 70
    Event: keep-alive
    User-Agent: Linksys/SPA941-5.1.8
    Content-Length: 0

    ------------------------------------------------------------------------
send 637 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:39.777522:
    ------------------------------------------------------------------------
    SIP/2.0 200 OK
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-4494dffc
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=9ddc56accbaeed50o0
    To: <sip:93.aaa.bbb.186>;tag=rv7p1FZe1eUtD
    Call-ID: 8acf935c-c8ed5860@192.168.1.34
    CSeq: 71 NOTIFY
    Contact: <sip:93.aaa.bbb.186>
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:42.268669:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------
send 647 bytes to udp/[95.xxx.yyy.231]:41000 at 19:01:46.268661:
    ------------------------------------------------------------------------
    SIP/2.0 487 Request Terminated
    Via: SIP/2.0/UDP 95.xxx.yyy.231:41000;branch=z9hG4bK-bf655f9e
    From: "1000" <sip:1000@93.aaa.bbb.186>;tag=ae60c1d11550e891o0
    To: "Extension 1002" <sip:1002@93.aaa.bbb.186>;tag=N1Ucvyc49Kr2a
    Call-ID: 97c7aad1-f86f1391@192.168.1.34
    CSeq: 102 INVITE
    User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-
    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, 
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
    Supported: timer, precondition, path, replaces
    Allow-Events: talk, hold, presence, dialog, line-seize, call-info, 
sla, include-session-description, presence.winfo, message-summary, refer
    Content-Length: 0

    ------------------------------------------------------------------------

freeswitch@internal> ...

[Freeswitch-users] SIP CANCEL Problems

Area Europa