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@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@internal> sofia status profile internal reg

Registrations:

=================================================================================================

Call-ID:        49e008f79bd41460

User:           102@192.168.1.6

Contact:        "Phil" <sip:102@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@192.168.1.6

Call-ID:        5f92c72e93a50f67

User:           226@192.168.1.6

Contact:        "Sonny" <sip:226@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@192.168.1.6

Call-ID:        09856e1e62e97740

User:           227@192.168.1.6

Contact:        "Laura" <sip:227@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@192.168.1.6

Call-ID:        69748b87cb4b8d1d

User:           257@192.168.1.6

Contact:        "Tina" <sip:257@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@192.168.1.6

Call-ID:        45249b30-85ddd13a@10.0.0.159

User:           519@192.168.1.6

Contact:        Fax Machine <sip:519@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@192.168.1.6

Call-ID:        effe7aec41953215

User:           102@192.168.2.105

Contact:        "Phil" <sip:102@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@192.168.2.105

Call-ID:        e9351a6c40675c86

User:           102@192.168.2.6

Contact:        "Phil" <sip:102@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@192.168.2.6

Call-ID:        45249b30-85ddd13a@10.0.0.159

User:           519@192.168.2.6

Contact:        Fax Machine <sip:519@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@192.168.2.6

Call-ID:        864e7aef4c59c423

User:           225@192.168.1.6

Contact:        "Vicky" <sip:225@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@192.168.1.6

Call-ID:        29b0d19d8063e55c

User:           226@192.168.1.6

Contact:        "Sonny" <sip:226@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@192.168.1.6

Call-ID:        6bc00b660278e069

User:           227@192.168.1.6

Contact:        "Laura" <sip:227@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@192.168.1.6

Call-ID:        e721049935e82279

User:           257@192.168.1.6

Contact:        "Tina" <sip:257@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@192.168.1.6

Call-ID:        54667b49ca74cabe

User:           3900@192.168.1.6

Contact:        "Brad" <sip:3900@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@192.168.1.6

Call-ID:        6dc54f7994ffb61a

User:           3901@192.168.1.6

Contact:        "KCC Main" <sip:3901@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@192.168.1.6

Call-ID:        bae1af9975ebfa50

User:           2001@192.168.1.6

Contact:        "Phil" <sip:2001@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@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@qsystemsengineering.com] Sent: Monday, April 02, 2012 12:37 AM To: 'freeswitch-users@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@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@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@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@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@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@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@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@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@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@10.0.0.159,sofia/internal/sip:519@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@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@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@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/102@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@192.168.1.6:5060) State INIT

2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:85 sofia/internal/102@192.168.1.6:5060 SOFIA INIT

2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:125 (sofia/internal/102@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/102@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@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@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@192.168.1.6:5060) State ROUTING

2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:148 sofia/internal/102@192.168.1.6:5060 SOFIA ROUTING

2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:104 sofia/internal/102@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@192.168.1.6:5060 parsing [default->unloop] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->call_direction] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [call_direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 ANTI-Action set(call_direction=local)

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->tod_example] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Date/TimeMatch (FAIL) [tod_example] break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->holiday_example] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->group-intercept] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [group-intercept] destination_number(2001) =~ /^\*8$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->redial] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [redial] destination_number(2001) =~ /^(redial|\*870)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->global] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never

Dialplan: sofia/internal/102@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@192.168.1.6:5060 Absolute Condition [global]

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->snom-demo-2] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [snom-demo-2] destination_number(2001) =~ /^\*9001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->snom-demo-1] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [snom-demo-1] destination_number(2001) =~ /^\*9000$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->call_privacy] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [call_privacy] destination_number(2001) =~ /^\*67(\d+)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->call_return] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [call_return] destination_number(2001) =~ /^\*69$|^869$|^lcr$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->del-group] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [del-group] destination_number(2001) =~ /^\*\*80(\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->add-group] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [add-group] destination_number(2001) =~ /^\*\*81(\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->call-group-simo] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [call-group-simo] destination_number(2001) =~ /^\*\*82(\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->call-group-order] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [call-group-order] destination_number(2001) =~ /^\*83(\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->intercept-ext] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [intercept-ext] destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Local_Extension_Skinny] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Local_Extension_Skinny] destination_number(2001) =~ /^(11[01][0-9])$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->send_to_voicemail] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [send_to_voicemail] destination_number(2001) =~ /^\*99(\d{2,7})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->enum.9.10d] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [enum.9.10d] destination_number(2001) =~ /^9(\d{10})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->enum.9.11d] continue=true

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [enum.9.11d] destination_number(2001) =~ /^9(\d{11})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->SipBroker.SIPDial] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [SipBroker.SIPDial] destination_number(2001) =~ /^([*]\d{5,})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->SipBroker.Toll_Free] continue=false

