Hello all,
Maybe you can help with an issue I have had from about day 2 of my
fusion/freeswitch install.
I am able to receive calls inbound to my softphone (counterpath eyebeam
V1.5.19.4) When I try to dial out, or any extensions I am unable to
connect. Watching the CLI it the softphone seems to connect and talk with
freeswitch, then hangs up the call. Below is CLI of the call I am
attempting. Any input to correct this issue will greatly help.
Ben
+OK log level [7]
freeswitch@internal> 2012-08-23 10:45:42.332691 [DEBUG] sofia.c:6466 IP
10.0.1.151 Approved by acl "domains[]". Access Granted.
2012-08-23 10:45:42.333693 [NOTICE] switch_channel.c:812 New Channel
sofia/internal/5555(a)10.0.1.162 [c915f249-a2d1-4c5e-8900-8ae47f3deea1]
2012-08-23 10:45:42.333693 [DEBUG] sofia.c:4744 Channel sofia/internal/
5555(a)10.0.1.162 entering state [received][100]
2012-08-23 10:45:42.333693 [DEBUG] sofia.c:4755 Remote SDP:
v=0
o=- 7 2 IN IP4 10.0.1.151
s=CounterPath eyeBeam 1.5
c=IN IP4 10.0.1.151
t=0 0
m=audio 51938 RTP/AVP 107 0 8 18 101
a=rtpmap:107 BV32/16000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 3 : RQXbULH6 jeWr1bhp 10.0.1.151 51938
a=alt:2 2 : lIrXnsi1 yeNfshsQ 192.168.238.1 51938
a=alt:3 1 : np3FXIkK K342ICWN 192.168.64.1 51938
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[BV32:107:16000:20:0]/[G722:9:8000:20:64000]
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[BV32:107:16000:20:0]/[PCMU:0:8000:20:64000]
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[BV32:107:16000:20:0]/[PCMA:8:8000:20:64000]
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[BV32:107:16000:20:0]/[GSM:3:8000:20:13200]
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2012-08-23 10:45:42.333693 [DEBUG] sofia_glue.c:4619 Audio Codec Compare
[PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-08-23 10:45:42.334691 [DEBUG] sofia_glue.c:2760 Set Codec
sofia/internal/5555(a)10.0.1.162 PCMU/8000 20 ms 160 samples 64000 bits
2012-08-23 10:45:42.334691 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_NEW
2012-08-23 10:45:42.334691 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/5555(a)10.0.1.162) State NEW
2012-08-23 10:45:42.334691 [DEBUG] sofia_glue.c:4733 Set 2833 dtmf
send/recv payload to 101
2012-08-23 10:45:42.334691 [DEBUG] sofia.c:4922 (sofia/internal/
5555(a)10.0.1.162) State Change CS_NEW -> CS_INIT
2012-08-23 10:45:42.334691 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_INIT
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:356
(sofia/internal/5555(a)10.0.1.162) State INIT
2012-08-23 10:45:42.335694 [DEBUG] mod_sofia.c:84 sofia/internal/
5555(a)10.0.1.162 SOFIA INIT
2012-08-23 10:45:42.335694 [DEBUG] mod_sofia.c:124 (sofia/internal/
5555(a)10.0.1.162) State Change CS_INIT -> CS_ROUTING
2012-08-23 10:45:42.335694 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:356
(sofia/internal/5555(a)10.0.1.162) State INIT going to sleep
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_ROUTING
2012-08-23 10:45:42.335694 [DEBUG] switch_channel.c:1664 (sofia/internal/
5555(a)10.0.1.162) Callstate Change DOWN -> RINGING
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:359
(sofia/internal/5555(a)10.0.1.162) State ROUTING
2012-08-23 10:45:42.335694 [DEBUG] mod_sofia.c:147 sofia/internal/
5555(a)10.0.1.162 SOFIA ROUTING
2012-08-23 10:45:42.335694 [DEBUG] switch_core_state_machine.c:77
sofia/internal/5555(a)10.0.1.162 Standard ROUTING
2012-08-23 10:45:42.335694 [INFO] mod_dialplan_xml.c:331 Processing Ben
<5555>->18002267611 in context public
Dialplan: sofia/internal/5555(a)10.0.1.162 parsing [public->unloop]
continue=false
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/5555(a)10.0.1.162 parsing [public->outside_call]
continue=true
Dialplan: sofia/internal/5555(a)10.0.1.162 Absolute Condition [outside_call]
Dialplan: sofia/internal/5555(a)10.0.1.162 Action set(outside_call=true)
Dialplan: sofia/internal/5555(a)10.0.1.162 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/5555(a)10.0.1.162 parsing [public->call_debug]
continue=true
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/5555(a)10.0.1.162 parsing
[public->public_extensions] continue=false
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (FAIL) [public_extensions]
destination_number(18002267611) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/5555(a)10.0.1.162 parsing [public->inbound to ext
55] continue=false
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (PASS) [inbound to ext 55]
context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/5555(a)10.0.1.162 Regex (FAIL) [inbound to ext 55]
destination_number(18002267611) =~ /4049371797/ break=on-false
2012-08-23 10:45:42.337693 [DEBUG] switch_core_state_machine.c:119
(sofia/internal/5555(a)10.0.1.162) State Change CS_ROUTING -> CS_EXECUTE
2012-08-23 10:45:42.337693 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.337693 [DEBUG] switch_core_state_machine.c:359
(sofia/internal/5555(a)10.0.1.162) State ROUTING going to sleep
2012-08-23 10:45:42.337693 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_EXECUTE
2012-08-23 10:45:42.337693 [DEBUG] switch_core_state_machine.c:366
(sofia/internal/5555(a)10.0.1.162) State EXECUTE
2012-08-23 10:45:42.337693 [DEBUG] mod_sofia.c:240 sofia/internal/
5555(a)10.0.1.162 SOFIA EXECUTE
2012-08-23 10:45:42.337693 [DEBUG] switch_core_state_machine.c:157
sofia/internal/5555(a)10.0.1.162 Standard EXECUTE
EXECUTE sofia/internal/5555(a)10.0.1.162 set(outside_call=true)
2012-08-23 10:45:42.337693 [DEBUG] mod_dptools.c:1059 sofia/internal/
5555(a)10.0.1.162 SET [outside_call]=[true]
EXECUTE sofia/internal/5555(a)10.0.1.162 set(RFC2822_DATE=Thu, 23 Aug 2012
10:45:42 +0530)
2012-08-23 10:45:42.338693 [DEBUG] mod_dptools.c:1059 sofia/internal/
5555(a)10.0.1.162 SET [RFC2822_DATE]=[Thu, 23 Aug 2012 10:45:42 +0530]
2012-08-23 10:45:42.338693 [NOTICE] switch_core_state_machine.c:189
sofia/internal/5555(a)10.0.1.162 has executed the last dialplan instruction,
hanging up.
2012-08-23 10:45:42.338693 [DEBUG] switch_channel.c:2559 (sofia/internal/
5555(a)10.0.1.162) Callstate Change RINGING -> HANGUP
2012-08-23 10:45:42.338693 [NOTICE] switch_core_state_machine.c:191 Hangup
sofia/internal/5555(a)10.0.1.162 [CS_EXECUTE] [NORMAL_CLEARING]
2012-08-23 10:45:42.338693 [DEBUG] switch_channel.c:2575 Send signal
sofia/internal/5555(a)10.0.1.162 [KILL]
2012-08-23 10:45:42.338693 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.338693 [DEBUG] switch_core_state_machine.c:366
(sofia/internal/5555(a)10.0.1.162) State EXECUTE going to sleep
2012-08-23 10:45:42.338693 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_HANGUP
2012-08-23 10:45:42.339694 [DEBUG] switch_core_state_machine.c:560
(sofia/internal/5555(a)10.0.1.162) State HANGUP
2012-08-23 10:45:42.339694 [DEBUG] mod_sofia.c:457 Channel sofia/internal/
5555(a)10.0.1.162 hanging up, cause: NORMAL_CLEARING
2012-08-23 10:45:42.339694 [DEBUG] mod_sofia.c:519 Responding to INVITE
with: 480
2012-08-23 10:45:42.340695 [DEBUG] switch_core_state_machine.c:46
sofia/internal/5555(a)10.0.1.162 Standard HANGUP, cause: NORMAL_CLEARING
2012-08-23 10:45:42.340695 [DEBUG] switch_core_state_machine.c:560
(sofia/internal/5555(a)10.0.1.162) State HANGUP going to sleep
2012-08-23 10:45:42.340695 [DEBUG] switch_core_state_machine.c:351
(sofia/internal/5555(a)10.0.1.162) State Change CS_HANGUP -> CS_REPORTING
2012-08-23 10:45:42.340695 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.340695 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_REPORTING
2012-08-23 10:45:42.340695 [DEBUG] switch_core_state_machine.c:620
(sofia/internal/5555(a)10.0.1.162) State REPORTING
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:53
sofia/internal/5555(a)10.0.1.162 Standard REPORTING, cause: NORMAL_CLEARING
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:620
(sofia/internal/5555(a)10.0.1.162) State REPORTING going to sleep
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:345
(sofia/internal/5555(a)10.0.1.162) State Change CS_REPORTING -> CS_DESTROY
2012-08-23 10:45:42.489418 [DEBUG] switch_core_session.c:1116 Send signal
sofia/internal/5555(a)10.0.1.162 [BREAK]
2012-08-23 10:45:42.489418 [DEBUG] switch_core_session.c:1288 Session 22
(sofia/internal/5555(a)10.0.1.162) Locked, Waiting on external entities
2012-08-23 10:45:42.489418 [NOTICE] switch_core_session.c:1306 Session 22
(sofia/internal/5555(a)10.0.1.162) Ended
2012-08-23 10:45:42.489418 [NOTICE] switch_core_session.c:1308 Close
Channel sofia/internal/5555(a)10.0.1.162 [CS_DESTROY]
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:449
(sofia/internal/5555(a)10.0.1.162) Callstate Change HANGUP -> DOWN
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:452
(sofia/internal/5555(a)10.0.1.162) Running State Change CS_DESTROY
2012-08-23 10:45:42.489418 [DEBUG] switch_core_state_machine.c:462
(sofia/internal/5555(a)10.0.1.162) State DESTROY
2012-08-23 10:45:42.491481 [DEBUG] mod_sofia.c:362 sofia/internal/
5555(a)10.0.1.162 SOFIA DESTROY
2012-08-23 10:45:42.491481 [DEBUG] switch_core_state_machine.c:60
sofia/internal/5555(a)10.0.1.162 Standard DESTROY
2012-08-23 10:45:42.491481 [DEBUG] switch_core_state_machine.c:462
(sofia/internal/5555(a)10.0.1.162) State DESTROY going to sleep