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