[Freeswitch-users] Possible registration/presence bug - Sometimes get "Originate Failed. Cause: USER_NOT_REGISTERED" when extension registration is present
Anthony Minessale
anthony.minessale at gmail.com
Tue Apr 3 01:02:06 MSD 2012
I tracked this down to a race on startup where the core has not loaded
the ACL lists but sofia tries to use them for NAT detection.
I'm sure this is not something new but it should be fixed in HEAD. (I
WISH SOMEONE WOULD HAVE OPENED A JIRA TO REFERENCE)
On Mon, Apr 2, 2012 at 3:24 PM, Alex Crow <acrow at integrafin.co.uk> wrote:
> Hi,
>
> I pulled from git today and am seeing something similar, will try to get a
> trace and submit a JIRA bug. It was not happening before my pull (last
> version was pulled in the middle of Feb).
>
> I have two profiles for extensions (internal and nat) and it seems to occur
> most often when trying to call from internal to nat registered devices.
>
> Cheers
>
> Alex
>
> On 02/04/12 20:44, Phil Quesinberry wrote:
>
> 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,hostname
>
> 102,192.168.1.6,a7289b6393a8023e,sofia/internal/sip:102 at 192.168.1.4:5060;transport=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;transport=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;transport=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;transport=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;transport=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_number})
>
> 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)}/${strftime(%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_number})
>
> 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-a6be7455c6c1)
>
> 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/9a9a3bde-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/9a9a3bde-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-a6be7455c6c1)
>
> 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
>
>
> --
> This message has been scanned for viruses and
> dangerous content by MailScanner, and is
> believed to be clean.
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
>
> --
> This message is intended only for the addressee and may contain
> confidential information. Unless you are that person, you may not
> disclose its contents or use it in any way and are requested to delete
> the message along with any attachments and notify us immediately.
>
> "Transact" is operated by Integrated Financial Arrangements plc
> Domain House, 5-7 Singer Street, London EC2A 4BQ
> Tel: (020) 7608 4900 Fax: (020) 7608 5300
> (Registered office: as above; Registered in England and Wales under number:
> 3727592)
> Authorised and regulated by the Financial Services Authority (entered on the
> FSA Register; number: 190856)
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
--
Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/
ClueCon http://www.cluecon.com/
Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm
MSN:anthony_minessale at hotmail.com
GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org
googletalk:conf+888 at conference.freeswitch.org
pstn:+19193869900
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list