We're using Erlang to serve up the configurations to Freeswitch. I've got things configured such that I can place a call from a SIP phone registered to extension 5000 to our "external" SIP provider (our Asterisk installation), but I can't place a call to extension 5001 from 5000. Below is the trace log Freeswitch produces when I attempt to do so. Any suggestions as to what I should be looking at? The directory seems to be getting served up correctly, as it provides the passwords both SIP softphones are using to register with Freeswitch. I'd have thought that once they've registered with FS, the extension would automatically be recognized when an incoming call is placed or bridged, but such does not seem to be the case. 2010-02-09 12:43:10.394647 [NOTICE] switch_channel.c:660 New Channel sofia/external/5000@testsrv.marketel [9854f2ea-cf04-4a48-a560-467cbd86bb1d] 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_NEW 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:322 (sofia/external/5000@testsrv.marketel) State NEW 2010-02-09 12:43:10.394647 [DEBUG] sofia.c:4019 Channel sofia/external/5000@testsrv.marketel entering state [received][100] 2010-02-09 12:43:10.394647 [DEBUG] sofia.c:4030 Remote SDP: v=0 o=- 4197664938 0 IN IP4 10.77.0.126 s=SIPPER for phoner c=IN IP4 10.77.0.126 t=0 0 m=audio 5062 RTP/AVP 8 0 2 3 97 9 111 112 113 114 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:9 G722/8000 a=rtpmap:111 speex/16000 a=rtpmap:112 G726-16/8000 a=rtpmap:113 G726-24/8000 a=rtpmap:114 G726-40/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2010-02-09 12:43:10.394647 [DEBUG] sofia_glue.c:3388 Audio Codec Compare [PCMA:8:8000:20]/[PCMU:0:8000:20] 2010-02-09 12:43:10.394647 [DEBUG] sofia_glue.c:3388 Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:20] 2010-02-09 12:43:10.394647 [DEBUG] sofia_glue.c:2211 Set Codec sofia/external/5000@testsrv.marketel PCMA/8000 20 ms 160 samples 2010-02-09 12:43:10.394647 [DEBUG] sofia_glue.c:3344 Set 2833 dtmf payload to 101 2010-02-09 12:43:10.394647 [DEBUG] sofia.c:4178 (sofia/external/5000@testsrv.marketel) State Change CS_NEW -> CS_INIT 2010-02-09 12:43:10.394647 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_INIT 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:340 (sofia/external/5000@testsrv.marketel) State INIT 2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:83 sofia/external/5000@testsrv.marketel SOFIA INIT 2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:111 (sofia/external/5000@testsrv.marketel) State Change CS_INIT -> CS_ROUTING 2010-02-09 12:43:10.394647 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:340 (sofia/external/5000@testsrv.marketel) State INIT going to sleep 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_ROUTING 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:343 (sofia/external/5000@testsrv.marketel) State ROUTING 2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:132 sofia/external/5000@testsrv.marketel SOFIA ROUTING 2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:78 sofia/external/5000@testsrv.marketel Standard ROUTING 2010-02-09 12:43:10.394647 [INFO] mod_dialplan_xml.c:408 Processing MSS Testing->5001 in context public 2010-02-09 12:43:10.394647 [DEBUG] mod_erlang_event.c:387 looking for bindings 2010-02-09 12:43:10.394647 [DEBUG] mod_erlang_event.c:403 binding for (null) in section dialplan with key (null) and value (null) requested from node pursuit@testsrv 2010-02-09 12:43:10.406527 [DEBUG] handle_msg.c:191 Found waiting slot for 7077ba5c-0aae-44fd-87fd-e7aa48f62659 2010-02-09 12:43:10.406527 [DEBUG] mod_erlang_event.c:456 got data <document type="freeswitch/xml"> <section name="dialplan" description="Dial Plan For FreeSwitch"> <context name="public"> <extension name="Operator"> <condition field="destination_number" expression="^(0)$"> <action application="bridge" data="sofia/external/160@rats.marketel"/> </condition> </extension> <extension name="InternalFS"> <condition field="destination_number" expression="^(\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@testsrv.marketel"/> </condition> </extension> <extension name="RatsExtension"> <condition field="destination_number" expression="^(\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="LocalCall"> <condition field="destination_number" expression="^(9\d\d\d\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="LongDistanceCall"> <condition field="destination_number" expression="^91(\d\d\d\d\d\d\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="DialerConference"> <condition field="destination_number" expression="^8(\d\d\d)$"> <action application="conference" data="conf$0@dialer"/> </condition> </extension> </context> <context name="default"> <extension name="InternalFS"> <condition field="destination_number" expression="^(\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@testsrv.marketel"/> </condition> </extension> <extension name="RatsExtension"> <condition field="destination_number" expression="^(\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="LocalCall"> <condition field="destination_number" expression="^(9\d\d\d\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="LongDistanceCall"> <condition field="destination_number" expression="^91(\d\d\d\d\d\d\d\d\d\d)$"> <action application="bridge" data="sofia/external/$0@rats.marketel"/> </condition> </extension> <extension name="DialerConference"> <condition field="destination_number" expression="^8(\d\d\d)$"> <action application="conference" data="conf$0@dialer"/> </condition> </extension> </context> </section> </document> after 10 milliseconds! 2010-02-09 12:43:10.406527 [DEBUG] mod_erlang_event.c:463 XML parsed OK! Dialplan: sofia/external/5000@testsrv.marketel parsing [public->Operator] continue=false Dialplan: sofia/external/5000@testsrv.marketel Regex (FAIL) [Operator] destination_number(5001) =~ /^(0)$/ break=on-false Dialplan: sofia/external/5000@testsrv.marketel parsing [public->InternalFS] continue=false Dialplan: sofia/external/5000@testsrv.marketel Regex (PASS) [InternalFS] destination_number(5001) =~ /^(\d\d\d\d)$/ break=on-false Dialplan: sofia/external/5000@testsrv.marketel Action bridge(sofia/external/5001@testsrv.marketel) 2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:122 (sofia/external/5000@testsrv.marketel) State Change CS_ROUTING -> CS_EXECUTE 2010-02-09 12:43:10.406527 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:343 (sofia/external/5000@testsrv.marketel) State ROUTING going to sleep 2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_EXECUTE 2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:350 (sofia/external/5000@testsrv.marketel) State EXECUTE 2010-02-09 12:43:10.406527 [DEBUG] mod_sofia.c:181 sofia/external/5000@testsrv.marketel SOFIA EXECUTE 2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:159 sofia/external/5000@testsrv.marketel Standard EXECUTE EXECUTE sofia/external/5000@testsrv.marketel bridge(sofia/external/5001@testsrv.marketel) 2010-02-09 12:43:10.406527 [NOTICE] switch_channel.c:660 New Channel sofia/external/5001@testsrv.marketel [813c2e55-8acf-486d-b3b6-3244edf5529a] 2010-02-09 12:43:10.406527 [DEBUG] mod_sofia.c:3317 (sofia/external/5001@testsrv.marketel) State Change CS_NEW -> CS_INIT 2010-02-09 12:43:10.406527 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5001@testsrv.marketel) Running State Change CS_INIT 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:340 (sofia/external/5001@testsrv.marketel) State INIT 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:83 sofia/external/5001@testsrv.marketel SOFIA INIT 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:111 (sofia/external/5001@testsrv.marketel) State Change CS_INIT -> CS_ROUTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:340 (sofia/external/5001@testsrv.marketel) State INIT going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5001@testsrv.marketel) Running State Change CS_ROUTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:343 (sofia/external/5001@testsrv.marketel) State ROUTING 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:132 sofia/external/5001@testsrv.marketel SOFIA ROUTING 2010-02-09 12:43:10.414137 [DEBUG] switch_ivr_originate.c:66 (sofia/external/5001@testsrv.marketel) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:343 (sofia/external/5001@testsrv.marketel) State ROUTING going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5001@testsrv.marketel) Running State Change CS_CONSUME_MEDIA 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:362 (sofia/external/5001@testsrv.marketel) State CONSUME_MEDIA 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:362 (sofia/external/5001@testsrv.marketel) State CONSUME_MEDIA going to sleep 2010-02-09 12:43:10.414137 [DEBUG] sofia.c:4019 Channel sofia/external/5001@testsrv.marketel entering state [calling][0] 2010-02-09 12:43:10.414137 [DEBUG] sofia.c:4019 Channel sofia/external/5001@testsrv.marketel entering state [terminated][503] 2010-02-09 12:43:10.414137 [NOTICE] sofia.c:4663 Hangup sofia/external/5001@testsrv.marketel [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-02-09 12:43:10.414137 [DEBUG] switch_ivr_originate.c:3209 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] 2010-02-09 12:43:10.414137 [DEBUG] switch_channel.c:1994 Send signal sofia/external/5001@testsrv.marketel [KILL] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5001@testsrv.marketel) Running State Change CS_HANGUP 2010-02-09 12:43:10.414137 [INFO] mod_dptools.c:2346 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [NOTICE] mod_dptools.c:2409 Hangup sofia/external/5000@testsrv.marketel [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE] 2010-02-09 12:43:10.414137 [DEBUG] switch_channel.c:1994 Send signal sofia/external/5000@testsrv.marketel [KILL] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:350 (sofia/external/5000@testsrv.marketel) State EXECUTE going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 (sofia/external/5001@testsrv.marketel) State HANGUP 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_HANGUP 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:352 sofia/external/5001@testsrv.marketel Overriding SIP cause 503 with 503 from the other leg 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:358 Channel sofia/external/5001@testsrv.marketel hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:46 sofia/external/5001@testsrv.marketel Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 (sofia/external/5001@testsrv.marketel) State HANGUP going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:335 (sofia/external/5001@testsrv.marketel) State Change CS_HANGUP -> CS_REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5001@testsrv.marketel) Running State Change CS_REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 (sofia/external/5001@testsrv.marketel) State REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:53 sofia/external/5001@testsrv.marketel Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 (sofia/external/5001@testsrv.marketel) State REPORTING going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:329 (sofia/external/5001@testsrv.marketel) State Change CS_REPORTING -> CS_DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5001@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1161 Session 18 (sofia/external/5001@testsrv.marketel) Locked, Waiting on external entities 2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1179 Session 18 (sofia/external/5001@testsrv.marketel) Ended 2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1181 Close Channel sofia/external/5001@testsrv.marketel [CS_DESTROY] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:425 (sofia/external/5001@testsrv.marketel) Running State Change CS_DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 (sofia/external/5001@testsrv.marketel) State DESTROY 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:293 sofia/external/5001@testsrv.marketel SOFIA DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:60 sofia/external/5001@testsrv.marketel Standard DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 (sofia/external/5001@testsrv.marketel) State DESTROY going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 (sofia/external/5000@testsrv.marketel) State HANGUP 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:352 sofia/external/5000@testsrv.marketel Overriding SIP cause 503 with 503 from the other leg 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:358 Channel sofia/external/5000@testsrv.marketel hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:424 Responding to INVITE with: 503 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:46 sofia/external/5000@testsrv.marketel Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 (sofia/external/5000@testsrv.marketel) State HANGUP going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:335 (sofia/external/5000@testsrv.marketel) State Change CS_HANGUP -> CS_REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 (sofia/external/5000@testsrv.marketel) Running State Change CS_REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 (sofia/external/5000@testsrv.marketel) State REPORTING 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:53 sofia/external/5000@testsrv.marketel Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 (sofia/external/5000@testsrv.marketel) State REPORTING going to sleep 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:329 (sofia/external/5000@testsrv.marketel) State Change CS_REPORTING -> CS_DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send signal sofia/external/5000@testsrv.marketel [BREAK] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1161 Session 17 (sofia/external/5000@testsrv.marketel) Locked, Waiting on external entities 2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1179 Session 17 (sofia/external/5000@testsrv.marketel) Ended 2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1181 Close Channel sofia/external/5000@testsrv.marketel [CS_DESTROY] 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:425 (sofia/external/5000@testsrv.marketel) Running State Change CS_DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 (sofia/external/5000@testsrv.marketel) State DESTROY 2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:293 sofia/external/5000@testsrv.marketel SOFIA DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:60 sofia/external/5000@testsrv.marketel Standard DESTROY 2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 (sofia/external/5000@testsrv.marketel) State DESTROY going to sleep -- Mark Sobkow Senior Developer MarkeTel Multi-Line Dialing Systems LTD. 428 Victoria Ave Regina, SK S4N-0P6 Toll-Free: 800-289-8616-X533 Local: 306-359-6893-X533 Fax: 306-359-6879 Email: m.sobkow@marketelsystems.com Web: http://www.marketelsystems.com