[Freeswitch-users] Having trouble establishing a call

Tue Feb 9 10:46:54 PST 2010

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 at testsrv.marketel [9854f2ea-cf04-4a48-a560-467cbd86bb1d]
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_NEW
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:322 
(sofia/external/5000 at testsrv.marketel) State NEW
2010-02-09 12:43:10.394647 [DEBUG] sofia.c:4019 Channel 
sofia/external/5000 at 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 at 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 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_INIT
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:340 
(sofia/external/5000 at testsrv.marketel) State INIT
2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:83 
sofia/external/5000 at testsrv.marketel SOFIA INIT
2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:111 
(sofia/external/5000 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:340 
(sofia/external/5000 at testsrv.marketel) State INIT going to sleep
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_ROUTING
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:343 
(sofia/external/5000 at testsrv.marketel) State ROUTING
2010-02-09 12:43:10.394647 [DEBUG] mod_sofia.c:132 
sofia/external/5000 at testsrv.marketel SOFIA ROUTING
2010-02-09 12:43:10.394647 [DEBUG] switch_core_state_machine.c:78 
sofia/external/5000 at 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 at 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 at rats.marketel"/>
        </condition>
      </extension>
      <extension name="InternalFS">
        <condition field="destination_number" expression="^(\d\d\d\d)$">
          <action application="bridge" 
data="sofia/external/$0 at testsrv.marketel"/>
        </condition>
      </extension>
      <extension name="RatsExtension">
        <condition field="destination_number" expression="^(\d\d\d)$">
          <action application="bridge" 
data="sofia/external/$0 at 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 at 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 at rats.marketel"/>
        </condition>
      </extension>
      <extension name="DialerConference">
        <condition field="destination_number" expression="^8(\d\d\d)$">
          <action application="conference" data="conf$0 at 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 at testsrv.marketel"/>
        </condition>
      </extension>
      <extension name="RatsExtension">
        <condition field="destination_number" expression="^(\d\d\d)$">
          <action application="bridge" 
data="sofia/external/$0 at 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 at 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 at rats.marketel"/>
        </condition>
      </extension>
      <extension name="DialerConference">
        <condition field="destination_number" expression="^8(\d\d\d)$">
          <action application="conference" data="conf$0 at 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 at testsrv.marketel parsing 
[public->Operator] continue=false
Dialplan: sofia/external/5000 at testsrv.marketel Regex (FAIL) [Operator] 
destination_number(5001) =~ /^(0)$/ break=on-false
Dialplan: sofia/external/5000 at testsrv.marketel parsing 
[public->InternalFS] continue=false
Dialplan: sofia/external/5000 at testsrv.marketel Regex (PASS) [InternalFS] 
destination_number(5001) =~ /^(\d\d\d\d)$/ break=on-false
Dialplan: sofia/external/5000 at testsrv.marketel Action 
bridge(sofia/external/5001 at testsrv.marketel)
2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:122 
(sofia/external/5000 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:343 
(sofia/external/5000 at testsrv.marketel) State ROUTING going to sleep
2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_EXECUTE
2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:350 
(sofia/external/5000 at testsrv.marketel) State EXECUTE
2010-02-09 12:43:10.406527 [DEBUG] mod_sofia.c:181 
sofia/external/5000 at testsrv.marketel SOFIA EXECUTE
2010-02-09 12:43:10.406527 [DEBUG] switch_core_state_machine.c:159 
sofia/external/5000 at testsrv.marketel Standard EXECUTE
EXECUTE sofia/external/5000 at testsrv.marketel 
bridge(sofia/external/5001 at testsrv.marketel)
2010-02-09 12:43:10.406527 [NOTICE] switch_channel.c:660 New Channel 
sofia/external/5001 at testsrv.marketel [813c2e55-8acf-486d-b3b6-3244edf5529a]
2010-02-09 12:43:10.406527 [DEBUG] mod_sofia.c:3317 
(sofia/external/5001 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5001 at testsrv.marketel) Running State Change CS_INIT
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:340 
(sofia/external/5001 at testsrv.marketel) State INIT
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:83 
sofia/external/5001 at testsrv.marketel SOFIA INIT
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:111 
(sofia/external/5001 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:340 
(sofia/external/5001 at testsrv.marketel) State INIT going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5001 at testsrv.marketel) Running State Change CS_ROUTING
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:343 
(sofia/external/5001 at testsrv.marketel) State ROUTING
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:132 
sofia/external/5001 at testsrv.marketel SOFIA ROUTING
2010-02-09 12:43:10.414137 [DEBUG] switch_ivr_originate.c:66 
(sofia/external/5001 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:343 
(sofia/external/5001 at testsrv.marketel) State ROUTING going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5001 at 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 at testsrv.marketel) State CONSUME_MEDIA
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:362 
(sofia/external/5001 at testsrv.marketel) State CONSUME_MEDIA going to sleep
2010-02-09 12:43:10.414137 [DEBUG] sofia.c:4019 Channel 
sofia/external/5001 at testsrv.marketel entering state [calling][0]
2010-02-09 12:43:10.414137 [DEBUG] sofia.c:4019 Channel 
sofia/external/5001 at testsrv.marketel entering state [terminated][503]
2010-02-09 12:43:10.414137 [NOTICE] sofia.c:4663 Hangup 
sofia/external/5001 at 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 at testsrv.marketel [KILL]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5001 at 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 at testsrv.marketel [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2010-02-09 12:43:10.414137 [DEBUG] switch_channel.c:1994 Send signal 
sofia/external/5000 at testsrv.marketel [KILL]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1019 Send 
signal sofia/external/5000 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:350 
(sofia/external/5000 at testsrv.marketel) State EXECUTE going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 
(sofia/external/5001 at testsrv.marketel) State HANGUP
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:352 
sofia/external/5001 at 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 at 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 at 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 at testsrv.marketel) State HANGUP going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:335 
(sofia/external/5001 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5001 at testsrv.marketel) Running State Change CS_REPORTING
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 
(sofia/external/5001 at testsrv.marketel) State REPORTING
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:53 
sofia/external/5001 at 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 at testsrv.marketel) State REPORTING going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:329 
(sofia/external/5001 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1161 Session 18 
(sofia/external/5001 at 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 at testsrv.marketel) Ended
2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1181 Close 
Channel sofia/external/5001 at testsrv.marketel [CS_DESTROY]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:425 
(sofia/external/5001 at testsrv.marketel) Running State Change CS_DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 
(sofia/external/5001 at testsrv.marketel) State DESTROY
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:293 
sofia/external/5001 at testsrv.marketel SOFIA DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:60 
sofia/external/5001 at testsrv.marketel Standard DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 
(sofia/external/5001 at testsrv.marketel) State DESTROY going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:496 
(sofia/external/5000 at testsrv.marketel) State HANGUP
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:352 
sofia/external/5000 at 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 at 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 at 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 at testsrv.marketel) State HANGUP going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:335 
(sofia/external/5000 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:316 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_REPORTING
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:587 
(sofia/external/5000 at testsrv.marketel) State REPORTING
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:53 
sofia/external/5000 at 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 at testsrv.marketel) State REPORTING going to sleep
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:329 
(sofia/external/5000 at 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 at testsrv.marketel [BREAK]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_session.c:1161 Session 17 
(sofia/external/5000 at 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 at testsrv.marketel) Ended
2010-02-09 12:43:10.414137 [NOTICE] switch_core_session.c:1181 Close 
Channel sofia/external/5000 at testsrv.marketel [CS_DESTROY]
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:425 
(sofia/external/5000 at testsrv.marketel) Running State Change CS_DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 
(sofia/external/5000 at testsrv.marketel) State DESTROY
2010-02-09 12:43:10.414137 [DEBUG] mod_sofia.c:293 
sofia/external/5000 at testsrv.marketel SOFIA DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:60 
sofia/external/5000 at testsrv.marketel Standard DESTROY
2010-02-09 12:43:10.414137 [DEBUG] switch_core_state_machine.c:436 
(sofia/external/5000 at 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 at marketelsystems.com
Web: http://www.marketelsystems.com 