.=======================================================. | _____ ____ ____ _ ___ | | | ___/ ___| / ___| | |_ _| | | | |_ \___ \ | | | | | | | | | _| ___) | | |___| |___ | | | | |_| |____/ \____|_____|___| | | | .=======================================================. | 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/ | .=======================================================. .=======================================================================================================. | ____ _ ____ | | / ___| |_ _ ___ / ___|___ _ __ | | | | | | | | |/ _ \ | / _ \| '_ \ | | | |___| | |_| | __/ |__| (_) | | | | | | \____|_|\__,_|\___|\____\___/|_| |_| | | | | _____ _ _ ____ __ | | |_ _|__| | ___ _ __ | |__ ___ _ __ _ _ / ___|___ _ __ / _| ___ _ __ ___ _ __ ___ ___ | | | |/ _ \ |/ _ \ '_ \| '_ \ / _ \| '_ \| | | | | | / _ \| '_ \| |_ / _ \ '__/ _ \ '_ \ / __/ _ \ | | | | __/ | __/ |_) | | | | (_) | | | | |_| | | |__| (_) | | | | _| __/ | | __/ | | | (_| __/ | | |_|\___|_|\___| .__/|_| |_|\___/|_| |_|\__, | \____\___/|_| |_|_| \___|_| \___|_| |_|\___\___| | | |_| |___/ | | _____ _ _ | | | ____|_ _____ _ __ _ _ / \ _ _ __ _ _ _ ___| |_ | | | _| \ \ / / _ \ '__| | | | / _ \| | | |/ _` | | | / __| __| | | | |___ \ V / __/ | | |_| | / ___ \ |_| | (_| | |_| \__ \ |_ | | |_____| \_/ \___|_| \__, | /_/ \_\__,_|\__, |\__,_|___/\__| | | |___/ |___/ | | ____ _ ____ | | __ ____ ____ __ / ___| |_ _ ___ / ___|___ _ __ ___ ___ _ __ ___ | | \ \ /\ / /\ \ /\ / /\ \ /\ / / | | | | | | |/ _ \ | / _ \| '_ \ / __/ _ \| '_ ` _ \ | | \ V V / \ V V / \ V V / _ | |___| | |_| | __/ |__| (_) | | | | _ | (_| (_) | | | | | | | | \_/\_/ \_/\_/ \_/\_/ (_) \____|_|\__,_|\___|\____\___/|_| |_| (_) \___\___/|_| |_| |_| | | | .=======================================================================================================. Type /help to see a list of commands +OK log level [7] freeswitch@DESKTOP-5PS5MGH> sofia global siptrace on +OK Global siptrace on freeswitch@DESKTOP-5PS5MGH> send 478 bytes to udp/[10.10.0.1]:5060 at 06:15:16.563655: ------------------------------------------------------------------------ OPTIONS sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKFy5FtgeU9p6ym Max-Forwards: 70 From: ;tag=eNBDmKNj04tQD To: Call-ID: a7460ca0-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809576 OPTIONS User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 363 bytes from udp/[10.10.0.1]:5060 at 06:15:16.774740: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809576 OPTIONS Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKFy5FtgeU9p6ym From: ;tag=eNBDmKNj04tQD Call-ID: a7460ca0-d4ad-1234-3fbf-c5acbca4426b To: ;tag=1015203708634984 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REGISTER, INFO, NOTIFY, MESSAGE, SUBSCRIBE, REFER, PUBLISH Content-Length: 0 ------------------------------------------------------------------------ sofia loglevel all 9 Sofia log level for component [all] has been set to [9] freeswitch@DESKTOP-5PS5MGH> ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (94809576) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BED38): sent signal r_options ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BED38): recv signal r_options ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::01356098, 01A28248, 004BED38) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031FDFA8, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031FDFA8, ...) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADC2D0) tpn = udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADC2D0): not found by name udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADC2D0): 478 bytes of 478 to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 478 send 478 bytes to udp/[10.10.0.1]:5060 at 06:15:36.622599: ------------------------------------------------------------------------ OPTIONS sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKg7y8UBZy6ZvHg Max-Forwards: 70 From: ;tag=Fy45Ne6NXDHaS To: Call-ID: b33acd11-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809577 OPTIONS User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent OPTIONS (94809577) to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADC2D0): pending 01AC5BA0 for udp/192.168.0.11:5070 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADC2D0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADC2D0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADC2D0) msg 01AC63C0 from (udp/192.168.0.11:5070) has 363 bytes, veclen = 1 recv 363 bytes from udp/[10.10.0.1]:5060 at 06:15:36.833615: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809577 OPTIONS Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKg7y8UBZy6ZvHg From: ;tag=Fy45Ne6NXDHaS Call-ID: b33acd11-d4ad-1234-3fbf-c5acbca4426b To: ;tag=1015403708655046 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REGISTER, INFO, NOTIFY, MESSAGE, SUBSCRIBE, REFER, PUBLISH Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADC2D0): msg 01AC63C0 (363 bytes) from udp/10.10.0.1:5070/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (94809577) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 211.514 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADC2D0): 01AC5BA0 by 0320FB30 with 01AC63C0 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BED38): event r_options 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BED38): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BED38): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::031FDFA8) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4211 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (94809577) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set ..\..\sofia-sip\libsofia-sip-ua\iptsec\auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(trillion:voipswitch:927bipin) = 6888b7aa95211dd720e4b32a7ddc889f ..\..\sofia-sip\libsofia-sip-ua\iptsec\auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:10.10.0.1;transport=udp) ..\..\sofia-sip\libsofia-sip-ua\iptsec\auth_digest.c:348 auth_digest_response() auth_response: fe86c5435bb3269ee393fbdbcc3f7658 = MD5(6888b7aa95211dd720e4b32a7ddc889f:dd0c601506e92dd8-04101021708142031431:328af1b33ea82019418600699dc55bbc) (qop=NONE) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADC2D0) tpn = udp/10.10.0.1:5060/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADC2D0): not found by name udp/10.10.0.1:5060/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADC2D0): 745 bytes of 745 to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 745 send 745 bytes to udp/[10.10.0.1]:5060 at 06:15:47.376265: ------------------------------------------------------------------------ REGISTER sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKHgr1X6F238j4B Max-Forwards: 70 From: ;tag=BtZ2e22789QZa To: Call-ID: e19865b4-3630-438a-9220-29c8e03e1603 CSeq: 94809566 REGISTER Contact: Expires: 3600 User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Proxy-Authorization: Digest username="trillion", realm="voipswitch", nonce="dd0c601506e92dd8-04101021708142031431", algorithm=MD5, uri="sip:10.10.0.1;transport=udp", response="fe86c5435bb3269ee393fbdbcc3f7658" Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent REGISTER (94809566) to udp/10.10.0.1:5060/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADC2D0): pending 01AC67D0 for udp/192.168.0.11:5070 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 01AC6DE8 from (udp/192.168.0.11:5060) has 4 bytes, veclen = 1 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): bad msg 01AC6DE8 (4 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADC2D0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADC2D0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADC2D0) msg 01AC6DE8 from (udp/192.168.0.11:5070) has 372 bytes, veclen = 1 recv 372 bytes from udp/[10.10.0.1]:5060 at 06:15:47.587536: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809566 REGISTER Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKHgr1X6F238j4B From: ;tag=BtZ2e22789QZa Call-ID: e19865b4-3630-438a-9220-29c8e03e1603 To: ;tag=1015503708665796 Contact: ;expires=120 Expires: 120 Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADC2D0): msg 01AC6DE8 (372 bytes) from udp/10.10.0.1:5070/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for REGISTER (94809566) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 211.271 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADC2D0): 01AC67D0 by 0320EFF0 with 01AC6DE8 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh register after 78 seconds (in [60..90]) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE838): event r_register 200 OK 2016-08-04 10:15:47.580534 [DEBUG] sofia_reg.c:2429 Changing expire time to 120 by request of proxy sip:10.10.0.1 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4210 ms 2016-08-04 10:15:48.780227 [INFO] mod_verto.c:4025 192.168.0.11:61745 Client Connect. 2016-08-04 10:15:48.780227 [INFO] mod_verto.c:1978 192.168.0.11:61745 Starting client thread. 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "method": "login", "params": { "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" }, "id": 2 }] 2016-08-04 10:15:48.840255 [INFO] mod_verto.c:1267 192.168.0.11:61745 re-connecting session de02989a-0170-a830-e80e-b052c07e81f5 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 2, "error": { "code": -32000, "message": "Authentication Required" } }] 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "method": "login", "params": { "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" }, "id": 1 }] 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 1, "error": { "code": -32000, "message": "Authentication Required" } }] 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "method": "login", "params": { "login": "trillionss@xbipin.com", "passwd": "927bipin", "loginParams": { }, "userVariables": { }, "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" }, "id": 3 }] 2016-08-04 10:15:48.840255 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 3, "result": { "message": "logged in", "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" } }] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (94809566) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BF198): sent signal r_options ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BF198): recv signal r_options ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::01356098, 01A28248, 004BF198) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADC2D0) tpn = udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADC2D0): not found by name udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADC2D0): 478 bytes of 478 to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 478 send 478 bytes to udp/[10.10.0.1]:5060 at 06:15:56.677936: ------------------------------------------------------------------------ OPTIONS sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKjSHtZ1050H9pQ Max-Forwards: 70 From: ;tag=g7XyQ9pStp7vm To: Call-ID: bf2f27e0-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809578 OPTIONS User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent OPTIONS (94809578) to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADC2D0): pending 01AC5998 for udp/192.168.0.11:5070 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADC2D0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADC2D0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADC2D0) msg 01AC6DE8 from (udp/192.168.0.11:5070) has 363 bytes, veclen = 1 recv 363 bytes from udp/[10.10.0.1]:5060 at 06:15:56.889370: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809578 OPTIONS Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKjSHtZ1050H9pQ From: ;tag=g7XyQ9pStp7vm Call-ID: bf2f27e0-d4ad-1234-3fbf-c5acbca4426b To: ;tag=1016003708675109 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REGISTER, INFO, NOTIFY, MESSAGE, SUBSCRIBE, REFER, PUBLISH Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADC2D0): msg 01AC6DE8 (363 bytes) from udp/10.10.0.1:5070/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (94809578) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 211.934 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADC2D0): 01AC5998 by 0320FBF0 with 01AC6DE8 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BF198): event r_options 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BF198): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BF198): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::031DA1C8) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4212 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (94809578) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set 2016-08-04 10:16:08.140291 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "method": "verto.invite", "params": { "sdp": "v=0\r\no=- 8720450899619411369 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI\r\nm=audio 61266 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126\r\nc=IN IP4 86.99.124.187\r\na=rtcp:61269 IN IP4 86.99.124.187\r\na=candidate:2591490071 1 udp 2122255103 2001::5ef5:79fd:10e3:1539:3f57:fff4 61264 typ host generation 0 network-id 2\r\na=candidate:2237255773 1 udp 2122194687 169.254.101.10 61265 typ host generation 0 network-id 3\r\na=candidate:3988902457 1 udp 2122129151 192.168.0.11 61266 typ host generation 0 network-id 1\r\na=candidate:2591490071 2 udp 2122255102 2001::5ef5:79fd:10e3:1539:3f57:fff4 61267 typ host generation 0 network-id 2\r\na=candidate:2237255773 2 udp 2122194686 169.254.101.10 61268 typ host generation 0 network-id 3\r\na=candidate:3988902457 2 udp 2122129150 192.168.0.11 61269 typ host generation 0 network-id 1\r\na=candidate:3572825319 1 tcp 1518275327 2001::5ef5:79fd:10e3:1539:3f57:fff4 9 typ host tcptype active generation 0 network-id 2\r\na=candidate:3420073133 1 tcp 1518214911 169.254.101.10 9 typ host tcptype active generation 0 network-id 3\r\na=candidate:2739023561 1 tcp 1518149375 192.168.0.11 9 typ host tcptype active generation 0 network-id 1\r\na=candidate:3572825319 2 tcp 1518275326 2001::5ef5:79fd:10e3:1539:3f57:fff4 9 typ host tcptype active generation 0 network-id 2\r\na=candidate:3420073133 2 tcp 1518214910 169.254.101.10 9 typ host tcptype active generation 0 network-id 3\r\na=candidate:2739023561 2 tcp 1518149374 192.168.0.11 9 typ host tcptype active generation 0 network-id 1\r\na=candidate:466725869 1 udp 1685921535 86.99.124.187 61266 typ srflx raddr 192.168.0.11 rport 61266 generation 0 network-id 1\r\na=candidate:466725869 2 udp 1685921534 86.99.124.187 61269 typ srflx raddr 192.168.0.11 rport 61269 generation 0 network-id 1\r\na=ice-ufrag:LW6dMsmqXjYwpHWI\r\na=ice-pwd:o2hkpfEAJqcZyIDhe6fa1Ppp\r\na=fingerprint:sha-256 04:87:66:8E:11:58:93:07:3C:CA:C4:17:BB:E7:71:BF:C3:A8:FA:DD:B5:9E:77:4B:85:50:03:A7:1A:2A:20:A9\r\na=setup:actpass\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=rtpmap:111 opus/48000/2\r\na=rtcp-fb:111 transport-cc\r\na=fmtp:111 minptime=10;useinbandfec=1\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:9 G722/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:126 telephone-event/8000\r\na=maxptime:60\r\na=ssrc:3803537473 cname:3TSma3p3nz57SdiF\r\na=ssrc:3803537473 msid:xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI 4c307149-c5b4-422f-81aa-f94d86c33461\r\na=ssrc:3803537473 mslabel:xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI\r\na=ssrc:3803537473 label:4c307149-c5b4-422f-81aa-f94d86c33461\r\n", "dialogParams": { "useVideo": false, "useStereo": false, "screenShare": false, "useCamera": "none", "useMic": "0cf03192275f0100c7e90f472d6e42d1abf3f4ac2b86080e5f1b8c1ff2147f2e", "useSpeak": "default", "tag": "webcam", "localTag": null, "login": "trillionss@xbipin.com", "videoParams": { "minWidth": 320, "minHeight": 180, "maxWidth": 320, "maxHeight": 180, "minFrameRate": 15 }, "destination_number": "2002", "caller_id_name": "1234", "caller_id_number": "", "outgoingBandwidth": 90354, "incomingBandwidth": 192000, "dedEnc": false, "mirrorInput": false, "userVariables": { "email": "", "avatar": "http://gravatar.com/avatar/d41d8cd98f00b204e9800998ecf8427e.png?s=600" }, "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "remote_caller_id_name": "Outbound Call", "remote_caller_id_number": "2002" }, "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" }, "id": 4 }] 2016-08-04 10:16:08.140291 [DEBUG] mod_rtc.c:389 () State Change CS_NEW -> CS_INIT 2016-08-04 10:16:08.140291 [DEBUG] switch_core_session.c:613 N/A set UUID=8e34ba61-e7b9-930e-4de0-2292db2c3009 2016-08-04 10:16:08.140291 [NOTICE] switch_channel.c:1104 New Channel verto.rtc/2002 [8e34ba61-e7b9-930e-4de0-2292db2c3009] 2016-08-04 10:16:08.140291 [DEBUG] mod_verto.c:3579 Remote SDP verto.rtc/2002: v=0 o=- 8720450899619411369 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE audio a=msid-semantic: WMS xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI m=audio 61266 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126 c=IN IP4 86.99.124.187 a=rtcp:61269 IN IP4 86.99.124.187 a=candidate:2591490071 1 udp 2122255103 2001::5ef5:79fd:10e3:1539:3f57:fff4 61264 typ host generation 0 network-id 2 a=candidate:2237255773 1 udp 2122194687 169.254.101.10 61265 typ host generation 0 network-id 3 a=candidate:3988902457 1 udp 2122129151 192.168.0.11 61266 typ host generation 0 network-id 1 a=candidate:2591490071 2 udp 2122255102 2001::5ef5:79fd:10e3:1539:3f57:fff4 61267 typ host generation 0 network-id 2 a=candidate:2237255773 2 udp 2122194686 169.254.101.10 61268 typ host generation 0 network-id 3 a=candidate:3988902457 2 udp 2122129150 192.168.0.11 61269 typ host generation 0 network-id 1 a=candidate:3572825319 1 tcp 1518275327 2001::5ef5:79fd:10e3:1539:3f57:fff4 9 typ host tcptype active generation 0 network-id 2 a=candidate:3420073133 1 tcp 1518214911 169.254.101.10 9 typ host tcptype active generation 0 network-id 3 a=candidate:2739023561 1 tcp 1518149375 192.168.0.11 9 typ host tcptype active generation 0 network-id 1 a=candidate:3572825319 2 tcp 1518275326 2001::5ef5:79fd:10e3:1539:3f57:fff4 9 typ host tcptype active generation 0 network-id 2 a=candidate:3420073133 2 tcp 1518214910 169.254.101.10 9 typ host tcptype active generation 0 network-id 3 a=candidate:2739023561 2 tcp 1518149374 192.168.0.11 9 typ host tcptype active generation 0 network-id 1 a=candidate:466725869 1 udp 1685921535 86.99.124.187 61266 typ srflx raddr 192.168.0.11 rport 61266 generation 0 network-id 1 a=candidate:466725869 2 udp 1685921534 86.99.124.187 61269 typ srflx raddr 192.168.0.11 rport 61269 generation 0 network-id 1 a=ice-ufrag:LW6dMsmqXjYwpHWI a=ice-pwd:o2hkpfEAJqcZyIDhe6fa1Ppp a=fingerprint:sha-256 04:87:66:8E:11:58:93:07:3C:CA:C4:17:BB:E7:71:BF:C3:A8:FA:DD:B5:9E:77:4B:85:50:03:A7:1A:2A:20:A9 a=setup:actpass a=mid:audio a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time a=sendrecv a=rtcp-mux a=rtpmap:111 opus/48000/2 a=rtcp-fb:111 transport-cc a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:126 telephone-event/8000 a=maxptime:60 a=ssrc:3803537473 cname:3TSma3p3nz57SdiF a=ssrc:3803537473 msid:xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI 4c307149-c5b4-422f-81aa-f94d86c33461 a=ssrc:3803537473 mslabel:xFbaghzziZW71YHWb2FL3HPrs19MftwTBaxI a=ssrc:3803537473 label:4c307149-c5b4-422f-81aa-f94d86c33461 2016-08-04 10:16:08.140291 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 4, "result": { "message": "CALL CREATED", "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" } }] 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:543 (verto.rtc/2002) Running State Change CS_INIT 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:586 (verto.rtc/2002) State INIT 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:40 verto.rtc/2002 Standard INIT 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/2002) State Change CS_INIT -> CS_ROUTING 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:586 (verto.rtc/2002) State INIT going to sleep 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:543 (verto.rtc/2002) Running State Change CS_ROUTING 2016-08-04 10:16:08.140291 [DEBUG] switch_channel.c:2249 (verto.rtc/2002) Callstate Change DOWN -> RINGING 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:602 (verto.rtc/2002) State ROUTING 2016-08-04 10:16:08.140291 [DEBUG] mod_rtc.c:89 verto.rtc/2002 RTC ROUTING 2016-08-04 10:16:08.140291 [DEBUG] switch_core_state_machine.c:236 verto.rtc/2002 Standard ROUTING 2016-08-04 10:16:08.140291 [INFO] mod_dialplan_xml.c:637 Processing 1234 <0000000000>->2002 in context lanusersdialout Dialplan: verto.rtc/2002 parsing [lanusersdialout->call_xlite] continue=false Dialplan: verto.rtc/2002 Regex (PASS) [call_xlite] destination_number(2002) =~ /^2002$/ break=on-false Dialplan: verto.rtc/2002 Action bridge(user/trillions@${domain_name}) 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:286 (verto.rtc/2002) State Change CS_ROUTING -> CS_EXECUTE 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:602 (verto.rtc/2002) State ROUTING going to sleep 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:543 (verto.rtc/2002) Running State Change CS_EXECUTE 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:609 (verto.rtc/2002) State EXECUTE 2016-08-04 10:16:08.160735 [DEBUG] mod_rtc.c:120 verto.rtc/2002 RTC EXECUTE 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:328 verto.rtc/2002 Standard EXECUTE EXECUTE verto.rtc/2002 bridge(user/trillions@192.168.0.11) 2016-08-04 10:16:08.160735 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-08-04 10:16:08.160735 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-08-04 10:16:08.160735 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/trillions@192.168.0.11:9040 [8319a985-5a8b-44c1-be11-d805def20700] 2016-08-04 10:16:08.160735 [DEBUG] mod_sofia.c:4754 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_NEW -> CS_INIT 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_INIT 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/trillions@192.168.0.11:9040) State INIT 2016-08-04 10:16:08.160735 [DEBUG] mod_sofia.c:90 sofia/internal/trillions@192.168.0.11:9040 SOFIA INIT 2016-08-04 10:16:08.160735 [DEBUG] switch_core_port_allocator.c:183 UDP port robustness check for port 1032 pass 2016-08-04 10:16:08.160735 [DEBUG] sofia_glue.c:1249 sofia/internal/trillions@192.168.0.11:9040 sending invite version: 1.7.0 git 18f1d56 2016-07-24 04:35:30Z 32bit Local SDP: v=0 o=Talkycom 1470290336 1470290337 IN IP4 192.168.0.11 s=Talkycom c=IN IP4 192.168.0.11 t=0 0 m=audio 1032 RTP/AVP 102 9 0 8 103 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BE978): sent signal r_invite 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:40 sofia/internal/trillions@192.168.0.11:9040 Standard INIT ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BE978): recv signal r_invite 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_INIT -> CS_ROUTING ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::013563E0, 01A28888, 004BE978) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/trillions@192.168.0.11:9040) State INIT going to sleep ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::031DA1C8, 00000000, 03213B94, -1) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::031DA1C8, 00000000, 03213B94, -1) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:338 nua_dialog_usage_add() nua(004BE978): adding session usage ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(03140940) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::031DA1C8) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::031DA1C8, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(031DA1C8, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1187 offer_answer_step() soa_static(031DA1C8, soa_generate_offer): generating local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1215 offer_answer_step() soa_static(031DA1C8, soa_generate_offer): upgrade with local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0298F510, 00000000, ""): called 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_ROUTING ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1444 offer_answer_step() soa_static(031DA1C8, soa_generate_offer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::031DA1C8, [00000000], [0298F588], [0298F598]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADB7A8) tpn = */192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.0.11:9040 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/trillions@192.168.0.11:9040) State ROUTING ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADB7A8): not found by name */192.168.0.11:9040 2016-08-04 10:16:08.160735 [DEBUG] mod_sofia.c:143 sofia/internal/trillions@192.168.0.11:9040 SOFIA ROUTING 2016-08-04 10:16:08.160735 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/trillions@192.168.0.11:9040) State ROUTING going to sleep ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADB7A8): 1480 bytes of 1480 to udp/192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1480 send 1480 bytes to udp/[192.168.0.11]:9040 at 06:16:08.166240: ------------------------------------------------------------------------ INVITE sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11;rport;branch=z9hG4bKK52tjpNXK5cyj Max-Forwards: 70 From: "1234" ;tag=QHm24p8jHSmBg To: Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809620 INVITE Contact: User-Agent: Talkycom 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 Content-Type: application/sdp Content-Disposition: session Content-Length: 5272016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_CONSUME_MEDIA X-FS-Support: update_display,send_info Remote-Party-ID: "1234" ;party=calling;screen=yes;privacy=off v=0 o=Talkycom 1470290336 1470290337 IN IP4 192.168.0.11 s=Talkycom c=IN IP4 192.168.0.11 t=0 0 m=audio 1032 RTP/AVP 102 9 0 8 103 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/trillions@192.168.0.11:9040) State CONSUME_MEDIA a=rtpmap:101 telephone-event/8000 2016-08-04 10:16:08.160735 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/trillions@192.168.0.11:9040) State CONSUME_MEDIA going to sleep a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent INVITE (94809620) to */192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADB7A8): pending 01AC71F8 for udp/192.168.0.11:5060 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(004BE978): call state changed: init -> calling, sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::031DA1C8, [0298F5A4], [0298F5D4], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(004BE978): event i_state INVITE sent 2016-08-04 10:16:08.160735 [DEBUG] sofia.c:6937 Channel sofia/internal/trillions@192.168.0.11:9040 entering state [calling][0] ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 01AC7400 from (udp/192.168.0.11:5060) has 309 bytes, veclen = 1 recv 309 bytes from udp/[192.168.0.11]:9040 at 06:16:08.248731: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.11;rport=5060;branch=z9hG4bKK52tjpNXK5cyj To: From: "1234" ;tag=QHm24p8jHSmBg Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809620 INVITE Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): msg 01AC7400 (309 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (94809620) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 82.991 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADB7A8): 01AC71F8 by 0320FB30 with 01AC7400 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 01AC6FF0 from (udp/192.168.0.11:5060) has 453 bytes, veclen = 1 recv 453 bytes from udp/[192.168.0.11]:9040 at 06:16:08.358255: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.11;rport=5060;branch=z9hG4bKK52tjpNXK5cyj Contact: To: "971559270058";tag=76d89c38 From: "1234" ;tag=QHm24p8jHSmBg Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809620 INVITE User-Agent: X-Lite release 4.9.5 stamp 81136 Allow-Events: talk, hold Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): msg 01AC6FF0 (453 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (94809620) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADB7A8): 01AC71F8 by 0320FB30 with 01AC6FF0 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event r_invite 180 Ringing ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(004BE978): call state changed: calling -> proceeding ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_state 180 Ringing 2016-08-04 10:16:08.340745 [DEBUG] sofia.c:6937 Channel sofia/internal/trillions@192.168.0.11:9040 entering state [proceeding][180] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BF198): sent signal r_options ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BF198): recv signal r_options ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::01356098, 01A28248, 004BF198) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA510, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA510, ...) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADC2D0) tpn = udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADC2D0): not found by name udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADC2D0): 478 bytes of 478 to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 478 send 478 bytes to udp/[10.10.0.1]:5060 at 06:16:16.744301: ------------------------------------------------------------------------ OPTIONS sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKK2aK1vH9XtZ9j Max-Forwards: 70 From: ;tag=HgQQS47vQZXFg To: Call-ID: cb250a47-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809579 OPTIONS User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent OPTIONS (94809579) to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADC2D0): pending 01AC63C0 for udp/192.168.0.11:5070 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADC2D0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADC2D0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADC2D0) msg 01AC7400 from (udp/192.168.0.11:5070) has 363 bytes, veclen = 1 recv 363 bytes from udp/[10.10.0.1]:5060 at 06:16:16.955716: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809579 OPTIONS Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKK2aK1vH9XtZ9j From: ;tag=HgQQS47vQZXFg Call-ID: cb250a47-d4ad-1234-3fbf-c5acbca4426b To: ;tag=1016203708695171 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REGISTER, INFO, NOTIFY, MESSAGE, SUBSCRIBE, REFER, PUBLISH Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADC2D0): msg 01AC7400 (363 bytes) from udp/10.10.0.1:5070/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (94809579) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 211.947 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADC2D0): 01AC63C0 by 0320FA70 with 01AC7400 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BF198): event r_options 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BF198): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BF198): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::031DA510) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 01AC67D0 from (udp/192.168.0.11:5060) has 4 bytes, veclen = 1 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): bad msg 01AC67D0 (4 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4211 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 01AC67D0 from (udp/192.168.0.11:5060) has 737 bytes, veclen = 1 recv 737 bytes from udp/[192.168.0.11]:9040 at 06:16:18.153174: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.11;rport=5060;branch=z9hG4bKK52tjpNXK5cyj Contact: To: ;tag=76d89c38 From: "1234" ;tag=QHm24p8jHSmBg Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809620 INVITE Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS Content-Type: application/sdp Supported: replaces User-Agent: X-Lite release 4.9.5 stamp 81136 Content-Length: 201 v=0 o=- 735382566 3 IN IP4 192.168.0.11 s=X-Lite release 4.9.5 stamp 81136 c=IN IP4 192.168.0.11 t=0 0 m=audio 10044 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): msg 01AC67D0 (737 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (94809620) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADB7A8): 01AC71F8 by 0320FB30 with 01AC67D0 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::031DA1C8, 00000000, 004BE2D0, 201) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::031DA1C8) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(031DA1C8, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(032B2F60, 033789E0, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1302 offer_answer_step() soa_static(031DA1C8, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1444 offer_answer_step() soa_static(031DA1C8, soa_process_answer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::031DA1C8, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(004BE978): INVITE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event r_invite 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(004BE978): call state changed: proceeding -> completing, received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::031DA1C8, [0298F3C8], [0298F3CC], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_state 200 OK 2016-08-04 10:16:18.140679 [DEBUG] sofia.c:6937 Channel sofia/internal/trillions@192.168.0.11:9040 entering state [completing][200] 2016-08-04 10:16:18.140679 [DEBUG] sofia.c:6947 Remote SDP: v=0 o=- 735382566 3 IN IP4 192.168.0.11 s=X-Lite release 4.9.5 stamp 81136 c=IN IP4 192.168.0.11 t=0 0 m=audio 10044 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BE978): sent signal r_ack ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BE978): recv signal r_ack ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::031DA1C8, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADB7A8) tpn = */192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADB7A8): not found by name */192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADB7A8): 401 bytes of 401 to udp/192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 401 send 401 bytes to udp/[192.168.0.11]:9040 at 06:16:18.157175: ------------------------------------------------------------------------ ACK sip:trillions@192.168.0.11:9040 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11;rport;branch=z9hG4bKmevKmH60ge3ge Max-Forwards: 70 From: "1234" ;tag=QHm24p8jHSmBg To: ;tag=76d89c38 Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809620 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent ACK (94809620) to */192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(004BE978): call state changed: completing -> ready ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_state 200 ACK sent ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_active 200 Call active 2016-08-04 10:16:18.140679 [DEBUG] sofia.c:6937 Channel sofia/internal/trillions@192.168.0.11:9040 entering state [ready][200] 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:2] 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4380 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4241 Set telephone-event payload to 101@8000 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:3032 Set Codec sofia/internal/trillions@192.168.0.11:9040 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2016-08-04 10:16:18.140679 [DEBUG] switch_core_codec.c:111 sofia/internal/trillions@192.168.0.11:9040 Original read codec set to PCMU:0 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4594 Set telephone-event payload to 101@8000 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:4653 sofia/internal/trillions@192.168.0.11:9040 Set 2833 dtmf send payload to 101 recv payload to 101 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:6479 AUDIO RTP [sofia/internal/trillions@192.168.0.11:9040] 192.168.0.11 port 1032 -> 192.168.0.11 port 10044 codec: 0 ms: 20 2016-08-04 10:16:18.140679 [DEBUG] switch_rtp.c:3833 Starting timer [soft] 160 bytes per 20ms 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:6778 sofia/internal/trillions@192.168.0.11:9040 Set 2833 dtmf send payload to 101 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:6785 sofia/internal/trillions@192.168.0.11:9040 Set 2833 dtmf receive payload to 101 2016-08-04 10:16:18.140679 [DEBUG] switch_core_media.c:6808 sofia/internal/trillions@192.168.0.11:9040 Set rtp dtmf delay to 40 2016-08-04 10:16:18.140679 [NOTICE] sofia.c:7968 Channel [sofia/internal/trillions@192.168.0.11:9040] has been answered 2016-08-04 10:16:18.140679 [DEBUG] switch_channel.c:3770 (sofia/internal/trillions@192.168.0.11:9040) Callstate Change DOWN -> ACTIVE 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [opus:111:48000:60:0:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4380 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [opus:111:48000:60:0:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [opus:111:48000:60:0:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [opus:111:48000:60:0:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [G722:9:8000:60:64000:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [G722:9:8000:60:64000:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4380 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:106:32000:60:0:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:106:32000:60:0:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:106:32000:60:0:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:106:32000:60:0:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:105:16000:60:0:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:105:16000:60:0:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:105:16000:60:0:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:105:16000:60:0:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:13:8000:60:0:1]/[opus:116:48000:20:0:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:13:8000:60:0:1]/[PCMU:0:8000:20:64000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:13:8000:60:0:1]/[G729:18:8000:20:8000:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4325 Audio Codec Compare [CN:13:8000:60:0:1]/[G723:4:8000:30:6300:1] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4241 Set telephone-event payload to 126@8000 2016-08-04 10:16:18.160185 [DEBUG] mod_opus.c:554 Opus encoder: set bitrate based on maxaveragebitrate value found in SDP or local config [20000bps] 2016-08-04 10:16:18.160185 [DEBUG] mod_opus.c:571 Opus encoder: set audio bandwidth to [WIDEBAND] based on maxplaybackrate value found in SDP or local config [16000Hz] 2016-08-04 10:16:18.160185 [DEBUG] mod_opus.c:554 Opus encoder: set bitrate based on maxaveragebitrate value found in SDP or local config [20000bps] 2016-08-04 10:16:18.160185 [DEBUG] mod_opus.c:571 Opus encoder: set audio bandwidth to [WIDEBAND] based on maxplaybackrate value found in SDP or local config [16000Hz] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3032 Set Codec verto.rtc/2002 opus/48000 20 ms 960 samples 0 bits 1 channels 2016-08-04 10:16:18.160185 [DEBUG] switch_core_codec.c:111 verto.rtc/2002 Original read codec set to opus:116 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3430 Drop audio Candidate cid: 1 proto: udp type: host addr: 2001::5ef5:79fd:10e3:1539:3f57:fff4:61264 (no network path) 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 1 proto: udp type: host addr: 169.254.101.10:61265 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.0.11:61266 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3430 Drop audio Candidate cid: 2 proto: udp type: host addr: 2001::5ef5:79fd:10e3:1539:3f57:fff4:61267 (no network path) 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 2 proto: udp type: host addr: 169.254.101.10:61268 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 2 proto: udp type: host addr: 192.168.0.11:61269 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 1 proto: udp type: srflx addr: 86.99.124.187:61266 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3436 Save audio Candidate cid: 2 proto: udp type: srflx addr: 86.99.124.187:61269 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3478 Searching for rtp candidate. 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3483 Choose rtp candidate, index 2, 86.99.124.187:61266 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3261 verto.rtc/2002 choosing family v4 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3494 Choose same candidate, index 3, for rtcp based on rtcp-mux attribute 86.99.124.187:61266 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3539 setting remote audio ice addr to index 2 86.99.124.187:61266 based on candidate 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:3560 Setting remote rtcp audio addr to 86.99.124.187:61266 based on candidate 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:4653 verto.rtc/2002 Set 2833 dtmf send payload to 126 recv payload to 126 2016-08-04 10:16:18.160185 [DEBUG] switch_core_port_allocator.c:183 UDP port robustness check for port 1030 pass 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:6479 AUDIO RTP [verto.rtc/2002] 192.168.0.11 port 1030 -> 86.99.124.187 port 61266 codec: 111 ms: 20 2016-08-04 10:16:18.160185 [DEBUG] switch_rtp.c:3833 Starting timer [soft] 960 bytes per 20ms 2016-08-04 10:16:18.160185 [INFO] switch_core_media.c:6654 Activating Audio ICE 2016-08-04 10:16:18.160185 [NOTICE] switch_rtp.c:4325 Activating RTP audio ICE: LW6dMsmqXjYwpHWI:H2lTdOjkW8YbdVjh 86.99.124.187:61266 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:6697 Activating RTCP PORT 61266 2016-08-04 10:16:18.160185 [DEBUG] switch_rtp.c:4222 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 61266 2016-08-04 10:16:18.160185 [INFO] switch_core_media.c:6705 Skipping RTCP ICE (Same as RTP) 2016-08-04 10:16:18.160185 [INFO] switch_rtp.c:3329 Activate RTP/RTCP audio DTLS client 2016-08-04 10:16:18.160185 [INFO] switch_rtp.c:3460 Changing audio DTLS state from OFF to HANDSHAKE 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:1998 Setting Jitterbuffer to 20ms (1 frames) (50 max frames) 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:6778 verto.rtc/2002 Set 2833 dtmf send payload to 126 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:6785 verto.rtc/2002 Set 2833 dtmf receive payload to 126 2016-08-04 10:16:18.160185 [DEBUG] mod_verto.c:2445 Local SDP verto.rtc/2002: v=0 o=FreeSWITCH 1470290348 1470290349 IN IP4 192.168.0.11 s=FreeSWITCH c=IN IP4 192.168.0.11 t=0 0 a=msid-semantic: WMS yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv a=end-of-candidates m=audio 1030 UDP/TLS/RTP/SAVPF 111 126 a=rtpmap:111 opus/48000/2 a=fmtp:111 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; minptime=10 a=rtpmap:126 telephone-event/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv a=fingerprint:sha-256 6C:DF:81:17:9B:0C:B9:0A:A2:A3:9A:AC:FF:EB:B2:44:3B:7A:77:E5:A1:69:CD:0B:78:31:6A:28:FB:78:D0:C3 a=setup:active a=rtcp-mux a=rtcp:1030 IN IP4 192.168.0.11 a=ice-ufrag:H2lTdOjkW8YbdVjh a=ice-pwd:sOi39omOLIOYyG0w41m74rgo a=candidate:9609061325 1 udp 659136 192.168.0.11 1030 typ host generation 0 a=ssrc:1524143252 cname:GN2x7iGjaC01JSbO a=ssrc:1524143252 msid:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv a0 a=ssrc:1524143252 mslabel:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv a=ssrc:1524143252 label:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNva0 2016-08-04 10:16:18.160185 [NOTICE] switch_ivr_originate.c:3549 Channel [verto.rtc/2002] has been answered 2016-08-04 10:16:18.160185 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 1, "method": "verto.answer", "params": { "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "sdp": "v=0\r\no=FreeSWITCH 1470290348 1470290349 IN IP4 192.168.0.11\r\ns=FreeSWITCH\r\nc=IN IP4 192.168.0.11\r\nt=0 0\r\na=msid-semantic: WMS yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv\r\na=end-of-candidates\r\nm=audio 1030 UDP/TLS/RTP/SAVPF 111 126\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; minptime=10\r\na=rtpmap:126 telephone-event/8000\r\na=silenceSupp:off - - - -\r\na=ptime:20\r\na=sendrecv\r\na=fingerprint:sha-256 6C:DF:81:17:9B:0C:B9:0A:A2:A3:9A:AC:FF:EB:B2:44:3B:7A:77:E5:A1:69:CD:0B:78:31:6A:28:FB:78:D0:C3\na=setup:active\r\na=rtcp-mux\r\na=rtcp:1030 IN IP4 192.168.0.11\r\na=ice-ufrag:H2lTdOjkW8YbdVjh\r\na=ice-pwd:sOi39omOLIOYyG0w41m74rgo\r\na=candidate:9609061325 1 udp 659136 192.168.0.11 1030 typ host generation 0\r\na=ssrc:1524143252 cname:GN2x7iGjaC01JSbO\r\na=ssrc:1524143252 msid:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv a0\r\na=ssrc:1524143252 mslabel:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNv\r\na=ssrc:1524143252 label:yKgnC3fH8eKgFNiTWdSVICvA7J3tIVNva0\r\n" } }] 2016-08-04 10:16:18.160185 [DEBUG] switch_channel.c:3770 (verto.rtc/2002) Callstate Change RINGING -> ACTIVE 2016-08-04 10:16:18.160185 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/trillions@192.168.0.11:9040] 2016-08-04 10:16:18.160185 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/trillions@192.168.0.11:9040] 2016-08-04 10:16:18.160185 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 1, "result": { "method": "verto.answer" } }] 2016-08-04 10:16:18.160185 [DEBUG] switch_core_media.c:9653 verto.rtc/2002 PAUSE Jitterbuffer 2016-08-04 10:16:18.160185 [DEBUG] switch_ivr_bridge.c:1600 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2016-08-04 10:16:18.160185 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_EXCHANGE_MEDIA 2016-08-04 10:16:18.160185 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/trillions@192.168.0.11:9040) State EXCHANGE_MEDIA 2016-08-04 10:16:18.160185 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2016-08-04 10:16:18.180826 [DEBUG] switch_rtp.c:6722 Correct audio ip/port confirmed. 2016-08-04 10:16:18.180826 [NOTICE] switch_core_io.c:1202 Activating write resampler 2016-08-04 10:16:18.180826 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 2, "method": "verto.display", "params": { "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "display_name": "Outbound Call", "display_number": "trillions", "caller_id_name": "1234", "caller_id_number": "0000000000", "callee_id_name": "Outbound Call", "callee_id_number": "trillions", "display_direction": "inbound" } }] 2016-08-04 10:16:18.180826 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 2, "result": { "method": "verto.display" } }] 2016-08-04 10:16:18.540269 [NOTICE] switch_rtp.c:1258 Auto Changing audio stun/rtp/dtls port from 86.99.124.187:61266 to 192.168.0.11:61266 2016-08-04 10:16:19.280734 [INFO] switch_rtp.c:3120 Changing audio DTLS state from HANDSHAKE to SETUP 2016-08-04 10:16:19.300271 [INFO] switch_rtp.c:3029 audio Fingerprint Verified. 2016-08-04 10:16:19.300271 [INFO] switch_rtp.c:3645 Activating Audio Secure RTP SEND 2016-08-04 10:16:19.300271 [INFO] switch_rtp.c:3623 Activating Audio Secure RTP RECV 2016-08-04 10:16:19.300271 [DEBUG] switch_core_sqldb.c:2612 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2016-08-04 10:16:19.300271 [INFO] switch_rtp.c:3069 Changing audio DTLS state from SETUP to READY 2016-08-04 10:16:19.300271 [DEBUG] switch_core_sqldb.c:2612 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2016-08-04 10:16:19.360687 [NOTICE] switch_core_io.c:1202 Activating write resampler 2016-08-04 10:16:19.380210 [DEBUG] switch_rtp.c:1847 rtcp_stats_init: audio ssrc[3803537473] base_seq[11906] ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADB7A8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADB7A8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADB7A8) msg 034B92D8 from (udp/192.168.0.11:5060) has 454 bytes, veclen = 1 recv 454 bytes from udp/[192.168.0.11]:9040 at 06:16:20.980693: ------------------------------------------------------------------------ BYE sip:mod_sofia@192.168.0.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:9040;branch=z9hG4bK-524287-1---2b2da306c520eb5a Max-Forwards: 70 Contact: To: "1234" ;tag=QHm24p8jHSmBg From: ;tag=76d89c38 Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 2 BYE User-Agent: X-Lite release 4.9.5 stamp 81136 Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADB7A8): msg 034B92D8 (454 bytes) from udp/192.168.0.11:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@192.168.0.11:5060 SIP/2.0 (CSeq 2) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@192.168.0.11:5060 with contact ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3060 agent_recv_request() nta: BYE (2) going to existing leg ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_bye 100 Trying 2016-08-04 10:16:21.001209 [DEBUG] switch_ivr_bridge.c:707 sofia/internal/trillions@192.168.0.11:9040 ending bridge by request from write function 2016-08-04 10:16:21.001209 [DEBUG] switch_ivr_bridge.c:786 BRIDGE THREAD DONE [verto.rtc/2002] 2016-08-04 10:16:21.001209 [NOTICE] sofia.c:988 Hangup sofia/internal/trillions@192.168.0.11:9040 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BE978): sent signal r_respond ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(004BE978): recv signal r_respond 200 OK ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::031DA1C8, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BE978): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADB7A8) tpn = UDP/192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADB7A8): not found by name UDP/192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADB7A8): 483 bytes of 483 to udp/192.168.0.11:9040 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 483 send 483 bytes to udp/[192.168.0.11]:9040 at 06:16:21.001710: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.11:9040;branch=z9hG4bK-524287-1---2b2da306c520eb5a From: ;tag=76d89c38 To: "1234" ;tag=QHm24p8jHSmBg Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b CSeq: 2 BYE User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (2) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:397 nua_dialog_usage_remove_at() nua(004BE978): removing session usage ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(004BE978): call state changed: ready -> terminated ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_state 200 Session Terminated ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BE978): event i_terminated 200 Session Terminated ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::031DA1C8) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(03140940) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BE978): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) 2016-08-04 10:16:21.001209 [DEBUG] switch_ivr_bridge.c:786 BRIDGE THREAD DONE [sofia/internal/trillions@192.168.0.11:9040] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/trillions@192.168.0.11:9040) State EXCHANGE_MEDIA going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_HANGUP 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/trillions@192.168.0.11:9040) Callstate Change ACTIVE -> HANGUP 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/trillions@192.168.0.11:9040) State HANGUP 2016-08-04 10:16:21.001209 [DEBUG] mod_sofia.c:438 Channel sofia/internal/trillions@192.168.0.11:9040 hanging up, cause: NORMAL_CLEARING 2016-08-04 10:16:21.001209 [DEBUG] switch_ivr_bridge.c:1698 sofia/internal/trillions@192.168.0.11:9040 skip receive message [UNBRIDGE] (channel is hungup already) 2016-08-04 10:16:21.001209 [DEBUG] switch_core_media.c:9721 verto.rtc/2002 RESUME Jitterbuffer 2016-08-04 10:16:21.001209 [NOTICE] switch_core_state_machine.c:385 verto.rtc/2002 has executed the last dialplan instruction, hanging up. 2016-08-04 10:16:21.001209 [NOTICE] switch_core_state_machine.c:387 Hangup verto.rtc/2002 [CS_EXECUTE] [NORMAL_CLEARING] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:609 (verto.rtc/2002) State EXECUTE going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:543 (verto.rtc/2002) Running State Change CS_HANGUP 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:60 sofia/internal/trillions@192.168.0.11:9040 Standard HANGUP, cause: NORMAL_CLEARING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/trillions@192.168.0.11:9040) State HANGUP going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_HANGUP -> CS_REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:809 (verto.rtc/2002) Callstate Change ACTIVE -> HANGUP 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:811 (verto.rtc/2002) State HANGUP 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:60 verto.rtc/2002 Standard HANGUP, cause: NORMAL_CLEARING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:811 (verto.rtc/2002) State HANGUP going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:578 (verto.rtc/2002) State Change CS_HANGUP -> CS_REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/trillions@192.168.0.11:9040) State REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:174 sofia/internal/trillions@192.168.0.11:9040 Standard REPORTING, cause: NORMAL_CLEARING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/trillions@192.168.0.11:9040) State REPORTING going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:543 (verto.rtc/2002) Running State Change CS_REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:897 (verto.rtc/2002) State REPORTING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:174 verto.rtc/2002 Standard REPORTING, cause: NORMAL_CLEARING 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:897 (verto.rtc/2002) State REPORTING going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/trillions@192.168.0.11:9040) State Change CS_REPORTING -> CS_DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_session.c:1647 Session 2 (sofia/internal/trillions@192.168.0.11:9040) Locked, Waiting on external entities 2016-08-04 10:16:21.001209 [NOTICE] switch_core_session.c:1665 Session 2 (sofia/internal/trillions@192.168.0.11:9040) Ended 2016-08-04 10:16:21.001209 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/trillions@192.168.0.11:9040 [CS_DESTROY] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:569 (verto.rtc/2002) State Change CS_REPORTING -> CS_DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_session.c:1647 Session 1 (verto.rtc/2002) Locked, Waiting on external entities 2016-08-04 10:16:21.001209 [NOTICE] switch_core_session.c:1665 Session 1 (verto.rtc/2002) Ended 2016-08-04 10:16:21.001209 [NOTICE] switch_core_session.c:1669 Close Channel verto.rtc/2002 [CS_DESTROY] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/trillions@192.168.0.11:9040) Running State Change CS_DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/trillions@192.168.0.11:9040) State DESTROY 2016-08-04 10:16:21.001209 [DEBUG] mod_sofia.c:343 sofia/internal/trillions@192.168.0.11:9040 SOFIA DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:181 sofia/internal/trillions@192.168.0.11:9040 Standard DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/trillions@192.168.0.11:9040) State DESTROY going to sleep 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:700 (verto.rtc/2002) Running State Change CS_DESTROY 2016-08-04 10:16:21.001209 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 3, "method": "verto.bye", "params": { "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "causeCode": 16, "cause": "NORMAL_CLEARING" } }] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:710 (verto.rtc/2002) State DESTROY 2016-08-04 10:16:21.001209 [DEBUG] mod_rtc.c:132 verto.rtc/2002 RTC DESTROY 2016-08-04 10:16:21.001209 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[80] PLC[0] FEC[0] 2016-08-04 10:16:21.001209 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:181 verto.rtc/2002 Standard DESTROY 2016-08-04 10:16:21.001209 [DEBUG] switch_core_state_machine.c:710 (verto.rtc/2002) State DESTROY going to sleep 2016-08-04 10:16:21.001209 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "method": "verto.bye", "params": { "dialogParams": { "useVideo": false, "useStereo": false, "screenShare": false, "useCamera": "none", "useMic": "0cf03192275f0100c7e90f472d6e42d1abf3f4ac2b86080e5f1b8c1ff2147f2e", "useSpeak": "default", "tag": "webcam", "localTag": null, "login": "trillionss@xbipin.com", "videoParams": { "minWidth": 320, "minHeight": 180, "maxWidth": 320, "maxHeight": 180, "minFrameRate": 15 }, "destination_number": "2002", "caller_id_name": "1234", "caller_id_number": "", "outgoingBandwidth": 90354, "incomingBandwidth": 192000, "dedEnc": false, "mirrorInput": false, "userVariables": { "email": "", "avatar": "http://gravatar.com/avatar/d41d8cd98f00b204e9800998ecf8427e.png?s=600" }, "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "remote_caller_id_name": "Outbound Call", "remote_caller_id_number": "trillions" }, "sessid": "de02989a-0170-a830-e80e-b052c07e81f5" }, "id": 5 }] 2016-08-04 10:16:21.001209 [ALERT] mod_verto.c:604 WRITE 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 5, "error": { "callID": "8e34ba61-e7b9-930e-4de0-2292db2c3009", "message": "CALL DOES NOT EXIST", "code": -32002 } }] 2016-08-04 10:16:21.040646 [ALERT] mod_verto.c:1370 READ 192.168.0.11:61745 [{ "jsonrpc": "2.0", "id": 3, "result": { "method": "verto.bye" } }] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (94809579) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set 2016-08-04 10:16:27.800593 [DEBUG] mod_verto.c:1862 BAD READ -1000 2016-08-04 10:16:27.800593 [INFO] mod_verto.c:2005 192.168.0.11:61745 Ending client thread. 2016-08-04 10:16:27.800593 [INFO] mod_verto.c:2013 192.168.0.11:61745 Thread ended ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BED38): sent signal r_options ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BED38): recv signal r_options ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::01356098, 01A28248, 004BED38) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::033658E0, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::033658E0, ...) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(01ADC2D0) tpn = udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(01ADC2D0): not found by name udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(01ADC2D0): 478 bytes of 478 to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 478 send 478 bytes to udp/[10.10.0.1]:5060 at 06:16:36.814118: ------------------------------------------------------------------------ OPTIONS sip:10.10.0.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKmB4B3Q2cU3Nve Max-Forwards: 70 From: ;tag=jSggUZr0m8K2B To: Call-ID: d71b4c72-d4ad-1234-3fbf-c5acbca4426b CSeq: 94809580 OPTIONS User-Agent: Talkycom Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent OPTIONS (94809580) to udp/10.10.0.1:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(01ADC2D0): pending 034B9AF8 for udp/192.168.0.11:5070 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1350 set_timeout() nta: timer set to 32000 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(01ADC2D0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(01ADC2D0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(01ADC2D0) msg 034B90D0 from (udp/192.168.0.11:5070) has 363 bytes, veclen = 1 recv 363 bytes from udp/[10.10.0.1]:5060 at 06:16:37.024501: ------------------------------------------------------------------------ SIP/2.0 200 OK CSeq: 94809580 OPTIONS Via: SIP/2.0/UDP 192.168.0.11:5070;rport;branch=z9hG4bKmB4B3Q2cU3Nve From: ;tag=jSggUZr0m8K2B Call-ID: d71b4c72-d4ad-1234-3fbf-c5acbca4426b To: ;tag=1016403708715234 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REGISTER, INFO, NOTIFY, MESSAGE, SUBSCRIBE, REFER, PUBLISH Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(01ADC2D0): msg 034B90D0 (363 bytes) from udp/10.10.0.1:5070/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (94809580) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 211.383 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(01ADC2D0): 034B9AF8 by 0320F3B0 with 034B90D0 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(004BED38): event r_options 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(004BED38): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(004BED38): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::033658E0) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4211 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (94809580) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0284F874) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set