root@fpbx01:~# fs_cli .=======================================================. | _____ ____ ____ _ ___ | | | ___/ ___| / ___| | |_ _| | | | |_ \___ \ | | | | | | | | | _| ___) | | |___| |___ | | | | |_| |____/ \____|_____|___| | | | .=======================================================. | Anthony Minessale II, Ken Rice, | | Michael Jerris, Travis Cross | | FreeSWITCH (http://www.freeswitch.org) | | Paypal Donations Appreciated: paypal@freeswitch.org | | Brought to you by ClueCon http://www.cluecon.com/ | .=======================================================. .=======================================================================================================. | _ _ ____ _ ____ | | / \ _ __ _ __ _ _ __ _| | / ___| |_ _ ___ / ___|___ _ __ | | / _ \ | '_ \| '_ \| | | |/ _` | | | | | | | | |/ _ \ | / _ \| '_ \ | | / ___ \| | | | | | | |_| | (_| | | | |___| | |_| | __/ |__| (_) | | | | | | /_/ \_\_| |_|_| |_|\__,_|\__,_|_| \____|_|\__,_|\___|\____\___/|_| |_| | | | | ____ _____ ____ ____ __ | | | _ \_ _/ ___| / ___|___ _ __ / _| ___ _ __ ___ _ __ ___ ___ | | | |_) || || | | | / _ \| '_ \| |_ / _ \ '__/ _ \ '_ \ / __/ _ \ | | | _ < | || |___ | |__| (_) | | | | _| __/ | | __/ | | | (_| __/ | | |_| \_\|_| \____| \____\___/|_| |_|_| \___|_| \___|_| |_|\___\___| | | | | ____ _ ____ | | / ___| |_ _ ___ / ___|___ _ __ ___ ___ _ __ ___ | | | | | | | | |/ _ \ | / _ \| '_ \ / __/ _ \| '_ ` _ \ | | | |___| | |_| | __/ |__| (_) | | | | _ | (_| (_) | | | | | | | | \____|_|\__,_|\___|\____\___/|_| |_| (_) \___\___/|_| |_| |_| | | | .=======================================================================================================. Type /help to see a list of commands +OK log level [7] freeswitch@fpbx01> hello -ERR hello Command not found! freeswitch@fpbx01> sofia loglevel all 9 Sofia log level for component [all] has been set to [9] freeswitch@fpbx01> sofia global siptrace on +OK Global siptrace on nua.c:575 nua_set_params() nua: nua_set_params: entering freeswitch@fpbx01> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params freeswitch@fpbx01> nua.c:575 nua_set_params() nua: nua_set_params: entering freeswitch@fpbx01> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params freeswitch@fpbx01> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@fpbx01> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params freeswitch@fpbx01> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@fpbx01> soa.c:403 soa_set_params() soa_set_params(static::0x7fce54084150, ...) called freeswitch@fpbx01> soa.c:403 soa_set_params() soa_set_params(static::0x7fce74005a30, ...) called freeswitch@fpbx01> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK freeswitch@fpbx01> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK freeswitch@fpbx01> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@fpbx01> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@fpbx01> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@fpbx01> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params freeswitch@fpbx01> nua.c:575 nua_set_params() nua: nua_set_params: entering freeswitch@fpbx01> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params freeswitch@fpbx01> nua.c:575 nua_set_params() nua: nua_set_params: entering freeswitch@fpbx01> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params freeswitch@fpbx01> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@fpbx01> soa.c:403 soa_set_params() soa_set_params(static::0x7fce40001930, ...) called freeswitch@fpbx01> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params freeswitch@fpbx01> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@fpbx01> soa.c:403 soa_set_params() soa_set_params(static::0x7fce60096e10, ...) called freeswitch@fpbx01> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK freeswitch@fpbx01> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK freeswitch@fpbx01> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@fpbx01> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@fpbx01> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params freeswitch@fpbx01> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@fpbx01> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@fpbx01> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@fpbx01> tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1 tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 4 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 4 bytes, veclen = 1 tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> nta.c:1296 agent_timer() nta: timer set next to 6609 ms nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE (5318782) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free nta.c:1296 agent_timer() nta: timer set next to 1 ms nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK (5318782) tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free nta.c:1289 agent_timer() nta: timer not set tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1 tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1248 bytes, veclen = 1 tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 259 bytes, veclen = 1 recv 1507 bytes from tcp/[10.55.4.5]:55848 at 15:33:16.358341: ------------------------------------------------------------------------ INVITE sip:7667398@10.55.4.7:5080 SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: Date: Wed, 05 Jun 2019 14:33:16 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 Supported: timer,resource-priority,replaces Min-SE: 1800 User-Agent: Cisco-CUCM10.5 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 101 INVITE Expires: 180 Allow-Events: presence, kpml Supported: X-cisco-srtp-fallback,X-cisco-original-called Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=500" Call-Info: ;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED Cisco-Guid: 3653460864-0000065536-0000003112-0084162314 Session-Expires: 1800 P-Asserted-Identity: "Stephen Barry" Remote-Party-ID: "Stephen Barry" ;party=calling;screen=yes;privacy=off Contact: Max-Forwards: 70 Content-Type: application/sdp Content-Length: 360 v=0 o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5 s=SIP Call c=IN IP4 10.55.102.51 b=TIAS:64000 b=AS:64 t=0 0 m=audio 16670 RTP/AVP 9 8 0 116 18 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:116 iLBC/8000 a=maxptime:60 a=fmtp:116 mode=20 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1507 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080 SIP/2.0 (CSeq 101) nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact nta.c:3085 agent_recv_request() nta: INVITE (101) 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:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce74005a30, 0x7fce7400d770, 0x7fce74002fd0) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce740033f0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a9b, 360) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce74002fd0): adding session usage nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: init -> received, received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): 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 2019-06-05 15:33:16.509165 [NOTICE] switch_channel.c:1104 New Channel sofia/external-lan/7398@10.55.4.5 [6efa6b88-248e-4a15-afca-09df2beb867e] nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_NEW (Cur 1 Tot 313) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10092 sofia/external-lan/7398@10.55.4.5 receiving invite from 10.55.4.5:55848 version: 1.8.5 -6-31281a0bf1 64bit 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10208 IP 10.55.4.5 Approved by acl "domains[]". Access Granted. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100] 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5 s=SIP Call c=IN IP4 10.55.102.51 b=TIAS:64000 b=AS:64 t=0 0 m=audio 16670 RTP/AVP 9 8 0 116 18 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:116 iLBC/8000 a=fmtp:116 mode=20 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:60 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:3781 Set Codec sofia/external-lan/7398@10.55.4.5 G722/8000 20 ms 160 samples 64000 bits 1 channels 2019-06-05 15:33:16.509165 [DEBUG] switch_core_codec.c:111 sofia/external-lan/7398@10.55.4.5 Original read codec set to G722:9 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7716 (sofia/external-lan/7398@10.55.4.5) State Change CS_NEW -> CS_INIT nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:603 (sofia/external-lan/7398@10.55.4.5) State NEW 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_INIT (Cur 1 Tot 313) 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:93 sofia/external-lan/7398@10.55.4.5 SOFIA INIT 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:40 sofia/external-lan/7398@10.55.4.5 Standard INIT 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:48 (sofia/external-lan/7398@10.55.4.5) State Change CS_INIT -> CS_ROUTING 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT going to sleep 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313) 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:2249 (sofia/external-lan/7398@10.55.4.5) Callstate Change DOWN -> RINGING 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 337 bytes of 337 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 337 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context public send 337 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.359409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 101 INVITE User-Agent: FreeSWITCH Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (101) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->caller-details] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [caller-details] () =~ // break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound) 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_destination=${destination_number}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_destination=7667398) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_destination]=[7667398] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_name=${caller_id_name}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_name=Stephen Barry) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_name]=[Stephen Barry] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_number=${caller_id_number}) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->7667398] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [7667398] destination_number(7667398) =~ /^(7667398)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound) 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_uuid]=[4772272a-5245-454d-8520-d9e852b4c5a2] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_name=voip.mydomain.com) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_name=voip.mydomain.com) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_name]=[voip.mydomain.com] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Action transfer(7667398 XML voip.mydomain.com) 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313) 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_number=7398) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_number]=[7398] EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 transfer(7667398 XML voip.mydomain.com) 2019-06-05 15:33:16.509165 [DEBUG] switch_ivr.c:2207 (sofia/external-lan/7398@10.55.4.5) State Change CS_EXECUTE -> CS_ROUTING 2019-06-05 15:33:16.509165 [NOTICE] switch_ivr.c:2214 Transfer sofia/external-lan/7398@10.55.4.5 to XML[7667398@voip.mydomain.com] 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313) 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context voip.mydomain.com Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_exists] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_exists=true) 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_exists]=[true] Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(extension_uuid=d268f1c9-32b4-46c7-8c22-74012c9929ac) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [extension_uuid]=[d268f1c9-32b4-46c7-8c22-74012c9929ac] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(hold_music=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hold_music]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_destination=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_destination]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_enabled=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_enabled]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_destination=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_destination]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_enabled=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_enabled]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_destination=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_destination]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_enabled=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_enabled]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_destination=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_destination]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=) 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(do_not_disturb=) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [do_not_disturb]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_timeout=30) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_timeout]=[30] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_app=) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_app]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_data=) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_data]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(toll_allow=) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [toll_allow]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_screen_enabled=false) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_screen_enabled]=[false] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_record=) 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_record]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->caller-details] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [caller-details] ${caller_destination}(7667398) =~ /^$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-direction] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->variables] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_record] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(from_user_exists=false) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [from_user_exists]=[false] Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->redial] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [redial] destination_number(7667398) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->speed_dial] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [speed_dial] destination_number(7667398) =~ /^\*0(.*)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->default_caller_id] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_name=) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_name]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_number=) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_number]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_name=) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_name]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_number=) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_number]=[UNDEF] Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.d4] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.d4] ${user_exists}(true) =~ /false/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.10.05800] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.10.05800] ${user_exists}(true) =~ /false/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status] destination_number(7667398) =~ /^\*22$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status_id] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status_id] destination_number(7667398) =~ /^\*23$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->group-intercept] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [group-intercept] destination_number(7667398) =~ /^\*8$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->page-extension] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [page-extension] destination_number(7667398) =~ /^\*8(\d{2,7})$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->eavesdrop] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [eavesdrop] destination_number(7667398) =~ /^\*33(\d{2,7})$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_privacy] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_privacy] destination_number(7667398) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_return] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_return] destination_number(7667398) =~ /^\*69$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext-polycom] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext-polycom] destination_number(7667398) =~ /^\*97(\d+)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*(\d+)$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension_queue] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension_queue] destination_number(7667398) =~ /^\*800(.*)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->dx] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [dx] destination_number(7667398) =~ /^dx$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->att_xfer] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [att_xfer] destination_number(7667398) =~ /^att_xfer$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->send_to_voicemail] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [send_to_voicemail] destination_number(7667398) =~ /^\*99(\d{2,10})$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension-to-voicemail] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] username(7398) =~ /^7398$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension-to-voicemail] destination_number(7667398) =~ /^7398$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->xfer_vm] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [xfer_vm] destination_number(7667398) =~ /^xfer_vm$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^vmain$|^\*4000$|^\*98$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain_user] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain_user] destination_number(7667398) =~ /^\*97$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_transfer] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_transfer] destination_number(7667398) =~ /^is_transfer$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->delay_echo] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [delay_echo] destination_number(7667398) =~ /^\*9195$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->cf] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [cf] destination_number(7667398) =~ /^cf$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->echo] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [echo] destination_number(7667398) =~ /^\*9196$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->milliwatt] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [milliwatt] destination_number(7667398) =~ /^\*9197$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_zrtp_secure] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 ANTI-Action eval(not_secure) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_secure] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_secure] ${sip_via_protocol}(tcp) =~ /tls/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->tone_stream] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [tone_stream] destination_number(7667398) =~ /^\*9198$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->hold_music] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [hold_music] destination_number(7667398) =~ /^\*9664$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->recordings] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [recordings] destination_number(7667398) =~ /^\*(732)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->directory] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [directory] destination_number(7667398) =~ /^\*411$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->wake-up] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [wake-up] destination_number(7667398) =~ /^\*(925)$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->valet_park] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator] destination_number(7667398) =~ /^0$|^operator$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator-forward] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator-forward] destination_number(7667398) =~ /^\*000$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->do-not-disturb] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*77$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*78$|\*363$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*79$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^dnd\+7398$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-forward] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*72$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*73$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*74$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^forward\+(\Q7398\E)(?:\/(\d+))?$/ break=on-true Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call forward all] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call forward all] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call forward all] ${forward_all_enabled}() =~ /true/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->follow-me] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [follow-me] destination_number(7667398) =~ /^\*21$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->clear_sip_auto_answer] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date and time] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date and time] destination_number(7667398) =~ /^\*9172$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock time] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock time] destination_number(7667398) =~ /^\*9170$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date] destination_number(7667398) =~ /^\*9171$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_screen] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->local_extension] continue=true Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(dialed_extension=${destination_number}) INLINE EXECUTE sofia/external-lan/7398@10.55.4.5 export(dialed_extension=7667398) 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[7667398] Dialplan: sofia/external-lan/7398@10.55.4.5 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(rtp_secure_media=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(rtp_secure_media=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] () =~ // break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true) Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(api_hangup_hook=lua app.lua hangup) Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(domain_name=${domain_name}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action bridge(user/${destination_number}@${domain_name}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua failure_handler) Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->voicemail] continue=false Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(record_append=false) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_action=save) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_id=${destination_number}) Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_profile=default) Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua voicemail) 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313) 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE EXECUTE sofia/external-lan/7398@10.55.4.5 export(origination_callee_id_name=7667398) 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[7667398] EXECUTE sofia/external-lan/7398@10.55.4.5 set(RFC2822_DATE=Wed, 05 Jun 2019 15:33:16 +0100) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [RFC2822_DATE]=[Wed, 05 Jun 2019 15:33:16 +0100] EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial/7398/7667398) EXECUTE sofia/external-lan/7398@10.55.4.5 eval(not_secure) EXECUTE sofia/external-lan/7398@10.55.4.5 limit(hash voip.mydomain.com 7667398 ) 2019-06-05 15:33:16.569170 [DEBUG] switch_limit.c:126 incr called: voip.mydomain.com_7667398 max:-1, interval:0 2019-06-05 15:33:16.569170 [DEBUG] mod_hash.c:194 Usage for voip.mydomain.com_7667398 is now 1 EXECUTE sofia/external-lan/7398@10.55.4.5 set(rtp_secure_media=true) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [rtp_secure_media]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 export(rtp_secure_media=true) 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [rtp_secure_media]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true] EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-call_return/7667398/7398) EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial_ext/7667398/6efa6b88-248e-4a15-afca-09df2beb867e) EXECUTE sofia/external-lan/7398@10.55.4.5 set(called_party_call_group=) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [called_party_call_group]=[UNDEF] EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial//6efa6b88-248e-4a15-afca-09df2beb867e) EXECUTE sofia/external-lan/7398@10.55.4.5 set(api_hangup_hook=lua app.lua hangup) 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [api_hangup_hook]=[lua app.lua hangup] EXECUTE sofia/external-lan/7398@10.55.4.5 export(domain_name=voip.mydomain.com) 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[voip.mydomain.com] EXECUTE sofia/external-lan/7398@10.55.4.5 bridge(user/7667398@voip.mydomain.com) 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables 2019-06-05 15:33:16.569170 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/7667398@185.39.248.196:2658 [ed928a3a-dd04-4402-979f-fafeb5f358be] 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:5019 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_NEW -> CS_INIT 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_INIT (Cur 2 Tot 314) 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:93 sofia/internal/7667398@185.39.248.196:2658 SOFIA INIT 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:faMAxHTT6xDoJK8DG73nmIUiV6vOV5VlZoIbT3R78Sheqtqx/wHBkkCyYPo=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [1 AEAD_AES_256_GCM_8 inline:QrHLk+2xbt+WkyRhJS83PIvqTPYaOVIhxFWkuON5ouNG/9N+M9dZWic9gbI=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [2 AEAD_AES_128_GCM_8 inline:4tayk1/aJmWWBCPxKb6uc/oGDK7xoBldZYU9yw==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [2 AEAD_AES_128_GCM_8 inline:LnAqV/YThGG5+O+aaIYB9eTBv5jbwa+EMqer4w==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:azOC6kxeppg9ZO09Qg+mw/7YWCVvx93U3HiKGUqY1ZP2bE/L0IPgmbtAE5gyaQ==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:ztZhc1/jJ7zSRK7co49aXvAXdd7A5d4c46Yl9eEDlc++s6mtpZqTvyIEoBKT/g==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:S3fooEDZ43IEd93bwM4y/lAKHIFwjgc1Oa8yCl9YrAelsD99uGE=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:uaOx/NSQpRl9+UbNiAC3p6N2cYjavh/ai7LCm42DdacMXJH7d7g=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:2GqvJpVS1GbdKdRWRCxHFrPklrTBXn1N6u8DyA/Q] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:Lk2H537S/4alzeJJM/7olJj7K0XcPBx7GkUmnEvM] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:yL1fqzga6CRH1TCisIgdgNkrtCkr1IKAOj+NOsGvJA7CWio8vQTnE5Wtx8keHQ==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:rhqYIdU+/AtoDOvLtpw6xBnuyoIz2gQc/hppkjM+kPi4F2R5dxlQZK0UlvNUlQ==] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:GmJdY0oDa1u5KXLocLT38x3ybXHkDDzDFo8HewOk0uZqvR2et6M=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:6ueP5qf7Tdj/PLHI0Nb0pTFrMTlT1qj2weBcrLMF/X/t9c9Y3Ss=] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:EbCU7W6c2iU5bDSIGdEaXJJCBbooZVNE6yHAKegu] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:PsTZCAm6QE5Uyp2B8TK5qhmmwGAC9gD89JYRFCxE] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [9 AES_CM_128_NULL_AUTH inline:WPUvScKp4hkNaGVgmwQZrSoIhsmi88d6KmVYTRu9] 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [9 AES_CM_128_NULL_AUTH inline:u2vFsaUv8vSDHNufV+j1Hc374p+Jqyv0cfMY7r8v] nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1271 sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls Setting proxy route to sofia/internal/7667398@185.39.248.196:2658 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1302 sofia/internal/7667398@185.39.248.196:2658 sending invite version: 1.8.5 -6-31281a0bf1 64bit Local SDP: v=0 o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165 s=FreeSWITCH c=IN IP4 185.39.250.165 t=0 0 m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106 a=rtpmap:9 G722/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60 a=rtpmap:104 opus/48000/2 a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:105 telephone-event/48000 a=fmtp:105 0-16 a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw= a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg== a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw== a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU= a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61 a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA== a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE= a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH a=rtpmap:13 CN/8000 a=rtpmap:106 CN/48000 a=ptime:20 a=sendrecv nua.c:633 nua_invite() nua: nua_invite: entering nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_invite nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6c02f9a0) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_invite 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:40 sofia/internal/7667398@185.39.248.196:2658 Standard INIT 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_INIT -> CS_ROUTING 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT going to sleep nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6c02f9a0): adding session usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce60050880) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce600921a0, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_generate_offer): called soa_static.c:1189 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): generating local description soa_static.c:1217 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b73ca70, (nil), ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [(nil)], [0x7fce6b73ebf8], [0x7fce6b73ebf4]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658 tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658 tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60061910 993 (993) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b1c0 68 (68) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60074d90 1697 (1697) tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 2758 bytes of 2758 to tls/185.39.248.196:2658 tport.c:3496 tport_send_msg() tport_vsend returned 2758 send 2758 bytes to tls/[185.39.248.196]:2658 at 15:33:16.418836: ------------------------------------------------------------------------ INVITE sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls SIP/2.0 Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKaFrX8FtHvD96Q Route: ;rinstance=117BFF20;transport=tls Max-Forwards: 68 From: "Stephen Barry" ;tag=pU8rDB8DUHjFe To: 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_ROUTING (Cur 2 Tot 314) Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318806 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 1697 X-FS-Support: update_display,send_info P-Asserted-Identity: "Stephen Barry" v=0 o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165 s=FreeSWITCH c=IN IP4 185.39.250.165 t=0 0 m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106 a=rtpmap:9 G722/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60 a=rtpmap:104 opus/48000/2 a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=rtpmap:105 telephone-event/48000 a=fmtp:105 0-16 a=rtpmap:106 CN/48000 a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw= a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg== a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw== a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU= a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61 a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA== a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE= a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer nta.c:8310 outgoing_send() nta: sent INVITE (5318806) to tls/185.39.248.196:2658 tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6008f8c0 for tls/185.39.248.196:2658 (already 0) nta.c:1350 set_timeout() nta: timer set to 32000 ms nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: init -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [0x7fce6b73ebd8], [0x7fce6b73ebe0], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7fce6c02f9a0): event i_state INVITE sent 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:154 sofia/internal/7667398@185.39.248.196:2658 SOFIA ROUTING 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING going to sleep nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 314) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.569170 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA going to sleep tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 421 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 421 bytes, veclen = 1 recv 421 bytes from tls/[185.39.248.196]:2658 at 15:33:16.593739: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165 From: "Stephen Barry" ;tag=pU8rDB8DUHjFe Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318806 INVITE To: User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a) Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (421 bytes) from tls/185.39.248.196:2658/sips next=(nil) nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (5318806) nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 174.962 ms tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary) tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 607 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 607 bytes, veclen = 1 recv 607 bytes from tls/[185.39.248.196]:2658 at 15:33:16.663273: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165 Contact: From: "Stephen Barry" ;tag=pU8rDB8DUHjFe Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318806 INVITE To: ;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a) Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (607 bytes) from tls/185.39.248.196:2658/sips next=(nil) nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (5318806) nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary) nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 180 Ringing nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: calling -> proceeding nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 180 Ringing tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): 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.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 2019-06-05 15:33:16.809164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [proceeding][180] 2019-06-05 15:33:16.809164 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/7667398@185.39.248.196:2658! 2019-06-05 15:33:16.809164 [DEBUG] switch_channel.c:3354 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change DOWN -> RINGING nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.829170 [INFO] switch_ivr_originate.c:1246 Sending early media 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/external-lan/7398@10.55.4.5] 10.55.4.7 port 26324 -> 10.55.102.51 port 16670 codec: 9 ms: 20 2019-06-05 15:33:16.829170 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8815 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8822 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf receive payload to 101 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8845 sofia/external-lan/7398@10.55.4.5 Set rtp dtmf delay to 40 2019-06-05 15:33:16.829170 [DEBUG] mod_sofia.c:2505 Ring SDP: v=0 o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv 2019-06-05 15:33:16.829170 [NOTICE] mod_sofia.c:2508 Pre-Answer sofia/external-lan/7398@10.55.4.5! 2019-06-05 15:33:16.829170 [DEBUG] switch_channel.c:3482 (sofia/external-lan/7398@10.55.4.5) Callstate Change RINGING -> EARLY nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 183 Session Progress nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -1) called 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16@16000hz 1 channel 20ms 2019-06-05 15:33:16.829170 [DEBUG] switch_core_codec.c:223 sofia/external-lan/7398@10.55.4.5 Push codec L16:100 soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -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::0x7fce74014690) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_answer): called soa_static.c:1189 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): generating local description soa_static.c:1230 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): upgrade with remote description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, 0x7fce74015680, ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): storing local description 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1373 Play Ringback Tone [%(2000,4000,440,480)] soa.c:1730 soa_activate() soa_activate(static::0x7fce74014690, (nil)) called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 889 bytes of 889 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 889 send 889 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.682014: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 101 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 158 P-Asserted-Identity: "7667398" v=0 o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 183 Session Progress for INVITE (101) nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: received -> early, sent answer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 183 Session Progress nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.849171 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [early][183] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:16.949164 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. nta.c:1296 agent_timer() nta: timer set next to 58323 ms tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 1017 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60078270 from (tls/185.39.248.196:2658) has 1017 bytes, veclen = 1 recv 1017 bytes from tls/[185.39.248.196]:2658 at 15:33:21.582934: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165 Contact: From: "Stephen Barry" ;tag=pU8rDB8DUHjFe Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318806 INVITE To: ;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path Content-Type: application/sdp User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a) Content-Length: 382 v=0 o=- 2214276607 13634 IN IP4 172.26.170.170 s=qdusifw c=IN IP4 10.71.172.74 t=0 0 m=audio 23288 RTP/SAVP 102 101 a=rtpmap:101 telephone-event/8000 a=rtpmap:102 opus/48000/2 a=fmtp:101 0-15 a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1 a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D a=ptime:20 a=sendrecv ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60078270 (1017 bytes) from tls/185.39.248.196:2658/sips next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (5318806) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60078270 soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce600921a0, (nil), 0x7fce60060d2b, 382) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fce600921a0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_process_answer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6005fff0, 0x7fce6007cb80, ""): called soa_static.c:1304 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): upgrade codecs with remote description soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): storing local description soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called nua_session.c:988 nua_session_client_response() nua(0x7fce6c02f9a0): INVITE: processed SDP answer in 200 OK nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: proceeding -> completing, received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce600921a0, [0x7fce6b73e5e8], [0x7fce6b73e5f0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7fce600921a0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer 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 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [completing][200] 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=- 2214276607 13634 IN IP4 172.26.170.170 s=qdusifw c=IN IP4 10.71.172.74 t=0 0 m=audio 23288 RTP/SAVP 102 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D a=ptime:20 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:7304 Pre-Answer sofia/internal/7667398@185.39.248.196:2658! 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3482 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change RINGING -> EARLY nua.c:639 nua_ack() nua: nua_ack: entering nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_ack nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_ack nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658 tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658 tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60052100 474 (474) tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 474 bytes of 474 to tls/185.39.248.196:2658 tport.c:3496 tport_send_msg() tport_vsend returned 474 send 474 bytes to tls/[185.39.248.196]:2658 at 15:33:21.584434: ------------------------------------------------------------------------ ACK sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0 Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKBrHpaBBNSpZSK Max-Forwards: 70 From: "Stephen Barry" ;tag=pU8rDB8DUHjFe To: ;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318806 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer nta.c:8310 outgoing_send() nta: sent ACK (5318806) to tls/185.39.248.196:2658 nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: completing -> ready nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 ACK sent nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): 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.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [ready][200] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1813 Found suite AES_CM_128_HMAC_SHA1_80 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1883 Set Remote Key [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps] 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps] 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/7667398@185.39.248.196:2658 opus/8000 20 ms 960 samples 0 bits 1 channels 2019-06-05 15:33:21.729164 [DEBUG] switch_core_codec.c:111 sofia/internal/7667398@185.39.248.196:2658 Original read codec set to opus:116 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5795 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101 recv payload to 101 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/7667398@185.39.248.196:2658] 10.66.4.7 port 16948 -> 10.71.172.74 port 23288 codec: 102 ms: 20 2019-06-05 15:33:21.729164 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 960 bytes per 20ms 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8815 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8822 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf receive payload to 101 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8845 sofia/internal/7667398@185.39.248.196:2658 Set rtp dtmf delay to 40 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4104 Activating audio Secure RTP SEND 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4082 Activating audio Secure RTP RECV 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:8429 Channel [sofia/internal/7667398@185.39.248.196:2658] has been answered 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3781 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change EARLY -> ACTIVE 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 2019-06-05 15:33:21.749169 [DEBUG] switch_core_codec.c:248 sofia/external-lan/7398@10.55.4.5 Restore previous codec G722:9. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/external-lan/7398@10.55.4.5. 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:882 Local SDP sofia/external-lan/7398@10.55.4.5: v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=ptime:20 a=sendrecv nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce700443d3, -1) called nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 903 bytes of 903 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 903 send 903 bytes to tcp/[10.55.4.5]:55848 at 15:33:21.600438: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 101 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 158 P-Asserted-Identity: "7667398" v=0 o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (101) nta.c:1348 set_timeout() nta: timer shortened to 500 ms 2019-06-05 15:33:21.749169 [NOTICE] switch_ivr_originate.c:3740 Channel [sofia/external-lan/7398@10.55.4.5] has been answered nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: early -> completed, sent answer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2019-06-05 15:33:21.749169 [DEBUG] switch_channel.c:3781 (sofia/external-lan/7398@10.55.4.5) Callstate Change EARLY -> ACTIVE nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658] 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658] 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_bridge.c:1782 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 314) 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:646 SOFIA EXCHANGE_MEDIA tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74013db0 from (tcp/10.55.4.5:55848) has 463 bytes, veclen = 1 recv 463 bytes from tcp/[10.55.4.5]:55848 at 15:33:21.602290: ------------------------------------------------------------------------ ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60d6ac3319b From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:16 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 User-Agent: Cisco-CUCM10.5 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: presence, kpml Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74013db0 (463 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 101) nta.c:3019 agent_recv_request() nta: ACK (101) is going to INVITE (101) 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::0x7fce74014690) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_ack 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: completed -> ready nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 200 Call active nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) nta.c:5744 incoming_free() nta: incoming_free(0x7fce74003c30) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer 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 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 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 2019-06-05 15:33:21.789165 [NOTICE] switch_core_media.c:15578 Activating write resampler 2019-06-05 15:33:21.809171 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps] 2019-06-05 15:33:21.809171 [NOTICE] switch_core_media.c:15578 Activating write resampler 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[1] PLC[0] FEC[0] 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps] 2019-06-05 15:33:22.009176 [INFO] switch_rtp.c:7510 Auto Changing audio port from 10.71.172.74:23288 to 185.39.248.196:23288 nta.c:1289 agent_timer() nta: timer not set freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fce600466b0): events IN tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7fce600466b0): new secondary tport 0x7fce60053a50 tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPIDLE to 30 tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPINTVL to 30 tport_type_tls.c:610 tport_tls_accept() tport_tls_accept(0x7fce60053a50): new connection from tls/162.243.35.55:64178/sips tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING freeswitch@fpbx01> tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING tport_tls.c:603 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (name): ECDHE-RSA-AES256-SHA tport_tls.c:605 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (version): TLSv1/SSLv3 tport_tls.c:608 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (bits/alg_bits): 256/256 tport_tls.c:611 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (description): ECDHE-RSA-AES256-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(256) Mac=SHA1 tport_tls.c:616 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): Peer did not provide X.509 Certificate. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer freeswitch@fpbx01> tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 542 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600aefb0 from (tls/162.243.35.55:64178) has 542 bytes, veclen = 1 recv 542 bytes from tls/[162.243.35.55]:64178 at 15:33:27.091213: ------------------------------------------------------------------------ REGISTER sip:voip.mydomain.com SIP/2.0 Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport Contact: ;expires=600 Max-Forwards: 70 From: ;tag=0379E1A1DB270E77E864F1CC563F5582 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path To: Expires: 600 Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A CSeq: 3 REGISTER User-Agent: Acrobits SIPIS Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600aefb0 (542 bytes) from tls/162.243.35.55:64178/sips next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 3) nta.c:3085 agent_recv_request() nta: REGISTER (3) 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:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600ae8c0) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600ae8c0): adding registrar usage tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0) nua_stack.c:271 nua_stack_event() nua(0x7fce600ae8c0): event i_register 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer 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:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_respond nua_stack.c:573 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_respond 401 Unauthorized nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering 2019-06-05 15:33:27.249166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55 soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178 tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b08b0 107 (107) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af679 71 (71) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b091b 50 (50) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af748 69 (69) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b094d 313 (313) tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 610 bytes of 610 to tls/162.243.35.55:64178 tport.c:3496 tport_send_msg() tport_vsend returned 610 send 610 bytes to tls/[162.243.35.55]:64178 at 15:33:27.091551: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport=64178 From: ;tag=0379E1A1DB270E77E864F1CC563F5582 To: ;tag=Q41HF6rHrt81S Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A CSeq: 3 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="33412b5e-8a70-4ccf-99e4-385b0439701d", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (3) nta.c:5744 incoming_free() nta: incoming_free(0x7fce600af360) nua_stack.c:569 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_destroy nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600ae8c0): removing registrar usage tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600ae8c0 with (nil) tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083780) called tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 790 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600ae4a0 from (tls/162.243.35.55:64178) has 790 bytes, veclen = 1 recv 790 bytes from tls/[162.243.35.55]:64178 at 15:33:27.163818: ------------------------------------------------------------------------ REGISTER sip:voip.mydomain.com SIP/2.0 Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport Contact: ;expires=600 Max-Forwards: 70 From: ;tag=0379E1A1DB270E77E864F1CC563F5582 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path To: Expires: 600 Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A CSeq: 4 REGISTER Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="33412b5e-8a70-4ccf-99e4-385b0439701d",qop=auth,cnonce="XPfSt9oi6WwqwF0s3uKNQX1I",nc=00000001,response="17317ab4aecbbf1ebd439a089ca22355" User-Agent: Acrobits SIPIS Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600ae4a0 (790 bytes) from tls/162.243.35.55:64178/sips next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 4) nta.c:3085 agent_recv_request() nta: REGISTER (4) 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:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600832c0) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600832c0): adding registrar usage tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0) nua_stack.c:271 nua_stack_event() nua(0x7fce600832c0): event i_register 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 162.243.35.55 You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute and you must configure your device to use the proper domain in it's authentication credentials. nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce600832c0): recv signal r_respond 403 Forbidden nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_respond 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55 tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178 nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b20 104 (104) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad929 71 (71) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b88 50 (50) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad9f8 69 (69) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0bba 189 (189) tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 483 bytes of 483 to tls/162.243.35.55:64178 tport.c:3496 tport_send_msg() tport_vsend returned 483 send 483 bytes to tls/[162.243.35.55]:64178 at 15:33:27.167172: ------------------------------------------------------------------------ SIP/2.0 403 Forbidden Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport=64178 From: ;tag=0379E1A1DB270E77E864F1CC563F5582 To: ;tag=rDUaH19mN3ymN Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A CSeq: 4 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (4) nta.c:5744 incoming_free() nta: incoming_free(0x7fce600afd50) nua_stack.c:569 nua_stack_signal() nua(0x7fce600832c0): recv signal r_destroy nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600832c0): removing registrar usage tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600832c0 with (nil) tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083700) called freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> freeswitch@fpbx01> tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1413 bytes, veclen = 1 recv 1413 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.019210: ------------------------------------------------------------------------ INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:30 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 Supported: timer,resource-priority,replaces User-Agent: Cisco-CUCM10.5 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 102 INVITE Max-Forwards: 70 Expires: 180 Allow-Events: presence Call-Info: ;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED Supported: X-cisco-srtp-fallback Supported: Geolocation Session-Expires: 1800;refresher=uac Min-SE: 1800 P-Asserted-Identity: "Stephen Barry" Remote-Party-ID: "Stephen Barry" ;party=calling;screen=yes;privacy=off Contact: Content-Type: application/sdp Content-Length: 367 v=0 o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5 s=SIP Call c=IN IP4 0.0.0.0 b=TIAS:64000 b=AS:64 t=0 0 m=audio 16670 RTP/AVP 9 8 0 116 18 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:116 iLBC/8000 a=maxptime:60 a=fmtp:116 mode=20 a=rtpmap:18 G729/8000 a=inactive a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1413 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102) nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact nta.c:3060 agent_recv_request() nta: INVITE (102) going to existing 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 soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a36, 367) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer 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:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 355 send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.020262: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 102 INVITE User-Agent: FreeSWITCH Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (102) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100] 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5 s=SIP Call c=IN IP4 0.0.0.0 b=TIAS:64000 b=AS:64 t=0 0 m=audio 16670 RTP/AVP 9 8 0 116 18 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:116 iLBC/8000 a=fmtp:116 mode=20 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=inactive a=maxptime:60 2019-06-05 15:33:30.169172 [WARNING] switch_core_media.c:4877 RFC2543 from March 1999 called; They want their 0.0.0.0 hold method back..... 2019-06-05 15:33:30.169172 [DEBUG] switch_channel.c:1844 (sofia/external-lan/7398@10.55.4.5) Callstate Change ACTIVE -> HELD 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr.c:625 sofia/internal/7667398@185.39.248.196:2658 Command Execute playback(local_stream://default) EXECUTE sofia/internal/7667398@185.39.248.196:2658 playback(local_stream://default) 2019-06-05 15:33:30.309180 [DEBUG] mod_local_stream.c:907 Opening Stream [default/8000] 8000hz 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@8000hz 1 channels 20ms 2019-06-05 15:33:30.329170 [NOTICE] switch_core_media.c:15605 Deactivating write resampler 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1] 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2019-06-05 15:33:30.429173 [WARNING] switch_core_media.c:5551 Crypto not negotiated but required. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101 2019-06-05 15:33:30.429173 [DEBUG] sofia.c:8216 Reinvite resulted in codec negotiation failure. nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 488 Not Acceptable Here nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) 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::0x7fce74014690) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 517 bytes of 517 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 517 send 517 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.270906: ------------------------------------------------------------------------ SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 102 INVITE User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE (102) nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: init nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 488 Not Acceptable Here nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 488 Call active soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: 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 tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 457 bytes, veclen = 1 recv 457 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.271982: ------------------------------------------------------------------------ ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:30 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 User-Agent: Cisco-CUCM10.5 Max-Forwards: 70 CSeq: 102 ACK Allow-Events: presence Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (457 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102) nta.c:3019 agent_recv_request() nta: ACK (102) is going to INVITE (102) tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.489166 [DEBUG] sofia.c:7284 Channel sofia/external-lan/7398@10.55.4.5 skipping state [ready][488] 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 tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 975 bytes, veclen = 1 recv 975 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.405514: ------------------------------------------------------------------------ UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:30 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 User-Agent: Cisco-CUCM10.5 Max-Forwards: 70 Supported: timer,resource-priority,replaces Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 103 UPDATE Call-Info: ;x-cisco-video-traffic-class=MIXED Supported: X-cisco-srtp-fallback Supported: Geolocation Session-Expires: 1800;refresher=uac Min-SE: 1800 P-Asserted-Identity: "Stephen Barry" Remote-Party-ID: "Stephen Barry" ;party=calling;screen=yes;privacy=off Contact: Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (975 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 103) nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact nta.c:3060 agent_recv_request() nta: UPDATE (103) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 606 bytes of 606 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 606 send 606 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.405641: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 103 UPDATE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 200 OK for UPDATE (103) nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_update 200 OK nta.c:5744 incoming_free() nta: incoming_free(0x7fce740885c0) tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74089e30 from (tcp/10.55.4.5:55848) has 1013 bytes, veclen = 1 recv 1013 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.410746: ------------------------------------------------------------------------ INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:30 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 Supported: timer,resource-priority,replaces User-Agent: Cisco-CUCM10.5 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 104 INVITE Max-Forwards: 70 Expires: 180 Allow-Events: presence Call-Info: ;x-cisco-video-traffic-class=MIXED Supported: X-cisco-srtp-fallback Supported: Geolocation Session-Expires: 1800;refresher=uac Min-SE: 1800 P-Asserted-Identity: "Stephen Barry" Remote-Party-ID: "Stephen Barry" ;party=calling;screen=yes;privacy=off Contact: Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74089e30 (1013 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 104) nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact nta.c:3060 agent_recv_request() nta: INVITE (104) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): 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.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.569165 [INFO] sofia.c:1345 sofia/external-lan/7398@10.55.4.5 Update Caller ID to "Stephen Barry" <2036964422> nua.c:366 nua_handle_magic() nua: nua_handle_magic: 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(0x7fce74002fd0): recv signal r_respond 100 Trying nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 355 send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411215: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE User-Agent: FreeSWITCH Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (104) nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.569165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce7009f09b, -1) called nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce74014690, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_offer): called soa_static.c:1217 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, (nil), ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 839 send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411597: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 170 v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=inactive a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (104) nta.c:1348 set_timeout() nta: timer shortened to 500 ms nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: completed sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.629163 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0) tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74088210 from (tcp/10.55.4.5:55848) has 516 bytes, veclen = 1 recv 516 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.491968: ------------------------------------------------------------------------ BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Date: Wed, 05 Jun 2019 14:33:30 GMT Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 User-Agent: Cisco-CUCM10.5 Max-Forwards: 70 P-Asserted-Identity: "Stephen Barry" CSeq: 105 BYE Reason: Q.850;cause=47 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74088210 (516 bytes) from tcp/10.55.4.5:55848/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 105) nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact nta.c:3060 agent_recv_request() nta: BYE (105) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_bye 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:30.709163 [DEBUG] switch_channel.c:2029 (sofia/external-lan/7398@10.55.4.5) Callstate Change HELD -> UNHELD 2019-06-05 15:33:30.709163 [NOTICE] sofia.c:1079 Hangup sofia/external-lan/7398@10.55.4.5 [CS_EXECUTE] [UNKNOWN] 2019-06-05 15:33:30.709163 [DEBUG] mod_hash.c:297 Usage for voip.mydomain.com_7667398 is now 0 nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_destroy tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 472 bytes of 472 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 472 send 472 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.552443: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 105 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:6797 incoming_reply() nta: sent 200 OK for BYE (105) nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce74002fd0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7fce74014690) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce740033f0) nta.c:5744 incoming_free() nta: incoming_free(0x7fce74014f80) nua_stack.c:569 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external-lan/7398@10.55.4.5] 2019-06-05 15:33:30.709163 [NOTICE] switch_ivr_bridge.c:932 Hangup sofia/internal/7667398@185.39.248.196:2658 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1881 sofia/internal/7667398@185.39.248.196:2658 skip receive message [UNBRIDGE] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1884 sofia/external-lan/7398@10.55.4.5 skip receive message [UNBRIDGE] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/external-lan/7398@10.55.4.5 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_HANGUP (Cur 2 Tot 314) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/external-lan/7398@10.55.4.5) Callstate Change UNHELD -> HANGUP 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/external-lan/7398@10.55.4.5 hanging up, cause: UNKNOWN 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/external-lan/7398@10.55.4.5 Standard HANGUP, cause: UNKNOWN 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP going to sleep 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:780 Hangup Command with no Session lua(app.lua hangup): 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/external-lan/7398@10.55.4.5) State Change CS_HANGUP -> CS_REPORTING 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_REPORTING (Cur 2 Tot 314) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_play_say.c:1941 done playing file local_stream://default 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/internal/7667398@185.39.248.196:2658 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:572 sofia/internal/7667398@185.39.248.196:2658 skip receive message [BRIDGE] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr.c:669 sofia/internal/7667398@185.39.248.196:2658 skip receive message [AUDIO_SYNC] (channel is hungup already) 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:831 sofia/internal/7667398@185.39.248.196:2658 ending bridge by request from read function 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/7667398@185.39.248.196:2658] 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA going to sleep 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_HANGUP (Cur 2 Tot 314) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change ACTIVE -> HANGUP 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:443 sofia/internal/7667398@185.39.248.196:2658 Overriding SIP cause 480 with 200 from the other leg 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/internal/7667398@185.39.248.196:2658 hanging up, cause: NORMAL_CLEARING 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/7667398@185.39.248.196:2658 nua.c:645 nua_bye() nua: nua_bye: entering nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_bye nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_bye 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7667398@185.39.248.196:2658 Standard HANGUP, cause: NORMAL_CLEARING soa.c:1784 soa_terminate() soa_terminate(static::0x7fce600921a0) called soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP going to sleep nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658 tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_HANGUP -> CS_REPORTING tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b5c0 606 (606) tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 606 bytes of 606 to tls/185.39.248.196:2658 tport.c:3496 tport_send_msg() tport_vsend returned 606 send 606 bytes to tls/[185.39.248.196]:2658 at 15:33:30.566247: ------------------------------------------------------------------------ BYE sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0 Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKc1aFc6UrpZNcF Max-Forwards: 70 From: "Stephen Barry" ;tag=pU8rDB8DUHjFe To: ;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318807 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=47 Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer nta.c:8310 outgoing_send() nta: sent BYE (5318807) to tls/185.39.248.196:2658 tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6007dec0 for tls/185.39.248.196:2658 (already 0) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_REPORTING (Cur 2 Tot 314) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:174 sofia/internal/7667398@185.39.248.196:2658 Standard REPORTING, cause: NORMAL_CLEARING 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING going to sleep 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_REPORTING -> CS_DESTROY 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:1715 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Locked, Waiting on external entities 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1733 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Ended 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/7667398@185.39.248.196:2658 [CS_DESTROY] 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_DESTROY (Cur 1 Tot 314) 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:354 sofia/internal/7667398@185.39.248.196:2658 SOFIA DESTROY 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[416] PLC[0] FEC[0] 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[436] Bytes encoded[12371] Encoded length ms[8720] Average encoded bitrate bps[12371] 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:181 sofia/internal/7667398@185.39.248.196:2658 Standard DESTROY 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY going to sleep 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:174 sofia/external-lan/7398@10.55.4.5 Standard REPORTING, cause: UNKNOWN 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING going to sleep 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:610 (sofia/external-lan/7398@10.55.4.5) State Change CS_REPORTING -> CS_DESTROY 2019-06-05 15:33:30.729171 [DEBUG] switch_core_session.c:1715 Session 313 (sofia/external-lan/7398@10.55.4.5) Locked, Waiting on external entities 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1733 Session 313 (sofia/external-lan/7398@10.55.4.5) Ended 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1737 Close Channel sofia/external-lan/7398@10.55.4.5 [CS_DESTROY] 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:738 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_DESTROY (Cur 0 Tot 314) 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY 2019-06-05 15:33:30.729171 [DEBUG] mod_sofia.c:354 sofia/external-lan/7398@10.55.4.5 SOFIA DESTROY 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:181 sofia/external-lan/7398@10.55.4.5 Standard DESTROY 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY going to sleep tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 599 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60082d70 from (tls/185.39.248.196:2658) has 599 bytes, veclen = 1 recv 599 bytes from tls/[185.39.248.196]:2658 at 15:33:30.640195: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKc1aFc6UrpZNcF;received=185.39.250.165 Contact: From: "Stephen Barry" ;tag=pU8rDB8DUHjFe Call-ID: b2998455-0241-1238-e9ba-005056860fd6 CSeq: 5318807 BYE To: ;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a) Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60082d70 (599 bytes) from tls/185.39.248.196:2658/sips next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (5318807) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 74.007 ms tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6007dec0 by 0x7fce6007cd00 with 0x7fce60082d70 nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_bye 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: terminating -> terminated nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 to BYE nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_terminated 200 to BYE nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6c02f9a0): removing session usage soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce60050880) nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7fce6c02f9a0 nta.c:8728 outgoing_free() nta: outgoing_free(0x7fce6007cd00) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer 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 nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: 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_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_destroy nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 839 send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.911677: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 170 v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=inactive a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fce6b5eac50) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 1/2 free nta.c:1296 agent_timer() nta: timer set next to 1000 ms tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN tport.c:2159 tport_shutdown0() tport_shutdown0(0x7fce60053a50, 2) tport.c:2092 tport_close() tport_close(0x7fce60053a50): tls/162.243.35.55:64178/sips tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 594 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 594 bytes, veclen = 1 recv 594 bytes from tls/[185.39.250.164]:41117 at 15:33:31.430496: ------------------------------------------------------------------------ REGISTER sip:voip.mydomain.com SIP/2.0 Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport Contact: ;expires=600;video Max-Forwards: 70 From: ;tag=FE14135E45D208D6CE5AC4C4FC9EE551 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path To: Expires: 600 Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA CSeq: 503 REGISTER User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a) Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (594 bytes) from tls/185.39.250.164:41117/sips next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 503) nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164 nta.c:3085 agent_recv_request() nta: REGISTER (503) 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:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce60037d30) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce60037d30): adding registrar usage tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0) nua_stack.c:271 nua_stack_event() nua(0x7fce60037d30): event i_register 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer 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:529 nua_signal() nua(0x7fce60037d30): sent signal r_respond nua_stack.c:573 nua_stack_signal() nua(0x7fce60037d30): recv signal r_respond 401 Unauthorized nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164 nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7fce60037d30): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117 tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722a0 129 (129) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c074e 71 (71) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072321 50 (50) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c081d 71 (71) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072353 313 (313) tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 634 bytes of 634 to tls/185.39.250.164:41117 tport.c:3496 tport_send_msg() tport_vsend returned 634 send 634 bytes to tls/[185.39.250.164]:41117 at 15:33:31.430888: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport=41117;received=185.39.250.164 From: ;tag=FE14135E45D208D6CE5AC4C4FC9EE551 To: ;tag=Spm3jvtrjcN7g Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA CSeq: 503 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (503) nta.c:5744 incoming_free() nta: incoming_free(0x7fce60052510) nua_stack.c:569 nua_stack_signal() nua(0x7fce60037d30): recv signal r_destroy nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce60037d30): removing registrar usage tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce60037d30 with (nil) tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7fce6007cb80) called tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50) tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 842 tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 842 bytes, veclen = 1 recv 842 bytes from tls/[185.39.250.164]:41117 at 15:33:31.442976: ------------------------------------------------------------------------ REGISTER sip:voip.mydomain.com SIP/2.0 Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport Contact: ;expires=600;video Max-Forwards: 70 From: ;tag=FE14135E45D208D6CE5AC4C4FC9EE551 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces, path To: Expires: 600 Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA CSeq: 504 REGISTER Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317",qop=auth,cnonce="XPfSu8WgFUtrKcJ1eXtLtrUz",nc=00000001,response="41f1e87f8e30cd2b0d5cf1b807f361b4" User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a) Content-Length: 0 ------------------------------------------------------------------------ tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (842 bytes) from tls/185.39.250.164:41117/sips next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 504) nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164 nta.c:3085 agent_recv_request() nta: REGISTER (504) 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:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6005d220) called soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6005d220): adding registrar usage tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0) nua_stack.c:271 nua_stack_event() nua(0x7fce6005d220): event i_register 100 Trying tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 185.39.250.164 You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute and you must configure your device to use the proper domain in it's authentication credentials. nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7fce6005d220): recv signal r_respond 403 Forbidden nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117 nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_respond 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164 tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072230 126 (126) nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072ece 71 (71) tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722ae 50 (50) nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072f9d 71 (71) nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722e0 189 (189) tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 507 bytes of 507 to tls/185.39.250.164:41117 tport.c:3496 tport_send_msg() tport_vsend returned 507 send 507 bytes to tls/[185.39.250.164]:41117 at 15:33:31.446079: ------------------------------------------------------------------------ SIP/2.0 403 Forbidden Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport=41117;received=185.39.250.164 From: ;tag=FE14135E45D208D6CE5AC4C4FC9EE551 To: ;tag=tZDvmQBvFNBtc Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA CSeq: 504 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (504) nta.c:5744 incoming_free() nta: incoming_free(0x7fce60037d30) nua_stack.c:569 nua_stack_signal() nua(0x7fce6005d220): recv signal r_destroy nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6005d220): removing registrar usage tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce6005d220 with (nil) tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 839 send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:31.911851: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 170 v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=inactive a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 2000 ms nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 839 send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:33.911871: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 170 v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=inactive a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848 tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848 tport.c:3496 tport_send_msg() tport_vsend returned 839 send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:37.911921: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848 From: "Stephen Barry" ;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925 To: ;tag=7c9UFg3rKvmNQ Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5 CSeq: 104 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 170 v=0 o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7 s=FreeSWITCH c=IN IP4 10.55.4.7 t=0 0 m=audio 26324 RTP/AVP 9 a=rtpmap:9 G722/8000 a=inactive a=ptime:20 ------------------------------------------------------------------------ tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms freeswitch@fpbx01>