Dialplan: sofia/internal/102@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@192.168.1.6:5060 parsing [default->TollFreeGateway] continue=false

Dialplan: sofia/internal/102@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@192.168.1.6:5060 parsing [default->FlowRoute.91d10or11] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [FlowRoute.91d10or11] destination_number(2001) =~ /^91?(\d{10})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->HL7519.9.10d] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [HL7519.9.10d] caller_id_number(102) =~ /519/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->HL7519.9.11d] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [HL7519.9.11d] caller_id_number(102) =~ /519/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->HL7612.9.10d] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [HL7612.9.10d] ${toll_allow}(local,domestic) =~ /local/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [HL7612.9.10d] destination_number(2001) =~ /^9(\d{10})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->HL7612.9.11d] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [HL7612.9.11d] ${toll_allow}(local,domestic) =~ /local/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [HL7612.9.11d] destination_number(2001) =~ /^9(\d{11})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->enum.7d7] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [enum.7d7] destination_number(2001) =~ /^7(\d{7})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->xmpp.8d10] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [xmpp.8d10] destination_number(2001) =~ /^8(\d{10})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->xmpp.8d11] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [xmpp.8d11] destination_number(2001) =~ /^8(\d{11})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Talking Clock Time] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Talking Clock Time] destination_number(2001) =~ /^9170$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Talking Clock Date] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Talking Clock Date] destination_number(2001) =~ /^9171$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Talking Clock Date and Time] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Talking Clock Date and Time] destination_number(2001) =~ /^9172$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Recordings] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Recordings] destination_number(2001) =~ /^\*(732)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Company_Directory] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Company_Directory] destination_number(2001) =~ /^5001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Hersch_Lauren_Main] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Hersch_Lauren_Main] destination_number(2001) =~ /^5000$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Holiday_Announcement] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Holiday_Announcement] destination_number(2001) =~ /^5010$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Ring all admin phones.park] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Ring all admin phones.park] destination_number(2001) =~ /^\*1001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Ring all admin phones] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [Ring all admin phones] destination_number(2001) =~ /^1001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->group_dial_sales] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [group_dial_sales] destination_number(2001) =~ /^\*2000$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->group_dial_support] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [group_dial_support] destination_number(2001) =~ /^\*2001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->group_dial_billing] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [group_dial_billing] destination_number(2001) =~ /^\*2002$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->operator] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [operator] destination_number(2001) =~ /^operator$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->vmain] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [vmain] destination_number(2001) =~ /^vmain$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->vmain1] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [vmain1] destination_number(2001) =~ /^vmain1$|^\*97$|^\*4000$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->vmain2] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [vmain2] destination_number(2001) =~ /^vmain2$|^\*98$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->sip_uri] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [sip_uri] destination_number(2001) =~ /^sip:(.*)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->nb_conferences] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [nb_conferences] destination_number(2001) =~ /^\*(30\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->wb_conferences] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [wb_conferences] destination_number(2001) =~ /^\*(31\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->uwb_conferences] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [uwb_conferences] destination_number(2001) =~ /^\*(32\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->cdquality_conferences] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [cdquality_conferences] destination_number(2001) =~ /^\*(33\d{2})$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->freeswitch_public_conf_via_sip] continue=false

