WHAT A LOG LOOKS LIKE WHEN ODBC IS ONLY ENABLED ON THE INTERNAL PROFILE
(Registrations are to the Internal Profile)

recv 1012 bytes from udp/[192.168.99.164]:50235 at 21:48:42.842799:
   ------------------------------------------------------------------------
   INVITE sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPj4vHrXEkeZFOHLtxUGjHoynV0G.tUyRhI
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>
   Contact: <sip:hmrjwogf@192.168.99.164:50235>
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8161 INVITE
   Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
   Supported: 100rel, replaces, norefersub
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Content-Type: application/sdp
   Content-Length:   381
   
   v=0
   o=- 3526667321 3526667321 IN IP4 192.168.99.164
   s=Blink Lite 1.2.0 (MacOSX)
   c=IN IP4 192.168.99.164
   t=0 0
   m=audio 50018 RTP/AVP 9 104 103 102 0 8 101
   a=rtcp:50019
   a=rtpmap:9 G722/8000
   a=rtpmap:104 speex/32000
   a=rtpmap:103 speex/16000
   a=rtpmap:102 speex/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=sendrecv
   ------------------------------------------------------------------------
send 425 bytes to udp/[192.168.99.164]:50235 at 21:48:42.843152:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPj4vHrXEkeZFOHLtxUGjHoynV0G.tUyRhI
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8161 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Content-Length: 0
   
   ------------------------------------------------------------------------
send 797 bytes to udp/[192.168.99.164]:50235 at 21:48:42.854407:
   ------------------------------------------------------------------------
   SIP/2.0 407 Proxy Authentication Required
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPj4vHrXEkeZFOHLtxUGjHoynV0G.tUyRhI
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>;tag=5Z7vaDQ2pZr7S
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8161 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Proxy-Authenticate: Digest realm="mydomain.com", nonce="7653c87a-ee09-11e0-9d3a-1f25ccb47de9", algorithm=MD5, qop="auth"
   Content-Length: 0
   
   ------------------------------------------------------------------------
recv 439 bytes from udp/[192.168.99.164]:50235 at 21:48:42.862807:
   ------------------------------------------------------------------------
   ACK sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPj4vHrXEkeZFOHLtxUGjHoynV0G.tUyRhI
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>;tag=5Z7vaDQ2pZr7S
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8161 ACK
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Content-Length:  0
   
   ------------------------------------------------------------------------
recv 1306 bytes from udp/[192.168.99.164]:50235 at 21:48:42.863440:
   ------------------------------------------------------------------------
   INVITE sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPjWuAVAREyEyOVjbEjcEGAcefeihJ82mfP
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>
   Contact: <sip:hmrjwogf@192.168.99.164:50235>
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8162 INVITE
   Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
   Supported: 100rel, replaces, norefersub
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Proxy-Authorization: Digest username="4002", realm="mydomain.com", nonce="7653c87a-ee09-11e0-9d3a-1f25ccb47de9", uri="sip:4001@mydomain.com", response="63f419f85a10cdf53c544e47d9031992", algorithm=MD5, cnonce="vlVdfwIPj29Qqhq3W3oOEmiWwGBWxruF", qop=auth, nc=00000001
   Content-Type: application/sdp
   Content-Length:   381
   
   v=0
   o=- 3526667321 3526667321 IN IP4 192.168.99.164
   s=Blink Lite 1.2.0 (MacOSX)
   c=IN IP4 192.168.99.164
   t=0 0
   m=audio 50018 RTP/AVP 9 104 103 102 0 8 101
   a=rtcp:50019
   a=rtpmap:9 G722/8000
   a=rtpmap:104 speex/32000
   a=rtpmap:103 speex/16000
   a=rtpmap:102 speex/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=sendrecv
   ------------------------------------------------------------------------
send 425 bytes to udp/[192.168.99.164]:50235 at 21:48:42.863657:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPjWuAVAREyEyOVjbEjcEGAcefeihJ82mfP
   From: "Test User123" <sip:4002@mydomain.com>;tag=UWdaSs4.9yUrJSlCe.trBFC-.ILfgyQA
   To: <sip:4001@mydomain.com>
   Call-ID: JNORZnA0R.1mYOJtonAx4Zn3tZ8xeh8Z
   CSeq: 8162 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Content-Length: 0
   
   ------------------------------------------------------------------------
