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/1000@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/1000@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/1000@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/1000@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/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_INIT 2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/1000@nshplpbx1.unix) State INIT 2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:83 sofia/internal/1000@nshplpbx1.unix SOFIA INIT 2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:111 (sofia/internal/1000@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/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/1000@nshplpbx1.unix) State INIT going to sleep 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_ROUTING 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1000@nshplpbx1.unix) State ROUTING 2009-11-03 15:39:50.800189 [DEBUG] mod_sofia.c:130 sofia/internal/1000@nshplpbx1.unix SOFIA ROUTING 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:78 sofia/internal/1000@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/1000@nshplpbx1.unix parsing [default->unloop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@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/1000@nshplpbx1.unix Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(open=true) Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [global-intercept] destination_number(1008) =~ /^886$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [group-intercept] destination_number(1008) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [intercept-ext] destination_number(1008) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->redial] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [redial] destination_number(1008) =~ /^870$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->global] continue=true Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@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/1000@nshplpbx1.unix Absolute Condition [global] Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [snom-demo-2] destination_number(1008) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [snom-demo-1] destination_number(1008) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^88(.*)$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^779$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call_return] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call_return] destination_number(1008) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->del-group] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [del-group] destination_number(1008) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->add-group] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [add-group] destination_number(1008) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call-group-simo] destination_number(1008) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call-group-order] destination_number(1008) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [extension-intercom] destination_number(1008) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (PASS) [Local_Extension] destination_number(1008) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(dialed_extension=1008) Dialplan: sofia/internal/1000@nshplpbx1.unix Action export(dialed_extension=1008) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1000@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/1000@nshplpbx1.unix Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(ringback=${us-ring}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(call_timeout=30) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action answer() Dialplan: sofia/internal/1000@nshplpbx1.unix Action sleep(1000) Dialplan: sofia/internal/1000@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/1000@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/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1000@nshplpbx1.unix) State ROUTING going to sleep 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:340 (sofia/internal/1000@nshplpbx1.unix) State EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] mod_sofia.c:173 sofia/internal/1000@nshplpbx1.unix SOFIA EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:151 sofia/internal/1000@nshplpbx1.unix Standard EXECUTE EXECUTE sofia/internal/1000@nshplpbx1.unix set(open=true) 2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [open]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-spymap/1000/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/1000/1008) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/global/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix set(dialed_extension=1008) 2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [dialed_extension]=[1008] EXECUTE sofia/internal/1000@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/1000@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/1000@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/1000@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/1000@nshplpbx1.unix set(ringback=%(2000,4000,440.0,480.0)) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [ringback]=[%(2000,4000,440.0,480.0)] EXECUTE sofia/internal/1000@nshplpbx1.unix set(transfer_ringback=local_stream://moh) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1000@nshplpbx1.unix set(call_timeout=30) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [call_timeout]=[30] EXECUTE sofia/internal/1000@nshplpbx1.unix set(hangup_after_bridge=true) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix set(continue_on_fail=true) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [continue_on_fail]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-call_return/1008/1000) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial_ext/1008/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix set(called_party_callgroup=techsupport) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/techsupport/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix bridge(user/1008@10.85.0.53) 2009-11-03 15:39:50.812162 [DEBUG] switch_ivr_originate.c:1333 variable string 0 = [presence_id=1008@10.85.0.53] 2009-11-03 15:39:50.812162 [NOTICE] switch_channel.c:613 New Channel sofia/internal/sip:1008@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:1008@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:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.812162 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060) State INIT 2009-11-03 15:39:50.812162 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA INIT 2009-11-03 15:39:50.812162 [DEBUG] sofia_glue.c:1761 sip:1008@10.86.11.50:51061;user=phone;transport=udp Setting proxy route to sofia/internal/sip:1008@10.86.11.50:5060 2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:111 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.814226 [DEBUG] sofia.c:3588 Channel sofia/internal/sip:1008@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:1008@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:1008@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:1008@10.86.11.50:5060) State ROUTING 2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:130 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA ROUTING 2009-11-03 15:39:50.814226 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/sip:1008@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:1008@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:1008@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:1008@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:1008@10.86.11.50:5060 entering state [terminated][503] 2009-11-03 15:39:50.817484 [NOTICE] sofia.c:4187 Hangup sofia/internal/sip:1008@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:1008@10.86.11.50:5060 [KILL] 2009-11-03 15:39:50.817484 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@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/1000@nshplpbx1.unix answer() 2009-11-03 15:39:50.817484 [DEBUG] mod_dptools.c:653 sofia/internal/1000@nshplpbx1.unix receive message [ANSWER] 2009-11-03 15:39:50.817484 [DEBUG] sofia_glue.c:2336 AUDIO RTP [sofia/internal/1000@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:1008@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:1008@10.86.11.50:5060) State HANGUP 2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:329 sofia/internal/sip:1008@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:1008@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:1008@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:1008@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:1008@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:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060) State REPORTING 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1008@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:1008@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:1008@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:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1140 Session 32 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060) Ended 2009-11-03 15:39:50.818924 [NOTICE] switch_core_session.c:1160 Close Channel sofia/internal/sip:1008@10.86.11.50:5060 [CS_DESTROY] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1008@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:1008@10.86.11.50:5060) State DESTROY 2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:278 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1008@10.86.11.50:5060 Standard DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/sip:1008@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/1000@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/1000@nshplpbx1.unix entering state [completed][200] 2009-11-03 15:39:50.821960 [DEBUG] switch_core_session.c:664 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.821960 [NOTICE] mod_dptools.c:653 Channel [sofia/internal/1000@nshplpbx1.unix] has been answered 2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182 sofia/internal/1000@nshplpbx1.unix receive message [AUDIO_SYNC] EXECUTE sofia/internal/1000@nshplpbx1.unix sleep(1000) 2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182 sofia/internal/1000@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/1000@nshplpbx1.unix entering state [ready][200] EXECUTE sofia/internal/1000@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/1000@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 L16@8000hz 1 channels 20ms 2009-11-03 15:39:51.961607 [DEBUG] switch_core_io.c:660 sofia/internal/1000@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 L16@8000hz 1 channels 20ms 2009-11-03 15:39:53.439693 [DEBUG] switch_core_io.c:660 sofia/internal/1000@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 L16@8000hz 1 channels 20ms 2009-11-03 15:39:53.899622 [DEBUG] switch_core_io.c:660 sofia/internal/1000@nshplpbx1.unix receive message [TRANSCODING_NECESSARY] 2009-11-03 15:39:54.127652 [NOTICE] sofia.c:328 Hangup sofia/internal/1000@nshplpbx1.unix [CS_EXECUTE] [NORMAL_CLEARING] 2009-11-03 15:39:54.127652 [DEBUG] switch_channel.c:1896 Send signal sofia/internal/1000@nshplpbx1.unix [KILL] 2009-11-03 15:39:54.127652 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@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/1000@nshplpbx1.unix) State EXECUTE going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_HANGUP 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@nshplpbx1.unix) State HANGUP 2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:329 sofia/internal/1000@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/1000@nshplpbx1.unix hanging up, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1000@nshplpbx1.unix Standard HANGUP, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@nshplpbx1.unix) State HANGUP going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1000@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/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_REPORTING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1000@nshplpbx1.unix) State REPORTING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1000@nshplpbx1.unix Standard REPORTING, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1000@nshplpbx1.unix) State REPORTING going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:319 (sofia/internal/1000@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/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1140 Session 31 (sofia/internal/1000@nshplpbx1.unix) Locked, Waiting on external entities 2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1158 Session 31 (sofia/internal/1000@nshplpbx1.unix) Ended 2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1160 Close Channel sofia/internal/1000@nshplpbx1.unix [CS_DESTROY] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/1000@nshplpbx1.unix) State DESTROY 2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:278 sofia/internal/1000@nshplpbx1.unix SOFIA DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@nshplpbx1.unix Standard DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/1000@nshplpbx1.unix) State DESTROY going to sleep ]0;root@NSHPLPBX1:/usr/local/freeswitch/log[root@NSHPLPBX1 log]#