Dialplan: sofia/internal/102@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@192.168.1.6:5060 parsing [default->ivr_demo] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ivr_demo] destination_number(2001) =~ /^\*5000$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->dynamic_conference] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [dynamic_conference] destination_number(2001) =~ /^\*5001$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->rtp_multicast_page] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [rtp_multicast_page] destination_number(2001) =~ /^pagegroup$|^\*7243$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->parking_slots] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [parking_slots] destination_number(2001) =~ /^(\*59[0-9][0-9])$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->valet_park_in] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [valet_park_in] destination_number(2001) =~ /^\*(6000)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->valet_park_out] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [valet_park_out] destination_number(2001) =~ /^\*(60\d\d)$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->park] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [park] destination_number(2001) =~ /park\+(\d+)/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->unpark] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [unpark] destination_number(2001) =~ /^parking$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->park] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [park] destination_number(2001) =~ /callpark/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->unpark] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [unpark] destination_number(2001) =~ /pickup/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->wait] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [wait] destination_number(2001) =~ /^wait$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->fax_receive] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [fax_receive] destination_number(2001) =~ /^\*9178$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->fax_transmit] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [fax_transmit] destination_number(2001) =~ /^\*9179$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ringback_180] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ringback_180] destination_number(2001) =~ /^\*9180$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ringback_183_uk_ring] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ringback_183_uk_ring] destination_number(2001) =~ /^\*9181$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ringback_183_music_ring] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ringback_183_music_ring] destination_number(2001) =~ /^\*9182$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ringback_post_answer_uk_ring] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(2001) =~ /^\*9183$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ringback_post_answer_music] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ringback_post_answer_music] destination_number(2001) =~ /^\*9184$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->ClueCon] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [ClueCon] destination_number(2001) =~ /^\*9191$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->show_info] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [show_info] destination_number(2001) =~ /^\*9192$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->video_record] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [video_record] destination_number(2001) =~ /^\*9193$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->video_playback] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [video_playback] destination_number(2001) =~ /^\*9194$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->delay_echo] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [delay_echo] destination_number(2001) =~ /^\*9195$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->echo] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [echo] destination_number(2001) =~ /^\*9196$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->milliwatt] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [milliwatt] destination_number(2001) =~ /^\*9197$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->tone_stream] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [tone_stream] destination_number(2001) =~ /^\*9198$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->zrtp_enrollement] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [zrtp_enrollement] destination_number(2001) =~ /^\*9787$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->hold_music] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (FAIL) [hold_music] destination_number(2001) =~ /^\*9664$/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 parsing [default->Local_Extension] continue=false

Dialplan: sofia/internal/102@192.168.1.6:5060 Regex (PASS) [Local_Extension] destination_number(2001) =~ /(^\d{2,7}$)/ break=on-false

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(dialed_extension=2001)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action export(dialed_extension=2001)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action limit(db ${domain_name} 2001 ${limit_max} ${limit_destination})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action bind_meta_app(1 b s execute_extension::dx XML features)

Dialplan: sofia/internal/102@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@192.168.1.6:5060 Action bind_meta_app(3 b s execute_extension::cf XML features)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(ringback=%(2000, 4000, 440.0, 480.0))

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(transfer_ringback=%(2000, 4000, 440.0, 480.0))

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(call_timeout=24)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(hangup_after_bridge=true)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(continue_on_fail=true)

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}@${domain_name})

Dialplan: sofia/internal/102@192.168.1.6:5060 Action answer()

Dialplan: sofia/internal/102@192.168.1.6:5060 Action sleep(1000)

Dialplan: sofia/internal/102@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/102@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@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@192.168.1.6:5060) State EXECUTE

2012-04-01 23:50:41.549553 [DEBUG] mod_sofia.c:241 sofia/internal/102@192.168.1.6:5060 SOFIA EXECUTE

2012-04-01 23:50:41.549553 [DEBUG] switch_core_state_machine.c:192 sofia/internal/102@192.168.1.6:5060 Standard EXECUTE

EXECUTE sofia/internal/102@192.168.1.6:5060 set(call_direction=local)

2012-04-01 23:50:41.549553 [DEBUG] mod_dptools.c:1281 sofia/internal/102@192.168.1.6:5060 SET [call_direction]=[local]

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-spymap/102/9a9a3bde-116c-4100-b269-a6be7455c6c1)

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-last_dial/102/2001)

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-last_dial/global/9a9a3bde-116c-4100-b269-a6be7455c6c1)

EXECUTE sofia/internal/102@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@192.168.1.6:5060 SET [RFC2822_DATE]=[Sun, 01 Apr 2012 23:50:41 -0400]

EXECUTE sofia/internal/102@192.168.1.6:5060 set(dialed_extension=2001)

