| _____ ____ ____ _ ___ |
| | ___/ ___| / ___| | |_ _| |
| | |_ \___ \ | | | | | | |
| | _| ___) | | |___| |___ | | |
| |_| |____/ \____|_____|___| |
| |
.=======================================================.
| 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 <enter> 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: <sip:10.10.0.1>;tag=eNBDmKNj04tQD
To: <sip:10.10.0.1>
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: <sip:10.10.0.1>;tag=eNBDmKNj04tQD
Call-ID: a7460ca0-d4ad-1234-3fbf-c5acbca4426b
To: <sip:10.10.0.1>;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: <sip:10.10.0.1>;tag=Fy45Ne6NXDHaS
To: <sip:10.10.0.1>
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: <sip:10.10.0.1>;tag=Fy45Ne6NXDHaS
Call-ID: b33acd11-d4ad-1234-3fbf-c5acbca4426b
To: <sip:10.10.0.1>;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 =
..\..\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: <sip:trillion@10.10.0.1>;tag=BtZ2e22789QZa
To: <sip:trillion@10.10.0.1>
Call-ID: e19865b4-3630-438a-9220-29c8e03e1603
CSeq: 94809566 REGISTER
Contact: <sip:trillion@192.168.0.11:5070;transport=udp;gw=bipin>
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: <sip:trillion@10.10.0.1>;tag=BtZ2e22789QZa
Call-ID: e19865b4-3630-438a-9220-29c8e03e1603
To: <sip:trillion@10.10.0.1>;tag=1015503708665796
Contact: <sip:trillion@192.168.0.11:5070;transport=udp;gw=bipin>;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":
"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: <sip:10.10.0.1>;tag=g7XyQ9pStp7vm
To: <sip:10.10.0.1>
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: <sip:10.10.0.1>;tag=g7XyQ9pStp7vm
Call-ID: bf2f27e0-d4ad-1234-3fbf-c5acbca4426b
To: <sip:10.10.0.1>;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" <sip:0000000000@192.168.0.11>;tag=QHm24p8jHSmBg
To: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>
Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b
CSeq: 94809620 INVITE
Contact: <sip:mod_sofia@192.168.0.11:5060>
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" <sip:0000000000@192.168.0.11>;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: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>
From: "1234" <sip:0000000000@192.168.0.11>;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: <sip:trillions@192.168.0.11:9040>
To: "971559270058"<sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>;tag=76d89c38
From: "1234" <sip:0000000000@192.168.0.11>;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: <sip:10.10.0.1>;tag=HgQQS47vQZXFg
To: <sip:10.10.0.1>
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: <sip:10.10.0.1>;tag=HgQQS47vQZXFg
Call-ID: cb250a47-d4ad-1234-3fbf-c5acbca4426b
To: <sip:10.10.0.1>;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: <sip:trillions@192.168.0.11:9040>
To: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>;tag=76d89c38
From: "1234" <sip:0000000000@192.168.0.11>;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" <sip:0000000000@192.168.0.11>;tag=QHm24p8jHSmBg
To: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>;tag=76d89c38
Call-ID: c6080e3c-d4ad-1234-3fbf-c5acbca4426b
CSeq: 94809620 ACK
Contact: <sip:mod_sofia@192.168.0.11:5060>
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: <sip:trillions@192.168.0.11:9040>
To: "1234" <sip:0000000000@192.168.0.11>;tag=QHm24p8jHSmBg
From: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>;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: <sip:trillions@192.168.0.11:9040;rinstance=1fc501a404528d22>;tag=76d89c38
To: "1234" <sip:0000000000@192.168.0.11>;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: <sip:10.10.0.1>;tag=jSggUZr0m8K2B
To: <sip:10.10.0.1>
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: <sip:10.10.0.1>;tag=jSggUZr0m8K2B
Call-ID: d71b4c72-d4ad-1234-3fbf-c5acbca4426b
To: <sip:10.10.0.1>;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