2011-10-03 15:48:42.884046 [NOTICE] switch_channel.c:911 New Channel sofia/internal/4002@mydomain.com [765bddb2-ee09-11e0-9d3b-1f25ccb47de9]
2011-10-03 15:48:42.884046 [DEBUG] sofia.c:5174 Channel sofia/internal/4002@mydomain.com entering state [received][100]
2011-10-03 15:48:42.884046 [DEBUG] sofia.c:5185 Remote SDP:
v=0
o=- 3526667321 3526667321 IN IP4 192.168.99.164
s=Blink Lite 1.2.0 (MacOSX)
c=IN IP4 192.168.99.164
t=0 0
m=audio 50018 RTP/AVP 9 104 103 102 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:104 speex/32000
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:50019

2011-10-03 15:48:42.884046 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2011-10-03 15:48:42.884046 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2011-10-03 15:48:42.884046 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2011-10-03 15:48:42.884046 [DEBUG] sofia_glue.c:2842 Set Codec sofia/internal/4002@mydomain.com G722/8000 20 ms 160 samples 64000 bits
2011-10-03 15:48:42.884046 [DEBUG] sofia_glue.c:4836 Set 2833 dtmf send/recv payload to 101
2011-10-03 15:48:42.884046 [DEBUG] sofia.c:5384 (sofia/internal/4002@mydomain.com) State Change CS_NEW -> CS_INIT
2011-10-03 15:48:42.884046 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_INIT
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/4002@mydomain.com) State INIT
2011-10-03 15:48:42.884046 [DEBUG] mod_sofia.c:85 sofia/internal/4002@mydomain.com SOFIA INIT
2011-10-03 15:48:42.884046 [DEBUG] mod_sofia.c:125 (sofia/internal/4002@mydomain.com) State Change CS_INIT -> CS_ROUTING
2011-10-03 15:48:42.884046 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/4002@mydomain.com) State INIT going to sleep
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_ROUTING
2011-10-03 15:48:42.884046 [DEBUG] switch_channel.c:1840 (sofia/internal/4002@mydomain.com) Callstate Change DOWN -> RINGING
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/4002@mydomain.com) State ROUTING
2011-10-03 15:48:42.884046 [DEBUG] mod_sofia.c:148 sofia/internal/4002@mydomain.com SOFIA ROUTING
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:104 sofia/internal/4002@mydomain.com Standard ROUTING
2011-10-03 15:48:42.884046 [INFO] mod_dialplan_xml.c:336 Processing Test User123 <4002>->4001 in context mydomain.com
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->unloop] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->global] continue=true
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/4002@mydomain.com Absolute Condition [global]
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/4002@mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->show_info] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [show_info] destination_number(4001) =~ /^0001$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->echo] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [echo] destination_number(4001) =~ /^0002$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->delay_echo] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [delay_echo] destination_number(4001) =~ /^0003$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->enter_callcenter_queue] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [enter_callcenter_queue] destination_number(4001) =~ /^cc(\++.*)$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_authentication] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_authentication] destination_number(4001) =~ /^ccauth$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_go_on_break] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_go_on_break] destination_number(4001) =~ /^cconbreak$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_go_off_break] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_go_off_break] destination_number(4001) =~ /^ccoffbreak$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_direct_dial_virtual_extension] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_direct_dial_virtual_extension] destination_number(4001) =~ /^7\d\d\d$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->company_extensions] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (PASS) [company_extensions] destination_number(4001) =~ /^(4[0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com Action set(dialed_extension=4001) 
Dialplan: sofia/internal/4002@mydomain.com Action export(dialed_extension=4001) 
Dialplan: sofia/internal/4002@mydomain.com Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/4002@mydomain.com Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/4002@mydomain.com Action set(call_timeout=30) 
Dialplan: sofia/internal/4002@mydomain.com Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/4002@mydomain.com Action set(continue_on_fail=true) 
Dialplan: sofia/internal/4002@mydomain.com Action bridge(user/${dialed_extension}@${domain_name}) 
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/4002@mydomain.com) State Change CS_ROUTING -> CS_EXECUTE
2011-10-03 15:48:42.884046 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/4002@mydomain.com) State ROUTING going to sleep
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_EXECUTE
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/4002@mydomain.com) State EXECUTE
2011-10-03 15:48:42.884046 [DEBUG] mod_sofia.c:241 sofia/internal/4002@mydomain.com SOFIA EXECUTE
2011-10-03 15:48:42.884046 [DEBUG] switch_core_state_machine.c:192 sofia/internal/4002@mydomain.com Standard EXECUTE
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-spymap/4002/765bddb2-ee09-11e0-9d3b-1f25ccb47de9)
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-last_dial/4002/4001)
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-last_dial/global/765bddb2-ee09-11e0-9d3b-1f25ccb47de9)
EXECUTE sofia/internal/4002@mydomain.com set(RFC2822_DATE=Mon, 03 Oct 2011 15:48:42 -0600)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [RFC2822_DATE]=[Mon, 03 Oct 2011 15:48:42 -0600]
EXECUTE sofia/internal/4002@mydomain.com set(dialed_extension=4001)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [dialed_extension]=[4001]
EXECUTE sofia/internal/4002@mydomain.com export(dialed_extension=4001)
2011-10-03 15:48:42.884046 [DEBUG] switch_channel.c:1078 EXPORT (export_vars) [dialed_extension]=[4001]
EXECUTE sofia/internal/4002@mydomain.com set(ringback=%(2000,4000,440,480))
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/4002@mydomain.com set(transfer_ringback=local_stream://moh)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/4002@mydomain.com set(call_timeout=30)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [call_timeout]=[30]
EXECUTE sofia/internal/4002@mydomain.com set(hangup_after_bridge=true)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/4002@mydomain.com set(continue_on_fail=true)
2011-10-03 15:48:42.884046 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [continue_on_fail]=[true]
EXECUTE sofia/internal/4002@mydomain.com bridge(user/4001@mydomain.com)
2011-10-03 15:48:42.903929 [DEBUG] switch_channel.c:1032 sofia/internal/4002@mydomain.com EXPORTING[export_vars] [dialed_extension]=[4001] to event
2011-10-03 15:48:42.903929 [DEBUG] switch_ivr_originate.c:1882 Parsing global variables
2011-10-03 15:48:43.063879 [DEBUG] switch_channel.c:1032 sofia/internal/4002@mydomain.com EXPORTING[export_vars] [dialed_extension]=[4001] to event
2011-10-03 15:48:43.063879 [DEBUG] switch_ivr_originate.c:1882 Parsing global variables
2011-10-03 15:48:43.063879 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[mydomain.com]
2011-10-03 15:48:43.063879 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[4001@mydomain.com]
2011-10-03 15:48:43.063879 [NOTICE] switch_channel.c:911 New Channel sofia/internal/sip:4001@192.168.99.164:28822 [767779f0-ee09-11e0-9d3c-1f25ccb47de9]
2011-10-03 15:48:43.063879 [DEBUG] mod_sofia.c:4496 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_NEW -> CS_INIT
2011-10-03 15:48:43.063879 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_INIT
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT
2011-10-03 15:48:43.063879 [DEBUG] mod_sofia.c:85 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA INIT
send 1208 bytes to udp/[192.168.99.164]:28822 at 21:48:43.078393:
   ------------------------------------------------------------------------
   INVITE sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213 SIP/2.0
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport;branch=z9hG4bKNvZg22Q21c91m
   Max-Forwards: 69
   From: "User 4002" <sip:4002@mydomain.com>;tag=7Htee3r9gH5cH
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   Call-ID: 4dd5dff3-68ac-122f-fca4-000c292e6c09
   CSeq: 18503197 INVITE
   Contact: <sip:mod_sofia@192.168.122.236:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 319
   X-FS-Support: update_display
   Remote-Party-ID: "User 4002" <sip:4002@mydomain.com>;party=calling;screen=yes;privacy=off
   
   v=0
   o=FreeSWITCH 1317654631 1317654632 IN IP4 192.168.122.236
   s=FreeSWITCH
   c=IN IP4 192.168.122.236
   t=0 0
   m=audio 23892 RTP/AVP 9 98 99 0 8 3 101 13
   a=rtpmap:98 G7221/32000
   a=fmtp:98 bitrate=48000
   a=rtpmap:99 G7221/16000
   a=fmtp:99 bitrate=32000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2011-10-03 15:48:43.063879 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:48:43.063879 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_INIT -> CS_ROUTING
2011-10-03 15:48:43.063879 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT going to sleep
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_ROUTING
2011-10-03 15:48:43.063879 [DEBUG] switch_channel.c:1840 (sofia/internal/sip:4001@192.168.99.164:28822) Callstate Change DOWN -> RINGING
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING
2011-10-03 15:48:43.063879 [DEBUG] mod_sofia.c:148 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA ROUTING
2011-10-03 15:48:43.063879 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-10-03 15:48:43.063879 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING going to sleep
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_CONSUME_MEDIA
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA
2011-10-03 15:48:43.063879 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA going to sleep
2011-10-03 15:48:43.063879 [DEBUG] sofia.c:5174 Channel sofia/internal/sip:4001@192.168.99.164:28822 entering state [calling][0]
recv 327 bytes from udp/[192.168.99.164]:28822 at 21:48:43.178263:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKNvZg22Q21c91m
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   From: "User 4002" <sip:4002@mydomain.com>;tag=7Htee3r9gH5cH
   Call-ID: 4dd5dff3-68ac-122f-fca4-000c292e6c09
   CSeq: 18503197 INVITE
   Content-Length: 0
   
   ------------------------------------------------------------------------
recv 455 bytes from udp/[192.168.99.164]:28822 at 21:48:43.380879:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKNvZg22Q21c91m
   Contact: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>;tag=9eeb2177
   From: "User 4002"<sip:4002@mydomain.com>;tag=7Htee3r9gH5cH
   Call-ID: 4dd5dff3-68ac-122f-fca4-000c292e6c09
   CSeq: 18503197 INVITE
   User-Agent: X-Lite 4 release 4.1 stamp 63215
   Content-Length: 0
   
   ------------------------------------------------------------------------

< ... > skipping the hangup logs

RESTARTING THE EXTERNAL PROFILE TO ENABLE ODBC SUPPORT

freeswitch@internal> sofia profile external restart
Reload XML [Success]
restarting: external
2011-10-03 15:49:17.269357 [INFO] mod_enum.c:775 ENUM Reloaded
2011-10-03 15:49:17.269357 [INFO] switch_time.c:1028 Timezone reloaded 530 definitions
2011-10-03 15:49:17.683871 [DEBUG] sofia.c:1969 Write lock external
2011-10-03 15:49:18.683891 [NOTICE] sofia.c:1984 Waiting for worker thread
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:2041 Write unlock external
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 debug [0]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 sip-trace [no]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 sip-capture [no]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 rfc2833-pt [101]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 dialplan [XML]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 context [public]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 dtmf-duration [2000]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 inbound-codec-prefs [G7221@32000h,G7221@16000h,G722,PCMU,PCMA,GSM]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 outbound-codec-prefs [G7221@32000h,G7221@16000h,G722,PCMU,PCMA,GSM]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 inbound-codec-negotiation [generous]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 nonce-ttl [60]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 hold-music [local_stream://moh]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 rtp-timer-name [soft]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 rtp-timeout-sec [300]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 rtp-hold-timeout-sec [1800]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 local-network-acl [localnet.auto]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 odbc-dsn [ps_voip_freeswitch:psFreeswitch:freeswitch]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 manage-presence [true]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 presence-hosts [192.168.122.236,192.168.122.236]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 auth-calls [true]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 inbound-reg-force-matching-username [true]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 log-auth-failures [true]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 auth-all-packets [false]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 challenge-realm [auto_from]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 record-path [/usr/local/freeswitch/recordings]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 record-template [${caller_id_number}.${target_domain}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 apply-nat-acl [nat.auto]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 aggressive-nat-detection [true]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 sip-port [5060]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 rtp-ip [192.168.122.236]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 sip-ip [192.168.122.236]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 tls [false]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 tls-bind-params [transport=tls]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 tls-sip-port [5061]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 tls-cert-dir [/usr/local/freeswitch/conf/ssl]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:3541 tls-version [tlsv1]
2011-10-03 15:49:18.683891 [NOTICE] sofia.c:4387 Connecting ODBC Profile external [sofia_reg_external]
2011-10-03 15:49:18.683891 [DEBUG] sofia.c:1761 Creating agent for external

WHAT A LOG LOOKS LIKE WHEN ODBC IS ENABLED ON BOTH THE INTERNAL AND EXTERNAL PROFILE
(Registrations are still only to the Internal Profile)

freeswitch@internal>
recv 1012 bytes from udp/[192.168.99.164]:50235 at 21:49:46.270969:
   ------------------------------------------------------------------------
   INVITE sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPj6tI4WixBftduKubP8KD4oAWWg7zzHC36
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>
   Contact: <sip:hmrjwogf@192.168.99.164:50235>
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8450 INVITE
   Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
   Supported: 100rel, replaces, norefersub
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Content-Type: application/sdp
   Content-Length:   381
   
   v=0
   o=- 3526667384 3526667384 IN IP4 192.168.99.164
   s=Blink Lite 1.2.0 (MacOSX)
   c=IN IP4 192.168.99.164
   t=0 0
   m=audio 50020 RTP/AVP 9 104 103 102 0 8 101
   a=rtcp:50021
   a=rtpmap:9 G722/8000
   a=rtpmap:104 speex/32000
   a=rtpmap:103 speex/16000
   a=rtpmap:102 speex/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=sendrecv
   ------------------------------------------------------------------------
send 425 bytes to udp/[192.168.99.164]:50235 at 21:49:46.271321:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPj6tI4WixBftduKubP8KD4oAWWg7zzHC36
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8450 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Content-Length: 0
   
   ------------------------------------------------------------------------
send 797 bytes to udp/[192.168.99.164]:50235 at 21:49:46.343489:
   ------------------------------------------------------------------------
   SIP/2.0 407 Proxy Authentication Required
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPj6tI4WixBftduKubP8KD4oAWWg7zzHC36
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>;tag=8tK7Fy9cetUZc
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8450 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Proxy-Authenticate: Digest realm="mydomain.com", nonce="9c22298e-ee09-11e0-9d3d-1f25ccb47de9", algorithm=MD5, qop="auth"
   Content-Length: 0
   
   ------------------------------------------------------------------------
recv 439 bytes from udp/[192.168.99.164]:50235 at 21:49:46.392366:
   ------------------------------------------------------------------------
   ACK sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPj6tI4WixBftduKubP8KD4oAWWg7zzHC36
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>;tag=8tK7Fy9cetUZc
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8450 ACK
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Content-Length:  0
   
   ------------------------------------------------------------------------
recv 1306 bytes from udp/[192.168.99.164]:50235 at 21:49:46.393257:
   ------------------------------------------------------------------------
   INVITE sip:4001@mydomain.com SIP/2.0
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport;branch=z9hG4bKPjLFXV-0PxhW97ZNyDZAEVO4tod1wfS4d-
   Max-Forwards: 70
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>
   Contact: <sip:hmrjwogf@192.168.99.164:50235>
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8451 INVITE
   Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
   Supported: 100rel, replaces, norefersub
   User-Agent: Blink Lite 1.2.0 (MacOSX)
   Proxy-Authorization: Digest username="4002", realm="mydomain.com", nonce="9c22298e-ee09-11e0-9d3d-1f25ccb47de9", uri="sip:4001@mydomain.com", response="5d46bc8f44f4e53eed695b2f3adbf7ba", algorithm=MD5, cnonce="as9ee8i9R1BqaaFa.mL2YR55Xf5hL2H-", qop=auth, nc=00000001
   Content-Type: application/sdp
   Content-Length:   381
   
   v=0
   o=- 3526667384 3526667384 IN IP4 192.168.99.164
   s=Blink Lite 1.2.0 (MacOSX)
   c=IN IP4 192.168.99.164
   t=0 0
   m=audio 50020 RTP/AVP 9 104 103 102 0 8 101
   a=rtcp:50021
   a=rtpmap:9 G722/8000
   a=rtpmap:104 speex/32000
   a=rtpmap:103 speex/16000
   a=rtpmap:102 speex/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=sendrecv
   ------------------------------------------------------------------------
send 425 bytes to udp/[192.168.99.164]:50235 at 21:49:46.393518:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.99.164:50235;rport=50235;branch=z9hG4bKPjLFXV-0PxhW97ZNyDZAEVO4tod1wfS4d-
   From: "Test User123" <sip:4002@mydomain.com>;tag=T-KI.SrDGS1QWN4f9Ji6UHwMKiVHZhln
   To: <sip:4001@mydomain.com>
   Call-ID: 4nP1mKaUlOrIChGuhNWWoHjzHB6jtCwV
   CSeq: 8451 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Content-Length: 0
   
   ------------------------------------------------------------------------
2011-10-03 15:49:46.643902 [NOTICE] switch_channel.c:911 New Channel sofia/internal/4002@mydomain.com [9c5ba8d0-ee09-11e0-9d3e-1f25ccb47de9]
2011-10-03 15:49:46.643902 [DEBUG] sofia.c:5174 Channel sofia/internal/4002@mydomain.com entering state [received][100]
2011-10-03 15:49:46.643902 [DEBUG] sofia.c:5185 Remote SDP:
v=0
o=- 3526667384 3526667384 IN IP4 192.168.99.164
s=Blink Lite 1.2.0 (MacOSX)
c=IN IP4 192.168.99.164
t=0 0
m=audio 50020 RTP/AVP 9 104 103 102 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:104 speex/32000
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:50021

2011-10-03 15:49:46.643902 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2011-10-03 15:49:46.643902 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2011-10-03 15:49:46.643902 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2011-10-03 15:49:46.643902 [DEBUG] sofia_glue.c:2842 Set Codec sofia/internal/4002@mydomain.com G722/8000 20 ms 160 samples 64000 bits
2011-10-03 15:49:46.643902 [DEBUG] sofia_glue.c:4836 Set 2833 dtmf send/recv payload to 101
2011-10-03 15:49:46.643902 [DEBUG] sofia.c:5384 (sofia/internal/4002@mydomain.com) State Change CS_NEW -> CS_INIT
2011-10-03 15:49:46.643902 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_INIT
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/4002@mydomain.com) State INIT
2011-10-03 15:49:46.643902 [DEBUG] mod_sofia.c:85 sofia/internal/4002@mydomain.com SOFIA INIT
2011-10-03 15:49:46.643902 [DEBUG] mod_sofia.c:125 (sofia/internal/4002@mydomain.com) State Change CS_INIT -> CS_ROUTING
2011-10-03 15:49:46.643902 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/4002@mydomain.com) State INIT going to sleep
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_ROUTING
2011-10-03 15:49:46.643902 [DEBUG] switch_channel.c:1840 (sofia/internal/4002@mydomain.com) Callstate Change DOWN -> RINGING
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/4002@mydomain.com) State ROUTING
2011-10-03 15:49:46.643902 [DEBUG] mod_sofia.c:148 sofia/internal/4002@mydomain.com SOFIA ROUTING
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:104 sofia/internal/4002@mydomain.com Standard ROUTING
2011-10-03 15:49:46.643902 [INFO] mod_dialplan_xml.c:336 Processing Test User123 <4002>->4001 in context mydomain.com
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->unloop] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->global] continue=true
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/4002@mydomain.com Absolute Condition [global]
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/4002@mydomain.com Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/4002@mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->show_info] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [show_info] destination_number(4001) =~ /^0001$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->echo] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [echo] destination_number(4001) =~ /^0002$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->delay_echo] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [delay_echo] destination_number(4001) =~ /^0003$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->enter_callcenter_queue] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [enter_callcenter_queue] destination_number(4001) =~ /^cc(\++.*)$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_authentication] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_authentication] destination_number(4001) =~ /^ccauth$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_go_on_break] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_go_on_break] destination_number(4001) =~ /^cconbreak$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_go_off_break] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_go_off_break] destination_number(4001) =~ /^ccoffbreak$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->callcenter_agent_direct_dial_virtual_extension] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (FAIL) [callcenter_agent_direct_dial_virtual_extension] destination_number(4001) =~ /^7\d\d\d$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com parsing [mydomain.com->company_extensions] continue=false
Dialplan: sofia/internal/4002@mydomain.com Regex (PASS) [company_extensions] destination_number(4001) =~ /^(4[0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/4002@mydomain.com Action set(dialed_extension=4001) 
Dialplan: sofia/internal/4002@mydomain.com Action export(dialed_extension=4001) 
Dialplan: sofia/internal/4002@mydomain.com Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/4002@mydomain.com Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/4002@mydomain.com Action set(call_timeout=30) 
Dialplan: sofia/internal/4002@mydomain.com Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/4002@mydomain.com Action set(continue_on_fail=true) 
Dialplan: sofia/internal/4002@mydomain.com Action bridge(user/${dialed_extension}@${domain_name}) 
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/4002@mydomain.com) State Change CS_ROUTING -> CS_EXECUTE
2011-10-03 15:49:46.643902 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/4002@mydomain.com [BREAK]
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/4002@mydomain.com) State ROUTING going to sleep
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/4002@mydomain.com) Running State Change CS_EXECUTE
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/4002@mydomain.com) State EXECUTE
2011-10-03 15:49:46.643902 [DEBUG] mod_sofia.c:241 sofia/internal/4002@mydomain.com SOFIA EXECUTE
2011-10-03 15:49:46.643902 [DEBUG] switch_core_state_machine.c:192 sofia/internal/4002@mydomain.com Standard EXECUTE
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-spymap/4002/9c5ba8d0-ee09-11e0-9d3e-1f25ccb47de9)
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-last_dial/4002/4001)
EXECUTE sofia/internal/4002@mydomain.com hash(insert/mydomain.com-last_dial/global/9c5ba8d0-ee09-11e0-9d3e-1f25ccb47de9)
EXECUTE sofia/internal/4002@mydomain.com set(RFC2822_DATE=Mon, 03 Oct 2011 15:49:46 -0600)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [RFC2822_DATE]=[Mon, 03 Oct 2011 15:49:46 -0600]
EXECUTE sofia/internal/4002@mydomain.com set(dialed_extension=4001)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [dialed_extension]=[4001]
EXECUTE sofia/internal/4002@mydomain.com export(dialed_extension=4001)
2011-10-03 15:49:46.643902 [DEBUG] switch_channel.c:1078 EXPORT (export_vars) [dialed_extension]=[4001]
EXECUTE sofia/internal/4002@mydomain.com set(ringback=%(2000,4000,440,480))
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/4002@mydomain.com set(transfer_ringback=local_stream://moh)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/4002@mydomain.com set(call_timeout=30)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [call_timeout]=[30]
EXECUTE sofia/internal/4002@mydomain.com set(hangup_after_bridge=true)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/4002@mydomain.com set(continue_on_fail=true)
2011-10-03 15:49:46.643902 [DEBUG] mod_dptools.c:1176 sofia/internal/4002@mydomain.com SET [continue_on_fail]=[true]
EXECUTE sofia/internal/4002@mydomain.com bridge(user/4001@mydomain.com)
2011-10-03 15:49:46.643902 [DEBUG] switch_channel.c:1032 sofia/internal/4002@mydomain.com EXPORTING[export_vars] [dialed_extension]=[4001] to event
2011-10-03 15:49:46.643902 [DEBUG] switch_ivr_originate.c:1882 Parsing global variables
2011-10-03 15:49:46.883896 [DEBUG] switch_channel.c:1032 sofia/internal/4002@mydomain.com EXPORTING[export_vars] [dialed_extension]=[4001] to event
2011-10-03 15:49:46.883896 [DEBUG] switch_ivr_originate.c:1882 Parsing global variables
2011-10-03 15:49:46.883896 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[mydomain.com]
2011-10-03 15:49:46.883896 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[4001@mydomain.com]
2011-10-03 15:49:46.883896 [NOTICE] switch_channel.c:911 New Channel sofia/internal/sip:4001@192.168.99.164:28822 [9c80598c-ee09-11e0-9d3f-1f25ccb47de9]
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:4496 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_NEW -> CS_INIT
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [NOTICE] switch_channel.c:911 New Channel sofia/internal/sip:4001@192.168.99.164:28822 [9c806a80-ee09-11e0-9d40-1f25ccb47de9]
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:4496 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_NEW -> CS_INIT
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_INIT
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:85 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA INIT
send 1208 bytes to udp/[192.168.99.164]:28822 at 21:49:46.890503:
   ------------------------------------------------------------------------
   INVITE sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213 SIP/2.0
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport;branch=z9hG4bKp5r93X85yNZmg
   Max-Forwards: 69
   From: "User 4002" <sip:4002@mydomain.com>;tag=aD6rKmBm8B84K
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   Call-ID: 73ded47f-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   Contact: <sip:mod_sofia@192.168.122.236:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 319
   X-FS-Support: update_display
   Remote-Party-ID: "User 4002" <sip:4002@mydomain.com>;party=calling;screen=yes;privacy=off
   
   v=0
   o=FreeSWITCH 1317645938 1317645939 IN IP4 192.168.122.236
   s=FreeSWITCH
   c=IN IP4 192.168.122.236
   t=0 0
   m=audio 32648 RTP/AVP 9 98 99 0 8 3 101 13
   a=rtpmap:98 G7221/32000
   a=fmtp:98 bitrate=48000
   a=rtpmap:99 G7221/16000
   a=fmtp:99 bitrate=32000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_INIT -> CS_ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT going to sleep
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_channel.c:1840 (sofia/internal/sip:4001@192.168.99.164:28822) Callstate Change DOWN -> RINGING
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:148 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING going to sleep
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA going to sleep
2011-10-03 15:49:46.883896 [DEBUG] sofia.c:5174 Channel sofia/internal/sip:4001@192.168.99.164:28822 entering state [calling][0]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_INIT
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:85 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA INIT
send 1208 bytes to udp/[192.168.99.164]:28822 at 21:49:46.892519:
   ------------------------------------------------------------------------
   INVITE sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213 SIP/2.0
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport;branch=z9hG4bKQej25rS9UyN7B
   Max-Forwards: 69
   From: "User 4002" <sip:4002@mydomain.com>;tag=BpZHNFvQ5myQF
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   Call-ID: 73df237e-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   Contact: <sip:mod_sofia@192.168.122.236:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-3317f5d 2011-09-30 09-45-00 -0500
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 319
   X-FS-Support: update_display
   Remote-Party-ID: "User 4002" <sip:4002@mydomain.com>;party=calling;screen=yes;privacy=off
   
   v=0
   o=FreeSWITCH 1317657128 1317657129 IN IP4 192.168.122.236
   s=FreeSWITCH
   c=IN IP4 192.168.122.236
   t=0 0
   m=audio 21458 RTP/AVP 9 98 99 0 8 3 101 13
   a=rtpmap:98 G7221/32000
   a=fmtp:98 bitrate=48000
   a=rtpmap:99 G7221/16000
   a=fmtp:99 bitrate=32000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_INIT -> CS_ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:4001@192.168.99.164:28822) State INIT going to sleep
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_channel.c:1840 (sofia/internal/sip:4001@192.168.99.164:28822) Callstate Change DOWN -> RINGING
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING
2011-10-03 15:49:46.883896 [DEBUG] mod_sofia.c:148 sofia/internal/sip:4001@192.168.99.164:28822 SOFIA ROUTING
2011-10-03 15:49:46.883896 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:4001@192.168.99.164:28822) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/sip:4001@192.168.99.164:28822 [BREAK]
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:4001@192.168.99.164:28822) State ROUTING going to sleep
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:4001@192.168.99.164:28822) Running State Change CS_CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA
2011-10-03 15:49:46.883896 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:4001@192.168.99.164:28822) State CONSUME_MEDIA going to sleep
2011-10-03 15:49:46.883896 [DEBUG] sofia.c:5174 Channel sofia/internal/sip:4001@192.168.99.164:28822 entering state [calling][0]
recv 327 bytes from udp/[192.168.99.164]:28822 at 21:49:46.989055:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKp5r93X85yNZmg
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   From: "User 4002" <sip:4002@mydomain.com>;tag=aD6rKmBm8B84K
   Call-ID: 73ded47f-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   Content-Length: 0
   
   ------------------------------------------------------------------------
