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@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@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@bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons@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@bluebox) State INIT
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:83 sofia/sipinterface_1/peter_gibbons@bluebox SOFIA INIT
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:123 (sofia/sipinterface_1/peter_gibbons@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@bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:342 (sofia/sipinterface_1/peter_gibbons@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@bluebox) Running State Change CS_ROUTING
2012-03-09 08:05:13.419735 [DEBUG] switch_channel.c:1615 (sofia/sipinterface_1/peter_gibbons@bluebox) Callstate Change DOWN -> RINGING
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:345 (sofia/sipinterface_1/peter_gibbons@bluebox) State ROUTING
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:146 sofia/sipinterface_1/peter_gibbons@bluebox SOFIA ROUTING
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:77 sofia/sipinterface_1/peter_gibbons@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@bluebox parsing [context_1->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (PASS) [conditioning_callerid] ${internal_caller_id_number}(2002) =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(effective_caller_id_name=${internal_caller_id_name})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(effective_caller_id_number=${internal_caller_id_number})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Absolute Condition [postroute_global]
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->preanswer_gtalk] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [preanswer_gtalk] source(mod_sofia) =~ /^mod_dingaling$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (PASS) [main_trunk_1_pattern_5] destination_number(4000) =~ /^(40[0-9]{2})$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(prepend=)
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (PASS) [main_trunk_1_pattern_5] ${outbound_caller_id_number}(5555552002) =~ /^.+$/ break=never
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action export(sip_cid_type=rpid)
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (PASS) [main_trunk_1_pattern_5] destination_number(4000) =~ /^(40[0-9]{2})$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action set(failure_causes=NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH)
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Action bridge(sofia/gateway/trunk_1/${prepend}4000)
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_6] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [main_number_6] destination_number(4000) =~ /^2006$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_5] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [main_number_5] destination_number(4000) =~ /^2005$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_4] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [main_number_4] destination_number(4000) =~ /^2004$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_3] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [main_number_3] destination_number(4000) =~ /^2003$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_2] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox Regex (FAIL) [main_number_2] destination_number(4000) =~ /^2002$/ break=on-false
Dialplan: sofia/sipinterface_1/peter_gibbons@bluebox parsing [context_1->main_number_1] continue=true
Dialplan: sofia/sipinterface_1/peter_gibbons@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@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@bluebox [BREAK]
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:345 (sofia/sipinterface_1/peter_gibbons@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@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@bluebox) State EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] mod_sofia.c:239 sofia/sipinterface_1/peter_gibbons@bluebox SOFIA EXECUTE
2012-03-09 08:05:13.419735 [DEBUG] switch_core_state_machine.c:157 sofia/sipinterface_1/peter_gibbons@bluebox Standard EXECUTE
EXECUTE sofia/sipinterface_1/peter_gibbons@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@bluebox SET [effective_caller_id_name]=[Peter Gibbons]
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox set(effective_caller_id_number=2002)
2012-03-09 08:05:13.419735 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons@bluebox SET [effective_caller_id_number]=[2002]
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox hash(insert/10.0.1.3-spymap/peter_gibbons/bc1115e3-b592-454c-8813-a6a7fb2754d4)
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox hash(insert/10.0.1.3-last_dial/peter_gibbons/4000)
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox hash(insert/10.0.1.3-last_dial/global/bc1115e3-b592-454c-8813-a6a7fb2754d4)
EXECUTE sofia/sipinterface_1/peter_gibbons@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@bluebox SET [RFC2822_DATE]=[Fri, 09 Mar 2012 08:05:13 -0800]
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox set(prepend=)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons@bluebox SET [prepend]=[UNDEF]
EXECUTE sofia/sipinterface_1/peter_gibbons@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@bluebox SET [effective_caller_id_name]=[Peter Gibbons]
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox set(effective_caller_id_number=5555552002)
2012-03-09 08:05:13.421692 [DEBUG] mod_dptools.c:1028 sofia/sipinterface_1/peter_gibbons@bluebox SET [effective_caller_id_number]=[5555552002]
EXECUTE sofia/sipinterface_1/peter_gibbons@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@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@bluebox SET [failure_causes]=[NORMAL_CLEARING,ORIGINATOR_CANCEL,CRASH]
EXECUTE sofia/sipinterface_1/peter_gibbons@bluebox bridge(sofia/gateway/trunk_1/4000)
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:890 sofia/sipinterface_1/peter_gibbons@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@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@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@bluebox [CS_EXECUTE] [NORMAL_CLEARING]
2012-03-09 08:05:13.421692 [DEBUG] switch_channel.c:2473 Send signal sofia/sipinterface_1/peter_gibbons@bluebox [KILL]
2012-03-09 08:05:13.421692 [DEBUG] switch_core_session.c:1057 Send signal sofia/sipinterface_1/peter_gibbons@bluebox [BREAK]
2012-03-09 08:05:13.421692 [DEBUG] switch_core_state_machine.c:352 (sofia/sipinterface_1/peter_gibbons@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@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@bluebox) State HANGUP
2012-03-09 08:05:13.423711 [DEBUG] mod_sofia.c:456 Channel sofia/sipinterface_1/peter_gibbons@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@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@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@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@bluebox [BREAK]
2012-03-09 08:05:13.427318 [DEBUG] switch_core_state_machine.c:318 (sofia/sipinterface_1/peter_gibbons@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@bluebox) State REPORTING
2012-03-09 08:05:13.586710 [DEBUG] switch_core_state_machine.c:53 sofia/sipinterface_1/peter_gibbons@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@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@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@bluebox [BREAK]
2012-03-09 08:05:13.586710 [DEBUG] switch_core_session.c:1224 Session 66 (sofia/sipinterface_1/peter_gibbons@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@bluebox) Ended
2012-03-09 08:05:13.586710 [NOTICE] switch_core_session.c:1244 Close Channel sofia/sipinterface_1/peter_gibbons@bluebox [CS_DESTROY]
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:431 (sofia/sipinterface_1/peter_gibbons@bluebox) Callstate Change HANGUP -> DOWN
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:434 (sofia/sipinterface_1/peter_gibbons@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@bluebox) State DESTROY
2012-03-09 08:05:13.588724 [DEBUG] mod_sofia.c:361 sofia/sipinterface_1/peter_gibbons@bluebox SOFIA DESTROY
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/peter_gibbons@bluebox Standard DESTROY
2012-03-09 08:05:13.588724 [DEBUG] switch_core_state_machine.c:444 (sofia/sipinterface_1/peter_gibbons@bluebox) State DESTROY going to sleep