[Freeswitch-users] Unable to call cisco from freeswitch/blubox

Fri Mar 9 19:08:35 MSK 2012

Hi All,

My home use lab uses cisco call manager 8.0. My old setup was cisco call manager to asterisk and then to google voice.  Since asterisk and google voice are now broken; I'm looking to move in the direction of free switch.

Currently My cisco call manager can call any extension on free switch and leave voicemail's. When I add google talk to frees witch I'm able to call from my cisco VoIP phone, through free switch, and to google.

My issue is that free switch is unable to call my cisco call manager.  Below is an output of the log of a call from extension 2002 to extension 4000.  From what I can tell is that free-switch is not even trying to talk to 10.0.1.99 (my call manger).  It's failing before it gets that far.

2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:0:64000]/[G7221:115:32000:20:48000]
2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:0:64000]/[G7221:107:16000:20:32000]
2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:0:64000]/[G722:9:8000:20:64000]
2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:4353 Audio Codec Compare [PCMU:0:8000:0:64000]/[PCMU:0:8000:20:64000]
2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:2721 Set Codec sofia/sipinterface_1/peter_gibbons at bluebox PCMU/8000 20 ms 160 samples 64000 bits
2012-03-09 08:05:13.418262 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf send/recv payload to 101
2012-03-09 08:05:13.418262 [DEBUG] sofia.c:4732 (sofia/sipinterface_1/peter_gibbons at bluebox) State Change CS_NEW -> CS_INIT
2012-03-09 08:05:13.418262 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_INIT
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:342 (sofia/sipinterface_1/peter_gibbons at bluebox) State INIT
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:83 sofia/sipinterface_1/peter_gibbons at bluebox SOFIA INIT
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:123 (sofia/sipinterface_1/peter_gibbons at bluebox) State Change CS_INIT -> CS_ROUTING
2012-03-09 08:05:13.419735 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:342 (sofia/sipinterface_1/peter_gibbons at bluebox) State INIT going to sleep
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_ROUTING
2012-03-09 08:05:13.419735 [DEBUG] switch_channel.c:1615 (sofia/sipinterface_1/peter_gibbons at bluebox) Callstate Change DOWN -> RINGING
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:345 (sofia/sipinterface_1/peter_gibbons at bluebox) State ROUTING
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:146 sofia/sipinterface_1/peter_gibbons at bluebox SOFIA ROUTING
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:77 sofia/sipinterface_1/peter_gibbons at bluebox Standard ROUTING
2012-03-09 08:05:13.419735 [INFO] mod_dialplan_xml.c:331 Processing peter_gibbons <peter_gibbons>->4000 in context context_1
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (PASS) [conditioning_callerid] ${internal_caller_id_number}(2002) =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(effective_caller_id_name=${internal_caller_id_name})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(effective_caller_id_number=${internal_caller_id_number})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Absolute Condition [postroute_global]
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->preanswer_gtalk] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [preanswer_gtalk] source(mod_sofia) =~ /^mod_dingaling$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (PASS) [main_trunk_1_pattern_5] destination_number(4000) =~ /^(40[0-9]{2})$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(prepend=)
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (PASS) [main_trunk_1_pattern_5] ${outbound_caller_id_number}(5555552002) =~ /^.+$/ break=never
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action export(sip_cid_type=rpid)
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (PASS) [main_trunk_1_pattern_5] destination_number(4000) =~ /^(40[0-9]{2})$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action set(failure_causes=NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH)
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Action bridge(sofia/gateway/trunk_1/${prepend}4000)
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_6] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_6] destination_number(4000) =~ /^2006$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_5] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_5] destination_number(4000) =~ /^2005$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_4] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_4] destination_number(4000) =~ /^2004$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_3] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_3] destination_number(4000) =~ /^2003$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_2] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_2] destination_number(4000) =~ /^2002$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox parsing [context_1->main_number_1] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons at bluebox Regex (FAIL) [main_number_1] destination_number(4000) =~ /^2001$/ break=on-false
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:119 (sofia/sipinterface_1/peter_gibbons at bluebox) State Change CS_ROUTING -> CS_EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:345 (sofia/sipinterface_1/peter_gibbons at bluebox) State ROUTING going to sleep
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:352 (sofia/sipinterface_1/peter_gibbons at bluebox) State EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:239 sofia/sipinterface_1/peter_gibbons at bluebox SOFIA EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:157 sofia/sipinterface_1/peter_gibbons at bluebox Standard EXECUTE
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(effective_caller_id_name=Peter Gibbons)
2012-03-09 08:05:13.419735 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [effective_caller_id_name]=[Peter Gibbons]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(effective_caller_id_number=2002)
2012-03-09 08:05:13.419735 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [effective_caller_id_number]=[2002]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox hash(insert/10.0.1.3-spymap/peter_gibbons/bc1115e3-b592-454c-8813-a6a7fb2754d4)
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox hash(insert/10.0.1.3-last_dial/peter_gibbons/4000)
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox hash(insert/10.0.1.3-last_dial/global/bc1115e3-b592-454c-8813-a6a7fb2754d4)
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(RFC2822_DATE=Fri, 09 Mar 2012 08:05:13 -0800)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [RFC2822_DATE]=[Fri, 09 Mar 2012 08:05:13 -0800]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(prepend=)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [prepend]=[UNDEF]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(effective_caller_id_name=Peter Gibbons)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [effective_caller_id_name]=[Peter Gibbons]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(effective_caller_id_number=5555552002)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [effective_caller_id_number]=[5555552002]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox export(sip_cid_type=rpid)
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:933 EXPORT (export_vars) [sip_cid_type]=[rpid]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox set(failure_causes=NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons at bluebox SET [failure_causes]=[NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH]
EXECUTE sofia/sipinterface_1/peter_gibbons at bluebox bridge(sofia/gateway/trunk_1/4000)
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:890 sofia/sipinterface_1/peter_gibbons at bluebox EXPORTING[export_vars] [sip_cid_type]=[rpid] to event
2012-03-09 08:05:13.421692 [ERR] mod_sofia.c:3738 Invalid Gateway
2012-03-09 08:05:13.421692 [NOTICE] mod_sofia.c:4060 Close Channel N/A [CS_NEW]
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:434 () Running State Change CS_DESTROY
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:444 (N/A) State DESTROY
2012-03-09 08:05:13.421692 [DEBUG] mod_sofia.c:361 N/A SOFIA DESTROY
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:444 (N/A) State DESTROY going to sleep
2012-03-09 08:05:13.421692 [ERR] switch_ivr_originate.c:2605 Cannot create outgoing channel of type [sofia] cause: [INVALID_NUMBER_FORMAT]
2012-03-09 08:05:13.421692 [DEBUG] switch_ivr_originate.c:3413 Originate Resulted in Error Cause: 28 [INVALID_NUMBER_FORMAT]
2012-03-09 08:05:13.421692 [INFO] mod_dptools.c:2579 Originate Failed.  Cause: INVALID_NUMBER_FORMAT
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:2610 Failure causes [NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH]:  Cause: INVALID_NUMBER_FORMAT
2012-03-09 08:05:13.421692 [NOTICE] switch_core_state_machine.c:189 sofia/sipinterface_1/peter_gibbons at bluebox has executed the last dialplan instruction, hanging up.
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:2457 (sofia/sipinterface_1/peter_gibbons at bluebox) Callstate Change RINGING -> HANGUP
2012-03-09 08:05:13.421692 [NOTICE] switch_core_state_machine.c:191 Hangup sofia/sipinterface_1/peter_gibbons at bluebox [CS_EXECUTE] [NORMAL_CLEARING]
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:2473 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [KILL]
2012-03-09 08:05:13.421692 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:352 (sofia/sipinterface_1/peter_gibbons at bluebox) State EXECUTE going to sleep
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_HANGUP
2012-03-09 08:05:13.423711 [DEBUG] switch_core_state_machine.c:539 (sofia/sipinterface_1/peter_gibbons at bluebox) State HANGUP
2012-03-09 08:05:13.423711 [DEBUG] mod_sofia.c:456 Channel sofia/sipinterface_1/peter_gibbons at bluebox hanging up, cause: NORMAL_CLEARING
2012-03-09 08:05:13.427318 [DEBUG] mod_sofia.c:518 Responding to INVITE with: 480
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:46 sofia/sipinterface_1/peter_gibbons at bluebox Standard HANGUP, cause: NORMAL_CLEARING
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:539 (sofia/sipinterface_1/peter_gibbons at bluebox) State HANGUP going to sleep
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:337 (sofia/sipinterface_1/peter_gibbons at bluebox) State Change CS_HANGUP -> CS_REPORTING
2012-03-09 08:05:13.427318 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_REPORTING
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:599 (sofia/sipinterface_1/peter_gibbons at bluebox) State REPORTING
2012-03-09 08:05:13.586710 [DEBUG] switch_core_state_machine.c:53 sofia/sipinterface_1/peter_gibbons at bluebox Standard REPORTING, cause: NORMAL_CLEARING
2012-03-09 08:05:13.586710 [DEBUG] switch_core_state_machine.c:599 (sofia/sipinterface_1/peter_gibbons at bluebox) State REPORTING going to sleep
2012-03-09 08:05:13.586710 [DEBUG] switch_core_state_machine.c:331 (sofia/sipinterface_1/peter_gibbons at bluebox) State Change CS_REPORTING -> CS_DESTROY
2012-03-09 08:05:13.586710 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons at bluebox [BREAK]
2012-03-09 08:05:13.586710 [DEBUG] switch_core_session.c:1224 Session 66 (sofia/sipinterface_1/peter_gibbons at bluebox) Locked, Waiting on external entities
2012-03-09 08:05:13.586710 [NOTICE] switch_core_session.c:1242 Session 66 (sofia/sipinterface_1/peter_gibbons at bluebox) Ended
2012-03-09 08:05:13.586710 [NOTICE] switch_core_session.c:1244 Close Channel sofia/sipinterface_1/peter_gibbons at bluebox [CS_DESTROY]
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:431 (sofia/sipinterface_1/peter_gibbons at bluebox) Callstate Change HANGUP -> DOWN
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:434 (sofia/sipinterface_1/peter_gibbons at bluebox) Running State Change CS_DESTROY
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:444 (sofia/sipinterface_1/peter_gibbons at bluebox) State DESTROY
2012-03-09 08:05:13.588724 [DEBUG] mod_sofia.c:361 sofia/sipinterface_1/peter_gibbons at bluebox SOFIA DESTROY
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/peter_gibbons at bluebox Standard DESTROY
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:444 (sofia/sipinterface_1/peter_gibbons at bluebox) State DESTROY going to sleep
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120309/1260f9ea/attachment-0001.html 