niklas-work*CLI> core set debug 9 Core debug was OFF and is now 9. <--- Received SIP request (943 bytes) from UDP:192.168.50.188:5060 ---> INVITE sip:0701992232@192.168.50.199 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.188:5060;branch=z9hG4bK-65562ed0 From: "6001" ;tag=6d735bd2ce755b31o0 To: Remote-Party-ID: "6001" ;screen=yes;party=calling Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 101 INVITE Max-Forwards: 70 Contact: "6001" Expires: 240 User-Agent: Cisco/SPA112-1.3.5(004p) Content-Length: 333 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 74332 74332 IN IP4 192.168.50.188 s=- c=IN IP4 192.168.50.188 t=0 0 m=audio 16434 RTP/AVP 0 8 2 18 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:18 G729a/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=101 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000029 to use for Request msg INVITE/cseq=101 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth 'auth6001'. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. <--- Transmitting SIP response (504 bytes) to UDP:192.168.50.188:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.50.188:5060;rport=5060;received=192.168.50.188;branch=z9hG4bK-65562ed0 Call-ID: fcd04d26-e522f9ed@192.168.50.188 From: "6001" ;tag=6d735bd2ce755b31o0 To: ;tag=z9hG4bK-65562ed0 CSeq: 101 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1505482619/98810f0955f2a49bcf02707e005c71c2",opaque="60ff07d6143b2726",algorithm=md5,qop="auth" Server: Asterisk PBX 13.17.0 Content-Length: 0 <--- Received SIP request (418 bytes) from UDP:192.168.50.188:5060 ---> ACK sip:0701992232@192.168.50.199 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.188:5060;branch=z9hG4bK-65562ed0 From: "6001" ;tag=6d735bd2ce755b31o0 To: ;tag=z9hG4bK-65562ed0 Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 101 ACK Max-Forwards: 70 Contact: "6001" User-Agent: Cisco/SPA112-1.3.5(004p) Content-Length: 0 [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg ACK/cseq=101 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000029 to use for Request msg ACK/cseq=101 (rdata0x7f74fc00a638) <--- Received SIP request (1210 bytes) from UDP:192.168.50.188:5060 ---> INVITE sip:0701992232@192.168.50.199 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.188:5060;branch=z9hG4bK-3546dc58 From: "6001" ;tag=6d735bd2ce755b31o0 To: Remote-Party-ID: "6001" ;screen=yes;party=calling Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="6001",realm="asterisk",nonce="1505482619/98810f0955f2a49bcf02707e005c71c2",uri="sip:0701992232@192.168.50.199",algorithm=MD5,response="59f4f5fbea4e722a1694a4dc35d38836",opaque="60ff07d6143b2726",qop=auth,nc=00000001,cnonce="cee1745a" Contact: "6001" Expires: 240 User-Agent: Cisco/SPA112-1.3.5(004p) Content-Length: 333 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 74332 74332 IN IP4 192.168.50.188 s=- c=IN IP4 192.168.50.188 t=0 0 m=audio 16434 RTP/AVP 0 8 2 18 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:18 G729a/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=102 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000029 to use for Request msg INVITE/cseq=102 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '6001' domain '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth 'auth6001'. [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_authenticator_digest.c:259 check_nonce: Calculated nonce 1505482619/98810f0955f2a49bcf02707e005c71c2. Actual nonce is 1505482619/98810f0955f2a49bcf02707e005c71c2 [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port ''. [Sep 15 15:36:59] DEBUG[23270]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000029 to use for Request msg INVITE/cseq=102 (rdata0x7f74fc015568) == Setting global variable 'SIPDOMAIN' to '192.168.50.199' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2532 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. <--- Transmitting SIP response (330 bytes) to UDP:192.168.50.188:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.50.188:5060;rport=5060;received=192.168.50.188;branch=z9hG4bK-3546dc58 Call-ID: fcd04d26-e522f9ed@192.168.50.188 From: "6001" ;tag=6d735bd2ce755b31o0 To: CSeq: 102 INVITE Server: Asterisk PBX 13.17.0 Content-Length: 0 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001()' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is INCOMING [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001()' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is INCOMING [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:269 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port ''. [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f74e000ff80' [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 15088 for RTP instance '0x7f74e000ff80' [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session [::]:15088 (15088) for RTP instance '0x7f74e000ff80' [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::cad3:a3ff:feac:9662' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::cad3:a3ff:feac:9662' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::cad3:a3ff:feac:9662' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::cad3:a3ff:feac:9662' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '2a02:760:1000:e:48ac:e5b7:5663:136d' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '2a02:760:1000:e:48ac:e5b7:5663:136d' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '2a02:760:1000:e:48ac:e5b7:5663:136d' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '2a02:760:1000:e:48ac:e5b7:5663:136d' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::3232:f9e9:c2eb:40ff' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::3232:f9e9:c2eb:40ff' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::3232:f9e9:c2eb:40ff' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::3232:f9e9:c2eb:40ff' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f74e000ff80' is setup and ready to go [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'niklas-work' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'niklas-work' and port ''. [Sep 15 15:36:59] DEBUG[23270]: acl.c:795 resolve_first: Multiple addresses. Using the first only [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f74e000ff80' [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:758 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 2 format for m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f75302fb3d0 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f74e002f2f8) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 2 (0x7f74e000df88) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f74e0010cd8) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f74e0029cf8) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f74e0011648) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f74e0006df8) from 0x7f75302fb3d0 to 0x7f74e0010148 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:279 handle_incoming_sdp: Media stream 'audio' handled by audio [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f74e000ff80' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_t38.c:745 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2468 handle_incoming_request: Method is INVITE [Sep 15 15:36:59] DEBUG[23270]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f74e000e5b0 'PJSIP/6001-0000000a' allocated [Sep 15 15:36:59] DEBUG[23270]: chan_pjsip.c:2550 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/6001-0000000a [Sep 15 15:36:59] DEBUG[23540][C-00000006]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [0701992232@internal:1] NoOp("PJSIP/6001-0000000a", "") in new stack [Sep 15 15:36:59] DEBUG[23540][C-00000006]: pbx.c:2875 pbx_extension_helper: Launching 'Dial' -- Executing [0701992232@internal:2] Dial("PJSIP/6001-0000000a", "PJSIP/6002") in new stack [Sep 15 15:36:59] DEBUG[23248]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Sep 15 15:36:59] DEBUG[23270]: config.c:3780 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Sep 15 15:36:59] DEBUG[23270]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 15 15:36:59] DEBUG[23270]: config.c:3780 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Sep 15 15:36:59] DEBUG[23270]: config.c:3742 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Sep 15 15:36:59] DEBUG[23270]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 86400] gives [0](0) [Sep 15 15:36:59] DEBUG[23540][C-00000006]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f7534004560 'PJSIP/6002-0000000b' allocated [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f74e00201f0' -- Called PJSIP/6002 [Sep 15 15:36:59] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6002-0000000b setting read format path: alaw -> alaw [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 10308 for RTP instance '0x7f74e00201f0' [Sep 15 15:36:59] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting read format path: ulaw -> ulaw [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session [::]:10308 (10308) for RTP instance '0x7f74e00201f0' [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::cad3:a3ff:feac:9662' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::cad3:a3ff:feac:9662' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::cad3:a3ff:feac:9662' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::cad3:a3ff:feac:9662' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '2a02:760:1000:e:48ac:e5b7:5663:136d' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '2a02:760:1000:e:48ac:e5b7:5663:136d' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '2a02:760:1000:e:48ac:e5b7:5663:136d' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '2a02:760:1000:e:48ac:e5b7:5663:136d' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::3232:f9e9:c2eb:40ff' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::3232:f9e9:c2eb:40ff' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::3232:f9e9:c2eb:40ff' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::3232:f9e9:c2eb:40ff' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.201' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.201' and port ''. [Sep 15 15:36:59] DEBUG[23270]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f74e00201f0' is setup and ready to go [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'niklas-work' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'niklas-work' and port ''. [Sep 15 15:36:59] DEBUG[23270]: acl.c:795 resolve_first: Multiple addresses. Using the first only [Sep 15 15:36:59] DEBUG[23270]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f74e00201f0' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_t38.c:745 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2517 handle_outgoing_request: Method is INVITE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote Contact URI host/port to 192.168.50.199:5060 [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. <--- Transmitting SIP request (932 bytes) to UDP:192.168.50.174:5060 ---> INVITE sip:6002@192.168.50.174:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.199:5060;rport;branch=z9hG4bKPj7f2dda23-fded-46bb-ac7a-b463ef30dcd1 From: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d To: Contact: Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 9334 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.17.0 Content-Type: application/sdp Content-Length: 265 v=0 o=- 1400923008 1400923008 IN IP4 192.168.50.199 s=Asterisk c=IN IP4 192.168.50.199 t=0 0 m=audio 10308 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CALLING [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Calling [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CALLING <--- Received SIP response (363 bytes) from UDP:192.168.50.174:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.50.199:5060;rport=5060;branch=z9hG4bKPj7f2dda23-fded-46bb-ac7a-b463ef30dcd1 From: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d To: Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 9334 INVITE User-Agent: Yealink SIP-T46S 66.81.0.110 Content-Length: 0 [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e002dd48 for Response msg 100/INVITE/cseq=9334 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/6002-0000005e associated with dialog dlg0x7f74e002dd48 <--- Received SIP response (590 bytes) from UDP:192.168.50.174:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.50.199:5060;rport=5060;branch=z9hG4bKPj7f2dda23-fded-46bb-ac7a-b463ef30dcd1 From: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d To: ;tag=4113811847 Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 9334 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T46S 66.81.0.110 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is RX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CALLING [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 100 Trying [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e002dd48 for Response msg 180/INVITE/cseq=9334 (rdata0x7f74fc00a638) [Sep 15 15:36:59] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/6002-0000005e associated with dialog dlg0x7f74e002dd48 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 180 Ringing [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is RX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 180 Ringing [Sep 15 15:36:59] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6002 [Sep 15 15:36:59] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6002 - state 6 (Ringing) [Sep 15 15:36:59] DEBUG[23321]: app_queue.c:2507 device_state_cb: Device 'PJSIP/6002' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- PJSIP/6002-0000000b is ringing [Sep 15 15:36:59] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6001 [Sep 15 15:36:59] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6001 - state 2 (In use) [Sep 15 15:36:59] DEBUG[23321]: app_queue.c:2507 device_state_cb: Device 'PJSIP/6001' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2532 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Sep 15 15:36:59] DEBUG[23270]: res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote Contact URI host/port to 192.168.50.199:5060 [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:36:59] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. <--- Transmitting SIP response (519 bytes) to UDP:192.168.50.188:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.50.188:5060;rport=5060;received=192.168.50.188;branch=z9hG4bK-3546dc58 Call-ID: fcd04d26-e522f9ed@192.168.50.188 From: "6001" ;tag=6d735bd2ce755b31o0 To: ;tag=a7ee6832-d87c-402c-a0b3-52d84241d6d4 CSeq: 102 INVITE Server: Asterisk PBX 13.17.0 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Content-Length: 0 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:36:59] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY <--- Received SIP response (833 bytes) from UDP:192.168.50.174:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.50.199:5060;rport=5060;branch=z9hG4bKPj7f2dda23-fded-46bb-ac7a-b463ef30dcd1 From: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d To: ;tag=4113811847 Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 9334 INVITE Contact: Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T46S 66.81.0.110 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 215 v=0 o=- 20384 20384 IN IP4 192.168.50.174 s=SDP data c=IN IP4 192.168.50.174 t=0 0 m=audio 12138 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:02] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e002dd48 for Response msg 200/INVITE/cseq=9334 (rdata0x7f74fc00a638) [Sep 15 15:37:02] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/6002-0000005e associated with dialog dlg0x7f74e002dd48 [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONNECTING [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 200 OK [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Sep 15 15:37:02] DEBUG[23270]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f74e00201f0' [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port ''. [Sep 15 15:37:02] DEBUG[23270]: acl.c:957 ast_ouraddrfor: For destination '192.168.50.174', our source address is '192.168.50.199'. [Sep 15 15:37:02] DEBUG[23270]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f74e00201f0' [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f75302facb0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f75302facb0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f74e00338d8) from 0x7f75302facb0 to 0x7f74e00203b8 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f74e004f048) from 0x7f75302facb0 to 0x7f74e00203b8 [Sep 15 15:37:02] DEBUG[23270]: channel.c:5711 set_format: Channel PJSIP/6002-0000000b setting read format path: ulaw -> alaw [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. <--- Transmitting SIP request (403 bytes) to UDP:192.168.50.174:5060 ---> ACK sip:6002@192.168.50.174:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.199:5060;rport;branch=z9hG4bKPjd375701e-4003-45cc-99b0-02c04e4c43fc From: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d To: ;tag=4113811847 Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 9334 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.17.0 Content-Length: 0 [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e000b298) [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONFIRMED [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Terminated [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is RX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONFIRMED [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 200 OK [Sep 15 15:37:02] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6002 [Sep 15 15:37:02] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6002 - state 2 (In use) -- PJSIP/6002-0000000b answered PJSIP/6001-0000000a [Sep 15 15:37:02] DEBUG[23321]: app_queue.c:2507 device_state_cb: Device 'PJSIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6002-0000000b setting read format path: ulaw -> ulaw [Sep 15 15:37:02] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting write format path: ulaw -> ulaw [Sep 15 15:37:02] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6001 [Sep 15 15:37:02] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6001 - state 2 (In use) [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Sep 15 15:37:02] DEBUG[23270]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f74e000ff80' [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port ''. [Sep 15 15:37:02] DEBUG[23270]: acl.c:957 ast_ouraddrfor: For destination '192.168.50.188', our source address is '192.168.50.199'. [Sep 15 15:37:02] DEBUG[23270]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f74e000ff80' [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:758 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 2 format for m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f75302faee0 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f74e003f068) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 2 (0x7f74e001d758) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f74e003f488) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f74e0026ca8) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f74e0027168) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f74e003c308) from 0x7f75302faee0 to 0x7f74e0010148 [Sep 15 15:37:02] DEBUG[23270]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting read format path: alaw -> ulaw [Sep 15 15:37:02] DEBUG[23270]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting write format path: ulaw -> alaw [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2532 handle_outgoing_response: Method is INVITE, Response is 200 OK [Sep 15 15:37:02] DEBUG[23270]: res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote Contact URI host/port to 192.168.50.199:5060 [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:37:02] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. <--- Transmitting SIP response (851 bytes) to UDP:192.168.50.188:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.50.188:5060;rport=5060;received=192.168.50.188;branch=z9hG4bK-3546dc58 Call-ID: fcd04d26-e522f9ed@192.168.50.188 From: "6001" ;tag=6d735bd2ce755b31o0 To: ;tag=a7ee6832-d87c-402c-a0b3-52d84241d6d4 CSeq: 102 INVITE Server: Asterisk PBX 13.17.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 255 v=0 o=- 74332 74334 IN IP4 192.168.50.199 s=Asterisk c=IN IP4 192.168.50.199 t=0 0 m=audio 15088 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONNECTING [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f74e0020a38) [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Completed [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONNECTING [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge 'd37fdb3d-1140-4fc2-8c8e-ac7926a71e82' can not use native RTP bridge as two channels are required [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:795 bridge_base_init: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: calling simple_bridge technology constructor [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:803 bridge_base_init: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: calling simple_bridge technology start [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f753400c370(PJSIP/6002-0000000b) is joining [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: pushing 0x7f753400c370(PJSIP/6002-0000000b) -- Channel PJSIP/6002-0000000b joined 'simple_bridge' basic-bridge [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge 'd37fdb3d-1140-4fc2-8c8e-ac7926a71e82' can not use native RTP bridge as two channels are required [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:1047 smart_bridge_operation: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82 is already using the new technology. [Sep 15 15:37:02] DEBUG[23542][C-00000006]: bridge.c:432 bridge_channel_complete_join: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f753400c370(PJSIP/6002-0000000b) is joining simple_bridge technology [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f7534003370(PJSIP/6001-0000000a) is joining [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: pushing 0x7f7534003370(PJSIP/6001-0000000a) -- Channel PJSIP/6001-0000000a joined 'simple_bridge' basic-bridge [Sep 15 15:37:02] DEBUG[23260]: cdr.c:1293 cdr_object_finalize: Finalized CDR for PJSIP/6002-0000000b - start 1505482619.701061 answer 1505482622.277610 end 1505482622.279025 dispo ANSWERED [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge_native_rtp.c:617 native_rtp_bridge_compatible_check: Bridge 'd37fdb3d-1140-4fc2-8c8e-ac7926a71e82'. Checking compatability for channels 'PJSIP/6002-0000000b' and 'PJSIP/6001-0000000a' [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge_native_rtp.c:695 native_rtp_bridge_compatible_check: Bridge 'd37fdb3d-1140-4fc2-8c8e-ac7926a71e82': Channel codec0 = (ulaw) is not codec1 = (alaw), cannot native bridge in RTP. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:1047 smart_bridge_operation: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82 is already using the new technology. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: bridge.c:432 bridge_channel_complete_join: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f7534003370(PJSIP/6001-0000000a) is joining simple_bridge technology [Sep 15 15:37:02] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting read format path: alaw -> alaw [Sep 15 15:37:02] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6002-0000000b setting write format path: alaw -> ulaw [Sep 15 15:37:02] DEBUG[23542][C-00000006]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7f74e0039000 -- Probation learning mode pass with source address 192.168.50.174:12138 [Sep 15 15:37:02] DEBUG[23540][C-00000006]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7f74e002ace0 -- Probation learning mode pass with source address 192.168.50.188:16434 > 0x7f74e0039000 -- Probation passed - setting RTP source address to 192.168.50.174:12138 > 0x7f74e002ace0 -- Probation passed - setting RTP source address to 192.168.50.188:16434 [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: res_rtp_asterisk.c:4017 ast_rtp_write: Ooh, format changed from none to alaw [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated <--- Received SIP request (699 bytes) from UDP:192.168.50.188:5060 ---> ACK sip:192.168.50.199:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.188:5060;branch=z9hG4bK-a8896580 From: "6001" ;tag=6d735bd2ce755b31o0 To: ;tag=a7ee6832-d87c-402c-a0b3-52d84241d6d4 Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="6001",realm="asterisk",nonce="1505482619/98810f0955f2a49bcf02707e005c71c2",uri="sip:0701992232@192.168.50.199",algorithm=MD5,response="59f4f5fbea4e722a1694a4dc35d38836",opaque="60ff07d6143b2726",qop=auth,nc=00000001,cnonce="cee1745a" Contact: "6001" User-Agent: Cisco/SPA112-1.3.5(004p) Content-Length: 0 [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:02] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e0008f78 for Request msg ACK/cseq=102 (rdata0x7f74fc00a638) [Sep 15 15:37:02] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/distributor-00000029 associated with dialog dlg0x7f74e0008f78 [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Terminated [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is USER [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONNECTING [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONFIRMED [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received request [Sep 15 15:37:02] DEBUG[23270]: res_pjsip_session.c:2468 handle_incoming_request: Method is ACK [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:02] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:03] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23542][C-00000006]: res_rtp_asterisk.c:4560 ast_rtcp_interpret: Got RTCP report of 60 bytes [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:12139' into... [Sep 15 15:37:04] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '12139'. [Sep 15 15:37:04] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:10309' into... [Sep 15 15:37:04] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '10309'. [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:04] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated <--- Received SIP request (418 bytes) from UDP:192.168.50.174:5060 ---> BYE sip:asterisk@192.168.50.199:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.174:5060;branch=z9hG4bK2869217449 From: ;tag=4113811847 To: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 CSeq: 2 BYE Contact: Max-Forwards: 70 User-Agent: Yealink SIP-T46S 66.81.0.110 Content-Length: 0 [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e002dd48 for Request msg BYE/cseq=2 (rdata0x7f74fc00a638) [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:732 chan_pjsip_read: Oooh, got a frame with format of ulaw on channel 'PJSIP/6001-0000000a' when it has not been negotiated [Sep 15 15:37:05] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/6002-0000005e associated with dialog dlg0x7f74e002dd48 [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:5060' into... [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '5060'. <--- Transmitting SIP response (353 bytes) to UDP:192.168.50.174:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.50.174:5060;rport=5060;received=192.168.50.174;branch=z9hG4bK2869217449 Call-ID: 775bf3ac-efae-4ec2-b04d-2254c0fac470 From: ;tag=4113811847 To: "6001" ;tag=65439192-3bc8-4339-8a63-5d6acda55c6d CSeq: 2 BYE Server: Asterisk PBX 13.17.0 Content-Length: 0 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Completed [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONFIRMED [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is DISCONNCTD [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received request [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2468 handle_incoming_request: Method is BYE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6002(PJSIP/6002-0000000b)' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7f74e0020a38 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Completed [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is RX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is DISCONNCTD [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f753400c370(PJSIP/6002-0000000b) state from:0 to:1 [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: pulling 0x7f753400c370(PJSIP/6002-0000000b) -- Channel PJSIP/6002-0000000b left 'simple_bridge' basic-bridge [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f753400c370(PJSIP/6002-0000000b) is leaving simple_bridge technology [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge.c:322 bridge_dissolve: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: dissolving bridge with cause 16(Normal Clearing) [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f7534003370(PJSIP/6001-0000000a) state from:0 to:2 [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge.c:283 bridge_queue_action_nodup: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: queueing action type:13 sub:1001 [Sep 15 15:37:05] DEBUG[23260]: cdr.c:1293 cdr_object_finalize: Finalized CDR for PJSIP/6001-0000000a - start 1505482619.700238 answer 1505482622.278032 end 1505482625.794455 dispo ANSWERED [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge.c:1004 smart_bridge_operation: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82 is dissolved, not performing smart bridge operation. [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: pulling 0x7f7534003370(PJSIP/6001-0000000a) -- Channel PJSIP/6001-0000000a left 'simple_bridge' basic-bridge [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: 0x7f7534003370(PJSIP/6001-0000000a) is leaving simple_bridge technology [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge.c:1004 smart_bridge_operation: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82 is dissolved, not performing smart bridge operation. [Sep 15 15:37:05] DEBUG[23542][C-00000006]: bridge_channel.c:347 ast_bridge_channel_restore_formats: Bridge is returning 0x7f753400c370(PJSIP/6002-0000000b) to write format ulaw [Sep 15 15:37:05] DEBUG[23542][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6002-0000000b setting write format path: ulaw -> ulaw [Sep 15 15:37:05] DEBUG[23542][C-00000006]: channel.c:2681 ast_hangup: Channel 0x7f7534004560 'PJSIP/6002-0000000b' hanging up. Refs: 2 [Sep 15 15:37:05] DEBUG[23542][C-00000006]: chan_pjsip.c:1991 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP) [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge_channel.c:337 ast_bridge_channel_restore_formats: Bridge is returning 0x7f7534003370(PJSIP/6001-0000000a) to read format ulaw [Sep 15 15:37:05] DEBUG[23540][C-00000006]: channel.c:5711 set_format: Channel PJSIP/6001-0000000a setting read format path: alaw -> ulaw [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge.c:649 destroy_bridge: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: actually destroying basic bridge, nobody wants it anymore [Sep 15 15:37:05] DEBUG[23542][C-00000006]: channel.c:2233 ast_channel_destructor: Channel 0x7f7534004560 'PJSIP/6002-0000000b' destroying [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge.c:674 destroy_bridge: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: calling basic bridge destructor [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge.c:680 destroy_bridge: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: calling simple_bridge technology stop [Sep 15 15:37:05] DEBUG[23540][C-00000006]: bridge.c:687 destroy_bridge: Bridge d37fdb3d-1140-4fc2-8c8e-ac7926a71e82: calling simple_bridge technology destructor [Sep 15 15:37:05] DEBUG[23260]: cdr.c:1121 cdr_object_create_public_records: CDR for PJSIP/6002-0000000b is dialed and has no Party B; discarding [Sep 15 15:37:05] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6002 [Sep 15 15:37:05] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6002 - state 1 (Not in use) [Sep 15 15:37:05] DEBUG[23321]: app_queue.c:2507 device_state_cb: Device 'PJSIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 15 15:37:05] DEBUG[23540][C-00000006]: app_dial.c:3233 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 15 15:37:05] DEBUG[23540][C-00000006]: pbx.c:4347 __ast_pbx_run: Spawn extension (internal,0701992232,2) exited non-zero on 'PJSIP/6001-0000000a' == Spawn extension (internal, 0701992232, 2) exited non-zero on 'PJSIP/6001-0000000a' [Sep 15 15:37:05] DEBUG[23540][C-00000006]: channel.c:2590 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/6001-0000000a' [Sep 15 15:37:05] DEBUG[23540][C-00000006]: channel.c:2681 ast_hangup: Channel 0x7f74e000e5b0 'PJSIP/6001-0000000a' hanging up. Refs: 2 [Sep 15 15:37:05] DEBUG[23540][C-00000006]: chan_pjsip.c:1991 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP) [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2517 handle_outgoing_request: Method is BYE [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:37:05] DEBUG[23270]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. <--- Transmitting SIP request (447 bytes) to UDP:192.168.50.188:5060 ---> BYE sip:6001@192.168.50.188:5060;ref=6001 SIP/2.0 Via: SIP/2.0/UDP 192.168.50.199:5060;rport;branch=z9hG4bKPj3d5605f4-a9e4-41f6-9948-bb409393caf1 From: ;tag=a7ee6832-d87c-402c-a0b3-52d84241d6d4 To: "6001" ;tag=6d735bd2ce755b31o0 Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 24281 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: Asterisk PBX 13.17.0 Content-Length: 0 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001(PJSIP/6001-0000000a)' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Calling [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is CONFIRMED [Sep 15 15:37:05] DEBUG[23540][C-00000006]: channel.c:2233 ast_channel_destructor: Channel 0x7f74e000e5b0 'PJSIP/6001-0000000a' destroying [Sep 15 15:37:05] DEBUG[23259]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6001 [Sep 15 15:37:05] DEBUG[23259]: devicestate.c:474 do_state_change: Changing state for PJSIP/6001 - state 1 (Not in use) [Sep 15 15:37:05] DEBUG[23321]: app_queue.c:2507 device_state_cb: Device 'PJSIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- Received SIP response (446 bytes) from UDP:192.168.50.188:5060 ---> SIP/2.0 200 OK To: "6001" ;tag=6d735bd2ce755b31o0 From: ;tag=a7ee6832-d87c-402c-a0b3-52d84241d6d4 Call-ID: fcd04d26-e522f9ed@192.168.50.188 CSeq: 24281 BYE Via: SIP/2.0/UDP 192.168.50.199:5060;branch=z9hG4bKPj3d5605f4-a9e4-41f6-9948-bb409393caf1 Server: Cisco/SPA112-1.3.5(004p) P-RTP-Stat: PS=266,OS=50000,PR=166,OR=26560,PL=0,JI=2,LA=0,DU=3,EN=G711u,DE=G711a Content-Length: 0 [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:5060' into... [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '5060'. [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:5060' into... [Sep 15 15:37:05] DEBUG[23269]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '5060'. [Sep 15 15:37:05] DEBUG[23269]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7f74e0008f78 for Response msg 200/BYE/cseq=24281 (rdata0x7f74fc00a638) [Sep 15 15:37:05] DEBUG[23269]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/distributor-00000029 associated with dialog dlg0x7f74e0008f78 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001()' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is DISCONNCTD [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 200 OK [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '6001()' [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2444 __print_debug_details: The inv session does NOT have an invite_tsx [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2447 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7f74e000b298 [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Completed [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is RX_MSG [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is DISCONNCTD [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2501 handle_incoming: Received response [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2485 handle_incoming_response: Response is 200 OK [Sep 15 15:37:05] DEBUG[23270]: res_pjsip_session.c:2806 session_inv_on_tsx_state_changed: BYE received final response code 200 [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:10309' into... [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '10309'. [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.174:12139' into... [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.174' and port '12139'. [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.199:15089' into... [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.199' and port '15089'. [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.50.188:16435' into... [Sep 15 15:37:07] DEBUG[23312]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.50.188' and port '16435'. niklas-work*CLI> core set debug 0 Core debug was 9 and is now OFF. niklas-work*CLI> exit Asterisk cleanly ending (0). Executing last minute cleanups