[Freeswitch-users] One way calling issue over an internal trunk

20 Jul 2011

      I have a connection between my FreeSWITCH and a Cisco CallManager:

This is from the default.xml

 <extension name="Dial to CM8">
      <condition field="destination_number" expression="^(800\d)$">
        <action application="bridge" data="sofia/internal/$1@172.16.200.100"/>
      </condition>
     </extension>

The phone I dial on the CallManager PBX is number 8000.  As soon as it dials it fails and spews out the debug below.  However, I can call from the CallManager to a phone on FreeSWITCH.

Can anyone give me some ideas on how to find out what's wrong?  A method of troubleshooting this issue.  I don't even see the traffic make it to the CallManager.

I've done debugs and gone through them line by line.  I can call phone to phone on the FreeSWITCH.

I'm suspecting that the FreeSWITCH is looking in the wrong area to make the call, but I'm not sure how to verify that.

Many Thanks, Mitch

2011-07-19 19:21:47.662473 [DEBUG] sofia.c:6418 IP 192.168.60.104 Approved by acl "domains[]". Access Granted.
2011-07-19 19:21:47.662473 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1002@172.16.200.60 [45a003c6-5a6b-430b-9214-a2279b4acf7e]
2011-07-19 19:21:47.664595 [DEBUG] sofia.c:4701 Channel sofia/internal/1002@172.16.200.60 entering state [received][100]
2011-07-19 19:21:47.664595 [DEBUG] sofia.c:4712 Remote SDP:
v=0
o=- 3520107294 3520107294 IN IP4 68.225.42.67
s=cpc_med
c=IN IP4 68.225.42.67
t=0 0
m=audio 18460 RTP/AVP 0 8 104 3 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15

2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:4601 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:4601 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:4601 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:4601 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:2760 Set Codec sofia/internal/1002@172.16.200.60 PCMU/8000 20 ms 160 samples 64000 bits
2011-07-19 19:21:47.664595 [DEBUG] sofia_glue.c:4713 Set 2833 dtmf send/recv payload to 96
2011-07-19 19:21:47.664595 [DEBUG] sofia.c:4879 (sofia/internal/1002@172.16.200.60) State Change CS_NEW -> CS_INIT
2011-07-19 19:21:47.664595 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.667744 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_INIT
2011-07-19 19:21:47.667744 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/1002@172.16.200.60) State INIT
2011-07-19 19:21:47.667744 [DEBUG] mod_sofia.c:84 sofia/internal/1002@172.16.200.60 SOFIA INIT
2011-07-19 19:21:47.667744 [DEBUG] mod_sofia.c:124 (sofia/internal/1002@172.16.200.60) State Change CS_INIT -> CS_ROUTING
2011-07-19 19:21:47.667744 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.667744 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/1002@172.16.200.60) State INIT going to sleep
2011-07-19 19:21:47.667744 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_ROUTING
2011-07-19 19:21:47.667744 [DEBUG] switch_channel.c:1664 (sofia/internal/1002@172.16.200.60) Callstate Change DOWN -> RINGING
2011-07-19 19:21:47.669630 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/1002@172.16.200.60) State ROUTING
2011-07-19 19:21:47.669630 [DEBUG] mod_sofia.c:147 sofia/internal/1002@172.16.200.60 SOFIA ROUTING
2011-07-19 19:21:47.669630 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1002@172.16.200.60 Standard ROUTING
2011-07-19 19:21:47.669630 [INFO] mod_dialplan_xml.c:331 Processing iPhone <1002>->8000 in context public
Dialplan: sofia/internal/1002@172.16.200.60 parsing [public->unloop] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [public->outside_call] continue=true
Dialplan: sofia/internal/1002@172.16.200.60 Absolute Condition [outside_call]
Dialplan: sofia/internal/1002@172.16.200.60 Action set(outside_call=true) 
Dialplan: sofia/internal/1002@172.16.200.60 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1002@172.16.200.60 parsing [public->call_debug] continue=true
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1002@172.16.200.60 parsing [public->public_extensions] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [public_extensions] destination_number(8000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [public->Calls from CM8] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (PASS) [Calls from CM8] destination_number(8000) =~ /^(800\d)$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 Action transfer(8000 XML default) 
2011-07-19 19:21:47.671552 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1002@172.16.200.60) State Change CS_ROUTING -> CS_EXECUTE
2011-07-19 19:21:47.671552 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.671552 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/1002@172.16.200.60) State ROUTING going to sleep
2011-07-19 19:21:47.671552 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_EXECUTE
2011-07-19 19:21:47.671552 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/1002@172.16.200.60) State EXECUTE
2011-07-19 19:21:47.672781 [DEBUG] mod_sofia.c:240 sofia/internal/1002@172.16.200.60 SOFIA EXECUTE
2011-07-19 19:21:47.672781 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1002@172.16.200.60 Standard EXECUTE
EXECUTE sofia/internal/1002@172.16.200.60 set(outside_call=true)
2011-07-19 19:21:47.672781 [DEBUG] mod_dptools.c:1059 sofia/internal/1002@172.16.200.60 SET [outside_call]=[true]
EXECUTE sofia/internal/1002@172.16.200.60 set(RFC2822_DATE=Tue, 19 Jul 2011 19:21:47 -0400)
2011-07-19 19:21:47.672781 [DEBUG] mod_dptools.c:1059 sofia/internal/1002@172.16.200.60 SET [RFC2822_DATE]=[Tue, 19 Jul 2011 19:21:47 -0400]
EXECUTE sofia/internal/1002@172.16.200.60 transfer(8000 XML default)
2011-07-19 19:21:47.674475 [DEBUG] switch_ivr.c:1600 (sofia/internal/1002@172.16.200.60) State Change CS_EXECUTE -> CS_ROUTING
2011-07-19 19:21:47.674475 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.674475 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.674475 [NOTICE] switch_ivr.c:1606 Transfer sofia/internal/1002@172.16.200.60 to XML[8000@default]
2011-07-19 19:21:47.676173 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/1002@172.16.200.60) State EXECUTE going to sleep
2011-07-19 19:21:47.676173 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_ROUTING
2011-07-19 19:21:47.676173 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/1002@172.16.200.60) State ROUTING
2011-07-19 19:21:47.676173 [DEBUG] mod_sofia.c:147 sofia/internal/1002@172.16.200.60 SOFIA ROUTING
2011-07-19 19:21:47.676173 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1002@172.16.200.60 Standard ROUTING
2011-07-19 19:21:47.676173 [INFO] mod_dialplan_xml.c:331 Processing iPhone <1002>->8000 in context default
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1002@172.16.200.60 Date/Time Match (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1002@172.16.200.60 Date/Time Match (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [global-intercept] destination_number(8000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [group-intercept] destination_number(8000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [intercept-ext] destination_number(8000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->redial] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [redial] destination_number(8000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->global] continue=true
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1002@172.16.200.60 Absolute Condition [global]
Dialplan: sofia/internal/1002@172.16.200.60 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1002@172.16.200.60 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1002@172.16.200.60 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1002@172.16.200.60 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [snom-demo-2] destination_number(8000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [snom-demo-1] destination_number(8000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [eavesdrop] destination_number(8000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [eavesdrop] destination_number(8000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (FAIL) [call_return] destination_number(8000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1002@172.16.200.60 Regex (PASS) [del-group] destination_number(8000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@172.16.200.60 Action answer() 
Dialplan: sofia/internal/1002@172.16.200.60 Action group(delete:00@${domain_name}:${sofia_contact(${sip_from_user}@${domain_name})}) 
Dialplan: sofia/internal/1002@172.16.200.60 Action gentones(%(1000, 0, 320)) 
2011-07-19 19:21:47.680477 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1002@172.16.200.60) State Change CS_ROUTING -> CS_EXECUTE
2011-07-19 19:21:47.680477 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.680477 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/1002@172.16.200.60) State ROUTING going to sleep
2011-07-19 19:21:47.680477 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_EXECUTE
2011-07-19 19:21:47.680477 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/1002@172.16.200.60) State EXECUTE
2011-07-19 19:21:47.681477 [DEBUG] mod_sofia.c:240 sofia/internal/1002@172.16.200.60 SOFIA EXECUTE
2011-07-19 19:21:47.681477 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1002@172.16.200.60 Standard EXECUTE
EXECUTE sofia/internal/1002@172.16.200.60 hash(insert/172.16.200.60-spymap/1002/45a003c6-5a6b-430b-9214-a2279b4acf7e)
EXECUTE sofia/internal/1002@172.16.200.60 hash(insert/172.16.200.60-last_dial/1002/8000)
EXECUTE sofia/internal/1002@172.16.200.60 hash(insert/172.16.200.60-last_dial/global/45a003c6-5a6b-430b-9214-a2279b4acf7e)
EXECUTE sofia/internal/1002@172.16.200.60 set(RFC2822_DATE=Tue, 19 Jul 2011 19:21:47 -0400)
2011-07-19 19:21:47.683508 [DEBUG] mod_dptools.c:1059 sofia/internal/1002@172.16.200.60 SET [RFC2822_DATE]=[Tue, 19 Jul 2011 19:21:47 -0400]
EXECUTE sofia/internal/1002@172.16.200.60 answer()
2011-07-19 19:21:47.686486 [DEBUG] sofia_glue.c:2990 AUDIO RTP [sofia/internal/1002@172.16.200.60] 172.16.200.60 port 16574 -> 68.225.42.67 port 18460 codec: 0 ms: 20
2011-07-19 19:21:47.686486 [DEBUG] switch_rtp.c:1621 Starting timer [soft] 160 bytes per 20ms
2011-07-19 19:21:47.687953 [DEBUG] sofia_glue.c:3245 Set 2833 dtmf send payload to 96
2011-07-19 19:21:47.687953 [DEBUG] sofia_glue.c:3250 Set 2833 dtmf receive payload to 96
2011-07-19 19:21:47.687953 [DEBUG] mod_sofia.c:681 Local SDP sofia/internal/1002@172.16.200.60:
v=0
o=FreeSWITCH 1311101133 1311101134 IN IP4 172.16.200.60
s=FreeSWITCH
c=IN IP4 172.16.200.60
t=0 0
m=audio 16574 RTP/AVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2011-07-19 19:21:47.689648 [DEBUG] sofia.c:4701 Channel sofia/internal/1002@172.16.200.60 entering state [completed][200]
2011-07-19 19:21:47.689648 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:47.689648 [DEBUG] switch_channel.c:2795 (sofia/internal/1002@172.16.200.60) Callstate Change RINGING -> ACTIVE
2011-07-19 19:21:47.690588 [NOTICE] mod_dptools.c:929 Channel [sofia/internal/1002@172.16.200.60] has been answered
EXECUTE sofia/internal/1002@172.16.200.60 group(delete:00@172.16.200.60:sofia/internal/sip:1002@192.168.60.104:50167;transport=UDP;fs_nat=yes;fs_path=sip%3A1002%40192.168.60.104%3A50167%3Btransport%3DUDP)
EXECUTE sofia/internal/1002@172.16.200.60 gentones(%(1000, 0, 320))
2011-07-19 19:21:47.849590 [DEBUG] sofia.c:4701 Channel sofia/internal/1002@172.16.200.60 entering state [ready][200]
2011-07-19 19:21:48.745448 [NOTICE] switch_core_state_machine.c:189 sofia/internal/1002@172.16.200.60 has executed the last dialplan instruction, hanging up.
2011-07-19 19:21:48.745448 [DEBUG] switch_channel.c:2545 (sofia/internal/1002@172.16.200.60) Callstate Change ACTIVE -> HANGUP
2011-07-19 19:21:48.745448 [NOTICE] switch_core_state_machine.c:191 Hangup sofia/internal/1002@172.16.200.60 [CS_EXECUTE] [NORMAL_CLEARING]
2011-07-19 19:21:48.745448 [DEBUG] switch_channel.c:2561 Send signal sofia/internal/1002@172.16.200.60 [KILL]
2011-07-19 19:21:48.745448 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/1002@172.16.200.60) State EXECUTE going to sleep
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_HANGUP
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1002@172.16.200.60) State HANGUP
2011-07-19 19:21:48.745448 [DEBUG] mod_sofia.c:457 Channel sofia/internal/1002@172.16.200.60 hanging up, cause: NORMAL_CLEARING
2011-07-19 19:21:48.745448 [DEBUG] mod_sofia.c:500 Sending BYE to sofia/internal/1002@172.16.200.60
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@172.16.200.60 Standard HANGUP, cause: NORMAL_CLEARING
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1002@172.16.200.60) State HANGUP going to sleep
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/1002@172.16.200.60) State Change CS_HANGUP -> CS_REPORTING
2011-07-19 19:21:48.745448 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@172.16.200.60) Running State Change CS_REPORTING
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1002@172.16.200.60) State REPORTING
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@172.16.200.60 Standard REPORTING, cause: NORMAL_CLEARING
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1002@172.16.200.60) State REPORTING going to sleep
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/1002@172.16.200.60) State Change CS_REPORTING -> CS_DESTROY
2011-07-19 19:21:48.745448 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@172.16.200.60 [BREAK]
2011-07-19 19:21:48.745448 [DEBUG] switch_core_session.c:1288 Session 39 (sofia/internal/1002@172.16.200.60) Locked, Waiting on external entities
2011-07-19 19:21:48.745448 [NOTICE] switch_core_session.c:1306 Session 39 (sofia/internal/1002@172.16.200.60) Ended
2011-07-19 19:21:48.745448 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1002@172.16.200.60 [CS_DESTROY]
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/1002@172.16.200.60) Callstate Change HANGUP -> DOWN
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/1002@172.16.200.60) Running State Change CS_DESTROY
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/1002@172.16.200.60) State DESTROY
2011-07-19 19:21:48.745448 [DEBUG] mod_sofia.c:362 sofia/internal/1002@172.16.200.60 SOFIA DESTROY
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@172.16.200.60 Standard DESTROY
2011-07-19 19:21:48.745448 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/1002@172.16.200.60) State DESTROY going to sleep

[Freeswitch-users] One way calling issue over an internal trunk

Mitch Johnson