recv 327 bytes from udp/[192.168.99.164]:28822 at 21:49:46.989275:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKQej25rS9UyN7B
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   From: "User 4002" <sip:4002@mydomain.com>;tag=BpZHNFvQ5myQF
   Call-ID: 73df237e-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   Content-Length: 0
   
   ------------------------------------------------------------------------
recv 455 bytes from udp/[192.168.99.164]:28822 at 21:49:47.210704:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKp5r93X85yNZmg
   Contact: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>;tag=928ba664
   From: "User 4002"<sip:4002@mydomain.com>;tag=aD6rKmBm8B84K
   Call-ID: 73ded47f-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   User-Agent: X-Lite 4 release 4.1 stamp 63215
   Content-Length: 0
   
   ------------------------------------------------------------------------

   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 192.168.122.236:5080;rport=5080;branch=z9hG4bKQej25rS9UyN7B
   Contact: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>
   To: <sip:4001@192.168.99.164:28822;rinstance=f1937c664a1cc213>;tag=580d452c
   From: "User 4002"<sip:4002@mydomain.com>;tag=BpZHNFvQ5myQF
   Call-ID: 73df237e-68ac-122f-fca4-000c292e6c09
   CSeq: 18503229 INVITE
   User-Agent: X-Lite 4 release 4.1 stamp 63215
   Content-Length: 0
   
   ------------------------------------------------------------------------

IF I WERE TO ADD ANOTHER PROFILE TO THE ODBC YOU WOULD SEE 3 B-Legs, Etc…
(Registrations are still only to the Internal Profile)