<--- Received SIP request (2484 bytes) from UDP:185.61.68.82:5060 ---> INVITE sip:+3140xxxxxxx@ims.imscore.net:5060;user=phone;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP 185.61.68.82;branch=z9hG4bK21d9.01940f2f8e0b575e4bd098c12fc78df0.0 Via: SIP/2.0/UDP 145.54.65.148:5060;rport=5060;branch=z9hG4bK+d11850aca9f1d680dd1fd0fdd9efab2f2+85347b59da9a545ad919839e4336440c+1000002;oai=yyyyEvC4yxqvckxyIyO7wq9-v2 Via: SIP/2.0/UDP KevrinegylYefdr0VeYhvGqHVbUQHsGSD5QM6yfW.KFABd1SJ.l.cWOt4vdpnzSDMVwHxOqJJuWP8VARtU-dCRj.EmOJvl.cUn37GxbpQjtzeGlAwvf58h6gXULG0G6JSYZMypT8l.cO4Vbodl3VYZEHSHWcUD6KWJlqYdBNSDvQUDhCGJMl.cKat.ell;tokenized-by=atlanta.com;branch=z9hG4bK-8 Via: SIP/2.0/UDP Kevrinegyf0gh7tUXg0bxAsBXdWSBmAM69SO.1hQZBHCD0Y4Vpl.cDlnsCfhBFKhkJbp.93f22nXUXp2jeMzrAdB.aY6Jl.c4SD25MTFoWN0K7dCk0HTGUh8KjTWUIFsGnVv3ENZl.cCiH9Kat.ell;tokenized-by=atlanta.com;branch=z9hG4bK-8 From: ;tag=127.0.0.1alUtKGp-05897+1+ad0f0700+5e4fb3fc To: CSeq: 989550440 INVITE Expires: 90 Content-Length: 449 Call-ID: 0DBAA7573AC0-1FBC021DGgUOvdGrRUZKXLtYsogkeNG1szvP1KL7q5jlJpc0KCY7N4tGSYqxmwYewTtX3EsT0A Contact: Content-Type: application/sdp Record-Route: Record-Route: Max-Forwards: 66 Min-SE: 90 Session-Expires: 1800 Supported: replaces, path, 100rel, timer Privacy: none Allow: INVITE, BYE, ACK, OPTIONS, CANCEL, PRACK, UPDATE User-Agent: Alcatel-Lucent 5060 MGC-8 9.2.0.7.0.5 P-Asserted-Identity: v=0 o=- 3703308829 3703308829 IN IP4 185.61.68.93 s=- c=IN IP4 185.61.68.93 t=0 0 m=audio 30668 RTP/AVP 8 18 108 111 101 a=ptime:20 a=maxptime:30 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:108 AMR/8000 a=fmtp:108 mode-change-capability=2 a=rtpmap:111 AMR-WB/16000 a=fmtp:111 mode-change-capability=2 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=fmtp:18 annexb=no a=silenceSupp:off - - - - a=sendrecv a=rtcp:30669 [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.82:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.82' and port '5060'. [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=989550440 (rdata0x7f1a9c0009e8) [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003c to use for Request msg INVITE/cseq=989550440 (rdata0x7f1a9c0009e8) [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.82' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.82' and port ''. [May 9 10:53:49] DEBUG[5515]: res_pjsip_endpoint_identifier_ip.c:128 ip_identify_match_check: Source address 185.61.68.82:5060 does not match identify 'sipx-glsw-sbc1' [May 9 10:53:49] DEBUG[5515]: res_pjsip_endpoint_identifier_ip.c:128 ip_identify_match_check: Source address 185.61.68.82:5060 does not match identify 'sipx-glsw-sbc0' [May 9 10:53:49] DEBUG[5515]: res_pjsip_endpoint_identifier_ip.c:123 ip_identify_match_check: Source address 185.61.68.82:5060 matches identify 'sipx-efx-sbc0' [May 9 10:53:49] DEBUG[5515]: res_pjsip_endpoint_identifier_ip.c:158 ip_identify: Retrieved endpoint sipx-efx-sbc0 [May 9 10:53:49] DEBUG[5515]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003c to use for Request msg INVITE/cseq=989550440 (rdata0x7f1a9c028ed8) == Setting global variable 'SIPDOMAIN' to 'ims.imscore.net' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:269 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.93' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.93' and port ''. [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f1aac023e10' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 14790 for RTP instance '0x7f1aac023e10' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session [::]:14790 (14790) for RTP instance '0x7f1aac023e10' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f1aac023e10' is setup and ready to go [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'sipx-pocs1' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'sipx-pocs1' and port ''. [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f1aac023e10' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f1a53701390 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f1a53701390 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 108 based on m type on 0x7f1a53701390 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 111 based on m type on 0x7f1a53701390 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f1a53701390 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f1aac07e468) from 0x7f1a53701390 to 0x7f1aac023fd8 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f1aac091888) from 0x7f1a53701390 to 0x7f1aac023fd8 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f1aac070118) from 0x7f1a53701390 to 0x7f1aac023fd8 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 108 (0x7f1aac0701d8) from 0x7f1a53701390 to 0x7f1aac023fd8 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 111 (0x7f1aac00bc18) from 0x7f1a53701390 to 0x7f1aac023fd8 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:279 handle_incoming_sdp: Media stream 'audio' handled by audio [May 9 10:53:49] DEBUG[5515]: res_pjsip_t38.c:739 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2502 handle_outgoing_response: Method is INVITE, Response is 100 Trying [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.82:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.82' and port '5060'. <--- Transmitting SIP response (1589 bytes) to UDP:185.61.68.82:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 185.61.68.82;rport=5060;received=185.61.68.82;branch=z9hG4bK21d9.01940f2f8e0b575e4bd098c12fc78df0.0 Via: SIP/2.0/UDP 145.54.65.148:5060;rport=5060;branch=z9hG4bK+d11850aca9f1d680dd1fd0fdd9efab2f2+85347b59da9a545ad919839e4336440c+1000002;oai=yyyyEvC4yxqvckxyIyO7wq9-v2 Via: SIP/2.0/UDP KevrinegylYefdr0VeYhvGqHVbUQHsGSD5QM6yfW.KFABd1SJ.l.cWOt4vdpnzSDMVwHxOqJJuWP8VARtU-dCRj.EmOJvl.cUn37GxbpQjtzeGlAwvf58h6gXULG0G6JSYZMypT8l.cO4Vbodl3VYZEHSHWcUD6KWJlqYdBNSDvQUDhCGJMl.cKat.ell;branch=z9hG4bK-8;tokenized-by=atlanta.com Via: SIP/2.0/UDP Kevrinegyf0gh7tUXg0bxAsBXdWSBmAM69SO.1hQZBHCD0Y4Vpl.cDlnsCfhBFKhkJbp.93f22nXUXp2jeMzrAdB.aY6Jl.c4SD25MTFoWN0K7dCk0HTGUh8KjTWUIFsGnVv3ENZl.cCiH9Kat.ell;branch=z9hG4bK-8;tokenized-by=atlanta.com Record-Route: Record-Route: Record-Route: Call-ID: 0DBAA7573AC0-1FBC021DGgUOvdGrRUZKXLtYsogkeNG1szvP1KL7q5jlJpc0KCY7N4tGSYqxmwYewTtX3EsT0A From: ;tag=127.0.0.1alUtKGp-05897+1+ad0f0700+5e4fb3fc To: CSeq: 989550440 INVITE Server: Asterisk PBX 13.14.1~dfsg-1 Content-Length: 0 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'sipx-efx-sbc0()' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab007cd78) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2426 __print_debug_details: There is no transaction involved in this state change [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is INCOMING [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2603 session_inv_on_state_changed: Source of transaction state change is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'sipx-efx-sbc0()' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab007cd78) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2417 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f1ab007cd78 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2421 __print_debug_details: The current transaction state is Proceeding [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2423 __print_debug_details: The transaction state change event is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is INCOMING [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2438 handle_incoming_request: Method is INVITE [May 9 10:53:49] DEBUG[15315]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [May 9 10:53:49] DEBUG[5515]: chan_pjsip.c:2480 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/sipx-efx-sbc0-0000009a [May 9 10:53:49] DEBUG[15739]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [May 9 10:53:49] DEBUG[15739]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [May 9 10:53:49] DEBUG[15739]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [May 9 10:53:49] DEBUG[15739]: res_pjsip.c:3562 endpt_send_request: 0x7f1ab0065780: Wrapper created [May 9 10:53:49] DEBUG[15739]: res_pjsip.c:3582 endpt_send_request: 0x7f1ab0065780: Set timer to 3000 msec [May 9 10:53:49] DEBUG[15739]: res_pjsip/pjsip_message_ip_updater.c:215 multihomed_on_tx_message: Re-wrote Contact URI host/port to 185.61.68.110:5060 [May 9 10:53:49] DEBUG[15739]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[15739]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[15739]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.92:5060' into... [May 9 10:53:49] DEBUG[15739]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.92' and port '5060'. <--- Transmitting SIP request (429 bytes) to UDP:185.61.68.92:5060 ---> OPTIONS sip:185.61.68.92 SIP/2.0 Via: SIP/2.0/UDP 185.61.68.110:5060;rport;branch=z9hG4bKPj98951043-0ba7-425d-aca5-151c1e3ce683 From: ;tag=76a92e94-5fad-447b-9572-b71740f97472 To: Contact: Call-ID: 385d2b01-9e60-4981-b756-161c209e5d3b CSeq: 17780 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.14.1~dfsg-1 Content-Length: 0 <--- Received SIP response (426 bytes) from UDP:185.61.68.92:5060 ---> SIP/2.0 200 Keepalive Via: SIP/2.0/UDP 185.61.68.110:5060;rport=5060;branch=z9hG4bKPj98951043-0ba7-425d-aca5-151c1e3ce683;received=185.61.68.110 From: ;tag=76a92e94-5fad-447b-9572-b71740f97472 To: ;tag=260181bfa95c18e3d8cc8decc2d3aff2.44fe Call-ID: 385d2b01-9e60-4981-b756-161c209e5d3b CSeq: 17780 OPTIONS Server: kamailio (4.4.5 (x86_64/linux)) Content-Length: 0 [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.92:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.92' and port '5060'. [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=17780 (rdata0x7f1a9c0009e8). Using request transaction as basis [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000010 on transaction tsx0x7f1aa40092d8 [May 9 10:53:49] DEBUG[5515]: res_pjsip.c:3440 endpt_send_request_cb: 0x7f1ab0065780: PJSIP tsx response received [May 9 10:53:49] DEBUG[5515]: res_pjsip.c:3453 endpt_send_request_cb: 0x7f1ab0065780: Cancelling timer [May 9 10:53:49] DEBUG[5515]: res_pjsip.c:3462 endpt_send_request_cb: 0x7f1ab0065780: Timer cancelled [May 9 10:53:49] DEBUG[5515]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [May 9 10:53:49] DEBUG[5515]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [May 9 10:53:49] DEBUG[5515]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [May 9 10:53:49] DEBUG[15746]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact sipx-glsw-sbc1/sip:185.61.68.92 status didn't change: Reachable, RTT: 4.014 msec [May 9 10:53:49] DEBUG[5515]: res_pjsip.c:3483 endpt_send_request_cb: 0x7f1ab0065780: Callbacks executed [May 9 10:53:49] DEBUG[5515]: res_pjsip.c:3539 send_request_wrapper_destructor: 0x7f1ab0065780: wrapper destroyed [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [+3140xxxxxxx@kpnincoming:1] NoOp("PJSIP/sipx-efx-sbc0-0000009a", "") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [+3140xxxxxxx@kpnincoming:2] Set("PJSIP/sipx-efx-sbc0-0000009a", "loopcount=0") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: func_rand.c:85 acf_rand_exec: 0 was the lucky number in range [0,1] [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function RAND(0,1) result is '0' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [+3140xxxxxxx@kpnincoming:3] Set("PJSIP/sipx-efx-sbc0-0000009a", "rand=0") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'loopcount' is '0' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [+3140xxxxxxx@kpnincoming:4] Set("PJSIP/sipx-efx-sbc0-0000009a", "loopcount=1") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'rand' is '0' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [+3140xxxxxxx@kpnincoming:5] Set("PJSIP/sipx-efx-sbc0-0000009a", "rand=1") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'rand' is '1' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [+3140xxxxxxx@kpnincoming:6] Set("PJSIP/sipx-efx-sbc0-0000009a", "mod=1") in new stack [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'mod' is '1' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Goto' -- Executing [+3140xxxxxxx@kpnincoming:7] Goto("PJSIP/sipx-efx-sbc0-0000009a", "dial1") in new stack -- Goto (kpnincoming,+3140xxxxxxx,10) [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '+3140xxxxxxx' [May 9 10:53:49] DEBUG[8480][C-0000003b]: pbx.c:2875 pbx_extension_helper: Launching 'Dial' -- Executing [+3140xxxxxxx@kpnincoming:10] Dial("PJSIP/sipx-efx-sbc0-0000009a", "PJSIP/+3140xxxxxxx@turnoutpocosnl") in new stack -- Called PJSIP/+3140xxxxxxx@turnoutpocosnl [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/turnoutpocosnl-0000009b setting read format path: amrwb -> amrwb [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/sipx-efx-sbc0-0000009a setting write format path: amrwb -> amrwb [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/sipx-efx-sbc0-0000009a setting read format path: amrwb -> amrwb [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/turnoutpocosnl-0000009b setting write format path: amrwb -> amrwb [May 9 10:53:49] DEBUG[15315]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f1aac0396a0' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 12524 for RTP instance '0x7f1aac0396a0' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session [::]:12524 (12524) for RTP instance '0x7f1aac0396a0' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f1aac0396a0' is setup and ready to go [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'sipx-pocs1' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'sipx-pocs1' and port ''. [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f1aac0396a0' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: res_pjsip_t38.c:739 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2487 handle_outgoing_request: Method is INVITE [May 9 10:53:49] DEBUG[5515]: res_pjsip/pjsip_message_ip_updater.c:215 multihomed_on_tx_message: Re-wrote Contact URI host/port to 185.61.68.110:5060 [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '109.235.32.47:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '109.235.32.47' and port '5060'. <--- Transmitting SIP request (1215 bytes) to UDP:109.235.32.47:5060 ---> INVITE sip:+3140xxxxxxx@109.235.32.47;user=phone SIP/2.0 Via: SIP/2.0/UDP 185.61.68.110:5060;rport;branch=z9hG4bKPja454c729-c772-4687-9c08-814da7191856 From: ;tag=3cc70504-9616-4452-bf2d-67fa97785d13 To: Contact: Call-ID: 8447a92b-d17e-4416-93df-5dc412bc9121 CSeq: 29284 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 900 Min-SE: 90 P-Asserted-Identity: Max-Forwards: 70 User-Agent: Asterisk PBX 13.14.1~dfsg-1 Content-Type: application/sdp Content-Length: 436 v=0 o=pocs 699633478 699633478 IN IP4 185.61.68.110 s=Asterisk c=IN IP4 185.61.68.110 t=0 0 m=audio 12524 RTP/AVP 8 9 109 108 18 111 101 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:109 AMR-WB/16000 a=fmtp:109 mode-change-capability=2 a=rtpmap:108 AMR/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009b)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00a1b88) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2426 __print_debug_details: There is no transaction involved in this state change [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is CALLING [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2603 session_inv_on_state_changed: Source of transaction state change is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009b)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00a1b88) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2417 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f1ab00a1b88 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2421 __print_debug_details: The current transaction state is Calling [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2423 __print_debug_details: The transaction state change event is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is CALLING <--- Received SIP response (469 bytes) from UDP:109.235.32.47:5060 ---> SIP/2.0 302 Redirect Via: SIP/2.0/UDP 185.61.68.110:5060;rport=5060;branch=z9hG4bKPja454c729-c772-4687-9c08-814da7191856;received=185.61.68.110 From: ;tag=3cc70504-9616-4452-bf2d-67fa97785d13 To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.9c01 Call-ID: 8447a92b-d17e-4416-93df-5dc412bc9121 CSeq: 29284 INVITE Contact: Content-Length: 0 [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '109.235.32.47:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '109.235.32.47' and port '5060'. [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x55f097784fe8 for Response msg 302/INVITE/cseq=29284 (rdata0x7f1a9c0009e8) [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/outsess/turnoutpocosnl-000000cc on dialog dlg0x55f097784fe8 [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '109.235.32.47:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '109.235.32.47' and port '5060'. <--- Transmitting SIP request (479 bytes) to UDP:109.235.32.47:5060 ---> ACK sip:+3140xxxxxxx@109.235.32.47;user=phone SIP/2.0 Via: SIP/2.0/UDP 185.61.68.110:5060;rport;branch=z9hG4bKPja454c729-c772-4687-9c08-814da7191856 From: ;tag=3cc70504-9616-4452-bf2d-67fa97785d13 To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.9c01 Call-ID: 8447a92b-d17e-4416-93df-5dc412bc9121 CSeq: 29284 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.14.1~dfsg-1 Content-Length: 0 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2471 handle_incoming: Received response [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2455 handle_incoming_response: Response is 302 Redirect [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009b)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00a1b88) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2426 __print_debug_details: There is no transaction involved in this state change [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is DISCONNCTD [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2603 session_inv_on_state_changed: Source of transaction state change is RX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2471 handle_incoming: Received response [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2455 handle_incoming_response: Response is 302 Redirect [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009b)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00a1b88) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2417 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f1ab00a1b88 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2421 __print_debug_details: The current transaction state is Completed [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2423 __print_debug_details: The transaction state change event is RX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is DISCONNCTD [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2471 handle_incoming: Received response [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2455 handle_incoming_response: Response is 302 Redirect -- Now forwarding PJSIP/sipx-efx-sbc0-0000009a to 'PJSIP/turnoutpocosnl/sip:+3140xxxxxxx@sip.itco.nl;user=phone' (thanks to PJSIP/turnoutpocosnl-0000009b) [May 9 10:53:49] DEBUG[15339]: threadpool.c:517 grow: Increasing threadpool SIP's size by 5 [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/turnoutpocosnl-0000009c setting read format path: amrwb -> amrwb [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: res_format_attr_amr.c:405 amr_getjoint: Both formats were not cached but the same. [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:5680 set_format: Channel PJSIP/turnoutpocosnl-0000009c setting write format path: amrwb -> amrwb [May 9 10:53:49] NOTICE[8480][C-0000003b]: app_dial.c:1000 do_forward: Not accepting call completion offers from call-forward recipient PJSIP/turnoutpocosnl-0000009c [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:2728 ast_hangup: Hanging up channel 'PJSIP/turnoutpocosnl-0000009b' [May 9 10:53:49] DEBUG[8480][C-0000003b]: chan_pjsip.c:1957 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2502 handle_outgoing_response: Method is INVITE, Response is 181 Call Is Being Forwarded [May 9 10:53:49] DEBUG[5515]: res_pjsip/pjsip_message_ip_updater.c:215 multihomed_on_tx_message: Re-wrote Contact URI host/port to 185.61.68.110:5060 [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.82:5060' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.82' and port '5060'. <--- Transmitting SIP response (1896 bytes) to UDP:185.61.68.82:5060 ---> SIP/2.0 181 Call Is Being Forwarded Via: SIP/2.0/UDP 185.61.68.82;rport=5060;received=185.61.68.82;branch=z9hG4bK21d9.01940f2f8e0b575e4bd098c12fc78df0.0 Via: SIP/2.0/UDP 145.54.65.148:5060;rport=5060;branch=z9hG4bK+d11850aca9f1d680dd1fd0fdd9efab2f2+85347b59da9a545ad919839e4336440c+1000002;oai=yyyyEvC4yxqvckxyIyO7wq9-v2 Via: SIP/2.0/UDP KevrinegylYefdr0VeYhvGqHVbUQHsGSD5QM6yfW.KFABd1SJ.l.cWOt4vdpnzSDMVwHxOqJJuWP8VARtU-dCRj.EmOJvl.cUn37GxbpQjtzeGlAwvf58h6gXULG0G6JSYZMypT8l.cO4Vbodl3VYZEHSHWcUD6KWJlqYdBNSDvQUDhCGJMl.cKat.ell;branch=z9hG4bK-8;tokenized-by=atlanta.com Via: SIP/2.0/UDP Kevrinegyf0gh7tUXg0bxAsBXdWSBmAM69SO.1hQZBHCD0Y4Vpl.cDlnsCfhBFKhkJbp.93f22nXUXp2jeMzrAdB.aY6Jl.c4SD25MTFoWN0K7dCk0HTGUh8KjTWUIFsGnVv3ENZl.cCiH9Kat.ell;branch=z9hG4bK-8;tokenized-by=atlanta.com Record-Route: Record-Route: Record-Route: Call-ID: 0DBAA7573AC0-1FBC021DGgUOvdGrRUZKXLtYsogkeNG1szvP1KL7q5jlJpc0KCY7N4tGSYqxmwYewTtX3EsT0A From: ;tag=127.0.0.1alUtKGp-05897+1+ad0f0700+5e4fb3fc To: ;tag=2951db5b-e3cc-4002-ba1c-93414673bcbc CSeq: 989550440 INVITE Server: Asterisk PBX 13.14.1~dfsg-1 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Diversion: ;reason=unknown Content-Length: 0 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'sipx-efx-sbc0(PJSIP/sipx-efx-sbc0-0000009a)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab007cd78) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2426 __print_debug_details: There is no transaction involved in this state change [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is EARLY [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2603 session_inv_on_state_changed: Source of transaction state change is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'sipx-efx-sbc0(PJSIP/sipx-efx-sbc0-0000009a)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab007cd78) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2417 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f1ab007cd78 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2421 __print_debug_details: The current transaction state is Proceeding [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2423 __print_debug_details: The transaction state change event is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is EARLY [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f1aac071d00' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 18890 for RTP instance '0x7f1aac071d00' [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session [::]:18890 (18890) for RTP instance '0x7f1aac071d00' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f1aac071d00' is setup and ready to go [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'sipx-pocs1' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'sipx-pocs1' and port ''. [May 9 10:53:49] DEBUG[5515]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f1aac071d00' [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'fe80::250:56ff:feb3:3d30' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'fe80::250:56ff:feb3:3d30' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110' into... [May 9 10:53:49] DEBUG[5515]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port ''. [May 9 10:53:49] DEBUG[5515]: res_pjsip_t38.c:739 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2487 handle_outgoing_request: Method is INVITE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009c)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00e7708) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2426 __print_debug_details: There is no transaction involved in this state change [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is CALLING [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2603 session_inv_on_state_changed: Source of transaction state change is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2392 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2406 __print_debug_details: The state change pertains to the endpoint 'turnoutpocosnl(PJSIP/turnoutpocosnl-0000009c)' [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2411 __print_debug_details: The inv session still has an invite_tsx (0x7f1ab00e7708) [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2417 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f1ab00e7708 [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2421 __print_debug_details: The current transaction state is Calling [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2423 __print_debug_details: The transaction state change event is TX_MSG [May 9 10:53:49] DEBUG[5515]: res_pjsip_session.c:2428 __print_debug_details: The current inv state is CALLING [May 9 10:53:49] DEBUG[15327]: cdr.c:1293 cdr_object_finalize: Finalized CDR for PJSIP/sipx-efx-sbc0-0000009a - start 1494320029.492451 answer 0.000000 end 1494320029.677234 dispo NO ANSWER [May 9 10:53:49] DEBUG[15327]: cdr.c:1293 cdr_object_finalize: Finalized CDR for PJSIP/turnoutpocosnl-0000009b - start 1494320029.549128 answer 0.000000 end 1494320029.677268 dispo FAILED [May 9 10:53:49] DEBUG[15327]: cdr.c:1121 cdr_object_create_public_records: CDR for PJSIP/turnoutpocosnl-0000009b is dialed and has no Party B; discarding [May 9 10:53:49] DEBUG[15326]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - turnoutpocosnl [May 9 10:53:49] DEBUG[15326]: devicestate.c:474 do_state_change: Changing state for PJSIP/turnoutpocosnl - state 1 (Not in use) [May 9 10:53:49] DEBUG[8480][C-0000003b]: channel.c:4537 indicate_connected_line: PJSIP/sipx-efx-sbc0-0000009a: Dropping redundant connected line update "" <+3140xxxxxxx>. [May 9 10:53:49] DEBUG[15341]: res_pjsip/pjsip_message_ip_updater.c:215 multihomed_on_tx_message: Re-wrote Contact URI host/port to 185.61.68.110:5060 [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '185.61.68.110:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '185.61.68.110' and port '5060'. [May 9 10:53:49] DEBUG[15341]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '109.235.32.56:5060' into... [May 9 10:53:49] DEBUG[15341]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '109.235.32.56' and port '5060'. <--- Transmitting SIP request (1304 bytes) to UDP:109.235.32.56:5060 ---> INVITE sip:+3140xxxxxxx@sip.itco.nl;user=phone;user=phone SIP/2.0 Via: SIP/2.0/UDP 185.61.68.110:5060;rport;branch=z9hG4bKPja1f755a8-d916-4194-9307-ba7418a3b3bf From: ;tag=5dc2b35f-c63c-4bda-8064-a51b1aa98f45 To: Contact: Call-ID: b3f7992a-b3d5-4be6-bd8c-f78f57eb05eb CSeq: 20062 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 900 Min-SE: 90 P-Asserted-Identity: Diversion: ;reason=unknown Max-Forwards: 70 User-Agent: Asterisk PBX 13.14.1~dfsg-1 Content-Type: application/sdp Content-Length: 436 v=0 o=pocs 806240170 806240170 IN IP4 185.61.68.110 s=Asterisk c=IN IP4 185.61.68.110 t=0 0 m=audio 18890 RTP/AVP 8 9 109 108 18 111 101 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:109 AMR-WB/16000 a=fmtp:109 mode-change-capability=2 a=rtpmap:108 AMR/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv