[Dec 22 16:51:00] Asterisk SVN-branch-13-r429983 built by root @ newtonr-laptop on a x86_64 running Linux on 2014-12-22 20:00:06 UTC [Dec 22 16:51:00] NOTICE[5769] cdr.c: CDR simple logging enabled. [Dec 22 16:51:00] NOTICE[5769] loader.c: 278 modules will be loaded. [Dec 22 16:51:00] WARNING[5769] loader.c: Error loading module 'res_monitor.so': /usr/lib/asterisk/modules/res_monitor.so: undefined symbol: __ast_beep_start [Dec 22 16:51:01] WARNING[5769] res_phoneprov.c: Unable to find a valid server address or name. [Dec 22 16:51:01] VERBOSE[5769] res_phoneprov.c: Registered phoneprov provider 'sipusers'. [Dec 22 16:51:01] ERROR[5769] ari/config.c: No configured users for ARI [Dec 22 16:51:01] ERROR[5769] pbx_lua.c: Error loading extensions.lua: cannot open '/etc/asterisk/extensions.lua' for reading: No such file or directory [Dec 22 16:51:01] WARNING[5769] loader.c: Error loading module 'res_ari_mailboxes.so': /usr/lib/asterisk/modules/res_ari_mailboxes.so: undefined symbol: stasis_app_mailbox_to_json [Dec 22 16:51:01] WARNING[5769] loader.c: Module 'res_ari_mailboxes.so' could not be loaded. [Dec 22 16:51:01] NOTICE[5769] res_config_ldap.c: No directory user found, anonymous binding as default. [Dec 22 16:51:01] ERROR[5769] res_config_ldap.c: No directory URL or host found. [Dec 22 16:51:01] ERROR[5769] res_config_ldap.c: Cannot load LDAP RealTime driver. [Dec 22 16:51:01] NOTICE[5769] chan_skinny.c: Configuring skinny from skinny.conf [Dec 22 16:51:01] VERBOSE[5769] res_phoneprov.c: Registered phoneprov provider 'res_pjsip_phoneprov_provider'. [Dec 22 16:51:02] NOTICE[5769] confbridge/conf_config_parser.c: Adding default_menu menu to app_confbridge [Dec 22 16:51:02] NOTICE[5769] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs. [Dec 22 16:51:02] NOTICE[5769] pbx_ael.c: File /etc/asterisk/extensions.ael not found; AEL declining load [Dec 22 16:51:02] VERBOSE[5769] asterisk.c: Asterisk Ready. [Dec 22 16:51:11] DEBUG[5845] http.c: HTTP opening session. Top level [Dec 22 16:51:11] DEBUG[5845] http.c: HTTP Request URI is /ws [Dec 22 16:51:11] DEBUG[5845] http.c: match request [ws] with handler [httpstatus] len 10 [Dec 22 16:51:11] DEBUG[5845] http.c: match request [ws] with handler [phoneprov] len 9 [Dec 22 16:51:11] DEBUG[5845] http.c: match request [ws] with handler [static] len 6 [Dec 22 16:51:11] DEBUG[5845] http.c: match request [ws] with handler [ari] len 3 [Dec 22 16:51:11] DEBUG[5845] http.c: match request [ws] with handler [ws] len 2 [Dec 22 16:51:11] DEBUG[5845] http.c: Match made with [ws] [Dec 22 16:51:11] DEBUG[5845] res_pjsip_transport_websocket.c: Write timeout for WS/WSS transports: 100 [Dec 22 16:51:14] DEBUG[5846] http.c: HTTP opening session. Top level [Dec 22 16:51:14] DEBUG[5846] http.c: HTTP Request URI is /ws [Dec 22 16:51:14] DEBUG[5846] http.c: match request [ws] with handler [httpstatus] len 10 [Dec 22 16:51:14] DEBUG[5846] http.c: match request [ws] with handler [phoneprov] len 9 [Dec 22 16:51:14] DEBUG[5846] http.c: match request [ws] with handler [static] len 6 [Dec 22 16:51:14] DEBUG[5846] http.c: match request [ws] with handler [ari] len 3 [Dec 22 16:51:14] DEBUG[5846] http.c: match request [ws] with handler [ws] len 2 [Dec 22 16:51:14] DEBUG[5846] http.c: Match made with [ws] [Dec 22 16:51:14] DEBUG[5846] res_pjsip_transport_websocket.c: Write timeout for WS/WSS transports: 100 [Dec 22 16:51:14] DEBUG[5795] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=980 (rdata0x7f9eb8008170) [Dec 22 16:51:14] VERBOSE[5795] res_pjsip_logger.c: <--- Received SIP request (669 bytes) from WS:10.24.18.124:45219 ---> REGISTER sip:10.24.18.124 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKiZBfeVtdXih7zniSksVtnspRa37TIhTB;rport From: "101";tag=EgyudklDe7vT0DmM7lq4 To: "101" Contact: "101";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: 6e9a97d4-5d7c-66aa-cfc8-4a6d552aa580 CSeq: 980 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="101",realm="10.24.18.124",nonce="",uri="sip:10.24.18.124",response="" User-Agent: IM-client/OMA1.0 sipML5-v1.2014.12.11 Organization: Doubango Telecom Supported: path [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=980 (rdata0x7f9eb800ea48) [Dec 22 16:51:14] DEBUG[5795] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:51:14] DEBUG[5795] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 101 [Dec 22 16:51:14] DEBUG[5795] pjsip: endpoint .Response msg 401/REGISTER/cseq=980 (tdta0x7f9eb800c2b0) created [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (520 bytes) to WS:10.24.18.124:45219 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=45219;received=10.24.18.124;branch=z9hG4bKiZBfeVtdXih7zniSksVtnspRa37TIhTB Call-ID: 6e9a97d4-5d7c-66aa-cfc8-4a6d552aa580 From: "101" ;tag=EgyudklDe7vT0DmM7lq4 To: "101" ;tag=z9hG4bKiZBfeVtdXih7zniSksVtnspRa37TIhTB CSeq: 980 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1419288674/95c9259079cd401f17f954e4e8a3d088",opaque="3235bfc917f3896f",algorithm=md5,qop="auth" Content-Length: 0 [Dec 22 16:51:14] DEBUG[5795] pjsip: tdta0x7f9eb800 .Destroying txdata Response msg 401/REGISTER/cseq=980 (tdta0x7f9eb800c2b0) [Dec 22 16:51:14] DEBUG[5795] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=981 (rdata0x7f9eb8008170) [Dec 22 16:51:14] VERBOSE[5795] res_pjsip_logger.c: <--- Received SIP request (843 bytes) from WS:10.24.18.124:45219 ---> REGISTER sip:10.24.18.124 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKMBmbTwqIQdSThTqtSVetdy33UFGqglfR;rport From: "101";tag=EgyudklDe7vT0DmM7lq4 To: "101" Contact: "101";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: 6e9a97d4-5d7c-66aa-cfc8-4a6d552aa580 CSeq: 981 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="101",realm="asterisk",nonce="1419288674/95c9259079cd401f17f954e4e8a3d088",uri="sip:10.24.18.124",response="1fa8b777ea2077b3b13c28182d06b432",algorithm=md5,cnonce="ac85d16d74c56013e1282b6505b5a764",opaque="3235bfc917f3896f",qop=auth,nc=00000001 User-Agent: IM-client/OMA1.0 sipML5-v1.2014.12.11 Organization: Doubango Telecom Supported: path [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=981 (rdata0x7f9eb80101e8) [Dec 22 16:51:14] DEBUG[5795] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:51:14] DEBUG[5795] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 101 [Dec 22 16:51:14] DEBUG[5795] pjsip: endpoint .Response msg 401/REGISTER/cseq=981 (tdta0x7f9eb800c2b0) created [Dec 22 16:51:14] DEBUG[5795] res_pjsip_authenticator_digest.c: Calculated nonce 1419288674/95c9259079cd401f17f954e4e8a3d088. Actual nonce is 1419288674/95c9259079cd401f17f954e4e8a3d088 [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:14] DEBUG[5795] pjsip: tdta0x7f9eb800 .Destroying txdata Response msg 401/REGISTER/cseq=981 (tdta0x7f9eb800c2b0) [Dec 22 16:51:14] DEBUG[5795] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:51:14] DEBUG[5801] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:51:14] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 101 [Dec 22 16:51:14] DEBUG[5786] devicestate.c: Changing state for PJSIP/101 - state 1 (Not in use) [Dec 22 16:51:14] DEBUG[5801] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:51:14] DEBUG[5795] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:51:14] DEBUG[5795] pjsip: endpoint Response msg 200/REGISTER/cseq=981 (tdta0x7f9eb800da10) created [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:14] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:14] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (482 bytes) to WS:10.24.18.124:45219 ---> SIP/2.0 200 OK Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=45219;received=10.24.18.124;branch=z9hG4bKMBmbTwqIQdSThTqtSVetdy33UFGqglfR Call-ID: 6e9a97d4-5d7c-66aa-cfc8-4a6d552aa580 From: "101" ;tag=EgyudklDe7vT0DmM7lq4 To: "101" ;tag=z9hG4bKMBmbTwqIQdSThTqtSVetdy33UFGqglfR CSeq: 981 REGISTER Date: Mon, 22 Dec 2014 22:51:14 GMT Contact: ;expires=199 Content-Length: 0 [Dec 22 16:51:14] DEBUG[5795] pjsip: tdta0x7f9eb800 Destroying txdata Response msg 200/REGISTER/cseq=981 (tdta0x7f9eb800da10) [Dec 22 16:51:14] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 101 [Dec 22 16:51:14] DEBUG[5786] devicestate.c: Changing state for PJSIP/101 - state 1 (Not in use) [Dec 22 16:51:20] DEBUG[5800] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=13240 (rdata0x3341b78) [Dec 22 16:51:20] VERBOSE[5800] res_pjsip_logger.c: <--- Received SIP request (1060 bytes) from UDP:10.24.18.16:5060 ---> INVITE sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjPM2BY4ftGRD-ccYEgnsByE.3NcfZGOmm Max-Forwards: 70 From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: Contact: "Alice" Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb CSeq: 13240 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Digium D40 1_4_2_0_63880 Content-Type: application/sdp Content-Length: 430 v=0 o=- 114659970 114659970 IN IP4 10.24.18.16 s=digphn c=IN IP4 10.24.18.16 t=0 0 a=X-nat:0 m=audio 4032 RTP/AVP 111 18 0 58 118 9 8 58 96 a=rtcp:4033 IN IP4 10.24.18.16 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=13240 (rdata0x7f9ec0002d58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:51:20] DEBUG[5795] pjsip: endpoint .Response msg 401/INVITE/cseq=13240 (tdta0x7f9eb800da10) created [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (524 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjPM2BY4ftGRD-ccYEgnsByE.3NcfZGOmm Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: ;tag=z9hG4bKPjPM2BY4ftGRD-ccYEgnsByE.3NcfZGOmm CSeq: 13240 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1419288680/02305ce15fd82ddef1bf847d197f48a9",opaque="11e1f8a020ee4900",algorithm=md5,qop="auth" Content-Length: 0 [Dec 22 16:51:20] DEBUG[5795] pjsip: tdta0x7f9eb800 .Destroying txdata Response msg 401/INVITE/cseq=13240 (tdta0x7f9eb800da10) [Dec 22 16:51:20] DEBUG[5776] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:51:20] DEBUG[5778] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:51:20] DEBUG[5774] threadpool.c: Destroying worker thread 1 [Dec 22 16:51:20] DEBUG[5780] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:51:20] DEBUG[5779] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:51:20] DEBUG[5774] threadpool.c: Destroying worker thread 2 [Dec 22 16:51:20] DEBUG[5774] threadpool.c: Destroying worker thread 4 [Dec 22 16:51:20] DEBUG[5774] threadpool.c: Destroying worker thread 3 [Dec 22 16:51:20] DEBUG[5800] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=13240 (rdata0x7f9ec0004ca8) [Dec 22 16:51:20] VERBOSE[5800] res_pjsip_logger.c: <--- Received SIP request (374 bytes) from UDP:10.24.18.16:5060 ---> ACK sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjPM2BY4ftGRD-ccYEgnsByE.3NcfZGOmm Max-Forwards: 70 From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: ;tag=z9hG4bKPjPM2BY4ftGRD-ccYEgnsByE.3NcfZGOmm Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb CSeq: 13240 ACK Content-Length: 0 [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=13240 (rdata0x7f9ec0006bf8) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:51:20] DEBUG[5800] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=13241 (rdata0x7f9ec0004b98) [Dec 22 16:51:20] VERBOSE[5800] res_pjsip_logger.c: <--- Received SIP request (1351 bytes) from UDP:10.24.18.16:5060 ---> INVITE sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjIYpWbY0UKA-gjgdzahq8rnz3fa4OE.dO Max-Forwards: 70 From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: Contact: "Alice" Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb CSeq: 13241 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Digium D40 1_4_2_0_63880 Authorization: Digest username="6001", realm="asterisk", nonce="1419288680/02305ce15fd82ddef1bf847d197f48a9", uri="sip:101@10.24.18.124", response="fc6454c52340e88bf2df3f1092751177", algorithm=md5, cnonce="lYFL9-31TWQ3mCetDLi7prfpPsTcxpAM", opaque="11e1f8a020ee4900", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 430 v=0 o=- 114659970 114659970 IN IP4 10.24.18.16 s=digphn c=IN IP4 10.24.18.16 t=0 0 a=X-nat:0 m=audio 4032 RTP/AVP 111 18 0 58 118 9 8 58 96 a=rtcp:4033 IN IP4 10.24.18.16 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] DEBUG[5800] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5800] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=13241 (rdata0x7f9ec0007a68) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:51:20] DEBUG[5795] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:51:20] DEBUG[5795] pjsip: endpoint .Response msg 401/INVITE/cseq=13241 (tdta0x7f9eb800da10) created [Dec 22 16:51:20] DEBUG[5795] res_pjsip_authenticator_digest.c: Calculated nonce 1419288680/02305ce15fd82ddef1bf847d197f48a9. Actual nonce is 1419288680/02305ce15fd82ddef1bf847d197f48a9 [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: tdta0x7f9eb800 .Destroying txdata Response msg 401/INVITE/cseq=13241 (tdta0x7f9eb800da10) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ..Transaction created for Request msg INVITE/cseq=13241 (rdata0x7f9ec0007a68) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 .Incoming Request msg INVITE/cseq=13241 (rdata0x7f9ec0007a68) in state Null [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ..State changed from Null to Trying, event=RX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ...Transaction tsx0x7f9eb8019298 state changed to Trying [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 .UAS dialog created [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 .Module mod-invite added as dialog usage, data=0x7f9eb800d708 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ..Session count inc to 2 by mod-invite [Dec 22 16:51:20] DEBUG[5795] pjsip: inv0x7f9eb8018 .UAS invite session created for dialog dlg0x7f9eb8018a88 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 .Module Session Module added as dialog usage, data=(nil) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ..Session count inc to 2 by Session Module [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f9eb8017618' [Dec 22 16:51:20] DEBUG[5795] res_rtp_asterisk.c: Allocated port 12060 for RTP instance '0x7f9eb8017618' [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 ICE session created, comp_cnt=2, role is Unknown agent [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:12060, base=10.24.18.124:12060, prio=0x7effffff (2130706431) [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:17495, base=10.24.18.124:12060, prio=0x64ffffff (1694498815) [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: RTP instance '0x7f9eb8017618' is setup and ready to go [Dec 22 16:51:20] DEBUG[5795] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f9eb8017618' [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:12061, base=10.24.18.124:12061, prio=0x7efffffe (2130706430) [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:17497, base=10.24.18.124:12061, prio=0x64fffffe (1694498814) [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Destroying ICE session 0x7f9eb801d6f8 [Dec 22 16:51:20] DEBUG[5795] pjsip: stuse0x7f9eb80 STUN session 0x7f9eb8012a88 destroy request, ref_cnt=4 [Dec 22 16:51:20] DEBUG[5795] pjsip: stuse0x7f9eb80 STUN session 0x7f9eb8013a88 destroy request, ref_cnt=3 [Dec 22 16:51:20] DEBUG[5795] pjsip: ice_session.c ICE session 0x7f9eb801d6f8 destroyed [Dec 22 16:51:20] DEBUG[5795] pjsip: stun_session.c STUN session 0x7f9eb8012a88 destroyed [Dec 22 16:51:20] DEBUG[5795] pjsip: stun_session.c STUN session 0x7f9eb8013a88 destroyed [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 111 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 18 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 0 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 58 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 118 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 9 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 8 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 58 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Setting payload 96 (0x7f9eb801aa48) based on m type on 0x7f9f1c153680 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 0 (0x7f9eb800bdc8) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 8 (0x7f9eb8012728) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 9 (0x7f9eb80126a8) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 18 (0x7f9eb8012628) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 58 (0x7f9eb8013878) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 96 (0x7f9eb8012c98) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 111 (0x7f9eb800bd48) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Copying payload 118 (0x7f9eb8013de8) from 0x7f9f1c153680 to 0x7f9eb80177e0 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Media stream 'audio' handled by audio [Dec 22 16:51:20] DEBUG[5795] pjsip: endpoint .Response msg 100/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) created [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 .Initial answer Response msg 100/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:51:20] DEBUG[5795] pjsip: inv0x7f9eb8018 .Sending Response msg 100/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ..Sending Response msg 100/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ..Sending Response msg 100/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) in state Trying [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (325 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjIYpWbY0UKA-gjgdzahq8rnz3fa4OE.dO Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: CSeq: 13241 INVITE Content-Length: 0 [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ...State changed from Trying to Proceeding, event=TX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ....Transaction tsx0x7f9eb8019298 state changed to Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is INCOMING [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8019298 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is INCOMING [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 Module NAT added as dialog usage, data=(nil) [Dec 22 16:51:20] DEBUG[5795] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6001-00000000 [Dec 22 16:51:20] DEBUG[5847][C-00000000] pbx.c: Launching 'Dial' [Dec 22 16:51:20] DEBUG[5795] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 UAC dialog created [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module Outbound Authentica added as dialog usage, data=0x7f9eb80153e0 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module mod-invite added as dialog usage, data=0x7f9eb80158e8 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 .Session count inc to 2 by mod-invite [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module mod-100rel added as dialog usage, data=0x7f9eb8015aa8 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 100rel module attached [Dec 22 16:51:20] DEBUG[5795] pjsip: inv0x7f9eb8023 UAC invite session created for dialog dlg0x7f9eb8023568 [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 .Session count inc to 2 by Session Module [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module Session Module added as dialog usage, data=(nil) [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f9eb8015538' [Dec 22 16:51:20] DEBUG[5795] res_rtp_asterisk.c: Allocated port 16540 for RTP instance '0x7f9eb8015538' [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 ICE session created, comp_cnt=2, role is Unknown agent [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:16540, base=10.24.18.124:16540, prio=0x7effffff (2130706431) [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16540, base=10.24.18.124:16540, prio=0x64ffffff (1694498815) [Dec 22 16:51:20] DEBUG[5795] rtp_engine.c: RTP instance '0x7f9eb8015538' is setup and ready to go [Dec 22 16:51:20] DEBUG[5795] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f9eb8015538' [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:16541, base=10.24.18.124:16541, prio=0x7efffffe (2130706430) [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:20] DEBUG[5795] pjsip: icess0x7f9eb80 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16541, base=10.24.18.124:16541, prio=0x64fffffe (1694498814) [Dec 22 16:51:20] DEBUG[5795] sdp_srtp.c: local_key64 nTo7avaDBQkS4VD6nL24DViGeeAwOYoXSFoOm7j/ len 40 [Dec 22 16:51:20] DEBUG[5795] pjsip: endpoint Request msg INVITE/cseq=32754 (tdta0x7f9eb800da10) created. [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module WebSocket Transport Module added as dialog usage, data=(nil) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 Module NAT added as dialog usage, data=(nil) [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5796] pjsip: inv0x7f9eb8018 .Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5796] pjsip: dlg0x7f9eb8018 ..Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5796] pjsip: tsx0x7f9eb8019 ..Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) in state Proceeding [Dec 22 16:51:20] DEBUG[5796] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5796] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5796] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5796] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] VERBOSE[5796] res_pjsip_logger.c: <--- Transmitting SIP response (512 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjIYpWbY0UKA-gjgdzahq8rnz3fa4OE.dO Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: ;tag=f7964a4c-022b-4d8c-9bf6-3a641a7f3690 CSeq: 13241 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Content-Length: 0 [Dec 22 16:51:20] DEBUG[5796] pjsip: tsx0x7f9eb8019 ...State changed from Proceeding to Proceeding, event=TX_MSG [Dec 22 16:51:20] DEBUG[5796] pjsip: dlg0x7f9eb8018 ....Transaction tsx0x7f9eb8019298 state changed to Proceeding [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8019298 [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5796] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5795] pjsip: inv0x7f9eb8023 .Sending Request msg INVITE/cseq=32754 (tdta0x7f9eb800da10) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ..Sending Request msg INVITE/cseq=32754 (tdta0x7f9eb800da10) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 ...Transaction created for Request msg INVITE/cseq=32753 (tdta0x7f9eb800da10) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 ..Sending Request msg INVITE/cseq=32753 (tdta0x7f9eb800da10) in state Null [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_resolve.c ...Target '10.24.18.124:45219' type=WS resolved to '10.24.18.124:45219' type=WS ((null)) [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP request (1533 bytes) to WS:10.24.18.124:45219 ---> INVITE sip:101@10.24.18.124:45219;transport=ws;rtcweb-breaker=no SIP/2.0 Via: SIP/2.0/WS 10.24.18.124:45219;rport;branch=z9hG4bKPjd8c9973d-4b84-4b97-93e9-77f92635913e;alias From: "Alice" ;tag=a15f2f26-97a2-4c55-b54c-342d8e55dbf1 To: Contact: Call-ID: e0fa5983-33b8-490e-8b4d-ade62def3986 CSeq: 32753 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 827 v=0 o=- 1034107634 1034107634 IN IP4 10.24.18.124 s=Asterisk c=IN IP4 10.24.18.124 t=0 0 m=audio 16540 UDP/TLS/RTP/SAVPF 0 101 a=connection:new a=setup:actpass a=fingerprint:SHA-256 D3:4C:64:80:0A:5D:BA:49:A1:CD:56:90:20:D1:5B:B3:B5:BA:CF:41:C1:5F:F6:6A:31:C4:11:36:5F:B8:33:26 a=ice-ufrag:3d66cc660fe1c384318649db2ab33644 a=ice-pwd:54a0e52d3882b1610e74b5262ba8d60a a=candidate:Ha18127c 1 UDP 2130706431 10.24.18.124 16540 typ host a=candidate:Sd8cff501 1 UDP 1694498815 216.207.245.1 16540 typ srflx raddr 10.24.18.124 rport 16540 a=candidate:Ha18127c 2 UDP 2130706430 10.24.18.124 16541 typ host a=candidate:Sd8cff501 2 UDP 1694498814 216.207.245.1 16541 typ srflx raddr 10.24.18.124 rport 16541 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 ...State changed from Null to Calling, event=TX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ....Transaction tsx0x7f9eb8038c58 state changed to Calling [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending request [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8038c58 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current transaction state is Calling [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending request [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=32753 (rdata0x7f9eb8008170) [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Received SIP response (376 bytes) from WS:10.24.18.124:45219 ---> SIP/2.0 100 Trying (sent from the Transaction Layer) Via: SIP/2.0/WS 10.24.18.124:45219;rport=45219;branch=z9hG4bKPjd8c9973d-4b84-4b97-93e9-77f92635913e;alias From: "Alice";tag=a15f2f26-97a2-4c55-b54c-342d8e55dbf1 To: Call-ID: e0fa5983-33b8-490e-8b4d-ade62def3986 CSeq: 32753 INVITE Content-Length: 0 [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 .Incoming Response msg 100/INVITE/cseq=32753 (rdata0x7f9eb803f868) in state Calling [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 ..State changed from Calling to Proceeding, event=RX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Received Response msg 100/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Transaction tsx0x7f9eb8038c58 state changed to Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8038c58 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Received response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Response is 100 Trying (sent from the Transaction Layer) [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=32753 (rdata0x7f9eb8008170) [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Received SIP response (503 bytes) from WS:10.24.18.124:45219 ---> SIP/2.0 180 Ringing Via: SIP/2.0/WS 10.24.18.124:45219;rport=45219;branch=z9hG4bKPjd8c9973d-4b84-4b97-93e9-77f92635913e;alias From: "Alice";tag=a15f2f26-97a2-4c55-b54c-342d8e55dbf1 To: ;tag=QT2nyyreQK4IVlq9vr64 Contact: Call-ID: e0fa5983-33b8-490e-8b4d-ade62def3986 CSeq: 32753 INVITE Content-Length: 0 Allow: ACK, BYE, CANCEL, INVITE, MESSAGE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:20] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 .Incoming Response msg 180/INVITE/cseq=32753 (rdata0x7f9eb803f868) in state Proceeding [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8038 ..State changed from Proceeding to Proceeding, event=RX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Received Response msg 180/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ....Route-set updated [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Transaction tsx0x7f9eb8038c58 state changed to Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Received response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8038c58 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Received response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 101 [Dec 22 16:51:20] DEBUG[5786] devicestate.c: Changing state for PJSIP/101 - state 6 (Ringing) [Dec 22 16:51:20] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5795] pjsip: inv0x7f9eb8018 .Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ..Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:20] DEBUG[5843] app_queue.c: Device 'PJSIP/101' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ..Sending Response msg 180/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) in state Proceeding [Dec 22 16:51:20] DEBUG[5786] devicestate.c: Changing state for PJSIP/6001 - state 2 (In use) [Dec 22 16:51:20] DEBUG[5843] app_queue.c: Device 'PJSIP/6001' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:20] DEBUG[5795] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:20] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:20] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (512 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjIYpWbY0UKA-gjgdzahq8rnz3fa4OE.dO Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: ;tag=f7964a4c-022b-4d8c-9bf6-3a641a7f3690 CSeq: 13241 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Contact: Content-Length: 0 [Dec 22 16:51:20] DEBUG[5795] pjsip: tsx0x7f9eb8019 ...State changed from Proceeding to Proceeding, event=TX_MSG [Dec 22 16:51:20] DEBUG[5795] pjsip: dlg0x7f9eb8018 ....Transaction tsx0x7f9eb8019298 state changed to Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8019298 [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:20] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:51:26] DEBUG[5795] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb8008170) [Dec 22 16:51:26] VERBOSE[5795] res_pjsip_logger.c: <--- Received SIP response (1823 bytes) from WS:10.24.18.124:45219 ---> SIP/2.0 200 OK Via: SIP/2.0/WS 10.24.18.124:45219;rport=45219;branch=z9hG4bKPjd8c9973d-4b84-4b97-93e9-77f92635913e;alias From: "Alice";tag=a15f2f26-97a2-4c55-b54c-342d8e55dbf1 To: ;tag=QT2nyyreQK4IVlq9vr64 Contact: Call-ID: e0fa5983-33b8-490e-8b4d-ade62def3986 CSeq: 32753 INVITE Content-Type: application/sdp Content-Length: 1291 Allow: ACK, BYE, CANCEL, INVITE, MESSAGE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE v=0 o=Mozilla-SIPUA-34.0 27168 0 IN IP4 0.0.0.0 s=Doubango Telecom - firefox t=0 0 a=ice-ufrag:4972e4a5 a=ice-pwd:faa8f3c4526fe89e686f9b59ad315d2b a=fingerprint:sha-256 68:E4:20:B7:30:EF:4B:7D:F7:92:C9:60:12:9A:38:49:1F:0C:BE:8C:4C:14:E2:93:3A:AA:2F:8C:16:22:D3:19 m=audio 9 UDP/TLS/RTP/SAVPF 0 101 c=IN IP4 0.0.0.0 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=setup:active a=candidate:0 1 UDP 2122252543 10.24.18.124 59105 typ host a=candidate:0 2 UDP 2122252542 10.24.18.124 35562 typ host a=candidate:1 1 UDP 1686110207 216.207.245.1 17498 typ srflx raddr 10.24.18.124 rport 59105 a=candidate:2 1 UDP 1686110207 216.207.245.1 17499 typ srflx raddr 10.24.18.124 rport 59105 a=candidate:3 1 UDP 1686110207 216.207.245.1 17500 typ srflx raddr 10.24.18.124 rport 59105 a=candidate:1 2 UDP 1686110206 216.207.245.1 35562 typ srflx raddr 10.24.18.124 rport 35562 a=candidate:2 2 UDP 1686110206 216.207.245.1 17502 typ srflx raddr 10.24.18.124 rport 35562 a=candidate:3 2 UDP 1686110206 216.207.245.1 17503 typ srflx raddr 10.24.18.124 rport 35562 a=candidate:4 1 UDP 1686110207 216.207.245.1 17501 typ srflx raddr 10.24.18.124 rport 59105 a=candidate:4 2 UDP 1686110206 216.207.245.1 17504 typ srflx raddr 10.24.18.124 rport 35562 [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:26] DEBUG[5795] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:26] DEBUG[5795] pjsip: tsx0x7f9eb8038 .Incoming Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb803f868) in state Proceeding [Dec 22 16:51:26] DEBUG[5795] pjsip: tsx0x7f9eb8038 ..State changed from Proceeding to Terminated, event=RX_MSG [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Received Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8023 ....Route-set updated [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8023 ....Route-set frozen [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8023 ...Transaction tsx0x7f9eb8038c58 state changed to Terminated [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current inv state is CONNECTING [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Received response [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Response is 200 OK [Dec 22 16:51:26] DEBUG[5795] pjsip: inv0x7f9eb8023 ....Got SDP answer in Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb803f868) [Dec 22 16:51:26] DEBUG[5795] pjsip: inv0x7f9eb8023 ....SDP negotiation done, status=0 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '0.0.0.0' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '0.0.0.0' and port ''. [Dec 22 16:51:26] DEBUG[5795] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f9eb8015538' [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Setting payload 0 (0x7f9eb800ac18) based on m type on 0x7f9f1c152e90 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Setting payload 101 (0x7f9eb800ac18) based on m type on 0x7f9f1c152e90 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Copying payload 0 (0x7f9eb800bab8) from 0x7f9f1c152e90 to 0x7f9eb8015700 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Copying payload 101 (0x7f9eb800b628) from 0x7f9f1c152e90 to 0x7f9eb8015700 [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Role changed to Controlling [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 2: [1] 10.24.18.124:16540-->10.24.18.124:59105 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 2: [2] 10.24.18.124:16541-->10.24.18.124:35562 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 7: [1] 10.24.18.124:16540-->216.207.245.1:17501 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 8: [1] 10.24.18.124:16540-->216.207.245.1:17499 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 7: [1] 10.24.18.124:16540-->216.207.245.1:17498 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 6: [1] 10.24.18.124:16540-->216.207.245.1:17500 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 11: [2] 10.24.18.124:16541-->216.207.245.1:17502 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 11: [2] 10.24.18.124:16541-->216.207.245.1:17503 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 11: [2] 10.24.18.124:16541-->216.207.245.1:17504 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Check 10: [2] 10.24.18.124:16541-->216.207.245.1:35562 pruned (duplicate found) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Checklist created: [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 0: [1] 10.24.18.124:16540-->10.24.18.124:59105 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 1: [2] 10.24.18.124:16541-->10.24.18.124:35562 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 2: [1] 10.24.18.124:16540-->216.207.245.1:17501 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 3: [1] 10.24.18.124:16540-->216.207.245.1:17499 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 4: [1] 10.24.18.124:16540-->216.207.245.1:17498 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 5: [1] 10.24.18.124:16540-->216.207.245.1:17500 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 6: [2] 10.24.18.124:16541-->216.207.245.1:17502 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 7: [2] 10.24.18.124:16541-->216.207.245.1:17503 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 8: [2] 10.24.18.124:16541-->216.207.245.1:17504 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .... 9: [2] 10.24.18.124:16541-->216.207.245.1:35562 (not nominated, state=Frozen) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Starting ICE check.. [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .....Check 0: [1] 10.24.18.124:16540-->10.24.18.124:59105: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Checklist: state changed from Idle to Running [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ....Starting checklist periodic check [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 .....Sending connectivity check for check 0: [1] 10.24.18.124:16540-->10.24.18.124:59105 [Dec 22 16:51:26] DEBUG[5795] pjsip: stuse0x7f9eb80 .......TX 140 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=120, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) USE-CANDIDATE: length=0 ICE-CONTROLLING: length=8, data=3a63c91b0015d5fb SOFTWARE: length=12, value="pjnath-2.3.0" USERNAME: length=41, value="4972e4a5:3d66cc660fe1c384318649db2ab33644" MESSAGE-INTEGRITY: length=20, data=02af071b749291300a3043b2c0be2d9c118fa8d6 FINGERPRINT: length=4, value=2479616144 (0x93cbf090) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5795] pjsip: utsx0x7f9eb804 .......STUN client transaction created [Dec 22 16:51:26] DEBUG[5795] pjsip: utsx0x7f9eb804 .......STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5795] pjsip: icess0x7f9eb80 ......Check 0: [1] 10.24.18.124:16540-->10.24.18.124:59105: state changed from Waiting to In Progress [Dec 22 16:51:26] DEBUG[5843] app_queue.c: Device 'PJSIP/6001' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Dec 22 16:51:26] DEBUG[5847][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Dec 22 16:51:26] DEBUG[5847][C-00000000] channel.c: Prodding channel 'PJSIP/6001-00000000' [Dec 22 16:51:26] DEBUG[5847][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x7f9eb8017618' so dropping frame [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817086 (0x6e7f00fe) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=933e48aba12210acbc687195bd55b36943ca47f5 FINGERPRINT: length=4, value=715325818 (0x2aa3017a) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:35562 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=19444b0a67f2452005e9255d889f84aa0d30e639 FINGERPRINT: length=4, value=4213184241 (0xfb2016f1) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Performing triggered check for check 1 [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 ..Sending connectivity check for check 1: [2] 10.24.18.124:16541-->10.24.18.124:35562 [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ....TX 140 bytes STUN message to 10.24.18.124:35562: --- begin STUN message --- STUN Binding request Hdr: length=120, magic=2112a442, tsx_id=000016891f15c3d22652dac1 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) USE-CANDIDATE: length=0 ICE-CONTROLLING: length=8, data=3a63c91b0015d5fb SOFTWARE: length=12, value="pjnath-2.3.0" USERNAME: length=41, value="4972e4a5:3d66cc660fe1c384318649db2ab33644" MESSAGE-INTEGRITY: length=20, data=774724966805c4dbdb9f6d660fb32d258bcd8078 FINGERPRINT: length=4, value=399942649 (0x17d6a3f9) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 ....STUN client transaction created [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 ....STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 ...Check 1: [2] 10.24.18.124:16541-->10.24.18.124:35562: state changed from Frozen to In Progress [Dec 22 16:51:26] DEBUG[5795] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f9eb8015538' [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817086 (0x6e7f00fe) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=933e48aba12210acbc687195bd55b36943ca47f5 FINGERPRINT: length=4, value=715325818 (0x2aa3017a) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:35562 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=19444b0a67f2452005e9255d889f84aa0d30e639 FINGERPRINT: length=4, value=4213184241 (0xfb2016f1) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 1 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817086 (0x6e7f00fe) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=933e48aba12210acbc687195bd55b36943ca47f5 FINGERPRINT: length=4, value=715325818 (0x2aa3017a) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:35562 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=19444b0a67f2452005e9255d889f84aa0d30e639 FINGERPRINT: length=4, value=4213184241 (0xfb2016f1) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 1 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817086 (0x6e7f00fe) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=933e48aba12210acbc687195bd55b36943ca47f5 FINGERPRINT: length=4, value=715325818 (0x2aa3017a) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=335440bfde480faea8689d09 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:35562 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=19444b0a67f2452005e9255d889f84aa0d30e639 FINGERPRINT: length=4, value=4213184241 (0xfb2016f1) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 1 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016891f15c3d22652dac1 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16541 MESSAGE-INTEGRITY: length=20, data=428c3fe73ec690deb94203e9f88961b53901ff54 FINGERPRINT: length=4, value=3703277890 (0xdcbb8942) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 1: [2] 10.24.18.124:16541-->10.24.18.124:35562 (nominated): connectivity check SUCCESS [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 1: [2] 10.24.18.124:16541-->10.24.18.124:35562: state changed from In Progress to Succeeded [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 2: [1] 10.24.18.124:16540-->216.207.245.1:17501: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 3: [1] 10.24.18.124:16540-->216.207.245.1:17499: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 4: [1] 10.24.18.124:16540-->216.207.245.1:17498: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 5: [1] 10.24.18.124:16540-->216.207.245.1:17500: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 6: [2] 10.24.18.124:16541-->216.207.245.1:17502: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 7: [2] 10.24.18.124:16541-->216.207.245.1:17503: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 8: [2] 10.24.18.124:16541-->216.207.245.1:17504: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 9: [2] 10.24.18.124:16541-->216.207.245.1:35562: state changed from Frozen to Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 1 is successful and nominated [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 6: [2] 10.24.18.124:16541-->216.207.245.1:17502 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 6: [2] 10.24.18.124:16541-->216.207.245.1:17502: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 7: [2] 10.24.18.124:16541-->216.207.245.1:17503 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 7: [2] 10.24.18.124:16541-->216.207.245.1:17503: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 8: [2] 10.24.18.124:16541-->216.207.245.1:17504 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 8: [2] 10.24.18.124:16541-->216.207.245.1:17504: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 9: [2] 10.24.18.124:16541-->216.207.245.1:35562 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 9: [2] 10.24.18.124:16541-->216.207.245.1:35562: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stun_session.c .tdata 0x7f9f08008b18 destroy request, force=0, tsx=0x7f9f08008d00 [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9f0800 .STUN transaction 0x7f9f08008d00 schedule destroy [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016891f15c3d22652dac1 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16541 MESSAGE-INTEGRITY: length=20, data=428c3fe73ec690deb94203e9f88961b53901ff54 FINGERPRINT: length=4, value=3703277890 (0xdcbb8942) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016891f15c3d22652dac1 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16541 MESSAGE-INTEGRITY: length=20, data=428c3fe73ec690deb94203e9f88961b53901ff54 FINGERPRINT: length=4, value=3703277890 (0xdcbb8942) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817087 (0x6e7f00ff) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=0770e9116fa06caaef6d323521edc3ee11c25782 FINGERPRINT: length=4, value=1995685020 (0x76f3bc9c) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:59105 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=3b7c2947b99054b5b281f5b908c83ce2261cfa5d FINGERPRINT: length=4, value=977780996 (0x3a47c104) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817087 (0x6e7f00ff) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=0770e9116fa06caaef6d323521edc3ee11c25782 FINGERPRINT: length=4, value=1995685020 (0x76f3bc9c) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:59105 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=3b7c2947b99054b5b281f5b908c83ce2261cfa5d FINGERPRINT: length=4, value=977780996 (0x3a47c104) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817087 (0x6e7f00ff) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=0770e9116fa06caaef6d323521edc3ee11c25782 FINGERPRINT: length=4, value=1995685020 (0x76f3bc9c) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:59105 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=3b7c2947b99054b5b281f5b908c83ce2261cfa5d FINGERPRINT: length=4, value=977780996 (0x3a47c104) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:35562: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016891f15c3d22652dac1 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16541 MESSAGE-INTEGRITY: length=20, data=428c3fe73ec690deb94203e9f88961b53901ff54 FINGERPRINT: length=4, value=3703277890 (0xdcbb8942) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817087 (0x6e7f00ff) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=0770e9116fa06caaef6d323521edc3ee11c25782 FINGERPRINT: length=4, value=1995685020 (0x76f3bc9c) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:59105 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=3b7c2947b99054b5b281f5b908c83ce2261cfa5d FINGERPRINT: length=4, value=977780996 (0x3a47c104) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 120 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding request Hdr: length=100, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: USERNAME: length=41, value="3d66cc660fe1c384318649db2ab33644:4972e4a5" PRIORITY: length=4, value=1853817087 (0x6e7f00ff) ICE-CONTROLLED: length=8, data=5b93bb8a7c5f0e68 MESSAGE-INTEGRITY: length=20, data=0770e9116fa06caaef6d323521edc3ee11c25782 FINGERPRINT: length=4, value=1995685020 (0x76f3bc9c) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 ..TX 80 bytes STUN message to 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=ffe0ac01d235899c79b83956 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:59105 SOFTWARE: length=12, value="pjnath-2.3.0" MESSAGE-INTEGRITY: length=20, data=3b7c2947b99054b5b281f5b908c83ce2261cfa5d FINGERPRINT: length=4, value=977780996 (0x3a47c104) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 ..STUN sending message (transmit count=1) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 0: [1] 10.24.18.124:16540-->10.24.18.124:59105 (nominated): connectivity check SUCCESS [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 0: [1] 10.24.18.124:16540-->10.24.18.124:59105: state changed from In Progress to Succeeded [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 0 is successful and nominated [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 2: [1] 10.24.18.124:16540-->216.207.245.1:17501 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 2: [1] 10.24.18.124:16540-->216.207.245.1:17501: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 3: [1] 10.24.18.124:16540-->216.207.245.1:17499 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 3: [1] 10.24.18.124:16540-->216.207.245.1:17499: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 4: [1] 10.24.18.124:16540-->216.207.245.1:17498 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 4: [1] 10.24.18.124:16540-->216.207.245.1:17498: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 5: [1] 10.24.18.124:16540-->216.207.245.1:17500 to be failed because state is Waiting [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Check 5: [1] 10.24.18.124:16540-->216.207.245.1:17500: state changed from Waiting to Failed [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .ICE process complete, status=Success [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 .Valid list [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 . 0: [1] 10.24.18.124:16540-->10.24.18.124:59105 (nominated, state=Succeeded) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: icess0x7f9eb80 . 1: [2] 10.24.18.124:16541-->10.24.18.124:35562 (nominated, state=Succeeded) [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: stun_session.c .tdata 0x7f9eb8047768 destroy request, force=0, tsx=0x7f9eb8047950 [Dec 22 16:51:26] DEBUG[5847][C-00000000] pjsip: utsx0x7f9eb804 .STUN transaction 0x7f9eb8047950 schedule destroy [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Dec 22 16:51:26] DEBUG[5795] pjsip: inv0x7f9eb8023 ....Received Response msg 200/INVITE/cseq=32753 (rdata0x7f9eb803f868), sending ACK [Dec 22 16:51:26] DEBUG[5795] pjsip: endpoint ....Request msg ACK/cseq=32753 (tdta0x7f9eb8068470) created. [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8023 .....Sending Request msg ACK/cseq=32753 (tdta0x7f9eb8068470) [Dec 22 16:51:26] DEBUG[5795] pjsip: sip_resolve.c .....Target '10.24.18.124:45219' type=WS resolved to '10.24.18.124:45219' type=WS ((null)) [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.124:45219' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.124' and port '45219'. [Dec 22 16:51:26] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP request (393 bytes) to WS:10.24.18.124:45219 ---> ACK sip:101@10.24.18.124:45219;transport=ws SIP/2.0 Via: SIP/2.0/WS 10.24.18.124:45219;rport;branch=z9hG4bKPj364b8b54-7746-48be-bc64-6b91435bfcd3;alias From: "Alice" ;tag=a15f2f26-97a2-4c55-b54c-342d8e55dbf1 To: ;tag=QT2nyyreQK4IVlq9vr64 Call-ID: e0fa5983-33b8-490e-8b4d-ade62def3986 CSeq: 32753 ACK Content-Length: 0 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8038c58) [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current inv state is CONFIRMED [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Sending request [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Method is ACK [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8038c58 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current transaction state is Terminated [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current inv state is CONFIRMED [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Received response [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Response is 200 OK [Dec 22 16:51:26] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 101 [Dec 22 16:51:26] DEBUG[5786] devicestate.c: Changing state for PJSIP/101 - state 2 (In use) [Dec 22 16:51:26] DEBUG[5843] app_queue.c: Device 'PJSIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 22 16:51:26] DEBUG[5847][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 22 16:51:26] DEBUG[5786] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 22 16:51:26] DEBUG[5786] devicestate.c: Changing state for PJSIP/6001 - state 8 (On Hold) [Dec 22 16:51:26] DEBUG[5795] pjsip: inv0x7f9eb8018 .SDP negotiation done, status=0 [Dec 22 16:51:26] DEBUG[5774] threadpool.c: Increasing threadpool stasis-core's size by 1 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:51:26] DEBUG[5795] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f9eb8017618' [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Setting payload 0 (0x7f9eb8041b18) based on m type on 0x7f9f1c153080 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Setting payload 96 (0x7f9eb8041b18) based on m type on 0x7f9f1c153080 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Copying payload 0 (0x7f9eb8044a58) from 0x7f9f1c153080 to 0x7f9eb80177e0 [Dec 22 16:51:26] DEBUG[5795] rtp_engine.c: Copying payload 96 (0x7f9eb8043c38) from 0x7f9f1c153080 to 0x7f9eb80177e0 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Dec 22 16:51:26] DEBUG[5795] pjsip: inv0x7f9eb8018 .Sending Response msg 200/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8018 ..Sending Response msg 200/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) [Dec 22 16:51:26] DEBUG[5795] pjsip: tsx0x7f9eb8019 ..Sending Response msg 200/INVITE/cseq=13241 (tdta0x7f9eb800c2b0) in state Proceeding [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:51:26] DEBUG[5795] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:51:26] DEBUG[5795] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:51:26] VERBOSE[5795] res_pjsip_logger.c: <--- Transmitting SIP response (874 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjIYpWbY0UKA-gjgdzahq8rnz3fa4OE.dO Call-ID: 9ONKXo9HQ358iT6kVolMyBvEMQgo1gxb From: "Alice" ;tag=6kKJO6TIUcEcMbCnOmuu1Ip5ZJqFBH-r To: ;tag=f7964a4c-022b-4d8c-9bf6-3a641a7f3690 CSeq: 13241 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Contact: Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 232 v=0 o=- 114659970 114659972 IN IP4 10.24.18.124 s=Asterisk c=IN IP4 10.24.18.124 t=0 0 m=audio 12060 RTP/AVP 0 96 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 22 16:51:26] DEBUG[5795] pjsip: tsx0x7f9eb8019 ...State changed from Proceeding to Completed, event=TX_MSG [Dec 22 16:51:26] DEBUG[5795] pjsip: dlg0x7f9eb8018 ....Transaction tsx0x7f9eb8019298 state changed to Completed [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current inv state is CONNECTING [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f9eb8019298) [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The transaction involved in this state change is 0x7f9eb8019298 [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current transaction state is Completed [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: The current inv state is CONNECTING [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Sending response [Dec 22 16:51:26] DEBUG[5795] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Dec 22 16:51:26] DEBUG[5847][C-00000000] features.c: Removing dialed interfaces datastore on PJSIP/101-00000001 since we're bridging [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge_native_rtp.c: Bridge '3d7a0cda-b55a-454b-8feb-a294998124cc' can not use native RTP bridge as two channels are required [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Chose bridge technology simple_bridge [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: calling simple_bridge technology constructor [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: calling simple_bridge technology start [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge_channel.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: 0x7f9f08003408(PJSIP/101-00000001) is joining [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge_channel.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: 0x7f9f0801a298(PJSIP/6001-00000000) is joining [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge_channel.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: pushing 0x7f9f08003408(PJSIP/101-00000001) [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge_native_rtp.c: Bridge '3d7a0cda-b55a-454b-8feb-a294998124cc' can not use native RTP bridge as two channels are required [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Chose bridge technology simple_bridge [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is already using the new technology. [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is happy that channel PJSIP/101-00000001 already has read format ulaw [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is happy that channel PJSIP/101-00000001 already has write format ulaw [Dec 22 16:51:26] DEBUG[5857][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: 0x7f9f08003408(PJSIP/101-00000001) is joining simple_bridge technology [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge_channel.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: pushing 0x7f9f0801a298(PJSIP/6001-00000000) [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 22 16:51:26] DEBUG[5788] cdr.c: Finalized CDR for PJSIP/101-00000001 - start 1419288680.361404 answer 1419288686.430244 end 1419288686.431267 dispo ANSWERED [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge_native_rtp.c: Bridge '3d7a0cda-b55a-454b-8feb-a294998124cc' can not use native RTP bridge as it was forbidden while getting details [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Chose bridge technology simple_bridge [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is already using the new technology. [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is happy that channel PJSIP/6001-00000000 already has read format ulaw [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc is happy that channel PJSIP/6001-00000000 already has write format ulaw [Dec 22 16:51:26] DEBUG[5847][C-00000000] bridge.c: Bridge 3d7a0cda-b55a-454b-8feb-a294998124cc: 0x7f9f0801a298(PJSIP/6001-00000000) is joining simple_bridge technology [Dec 22 16:51:26] DEBUG[5857][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5857][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5857][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5857][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5857][C-00000000] pjsip: stuse0x7f9eb80 .RX 64 bytes STUN message from 10.24.18.124:59105: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000016894113b3eb2652dac0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16540 MESSAGE-INTEGRITY: length=20, data=d0e22b8dea67ca238b1234d7b5d383efdc98ea9f FINGERPRINT: length=4, value=3855583542 (0xe5cf8936) --- end of STUN message --- [Dec 22 16:51:26] DEBUG[5800] pjsip: tsx0x7f9eb8038 Timeout timer event [Dec 22 16:51:26] DEBUG[5800] pjsip: tsx0x7f9eb8038 .State changed from Terminated to Destroyed, event=TIMER [Dec 22 16:51:26] DEBUG[5800] pjsip: tsx0x7f9eb8038 Transaction destroyed! [Dec 22 16:51:26] DEBUG[5808] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5808] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:51:26] DEBUG[5808] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f9eb8015538' [Dec 22 16:51:26] DEBUG[5808] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:51:26] DEBUG[5808] netsock2.c: ...host '10.24.18.124' and port ''.