I'm working on an alternative to a $120,000 Cisco phone system that my
company is looking at. I got Freeswitch installed on CentOS last week
using the Quick and Dirty instructions. That part was painless. We had a
few 7940s laying around. After some wrestling with it, I got the latest
SIP firmware installed and what I hoped was a functional config
(attached). X-Lite phones can call each other no problem. 7940s can call
X-Lite no problem. Anytime I try and call a 7940, it goes straight to
voicemail. I attached a log file that shows the activity when trying to
call a7940 from X-Lite.
X-Lite is at 10.86.10.58. 7940 is at 10.86.11.50. Freeswitch is
nshplpbx1.unix/10.85.0.53. Everything is on the same LAN. Different
subnets, but no firewalls.
I didn't see anything that said posting attachments was frowned upon. I
apologize if it isn't appropriate. I'm guessing this is something simple
and I'm just clueless on how to diagnose the issue.
I'm not tied to using this model for good, but it is what we had laying
around. Any help would be greatly appreciated. Next step is configuring
it to talk to Verizon VOIP over a DS3.
Thanks,
Matthew Kitchin
dsi> sh conf
------ Current *FLASH* Configuration ------
Platform : Cisco Systems, Inc. IP Phone CP-7940G
Elapsed Time: 01:01:06
dhcp_server : Disabled
my_ip_addr : 10.86.11.50
subnet_mask : 255.255.0.0
defaultgw : 10.86.0.1
dyn_dns_addr_1 : 0.0.0.0
dyn_dns_addr_2 : 0.0.0.0
dns_addr : 10.85.0.11
dns_backup_1: 10.85.0.10
primary_tftp_addr : 10.86.10.58
dyn_tftp_addr : 0.0.0.0
my_mac_addr : 0012:7f98:eaa9
domain_name : dsi-corp.net
my_name : SIP00127F98EAA9
Status Flags : 12300001
image_version : "P003-8-12-00"
FirmLoadID : "PC030301"
DSPLoadID : "PS03AT38"
network_media_type : Auto
network_port2_type : Hub/Switch
dscpForAudio : 184
phone_label : "Matthew Kitchin"
tftp_cfg_dir : ""
phone_password : **********
phone_prompt : "dsi"
language : english
sntp_mode : Unicast
sntp_server : 10.85.0.10
time_zone : CST
dst_offset : 01/00
dst_start_month : March
dst_start_day : 0
dst_start_day_of_week : Sunday
dst_start_week_of_month : 8
dst_start_time : 02/00
dst_stop_month : October
dst_stop_day : 0
dst_stop_day_of_week : Sunday
dst_stop_week_of_month : 8
dst_stop_time : 02/00
dst_auto_adjust : 1
time_format_24hr : 1
date_format : M/D/Y
nat_enable : 0
nat_address : UNPROVISIONED
voip_control_port : 5060
start_media_port : 16384
end_media_port : 32766
sync : "1"
xml_card_dir : ""
xml_card_file : "CARD.XML"
telnet_level : 1
services_url : ""
directory_url : ""
logo_url : ""
http_proxy_addr : UNPROVISIONED
http_proxy_port : 80
garp_enable : 0
enable_vad : 0
dial_template : "dialplan"
callerid_blocking : 0
anonymous_call_block : 0
autocomplete : 0
messages_uri : ""
dnd_control : 2
preferred_codec : g711ulaw
dtmf_outofband : avt_always
dtmf_avt_payload : 101
dtmf_db_level : 3
dtmf_inband : 0
call_manager1_addr : "UNPROVISIONED"
call_manager2_addr : "UNPROVISIONED"
call_manager3_addr : "UNPROVISIONED"
call_manager1_sip_port : 5060
call_manager2_sip_port : 5060
call_manager3_sip_port : 5060
call_manager5_addr : "UNPROVISIONED"
call_manager5_sip_port : 5060
call_manager4_addr : "UNPROVISIONED"
call_manager4_sip_port : 0
line1_name : "1008"
line2_name : "1001"
line1_authname : "1008"
line2_authname : "1001"
line1_password : **********
line2_password : **********
line1_shortname : "1008"
line2_shortname : "1001"
line1_displayname : "1008"
line2_displayname : "UNPROVISIONED"
line1_contact : "UNPROVISIONED"
line2_contact : "UNPROVISIONED"
proxy1_address : "nshplpbx1.unix"
proxy2_address : "nshplpbx1.unix"
proxy1_port : 5060
proxy2_port : 5060
sip_retx : 10
sip_invite_retx : 6
timer_t1 : 500
timer_t2 : 4000
timer_invite_expires : 180
timer_register_expires : 3600
proxy_register : 1
proxy_backup : ""
proxy_emergency : ""
proxy_backup_port : 5060
proxy_emergency_port : 5060
outbound_proxy : UNPROVISIONED
outbound_proxy_port : 5060
nat_received_processing : 0
mwi_status : 0
call_waiting : 1
user_info : phone
cnf_join_enable : 0
remote_party_id : 1
semi_attended_transfer : 1
transfer_onhook_enabled : 0
call_hold_ringback : 3
stutter_msg_waiting : 0
cfwd_url : ""
call_stats : 0
auto_answer : 0
local_cfwd_enable : 1
timer_register_delta : 5
sip_max_forwards : 70
rfc_2543_hold : 0
version_stamp : ""
timer_keepalive_expires : 120
connection_monitor_duration : 120
encrypt_key : **********
2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5067 0 acls to check for proxy
2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5085 network ip is a proxy [0]
2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5113 IP 10.86.10.58 Rejected by acl
"domains". Falling back to Digest auth.
2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5067 0 acls to check for proxy
2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5085 network ip is a proxy [0]
2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5113 IP 10.86.10.58 Rejected by acl
"domains". Falling back to Digest auth.
2009-11-03 15:39:50.797901 [NOTICE] switch_channel.c:613 New Channel
sofia/internal/1...@nshplpbx1.unix [8c133ad4-67cf-4ffa-8655-56ffa0e3933d]
2009-11-03 15:39:50.799061 [DEBUG] sofia.c:5812 Setting NAT mode based on
nat.auto
2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3588 Channel
sofia/internal/1...@nshplpbx1.unix entering state [received][100]
2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3599 Remote SDP:
v=0
o=- 8 2 IN IP4 10.86.10.58
s=CounterPath X-Lite 3.0
c=IN IP4 10.86.10.58
t=0 0
m=audio 37250 RTP/AVP 107 0 8 101
a=rtpmap:107 BV32/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : cwKnUvoi NsQWtT4P 10.86.10.58 37250
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[G7221:115:32000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[G7221:107:16000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[G722:9:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[PCMU:0:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[PCMA:8:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[BV32:107:16000:0]/[GSM:3:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[PCMU:0:8000:0]/[G7221:115:32000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[PCMU:0:8000:0]/[G7221:107:16000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[PCMU:0:8000:0]/[G722:9:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare
[PCMU:0:8000:0]/[PCMU:0:8000:20]
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:2102 Set Codec
sofia/internal/1...@nshplpbx1.unix PCMU/8000 20 ms 160 samples
2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3120 Set 2833 dtmf payload to
101
2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3744
(sofia/internal/1...@nshplpbx1.unix) State Change CS_NEW -> CS_INIT
2009-11-03 15:39:50.799061 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_INIT
2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:330
(sofia/internal/1...@nshplpbx1.unix) State INIT
2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:83
sofia/internal/1...@nshplpbx1.unix SOFIA INIT
2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:111
(sofia/internal/1...@nshplpbx1.unix) State Change CS_INIT -> CS_ROUTING
2009-11-03 15:39:50.799061 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:330
(sofia/internal/1...@nshplpbx1.unix) State INIT going to sleep
2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_ROUTING
2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/1...@nshplpbx1.unix) State ROUTING
2009-11-03 15:39:50.800189 [DEBUG] mod_sofia.c:130
sofia/internal/1...@nshplpbx1.unix SOFIA ROUTING
2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:78
sofia/internal/1...@nshplpbx1.unix Standard ROUTING
2009-11-03 15:39:50.800189 [INFO] mod_dialplan_xml.c:397 Processing 1000->1008
in context default
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->unloop]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->tod_example]
continue=true
Dialplan: day of week[3] =~ 2-6 (PASS)
Dialplan: hour[15] =~ 9-18 (PASS)
Dialplan: sofia/internal/1...@nshplpbx1.unix Date/Time Match (PASS)
[tod_example] break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix Action set(open=true)
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [global-intercept]
destination_number(1008) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->group-intercept]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [group-intercept]
destination_number(1008) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->intercept-ext]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [intercept-ext]
destination_number(1008) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->redial]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [redial]
destination_number(1008) =~ /^870$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->global]
continue=true
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [global]
${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/
break=never
Dialplan: sofia/internal/1...@nshplpbx1.unix Absolute Condition [global]
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->snom-demo-2]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [snom-demo-2]
destination_number(1008) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->snom-demo-1]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [snom-demo-1]
destination_number(1008) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [eavesdrop]
destination_number(1008) =~ /^88(.*)$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [eavesdrop]
destination_number(1008) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->call_return]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [call_return]
destination_number(1008) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->del-group]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [del-group]
destination_number(1008) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->add-group]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [add-group]
destination_number(1008) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->call-group-simo]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [call-group-simo]
destination_number(1008) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [call-group-order]
destination_number(1008) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (FAIL) [extension-intercom]
destination_number(1008) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix parsing [default->Local_Extension]
continue=false
Dialplan: sofia/internal/1...@nshplpbx1.unix Regex (PASS) [Local_Extension]
destination_number(1008) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1...@nshplpbx1.unix Action set(dialed_extension=1008)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
export(dialed_extension=1008)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/1...@nshplpbx1.unix 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/1...@nshplpbx1.unix Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action set(ringback=${us-ring})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action set(call_timeout=30)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action set(continue_on_fail=true)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
set(called_party_callgroup=${user_data(${dialed_extensi...@${domain_name} var
callgroup)})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action
bridge(user/${dialed_extensi...@${domain_name})
Dialplan: sofia/internal/1...@nshplpbx1.unix Action answer()
Dialplan: sofia/internal/1...@nshplpbx1.unix Action sleep(1000)
Dialplan: sofia/internal/1...@nshplpbx1.unix Action voicemail(default
${domain_name} ${dialed_extension})
2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:114
(sofia/internal/1...@nshplpbx1.unix) State Change CS_ROUTING -> CS_EXECUTE
2009-11-03 15:39:50.801914 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/1...@nshplpbx1.unix) State ROUTING going to sleep
2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_EXECUTE
2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:340
(sofia/internal/1...@nshplpbx1.unix) State EXECUTE
2009-11-03 15:39:50.801914 [DEBUG] mod_sofia.c:173
sofia/internal/1...@nshplpbx1.unix SOFIA EXECUTE
2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:151
sofia/internal/1...@nshplpbx1.unix Standard EXECUTE
EXECUTE sofia/internal/1...@nshplpbx1.unix set(open=true)
2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [open]=[true]
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-spymap/1000/8c133ad4-67cf-4ffa-8655-56ffa0e3933d)
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-last_dial/1000/1008)
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-last_dial/global/8c133ad4-67cf-4ffa-8655-56ffa0e3933d)
EXECUTE sofia/internal/1...@nshplpbx1.unix set(dialed_extension=1008)
2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [dialed_extension]=[1008]
EXECUTE sofia/internal/1...@nshplpbx1.unix export(dialed_extension=1008)
2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:846 EXPORT
[dialed_extension]=[1008]
EXECUTE sofia/internal/1...@nshplpbx1.unix bind_meta_app(1 b s
execute_extension::dx XML features)
2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 1
execute_extension::dx XML features
EXECUTE sofia/internal/1...@nshplpbx1.unix bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/1000.2009-11-03-15-39-50.wav)
2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 2
record_session::/usr/local/freeswitch/recordings/1000.2009-11-03-15-39-50.wav
EXECUTE sofia/internal/1...@nshplpbx1.unix bind_meta_app(3 b s
execute_extension::cf XML features)
2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 3
execute_extension::cf XML features
EXECUTE sofia/internal/1...@nshplpbx1.unix
set(ringback=%(2000,4000,440.0,480.0))
2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE sofia/internal/1...@nshplpbx1.unix
set(transfer_ringback=local_stream://moh)
2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1...@nshplpbx1.unix set(call_timeout=30)
2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [call_timeout]=[30]
EXECUTE sofia/internal/1...@nshplpbx1.unix set(hangup_after_bridge=true)
2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1...@nshplpbx1.unix set(continue_on_fail=true)
2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-call_return/1008/1000)
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-last_dial_ext/1008/8c133ad4-67cf-4ffa-8655-56ffa0e3933d)
EXECUTE sofia/internal/1...@nshplpbx1.unix
set(called_party_callgroup=techsupport)
2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763
sofia/internal/1...@nshplpbx1.unix SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1...@nshplpbx1.unix
hash(insert/10.85.0.53-last_dial/techsupport/8c133ad4-67cf-4ffa-8655-56ffa0e3933d)
EXECUTE sofia/internal/1...@nshplpbx1.unix bridge(user/1...@10.85.0.53)
2009-11-03 15:39:50.812162 [DEBUG] switch_ivr_originate.c:1333 variable string
0 = [presence_id=1...@10.85.0.53]
2009-11-03 15:39:50.812162 [NOTICE] switch_channel.c:613 New Channel
sofia/internal/sip:1...@10.86.11.50:5060 [32661f42-b0a9-4179-867d-156b46ae71ce]
2009-11-03 15:39:50.812162 [DEBUG] mod_sofia.c:3061
(sofia/internal/sip:1...@10.86.11.50:5060) State Change CS_NEW -> CS_INIT
2009-11-03 15:39:50.812162 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.812162 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_INIT
2009-11-03 15:39:50.812162 [DEBUG] switch_core_state_machine.c:330
(sofia/internal/sip:1...@10.86.11.50:5060) State INIT
2009-11-03 15:39:50.812162 [DEBUG] mod_sofia.c:83
sofia/internal/sip:1...@10.86.11.50:5060 SOFIA INIT
2009-11-03 15:39:50.812162 [DEBUG] sofia_glue.c:1761
sip:1...@10.86.11.50:51061;user=phone;transport=udp Setting proxy route to
sofia/internal/sip:1...@10.86.11.50:5060
2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:111
(sofia/internal/sip:1...@10.86.11.50:5060) State Change CS_INIT -> CS_ROUTING
2009-11-03 15:39:50.814226 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.814226 [DEBUG] sofia.c:3588 Channel
sofia/internal/sip:1...@10.86.11.50:5060 entering state [calling][0]
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:330
(sofia/internal/sip:1...@10.86.11.50:5060) State INIT going to sleep
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_ROUTING
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/sip:1...@10.86.11.50:5060) State ROUTING
2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:130
sofia/internal/sip:1...@10.86.11.50:5060 SOFIA ROUTING
2009-11-03 15:39:50.814226 [DEBUG] switch_ivr_originate.c:66
(sofia/internal/sip:1...@10.86.11.50:5060) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2009-11-03 15:39:50.814226 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/sip:1...@10.86.11.50:5060) State ROUTING going to sleep
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_CONSUME_MEDIA
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:352
(sofia/internal/sip:1...@10.86.11.50:5060) State CONSUME_MEDIA
2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:352
(sofia/internal/sip:1...@10.86.11.50:5060) State CONSUME_MEDIA going to sleep
2009-11-03 15:39:50.817484 [DEBUG] sofia.c:3588 Channel
sofia/internal/sip:1...@10.86.11.50:5060 entering state [terminated][503]
2009-11-03 15:39:50.817484 [NOTICE] sofia.c:4187 Hangup
sofia/internal/sip:1...@10.86.11.50:5060 [CS_CONSUME_MEDIA]
[NORMAL_TEMPORARY_FAILURE]
2009-11-03 15:39:50.817484 [DEBUG] switch_channel.c:1896 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [KILL]
2009-11-03 15:39:50.817484 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.817484 [DEBUG] switch_core_state_machine.c:451 thread
mismatch skipping state handler.
2009-11-03 15:39:50.817484 [DEBUG] switch_ivr_originate.c:2543 Originate
Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2009-11-03 15:39:50.817484 [ERR] switch_ivr_originate.c:1829 Cannot create
outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
2009-11-03 15:39:50.817484 [DEBUG] switch_ivr_originate.c:2543 Originate
Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2009-11-03 15:39:50.817484 [INFO] mod_dptools.c:2290 Originate Failed. Cause:
NORMAL_TEMPORARY_FAILURE
2009-11-03 15:39:50.817484 [DEBUG] mod_dptools.c:2312 Continue on fail [true]:
Cause: NORMAL_TEMPORARY_FAILURE
EXECUTE sofia/internal/1...@nshplpbx1.unix answer()
2009-11-03 15:39:50.817484 [DEBUG] mod_dptools.c:653
sofia/internal/1...@nshplpbx1.unix receive message [ANSWER]
2009-11-03 15:39:50.817484 [DEBUG] sofia_glue.c:2336 AUDIO RTP
[sofia/internal/1...@nshplpbx1.unix] 10.85.0.53 port 24712 -> 10.86.10.58 port
37250 codec: 0 ms: 20
2009-11-03 15:39:50.817484 [DEBUG] switch_rtp.c:1155 Starting timer [soft] 160
bytes per 20ms
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_HANGUP
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:478
(sofia/internal/sip:1...@10.86.11.50:5060) State HANGUP
2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:329
sofia/internal/sip:1...@10.86.11.50:5060 Overriding SIP cause 503 with 503 from
the other leg
2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:361 Channel
sofia/internal/sip:1...@10.86.11.50:5060 hanging up, cause:
NORMAL_TEMPORARY_FAILURE
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:46
sofia/internal/sip:1...@10.86.11.50:5060 Standard HANGUP, cause:
NORMAL_TEMPORARY_FAILURE
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:478
(sofia/internal/sip:1...@10.86.11.50:5060) State HANGUP going to sleep
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:325
(sofia/internal/sip:1...@10.86.11.50:5060) State Change CS_HANGUP ->
CS_REPORTING
2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_REPORTING
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:569
(sofia/internal/sip:1...@10.86.11.50:5060) State REPORTING
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:53
sofia/internal/sip:1...@10.86.11.50:5060 Standard REPORTING, cause:
NORMAL_TEMPORARY_FAILURE
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:569
(sofia/internal/sip:1...@10.86.11.50:5060) State REPORTING going to sleep
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:319
(sofia/internal/sip:1...@10.86.11.50:5060) State Change CS_REPORTING ->
CS_DESTROY
2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/sip:1...@10.86.11.50:5060 [BREAK]
2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1140 Session 32
(sofia/internal/sip:1...@10.86.11.50:5060) Locked, Waiting on external entities
2009-11-03 15:39:50.818924 [NOTICE] switch_core_session.c:1158 Session 32
(sofia/internal/sip:1...@10.86.11.50:5060) Ended
2009-11-03 15:39:50.818924 [NOTICE] switch_core_session.c:1160 Close Channel
sofia/internal/sip:1...@10.86.11.50:5060 [CS_DESTROY]
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1...@10.86.11.50:5060) Running State Change CS_DESTROY
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:426
(sofia/internal/sip:1...@10.86.11.50:5060) State DESTROY
2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:278
sofia/internal/sip:1...@10.86.11.50:5060 SOFIA DESTROY
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:60
sofia/internal/sip:1...@10.86.11.50:5060 Standard DESTROY
2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:426
(sofia/internal/sip:1...@10.86.11.50:5060) State DESTROY going to sleep
2009-11-03 15:39:50.820304 [DEBUG] mod_sofia.c:569 Local SDP
sofia/internal/1...@nshplpbx1.unix:
v=0
o=FreeSWITCH 1257259678 1257259679 IN IP4 10.85.0.53
s=FreeSWITCH
c=IN IP4 10.85.0.53
t=0 0
m=audio 24712 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:20
a=sendrecv
2009-11-03 15:39:50.821960 [DEBUG] sofia.c:3588 Channel
sofia/internal/1...@nshplpbx1.unix entering state [completed][200]
2009-11-03 15:39:50.821960 [DEBUG] switch_core_session.c:664 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:50.821960 [NOTICE] mod_dptools.c:653 Channel
[sofia/internal/1...@nshplpbx1.unix] has been answered
2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182
sofia/internal/1...@nshplpbx1.unix receive message [AUDIO_SYNC]
EXECUTE sofia/internal/1...@nshplpbx1.unix sleep(1000)
2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182
sofia/internal/1...@nshplpbx1.unix receive message [AUDIO_SYNC]
2009-11-03 15:39:50.867612 [DEBUG] switch_rtp.c:1917 Correct ip/port confirmed.
2009-11-03 15:39:50.926503 [DEBUG] sofia.c:3588 Channel
sofia/internal/1...@nshplpbx1.unix entering state [ready][200]
EXECUTE sofia/internal/1...@nshplpbx1.unix voicemail(default 10.85.0.53 1008)
2009-11-03 15:39:51.840356 [DEBUG] mod_voicemail.c:799 [default] rwlock
2009-11-03 15:39:51.840356 [DEBUG] switch_channel.c:182
sofia/internal/1...@nshplpbx1.unix receive message [AUDIO_SYNC]
2009-11-03 15:39:51.959567 [DEBUG] switch_ivr_play_say.c:118 No language
specified - Using [en]
2009-11-03 15:39:51.961607 [DEBUG] switch_ivr_play_say.c:273 Handle
play-file:[voicemail/vm-person.wav] (en:en)
2009-11-03 15:39:51.961607 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated
l...@8000hz 1 channels 20ms
2009-11-03 15:39:51.961607 [DEBUG] switch_core_io.c:660
sofia/internal/1...@nshplpbx1.unix receive message [TRANSCODING_NECESSARY]
2009-11-03 15:39:53.319706 [DEBUG] switch_ivr_play_say.c:1428 done playing file
2009-11-03 15:39:53.439693 [DEBUG] switch_ivr_play_say.c:273 Handle say:[1008]
(en:en)
2009-11-03 15:39:53.439693 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated
l...@8000hz 1 channels 20ms
2009-11-03 15:39:53.439693 [DEBUG] switch_core_io.c:660
sofia/internal/1...@nshplpbx1.unix receive message [TRANSCODING_NECESSARY]
2009-11-03 15:39:53.899622 [DEBUG] switch_ivr_play_say.c:1428 done playing file
2009-11-03 15:39:53.899622 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated
l...@8000hz 1 channels 20ms
2009-11-03 15:39:53.899622 [DEBUG] switch_core_io.c:660
sofia/internal/1...@nshplpbx1.unix receive message [TRANSCODING_NECESSARY]
2009-11-03 15:39:54.127652 [NOTICE] sofia.c:328 Hangup
sofia/internal/1...@nshplpbx1.unix [CS_EXECUTE] [NORMAL_CLEARING]
2009-11-03 15:39:54.127652 [DEBUG] switch_channel.c:1896 Send signal
sofia/internal/1...@nshplpbx1.unix [KILL]
2009-11-03 15:39:54.127652 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:54.127652 [DEBUG] switch_core_state_machine.c:451 thread
mismatch skipping state handler.
2009-11-03 15:39:54.139706 [DEBUG] switch_ivr_play_say.c:1428 done playing file
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:340
(sofia/internal/1...@nshplpbx1.unix) State EXECUTE going to sleep
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_HANGUP
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478
(sofia/internal/1...@nshplpbx1.unix) State HANGUP
2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:329
sofia/internal/1...@nshplpbx1.unix Overriding SIP cause 480 with 503 from the
other leg
2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:361 Channel
sofia/internal/1...@nshplpbx1.unix hanging up, cause: NORMAL_CLEARING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:46
sofia/internal/1...@nshplpbx1.unix Standard HANGUP, cause: NORMAL_CLEARING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478
(sofia/internal/1...@nshplpbx1.unix) State HANGUP going to sleep
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:325
(sofia/internal/1...@nshplpbx1.unix) State Change CS_HANGUP -> CS_REPORTING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_REPORTING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569
(sofia/internal/1...@nshplpbx1.unix) State REPORTING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:53
sofia/internal/1...@nshplpbx1.unix Standard REPORTING, cause: NORMAL_CLEARING
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569
(sofia/internal/1...@nshplpbx1.unix) State REPORTING going to sleep
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:319
(sofia/internal/1...@nshplpbx1.unix) State Change CS_REPORTING -> CS_DESTROY
2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1003 Send signal
sofia/internal/1...@nshplpbx1.unix [BREAK]
2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1140 Session 31
(sofia/internal/1...@nshplpbx1.unix) Locked, Waiting on external entities
2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1158 Session 31
(sofia/internal/1...@nshplpbx1.unix) Ended
2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1160 Close Channel
sofia/internal/1...@nshplpbx1.unix [CS_DESTROY]
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1...@nshplpbx1.unix) Running State Change CS_DESTROY
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426
(sofia/internal/1...@nshplpbx1.unix) State DESTROY
2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:278
sofia/internal/1...@nshplpbx1.unix SOFIA DESTROY
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:60
sofia/internal/1...@nshplpbx1.unix Standard DESTROY
2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426
(sofia/internal/1...@nshplpbx1.unix) State DESTROY going to sleep
]0;r...@nshplpbx1:/usr/local/freeswitch/log[r...@nshplpbx1 log]# _______________________________________________
FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
