received INVITE sips:1002@sips2.lab.algosolutions.com:5061 SIP/2.0 (CSeq 26620)
nta.c:3085 agent_recv_request() nta: INVITE (26620) going to a default leg
nta.c:1350 set_timeout() nta: timer set to 2000 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x8c50360, 0x8c4c6a0, 0x8cca5a0) called
soa.c:403 soa_set_params() soa_set_params(static::0x8ca1838, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x8ccb490)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x8ca1838) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x8ca1838, (nil), 0x8ca10bb, 601) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x8cca5a0): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x8cca1c8) tpn = TLS/10.30.11.53:40452
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x8d610d0 0x8cc98d0 368 (368)
tport.c:3492 tport_send_msg() tport_vsend returned 368
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (26620)
nua_session.c:4139 signal_call_state_change() nua(0x8cca5a0): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x8ca1838, [0xb52d7dec], [0xb52d7df0], [(nil)]) called
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-07-21 15:56:28.883729 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@sips2.lab.algosolutions.com:5061 [64611c78-7f79-4852-b5ad-1f48584efb01]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-07-21 15:56:28.883729 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) Running State Change CS_NEW (Cur 1 Tot 19)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-07-21 15:56:28.883729 [DEBUG] sofia.c:9837 sofia/internal/1001@sips2.lab.algosolutions.com:5061 receiving invite from 10.30.11.53:40452 version: 1.6.18 git db529ca 2017-06-30 17:38:19Z 32bit
2017-07-21 15:56:28.883729 [DEBUG] sofia.c:10008 IP 10.30.11.53 Rejected by acl "domains". Falling back to Digest auth.
nua.c:879 nua_respond() nua: nua_respond: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x8ca1838, ...) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x8ca1838) called
tport.c:3257 tport_tsend() tport_tsend(0x8cca1c8) tpn = TLS/10.30.11.53:40452
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x8d610d0 0x8ccef48 886 (886)
tport.c:3492 tport_send_msg() tport_vsend returned 886
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (26620)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x8cca5a0): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x8cca5a0): call state changed: received -> terminated
soa.c:356 soa_destroy() soa_destroy(static::0x8ca1838) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x8ccb490)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-07-21 15:56:28.883729 [DEBUG] sofia.c:2334 detaching session 64611c78-7f79-4852-b5ad-1f48584efb01
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x8cca5a0): sent signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0x8cca5a0): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2017-07-21 15:56:28.883729 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State NEW
tport.c:2773 tport_wakeup() tport_wakeup(0x8cca1c8): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x8cca1c8)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x8cca1c8): tls_read() returned 386
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x8cca1c8) msg 0x8ca1770 from (tls/10.30.11.53:40452) has 386 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x8cca1c8): msg 0x8ca1770 (386 bytes) from tls/10.30.11.53:40452/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sips:1002@sips2.lab.algosolutions.com:5061 SIP/2.0 (CSeq 26620)
nta.c:3019 agent_recv_request() nta: ACK (26620) is going to INVITE (26620)
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x8cca1c8): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x8cca1c8)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x8cca1c8): tls_read() returned 1341
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x8cca1c8) msg 0x8ca1770 from (tls/10.30.11.53:40452) has 1341 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x8cca1c8): msg 0x8ca1770 (1341 bytes) from tls/10.30.11.53:40452/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sips:1002@sips2.lab.algosolutions.com:5061 SIP/2.0 (CSeq 26621)
nta.c:3085 agent_recv_request() nta: INVITE (26621) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x8c50360, 0x8c4c6a0, 0x8d98e00) called
soa.c:403 soa_set_params() soa_set_params(static::0x8cd0248, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x8d643a8)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x8cd0248) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x8cd0248, (nil), 0x8d98a14, 601) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x8d98e00): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x8cca1c8) tpn = TLS/10.30.11.53:40452
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x8d610d0 0x8cc98d0 368 (368)
tport.c:3492 tport_send_msg() tport_vsend returned 368
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (26621)
nua_session.c:4139 signal_call_state_change() nua(0x8d98e00): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x8cd0248, [0xb52d7dec], [0xb52d7df0], [(nil)]) called
tport.c:2296 tport_set_secondary_timer() tport(0x8cca1c8): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-07-21 15:56:28.943857 [DEBUG] sofia.c:2442 Re-attaching to session 64611c78-7f79-4852-b5ad-1f48584efb01
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-07-21 15:56:28.973694 [DEBUG] sofia.c:9837 sofia/internal/1001@sips2.lab.algosolutions.com:5061 receiving invite from 10.30.11.53:40452 version: 1.6.18 git db529ca 2017-06-30 17:38:19Z 32bit
2017-07-21 15:56:28.973694 [DEBUG] sofia.c:10008 IP 10.30.11.53 Rejected by acl "domains". Falling back to Digest auth.
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-07-21 15:56:28.973694 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@sips2.lab.algosolutions.com:5061 entering state [received][100]
2017-07-21 15:56:28.973694 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 1059576656 1397714575 IN IP4 10.30.11.53
s=-
c=IN IP4 10.30.11.53
t=0 0
m=audio 3000 RTP/SAVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=label:1
a=rtcp-rsize
a=ssrc:3843876445 cname:sips:1001@sips2.lab.algosolutions.com:5061
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:y6nj/mrfJAM2HVUP6zd06LitSWzDlo+Xy1FoQEKo
a=ptime:20
m=video 6000 RTP/AVP 110 111
a=rtpmap:110 H264/90000
a=fmtp:110 profile-level-id=42c00d
a=rtpmap:111 H264/90000
a=fmtp:111 profile-level-id=64001f
a=sendonly

