__MARK__ [Sep 17 14:22:14] DEBUG[22306] res_pjsip.c: 0x7fa394005e20: Internal tsx timer expired after 3000 msec [Sep 17 14:22:14] DEBUG[22306] res_pjsip.c: 0x7fa394005e20: Timer handled here [Sep 17 14:22:14] DEBUG[22306] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:14] DEBUG[22306] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:14] DEBUG[22306] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:14] DEBUG[22306] res_pjsip.c: 0x7fa394005e20: Callbacks executed [Sep 17 14:22:14] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact kam_test_aor/sip:212.183.160.236:5060 status didn't change: Unreachable, RTT: 0.000 msec [Sep 17 14:22:14] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:14] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:14] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:14] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:15] DEBUG[22306] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:15] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:15] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000023 to use for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:15] DEBUG[13408] netsock2.c: Splitting '212.183.160.228' into... [Sep 17 14:22:15] DEBUG[13408] netsock2.c: ...host '212.183.160.228' and port ''. [Sep 17 14:22:15] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.228:5060 matches identify 'kamailio_id' [Sep 17 14:22:15] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Identify 'kamailio_id' SIP message matched to endpoint kamailio [Sep 17 14:22:15] DEBUG[13408] netsock2.c: Splitting '212.183.160.228' into... [Sep 17 14:22:15] DEBUG[13408] netsock2.c: ...host '212.183.160.228' and port ''. [Sep 17 14:22:15] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:15] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:15] DEBUG[13408] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:15] DEBUG[13408] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:15] DEBUG[29433] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:15] DEBUG[29433] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:15] DEBUG[29433] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:15] DEBUG[29433] res_pjsip.c: 0x7fa3a40014f0: Wrapper created [Sep 17 14:22:15] DEBUG[29433] res_pjsip.c: 0x7fa3a40014f0: Set timer to 3000 msec [Sep 17 14:22:15] DEBUG[29433] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:15] DEBUG[29433] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:15] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:15] DEBUG[29433] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:15] DEBUG[29433] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:15] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:15] DEBUG[29433] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:15] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:15] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:15] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:15] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=52684 (rdata0x7fa3c800eef8). Using request transaction as basis. [Sep 17 14:22:15] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c02ca88 for Response msg 200/OPTIONS/cseq=52684 (rdata0x7fa3c800eef8). [Sep 17 14:22:15] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-0000000f on transaction tsx0x7fa38c02ca88 [Sep 17 14:22:15] DEBUG[24181] res_pjsip.c: 0x7fa3a40014f0: PJSIP tsx response received [Sep 17 14:22:15] DEBUG[24181] res_pjsip.c: 0x7fa3a40014f0: Cancelling timer [Sep 17 14:22:15] DEBUG[24181] res_pjsip.c: 0x7fa3a40014f0: Timer cancelled [Sep 17 14:22:15] DEBUG[24181] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:15] DEBUG[24181] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:15] DEBUG[24181] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:15] DEBUG[24181] res_pjsip.c: 0x7fa3a40014f0: Callbacks executed [Sep 17 14:22:15] DEBUG[24181] res_pjsip.c: 0x7fa3a40014f0: wrapper destroyed [Sep 17 14:22:15] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact aarenet1_aor/sip:83.137.237.140:5060 status didn't change: Reachable, RTT: 3.704 msec [Sep 17 14:22:16] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:16] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:16] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:16] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:16] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:16] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:16] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:17] DEBUG[13408] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:17] DEBUG[13408] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:17] DEBUG[13408] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:17] DEBUG[13408] res_pjsip.c: 0x7fa3c4013990: Wrapper created [Sep 17 14:22:17] DEBUG[13408] res_pjsip.c: 0x7fa3c4013990: Set timer to 3000 msec [Sep 17 14:22:17] DEBUG[13408] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:17] DEBUG[13408] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:17] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:17] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:17] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:17] DEBUG[13408] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:17] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:17] DEBUG[22306] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:17] DEBUG[22306] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:17] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:17] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:17] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 501/OPTIONS/cseq=32813 (rdata0x7fa3c80008e8). Using request transaction as basis. [Sep 17 14:22:17] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c072e58 for Response msg 501/OPTIONS/cseq=32813 (rdata0x7fa3c80008e8). [Sep 17 14:22:17] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-00000010 on transaction tsx0x7fa38c072e58 [Sep 17 14:22:17] DEBUG[29433] res_pjsip.c: 0x7fa3c4013990: PJSIP tsx response received [Sep 17 14:22:17] DEBUG[29433] res_pjsip.c: 0x7fa3c4013990: Cancelling timer [Sep 17 14:22:17] DEBUG[29433] res_pjsip.c: 0x7fa3c4013990: Timer cancelled [Sep 17 14:22:17] DEBUG[29433] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:17] DEBUG[29433] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:17] DEBUG[29433] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:17] DEBUG[29433] res_pjsip.c: 0x7fa3c4013990: Callbacks executed [Sep 17 14:22:17] DEBUG[29433] res_pjsip.c: 0x7fa3c4013990: wrapper destroyed [Sep 17 14:22:17] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact kam_staging_aor/sip:212.183.160.238:5060 status didn't change: Reachable, RTT: 4.707 msec [Sep 17 14:22:18] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:18] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPja4fab9f1-52dc-4167-ab58-922b96c2d62f From: ;tag=60b217bf-b68a-48dd-bc14-34a02b300b52 To: Contact: Call-ID: f3a8dcea-e978-4767-ae66-80d4745946fc CSeq: 54371 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:18] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:18] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPje07b9575-83ce-41cc-a809-a4611705e514 From: ;tag=66a7aeb7-bb1a-4dfd-93a9-b2ed94fa8b78 To: Contact: Call-ID: 52293337-188c-4cf9-a6cc-700c81fd61b8 CSeq: 33707 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:18] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP request (387 bytes) from UDP:212.183.160.238:5060 ---> OPTIONS sip:212.183.166.23:5060 SIP/2.0 Via: SIP/2.0/UDP 212.183.160.238;branch=z9hG4bK4e0e.1d4978c7000000000000000000000000.0 To: From: ;tag=1579ac949957a2acf28c29a8989316e7-17f3 CSeq: 10 OPTIONS Call-ID: 7edf10387b1c82ee-20583@212.183.160.238 Max-Forwards: 70 Content-Length: 0 User-Agent: kamailio (5.1.4 (x86_64/linux)) [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:18] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:18] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:18] DEBUG[22306] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:18] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002c to use for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:18] DEBUG[24181] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:18] DEBUG[24181] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kamailio_id' [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam05_id' [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'aarenet1_id' [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam_test_id' [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 matches identify 'kam_staging_id' [Sep 17 14:22:18] DEBUG[24181] res_pjsip_endpoint_identifier_ip.c: Identify 'kam_staging_id' SIP message matched to endpoint kam_staging [Sep 17 14:22:18] DEBUG[24181] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:18] DEBUG[24181] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:18] DEBUG[24181] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:18] DEBUG[24181] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:18] DEBUG[24181] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:18] DEBUG[24181] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:18] VERBOSE[24181] res_pjsip_logger.c: <--- Transmitting SIP response (908 bytes) to UDP:212.183.160.238:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 212.183.160.238;rport=5060;received=212.183.160.238;branch=z9hG4bK4e0e.1d4978c7000000000000000000000000.0 Call-ID: 7edf10387b1c82ee-20583@212.183.160.238 From: ;tag=1579ac949957a2acf28c29a8989316e7-17f3 To: ;tag=z9hG4bK4e0e.1d4978c7000000000000000000000000.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Server: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:19] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP request (385 bytes) from UDP:212.183.160.237:5060 ---> OPTIONS sip:212.183.166.23:5060 SIP/2.0 Via: SIP/2.0/UDP 212.183.160.237;branch=z9hG4bK5c63.8bd637e3000000000000000000000000.0 To: From: ;tag=ee2fbe26e50f87d03755740e34cd3187-82ca CSeq: 10 OPTIONS Call-ID: 5ca68c3b6f4531eb-923@212.183.160.237 Max-Forwards: 70 Content-Length: 0 User-Agent: kamailio (5.1.3 (x86_64/linux)) [Sep 17 14:22:19] DEBUG[22306] netsock2.c: Splitting '212.183.160.237:5060' into... [Sep 17 14:22:19] DEBUG[22306] netsock2.c: ...host '212.183.160.237' and port '5060'. [Sep 17 14:22:19] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:19] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:19] DEBUG[22306] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:19] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003a to use for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:19] DEBUG[13408] netsock2.c: Splitting '212.183.160.237' into... [Sep 17 14:22:19] DEBUG[13408] netsock2.c: ...host '212.183.160.237' and port ''. [Sep 17 14:22:19] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.237:5060 does not match identify 'kamailio_id' [Sep 17 14:22:19] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.237:5060 matches identify 'kam05_id' [Sep 17 14:22:19] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Identify 'kam05_id' SIP message matched to endpoint kam05 [Sep 17 14:22:19] DEBUG[13408] netsock2.c: Splitting '212.183.160.237' into... [Sep 17 14:22:19] DEBUG[13408] netsock2.c: ...host '212.183.160.237' and port ''. [Sep 17 14:22:19] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:19] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:19] DEBUG[13408] netsock2.c: Splitting '212.183.160.237:5060' into... [Sep 17 14:22:19] DEBUG[13408] netsock2.c: ...host '212.183.160.237' and port '5060'. [Sep 17 14:22:19] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP response (906 bytes) to UDP:212.183.160.237:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 212.183.160.237;rport=5060;received=212.183.160.237;branch=z9hG4bK5c63.8bd637e3000000000000000000000000.0 Call-ID: 5ca68c3b6f4531eb-923@212.183.160.237 From: ;tag=ee2fbe26e50f87d03755740e34cd3187-82ca To: ;tag=z9hG4bK5c63.8bd637e3000000000000000000000000.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Server: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP request (1553 bytes) from UDP:212.183.160.238:5060 ---> INVITE sip:03631979004@212.183.160.238;user=phone SIP/2.0 Record-Route: Via: SIP/2.0/UDP 212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 Via: SIP/2.0/UDP 10.132.20.51:2174;received=212.183.161.99;branch=z9hG4bK-ibbp47gpd96j;rport=62590 From: "03421950085" ;tag=mtwl0ivrok To: Call-ID: 3c64394a57a8-8u0e813m9w70 CSeq: 2 INVITE Max-Forwards: 70 Contact: ;reg-id=1 X-Serialnumber: 000413249E36 P-Key-Flags: keys="3" User-Agent: snom320/8.4.35 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Call-Info: ;appearance-index=1 Session-Expires: 300;refresher=uas Min-SE: 90 Proxy-Authorization: Digest username="test.int.03421950085.voce",realm="212.183.160.238",nonce="W5+dqFufnHxewizkWoJj8xNjX3h0eQcM",uri="sip:03631979004@212.183.160.238;user=phone",response="d2b280bbae5a9aab18eae9a1f4801d4b",algorithm=MD5 Content-Type: application/sdp Content-Length: 291 v=0 o=root 2002309170 2002309170 IN IP4 212.183.160.238 s=call c=IN IP4 212.183.160.238 t=0 0 m=audio 35642 RTP/AVP 18 8 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv a=nortpproxy:yes [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x7fa3c80008e8) [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000027 to use for Request msg INVITE/cseq=2 (rdata0x7fa3c80008e8) [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kamailio_id' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam05_id' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'aarenet1_id' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam_test_id' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 matches identify 'kam_staging_id' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Identify 'kam_staging_id' SIP message matched to endpoint kam_staging [Sep 17 14:22:20] DEBUG[29433] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000027 to use for Request msg INVITE/cseq=2 (rdata0x7fa3c801afc8) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:20] VERBOSE[29433] res_pjsip_logger.c: <--- Transmitting SIP response (537 bytes) to UDP:212.183.160.238:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 212.183.160.238;rport=5060;received=212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 Via: SIP/2.0/UDP 10.132.20.51:2174;rport=62590;received=212.183.161.99;branch=z9hG4bK-ibbp47gpd96j Record-Route: Call-ID: 3c64394a57a8-8u0e813m9w70 From: "03421950085" ;tag=mtwl0ivrok To: CSeq: 2 INVITE Server: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging()' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current inv state is INCOMING [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Source of transaction state change is TX_MSG [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging()' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa394054f18 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current transaction state is Proceeding [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current inv state is INCOMING [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.166.23' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port ''. [Sep 17 14:22:20] DEBUG[29433] res_pjsip_sdp_rtp.c: Transport transport_kamailio bound to 212.183.166.23: Using it for RTP media. [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa3a4050910' [Sep 17 14:22:20] DEBUG[29433] res_rtp_asterisk.c: Allocated port 19332 for RTP instance '0x7fa3a4050910' [Sep 17 14:22:20] DEBUG[29433] res_rtp_asterisk.c: Creating ICE session 212.183.166.23:19332 (19332) for RTP instance '0x7fa3a4050910' [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.166.23' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.166.23' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '83.137.237.154' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '83.137.237.154' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port ''. [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: RTP instance '0x7fa3a4050910' is setup and ready to go [Sep 17 14:22:20] DEBUG[29433] acl.c: Attached to given IP address [Sep 17 14:22:20] DEBUG[29433] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa3a4050910' [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fa3726542f0 [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fa3726542f0 [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fa3726542f0 [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Copying payload 8 (0x7fa3a4005958) from 0x7fa3726542f0 to 0x7fa3a4050ad8 [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Copying payload 18 (0x7fa3a4005998) from 0x7fa3726542f0 to 0x7fa3a4050ad8 [Sep 17 14:22:20] DEBUG[29433] rtp_engine.c: Copying payload 101 (0x7fa3a4006368) from 0x7fa3726542f0 to 0x7fa3a4050ad8 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Media stream 'audio' handled by audio [Sep 17 14:22:20] DEBUG[29433] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fa3a4050910' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Method is INVITE [Sep 17 14:22:20] DEBUG[29433] channel.c: Channel 0x7fa3a4017320 'PJSIP/kam_staging-00000382' allocated [Sep 17 14:22:20] DEBUG[22283] threadpool.c: Increasing threadpool stasis-core's size by 1 [Sep 17 14:22:20] DEBUG[29433] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/kam_staging-00000382 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Chiamata in uscita: Inizio [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'DumpChan' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Numero chiamante: 03421950085 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EXTEN' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Numero chiamato: 03631979004 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(endpoint) result is 'kam_staging' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Account SIP chiamante: kam_staging [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'CHANNEL' is 'PJSIP/kam_staging-00000382' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Canale in ingresso: PJSIP/kam_staging-00000382 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function PJSIP_HEADER(read,Contact) result is ';reg-id=1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Evaluating 'CUT(sipContact,@,2)' (from 'CUT(sipContact,@,2)}' len 19) [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Evaluating 'sipContact' (from 'sipContact}' len 10) [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipContact' is ';reg-id=1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CUT(sipContact,@,2) result is '212.183.161.99:62590;line=58tgbyze>;reg-id=1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CUT(CUT(sipContact,@,2),>,1) result is '212.183.161.99:62590;line=58tgbyze' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EXTEN' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'ipAddress' is '212.183.161.99:62590;line=58tgbyze' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Dettagli UDP Sorgente: 212.183.161.99:62590;line=58tgbyze [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EXTEN' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Called with data=0x7fa3eec3b298, str=0x7fa3e0002ee0, realsize=6, len=16, used=0 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Now, len=16, used=6 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: str='ALLOW' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CURL(http://127.0.0.9:1805/allow/out?a=03421950085&b=03631979004) result is 'ALLOW' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'allowd' is 'ALLOW' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'NoOp' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EXTEN' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Called with data=0x7fa3eec3b288, str=0x7fa3e0018a40, realsize=9, len=16, used=0 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Now, len=16, used=9 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: str='aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CURL(http://127.0.0.9:1805/route/out?a=03421950085&b=03631979004) result is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] db.c: Unable to find key 'out' in family 'sipGwBl' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_db.c: DB: sipGwBl/out not found in database. [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function DB(sipGwBl/out) result is '' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Evaluating 'sipGwOutBl' (from 'sipGwOutBl}' len 10) [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutBl' is '' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function FIELDQTY(sipGwOutBl,\,) result is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'z' is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroBlGw' is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'While' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutList' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Gateway disponibili: aarenet1 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Evaluating 'sipGwOutList' (from 'sipGwOutList}' len 12) [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutList' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function FIELDQTY(sipGwOutList,\,) result is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EXTEN' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function MATH(5+4,int) result is '9' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'chiaveRicerca' is '9' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroGw' is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function MATH(9+1,int) result is '10' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'chiaveRicerca' is '10' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroGw' is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function MATH(10%1,int) result is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutId' is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function MATH(0+1,int) result is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutId' is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Evaluating 'sipGwOutList' (from 'sipGwOutList}' len 12) [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutList' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CUT(sipGwOutList,\,,1) result is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'ExitWhile' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Gateway selezionato: aarenet1 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function DEVICE_STATE(PJSIP/aarenet1) result is 'NOT_INUSE' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutStatus' is 'NOT_INUSE' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Stato del Gateway: NOT_INUSE [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOutStatus' is 'NOT_INUSE' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is 'NOT_INUSE' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'NoOp' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function PJSIP_ENDPOINT(aarenet1,aors) result is 'aarenet1_aor' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'outAOR' is 'aarenet1_aor' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function PJSIP_AOR(aarenet1_aor,contact) result is 'aarenet1_aor@@f8f851bea348ffd4c02c5b57bab9dbca' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'outContact' is 'aarenet1_aor@@f8f851bea348ffd4c02c5b57bab9dbca' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function PJSIP_CONTACT(aarenet1_aor@@f8f851bea348ffd4c02c5b57bab9dbca,uri) result is 'sip:83.137.237.140:5060' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[22283] threadpool.c: Increasing threadpool stasis-core's size by 1 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'outUri' is 'sip:83.137.237.140:5060' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] URI del Gateway: sip:83.137.237.140:5060 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function PJSIP_MEDIA_OFFER(audio) result is 'alaw,g729' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'codecPreferito' is '"alaw,g729"' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_builtins.c: Not taking any branch [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'codecPreferito' is '"alaw,g729"' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '0' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_builtins.c: Not taking any branch [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Goto' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'codecPreferito' is '"alaw,g729"' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Codec utilizzato dal chiamante: "alaw,g729" [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(audioreadformat) result is 'alaw' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Codec utilizzato in ingresso: alaw [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroDaChiamare' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Eseguo la chiamata verso il gateway: 03631979004@aarenet1 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Called with data=0x7fa3eec3b288, str=0x7fa3e0003190, realsize=12, len=16, used=0 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Now, len=16, used=12 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: str='03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CURL(http://127.0.0.9:1805/mangle?ab=a&n=03421950085&gw=aarenet1) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroDaChiamare' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Called with data=0x7fa3eec3b278, str=0x7fa3e0003220, realsize=12, len=16, used=0 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: Now, len=16, used=12 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] func_curl.c: str='03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CURL(http://127.0.0.9:1805/mangle?ab=b&n=03631979004&gw=aarenet1) result is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CALLERID(num) result is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroManeggiatoA' is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Numero chiamante trasformato da 03421950085 a 03421950085 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186940' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186940,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:20' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroDaChiamare' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroManeggiatoB' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:20] VERBOSE[14297][C-000001ca] Ext. 03631979004: [2018/09/17 14:22:20] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Numero chiamato trasformato da 03631979004 a 03631979004 [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroManeggiatoA' is '03421950085' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Set' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'numeroManeggiatoB' is '03631979004' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'sipGwOut' is 'aarenet1' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] pbx.c: Launching 'Dial' [Sep 17 14:22:20] DEBUG[14297][C-000001ca] channel.c: Channel 0x7fa3e00155b0 'PJSIP/aarenet1-00000383' allocated [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.154' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.154' and port ''. [Sep 17 14:22:20] DEBUG[13408] res_pjsip_sdp_rtp.c: Transport transport_aarenet bound to 83.137.237.154: Using it for RTP media. [Sep 17 14:22:20] DEBUG[13408] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa3c4017330' [Sep 17 14:22:20] DEBUG[13408] res_rtp_asterisk.c: Allocated port 12680 for RTP instance '0x7fa3c4017330' [Sep 17 14:22:20] DEBUG[13408] res_rtp_asterisk.c: Creating ICE session 83.137.237.154:12680 (12680) for RTP instance '0x7fa3c4017330' [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.166.23' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port ''. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.166.23' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port ''. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.154' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.154' and port ''. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.154' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.154' and port ''. [Sep 17 14:22:20] DEBUG[13408] rtp_engine.c: RTP instance '0x7fa3c4017330' is setup and ready to go [Sep 17 14:22:20] DEBUG[13408] acl.c: Attached to given IP address [Sep 17 14:22:20] DEBUG[13408] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa3c4017330' [Sep 17 14:22:20] DEBUG[13408] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Method is INVITE [Sep 17 14:22:20] DEBUG[13408] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:20] DEBUG[13408] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:20] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP request (1010 bytes) to UDP:83.137.237.140:5060 ---> INVITE sip:03631979004@83.137.237.140:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 From: "03421950085" ;tag=261f2e78-dac0-41de-988c-721f335baee1 To: Contact: Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Require: 100rel Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Type: application/sdp Content-Length: 288 v=0 o=- 1362288673 1362288673 IN IP4 83.137.237.154 s=Asterisk c=IN IP4 83.137.237.154 t=0 0 m=audio 12680 RTP/AVP 8 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current inv state is CALLING [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Source of transaction state change is TX_MSG [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa38c0326a8 [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current transaction state is Calling [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current inv state is CALLING [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (396 bytes) from UDP:83.137.237.140:5060 ---> SIP/2.0 100 Trying From: "03421950085";tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 INVITE Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 Contact: [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa38c0488c8 for Response msg 100/INVITE/cseq=27019 (rdata0x7fa3c800eef8) [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/aarenet1-00000214 associated with dialog dlg0x7fa38c0488c8 [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa38c0326a8 [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The current transaction state is Proceeding [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The current inv state is CALLING [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Received response [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Response is 100 Trying [Sep 17 14:22:20] DEBUG[14305] manager.c: Running action 'Login' [Sep 17 14:22:20] DEBUG[14305] manager.c: Running action 'Command' [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (442 bytes) from UDP:83.137.237.140:5060 ---> SIP/2.0 180 Ringing From: "03421950085";tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 INVITE RSeq: 1 Require: 100rel Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 Contact: Content-Length: 0 [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa38c0488c8 for Response msg 180/INVITE/cseq=27019 (rdata0x7fa3c800eef8) [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/aarenet1-00000214 associated with dialog dlg0x7fa38c0488c8 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Received response [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Response is 180 Ringing [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:20] DEBUG[29433] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:20] VERBOSE[29433] res_pjsip_logger.c: <--- Transmitting SIP request (482 bytes) to UDP:83.137.237.140:5060 ---> PRACK sip:03631979004@83.137.237.140:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPjf787b2f6-9505-4c8f-a192-d76ec85c808c From: "03421950085" ;tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27020 PRACK RAck: 1 27019 INVITE Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7fa38c062db8 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current transaction state is Calling [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa38c0326a8 [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current transaction state is Proceeding [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Received response [Sep 17 14:22:20] DEBUG[29433] res_pjsip_session.c: Response is 180 Ringing [Sep 17 14:22:20] DEBUG[22294] devicestate.c: No provider found, checking channel drivers for PJSIP - aarenet1 [Sep 17 14:22:20] DEBUG[22294] devicestate.c: Changing state for PJSIP/aarenet1 - state 6 (Ringing) [Sep 17 14:22:20] DEBUG[22358] app_queue.c: Device 'PJSIP/aarenet1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (343 bytes) from UDP:83.137.237.140:5060 ---> SIP/2.0 200 OK From: "03421950085";tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27020 PRACK Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPjf787b2f6-9505-4c8f-a192-d76ec85c808c [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa38c0488c8 for Response msg 200/PRACK/cseq=27020 (rdata0x7fa3c800eef8) [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/aarenet1-00000214 associated with dialog dlg0x7fa38c0488c8 [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Sep 17 14:22:20] DEBUG[13408] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7fa38c062db8 [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The current transaction state is Completed [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Received response [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: Response is 200 OK [Sep 17 14:22:20] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP response (726 bytes) to UDP:212.183.160.238:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 212.183.160.238;rport=5060;received=212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 Via: SIP/2.0/UDP 10.132.20.51:2174;rport=62590;received=212.183.161.99;branch=z9hG4bK-ibbp47gpd96j Record-Route: Call-ID: 3c64394a57a8-8u0e813m9w70 From: "03421950085" ;tag=mtwl0ivrok To: ;tag=e1e401c5-f15f-463e-a467-57de95f39f21 CSeq: 2 INVITE Server: Asterisk PBX 13.21.1~qcom-1.1 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Content-Length: 0 [Sep 17 14:22:20] DEBUG[24181] res_pjsip_session.c: PRACK received final response code 200 [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Source of transaction state change is TX_MSG [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa394054f18 [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current transaction state is Proceeding [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:20] DEBUG[13408] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:20] DEBUG[22294] devicestate.c: No provider found, checking channel drivers for PJSIP - kam_staging [Sep 17 14:22:20] DEBUG[22294] devicestate.c: Changing state for PJSIP/kam_staging - state 2 (In use) [Sep 17 14:22:20] DEBUG[22358] app_queue.c: Device 'PJSIP/kam_staging' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3a404dca0: Wrapper created [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3a404dca0: Set timer to 3000 msec [Sep 17 14:22:20] DEBUG[29433] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.237' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.237' and port ''. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[29433] netsock2.c: Splitting '212.183.160.237:5060' into... [Sep 17 14:22:20] DEBUG[29433] netsock2.c: ...host '212.183.160.237' and port '5060'. [Sep 17 14:22:20] VERBOSE[29433] res_pjsip_logger.c: <--- Transmitting SIP request (434 bytes) to UDP:212.183.160.237:5060 ---> OPTIONS sip:212.183.160.237:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPjfd8767f8-73ac-488f-ac85-709a712e0148 From: ;tag=ac20252d-6a3f-45be-9daa-4188b4905501 To: Contact: Call-ID: 7178404b-7908-4b55-a650-66c837e96214 CSeq: 47054 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (429 bytes) from UDP:212.183.160.237:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 83.137.237.154:5060;rport=5060;branch=z9hG4bKPjfd8767f8-73ac-488f-ac85-709a712e0148;received=212.183.166.23 From: ;tag=ac20252d-6a3f-45be-9daa-4188b4905501 To: ;tag=120ef7e6e318ec39fd64f35c6bcc9f83.f4e1 Call-ID: 7178404b-7908-4b55-a650-66c837e96214 CSeq: 47054 OPTIONS Server: kamailio (5.1.3 (x86_64/linux)) Content-Length: 0 [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.160.237:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.160.237' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 501/OPTIONS/cseq=47054 (rdata0x7fa3c80008e8). Using request transaction as basis. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c0af6a8 for Response msg 501/OPTIONS/cseq=47054 (rdata0x7fa3c80008e8). [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-0000000a on transaction tsx0x7fa38c0af6a8 [Sep 17 14:22:20] DEBUG[24181] res_pjsip.c: 0x7fa3a404dca0: PJSIP tsx response received [Sep 17 14:22:20] DEBUG[24181] res_pjsip.c: 0x7fa3a404dca0: Cancelling timer [Sep 17 14:22:20] DEBUG[24181] res_pjsip.c: 0x7fa3a404dca0: Timer cancelled [Sep 17 14:22:20] DEBUG[24181] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:20] DEBUG[24181] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:20] DEBUG[24181] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:20] DEBUG[24181] res_pjsip.c: 0x7fa3a404dca0: Callbacks executed [Sep 17 14:22:20] DEBUG[24181] res_pjsip.c: 0x7fa3a404dca0: wrapper destroyed [Sep 17 14:22:20] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact kam05_aor/sip:212.183.160.237:5060 status didn't change: Reachable, RTT: 3.067 msec [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj0f65c7da-f1fc-47b6-9cf0-83031444dae3 From: ;tag=f302e006-2c71-41ec-a9ba-15096c0d99a9 To: Contact: Call-ID: d0da42ba-9b94-4ee3-b837-18bf7442cf04 CSeq: 60592 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] DEBUG[13408] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:20] DEBUG[13408] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:20] DEBUG[13408] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:20] DEBUG[13408] res_pjsip.c: 0x7fa3c403ef40: Wrapper created [Sep 17 14:22:20] DEBUG[13408] res_pjsip.c: 0x7fa3c403ef40: Set timer to 3000 msec [Sep 17 14:22:20] DEBUG[13408] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.160.228' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.160.228' and port ''. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[13408] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:20] DEBUG[13408] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:20] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.228:5060 ---> OPTIONS sip:212.183.160.228:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj5050cccb-c7ab-46e7-99e4-c3b742294c51 From: ;tag=cad53485-88b1-44db-b5ef-eda86eeb348f To: Contact: Call-ID: 963997a3-1c7f-4d02-aabf-891c2707b38d CSeq: 42743 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:20] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (432 bytes) from UDP:212.183.160.228:5060 ---> SIP/2.0 501 Not Implemented Via: SIP/2.0/UDP 83.137.237.154:5060;rport=5060;branch=z9hG4bKPj5050cccb-c7ab-46e7-99e4-c3b742294c51;received=212.183.166.23 From: ;tag=cad53485-88b1-44db-b5ef-eda86eeb348f To: ;tag=038edcba643519ecf2d507ed018e94aa.5575 Call-ID: 963997a3-1c7f-4d02-aabf-891c2707b38d CSeq: 42743 OPTIONS Server: kamailio (3.2.4 (x86_64/linux)) Content-Length: 0 [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:20] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 501/OPTIONS/cseq=42743 (rdata0x7fa3c80008e8). Using request transaction as basis. [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c053908 for Response msg 501/OPTIONS/cseq=42743 (rdata0x7fa3c80008e8). [Sep 17 14:22:20] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-0000000b on transaction tsx0x7fa38c053908 [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3c403ef40: PJSIP tsx response received [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3c403ef40: Cancelling timer [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3c403ef40: Timer cancelled [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:20] DEBUG[29433] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:20] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact kamailio_aor/sip:212.183.160.228:5060 status didn't change: Reachable, RTT: 2.944 msec [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3c403ef40: Callbacks executed [Sep 17 14:22:20] DEBUG[29433] res_pjsip.c: 0x7fa3c403ef40: wrapper destroyed [Sep 17 14:22:21] DEBUG[24181] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:21] DEBUG[24181] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:21] DEBUG[24181] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:21] DEBUG[24181] res_pjsip.c: 0x7fa3940559b0: Wrapper created [Sep 17 14:22:21] DEBUG[24181] res_pjsip.c: 0x7fa3940559b0: Set timer to 3000 msec [Sep 17 14:22:21] DEBUG[24181] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:21] DEBUG[24181] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:21] DEBUG[24181] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:21] DEBUG[24181] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:21] DEBUG[24181] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:21] DEBUG[24181] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:21] DEBUG[24181] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:21] VERBOSE[24181] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj4190bcc9-0e7d-4bd5-86d3-c6c18a91e5eb From: ;tag=4e0ec0f6-eb93-4fd9-ba86-22a1ed100010 To: Contact: Call-ID: 231d8f2d-74c7-4f04-8387-8493cd51ba4f CSeq: 21641 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:21] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:21] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:21] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:21] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:21] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:21] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:21] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:21] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj4190bcc9-0e7d-4bd5-86d3-c6c18a91e5eb From: ;tag=4e0ec0f6-eb93-4fd9-ba86-22a1ed100010 To: Contact: Call-ID: 231d8f2d-74c7-4f04-8387-8493cd51ba4f CSeq: 21641 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP request (415 bytes) from UDP:212.183.160.238:5060 ---> CANCEL sip:03631979004@212.183.160.238;user=phone SIP/2.0 Via: SIP/2.0/UDP 212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 From: "03421950085" ;tag=mtwl0ivrok To: Call-ID: 3c64394a57a8-8u0e813m9w70 CSeq: 2 CANCEL Max-Forwards: 70 Content-Length: 0 Reason: SIP;cause=487;text="Request terminated by user" [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa3a404c298 for Request msg CANCEL/cseq=2 (rdata0x7fa3c80008e8) [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000027 associated with dialog dlg0x7fa3a404c298 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The UAS CANCEL transaction involved in this state change is 0x7fa38c04e178 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current transaction state is Trying [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Received request [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Method is CANCEL [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:22] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP response (414 bytes) to UDP:212.183.160.238:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 212.183.160.238;rport=5060;received=212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 Call-ID: 3c64394a57a8-8u0e813m9w70 From: "03421950085" ;tag=mtwl0ivrok To: ;tag=e1e401c5-f15f-463e-a467-57de95f39f21 CSeq: 2 CANCEL Server: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The UAS CANCEL transaction involved in this state change is 0x7fa38c04e178 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current transaction state is Completed [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:22] VERBOSE[13408] res_pjsip_logger.c: <--- Transmitting SIP response (701 bytes) to UDP:212.183.160.238:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 212.183.160.238;rport=5060;received=212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 Via: SIP/2.0/UDP 10.132.20.51:2174;rport=62590;received=212.183.161.99;branch=z9hG4bK-ibbp47gpd96j Record-Route: Call-ID: 3c64394a57a8-8u0e813m9w70 From: "03421950085" ;tag=mtwl0ivrok To: ;tag=e1e401c5-f15f-463e-a467-57de95f39f21 CSeq: 2 INVITE Server: Asterisk PBX 13.21.1~qcom-1.1 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Content-Length: 0 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Source of transaction state change is TX_MSG [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP request (393 bytes) from UDP:212.183.160.238:5060 ---> ACK sip:03631979004@212.183.160.238;user=phone SIP/2.0 Via: SIP/2.0/UDP 212.183.160.238;branch=z9hG4bK361a.09665bc5d6cb0a2379cb292ae0d550e3.0 From: "03421950085" ;tag=mtwl0ivrok To: ;tag=e1e401c5-f15f-463e-a467-57de95f39f21 Call-ID: 3c64394a57a8-8u0e813m9w70 CSeq: 2 ACK Max-Forwards: 70 Content-Length: 0 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The state change pertains to the endpoint 'kam_staging(PJSIP/kam_staging-00000382)' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa394054f18 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current transaction state is Completed [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.238:5060' into... [Sep 17 14:22:22] DEBUG[14297][C-000001ca] channel.c: Channel 0x7fa3e00155b0 'PJSIP/aarenet1-00000383' hanging up. Refs: 2 [Sep 17 14:22:22] DEBUG[14297][C-000001ca] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Sep 17 14:22:22] DEBUG[14297][C-000001ca] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx.c: Spawn extension (chiamateInUscita,03631979004,68) exited non-zero on 'PJSIP/kam_staging-00000382' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/kam_staging-00000382' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] channel.c: Soft-Hanging (0x80) up channel 'PJSIP/kam_staging-00000382' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'relCause' is NULL [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx_variables.c: Expression result is '1' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx.c: Launching 'GotoIf' [Sep 17 14:22:22] DEBUG[22295] cdr.c: Finalized CDR for PJSIP/kam_staging-00000382 - start 1537186940.293838 answer 0.000000 end 1537186942.078326 dispo NO ANSWER [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Method is CANCEL [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:22] DEBUG[29433] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.238' and port '5060'. [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:22] VERBOSE[29433] res_pjsip_logger.c: <--- Transmitting SIP request (456 bytes) to UDP:83.137.237.140:5060 ---> CANCEL sip:03631979004@83.137.237.140:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 From: "03421950085" ;tag=261f2e78-dac0-41de-988c-721f335baee1 To: Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 CANCEL Reason: Q.850;cause=0 Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1(PJSIP/aarenet1-00000383)' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx_variables.c: Result of 'EPOCH' is '1537186942' [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7fa38c02ca88 [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The current transaction state is Calling [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The current inv state is EARLY [Sep 17 14:22:22] DEBUG[29433] channel.c: Channel 0x7fa3e00155b0 'PJSIP/aarenet1-00000383' destroying [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx_variables.c: Function STRFTIME(1537186942,,%Y/%m/%d %H:%M:%S) result is '2018/09/17 14:22:22' [Sep 17 14:22:22] DEBUG[22294] devicestate.c: No provider found, checking channel drivers for PJSIP - aarenet1 [Sep 17 14:22:22] DEBUG[22294] devicestate.c: Changing state for PJSIP/aarenet1 - state 1 (Not in use) [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx_variables.c: Function CHANNEL(pjsip,call-id) result is '3c64394a57a8-8u0e813m9w70' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx.c: Launching 'Log' [Sep 17 14:22:22] DEBUG[22358] app_queue.c: Device 'PJSIP/aarenet1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[22295] cdr.c: Finalized CDR for PJSIP/aarenet1-00000383 - start 1537186940.383137 answer 0.000000 end 1537186942.081441 dispo FAILED [Sep 17 14:22:22] DEBUG[22295] cdr.c: CDR for PJSIP/aarenet1-00000383 is dialed and has no Party B; discarding [Sep 17 14:22:22] VERBOSE[14297][C-000001ca] Ext. s-CANCEL: [2018/09/17 14:22:22] Chiamata in uscita [3c64394a57a8-8u0e813m9w70] Chiamata terminata dal chiamante [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx.c: Launching 'Hangup' [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa3a404c298 for Request msg ACK/cseq=2 (rdata0x7fa3c80008e8) [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000027 to use for Request msg ACK/cseq=2 (rdata0x7fa3c80008e8) [Sep 17 14:22:22] DEBUG[14297][C-000001ca] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/kam_staging-00000382' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] pbx.c: Spawn extension (chiamateInUscita,s-CANCEL,2) exited non-zero on 'PJSIP/kam_staging-00000382' [Sep 17 14:22:22] DEBUG[14297][C-000001ca] channel.c: Channel 0x7fa3a4017320 'PJSIP/kam_staging-00000382' hanging up. Refs: 2 [Sep 17 14:22:22] DEBUG[14297][C-000001ca] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (408 bytes) from UDP:83.137.237.140:5060 ---> SIP/2.0 487 Request Terminated From: "03421950085";tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 INVITE Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 Contact: [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa38c0488c8 for Response msg 487/INVITE/cseq=27019 (rdata0x7fa3c800eef8) [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/aarenet1-00000214 associated with dialog dlg0x7fa38c0488c8 [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:22] DEBUG[29433] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:22] DEBUG[29433] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:22] DEBUG[29433] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:22] VERBOSE[29433] res_pjsip_logger.c: <--- Transmitting SIP request (456 bytes) to UDP:83.137.237.140:5060 ---> ACK sip:03631979004@83.137.237.140:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 From: "03421950085" ;tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1()' [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: There is no transaction involved in this state change [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Received response [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Response is 487 Request Terminated [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The state change pertains to the endpoint 'aarenet1()' [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa38c0326a8 [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The current transaction state is Completed [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:22] DEBUG[13408] netsock2.c: Splitting '212.183.160.238' into... [Sep 17 14:22:22] DEBUG[13408] netsock2.c: ...host '212.183.160.238' and port ''. [Sep 17 14:22:22] DEBUG[29433] rtp_engine.c: Destroyed RTP instance '0x7fa3c4017330' [Sep 17 14:22:22] DEBUG[29433] res_pjsip_session.c: Destroying SIP session with endpoint aarenet1 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kamailio_id' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam05_id' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'aarenet1_id' [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Received SIP response (501 bytes) from UDP:83.137.237.140:5060 ---> SIP/2.0 200 OK From: "03421950085";tag=261f2e78-dac0-41de-988c-721f335baee1 To: ;tag=sc2qcom1-292c9cde419c73ff Call-ID: b99d0ce5-6347-4925-bc6d-1d1cc5ee2af3 CSeq: 27019 CANCEL Allow: INVITE, ACK, PRACK, CANCEL, BYE, OPTIONS, MESSAGE, NOTIFY, REGISTER, INFO, REFER, SUBSCRIBE, PUBLISH Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj333a2cae-1f87-4d7f-a7d2-f82269dcd537 Contact: [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 does not match identify 'kam_test_id' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.238:5060 matches identify 'kam_staging_id' [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:22] DEBUG[13408] res_pjsip_endpoint_identifier_ip.c: Identify 'kam_staging_id' SIP message matched to endpoint kam_staging [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa38c0488c8 for Response msg 200/CANCEL/cseq=27019 (rdata0x7fa3c800eef8) [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/CANCEL/cseq=27019 (rdata0x7fa3c800eef8). Using request transaction as basis. [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c02ca88 for Response msg 200/CANCEL/cseq=27019 (rdata0x7fa3c800eef8). [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000028 to use for Response msg 200/CANCEL/cseq=27019 (rdata0x7fa3c800eef8) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: inv_session 0x7fa3a401ef08 has no ast session [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa394054f18) [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa394054f18 [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current transaction state is Confirmed [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:22] DEBUG[13408] rtp_engine.c: Destroyed RTP instance '0x7fa3a4050910' [Sep 17 14:22:22] DEBUG[13408] res_pjsip_session.c: Destroying SIP session with endpoint kam_staging [Sep 17 14:22:22] DEBUG[13408] channel.c: Channel 0x7fa3a4017320 'PJSIP/kam_staging-00000382' destroying [Sep 17 14:22:22] DEBUG[22295] cdr_mysql.c: Inserting a CDR record. [Sep 17 14:22:22] DEBUG[22295] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`server`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2018-09-17 14:22:20','ast04','03421950085','03631979004','chiamateInUscita','PJSIP/kam_staging-00000382','PJSIP/aarenet1-00000383','Dial','PJSIP/03631979004@aarenet1,180,M(dettagliChiamatoUscita^3c64394a57a8-8u0e813m9w','1','0','NO ANSWER','3','ast04t-1537186940.1452') [Sep 17 14:22:22] DEBUG[22294] devicestate.c: No provider found, checking channel drivers for PJSIP - kam_staging [Sep 17 14:22:22] DEBUG[22294] devicestate.c: Changing state for PJSIP/kam_staging - state 1 (Not in use) [Sep 17 14:22:22] DEBUG[22358] app_queue.c: Device 'PJSIP/kam_staging' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPj4190bcc9-0e7d-4bd5-86d3-c6c18a91e5eb From: ;tag=4e0ec0f6-eb93-4fd9-ba86-22a1ed100010 To: Contact: Call-ID: 231d8f2d-74c7-4f04-8387-8493cd51ba4f CSeq: 21641 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPja4fab9f1-52dc-4167-ab58-922b96c2d62f From: ;tag=60b217bf-b68a-48dd-bc14-34a02b300b52 To: Contact: Call-ID: f3a8dcea-e978-4767-ae66-80d4745946fc CSeq: 54371 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:22] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:22] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:22] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:22] VERBOSE[22306] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:212.183.160.236:5060 ---> OPTIONS sip:212.183.160.236:5060 SIP/2.0 Via: SIP/2.0/UDP 83.137.237.154:5060;rport;branch=z9hG4bKPje07b9575-83ce-41cc-a809-a4611705e514 From: ;tag=66a7aeb7-bb1a-4dfd-93a9-b2ed94fa8b78 To: Contact: Call-ID: 52293337-188c-4cf9-a6cc-700c81fd61b8 CSeq: 33707 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.21.1~qcom-1.1 Content-Length: 0 [Sep 17 14:22:23] DEBUG[22306] res_pjsip.c: 0x7fa39403aca0: PJSIP tsx timer expired [Sep 17 14:22:23] DEBUG[22306] res_pjsip.c: 0x7fa39403aca0: Timeout already handled [Sep 17 14:22:23] DEBUG[22306] res_pjsip.c: 0x7fa39403aca0: wrapper destroyed [Sep 17 14:22:23] DEBUG[22322] res_pjsip_registrar.c: Woke up at 1537186943 Interval: 30 [Sep 17 14:22:23] DEBUG[22322] res_pjsip_registrar.c: Expiring 0 contacts [Sep 17 14:22:24] DEBUG[22306] res_pjsip.c: 0x7fa3940559b0: Internal tsx timer expired after 3000 msec [Sep 17 14:22:24] DEBUG[22306] res_pjsip.c: 0x7fa3940559b0: Timer handled here [Sep 17 14:22:24] DEBUG[22306] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:24] DEBUG[22306] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:24] DEBUG[22306] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:24] DEBUG[22306] res_pjsip.c: 0x7fa3940559b0: Callbacks executed [Sep 17 14:22:24] DEBUG[4480] res_pjsip/pjsip_configuration.c: Contact kam_test_aor/sip:212.183.160.236:5060 status didn't change: Unreachable, RTT: 0.000 msec [Sep 17 14:22:24] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:24] DEBUG[22306] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.160.236' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port ''. [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:24] DEBUG[22306] netsock2.c: Splitting '212.183.160.236:5060' into... [Sep 17 14:22:24] DEBUG[22306] netsock2.c: ...host '212.183.160.236' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:25] DEBUG[22306] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:25] DEBUG[22306] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:25] DEBUG[22306] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000026 to use for Request msg OPTIONS/cseq=10 (rdata0x7fa3c80008e8) [Sep 17 14:22:25] DEBUG[29433] netsock2.c: Splitting '212.183.160.228' into... [Sep 17 14:22:25] DEBUG[29433] netsock2.c: ...host '212.183.160.228' and port ''. [Sep 17 14:22:25] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Source address 212.183.160.228:5060 matches identify 'kamailio_id' [Sep 17 14:22:25] DEBUG[29433] res_pjsip_endpoint_identifier_ip.c: Identify 'kamailio_id' SIP message matched to endpoint kamailio [Sep 17 14:22:25] DEBUG[29433] netsock2.c: Splitting '212.183.160.228' into... [Sep 17 14:22:25] DEBUG[29433] netsock2.c: ...host '212.183.160.228' and port ''. [Sep 17 14:22:25] DEBUG[29433] netsock2.c: Splitting '212.183.166.23:5060' into... [Sep 17 14:22:25] DEBUG[29433] netsock2.c: ...host '212.183.166.23' and port '5060'. [Sep 17 14:22:25] DEBUG[29433] netsock2.c: Splitting '212.183.160.228:5060' into... [Sep 17 14:22:25] DEBUG[29433] netsock2.c: ...host '212.183.160.228' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: inv_session 0x7fa394015988 has no ast session [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa38c0326a8) [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7fa38c062db8 [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: The current transaction state is Terminated [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: The transaction state change event is TIMER [Sep 17 14:22:25] DEBUG[22306] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 17 14:22:25] DEBUG[24181] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:25] DEBUG[24181] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:25] DEBUG[24181] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:25] DEBUG[24181] res_pjsip.c: 0x7fa39400e8d0: Wrapper created [Sep 17 14:22:25] DEBUG[24181] res_pjsip.c: 0x7fa39400e8d0: Set timer to 3000 msec [Sep 17 14:22:25] DEBUG[24181] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 83.137.237.154:5060 (this may be re-written again later) [Sep 17 14:22:25] DEBUG[24181] netsock2.c: Splitting '83.137.237.140' into... [Sep 17 14:22:25] DEBUG[24181] netsock2.c: ...host '83.137.237.140' and port ''. [Sep 17 14:22:25] DEBUG[24181] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [Sep 17 14:22:25] DEBUG[24181] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:25] DEBUG[24181] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:25] DEBUG[24181] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:25] DEBUG[24181] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] netsock2.c: Splitting '83.137.237.140:5060' into... [Sep 17 14:22:25] DEBUG[22306] netsock2.c: ...host '83.137.237.140' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] netsock2.c: Splitting '83.137.237.154:5060' into... [Sep 17 14:22:25] DEBUG[22306] netsock2.c: ...host '83.137.237.154' and port '5060'. [Sep 17 14:22:25] DEBUG[22306] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=483 (rdata0x7fa3c800eef8). Using request transaction as basis. [Sep 17 14:22:25] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa38c053908 for Response msg 200/OPTIONS/cseq=483 (rdata0x7fa3c800eef8). [Sep 17 14:22:25] DEBUG[22306] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-0000000d on transaction tsx0x7fa38c053908 [Sep 17 14:22:25] DEBUG[13408] res_pjsip.c: 0x7fa39400e8d0: PJSIP tsx response received [Sep 17 14:22:25] DEBUG[13408] res_pjsip.c: 0x7fa39400e8d0: Cancelling timer [Sep 17 14:22:25] DEBUG[13408] res_pjsip.c: 0x7fa39400e8d0: Timer cancelled [Sep 17 14:22:25] DEBUG[13408] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Sep 17 14:22:25] DEBUG[13408] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Sep 17 14:22:25] DEBUG[13408] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Sep 17 14:22:25] DEBUG[13408] res_pjsip.c: 0x7fa39400e8d0: Callbacks executed [Sep 17 14:22:25] DEBUG[13408] res_pjsip.c: 0x7fa39400e8d0: wrapper destroyed