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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)93.aaa.bbb.186) State NEW
2010-08-11 21:01:04.023433 [DEBUG] sofia.c:4318 Channel
sofia/internal/1000(a)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(a)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(a)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(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000(a)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(a)93.aaa.bbb.186) State INIT
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:83
sofia/internal/1000(a)93.aaa.bbb.186 SOFIA INIT
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:119
(sofia/internal/1000(a)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(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/1000(a)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(a)93.aaa.bbb.186) Running State Change CS_ROUTING
2010-08-11 21:01:04.024600 [DEBUG] switch_channel.c:1512
(sofia/internal/1000(a)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(a)93.aaa.bbb.186) State ROUTING
2010-08-11 21:01:04.024600 [DEBUG] mod_sofia.c:142
sofia/internal/1000(a)93.aaa.bbb.186 SOFIA ROUTING
2010-08-11 21:01:04.024600 [DEBUG] switch_core_state_machine.c:77
sofia/internal/1000(a)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(a)93.aaa.bbb.186 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->tod_example] continue=true
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Date/Time Match (FAIL)
[tod_example] break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Date/Time Match (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[global-intercept] destination_number(1002) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->intercept-ext] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing [default->redial]
continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [redial]
destination_number(1002) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing [default->global]
continue=true
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1000(a)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(a)93.aaa.bbb.186 Absolute Condition [global]
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->snom-demo-2] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [snom-demo-2]
destination_number(1002) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->snom-demo-1] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [snom-demo-1]
destination_number(1002) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [eavesdrop]
destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [eavesdrop]
destination_number(1002) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->call_return] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [call_return]
destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->del-group] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [del-group]
destination_number(1002) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->add-group] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL) [add-group]
destination_number(1002) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (FAIL)
[extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Regex (PASS)
[Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(dialed_extension=1002)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
export(dialed_extension=1002)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/1000(a)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(a)93.aaa.bbb.186 Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(ringback=${us-ring})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action set(call_timeout=30)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(continue_on_fail=true)
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var
callgroup)})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action
bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action answer()
Dialplan: sofia/internal/1000(a)93.aaa.bbb.186 Action sleep(1000)
Dialplan: sofia/internal/1000(a)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(a)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(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/1000(a)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(a)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(a)93.aaa.bbb.186) State EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] mod_sofia.c:235
sofia/internal/1000(a)93.aaa.bbb.186 SOFIA EXECUTE
2010-08-11 21:01:04.025632 [DEBUG] switch_core_state_machine.c:157
sofia/internal/1000(a)93.aaa.bbb.186 Standard EXECUTE
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-spymap/1000/ca21d98e-a57a-11df-8499-6130e0d7e4c0)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-last_dial/1000/1002)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-last_dial/global/ca21d98e-a57a-11df-8499-6130e0d7e4c0)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186 set(dialed_extension=1002)
2010-08-11 21:01:04.026839 [DEBUG] mod_dptools.c:854
sofia/internal/1000(a)93.aaa.bbb.186 SET [dialed_extension]=[1002]
EXECUTE sofia/internal/1000(a)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(a)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(a)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(a)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(a)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(a)93.aaa.bbb.186 SET
[ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE sofia/internal/1000(a)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(a)93.aaa.bbb.186 SET
[transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186 set(call_timeout=30)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854
sofia/internal/1000(a)93.aaa.bbb.186 SET [call_timeout]=[30]
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186 set(hangup_after_bridge=true)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854
sofia/internal/1000(a)93.aaa.bbb.186 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186 set(continue_on_fail=true)
2010-08-11 21:01:04.029110 [DEBUG] mod_dptools.c:854
sofia/internal/1000(a)93.aaa.bbb.186 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-call_return/1002/1000)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-last_dial_ext/1002/ca21d98e-a57a-11df-8499-6130e0d7e4c0)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
set(called_party_callgroup=techsupport)
2010-08-11 21:01:04.030434 [DEBUG] mod_dptools.c:854
sofia/internal/1000(a)93.aaa.bbb.186 SET
[called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186
hash(insert/93.aaa.bbb.186-last_dial/techsupport/ca21d98e-a57a-11df-8499-6130e0d7e4c0)
EXECUTE sofia/internal/1000(a)93.aaa.bbb.186 bridge(user/1002(a)93.aaa.bbb.186)
2010-08-11 21:01:04.032457 [DEBUG] switch_ivr_originate.c:1979 variable
string 0 = [presence_id=1002(a)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(a)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(a)93.aaa.bbb.186!
2010-08-11 21:01:04.278977 [DEBUG] switch_channel.c:2397
(sofia/internal/1000(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)93.aaa.bbb.186 entering state [terminated][487]
2010-08-11 21:01:14.762892 [DEBUG] switch_channel.c:2309
(sofia/internal/1000(a)93.aaa.bbb.186) Callstate Change EARLY -> HANGUP
2010-08-11 21:01:14.762892 [NOTICE] sofia.c:4932 Hangup
sofia/internal/1000(a)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(a)93.aaa.bbb.186 [KILL]
2010-08-11 21:01:14.762892 [DEBUG] switch_core_session.c:1039 Send
signal sofia/internal/1000(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.785078 [DEBUG] switch_core_codec.c:140
sofia/internal/1000(a)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(a)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(a)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(a)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(a)93.aaa.bbb.186) State HANGUP
2010-08-11 21:01:14.788208 [DEBUG] mod_sofia.c:447
sofia/internal/1000(a)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(a)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(a)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(a)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(a)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(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000(a)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(a)93.aaa.bbb.186) State REPORTING
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:53
sofia/internal/1000(a)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(a)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(a)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(a)93.aaa.bbb.186 [BREAK]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_session.c:1202 Session 15
(sofia/internal/1000(a)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(a)93.aaa.bbb.186) Ended
2010-08-11 21:01:14.801620 [NOTICE] switch_core_session.c:1222 Close
Channel sofia/internal/1000(a)93.aaa.bbb.186 [CS_DESTROY]
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:427
(sofia/internal/1000(a)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(a)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(a)93.aaa.bbb.186) State DESTROY
2010-08-11 21:01:14.801620 [DEBUG] mod_sofia.c:358
sofia/internal/1000(a)93.aaa.bbb.186 SOFIA DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:60
sofia/internal/1000(a)93.aaa.bbb.186 Standard DESTROY
2010-08-11 21:01:14.801620 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/1000(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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> ...