Freeswitch incoming calls not ringing



  • pfsense 1.2.3-RC1
    freeswitch 0.8.6.1

    In the public tab I have

    
    condition  destination_number   ^(1780xxxxxxx)$ 
    action       transfer                 1001 XML default   
    
    

    The status tab shows that my ATA is registered on extension 1001, but when I tried calling in I got a busy signal. I had not set up any extensions yet.

    I then set up an extention 1001 with password 1234 (I thought this existed in a fresh setup?). Now when I call in I hear "The person at extension [pause] is not available…" I left a message but did not receive an email, although I set up emailing.

    This from the log right after calling in and hearing the message.

    2009-05-13 17:47:43 [DEBUG] sofia_glue.c:2939 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000:0]/[PCMU:0:8000:20]
    2009-05-13 17:47:43 [DEBUG] sofia_glue.c:1912 sofia_glue_tech_set_codec() Set Codec sofia/external/780xxxxx40@66.51.127.163 PCMU/8000 20 ms 160 samples
    2009-05-13 17:47:43 [DEBUG] sofia_glue.c:2899 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
    2009-05-13 17:47:43 [DEBUG] sofia.c:3081 sofia_handle_sip_i_state() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_NEW -> CS_INIT
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_INIT
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State INIT
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/external/780xxxxx40@66.51.127.163 SOFIA INIT
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_INIT -> CS_ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State INIT going to sleep
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State ROUTING
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/external/780xxxxx40@66.51.127.163 SOFIA ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:78 switch_core_standard_on_routing() sofia/external/780xxxxx40@66.51.127.163 Standard ROUTING
    2009-05-13 17:47:43 [INFO] mod_dialplan_xml.c:252 dialplan_hunt() Processing 780xxxxx40->1780xxxxx86 in context public
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [public->unloop] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [public->outside_call] continue=true
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Absolute Condition [outside_call]
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(outside_call=true)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [public->call_debug] continue=true
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [public->public_extensions] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [public_extensions] destination_number(1780xxxxx86) =~ /^(10[01][0-9])$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [public->1001] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [1001] destination_number(1780xxxxx86) =~ /^(1780xxxxx86)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action transfer(1001 XML default)
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:114 switch_core_standard_on_routing() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_ROUTING -> CS_EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State ROUTING going to sleep
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State EXECUTE
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:173 sofia_on_execute() sofia/external/780xxxxx40@66.51.127.163 SOFIA EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:151 switch_core_standard_on_execute() sofia/external/780xxxxx40@66.51.127.163 Standard EXECUTE
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(outside_call=true)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [outside_call]=[true]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 transfer(1001 XML default)
    2009-05-13 17:47:43 [DEBUG] switch_ivr.c:1342 switch_ivr_session_transfer() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_EXECUTE -> CS_ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [DEBUG] switch_ivr.c:1346 switch_ivr_session_transfer() sofia/external/780xxxxx40@66.51.127.163 receive message [TRANSFER]
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [NOTICE] switch_ivr.c:1348 switch_ivr_session_transfer() Transfer sofia/external/780xxxxx40@66.51.127.163 to XML[1001@default]
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State EXECUTE going to sleep
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State ROUTING
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/external/780xxxxx40@66.51.127.163 SOFIA ROUTING
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:78 switch_core_standard_on_routing() sofia/external/780xxxxx40@66.51.127.163 Standard ROUTING
    2009-05-13 17:47:43 [INFO] mod_dialplan_xml.c:252 dialplan_hunt() Processing 780xxxxx40->1001 in context default
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->unloop] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->tod_example] continue=true
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [tod_example] ${strftime(%w)}(3) =~ /^([1-5])$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [tod_example] ${strftime(%H%M)}(1747) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(open=true)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->global-intercept] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^\*886$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->group-intercept] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->intercept-ext] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->redial] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [redial] destination_number(1001) =~ /^\*870$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->global] continue=true
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global] ${network_addr}(66.51.127.173) =~ /^$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 ANTI-Action set(use_profile=${cond(${acl(${network_addr} rfc1918)} == true ? nat : default)})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [global] ${numbering_plan}() =~ /^$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set_user(default@${domain_name})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global] ${sip_secure_media}() =~ /^true$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [global] ${sip_user_agent}(Link2VoIP) =~ /^PolycomSound(Point|Station)IP-S(S|P)IP_\d{3,4}-UA\/((3).(\d).(\d).(\d{4}))$/ break=never
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Absolute Condition [global]
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-last_dial/global/${uuid})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->snom-demo-2] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^\*9001$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->snom-demo-1] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^\*9000$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->eavesdrop] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^\*88(.*)$|^\*0(.*)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->eavesdrop] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^\*779$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->call_return] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->del-group] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [del-group] destination_number(1001) =~ /^\*80(\d{2})$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->add-group] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [add-group] destination_number(1001) =~ /^\*81(\d{2})$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->call-group-simo] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^\*82(\d{2})$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->call-group-order] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^\*83(\d{2})$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->extension-intercom] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^\*8(10[01][0-9])$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->pizza_demo] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [pizza_demo] destination_number(1001) =~ /^(pizza|74992)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->Recordings] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [Recordings] destination_number(1001) =~ /^\*(732673)$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->sip.ca1.link2voip.com.11d] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (FAIL) [sip.ca1.link2voip.com.11d] destination_number(1001) =~ /^(\d{11})$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 parsing [default->Local_Extension] continue=false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(dialed_extension=1001)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action export(dialed_extension=1001)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action bind_meta_app(1 b s execute_extension::dx XML features)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 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/external/780xxxxx40@66.51.127.163 Action bind_meta_app(3 b s execute_extension::cf XML features)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(ringback=${us-ring})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(transfer_ringback=local_stream://moh)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(call_timeout=30)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(hangup_after_bridge=true)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(continue_on_fail=true)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action bridge(user/${dialed_extension}@${domain_name})
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action answer()
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action sleep(1000)
    Dialplan: sofia/external/780xxxxx40@66.51.127.163 Action voicemail(default ${domain_name} ${dialed_extension})
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:114 switch_core_standard_on_routing() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_ROUTING -> CS_EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State ROUTING going to sleep
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State EXECUTE
    2009-05-13 17:47:43 [DEBUG] mod_sofia.c:173 sofia_on_execute() sofia/external/780xxxxx40@66.51.127.163 SOFIA EXECUTE
    2009-05-13 17:47:43 [DEBUG] switch_core_state_machine.c:151 switch_core_standard_on_execute() sofia/external/780xxxxx40@66.51.127.163 Standard EXECUTE
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(open=true)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [open]=[true]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(use_profile=default)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [use_profile]=[default]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set_user(default@)
    2009-05-13 17:47:43 [WARNING] switch_ivr.c:2045 switch_ivr_set_user() can't find user [default@]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-spymap/780xxxxx40/460e5a29-e63f-de11-acaa-000024cbeb68)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-last_dial/780xxxxx40/1001)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-last_dial/global/460e5a29-e63f-de11-acaa-000024cbeb68)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(dialed_extension=1001)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [dialed_extension]=[1001]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 export(dialed_extension=1001)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:886 export_function() EXPORT [dialed_extension]=[1001]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 bind_meta_app(1 b s execute_extension::dx XML features)
    2009-05-13 17:47:43 [INFO] switch_ivr_async.c:1770 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 1 execute_extension::dx XML features
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/780xxxxx40.2009-05-13-17-47-43.wav)
    2009-05-13 17:47:43 [INFO] switch_ivr_async.c:1770 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 2 record_session::/usr/local/freeswitch/recordings/780xxxxx40.2009-05-13-17-47-43.wav
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 bind_meta_app(3 b s execute_extension::cf XML features)
    2009-05-13 17:47:43 [INFO] switch_ivr_async.c:1770 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 3 execute_extension::cf XML features
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(ringback=%(2000, 4000, 440.0, 480.0))
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(transfer_ringback=local_stream://moh)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [transfer_ringback]=[local_stream://moh]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(call_timeout=30)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [call_timeout]=[30]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(hangup_after_bridge=true)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [hangup_after_bridge]=[true]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(continue_on_fail=true)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [continue_on_fail]=[true]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-call_return/1001/780xxxxx40)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-last_dial_ext/1001/460e5a29-e63f-de11-acaa-000024cbeb68)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 set(called_party_callgroup=)
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:748 set_function() sofia/external/780xxxxx40@66.51.127.163 SET [called_party_callgroup]=[UNDEF]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 hash(insert/-last_dial//460e5a29-e63f-de11-acaa-000024cbeb68)
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 bridge(user/1001@)
    2009-05-13 17:47:43 [WARNING] mod_dptools.c:2318 user_outgoing_channel() Can't find user [1001@]
    2009-05-13 17:47:43 [ERR] switch_ivr_originate.c:1495 switch_ivr_originate() Cannot create outgoing channel of type [user] cause: [SUBSCRIBER_ABSENT]
    2009-05-13 17:47:43 [DEBUG] switch_ivr_originate.c:2094 switch_ivr_originate() Originate Resulted in Error Cause: 20 [SUBSCRIBER_ABSENT]
    2009-05-13 17:47:43 [INFO] mod_dptools.c:2074 audio_bridge_function() Originate Failed.  Cause: SUBSCRIBER_ABSENT
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:2101 audio_bridge_function() Continue on fail [true]:  Cause: SUBSCRIBER_ABSENT
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 answer()
    2009-05-13 17:47:43 [DEBUG] mod_dptools.c:649 answer_function() sofia/external/780xxxxx40@66.51.127.163 receive message [ANSWER]
    2009-05-13 17:47:44 [DEBUG] sofia_glue.c:583 sofia_glue_ext_address_lookup() STUN Success [75.159.x.x]:[19512]
    2009-05-13 17:47:44 [DEBUG] sofia_glue.c:587 sofia_glue_ext_address_lookup() STUN Not Required ip and port match. [75.159.x.x]:[19512]
    2009-05-13 17:47:44 [DEBUG] sofia_glue.c:2146 sofia_glue_activate_rtp() AUDIO RTP [sofia/external/780xxxxx40@66.51.127.163] 75.159.x.x port 19512 -> 66.51.127.163 port 54296 codec: 0 ms: 20
    2009-05-13 17:47:44 [DEBUG] switch_rtp.c:906 switch_rtp_create() Starting timer [soft] 160 bytes per 20ms
    2009-05-13 17:47:44 [DEBUG] mod_sofia.c:534 sofia_answer_channel() Local SDP sofia/external/780xxxxx40@66.51.127.163:
    v=0
    o=FreeSWITCH 1242217352 1242217353 IN IP4 75.159.x.x
    s=FreeSWITCH
    c=IN IP4 75.159.x.x
    t=0 0
    m=audio 19512 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-05-13 17:47:44 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:44 [NOTICE] mod_dptools.c:649 answer_function() Channel [sofia/external/780xxxxx40@66.51.127.163] has been answered
    2009-05-13 17:47:44 [DEBUG] switch_channel.c:182 switch_channel_audio_sync() sofia/external/780xxxxx40@66.51.127.163 receive message [AUDIO_SYNC]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 sleep(1000)
    2009-05-13 17:47:44 [DEBUG] switch_channel.c:182 switch_channel_audio_sync() sofia/external/780xxxxx40@66.51.127.163 receive message [AUDIO_SYNC]
    2009-05-13 17:47:44 [DEBUG] sofia.c:2915 sofia_handle_sip_i_state() Channel sofia/external/780xxxxx40@66.51.127.163 entering state [completed][200]
    2009-05-13 17:47:44 [DEBUG] sofia.c:2915 sofia_handle_sip_i_state() Channel sofia/external/780xxxxx40@66.51.127.163 entering state [ready][200]
    EXECUTE sofia/external/780xxxxx40@66.51.127.163 voicemail(default  1001)
    2009-05-13 17:47:45 [DEBUG] switch_channel.c:182 switch_channel_audio_sync() sofia/external/780xxxxx40@66.51.127.163 receive message [AUDIO_SYNC]
    2009-05-13 17:47:45 [DEBUG] switch_ivr_play_say.c:118 switch_ivr_phrase_macro() No language specified - Using [en]
    2009-05-13 17:47:45 [DEBUG] switch_ivr_play_say.c:273 switch_ivr_phrase_macro() Handle play-file:[voicemail/vm-person.wav] (en:en)
    2009-05-13 17:47:45 [DEBUG] switch_ivr_play_say.c:1086 switch_ivr_play_file() Codec Activated L16@8000hz 1 channels 20ms
    2009-05-13 17:47:45 [DEBUG] switch_core_io.c:649 switch_core_session_write_frame() sofia/external/780xxxxx40@66.51.127.163 receive message [TRANSCODING_NECESSARY]
    2009-05-13 17:47:46 [DEBUG] switch_ivr_play_say.c:1381 switch_ivr_play_file() done playing file
    2009-05-13 17:47:46 [DEBUG] switch_ivr_play_say.c:273 switch_ivr_phrase_macro() Handle say:[] (en:en)
    2009-05-13 17:47:46 [DEBUG] switch_ivr_play_say.c:273 switch_ivr_phrase_macro() Handle play-file:[voicemail/vm-not_available.wav] (en:en)
    2009-05-13 17:47:46 [DEBUG] switch_ivr_play_say.c:1086 switch_ivr_play_file() Codec Activated L16@8000hz 1 channels 20ms
    2009-05-13 17:47:46 [DEBUG] switch_core_io.c:649 switch_core_session_write_frame() sofia/external/780xxxxx40@66.51.127.163 receive message [TRANSCODING_NECESSARY]
    2009-05-13 17:47:47 [DEBUG] switch_ivr_play_say.c:1381 switch_ivr_play_file() done playing file
    2009-05-13 17:47:47 [DEBUG] switch_ivr_play_say.c:118 switch_ivr_phrase_macro() No language specified - Using [en]
    2009-05-13 17:47:47 [DEBUG] switch_ivr_play_say.c:273 switch_ivr_phrase_macro() Handle play-file:[voicemail/vm-record_message.wav] (en:en)
    2009-05-13 17:47:47 [DEBUG] switch_ivr_play_say.c:1086 switch_ivr_play_file() Codec Activated L16@8000hz 1 channels 20ms
    2009-05-13 17:47:47 [DEBUG] switch_core_io.c:649 switch_core_session_write_frame() sofia/external/780xxxxx40@66.51.127.163 receive message [TRANSCODING_NECESSARY]
    2009-05-13 17:47:49 [DEBUG] sofia.c:2915 sofia_handle_sip_i_state() Channel sofia/external/780xxxxx40@66.51.127.163 entering state [terminated][200]
    2009-05-13 17:47:49 [NOTICE] sofia.c:3472 sofia_handle_sip_i_state() Hangup sofia/external/780xxxxx40@66.51.127.163 [CS_EXECUTE] [NORMAL_CLEARING]
    2009-05-13 17:47:49 [DEBUG] switch_channel.c:1641 switch_channel_perform_hangup() Send signal sofia/external/780xxxxx40@66.51.127.163 [KILL]
    2009-05-13 17:47:49 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:49 [DEBUG] switch_ivr_play_say.c:1381 switch_ivr_play_file() done playing file
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State EXECUTE going to sleep
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_HANGUP
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State HANGUP
    2009-05-13 17:47:49 [DEBUG] mod_sofia.c:291 sofia_on_hangup() sofia/external/780xxxxx40@66.51.127.163 Overriding SIP cause 480 with 200 from the other leg
    2009-05-13 17:47:49 [DEBUG] mod_sofia.c:323 sofia_on_hangup() Channel sofia/external/780xxxxx40@66.51.127.163 hanging up, cause: NORMAL_CLEARING
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/external/780xxxxx40@66.51.127.163 Standard HANGUP, cause: NORMAL_CLEARING
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State HANGUP going to sleep
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:475 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_HANGUP -> CS_REPORTING
    2009-05-13 17:47:49 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/external/780xxxxx40@66.51.127.163 [BREAK]
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) Running State Change CS_REPORTING
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/external/780xxxxx40@66.51.127.163) State REPORTING
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:53 switch_core_standard_on_reporting() sofia/external/780xxxxx40@66.51.127.163 Standard REPORTING, cause: NORMAL_CLEARING
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/external/780xxxxx40@66.51.127.163) State REPORTING going to sleep
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:410 switch_core_session_run() (sofia/external/780xxxxx40@66.51.127.163) State Change CS_REPORTING -> CS_DESTROY
    2009-05-13 17:47:49 [DEBUG] switch_core_session.c:1067 switch_core_session_thread() Session 22 (sofia/external/780xxxxx40@66.51.127.163) Locked, Waiting on external entities
    2009-05-13 17:47:49 [NOTICE] switch_core_session.c:1085 switch_core_session_thread() Session 22 (sofia/external/780xxxxx40@66.51.127.163) Ended
    2009-05-13 17:47:49 [NOTICE] switch_core_session.c:1087 switch_core_session_thread() Close Channel sofia/external/780xxxxx40@66.51.127.163 [CS_DESTROY]
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/external/780xxxxx40@66.51.127.163) State DESTROY
    2009-05-13 17:47:49 [DEBUG] mod_sofia.c:240 sofia_on_destroy() sofia/external/780xxxxx40@66.51.127.163 SOFIA DESTROY
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:60 switch_core_standard_on_destroy() sofia/external/780xxxxx40@66.51.127.163 Standard DESTROY
    2009-05-13 17:47:49 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/external/780xxxxx40@66.51.127.163) State DESTROY going to sleep
    
    


  • Try contact mcrane in #pfsense-freeswitch
    jigp
    Davao City



  • @clarknova:

    The status tab shows that my ATA is registered on extension 1001, but when I tried calling in I got a busy signal. I had not set up any extensions yet.

    I then set up an extention 1001 with password 1234 (I thought this existed in a fresh setup?). Now when I call in I hear "The person at extension [pause] is not available…" I left a message but did not receive an email, although I set up emailing.

    pfSense FreeSWITCH package new install doesn't have any extensions by default. Your phone cannot be registered if the extension does not exist. After you setup an extension you need to go to the 'Status' tab and click on 'reload xml'. Then register the phone and the check the 'Status' tab again to see if the phone is registered. Try some test calls like *98 (voicemail) *9999 (music on hold) or setup another extension and try to calling it.

    As jigpe also stated I can be reached on IRC at freenode #pfsense-freeswitch



  • Thank you both for the pointers. I have now registered two lines on my ATA as extensions 1001 and 1002. I can call either extension from the other, leave a message, and then retrieve that message. It appears the extensions are working as expected.

    However when I call into freeswitch, i.e., using my 11-digit DID, I still hear the freeswitch recording "the person at extension…is unavailable...". If I leave a message at this point it does not appear in either mailbox (1001 nor 1002).

    Interestingly, if I make changes in the public tab to direct incoming calls to a nonexistant extension, then incoming caller hears only a busy signal. It is only when the incoming call is directed to extension 1001 (I haven't tried other destinations yet) that the recording is heard.

    update: If I direct the incoming call to an ivr that I created it works. It appears that freeswitch is able to route a call to the ivr but not an extension. I downloaded the cdr and the calls to the extension (1001) and ivr (5002) look the same.

    
    7808356640	7808356640	1001	default	5/14/2009 10:19	5/14/2009 10:19	5/14/2009 10:19	4	4	NORMAL_CLEARING	467d86fd-a240-de11-b4ee-000024cbeb68			PCMU	PCMU
    7808356640	7808356640	5002	default	5/14/2009 10:11	5/14/2009 10:11	5/14/2009 10:12	18	18	NORMAL_CLEARING	54f371f1-a140-de11-b4ee-000024cbeb68			PCMU	PCMU
    
    

    The freeswitch status page shows that extensions 1001 and 1002 are registered on the lan (or internal profile, as the case may be). And as I said, I can call externally or internally from these extensions, so why aren't they receiving incoming calls?



  • Resolved. mcrane restored my vars.xml file. I had edited it in the first place, following a brief guide in my voip provider's help pages. When things got bad I removed the freeswitch package and reset pfsense to default, then reinstalled freeswitch. I didn't realize that the xml files survived this procedure, so I thought I had a clean slate when I didn't.

    Big thanks to mcrane, forum and irc users that lent a hand.


Locked