[Mar 4 21:47:27] Asterisk 13.2.0 built by root @ ip-10-37-XX-XX on a x86_64 running Linux on 2015-03-04 16:57:46 UTC [Mar 4 21:47:44] DEBUG[14964] pjsip: tcps0x7fb60000 Sending 4 byte(s) keep-alive to 190.77.XX-XX:47705 [Mar 4 21:47:48] DEBUG[17686] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:47:48] DEBUG[14958] threadpool.c: Destroying worker thread 120 [Mar 4 21:47:53] DEBUG[14958] threadpool.c: Increasing threadpool SIP's size by 5 [Mar 4 21:47:53] DEBUG[17702] config.c: extract int from [0] in [0, 86400] gives [0](0) [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f UAC dialog created [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module Outbound Authentica added as dialog usage, data=0x7fb5ec0026a0 [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module mod-invite added as dialog usage, data=0x7fb5ec0027c8 [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f .Session count inc to 2 by mod-invite [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module mod-100rel added as dialog usage, data=0x7fb5ec002988 [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f 100rel module attached [Mar 4 21:47:53] DEBUG[17702] pjsip: inv0x7fb5e000f UAC invite session created for dialog dlg0x7fb5e000fe18 [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f .Session count inc to 2 by Session Module [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module Session Module added as dialog usage, data=(nil) [Mar 4 21:47:53] DEBUG[14936] threadpool.c: Increasing threadpool stasis-core's size by 1 [Mar 4 21:47:53] DEBUG[17702] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb5ec0053b8' [Mar 4 21:47:53] DEBUG[17702] res_rtp_asterisk.c: Allocated port 12212 for RTP instance '0x7fb5ec0053b8' [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 ICE session created, comp_cnt=2, role is Unknown agent [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 0 added: comp_id=1, type=host, foundation=Ha25ac59, addr=10.37.XX.XX:12212, base=10.37.XX.XX:12212, prio=0x7effffff (2130706431) [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '54.159.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '54.159.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 1 added: comp_id=1, type=srflx, foundation=S369fc99e, addr=54.159.XX.XX:12212, base=10.37.XX.XX:12212, prio=0x64ffffff (1694498815) [Mar 4 21:47:53] DEBUG[17702] rtp_engine.c: RTP instance '0x7fb5ec0053b8' is setup and ready to go [Mar 4 21:47:53] DEBUG[17702] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb5ec0053b8' [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 2 added: comp_id=2, type=host, foundation=Ha25ac59, addr=10.37.XX.XX:12213, base=10.37.XX.XX:12213, prio=0x7efffffe (2130706430) [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '54.159.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '54.159.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 3 added: comp_id=2, type=srflx, foundation=S369fc99e, addr=54.159.XX.XX:12213, base=10.37.XX.XX:12213, prio=0x64fffffe (1694498814) [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Destroying ICE session 0x7fb5ec00ac18 [Mar 4 21:47:53] DEBUG[17702] pjsip: stuse0x7fb5ec0 STUN session 0x7fb5ec004118 destroy request, ref_cnt=4 [Mar 4 21:47:53] DEBUG[17702] pjsip: stuse0x7fb5ec0 STUN session 0x7fb5ec00cc28 destroy request, ref_cnt=3 [Mar 4 21:47:53] DEBUG[17702] pjsip: ice_session.c ICE session 0x7fb5ec00ac18 destroyed [Mar 4 21:47:53] DEBUG[17702] pjsip: stun_session.c STUN session 0x7fb5ec004118 destroyed [Mar 4 21:47:53] DEBUG[17702] pjsip: stun_session.c STUN session 0x7fb5ec00cc28 destroyed [Mar 4 21:47:53] DEBUG[17702] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb5ec004038' [Mar 4 21:47:53] DEBUG[17702] res_rtp_asterisk.c: Allocated port 15002 for RTP instance '0x7fb5ec004038' [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 ICE session created, comp_cnt=2, role is Unknown agent [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 0 added: comp_id=1, type=host, foundation=Ha25ac59, addr=10.37.XX.XX:15002, base=10.37.XX.XX:15002, prio=0x7effffff (2130706431) [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '54.159.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '54.159.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 1 added: comp_id=1, type=srflx, foundation=S369fc99e, addr=54.159.XX.XX:15002, base=10.37.XX.XX:15002, prio=0x64ffffff (1694498815) [Mar 4 21:47:53] DEBUG[17702] rtp_engine.c: RTP instance '0x7fb5ec004038' is setup and ready to go [Mar 4 21:47:53] DEBUG[17702] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb5ec004038' [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 2 added: comp_id=2, type=host, foundation=Ha25ac59, addr=10.37.XX.XX:15003, base=10.37.XX.XX:15003, prio=0x7efffffe (2130706430) [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '54.159.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '54.159.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Candidate 3 added: comp_id=2, type=srflx, foundation=S369fc99e, addr=54.159.XX.XX:15003, base=10.37.XX.XX:15003, prio=0x64fffffe (1694498814) [Mar 4 21:47:53] DEBUG[17702] pjsip: icess0x7fb5ec0 Destroying ICE session 0x7fb5ec00dc28 [Mar 4 21:47:53] DEBUG[17702] pjsip: stuse0x7fb5ec0 STUN session 0x7fb5ec00fc38 destroy request, ref_cnt=4 [Mar 4 21:47:53] DEBUG[17702] pjsip: stuse0x7fb5ec0 STUN session 0x7fb5ec010c38 destroy request, ref_cnt=3 [Mar 4 21:47:53] DEBUG[17702] pjsip: ice_session.c ICE session 0x7fb5ec00dc28 destroyed [Mar 4 21:47:53] DEBUG[17702] pjsip: stun_session.c STUN session 0x7fb5ec00fc38 destroyed [Mar 4 21:47:53] DEBUG[17702] pjsip: stun_session.c STUN session 0x7fb5ec010c38 destroyed [Mar 4 21:47:53] DEBUG[17702] pjsip: endpoint Request msg INVITE/cseq=16514 (tdta0x7fb6000044d0) created. [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Method is INVITE [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module WebSocket Transport Module added as dialog usage, data=(nil) [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f Module NAT added as dialog usage, data=(nil) [Mar 4 21:47:53] DEBUG[17702] pjsip: inv0x7fb5e000f .Sending Request msg INVITE/cseq=16514 (tdta0x7fb6000044d0) [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f ..Sending Request msg INVITE/cseq=16514 (tdta0x7fb6000044d0) [Mar 4 21:47:53] DEBUG[17702] pjsip: tsx0x7fb5e0016 ...Transaction created for Request msg INVITE/cseq=16513 (tdta0x7fb6000044d0) [Mar 4 21:47:53] DEBUG[17702] pjsip: tsx0x7fb5e0016 ..Sending Request msg INVITE/cseq=16513 (tdta0x7fb6000044d0) in state Null [Mar 4 21:47:53] DEBUG[17702] pjsip: sip_resolve.c ...Target '190.77.XX-XX:47705' type=TCP resolved to '190.77.XX-XX:47705' type=TCP (TCP transport) [Mar 4 21:47:53] DEBUG[17702] pjsip: tcpc0x7fb5ec01 ...TCP client transport created [Mar 4 21:47:53] DEBUG[17702] pjsip: tcpc0x7fb5ec01 ...TCP transport 10.37.XX.XX:35898 is connecting to 190.77.XX-XX:47705... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '190.77.XX-XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '190.77.XX-XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port ''. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '10.37.XX.XX:35898' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '10.37.XX.XX' and port '35898'. [Mar 4 21:47:53] DEBUG[17702] netsock2.c: Splitting '190.77.XX-XX:47705' into... [Mar 4 21:47:53] DEBUG[17702] netsock2.c: ...host '190.77.XX-XX' and port '47705'. [Mar 4 21:47:53] VERBOSE[17702] res_pjsip_logger.c: <--- Transmitting SIP request (1062 bytes) to TCP:190.77.XX-XX:47705 ---> INVITE sip:nathy@190.77.XX-XX:47705;transport=tcp;rinstance=bfcd3ead72eed6f3 SIP/2.0 Via: SIP/2.0/TCP 54.159.XX.XX:35898;rport;branch=z9hG4bKPj0dc75035-f22f-4128-9bbd-f8d5200eaa3d;alias From: ;tag=ae638036-29b0-4ddf-b7c1-4222093d9912 To: Contact: Call-ID: 279ce138-2a64-434d-9f65-7a9e84123bf0 CSeq: 16513 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 302 v=0 o=- 2041618354 2041618354 IN IP4 10.37.XX.XX s=Asterisk c=IN IP4 54.159.XX.XX t=0 0 m=audio 12212 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 15002 RTP/AVP 100 a=rtpmap:100 VP8/90000 a=sendrecv [Mar 4 21:47:53] DEBUG[17702] pjsip: tsx0x7fb5e0016 ...State changed from Null to Calling, event=TX_MSG [Mar 4 21:47:53] DEBUG[17702] pjsip: dlg0x7fb5e000f ....Transaction tsx0x7fb5e0016b28 state changed to Calling [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The state change pertains to the session with nathy [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fb5e0016b28) [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: There is no transaction involved in this state change [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The current inv state is CALLING [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Source of transaction state change is TX_MSG [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Sending request [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Method is INVITE [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The state change pertains to the session with nathy [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fb5e0016b28) [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The transaction involved in this state change is 0x7fb5e0016b28 [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The current transaction state is Calling [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: The current inv state is CALLING [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Sending request [Mar 4 21:47:53] DEBUG[17702] res_pjsip_session.c: Method is INVITE [Mar 4 21:48:13] DEBUG[17708] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:13] DEBUG[14936] threadpool.c: Destroying worker thread 132 [Mar 4 21:48:23] DEBUG[17707] channel.c: Hanging up channel 'PJSIP/nathy-00000002' [Mar 4 21:48:23] DEBUG[17707] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Mar 4 21:48:23] DEBUG[17702] pjsip: inv0x7fb5e000f .Delaying CANCEL since no provisional response is received yet [Mar 4 21:48:23] DEBUG[14950] cdr.c: Finalized CDR for PJSIP/nathy-00000002 - start 1425505673.227953 answer 0.000000 end 1425505703.259204 dispo FAILED [Mar 4 21:48:23] DEBUG[14950] cdr.c: Skipping CDR for PJSIP/nathy-00000002 since we weren't answered [Mar 4 21:48:23] DEBUG[14936] threadpool.c: Increasing threadpool stasis-core's size by 1 [Mar 4 21:48:23] DEBUG[14948] devicestate.c: No provider found, checking channel drivers for PJSIP - nathy [Mar 4 21:48:23] DEBUG[14948] devicestate.c: Changing state for PJSIP/nathy - state 1 (Not in use) [Mar 4 21:48:25] DEBUG[14964] pjsip: tsx0x7fb5e0016 Timeout timer event [Mar 4 21:48:25] DEBUG[14964] pjsip: tsx0x7fb5e0016 .State changed from Calling to Terminated, event=TIMER [Mar 4 21:48:25] DEBUG[14964] pjsip: dlg0x7fb5e000f ..Transaction tsx0x7fb5e0016b28 state changed to Terminated [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The state change pertains to the session with nathy [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fb5e0016b28) [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: There is no transaction involved in this state change [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: Source of transaction state change is TIMER [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: Destroying SIP session with endpoint nathy [Mar 4 21:48:25] DEBUG[14964] taskprocessor.c: destroying taskprocessor '43ddcdb6-5c59-43a5-aa25-78c49198f269' [Mar 4 21:48:25] DEBUG[14964] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb5ec0053b8' [Mar 4 21:48:25] DEBUG[14964] rtp_engine.c: Destroyed RTP instance '0x7fb5ec0053b8' [Mar 4 21:48:25] DEBUG[14964] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb5ec004038' [Mar 4 21:48:25] DEBUG[14964] rtp_engine.c: Destroyed RTP instance '0x7fb5ec004038' [Mar 4 21:48:25] DEBUG[14964] pjsip: dlg0x7fb5e000f ....Session count dec to 2 by Session Module [Mar 4 21:48:25] DEBUG[14964] pjsip: dlg0x7fb5e000f ....Session count dec to 1 by mod-invite [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: inv_session 0x7fb5ec0027c8 has no ast session [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The transaction involved in this state change is 0x7fb5e0016b28 [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The current transaction state is Terminated [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The transaction state change event is TIMER [Mar 4 21:48:25] DEBUG[14964] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 4 21:48:25] DEBUG[14964] pjsip: dlg0x7fb5e000f ...Dialog destroyed [Mar 4 21:48:25] DEBUG[14964] pjsip: tsx0x7fb5e0016 Timeout timer event [Mar 4 21:48:25] DEBUG[14964] pjsip: tsx0x7fb5e0016 .State changed from Terminated to Destroyed, event=TIMER [Mar 4 21:48:25] DEBUG[14964] pjsip: tsx0x7fb5e0016 Transaction destroyed! [Mar 4 21:48:25] ERROR[14964] pjsip: tcpc0xb48588 TCP connect() error: Connection timed out [code=120110] [Mar 4 21:48:25] DEBUG[14964] pjsip: tdta0x7fb5e000 Destroying txdata Request msg INVITE/cseq=4108 (tdta0x7fb5e0004d60) [Mar 4 21:48:25] DEBUG[14964] pjsip: tcpc0xb48588 TCP send() error, sent=-120110 [Mar 4 21:48:25] DEBUG[14964] pjsip: tcpc0xb48588 TCP transport destroyed with reason 120110: Connection timed out [Mar 4 21:48:43] DEBUG[17717] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:43] DEBUG[14936] threadpool.c: Destroying worker thread 133 [Mar 4 21:48:45] DEBUG[16578] config.c: extract int from [0] in [0, 86400] gives [0](0) [Mar 4 21:48:53] DEBUG[17706] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:53] DEBUG[17705] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:53] DEBUG[17704] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:53] DEBUG[17703] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 4 21:48:53] DEBUG[14958] threadpool.c: Destroying worker thread 131 [Mar 4 21:48:53] DEBUG[14958] threadpool.c: Destroying worker thread 130 [Mar 4 21:48:53] DEBUG[14958] threadpool.c: Destroying worker thread 129 [Mar 4 21:48:53] DEBUG[14958] threadpool.c: Destroying worker thread 128