tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x13196a0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x13196a0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x13196a0) msg 0x14c3d90 from (udp/192.168.1.118:5060) has 4 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x13196a0): bad msg 0x14c3d90 (4 bytes) from udp/192.168.1.156:5060/sip next=(nil)
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x14c3d90 from (tcp/192.168.1.33:54582) has 995 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x14c3d90 (995 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received PUBLISH sip:1000@192.168.1.118;transport=TCP SIP/2.0 (CSeq 202)
nta.c:3248 agent_aliases() nta: canonizing sip:1000@192.168.1.118 with contact
nta.c:3085 agent_recv_request() nta: PUBLISH (202) 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::0x120fea0, 0x11f8990, 0x11149b0) called
soa.c:403 soa_set_params() soa_set_params(static::0x1319210, ...) called
nua_stack.c:271 nua_stack_event() nua(0x11149b0): event i_publish 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x11fa5b0 from (tcp/192.168.1.33:54582) has 1988 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x11fa5b0 (995 bytes) from tcp/192.168.1.33:54582/sip next=0x1126c70
nta.c:2880 agent_recv_request() nta: received PUBLISH sip:1001@192.168.1.118;transport=TCP SIP/2.0 (CSeq 202)
nta.c:3248 agent_aliases() nta: canonizing sip:1001@192.168.1.118 with contact
nta.c:3085 agent_recv_request() nta: PUBLISH (202) 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::0x120fea0, 0x11f8990, 0x12085a0) called
soa.c:403 soa_set_params() soa_set_params(static::0x120ec60, ...) called
nua_stack.c:271 nua_stack_event() nua(0x12085a0): event i_publish 100 Trying
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x1126c70 (993 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received PUBLISH sip:1003@192.168.1.118;transport=TCP SIP/2.0 (CSeq 6)
nta.c:3248 agent_aliases() nta: canonizing sip:1003@192.168.1.118 with contact
nta.c:3085 agent_recv_request() nta: PUBLISH (6) 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::0x120fea0, 0x11f8990, 0x121a720) called
soa.c:403 soa_set_params() soa_set_params(static::0x127c110, ...) called
nua_stack.c:271 nua_stack_event() nua(0x121a720): event i_publish 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x11149b0): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x1319210, ...) called
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 758 bytes of 758 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 758
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for PUBLISH (202)
nta.c:5744 incoming_free() nta: incoming_free(0x1100e20)
nua_stack.c:529 nua_signal() nua(0x11149b0): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x11149b0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x1319210) called
nua_stack.c:529 nua_signal() nua(0x11149b0): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x12085a0): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x120ec60, ...) called
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 758 bytes of 758 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 758
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for PUBLISH (202)
nta.c:5744 incoming_free() nta: incoming_free(0x1206d50)
nua_stack.c:529 nua_signal() nua(0x12085a0): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x12085a0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x120ec60) called
nua_stack.c:529 nua_signal() nua(0x12085a0): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x121a720): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x127c110, ...) called
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 756 bytes of 756 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 756
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for PUBLISH (6)
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:5744 incoming_free() nta: incoming_free(0x127c7a0)
nua_stack.c:529 nua_signal() nua(0x121a720): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x121a720): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x127c110) called
nua_stack.c:529 nua_signal() nua(0x121a720): sent signal r_destroy
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x10f5750 from (tcp/192.168.1.33:54582) has 907 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x10f5750 (907 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:3000@192.168.1.118;transport=TCP SIP/2.0 (CSeq 1)
nta.c:3248 agent_aliases() nta: canonizing sip:3000@192.168.1.118 with contact
nta.c:3085 agent_recv_request() nta: INVITE (1) 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::0x120fea0, 0x11f8990, 0x1534270) called
soa.c:403 soa_set_params() soa_set_params(static::0x12127e0, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x1114b70)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x12127e0) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x12127e0, (nil), 0x1532ec8, 243) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x1534270): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 362 bytes of 362 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 362
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
nua_stack.c:271 nua_stack_event() nua(0x1534270): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x1534270): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x12127e0, [0x7f86c53328c8], [0x7f86c53328d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x1534270): event i_state 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): 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-10-12 20:27:01.165465 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@192.168.1.118 [f785cb04-a3ee-43e4-9415-e43e7e606990]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-10-12 20:27:01.165465 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.1.118) Running State Change CS_NEW (Cur 1 Tot 85)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.165465 [DEBUG] sofia.c:9837 sofia/internal/1000@192.168.1.118 receiving invite from 192.168.1.33:54582 version: 1.6.18  64bit
2017-10-12 20:27:01.165465 [DEBUG] sofia.c:10008 IP 192.168.1.33 Rejected by acl "domains". Falling back to Digest auth.
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x1534270): recv signal r_respond 407 Proxy Authentication Required
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x12127e0, ...) 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::0x12127e0) called
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 866 bytes of 866 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 866
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x1534270): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x1534270): call state changed: received -> terminated
nua_stack.c:271 nua_stack_event() nua(0x1534270): event i_state 407 Proxy Authentication Required
nua_stack.c:271 nua_stack_event() nua(0x1534270): event i_terminated 407 Proxy Authentication Required
soa.c:356 soa_destroy() soa_destroy(static::0x12127e0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x1114b70)
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-10-12 20:27:01.165465 [DEBUG] sofia.c:2334 detaching session f785cb04-a3ee-43e4-9415-e43e7e606990
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x1534270): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x1534270): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0x1534270): 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-10-12 20:27:01.165465 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@192.168.1.118) State NEW
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x162cff0 from (tcp/192.168.1.33:54582) has 366 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x162cff0 (366 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:3000@192.168.1.118;transport=TCP SIP/2.0 (CSeq 1)
nta.c:3019 agent_recv_request() nta: ACK (1) is going to INVITE (1)
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x162cff0 from (tcp/192.168.1.33:54582) has 1183 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x162cff0 (1183 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:3000@192.168.1.118;transport=TCP SIP/2.0 (CSeq 2)
nta.c:3248 agent_aliases() nta: canonizing sip:3000@192.168.1.118 with contact
nta.c:3085 agent_recv_request() nta: INVITE (2) 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::0x120fea0, 0x11f8990, 0x120ea30) called
soa.c:403 soa_set_params() soa_set_params(static::0x1534190, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x12110e0)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x1534190) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x1534190, (nil), 0x114377c, 243) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x120ea30): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 362 bytes of 362 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 362
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (2)
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x120ea30): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x1534190, [0x7f86c53328c8], [0x7f86c53328d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_state 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): 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-10-12 20:27:01.205456 [DEBUG] sofia.c:2442 Re-attaching to session f785cb04-a3ee-43e4-9415-e43e7e606990
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.205456 [DEBUG] sofia.c:9837 sofia/internal/1000@192.168.1.118 receiving invite from 192.168.1.33:54582 version: 1.6.18  64bit
2017-10-12 20:27:01.205456 [DEBUG] sofia.c:10008 IP 192.168.1.33 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-10-12 20:27:01.205456 [DEBUG] sofia.c:7048 Channel sofia/internal/1000@192.168.1.118 entering state [received][100]
2017-10-12 20:27:01.205456 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=Z 0 0 IN IP4 117.247.91.162
s=Z
c=IN IP4 117.247.91.162
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 98 101
a=rtpmap:110 speex/8000
a=rtpmap:98 iLBC/8000
a=fmtp:98 mode=20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2017-10-12 20:27:01.205456 [DEBUG] sofia.c:7450 (sofia/internal/1000@192.168.1.118) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.1.118) Running State Change CS_INIT (Cur 1 Tot 85)
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.1.118) State INIT
2017-10-12 20:27:01.205456 [DEBUG] mod_sofia.c:90 sofia/internal/1000@192.168.1.118 SOFIA INIT
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.1.118 Standard INIT
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.1.118) State Change CS_INIT -> CS_ROUTING
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.1.118) State INIT going to sleep
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.1.118) Running State Change CS_ROUTING (Cur 1 Tot 85)
2017-10-12 20:27:01.205456 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@192.168.1.118) Callstate Change DOWN -> RINGING
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.1.118) State ROUTING
2017-10-12 20:27:01.205456 [DEBUG] mod_sofia.c:143 sofia/internal/1000@192.168.1.118 SOFIA ROUTING
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@192.168.1.118 Standard ROUTING
2017-10-12 20:27:01.205456 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->3000 in context default
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1000@192.168.1.118 Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1000@192.168.1.118 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [global-intercept] destination_number(3000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [group-intercept] destination_number(3000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [intercept-ext] destination_number(3000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->redial] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [redial] destination_number(3000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->global] continue=true
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never
Dialplan: sofia/internal/1000@192.168.1.118 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/1000@192.168.1.118 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=Z 0 0 IN IP4 117.247.91.162
s=Z
c=IN IP4 117.247.91.162
t=0 0
m=audio 8000 RTP/AVP 3 110 8 0 98 101
a=rtpmap:110 speex/8000
a=rtpmap:98 iLBC/8000
a=fmtp:98 mode=20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1000@192.168.1.118 Absolute Condition [global]
Dialplan: sofia/internal/1000@192.168.1.118 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1000@192.168.1.118 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1000@192.168.1.118 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1000@192.168.1.118 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [snom-demo-2] destination_number(3000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [snom-demo-1] destination_number(3000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [eavesdrop] destination_number(3000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [eavesdrop] destination_number(3000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [call_return] destination_number(3000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [del-group] destination_number(3000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [add-group] destination_number(3000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [call-group-simo] destination_number(3000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [call-group-order] destination_number(3000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [extension-intercom] destination_number(3000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [Local_Extension] destination_number(3000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [Local_Extension_Skinny] destination_number(3000) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->group_dial_sales] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [group_dial_sales] destination_number(3000) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->group_dial_support] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [group_dial_support] destination_number(3000) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->group_dial_billing] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [group_dial_billing] destination_number(3000) =~ /^2002$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->operator] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [operator] destination_number(3000) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->vmain] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [vmain] destination_number(3000) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (FAIL) [sip_uri] destination_number(3000) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/1000@192.168.1.118 Regex (PASS) [nb_conferences] destination_number(3000) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@192.168.1.118 Action answer() 
Dialplan: sofia/internal/1000@192.168.1.118 Action conference(3000-${domain_name}@default) 
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1000@192.168.1.118) State Change CS_ROUTING -> CS_EXECUTE
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.1.118) State ROUTING going to sleep
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.1.118) Running State Change CS_EXECUTE (Cur 1 Tot 85)
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@192.168.1.118) State EXECUTE
2017-10-12 20:27:01.205456 [DEBUG] mod_sofia.c:198 sofia/internal/1000@192.168.1.118 SOFIA EXECUTE
2017-10-12 20:27:01.205456 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@192.168.1.118 Standard EXECUTE
EXECUTE sofia/internal/1000@192.168.1.118 hash(insert/192.168.1.118-spymap/1000/f785cb04-a3ee-43e4-9415-e43e7e606990)
EXECUTE sofia/internal/1000@192.168.1.118 hash(insert/192.168.1.118-last_dial/1000/3000)
EXECUTE sofia/internal/1000@192.168.1.118 hash(insert/192.168.1.118-last_dial/global/f785cb04-a3ee-43e4-9415-e43e7e606990)
EXECUTE sofia/internal/1000@192.168.1.118 export(RFC2822_DATE=Thu, 12 Oct 2017 20:27:01 +0530)
2017-10-12 20:27:01.205456 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 12 Oct 2017 20:27:01 +0530]
EXECUTE sofia/internal/1000@192.168.1.118 answer()
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:3057 Set Codec sofia/internal/1000@192.168.1.118 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2017-10-12 20:27:01.205456 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.1.118 Original read codec set to PCMA:8
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:4763 sofia/internal/1000@192.168.1.118 Set 2833 dtmf send payload to 101 recv payload to 101
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/internal/1000@192.168.1.118] 192.168.1.118 port 17278 -> 117.247.91.162 port 8000 codec: 8 ms: 20
2017-10-12 20:27:01.205456 [DEBUG] switch_rtp.c:4108 Starting timer [soft] 160 bytes per 20ms
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:7175 sofia/internal/1000@192.168.1.118 Set 2833 dtmf send payload to 101
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:7182 sofia/internal/1000@192.168.1.118 Set 2833 dtmf receive payload to 101
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:7205 sofia/internal/1000@192.168.1.118 Set rtp dtmf delay to 40
2017-10-12 20:27:01.205456 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.1.118!
2017-10-12 20:27:01.205456 [DEBUG] switch_channel.c:3474 (sofia/internal/1000@192.168.1.118) Callstate Change RINGING -> EARLY
2017-10-12 20:27:01.205456 [DEBUG] switch_core_media.c:6857 Audio params are unchanged for sofia/internal/1000@192.168.1.118.
2017-10-12 20:27:01.205456 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1000@192.168.1.118:
v=0
o=FreeSWITCH 1507802943 1507802944 IN IP4 192.168.1.118
s=FreeSWITCH
c=IN IP4 192.168.1.118
t=0 0
m=audio 17278 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x120ea30): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x1534190, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x1534190, (nil), 0x1651902, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x1534190, (nil), 0x1651902, -1) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x1534190) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x1534190, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x1534190, soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x1534190, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f86c5330b00, 0x112c3f0, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x1534190, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x1534190, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x1534190, [(nil)], [0x7f86c5332c38], [0x7f86c5332c34]) called
tport.c:3257 tport_tsend() tport_tsend(0x1289300) tpn = TCP/192.168.1.33:54582
tport.c:3594 tport_vsend() tport_vsend(0x1289300): 1141 bytes of 1141 to tcp/192.168.1.33:54582
tport.c:3492 tport_send_msg() tport_vsend returned 1141
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (2)
nta.c:1348 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4139 signal_call_state_change() nua(0x120ea30): call state changed: received -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x1534190, [0x7f86c5332ce8], [0x7f86c5332cf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x1534190, ...) called
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x120ea30): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.205456 [DEBUG] sofia.c:7048 Channel sofia/internal/1000@192.168.1.118 entering state [completed][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.205456 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/1000@192.168.1.118] has been answered
2017-10-12 20:27:01.225455 [DEBUG] switch_channel.c:3773 (sofia/internal/1000@192.168.1.118) Callstate Change EARLY -> ACTIVE
EXECUTE sofia/internal/1000@192.168.1.118 conference(3000-192.168.1.118@default)
2017-10-12 20:27:01.225455 [DEBUG] mod_conference.c:3065 using channel sound prefix: /usr/local/freeswitch/sounds/en/us/callie
2017-10-12 20:27:01.225455 [DEBUG] conference_member.c:1690 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-10-12 20:27:01.225455 [DEBUG] conference_member.c:1737 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-10-12 20:27:01.225455 [DEBUG] switch_core_codec.c:223 sofia/internal/1000@192.168.1.118 Push codec L16:100
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '0' to 'mute'
2017-10-12 20:27:01.245468 [INFO] switch_ivr_async.c:214 Digit parser mod_conference: Setting realm to 'conf'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 0/conf/0 callback: 0x7f86c783eb40 data: 0x10083f8
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '*' to 'deaf mute'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding */conf/0 callback: 0x7f86c783eb40 data: 0x1008428
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '9' to 'energy up'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 9/conf/0 callback: 0x7f86c783eb40 data: 0x1008458
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '8' to 'energy equ'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 8/conf/0 callback: 0x7f86c783eb40 data: 0x1008488
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '7' to 'energy dn'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 7/conf/0 callback: 0x7f86c783eb40 data: 0x10084b8
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '3' to 'vol talk up'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 3/conf/0 callback: 0x7f86c783eb40 data: 0x10084e8
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '2' to 'vol talk zero'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 2/conf/0 callback: 0x7f86c783eb40 data: 0x1008518
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '1' to 'vol talk dn'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 1/conf/0 callback: 0x7f86c783eb40 data: 0x1008548
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '6' to 'vol listen up'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 6/conf/0 callback: 0x7f86c783eb40 data: 0x1008578
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '5' to 'vol listen zero'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 5/conf/0 callback: 0x7f86c783eb40 data: 0x10085a8
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '4' to 'vol listen dn'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 4/conf/0 callback: 0x7f86c783eb40 data: 0x10085d8
2017-10-12 20:27:01.245468 [DEBUG] conference_member.c:128 sofia/internal/1000@192.168.1.118 binding '#' to 'execute_application'
2017-10-12 20:27:01.245468 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding #/conf/0 callback: 0x7f86c783eb40 data: 0x1008608
2017-10-12 20:27:01.245468 [DEBUG] conference_loop.c:1140 Setup timer soft success interval: 20  samples: 160 from codec PCMA
2017-10-12 20:27:01.245468 [DEBUG] mod_conference.c:220 Setup timer success interval: 20  samples: 160
tport.c:2773 tport_wakeup() tport_wakeup(0x1289300): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x1289300)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x1289300) msg 0x11026d0 from (tcp/192.168.1.33:54582) has 735 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x1289300): msg 0x11026d0 (735 bytes) from tcp/192.168.1.33:54582/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:3000@192.168.1.118:5060;transport=tcp SIP/2.0 (CSeq 2)
nta.c:3019 agent_recv_request() nta: ACK (2) is going to INVITE (2)
nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x1534190) called
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_ack 200 OK
nua_session.c:4139 signal_call_state_change() nua(0x120ea30): call state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x120ea30): event i_active 200 Call active
nta.c:5744 incoming_free() nta: incoming_free(0x10f5b00)
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: 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:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.265457 [DEBUG] sofia.c:7048 Channel sofia/internal/1000@192.168.1.118 entering state [ready][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:01.505461 [INFO] switch_rtp.c:7214 Auto Changing audio port from 117.247.91.162:8000 to 192.168.1.33:8000
tport.c:2296 tport_set_secondary_timer() tport(0x1289300): reset timer
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f86c5332c60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 0/0 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
2017-10-12 20:27:04.005458 [DEBUG] mod_local_stream.c:871 Opening Stream [moh/8000] 8000hz
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
freeswitch@freeswitch> 
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x13196a0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x13196a0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x13196a0) msg 0x11c46a0 from (udp/192.168.1.118:5060) has 853 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x13196a0): msg 0x11c46a0 (853 bytes) from udp/192.168.1.156:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:3000@192.168.1.118:5060 SIP/2.0 (CSeq 1)
nta.c:3248 agent_aliases() nta: canonizing sip:3000@192.168.1.118:5060 with contact
nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg
nta.c:1350 set_timeout() nta: timer set to 200 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::0x120fea0, 0x11f8990, 0x12099d0) called
soa.c:403 soa_set_params() soa_set_params(static::0x123cfc0, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x1289530)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x123cfc0) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x123cfc0, (nil), 0x1102920, 261) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x12099d0): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x13196a0) tpn = UDP/192.168.1.156:5062
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.156:5062
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x13196a0): not found by name UDP/192.168.1.156:5062
tport.c:3594 tport_vsend() tport_vsend(0x13196a0): 285 bytes of 285 to udp/192.168.1.156:5062
tport.c:3492 tport_send_msg() tport_vsend returned 285
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1)
nua_stack.c:271 nua_stack_event() nua(0x12099d0): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x12099d0): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x123cfc0, [0x7f86c53328c8], [0x7f86c53328d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x12099d0): event i_state 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-10-12 20:27:11.485457 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@192.168.1.118 [9626d8bb-97d1-4b43-b588-0ec2a561bedc]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-10-12 20:27:11.485457 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.1.118) Running State Change CS_NEW (Cur 2 Tot 86)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.485457 [DEBUG] sofia.c:9837 sofia/internal/1002@192.168.1.118 receiving invite from 192.168.1.156:5062 version: 1.6.18  64bit
2017-10-12 20:27:11.485457 [DEBUG] sofia.c:10008 IP 192.168.1.156 Rejected by acl "domains". Falling back to Digest auth.
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x12099d0): recv signal r_respond 407 Proxy Authentication Required
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x123cfc0, ...) 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::0x123cfc0) called
tport.c:3257 tport_tsend() tport_tsend(0x13196a0) tpn = UDP/192.168.1.156:5062
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.156:5062
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x13196a0): not found by name UDP/192.168.1.156:5062
tport.c:3594 tport_vsend() tport_vsend(0x13196a0): 789 bytes of 789 to udp/192.168.1.156:5062
tport.c:3492 tport_send_msg() tport_vsend returned 789
nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x12099d0): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x12099d0): call state changed: received -> terminated
nua_stack.c:271 nua_stack_event() nua(0x12099d0): event i_state 407 Proxy Authentication Required
nua_stack.c:271 nua_stack_event() nua(0x12099d0): event i_terminated 407 Proxy Authentication Required
soa.c:356 soa_destroy() soa_destroy(static::0x123cfc0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x1289530)
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-10-12 20:27:11.485457 [DEBUG] sofia.c:2334 detaching session 9626d8bb-97d1-4b43-b588-0ec2a561bedc
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x12099d0): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x12099d0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0x12099d0): 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-10-12 20:27:11.485457 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1002@192.168.1.118) State NEW
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x13196a0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x13196a0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x13196a0) msg 0x1397050 from (udp/192.168.1.118:5060) has 274 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x13196a0): msg 0x1397050 (274 bytes) from udp/192.168.1.156:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:3000@192.168.1.118:5060 SIP/2.0 (CSeq 1)
nta.c:3019 agent_recv_request() nta: ACK (1) is going to INVITE (1)
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x13196a0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x13196a0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x13196a0) msg 0x1397050 from (udp/192.168.1.118:5060) has 1104 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x13196a0): msg 0x1397050 (1104 bytes) from udp/192.168.1.156:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:3000@192.168.1.118:5060 SIP/2.0 (CSeq 2)
nta.c:3248 agent_aliases() nta: canonizing sip:3000@192.168.1.118:5060 with contact
nta.c:3085 agent_recv_request() nta: INVITE (2) 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::0x120fea0, 0x11f8990, 0x1315880) called
soa.c:403 soa_set_params() soa_set_params(static::0x123cfc0, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x1212830)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x123cfc0) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x123cfc0, (nil), 0x10f5b0b, 261) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x1315880): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x13196a0) tpn = UDP/192.168.1.156:5062
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.156:5062
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x13196a0): not found by name UDP/192.168.1.156:5062
tport.c:3594 tport_vsend() tport_vsend(0x13196a0): 285 bytes of 285 to udp/192.168.1.156:5062
tport.c:3492 tport_send_msg() tport_vsend returned 285
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (2)
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x1315880): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x123cfc0, [0x7f86c53328c8], [0x7f86c53328d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_state 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-10-12 20:27:11.645458 [DEBUG] sofia.c:2442 Re-attaching to session 9626d8bb-97d1-4b43-b588-0ec2a561bedc
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.645458 [DEBUG] sofia.c:9837 sofia/internal/1002@192.168.1.118 receiving invite from 192.168.1.156:5062 version: 1.6.18  64bit
2017-10-12 20:27:11.645458 [DEBUG] sofia.c:10008 IP 192.168.1.156 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-10-12 20:27:11.645458 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@192.168.1.118 entering state [received][100]
2017-10-12 20:27:11.645458 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20020 20020 IN IP4 192.168.1.156
s=SDP data
c=IN IP4 192.168.1.156
t=0 0
m=audio 11798 RTP/AVP 0 4 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-10-12 20:27:11.645458 [DEBUG] sofia.c:7450 (sofia/internal/1002@192.168.1.118) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.1.118) Running State Change CS_INIT (Cur 2 Tot 86)
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.1.118) State INIT
2017-10-12 20:27:11.645458 [DEBUG] mod_sofia.c:90 sofia/internal/1002@192.168.1.118 SOFIA INIT
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@192.168.1.118 Standard INIT
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@192.168.1.118) State Change CS_INIT -> CS_ROUTING
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.1.118) State INIT going to sleep
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.1.118) Running State Change CS_ROUTING (Cur 2 Tot 86)
2017-10-12 20:27:11.645458 [DEBUG] switch_channel.c:2249 (sofia/internal/1002@192.168.1.118) Callstate Change DOWN -> RINGING
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.1.118) State ROUTING
2017-10-12 20:27:11.645458 [DEBUG] mod_sofia.c:143 sofia/internal/1002@192.168.1.118 SOFIA ROUTING
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1002@192.168.1.118 Standard ROUTING
2017-10-12 20:27:11.645458 [INFO] mod_dialplan_xml.c:637 Processing mayur <1002>->3000 in context default
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1002@192.168.1.118 Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1002@192.168.1.118 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [global-intercept] destination_number(3000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [group-intercept] destination_number(3000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [intercept-ext] destination_number(3000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->redial] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [redial] destination_number(3000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->global] continue=true
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never
Dialplan: sofia/internal/1002@192.168.1.118 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/1002@192.168.1.118 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 20020 20020 IN IP4 192.168.1.156
s=SDP data
c=IN IP4 192.168.1.156
t=0 0
m=audio 11798 RTP/AVP 0 4 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1002@192.168.1.118 Absolute Condition [global]
Dialplan: sofia/internal/1002@192.168.1.118 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1002@192.168.1.118 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1002@192.168.1.118 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1002@192.168.1.118 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [snom-demo-2] destination_number(3000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [snom-demo-1] destination_number(3000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [eavesdrop] destination_number(3000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [eavesdrop] destination_number(3000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [call_return] destination_number(3000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [del-group] destination_number(3000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [add-group] destination_number(3000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [call-group-simo] destination_number(3000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [call-group-order] destination_number(3000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [extension-intercom] destination_number(3000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [Local_Extension] destination_number(3000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [Local_Extension_Skinny] destination_number(3000) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->group_dial_sales] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [group_dial_sales] destination_number(3000) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->group_dial_support] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [group_dial_support] destination_number(3000) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->group_dial_billing] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [group_dial_billing] destination_number(3000) =~ /^2002$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->operator] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [operator] destination_number(3000) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->vmain] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [vmain] destination_number(3000) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (FAIL) [sip_uri] destination_number(3000) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/1002@192.168.1.118 Regex (PASS) [nb_conferences] destination_number(3000) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.1.118 Action answer() 
Dialplan: sofia/internal/1002@192.168.1.118 Action conference(3000-${domain_name}@default) 
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1002@192.168.1.118) State Change CS_ROUTING -> CS_EXECUTE
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.1.118) State ROUTING going to sleep
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.1.118) Running State Change CS_EXECUTE (Cur 2 Tot 86)
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1002@192.168.1.118) State EXECUTE
2017-10-12 20:27:11.645458 [DEBUG] mod_sofia.c:198 sofia/internal/1002@192.168.1.118 SOFIA EXECUTE
2017-10-12 20:27:11.645458 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1002@192.168.1.118 Standard EXECUTE
EXECUTE sofia/internal/1002@192.168.1.118 hash(insert/192.168.1.118-spymap/1002/9626d8bb-97d1-4b43-b588-0ec2a561bedc)
EXECUTE sofia/internal/1002@192.168.1.118 hash(insert/192.168.1.118-last_dial/1002/3000)
EXECUTE sofia/internal/1002@192.168.1.118 hash(insert/192.168.1.118-last_dial/global/9626d8bb-97d1-4b43-b588-0ec2a561bedc)
EXECUTE sofia/internal/1002@192.168.1.118 export(RFC2822_DATE=Thu, 12 Oct 2017 20:27:11 +0530)
2017-10-12 20:27:11.645458 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 12 Oct 2017 20:27:11 +0530]
EXECUTE sofia/internal/1002@192.168.1.118 answer()
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:3057 Set Codec sofia/internal/1002@192.168.1.118 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-10-12 20:27:11.645458 [DEBUG] switch_core_codec.c:111 sofia/internal/1002@192.168.1.118 Original read codec set to PCMU:0
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:4763 sofia/internal/1002@192.168.1.118 Set 2833 dtmf send payload to 101 recv payload to 101
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/internal/1002@192.168.1.118] 192.168.1.118 port 32036 -> 192.168.1.156 port 11798 codec: 0 ms: 20
2017-10-12 20:27:11.645458 [DEBUG] switch_rtp.c:4108 Starting timer [soft] 160 bytes per 20ms
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:7175 sofia/internal/1002@192.168.1.118 Set 2833 dtmf send payload to 101
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:7182 sofia/internal/1002@192.168.1.118 Set 2833 dtmf receive payload to 101
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:7205 sofia/internal/1002@192.168.1.118 Set rtp dtmf delay to 40
2017-10-12 20:27:11.645458 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1002@192.168.1.118!
2017-10-12 20:27:11.645458 [DEBUG] switch_channel.c:3474 (sofia/internal/1002@192.168.1.118) Callstate Change RINGING -> EARLY
2017-10-12 20:27:11.645458 [DEBUG] switch_core_media.c:6857 Audio params are unchanged for sofia/internal/1002@192.168.1.118.
2017-10-12 20:27:11.645458 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1002@192.168.1.118:
v=0
o=FreeSWITCH 1507788195 1507788196 IN IP4 192.168.1.118
s=FreeSWITCH
c=IN IP4 192.168.1.118
t=0 0
m=audio 32036 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x1315880): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x123cfc0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x123cfc0, (nil), 0x1650352, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x123cfc0, (nil), 0x1650352, -1) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x123cfc0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x123cfc0, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x123cfc0, soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x123cfc0, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f86c5330b00, 0x1538c30, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x123cfc0, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x123cfc0, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x123cfc0, [(nil)], [0x7f86c5332c38], [0x7f86c5332c34]) called
tport.c:3257 tport_tsend() tport_tsend(0x13196a0) tpn = UDP/192.168.1.156:5062
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.156:5062
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x13196a0): not found by name UDP/192.168.1.156:5062
tport.c:3594 tport_vsend() tport_vsend(0x13196a0): 1064 bytes of 1064 to udp/192.168.1.156:5062
tport.c:3492 tport_send_msg() tport_vsend returned 1064
nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (2)
nua_session.c:4139 signal_call_state_change() nua(0x1315880): call state changed: received -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x123cfc0, [0x7f86c5332ce8], [0x7f86c5332cf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x123cfc0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x1315880): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.645458 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@192.168.1.118 entering state [completed][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.645458 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/1002@192.168.1.118] has been answered
2017-10-12 20:27:11.665452 [DEBUG] switch_channel.c:3773 (sofia/internal/1002@192.168.1.118) Callstate Change EARLY -> ACTIVE
EXECUTE sofia/internal/1002@192.168.1.118 conference(3000-192.168.1.118@default)
2017-10-12 20:27:11.665452 [DEBUG] conference_member.c:1690 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-10-12 20:27:11.665452 [DEBUG] conference_member.c:1737 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-10-12 20:27:11.665452 [DEBUG] switch_core_codec.c:223 sofia/internal/1002@192.168.1.118 Push codec L16:100
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '0' to 'mute'
2017-10-12 20:27:11.685455 [INFO] switch_ivr_async.c:214 Digit parser mod_conference: Setting realm to 'conf'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 0/conf/0 callback: 0x7f86c783eb40 data: 0x1688c98
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '*' to 'deaf mute'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding */conf/0 callback: 0x7f86c783eb40 data: 0x1688cc8
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '9' to 'energy up'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 9/conf/0 callback: 0x7f86c783eb40 data: 0x1688cf8
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '8' to 'energy equ'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 8/conf/0 callback: 0x7f86c783eb40 data: 0x1688d28
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '7' to 'energy dn'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 7/conf/0 callback: 0x7f86c783eb40 data: 0x1688d58
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '3' to 'vol talk up'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 3/conf/0 callback: 0x7f86c783eb40 data: 0x1688d88
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '2' to 'vol talk zero'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 2/conf/0 callback: 0x7f86c783eb40 data: 0x1688db8
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '1' to 'vol talk dn'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 1/conf/0 callback: 0x7f86c783eb40 data: 0x1688de8
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '6' to 'vol listen up'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 6/conf/0 callback: 0x7f86c783eb40 data: 0x1688e18
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '5' to 'vol listen zero'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 5/conf/0 callback: 0x7f86c783eb40 data: 0x1688e48
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '4' to 'vol listen dn'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding 4/conf/0 callback: 0x7f86c783eb40 data: 0x1688e78
2017-10-12 20:27:11.685455 [DEBUG] conference_member.c:128 sofia/internal/1002@192.168.1.118 binding '#' to 'execute_application'
2017-10-12 20:27:11.685455 [DEBUG] switch_ivr_async.c:323 Digit parser mod_conference: binding #/conf/0 callback: 0x7f86c783eb40 data: 0x1688ea8
2017-10-12 20:27:11.685455 [DEBUG] conference_loop.c:1140 Setup timer soft success interval: 20  samples: 160 from codec PCMU
nta.c:1296 agent_timer() nta: timer set next to 475 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x13196a0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x13196a0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x13196a0) msg 0x11433d0 from (udp/192.168.1.118:5060) has 639 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x13196a0): msg 0x11433d0 (639 bytes) from udp/192.168.1.156:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:3000@192.168.1.118:5060;transport=udp SIP/2.0 (CSeq 2)
nta.c:3019 agent_recv_request() nta: ACK (2) is going to INVITE (2)
nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x123cfc0) called
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_ack 200 OK
nua_session.c:4139 signal_call_state_change() nua(0x1315880): call state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x1315880): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: 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:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:11.905454 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@192.168.1.118 entering state [ready][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-10-12 20:27:12.025456 [DEBUG] switch_rtp.c:7254 Correct audio ip/port confirmed.
nta.c:1296 agent_timer() nta: timer set next to 4405 ms
nta.c:7134 _nta_incoming_timer() nta: timer I fired, terminate 407 response
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f86c5332c60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 330 ms
nta.c:7134 _nta_incoming_timer() nta: timer I fired, terminate 200 response
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f86c5332c60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set