2012-04-01 23:50:41.549553 [DEBUG] mod_dptools.c:1281 sofia/internal/102@192.168.1.6:5060 SET [dialed_extension]=[2001]

EXECUTE sofia/internal/102@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@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@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@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@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@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@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@192.168.1.6:5060 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]

EXECUTE sofia/internal/102@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@192.168.1.6:5060 SET [transfer_ringback]=[%(2000, 4000, 440.0, 480.0)]

EXECUTE sofia/internal/102@192.168.1.6:5060 set(call_timeout=24)

2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281 sofia/internal/102@192.168.1.6:5060 SET [call_timeout]=[24]

EXECUTE sofia/internal/102@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@192.168.1.6:5060 SET [hangup_after_bridge]=[true]

EXECUTE sofia/internal/102@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@192.168.1.6:5060 SET [continue_on_fail]=[true]

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-call_return/2001/102)

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-last_dial_ext/2001/9a9a3bde-116c-4100-b269-a6be7455c6c1)

EXECUTE sofia/internal/102@192.168.1.6:5060 set(called_party_callgroup=)

2012-04-01 23:50:41.569549 [DEBUG] mod_dptools.c:1281 sofia/internal/102@192.168.1.6:5060 SET [called_party_callgroup]=[UNDEF]

EXECUTE sofia/internal/102@192.168.1.6:5060 hash(insert/192.168.1.6-last_dial//9a9a3bde-116c-4100-b269-a6be7455c6c1)

EXECUTE sofia/internal/102@192.168.1.6:5060 bridge(user/2001@192.168.1.6)

2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:1047 sofia/internal/102@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@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@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@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@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@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@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@192.168.1.6:5060!

2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:2932 (sofia/internal/102@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.569549 [DEBUG] switch_channel.c:3190 (sofia/internal/102@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.569549 [DEBUG] sofia.c:5541 Channel sofia/internal/102@192.168.1.6:5060 entering state [completed][200]

EXECUTE sofia/internal/102@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.649589 [DEBUG] switch_core_session.c:877 Send signal sofia/internal/102@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.649589 [DEBUG] switch_core_session.c:877 Send signal sofia/internal/102@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:41.669832 [DEBUG] sofia.c:5541 Channel sofia/internal/102@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@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@8000hz 1 channels 20ms

2012-04-01 23:50:46.249491 [DEBUG] switch_core_session.c:877 Send signal sofia/internal/102@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:46.269490 [DEBUG] switch_channel.c:2848 (sofia/internal/102@192.168.1.6:5060) Callstate Change ACTIVE -> HANGUP

2012-04-01 23:50:46.269490 [NOTICE] sofia.c:628 Hangup sofia/internal/102@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@192.168.1.6:5060 [KILL]

2012-04-01 23:50:46.269490 [DEBUG] switch_core_session.c:1182 Send signal sofia/internal/102@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@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@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@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@192.168.1.6:5060) State HANGUP

2012-04-01 23:50:46.269490 [DEBUG] mod_sofia.c:469 Channel sofia/internal/102@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@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@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:46.269490 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/102@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@192.168.1.6:5060) State REPORTING

2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:79 sofia/internal/102@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@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@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@192.168.1.6:5060 [BREAK]

2012-04-01 23:50:46.289510 [DEBUG] switch_core_session.c:1382 Session 13 (sofia/internal/102@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@192.168.1.6:5060) Ended

2012-04-01 23:50:46.289510 [NOTICE] switch_core_session.c:1402 Close Channel sofia/internal/102@192.168.1.6:5060 [CS_DESTROY]

2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/102@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@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@192.168.1.6:5060) State DESTROY

2012-04-01 23:50:46.289510 [DEBUG] mod_sofia.c:374 sofia/internal/102@192.168.1.6:5060 SOFIA DESTROY

2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:86 sofia/internal/102@192.168.1.6:5060 Standard DESTROY

2012-04-01 23:50:46.289510 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/102@192.168.1.6:5060) State DESTROY going to sleep

freeswitch@internal> /bye

[root@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@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com

FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com

Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com

FreeSWITCH-users mailing list FreeSWITCH-users@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@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900

On 02/04/12 22:02, Anthony Minessale wrote:

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)

Sorry, I did only notice it today :-( Alex -- 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)