[Freeswitch-users] Possible registration/presence bug - Sometimes get "Originate Failed. Cause: USER_NOT_REGISTERED" when extension registration is present
Phil Quesinberry
philq at qsystemsengineering.com
Mon Apr 2 23:44:22 MSD 2012
The phone never stops working. The problem is either present from the time
FS is started or it isn't. I'll have to bring it down and try to get it to
fail again after hours so I can provide more detailed info. To me, it
appears from the log I captured that presence_id is not always being
initialized properly when FS is started but I haven't looked at the source
code to see what's really happening. I do have the two FS books on the way
though, which should give me a deeper understanding of how things work. The
wiki only goes so far.
Also, when I do a sofia status profile internal reg, I see a bunch of long
expired registration entries. Not sure if that could somehow be related to
this problem.
freeswitch at internal> sofia status profile internal reg
Registrations:
============================================================================
=====================
Call-ID: 49e008f79bd41460
User: 102 at 192.168.1.6
Contact: "Phil" <sip:102 at 192.168.1.4:5060;transport=udp>
Agent: Aastra 9480i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:39:06)
EXPSECS(271)
Host: Server
IP: 192.168.1.4
Port: 5060
Auth-User: 102
Auth-Realm: 192.168.1.6
MWI-Account: 102 at 192.168.1.6
Call-ID: 5f92c72e93a50f67
User: 226 at 192.168.1.6
Contact: "Sonny" <sip:226 at 74.93.xx.xx:5060;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-03-02 13:49:47)
EXPSECS(-2681088)
Host: Server
IP: 74.93.xx.xx
Port: 1066
Auth-User: 226
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 226 at 192.168.1.6
Call-ID: 09856e1e62e97740
User: 227 at 192.168.1.6
Contact: "Laura" <sip:227 at 74.93.xx.xx:1064;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-03-02 13:47:39)
EXPSECS(-2681216)
Host: Server
IP: 74.93.xx.xx
Port: 5060
Auth-User: 227
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 227 at 192.168.1.6
Call-ID: 69748b87cb4b8d1d
User: 257 at 192.168.1.6
Contact: "Tina" <sip:257 at 74.93.xx.xx:1060;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-03-02 13:49:11)
EXPSECS(-2681124)
Host: Server
IP: 74.93.xx.xx
Port: 1064
Auth-User: 257
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 257 at 192.168.1.6
Call-ID: 45249b30-85ddd13a at 10.0.0.159
User: 519 at 192.168.1.6
Contact: Fax Machine <sip:519 at 74.93.xx.xx:1062>
Agent: Linksys/SPA2102-5.2.12
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:36:47)
EXPSECS(132)
Host: Server
IP: 74.93.xx.xx
Port: 1062
Auth-User: 519
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 519 at 192.168.1.6
Call-ID: effe7aec41953215
User: 102 at 192.168.2.105
Contact: "Phil" <sip:102 at 192.168.2.104:5060;transport=udp>
Agent: Aastra 9480i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-03-09 00:22:38)
EXPSECS(-2124717)
Host: localhost.localdomain
IP: 192.168.2.104
Port: 5060
Auth-User: 102
Auth-Realm: 192.168.2.105
MWI-Account: 102 at 192.168.2.105
Call-ID: e9351a6c40675c86
User: 102 at 192.168.2.6
Contact: "Phil" <sip:102 at 192.168.2.104:5060;transport=udp>
Agent: Aastra 9480i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-03-15 00:46:48)
EXPSECS(-1608467)
Host: pbx
IP: 192.168.2.104
Port: 5060
Auth-User: 102
Auth-Realm: 192.168.2.6
MWI-Account: 102 at 192.168.2.6
Call-ID: 45249b30-85ddd13a at 10.0.0.159
User: 519 at 192.168.2.6
Contact: Fax Machine <sip:519 at 74.93.xx.xx:1062>
Agent: Linksys/SPA2102-5.2.12
Status: Registered(UDP)(unknown) EXP(2012-03-15 00:46:23)
EXPSECS(-1608492)
Host: pbx
IP: 74.93.xx.xx
Port: 1062
Auth-User: 519
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 519 at 192.168.2.6
Call-ID: 864e7aef4c59c423
User: 225 at 192.168.1.6
Contact: "Vicky" <sip:225 at 74.93.xx.xx:1067;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:36:25)
EXPSECS(110)
Host: server
IP: 74.93.xx.xx
Port: 1067
Auth-User: 225
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 225 at 192.168.1.6
Call-ID: 29b0d19d8063e55c
User: 226 at 192.168.1.6
Contact: "Sonny" <sip:226 at 74.93.xx.xx:1068;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:36:25)
EXPSECS(110)
Host: server
IP: 74.93.xx.xx
Port: 1068
Auth-User: 226
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 226 at 192.168.1.6
Call-ID: 6bc00b660278e069
User: 227 at 192.168.1.6
Contact: "Laura" <sip:227 at 74.93.xx.xx:1066;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:35:51)
EXPSECS(76)
Host: server
IP: 74.93.xx.xx
Port: 1066
Auth-User: 227
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 227 at 192.168.1.6
Call-ID: e721049935e82279
User: 257 at 192.168.1.6
Contact: "Tina" <sip:257 at 74.93.xx.xx:5060;transport=udp>
Agent: Aastra 9143i/3.2.2.1136
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:36:32)
EXPSECS(117)
Host: server
IP: 74.93.xx.xx
Port: 5060
Auth-User: 257
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 257 at 192.168.1.6
Call-ID: 54667b49ca74cabe
User: 3900 at 192.168.1.6
Contact: "Brad"
<sip:3900 at 173.66.xx.xx:54629;transport=udp;fs_nat=yes>
Agent: Aastra 9143i/3.2.2.2044
Status: Registered(AUTO-NAT)(unknown) EXP(2012-04-02 15:36:22)
EXPSECS(107)
Host: server.home
IP: 173.66.xx.xx
Port: 54629
Auth-User: 3900
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 3900 at 192.168.1.6
Call-ID: 6dc54f7994ffb61a
User: 3901 at 192.168.1.6
Contact: "KCC Main"
<sip:3901 at 173.66.xx.xx:6480;transport=udp;fs_nat=yes>
Agent: Aastra 9143i/3.2.2.2044
Status: Registered(AUTO-NAT)(unknown) EXP(2012-04-02 15:36:38)
EXPSECS(123)
Host: server.home
IP: 173.66.xx.xx
Port: 6480
Auth-User: 3901
Auth-Realm: qsystemseng.ourdomain.com
MWI-Account: 3901 at 192.168.1.6
Call-ID: bae1af9975ebfa50
User: 2001 at 192.168.1.6
Contact: "Phil" <sip:2001 at 192.168.1.4:5060;transport=udp>
Agent: Aastra 9480i/3.2.2.2044
Status: Registered(UDP)(unknown) EXP(2012-04-02 15:36:37)
EXPSECS(122)
Host: server.home
IP: 192.168.1.4
Port: 5060
Auth-User: 2001
Auth-Realm: 192.168.1.6
MWI-Account: 2001 at 192.168.1.6
Total items returned: 15
============================================================================
=====================
- Phil
----------
Anthony Minessale wrote:
plus the log is not detailed enough
sofia global siptrace on
sofia loglevel all 9
console loglevel debug (/log debug)
you would need enough log to cover the time when the phone is working
until when it stops working.
_____________________________________________
From: Phil Quesinberry [mailto:philq at qsystemsengineering.com]
Sent: Monday, April 02, 2012 12:37 AM
To: 'freeswitch-users at lists.freeswitch.org'
Subject: Possible registration/presence bug - Sometimes get "Originate
Failed. Cause: USER_NOT_REGISTERED" when extension registration is present
Hi,
I've noticed what appears to be a bug which I wanted to bring to your
attention. Sometimes when FS is started, extensions can't be called even
after they've registered. This doesn't happen all the time. and restarting
FS always solves the problem. Just to be clear - this problem only
sometimes occurs when FS has been started/restarted, like after an update.
Once FS has "started successfully" and sees presence for registered
extensions, it continues to work fine.
It's all or nothing - no extensions can be dialed when this issue is
present, whether they're local or NATted. If one extension can be reached,
you can reach them all (if they're registered, of course).
See debug info below on an attempt to dial a local (no NAT) extension - this
was one of the recent beta git pulls and the problem has been present
through several updates. Let me know if you need any additional info.
freeswitch at internal> show registrations
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostn
ame
102,192.168.1.6,a7289b6393a8023e,sofia/internal/sip:102 at 192.168.1.4:5060;tra
nsport=udp,1333338853,192.168.1.4,5060,udp,server.home
257,192.168.1.6,aab02ec49af03567,sofia/internal/sip:257 at 74.93.222.xx.xx:5060
;transport=udp,1333338709,74.93.xx.xx,5060,udp,server.home
2001,192.168.1.6,bae1af9975ebfa50,sofia/internal/sip:2001 at 192.168.1.4:5060;t
ransport=udp,1333338743,192.168.1.4,5060,udp,server.home
227,192.168.1.6,42db21f84f52e3ef,sofia/internal/sip:227 at 74.93.xx.xx:1066;tra
nsport=udp,1333338747,74.93.xx.xx,1066,udp,server.home
226,192.168.1.6,25619841fc53c75e,sofia/internal/sip:226 at 74.93.xx.xx:1068;tra
nsport=udp,1333338751,74.93.xx.xx,1068,udp,server.home
225,192.168.1.6,308cce2ca1734cdc,sofia/internal/sip:225 at 74.93.xx.xx:1067;tra
nsport=udp,1333338751,74.93.xx.xx,1067,udp,server.home
3900,192.168.1.6,54667b49ca74cabe,sofia/internal/sip:3900 at 173.66.xx.xx:54629
;transport=udp;fs_nat=yes,1333338762,173.66.xx.xx,54629,udp,server.home
3901,192.168.1.6,6dc54f7994ffb61a,sofia/internal/sip:3901 at 173.66.xx.xx:6480;
transport=udp;fs_nat=yes,1333338779,173.66.xx.xx,6480,udp,server.home
519,192.168.1.6,45249b30-85ddd13a at 10.0.0.159,sofia/internal/sip:519 at 74.93.xx
.xx:1062,1333338779,74.93.xx.xx,1062,udp,server.home
9 total.
2012-04-01 23:50:41.449612 [DEBUG] sofia.c:7576 IP 192.168.1.4 Rejected by
acl "domains". Falling back to Digest auth.
2012-04-01 23:50:41.449612 [WARNING] sofia_reg.c:1422 SIP auth challenge
(INVITE) on sofia profile 'internal' for [2001 at 192.168.1.6] from ip
192.168.1.4
2012-04-01 23:50:41.549553 [DEBUG] sofia.c:7576 IP 192.168.1.4 Rejected by
acl "domains". Falling back to Digest auth.
2012-04-01 23:50:41.549553 [NOTICE] switch_channel.c:926 New Channel
sofia/internal/102 at 192.168.1.6:5060 [9a9a3bde-116c-4100-b269-a6be7455c6c1]
2012-04-01 23:50:41.549553 [DEBUG] sofia.c:5541 Channel
sofia/internal/102 at 192.168.1.6:5060 entering state [received][100]
2012-04-01 23:50:41.549553 [DEBUG] sofia.c:5552 Remote SDP:
v=0
o=MxSIP 0 1 IN IP4 192.168.1.4
s=SIP Call
c=IN IP4 192.168.1.4
t=0 0
m=audio 16384 RTP/AVP 0 110 8 9
a=rtpmap:0 PCMU/8000
a=rtpmap:110 PCMU/16000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=silenceSupp:off - - - -
a=ptime:20
2012-04-01 23:50:41.549553 [DEBUG] sofia.c:5746
(sofia/internal/102 at 192.168.1.6:5060) State Change CS_NEW -> CS_INIT
2012-04-01 23:50:41.549553 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_INIT
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:401
(sofia/internal/102 at 192.168.1.6:5060) State INIT
2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:85
sofia/internal/102 at 192.168.1.6:5060 SOFIA INIT
2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:125
(sofia/internal/102 at 192.168.1.6:5060) State Change CS_INIT -> CS_ROUTING
2012-04-01 23:50:41.549553 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:401
(sofia/internal/102 at 192.168.1.6:5060) State INIT going to sleep
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_ROUTING
2012-04-01 23:50:41.549553 [DEBUG] switch_channel.c:1886
(sofia/internal/102 at 192.168.1.6:5060) Callstate Change DOWN -> RINGING
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:410
(sofia/internal/102 at 192.168.1.6:5060) State ROUTING
2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:148
sofia/internal/102 at 192.168.1.6:5060 SOFIA ROUTING
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:104
sofia/internal/102 at 192.168.1.6:5060 Standard ROUTING
2012-04-01 23:50:41.549553 [INFO] mod_dialplan_xml.c:485 Processing Phil
<102>->2001 in context default
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->call_direction] continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [call_direction]
${call_direction}() =~ /^(inbound|outbound|local)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 ANTI-Action
set(call_direction=local)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->tod_example]
continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Date/TimeMatch (FAIL)
[tod_example] break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [group-intercept]
destination_number(2001) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->redial]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [redial]
destination_number(2001) =~ /^(redial|\*870)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->global]
continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [global]
${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/
break=never
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Absolute Condition [global]
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_numbe
r})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->snom-demo-2]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [snom-demo-2]
destination_number(2001) =~ /^\*9001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->snom-demo-1]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [snom-demo-1]
destination_number(2001) =~ /^\*9000$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->call_privacy] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [call_privacy]
destination_number(2001) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->call_return]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [call_return]
destination_number(2001) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->del-group]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [del-group]
destination_number(2001) =~ /^\*\*80(\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->add-group]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [add-group]
destination_number(2001) =~ /^\*\*81(\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [call-group-simo]
destination_number(2001) =~ /^\*\*82(\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[call-group-order] destination_number(2001) =~ /^\*83(\d{2})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->intercept-ext] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [intercept-ext]
destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[Local_Extension_Skinny] destination_number(2001) =~ /^(11[01][0-9])$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->send_to_voicemail] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[send_to_voicemail] destination_number(2001) =~ /^\*99(\d{2,7})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->enum.9.10d]
continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [enum.9.10d]
destination_number(2001) =~ /^9(\d{10})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->enum.9.11d]
continue=true
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [enum.9.11d]
destination_number(2001) =~ /^9(\d{11})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->SipBroker.SIPDial] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[SipBroker.SIPDial] destination_number(2001) =~ /^([*]\d{5,})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->SipBroker.Toll_Free] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[SipBroker.Toll_Free] destination_number(2001) =~
/^91?(8(00|66|77|88)[2-9]\d{6})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->TollFreeGateway] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [TollFreeGateway]
destination_number(2001) =~ /^91?(8(00|55|66|77|88)[2-9]\d{6})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->FlowRoute.91d10or11] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[FlowRoute.91d10or11] destination_number(2001) =~ /^91?(\d{10})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->HL7519.9.10d] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [HL7519.9.10d]
caller_id_number(102) =~ /519/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->HL7519.9.11d] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [HL7519.9.11d]
caller_id_number(102) =~ /519/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->HL7612.9.10d] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [HL7612.9.10d]
${toll_allow}(local,domestic) =~ /local/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [HL7612.9.10d]
destination_number(2001) =~ /^9(\d{10})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->HL7612.9.11d] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [HL7612.9.11d]
${toll_allow}(local,domestic) =~ /local/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [HL7612.9.11d]
destination_number(2001) =~ /^9(\d{11})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->enum.7d7]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [enum.7d7]
destination_number(2001) =~ /^7(\d{7})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->xmpp.8d10]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [xmpp.8d10]
destination_number(2001) =~ /^8(\d{10})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->xmpp.8d11]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [xmpp.8d11]
destination_number(2001) =~ /^8(\d{11})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Talking
Clock Time] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Talking Clock
Time] destination_number(2001) =~ /^9170$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Talking
Clock Date] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Talking Clock
Date] destination_number(2001) =~ /^9171$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Talking
Clock Date and Time] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Talking Clock
Date and Time] destination_number(2001) =~ /^9172$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Recordings]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Recordings]
destination_number(2001) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->Company_Directory] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[Company_Directory] destination_number(2001) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->Hersch_Lauren_Main] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[Hersch_Lauren_Main] destination_number(2001) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->Holiday_Announcement] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[Holiday_Announcement] destination_number(2001) =~ /^5010$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Ring all
admin phones.park] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Ring all admin
phones.park] destination_number(2001) =~ /^\*1001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->Ring all
admin phones] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [Ring all admin
phones] destination_number(2001) =~ /^1001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->group_dial_sales] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[group_dial_sales] destination_number(2001) =~ /^\*2000$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->group_dial_support] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[group_dial_support] destination_number(2001) =~ /^\*2001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->group_dial_billing] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[group_dial_billing] destination_number(2001) =~ /^\*2002$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->operator]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [operator]
destination_number(2001) =~ /^operator$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->vmain]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [vmain]
destination_number(2001) =~ /^vmain$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->vmain1]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [vmain1]
destination_number(2001) =~ /^vmain1$|^\*97$|^\*4000$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->vmain2]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [vmain2]
destination_number(2001) =~ /^vmain2$|^\*98$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->sip_uri]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [sip_uri]
destination_number(2001) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->nb_conferences] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [nb_conferences]
destination_number(2001) =~ /^\*(30\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->wb_conferences] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [wb_conferences]
destination_number(2001) =~ /^\*(31\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->uwb_conferences] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [uwb_conferences]
destination_number(2001) =~ /^\*(32\d{2})$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->cdquality_conferences] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[cdquality_conferences] destination_number(2001) =~ /^\*(33\d{2})$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[freeswitch_public_conf_via_sip] destination_number(2001) =~
/^\*9(888|8888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->ivr_demo]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [ivr_demo]
destination_number(2001) =~ /^\*5000$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->dynamic_conference] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[dynamic_conference] destination_number(2001) =~ /^\*5001$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[rtp_multicast_page] destination_number(2001) =~ /^pagegroup$|^\*7243$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->parking_slots] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [parking_slots]
destination_number(2001) =~ /^(\*59[0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->valet_park_in] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [valet_park_in]
destination_number(2001) =~ /^\*(6000)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->valet_park_out] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [valet_park_out]
destination_number(2001) =~ /^\*(60\d\d)$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->park]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [park]
destination_number(2001) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->unpark]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [unpark]
destination_number(2001) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->park]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [park]
destination_number(2001) =~ /callpark/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->unpark]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [unpark]
destination_number(2001) =~ /pickup/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->wait]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [wait]
destination_number(2001) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->fax_receive]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [fax_receive]
destination_number(2001) =~ /^\*9178$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->fax_transmit] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [fax_transmit]
destination_number(2001) =~ /^\*9179$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->ringback_180] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [ringback_180]
destination_number(2001) =~ /^\*9180$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->ringback_183_uk_ring] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[ringback_183_uk_ring] destination_number(2001) =~ /^\*9181$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->ringback_183_music_ring] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[ringback_183_music_ring] destination_number(2001) =~ /^\*9182$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->ringback_post_answer_uk_ring] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[ringback_post_answer_uk_ring] destination_number(2001) =~ /^\*9183$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->ringback_post_answer_music] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[ringback_post_answer_music] destination_number(2001) =~ /^\*9184$/
break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->ClueCon]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [ClueCon]
destination_number(2001) =~ /^\*9191$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->show_info]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [show_info]
destination_number(2001) =~ /^\*9192$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->video_record] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [video_record]
destination_number(2001) =~ /^\*9193$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->video_playback] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [video_playback]
destination_number(2001) =~ /^\*9194$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->delay_echo]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [delay_echo]
destination_number(2001) =~ /^\*9195$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->echo]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [echo]
destination_number(2001) =~ /^\*9196$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->milliwatt]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [milliwatt]
destination_number(2001) =~ /^\*9197$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->tone_stream]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [tone_stream]
destination_number(2001) =~ /^\*9198$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->zrtp_enrollement] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL)
[zrtp_enrollement] destination_number(2001) =~ /^\*9787$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing [default->hold_music]
continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (FAIL) [hold_music]
destination_number(2001) =~ /^\*9664$/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Regex (PASS) [Local_Extension]
destination_number(2001) =~ /(^\d{2,7}$)/ break=on-false
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(dialed_extension=2001)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
export(dialed_extension=2001)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action limit(db ${domain_name}
2001 ${limit_max} ${limit_destination})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/archive/${strftime(%Y)}/${s
trftime(%b)}/${strftime(%d)}/${uuid}.wav)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action bind_meta_app(4 b s
execute_extension::att_xfer XML features)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action set(ringback=%(2000,
4000, 440.0, 480.0))
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(transfer_ringback=%(2000, 4000, 440.0, 480.0))
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action set(call_timeout=24)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(continue_on_fail=true)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_numbe
r})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name}
var callgroup)})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action
bridge(user/${user_data(${destination_number}@${domain_name} attr
id)}@${domain_name})
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action answer()
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action sleep(1000)
Dialplan: sofia/internal/102 at 192.168.1.6:5060 Action voicemail(default
${domain_name} ${dialed_extension})
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:154
(sofia/internal/102 at 192.168.1.6:5060) State Change CS_ROUTING -> CS_EXECUTE
2012-04-01 23:50:41.549553 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:410
(sofia/internal/102 at 192.168.1.6:5060) State ROUTING going to sleep
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_EXECUTE
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:417
(sofia/internal/102 at 192.168.1.6:5060) State EXECUTE
2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:241
sofia/internal/102 at 192.168.1.6:5060 SOFIA EXECUTE
2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:192
sofia/internal/102 at 192.168.1.6:5060 Standard EXECUTE
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(call_direction=local)
2012-04-01 23:50:41.549553 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [call_direction]=[local]
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-spymap/102/9a9a3bde-116c-4100-b269-a6be7455c6c1)
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-last_dial/102/2001)
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-last_dial/global/9a9a3bde-116c-4100-b269-a6be7455c6c
1)
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(RFC2822_DATE=Sun, 01 Apr
2012 23:50:41 -0400)
2012-04-01 23:50:41.549553 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [RFC2822_DATE]=[Sun, 01 Apr 2012
23:50:41 -0400]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(dialed_extension=2001)
2012-04-01 23:50:41.549553 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [dialed_extension]=[2001]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 export(dialed_extension=2001)
2012-04-01 23:50:41.549553 [DEBUG] switch_channel.c:1093 EXPORT
(export_vars) [dialed_extension]=[2001]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 limit(db 192.168.1.6 2001 5 )
2012-04-01 23:50:41.549553 [INFO] switch_limit.c:126 incr called:
192.168.1.6_2001 max:5, interval:0
2012-04-01 23:50:41.569549 [INFO] mod_db.c:197 Usage for 192.168.1.6_2001 is
now 1/5
EXECUTE sofia/internal/102 at 192.168.1.6:5060 bind_meta_app(1 b s
execute_extension::dx XML features)
2012-04-01 23:50:41.569549 [INFO] switch_ivr_async.c:3204 Bound B-Leg: *1
execute_extension::dx XML features
EXECUTE sofia/internal/102 at 192.168.1.6:5060 bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/archive/2012/Apr/01/9a9a3bd
e-116c-4100-b269-a6be7455c6c1.wav)
2012-04-01 23:50:41.569549 [INFO] switch_ivr_async.c:3204 Bound B-Leg: *2
record_session::/usr/local/freeswitch/recordings/archive/2012/Apr/01/9a9a3bd
e-116c-4100-b269-a6be7455c6c1.wav
EXECUTE sofia/internal/102 at 192.168.1.6:5060 bind_meta_app(3 b s
execute_extension::cf XML features)
2012-04-01 23:50:41.569549 [INFO] switch_ivr_async.c:3204 Bound B-Leg: *3
execute_extension::cf XML features
EXECUTE sofia/internal/102 at 192.168.1.6:5060 bind_meta_app(4 b s
execute_extension::att_xfer XML features)
2012-04-01 23:50:41.569549 [INFO] switch_ivr_async.c:3204 Bound B-Leg: *4
execute_extension::att_xfer XML features
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(ringback=%(2000, 4000,
440.0, 480.0))
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [ringback]=[%(2000, 4000, 440.0,
480.0)]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(transfer_ringback=%(2000,
4000, 440.0, 480.0))
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [transfer_ringback]=[%(2000, 4000,
440.0, 480.0)]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(call_timeout=24)
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [call_timeout]=[24]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(hangup_after_bridge=true)
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(continue_on_fail=true)
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-call_return/2001/102)
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-last_dial_ext/2001/9a9a3bde-116c-4100-b269-a6be7455c
6c1)
EXECUTE sofia/internal/102 at 192.168.1.6:5060 set(called_party_callgroup=)
2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281
sofia/internal/102 at 192.168.1.6:5060 SET [called_party_callgroup]=[UNDEF]
EXECUTE sofia/internal/102 at 192.168.1.6:5060
hash(insert/192.168.1.6-last_dial//9a9a3bde-116c-4100-b269-a6be7455c6c1)
EXECUTE sofia/internal/102 at 192.168.1.6:5060 bridge(user/2001 at 192.168.1.6)
2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:1047
sofia/internal/102 at 192.168.1.6:5060 EXPORTING[export_vars]
[dialed_extension]=[2001] to event
2012-04-01 23:50:41.569549 [DEBUG] switch_ivr_originate.c:1884 Parsing
global variables
2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:1047
sofia/internal/102 at 192.168.1.6:5060 EXPORTING[export_vars]
[dialed_extension]=[2001] to event
2012-04-01 23:50:41.569549 [DEBUG] switch_ivr_originate.c:1884 Parsing
global variables
2012-04-01 23:50:41.569549 [DEBUG] switch_event.c:1522 Parsing variable
[sip_invite_domain]=[192.168.1.6]
2012-04-01 23:50:41.569549 [DEBUG] switch_event.c:1522 Parsing variable
[presence_id]=[2001 at 192.168.1.6]
2012-04-01 23:50:41.569549 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2012-04-01 23:50:41.569549 [DEBUG] switch_ivr_originate.c:3364 Originate
Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2012-04-01 23:50:41.569549 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [user] cause: [USER_NOT_REGISTERED]
2012-04-01 23:50:41.569549 [DEBUG] switch_ivr_originate.c:3364 Originate
Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2012-04-01 23:50:41.569549 [INFO] mod_dptools.c:2922 Originate Failed.
Cause: USER_NOT_REGISTERED
EXECUTE sofia/internal/102 at 192.168.1.6:5060 answer()
2012-04-01 23:50:41.569549 [DEBUG] sofia_glue.c:4876 Audio Codec Compare
[PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-04-01 23:50:41.569549 [DEBUG] sofia_glue.c:2996 Set Codec
sofia/internal/102 at 192.168.1.6:5060 PCMU/8000 20 ms 160 samples 64000 bits
2012-04-01 23:50:41.569549 [DEBUG] switch_core_codec.c:111
sofia/internal/102 at 192.168.1.6:5060 Original read codec set to PCMU:0
2012-04-01 23:50:41.569549 [DEBUG] sofia_glue.c:5008 No 2833 in SDP.
Disable 2833 dtmf and switch to INFO
2012-04-01 23:50:41.569549 [DEBUG] sofia_glue.c:3248 AUDIO RTP
[sofia/internal/102 at 192.168.1.6:5060] 192.168.1.6 port 23164 -> 192.168.1.4
port 16384 codec: 0 ms: 20
2012-04-01 23:50:41.569549 [DEBUG] switch_rtp.c:1661 Starting timer [soft]
160 bytes per 20ms
2012-04-01 23:50:41.569549 [NOTICE] sofia_glue.c:4022 Pre-Answer
sofia/internal/102 at 192.168.1.6:5060!
2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:2932
(sofia/internal/102 at 192.168.1.6:5060) Callstate Change RINGING -> EARLY
2012-04-01 23:50:41.569549 [DEBUG] mod_sofia.c:750 Local SDP
sofia/internal/102 at 192.168.1.6:5060:
v=0
o=FreeSWITCH 1333315477 1333315478 IN IP4 192.168.1.6
s=FreeSWITCH
c=IN IP4 192.168.1.6
t=0 0
m=audio 23164 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2012-04-01 23:50:41.569549 [DEBUG] switch_core_session.c:731 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:3190
(sofia/internal/102 at 192.168.1.6:5060) Callstate Change EARLY -> ACTIVE
2012-04-01 23:50:41.569549 [NOTICE] mod_dptools.c:1135 Channel
[sofia/internal/102 at 192.168.1.6:5060] has been answered
2012-04-01 23:50:41.569549 [DEBUG] switch_core_session.c:877 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.569549 [DEBUG] sofia.c:5541 Channel
sofia/internal/102 at 192.168.1.6:5060 entering state [completed][200]
EXECUTE sofia/internal/102 at 192.168.1.6:5060 sleep(1000)
2012-04-01 23:50:41.649589 [DEBUG] switch_core_session.c:877 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.649589 [DEBUG] switch_core_session.c:877 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.649589 [DEBUG] switch_core_session.c:877 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:41.669832 [DEBUG] sofia.c:5541 Channel
sofia/internal/102 at 192.168.1.6:5060 entering state [ready][200]
2012-04-01 23:50:41.849781 [DEBUG] switch_rtp.c:3224 Correct ip/port
confirmed.
EXECUTE sofia/internal/102 at 192.168.1.6:5060 voicemail(default 192.168.1.6
2001)
2012-04-01 23:50:42.689527 [DEBUG] switch_ivr_play_say.c:1306 Codec
Activated L16 at 8000hz 1 channels 20ms
2012-04-01 23:50:46.249491 [DEBUG] switch_core_session.c:877 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:46.269490 [DEBUG] switch_channel.c:2848
(sofia/internal/102 at 192.168.1.6:5060) Callstate Change ACTIVE -> HANGUP
2012-04-01 23:50:46.269490 [NOTICE] sofia.c:628 Hangup
sofia/internal/102 at 192.168.1.6:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2012-04-01 23:50:46.269490 [DEBUG] switch_channel.c:2871 Send signal
sofia/internal/102 at 192.168.1.6:5060 [KILL]
2012-04-01 23:50:46.269490 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:46.269490 [DEBUG] switch_ivr_play_say.c:1678 done playing
file
/usr/local/freeswitch/storage/voicemail/default/192.168.1.6/2001/greeting_1.
wav
2012-04-01 23:50:46.269490 [DEBUG] switch_core_session.c:2287
sofia/internal/102 at 192.168.1.6:5060 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:417
(sofia/internal/102 at 192.168.1.6:5060) State EXECUTE going to sleep
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_HANGUP
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:602
(sofia/internal/102 at 192.168.1.6:5060) State HANGUP
2012-04-01 23:50:46.269490 [DEBUG] mod_sofia.c:469 Channel
sofia/internal/102 at 192.168.1.6:5060 hanging up, cause: NORMAL_CLEARING
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:47
sofia/internal/102 at 192.168.1.6:5060 Standard HANGUP, cause: NORMAL_CLEARING
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:602
(sofia/internal/102 at 192.168.1.6:5060) State HANGUP going to sleep
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:393
(sofia/internal/102 at 192.168.1.6:5060) State Change CS_HANGUP -> CS_REPORTING
2012-04-01 23:50:46.269490 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:362
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_REPORTING
2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:662
(sofia/internal/102 at 192.168.1.6:5060) State REPORTING
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:79
sofia/internal/102 at 192.168.1.6:5060 Standard REPORTING, cause:
NORMAL_CLEARING
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:662
(sofia/internal/102 at 192.168.1.6:5060) State REPORTING going to sleep
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:387
(sofia/internal/102 at 192.168.1.6:5060) State Change CS_REPORTING ->
CS_DESTROY
2012-04-01 23:50:46.289510 [DEBUG] switch_core_session.c:1182 Send signal
sofia/internal/102 at 192.168.1.6:5060 [BREAK]
2012-04-01 23:50:46.289510 [DEBUG] switch_core_session.c:1382 Session 13
(sofia/internal/102 at 192.168.1.6:5060) Locked, Waiting on external entities
2012-04-01 23:50:46.289510 [NOTICE] switch_core_session.c:1400 Session 13
(sofia/internal/102 at 192.168.1.6:5060) Ended
2012-04-01 23:50:46.289510 [NOTICE] switch_core_session.c:1402 Close Channel
sofia/internal/102 at 192.168.1.6:5060 [CS_DESTROY]
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:491
(sofia/internal/102 at 192.168.1.6:5060) Callstate Change HANGUP -> DOWN
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:494
(sofia/internal/102 at 192.168.1.6:5060) Running State Change CS_DESTROY
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:504
(sofia/internal/102 at 192.168.1.6:5060) State DESTROY
2012-04-01 23:50:46.289510 [DEBUG] mod_sofia.c:374
sofia/internal/102 at 192.168.1.6:5060 SOFIA DESTROY
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:86
sofia/internal/102 at 192.168.1.6:5060 Standard DESTROY
2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:504
(sofia/internal/102 at 192.168.1.6:5060) State DESTROY going to sleep
freeswitch at internal> /bye
[root at server bin]#
Regards,
Phil Quesinberry
Q Systems Engineering, Inc.
Electronic Controls and Embedded Systems Development
(410) 969-8002
http://www.qsystemsengineering.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120402/1fca2edb/attachment-0001.html
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list