2017-07-21 15:56:28.973694 [DEBUG] sofia.c:7436 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) Running State Change CS_INIT (Cur 1 Tot 19)
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State INIT
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:90 sofia/internal/1001@sips2.lab.algosolutions.com:5061 SOFIA INIT
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@sips2.lab.algosolutions.com:5061 Standard INIT
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State Change CS_INIT -> CS_ROUTING
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State INIT going to sleep
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) Running State Change CS_ROUTING (Cur 1 Tot 19)
2017-07-21 15:56:28.973694 [DEBUG] switch_channel.c:2249 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) Callstate Change DOWN -> RINGING
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State ROUTING
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:143 sofia/internal/1001@sips2.lab.algosolutions.com:5061 SOFIA ROUTING
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@sips2.lab.algosolutions.com:5061 Standard ROUTING
2017-07-21 15:56:28.973694 [INFO] mod_dialplan_xml.c:637 Processing 1001 <1001>->1002 in context default
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(open=true) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [global-intercept] destination_number(1002) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->redial] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [redial] destination_number(1002) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->global] continue=true
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [global] ${default_password}(0000) =~ /^1234$/ break=never
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [global] ${endpoint_disposition}(RECEIVED_NOMEDIA) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [snom-demo-2] destination_number(1002) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [snom-demo-1] destination_number(1002) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [call_return] destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [del-group] destination_number(1002) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [add-group] destination_number(1002) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (FAIL) [extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action export(dialed_extension=1002) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(call_timeout=30) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action answer() 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action sleep(1000) 
Dialplan: sofia/internal/1001@sips2.lab.algosolutions.com:5061 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State Change CS_ROUTING -> CS_EXECUTE
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State ROUTING going to sleep
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) Running State Change CS_EXECUTE (Cur 1 Tot 19)
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@sips2.lab.algosolutions.com:5061) State EXECUTE
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:198 sofia/internal/1001@sips2.lab.algosolutions.com:5061 SOFIA EXECUTE
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@sips2.lab.algosolutions.com:5061 Standard EXECUTE
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(open=true)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [open]=[true]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 export(dialed_extension=1002)
2017-07-21 15:56:28.973694 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1002]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 bind_meta_app(1 b s execute_extension::dx XML features)
2017-07-21 15:56:28.973694 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1001.2017-07-21-15-56-28.wav)
2017-07-21 15:56:28.973694 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1001.2017-07-21-15-56-28.wav
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 bind_meta_app(3 b s execute_extension::cf XML features)
2017-07-21 15:56:28.973694 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2017-07-21 15:56:28.973694 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(ringback=%(2000,4000,440,480))
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(transfer_ringback=local_stream://moh)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(call_timeout=30)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [call_timeout]=[30]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(hangup_after_bridge=true)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(continue_on_fail=true)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [continue_on_fail]=[true]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 hash(insert/10.30.14.236-call_return/1002/1001)
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 hash(insert/10.30.14.236-last_dial_ext/1002/64611c78-7f79-4852-b5ad-1f48584efb01)
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 set(called_party_callgroup=techsupport)
2017-07-21 15:56:28.973694 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@sips2.lab.algosolutions.com:5061 [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 hash(insert/10.30.14.236-last_dial_ext/techsupport/64611c78-7f79-4852-b5ad-1f48584efb01)
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 hash(insert/10.30.14.236-last_dial_ext/global/64611c78-7f79-4852-b5ad-1f48584efb01)
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 hash(insert/10.30.14.236-last_dial/techsupport/64611c78-7f79-4852-b5ad-1f48584efb01)
EXECUTE sofia/internal/1001@sips2.lab.algosolutions.com:5061 bridge(user/1002@10.30.14.236)
2017-07-21 15:56:28.973694 [DEBUG] switch_channel.c:1250 sofia/internal/1001@sips2.lab.algosolutions.com:5061 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2017-07-21 15:56:28.973694 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-07-21 15:56:28.973694 [DEBUG] switch_channel.c:1250 sofia/internal/1001@sips2.lab.algosolutions.com:5061 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2017-07-21 15:56:28.973694 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-07-21 15:56:28.973694 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@10.30.14.245:5061 [dd73a4d8-c79e-4c43-9d93-101861addc07]
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:4819 (sofia/internal/1002@10.30.14.245:5061) State Change CS_NEW -> CS_INIT
2017-07-21 15:56:28.973694 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@10.30.14.245:5061) Running State Change CS_INIT (Cur 2 Tot 20)
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@10.30.14.245:5061) State INIT
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:90 sofia/internal/1002@10.30.14.245:5061 SOFIA INIT
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-07-21 15:56:28.973694 [DEBUG] sofia_glue.c:1295 sofia/internal/1002@10.30.14.245:5061 sending invite version: 1.6.18 git db529ca 2017-06-30 17:38:19Z 32bit
Local SDP:
v=0
o=- 1059576656 1397714575 IN IP4 10.30.11.53
s=-
c=IN IP4 10.30.11.53
t=0 0
m=audio 3000 RTP/SAVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=label:1
a=rtcp-rsize
a=ssrc:3843876445 cname:sips:1001@sips2.lab.algosolutions.com:5061
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:y6nj/mrfJAM2HVUP6zd06LitSWzDlo+Xy1FoQEKo
a=ptime:20
m=video 6000 RTP/AVP 110 111
a=rtpmap:110 H264/90000
a=fmtp:110 profile-level-id=42c00d
a=rtpmap:111 H264/90000
a=fmtp:111 profile-level-id=64001f
a=sendonly

nua.c:633 nua_invite() nua: nua_invite: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x8c50360, 0x8c4c6a0, 0xb4426cb8) called
soa.c:403 soa_set_params() soa_set_params(static::0x8ccec90, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x8ccec90, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x8ccec90, (nil), 0xb5dc6213, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x8ccec90, (nil), 0xb5dc6213, -1) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0xb4426cb8): adding session usage
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x8cca5f8)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x8ccec90) called
soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x8ccec90, 0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x8ccec90, soa_generate_offer): called
soa_static.c:1189 offer_answer_step() soa_static(0x8ccec90, soa_generate_offer): generating local description
soa_static.c:1217 offer_answer_step() soa_static(0x8ccec90, soa_generate_offer): upgrade with local description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0xb52d5f6c, (nil), ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x8ccec90, soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x8ccec90, [(nil)], [0xb52d8088], [0xb52d808c]) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x8c52580) tpn = */10.30.14.245:5061
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.30.14.245:5061
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x8c52580): not found by name */10.30.14.245:5061
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x8c52580): new secondary tport 0x8d3cb08
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x8d3cb08): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x8d3cb08): Setting TCP_KEEPINTVL to 30
tport_type_tls.c:683 tport_tls_connect() tport_tls_connect(0x8d3cb08): connecting to tls/10.30.14.245:5061/sips
tport.c:2296 tport_set_secondary_timer() tport(0x8d3cb08): reset timer
tport.c:3782 tport_queue() tport_queue(0x8d3cb08): queueing 0x8bd4c38 for tls/10.30.14.245:5061
nta.c:8304 outgoing_send() nta: sent INVITE (110002830) to */10.30.14.245:5061
tport.c:4160 tport_pend() tport_pend(0x8d3cb08): pending 0x8bd4c38 for tls/10.30.14.245:5061 (already 0)
nua_session.c:4139 signal_call_state_change() nua(0xb4426cb8): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x8ccec90, [0xb52d8084], [0xb52d8088], [(nil)]) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0xb4426cb8): sent signal r_invite
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@10.30.14.245:5061 Standard INIT
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@10.30.14.245:5061) State Change CS_INIT -> CS_ROUTING
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@10.30.14.245:5061) State INIT going to sleep
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@10.30.14.245:5061) Running State Change CS_ROUTING (Cur 2 Tot 20)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport_tls.c:955 tls_connect() tls_connect(0x8d3cb08): events CONNECTING
2017-07-21 15:56:28.973694 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@10.30.14.245:5061 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@10.30.14.245:5061) State ROUTING
2017-07-21 15:56:28.973694 [DEBUG] mod_sofia.c:143 sofia/internal/1002@10.30.14.245:5061 SOFIA ROUTING
2017-07-21 15:56:28.973694 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1002@10.30.14.245:5061) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@10.30.14.245:5061) State ROUTING going to sleep
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@10.30.14.245:5061) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 20)
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@10.30.14.245:5061) State CONSUME_MEDIA
2017-07-21 15:56:28.973694 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@10.30.14.245:5061) State CONSUME_MEDIA going to sleep
tport_tls.c:955 tls_connect() tls_connect(0x8d3cb08): events NEGOTIATING
tport_tls.c:1044 tls_connect() tls_connect(0x8d3cb08): TLS setup failed (error:00000001:lib(0):func(0):reason(1))
tport.c:2090 tport_close() tport_close(0x8d3cb08): tls/10.30.14.245:5061/sips
tport.c:4222 tport_release() tport_release(0x8d3cb08): 0x8bd4c38 by 0x8d70e08 with (nil)
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0xb52d8140)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 0/0 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 30089 ms