Asterisk SVN-branch-1.4-r58906, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= == Parsing '/etc/asterisk/asterisk.conf': Found == Parsing '/etc/asterisk/extconfig.conf': Found Connected to Asterisk SVN-branch-1.4-r58906 currently running on asterisk (pid = 8762) asterisk*CLI> Verbosity is at least 4 Core debug is at least 4 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 26 [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 25 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 19 on 25/0 to 192.168.1.162:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00019ms SCall: 00025 DCall: 00000 [192.168.1.162:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00019ms SCall: 00429 DCall: 00025 [192.168.1.162:4569] [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 4) [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00019ms SCall: 00429 DCall: 00025 [192.168.1.162:4569] RR_JITTER : 0 [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 19 on 25/429 to 192.168.1.162:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00019ms SCall: 00025 DCall: 00429 [192.168.1.162:4569] [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:7110 socket_process: Peer 608: got pong, lastms 6, historicms 6, maxms 2000 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 27 [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 26 [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 28 [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 27 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 11 on 26/0 to 81.201.82.28:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00011ms SCall: 00026 DCall: 00000 [81.201.82.28:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 11 on 27/0 to 81.201.82.21:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00011ms SCall: 00027 DCall: 00000 [81.201.82.21:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00011ms SCall: 00002 DCall: 00026 [81.201.82.28:4569] [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 11 on 26/2 to 81.201.82.28:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00011ms SCall: 00026 DCall: 00002 [81.201.82.28:4569] [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:7110 socket_process: Peer 81.201.82.28: got pong, lastms 7, historicms 7, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00011ms SCall: 00002 DCall: 00027 [81.201.82.21:4569] [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 11 on 27/2 to 81.201.82.21:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00011ms SCall: 00027 DCall: 00002 [81.201.82.21:4569] [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.82.21: got pong, lastms 7, historicms 7, maxms 2000 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 29 [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:1258 find_callno: Creating new call structure 28 [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 40 [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:1258 find_callno: Creating new call structure 39 [Mar 15 17:59:39] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 41 [Mar 15 17:59:39] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 40 [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 42 [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 41 [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 43 [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 42 [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 44 [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:1258 find_callno: Creating new call structure 43 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 28/0 to 81.201.82.27:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00028 DCall: 00000 [81.201.82.27:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 39/0 to 81.201.82.25:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00039 DCall: 00000 [81.201.82.25:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 40/0 to 81.201.82.23:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00040 DCall: 00000 [81.201.82.23:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 4 on 41/0 to 81.201.82.22:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00004ms SCall: 00041 DCall: 00000 [81.201.82.22:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 4 on 42/0 to 81.201.82.26:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00004ms SCall: 00042 DCall: 00000 [81.201.82.26:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 4 on 43/0 to 81.201.82.24:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00004ms SCall: 00043 DCall: 00000 [81.201.82.24:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00003ms SCall: 00002 DCall: 00028 [81.201.82.27:4569] asterisk*CLI> [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 3 on 28/2 to 81.201.82.27:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00028 DCall: 00002 [81.201.82.27:4569] [Mar 15 17:59:39] DEBUG[8768]: chan_iax2.c:7110 socket_process: Peer 81.201.82.27: got pong, lastms 8, historicms 8, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00003ms SCall: 00003 DCall: 00039 [81.201.82.25:4569] [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:1650 send_packet: Sending 3 on 39/3 to 81.201.82.25:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00039 DCall: 00003 [81.201.82.25:4569] [Mar 15 17:59:39] DEBUG[8776]: chan_iax2.c:7110 socket_process: Peer 81.201.82.25: got pong, lastms 9, historicms 9, maxms 2000 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00003ms SCall: 00001 DCall: 00040 [81.201.82.23:4569] [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 3 on 40/1 to 81.201.82.23:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00040 DCall: 00001 [81.201.82.23:4569] [Mar 15 17:59:39] DEBUG[8772]: chan_iax2.c:7110 socket_process: Peer 81.201.82.23: got pong, lastms 9, historicms 9, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00004ms SCall: 00002 DCall: 00041 [81.201.82.22:4569] [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 4 on 41/2 to 81.201.82.22:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00004ms SCall: 00041 DCall: 00002 [81.201.82.22:4569] [Mar 15 17:59:39] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.82.22: got pong, lastms 9, historicms 9, maxms 2000 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00004ms SCall: 00003 DCall: 00042 [81.201.82.26:4569] [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 4 on 42/3 to 81.201.82.26:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00004ms SCall: 00042 DCall: 00003 [81.201.82.26:4569] [Mar 15 17:59:39] DEBUG[8775]: chan_iax2.c:7110 socket_process: Peer 81.201.82.26: got pong, lastms 9, historicms 9, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00004ms SCall: 00002 DCall: 00043 [81.201.82.24:4569] [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 4 on 43/2 to 81.201.82.24:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00004ms SCall: 00043 DCall: 00002 [81.201.82.24:4569] [Mar 15 17:59:39] DEBUG[8773]: chan_iax2.c:7110 socket_process: Peer 81.201.82.24: got pong, lastms 10, historicms 10, maxms 2000 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 53 [Mar 15 17:59:39] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 52 [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 54 [Mar 15 17:59:39] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 53 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 52/0 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00052 DCall: 00000 [85.119.188.2:4569] [Mar 15 17:59:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 53/0 to 80.92.86.39:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00053 DCall: 00000 [80.92.86.39:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00003ms SCall: 00006 DCall: 00052 [85.119.188.2:4569] [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:1650 send_packet: Sending 3 on 52/6 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00052 DCall: 00006 [85.119.188.2:4569] [Mar 15 17:59:39] DEBUG[8769]: chan_iax2.c:7110 socket_process: Peer 28889302: got pong, lastms 11, historicms 11, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00003ms SCall: 00229 DCall: 00053 [80.92.86.39:4569] [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 3 on 53/229 to 80.92.86.39:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00053 DCall: 00229 [80.92.86.39:4569] [Mar 15 17:59:39] DEBUG[8767]: chan_iax2.c:7110 socket_process: Peer pchretien: got pong, lastms 14, historicms 14, maxms 2000 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:39] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.5 with 192.168.1.0 asterisk*CLI> [Mar 15 17:59:39] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '1405038f557609372b3ba3302f0b80e4@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '1405038f557609372b3ba3302f0b80e4@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:40] DEBUG[8768]: chan_iax2.c:7694 iax2_do_register: Sending registration request for 'pchretien' [Mar 15 17:59:40] DEBUG[8768]: chan_iax2.c:7724 iax2_do_register: Allocate call number [Mar 15 17:59:40] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 30 [Mar 15 17:59:40] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 29 [Mar 15 17:59:40] DEBUG[8768]: chan_iax2.c:7730 iax2_do_register: Registration created on call 29 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 29/0 to 80.92.86.40:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ Timestamp: 00003ms SCall: 00029 DCall: 00000 [80.92.86.40:4569] USERNAME : pchretien REFRESH : 60 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00003ms SCall: 00204 DCall: 00029 [80.92.86.40:4569] [Mar 15 17:59:40] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 4) [Mar 15 17:59:40] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:40] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGACK Timestamp: 00019ms SCall: 00204 DCall: 00029 [80.92.86.40:4569] USERNAME : pchretien DATE TIME : 2007-03-15 17:59:34 REFRESH : 60 APPARENT ADDRES : IPV4 81.242.238.174:4569 MESSAGE COUNT : 0 [Mar 15 17:59:40] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 15) [Mar 15 17:59:40] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 15 received [Mar 15 17:59:40] DEBUG[8772]: chan_iax2.c:6697 socket_process: For call=29, set last=19 [Mar 15 17:59:40] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 19 on 29/204 to 80.92.86.40:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00019ms SCall: 00029 DCall: 00204 [80.92.86.40:4569] asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.161 with 192.168.1.0 [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.160 with 192.168.1.0 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '3b221a9a1271cb19617607df3997f7dd@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '3b221a9a1271cb19617607df3997f7dd@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '139d43ec2e68f8287b9962d41e7c7eff@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '139d43ec2e68f8287b9962d41e7c7eff@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '112e36dd28ed07b21396309248cc0456@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '112e36dd28ed07b21396309248cc0456@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5f38c4ce4f4232ec1c7e5e9261f3b76d@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '5f38c4ce4f4232ec1c7e5e9261f3b76d@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:40] DEBUG[8770]: chan_iax2.c:7694 iax2_do_register: Sending registration request for '28889302' [Mar 15 17:59:40] DEBUG[8770]: chan_iax2.c:7724 iax2_do_register: Allocate call number [Mar 15 17:59:40] DEBUG[8770]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 31 [Mar 15 17:59:40] DEBUG[8770]: chan_iax2.c:1258 find_callno: Creating new call structure 30 [Mar 15 17:59:40] DEBUG[8770]: chan_iax2.c:7730 iax2_do_register: Registration created on call 30 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 15 on 30/0 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ Timestamp: 00015ms SCall: 00030 DCall: 00000 [85.119.188.2:4569] USERNAME : 28889302 REFRESH : 60 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH asterisk*CLI> Timestamp: 00007ms SCall: 00005 DCall: 00030 [85.119.188.2:4569] asterisk*CLI> AUTHMETHODS : 3 asterisk*CLI> CHALLENGE : 189168059 asterisk*CLI> USERNAME : 28889302 asterisk*CLI> asterisk*CLI> [Mar 15 17:59:40] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 14) asterisk*CLI> [Mar 15 17:59:40] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 14 received asterisk*CLI> [Mar 15 17:59:40] DEBUG[8775]: chan_iax2.c:6697 socket_process: For call=30, set last=7 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 34 on 30/5 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ Timestamp: 00034ms SCall: 00030 DCall: 00005 [85.119.188.2:4569] USERNAME : 28889302 REFRESH : 60 MD5 RESULT : 22322a2c60d8f7bd33b41a084342dfc6 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK asterisk*CLI> Timestamp: 00033ms SCall: 00005 DCall: 00030 [85.119.188.2:4569] asterisk*CLI> USERNAME : 28889302 asterisk*CLI> DATE TIME : 2007-03-15 17:59:34 asterisk*CLI> REFRESH : 60 asterisk*CLI> APPARENT ADDRES : IPV4 81.242.238.174:4569 asterisk*CLI> asterisk*CLI> [Mar 15 17:59:40] DEBUG[8773]: chan_iax2.c:6494 socket_process: Received packet 1, (6, 15) asterisk*CLI> [Mar 15 17:59:40] DEBUG[8773]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 1 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8773]: chan_iax2.c:6688 socket_process: IAX subclass 15 received asterisk*CLI> [Mar 15 17:59:40] DEBUG[8773]: chan_iax2.c:6697 socket_process: For call=30, set last=33 asterisk*CLI> [Mar 15 17:59:40] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 33 on 30/5 to 85.119.188.2:4569 asterisk*CLI> Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK asterisk*CLI> Timestamp: 00033ms SCall: 00030 DCall: 00005 [85.119.188.2:4569] asterisk*CLI> [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 36 [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 35 [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 37 [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 36 [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 38 [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 37 [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 45 [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 44 [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 46 [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:1258 find_callno: Creating new call structure 45 [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 47 [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:1258 find_callno: Creating new call structure 46 [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 48 [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:1258 find_callno: Creating new call structure 47 [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 49 [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:1258 find_callno: Creating new call structure 48 [Mar 15 17:59:41] DEBUG[8773]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 50 [Mar 15 17:59:41] DEBUG[8773]: chan_iax2.c:1258 find_callno: Creating new call structure 49 asterisk*CLI> [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 7 on 35/0 to 81.201.84.29:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00007ms SCall: 00035 DCall: 00000 [81.201.84.29:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 7 on 36/0 to 81.201.84.26:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00007ms SCall: 00036 DCall: 00000 [81.201.84.26:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 37/0 to 81.201.84.28:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00037 DCall: 00000 [81.201.84.28:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 44/0 to 81.201.84.27:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00044 DCall: 00000 [81.201.84.27:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 45/0 to 81.201.84.25:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00045 DCall: 00000 [81.201.84.25:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 46/0 to 81.201.84.21:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00046 DCall: 00000 [81.201.84.21:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 47/0 to 81.201.84.23:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00047 DCall: 00000 [81.201.84.23:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 8 on 48/0 to 81.201.84.22:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00008ms SCall: 00048 DCall: 00000 [81.201.84.22:4569] [Mar 15 17:59:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 9 on 49/0 to 81.201.84.24:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00009ms SCall: 00049 DCall: 00000 [81.201.84.24:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00007ms SCall: 00003 DCall: 00035 [81.201.84.29:4569] [Mar 15 17:59:41] DEBUG[8771]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8771]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8771]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8771]: chan_iax2.c:1650 send_packet: Sending 7 on 35/3 to 81.201.84.29:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00007ms SCall: 00035 DCall: 00003 [81.201.84.29:4569] [Mar 15 17:59:41] DEBUG[8771]: chan_iax2.c:7110 socket_process: Peer 81.201.84.29: got pong, lastms 89, historicms 89, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00007ms SCall: 00002 DCall: 00036 [81.201.84.26:4569] [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 7 on 36/2 to 81.201.84.26:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00007ms SCall: 00036 DCall: 00002 [81.201.84.26:4569] [Mar 15 17:59:41] DEBUG[8774]: chan_iax2.c:7110 socket_process: Peer 81.201.84.26: got pong, lastms 89, historicms 89, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00008ms SCall: 00004 DCall: 00037 [81.201.84.28:4569] [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:1650 send_packet: Sending 8 on 37/4 to 81.201.84.28:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00037 DCall: 00004 [81.201.84.28:4569] [Mar 15 17:59:41] DEBUG[8769]: chan_iax2.c:7110 socket_process: Peer 81.201.84.28: got pong, lastms 89, historicms 89, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00008ms SCall: 00004 DCall: 00044 [81.201.84.27:4569] [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 8 on 44/4 to 81.201.84.27:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00044 DCall: 00004 [81.201.84.27:4569] [Mar 15 17:59:41] DEBUG[8768]: chan_iax2.c:7110 socket_process: Peer 81.201.84.27: got pong, lastms 90, historicms 90, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00008ms SCall: 00001 DCall: 00045 [81.201.84.25:4569] [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:1650 send_packet: Sending 8 on 45/1 to 81.201.84.25:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00045 DCall: 00001 [81.201.84.25:4569] [Mar 15 17:59:41] DEBUG[8776]: chan_iax2.c:7110 socket_process: Peer 81.201.84.25: got pong, lastms 90, historicms 90, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00008ms SCall: 00002 DCall: 00047 [81.201.84.23:4569] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG asterisk*CLI> [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 8 on 47/2 to 81.201.84.23:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00047 DCall: 00002 [81.201.84.23:4569] [Mar 15 17:59:41] DEBUG[8772]: chan_iax2.c:7110 socket_process: Peer 81.201.84.23: got pong, lastms 91, historicms 91, maxms 2000 Timestamp: 00008ms SCall: 00004 DCall: 00046 [81.201.84.21:4569] [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 8 on 46/4 to 81.201.84.21:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00046 DCall: 00004 [81.201.84.21:4569] [Mar 15 17:59:41] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.84.21: got pong, lastms 92, historicms 92, maxms 2000 asterisk*CLI> Timestamp: 00008ms SCall: 00004 DCall: 00048 [81.201.84.22:4569] [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 8 on 48/4 to 81.201.84.22:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00008ms SCall: 00048 DCall: 00004 [81.201.84.22:4569] [Mar 15 17:59:41] DEBUG[8775]: chan_iax2.c:7110 socket_process: Peer 81.201.84.22: got pong, lastms 92, historicms 92, maxms 2000 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00009ms SCall: 00004 DCall: 00049 [81.201.84.24:4569] [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 9 on 49/4 to 81.201.84.24:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00009ms SCall: 00049 DCall: 00004 [81.201.84.24:4569] [Mar 15 17:59:41] DEBUG[8767]: chan_iax2.c:7110 socket_process: Peer 81.201.84.24: got pong, lastms 92, historicms 92, maxms 2000 asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.28 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.28 is not local, substituting externip [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.20 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.20 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '15b355bb71d7d5b9422e65a7700273ff@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '15b355bb71d7d5b9422e65a7700273ff@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '51e0ca12091fd7933d78f2ce1b1f45df@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '51e0ca12091fd7933d78f2ce1b1f45df@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.26 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.26 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '23d3902d048057cb4f880f9957432cd5@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '23d3902d048057cb4f880f9957432cd5@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.25 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.25 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4e37ff2d51190c553edd8a4644f3f9f2@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '4e37ff2d51190c553edd8a4644f3f9f2@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.24 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.24 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6853dcff143ed1db615bd944547f11b6@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '6853dcff143ed1db615bd944547f11b6@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.23 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.23 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0c44a41d493ca9925bec00ff6db8eca2@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '0c44a41d493ca9925bec00ff6db8eca2@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.22 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.22 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7f09846f591d8f406927f491570fe261@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '7f09846f591d8f406927f491570fe261@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.21 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.21 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5559e1df5694d46923b7b5f82e9419b4@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '5559e1df5694d46923b7b5f82e9419b4@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 85.119.188.3 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 85.119.188.3 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2239d6ef40342a456db21bed16d34cfc@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '2239d6ef40342a456db21bed16d34cfc@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 85.119.188.3 with 192.168.1.0 [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 85.119.188.3 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '15a880b657ee4d1b3d29c6fe23cd41ed@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '15a880b657ee4d1b3d29c6fe23cd41ed@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 65cc425a71d19327729bc4d40accd399@81.242.238.174 Really destroying SIP dialog '65cc425a71d19327729bc4d40accd399@81.242.238.174' Method: OPTIONS [Mar 15 17:59:42] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.33 [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 48cc77d06c1fa1154d5770d14aa293b4@81.242.238.174 Really destroying SIP dialog '48cc77d06c1fa1154d5770d14aa293b4@81.242.238.174' Method: OPTIONS [Mar 15 17:59:42] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.32 [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 25a3db0b5e72538d69caed8d25fb4845@81.242.238.174 Really destroying SIP dialog '25a3db0b5e72538d69caed8d25fb4845@81.242.238.174' Method: OPTIONS [Mar 15 17:59:42] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.31 [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 2817fd5d2238141e6502e718359e6cea@81.242.238.174 Really destroying SIP dialog '2817fd5d2238141e6502e718359e6cea@81.242.238.174' Method: OPTIONS [Mar 15 17:59:42] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.30 [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 328bbd1142ecb2906d8ebf425f89d911@81.242.238.174 Really destroying SIP dialog '328bbd1142ecb2906d8ebf425f89d911@81.242.238.174' Method: OPTIONS [Mar 15 17:59:42] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.29 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.33 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.33 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.33 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.32 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.32 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.32 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.31 asterisk*CLI> [Mar 15 17:59:42] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.31 [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.31 - state 1 (Not in use) [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.30 [Mar 15 17:59:42] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.30 [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.30 - state 1 (Not in use) [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.29 [Mar 15 17:59:42] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.29 [Mar 15 17:59:42] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.29 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:42] DEBUG[9297]: app_queue.c:546 changethread: Device 'SIP/81.201.82.33' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:42] DEBUG[9298]: app_queue.c:546 changethread: Device 'SIP/81.201.82.32' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:42] DEBUG[9299]: app_queue.c:546 changethread: Device 'SIP/81.201.82.31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:42] DEBUG[9300]: app_queue.c:546 changethread: Device 'SIP/81.201.82.30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:42] DEBUG[9301]: app_queue.c:546 changethread: Device 'SIP/81.201.82.29' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:42] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 194.120.0.193 with 192.168.1.0 [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 194.120.0.193 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:42] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '368f666d0555d774767ba5282c38e3a7@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '368f666d0555d774767ba5282c38e3a7@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 17:59:43] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 10019 on 1/0 to 81.201.84.34:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: LAGRQ Timestamp: 10019ms SCall: 00001 DCall: 00000 [81.201.84.34:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00017ms SCall: 00007 DCall: 00000 [85.119.188.2:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (ulaw|alaw|slin|gsm|g726|adpcm|lpc10|speex|ilbc|g729) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 LANGUAGE : en USERNAME : 28889302 FORMAT : 64 CAPABILITY : 65534 ADSICPE : 0 DATE TIME : 2007-03-15 17:59:38 [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 16 [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 15 [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 1) [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:6688 socket_process: IAX subclass 1 received [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:6697 socket_process: For call=15, set last=17 [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 17 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] asterisk*CLI> [Mar 15 17:59:44] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 5 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00005ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] AUTHMETHODS : 2 CHALLENGE : 124366572 USERNAME : 28889302 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00035ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] MD5 RESULT : 8c5a2db8d6750193ed784c3c462408ad [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 1, (6, 9) [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 9 received [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:6697 socket_process: For call=15, set last=35 [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 35 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00035ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] -- Accepting AUTHENTICATED call from 85.119.188.2: > requested format = slin, > requested prefs = (ulaw|alaw|slin|gsm|g726|adpcm|lpc10|speex|ilbc|g729), > actual format = g729, > host prefs = (g729|ulaw|alaw|ilbc|gsm), > priority = mine asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'Macro' asterisk*CLI> -- Executing [s@incoming:1] Macro("IAX2/28889302-15", "reception_appel") in new stack asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'Answer' asterisk*CLI> -- Executing [s@macro-reception_appel:1] Answer("IAX2/28889302-15", "") in new stack asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:3183 iax2_answer: Answering IAX2 call asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/28889302-15 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 28889302 [Mar 15 17:59:44] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 28889302 [Mar 15 17:59:44] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 28889302? addr=45905749, defaddr=0 maxms=2000, lastms=11 [Mar 15 17:59:44] DEBUG[8765]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x819f688' asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0473883858' asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' asterisk*CLI> -- Executing [s@macro-reception_appel:2] NoOp("IAX2/28889302-15", "Incoming call from 0473883858") in new stack asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'Set' asterisk*CLI> -- Executing [s@macro-reception_appel:3] Set("IAX2/28889302-15", "TIMEOUT(digit)=5") in new stack asterisk*CLI> -- Digit timeout set to 5 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'Set' asterisk*CLI> -- Executing [s@macro-reception_appel:4] Set("IAX2/28889302-15", "TIMEOUT(response)=20") in new stack asterisk*CLI> -- Response timeout set to 20 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'BackGround' asterisk*CLI> -- Executing [s@macro-reception_appel:5] BackGround("IAX2/28889302-15", "user_defined/bienvenue") in new stack asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: channel.c:2845 set_format: Set channel IAX2/28889302-15 to write format gsm asterisk*CLI> -- Playing 'user_defined/bienvenue' (language 'fr') asterisk*CLI> [Mar 15 17:59:44] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/28889302 - state 2 (In use) asterisk*CLI> [Mar 15 17:59:44] DEBUG[9303]: app_queue.c:546 changethread: Device 'IAX2/28889302' changed to state '2' (In use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:44] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 22 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00022ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] FORMAT : 256 [Mar 15 17:59:44] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 25 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER Timestamp: 00025ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] [Mar 15 17:59:44] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 40 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: VOICE Subclass: 136 Timestamp: 00040ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00022ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:44] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 2, (6, 4) [Mar 15 17:59:44] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 1 [Mar 15 17:59:44] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00025ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:44] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 2, (6, 4) [Mar 15 17:59:44] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 2 [Mar 15 17:59:44] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00040ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:44] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 2, (6, 4) [Mar 15 17:59:44] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 3 [Mar 15 17:59:44] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: VOICE Subclass: 136 Timestamp: 00080ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:44] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 2, (2, 256) [Mar 15 17:59:44] DEBUG[8775]: chan_iax2.c:6647 socket_process: Ooh, voice format changed to 256 [Mar 15 17:59:44] DEBUG[8775]: channel.c:2845 set_format: Set channel IAX2/28889302-15 to read format g729 [Mar 15 17:59:44] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 80 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00080ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] asterisk*CLI> [Mar 15 17:59:44] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=80 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 60 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=100 [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 80 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=120 [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=140 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=160 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=180 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=200 [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=220 [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:44] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=240 asterisk*CLI> [Mar 15 17:59:44] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=260 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=280 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=300 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=320 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 300 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=340 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 320 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=360 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 340 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=380 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 360 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=400 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 380 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=420 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 400 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=440 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 420 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=460 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 440 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=480 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 460 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=500 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 480 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=520 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 500 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=540 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 520 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=560 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 540 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=580 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 560 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=600 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 580 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=620 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 600 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=640 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 620 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=660 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 640 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=680 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 660 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=700 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 680 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=720 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 700 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=740 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 720 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=760 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 740 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=780 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 760 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=800 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 780 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=820 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 800 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=840 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 820 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=860 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 840 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=880 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 860 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=900 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 880 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=920 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 900 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=940 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 920 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=960 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 940 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=980 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 960 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=1000 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 980 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=1020 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1000 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=1040 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1020 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=1060 asterisk*CLI> [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1040 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=1080 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1060 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=1100 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1080 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=1120 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=1140 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=1160 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=1180 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=1200 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=1220 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:45] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=1240 [Mar 15 17:59:45] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=1260 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=1280 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=1300 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=1320 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1300 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=1340 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1320 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=1360 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1340 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=1380 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1360 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=1400 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1380 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=1420 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1400 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=1440 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1420 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=1460 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1440 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=1480 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1460 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=1500 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1480 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=1520 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1500 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=1540 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1520 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=1560 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1540 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=1580 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1560 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=1600 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1580 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=1620 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1600 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=1640 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1620 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=1660 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1640 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=1680 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1660 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=1700 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1680 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=1720 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1700 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=1740 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1720 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=1760 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1740 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=1780 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1760 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=1800 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1780 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=1820 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1800 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=1840 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1820 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=1860 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1840 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=1880 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1860 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=1900 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1880 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=1920 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1900 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=1940 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1920 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=1960 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1940 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=1980 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1960 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=2000 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 1980 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2020 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2000 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2040 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2020 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2060 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2040 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=2080 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2060 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=2100 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2080 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=2120 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2140 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2160 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=2180 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2200 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=2220 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:46] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=2240 [Mar 15 17:59:46] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=2260 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=2280 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=2300 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=2320 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2300 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2340 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2320 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2360 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2340 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=2380 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2360 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2400 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2380 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=2420 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2400 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=2440 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2420 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=2460 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2440 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=2480 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2460 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=2500 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2480 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=2520 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2500 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2520 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2540 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2560 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2540 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=2580 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2560 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2600 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2580 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=2620 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2600 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=2640 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2620 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=2660 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2640 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=2680 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2660 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=2700 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2680 on 15/7 to 85.119.188.2:4569 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF_E Subclass: 4 Timestamp: 02683ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 3, (1, 52) [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 2683 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 02683ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:7582 socket_process: Received out of order packet... (type=1, subclass 52, ts = 2683, last = 2700) asterisk*CLI> [Mar 15 17:59:47] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2720 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2700 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2740 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2720 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=2760 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2740 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2780 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2760 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=2800 asterisk*CLI> [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2780 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=2820 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2800 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=2840 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2820 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=2860 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2840 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=2880 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2860 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=2900 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2880 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=2920 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2900 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=2940 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2920 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=2960 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2940 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=2980 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2960 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3000 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 2980 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=3020 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3000 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=3040 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3020 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=3060 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3040 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=3080 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3060 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=3100 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3080 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=3120 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=3140 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=3160 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=3180 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3200 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=3220 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:47] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=3240 [Mar 15 17:59:47] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=3260 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=3280 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=3300 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=3320 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3300 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=3340 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3320 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=3360 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3340 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=3380 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3360 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3400 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3380 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=3420 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3400 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=3440 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3420 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=3460 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3440 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=3480 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3460 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=3500 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3480 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=3520 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3500 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=3540 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3520 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=3560 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3540 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=3580 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3560 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3600 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3580 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=3620 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3600 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=3640 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3620 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=3660 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3640 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=3680 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3660 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=3700 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3680 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=3720 asterisk*CLI> [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3700 on 15/7 to 85.119.188.2:4569 Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: DTMF_E Subclass: 5 Timestamp: 03703ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:6494 socket_process: Received packet 4, (1, 53) [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:1650 send_packet: Sending 3703 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 03703ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:7582 socket_process: Received out of order packet... (type=1, subclass 53, ts = 3703, last = 3720) asterisk*CLI> [Mar 15 17:59:48] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=3740 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3720 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=3760 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3740 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3780 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3760 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=3800 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3780 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=3820 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3800 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=3840 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3820 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=3860 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3840 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=3880 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3860 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=3900 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3880 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=3920 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3900 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=3940 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3920 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=3960 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3940 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=3980 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3960 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4000 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 3980 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=4020 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4000 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=4040 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4020 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=4060 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4040 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=4080 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4060 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=4100 asterisk*CLI> [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4080 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=4120 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=4140 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=4160 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=4180 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4200 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=4220 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:48] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=4240 [Mar 15 17:59:48] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=4260 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=4280 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=4300 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=4320 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4300 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=4340 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4320 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=4360 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4340 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=4380 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4360 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4400 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4380 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=4420 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4400 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=4440 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4420 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=4460 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4440 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=4480 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4460 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=4500 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4480 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=4520 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4500 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=4540 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4520 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=4560 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4540 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=4580 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4560 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4600 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4580 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=4620 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4600 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=4640 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4620 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=4660 asterisk*CLI> [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4640 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=4680 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4660 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=4700 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4680 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=4720 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4700 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=4740 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4720 on 15/7 to 85.119.188.2:4569 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: DTMF_E Subclass: 6 Timestamp: 04723ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 5, (1, 54) [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 4723 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX Subclass: ACK Timestamp: 04723ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:7582 socket_process: Received out of order packet... (type=1, subclass 54, ts = 4723, last = 4740) asterisk*CLI> [Mar 15 17:59:49] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=4760 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4740 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4780 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4760 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=4800 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4780 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=4820 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4800 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=4840 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4820 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=4860 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4840 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=4880 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4860 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=4900 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4880 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=4920 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4900 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=4940 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4920 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=4960 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4940 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=4980 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4960 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5000 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 4980 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5020 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5000 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=5040 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5020 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=5060 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5040 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=5080 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5060 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=5100 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5080 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=5120 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5100 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=5140 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5120 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=5160 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5140 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=5180 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5160 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5200 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5180 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5220 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5200 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:49] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=5240 [Mar 15 17:59:49] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5220 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=5260 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5240 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=5280 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5260 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=5300 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1650 send_packet: Sending 5280 on 15/7 to 85.119.188.2:4569 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=5320 [Mar 15 17:59:50] DEBUG[9302]: channel.c:2845 set_format: Set channel IAX2/28889302-15 to write format g729 [Mar 15 17:59:50] DEBUG[9302]: pbx.c:1791 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-reception_appel:6] Dial("IAX2/28889302-15", "SIP/600&SIP/601&IAX2/606&IAX2/607&IAX2/608&SIP/610&SIP/611|60|TtrHg") in new stack [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:59:50] DEBUG[9302]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3805 sip_new: *** Our native formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. asterisk*CLI> [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1558 ast_rtp_make_compatible: Channel 'IAX2/28889302-15' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2830 sip_call: Outgoing Call for 600 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6188 add_sdp: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: False [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) -- Called 600 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:59:50] DEBUG[9302]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3805 sip_new: *** Our native formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1558 ast_rtp_make_compatible: Channel 'IAX2/28889302-15' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2830 sip_call: Outgoing Call for 601 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6188 add_sdp: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: False [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) -- Called 601 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 17 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1258 find_callno: Creating new call structure 16 [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1551 ast_rtp_make_compatible: Channel 'IAX2/606-16' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. asterisk*CLI> [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/606-16 -- Called 606 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 18 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1258 find_callno: Creating new call structure 17 [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1551 ast_rtp_make_compatible: Channel 'IAX2/607-17' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/607-17 -- Called 607 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 22 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:1258 find_callno: Creating new call structure 21 [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1551 ast_rtp_make_compatible: Channel 'IAX2/608-21' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/608-21 -- Called 608 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:59:50] DEBUG[9302]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.160 with 192.168.1.0 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3805 sip_new: *** Our native formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1558 ast_rtp_make_compatible: Channel 'IAX2/28889302-15' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2830 sip_call: Outgoing Call for 610 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6188 add_sdp: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: False [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) -- Called 610 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:59:50] DEBUG[9302]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.161 with 192.168.1.0 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3805 sip_new: *** Our native formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 17:59:50] DEBUG[9302]: rtp.c:1558 ast_rtp_make_compatible: Channel 'IAX2/28889302-15' has no RTP, not doing anything [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-6. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-5. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-4. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-3. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-2. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-reception_appel-s-1. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 15 17:59:50] DEBUG[9302]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2830 sip_call: Outgoing Call for 611 [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6188 add_sdp: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: False [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:59:50] DEBUG[9302]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) -- Called 611 [Mar 15 17:59:50] DEBUG[9302]: chan_iax2.c:3194 iax2_indicate: Indicating condition 3 [Mar 15 17:59:50] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 15 on 16/0 to 192.168.1.20:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00015ms SCall: 00016 DCall: 00000 [192.168.1.20:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (ulaw|alaw|ilbc|gsm) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : LANGUAGE : fr FORMAT : 2 CAPABILITY : 58382 ADSICPE : 2 DATE TIME : 2007-03-15 17:59:50 [Mar 15 17:59:50] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 16 on 17/0 to 192.168.1.12:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW asterisk*CLI> Timestamp: 00016ms SCall: 00017 DCall: 00000 [192.168.1.12:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (ulaw|alaw|ilbc|gsm) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : LANGUAGE : fr FORMAT : 2 CAPABILITY : 58382 ADSICPE : 2 DATE TIME : 2007-03-15 17:59:50 [Mar 15 17:59:50] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 17 on 21/0 to 192.168.1.162:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00017ms SCall: 00021 DCall: 00000 [192.168.1.162:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (g729|ulaw|alaw|ilbc|gsm) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : LANGUAGE : fr FORMAT : 256 CAPABILITY : 58638 ADSICPE : 2 DATE TIME : 2007-03-15 17:59:50 [Mar 15 17:59:50] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 5283 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 006 Type: CONTROL Subclass: RINGING Timestamp: 05283ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 606 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 606 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 606? addr=335653056, defaddr=0 maxms=2000, lastms=0 [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/606 - state 6 (Ringing) [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d408d0158416210251a0cd934211d4a@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 607 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 607 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 607? addr=201435328, defaddr=0 maxms=2000, lastms=0 [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/607 - state 6 (Ringing) [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 608 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 608 [Mar 15 17:59:50] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 608? addr=-1576949568, defaddr=0 maxms=2000, lastms=6 [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/608 - state 6 (Ringing) asterisk*CLI> [Mar 15 17:59:50] DEBUG[9304]: app_queue.c:546 changethread: Device 'IAX2/606' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[9305]: app_queue.c:546 changethread: Device 'IAX2/607' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[9306]: app_queue.c:546 changethread: Device 'IAX2/608' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d408d0158416210251a0cd934211d4a@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 101 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=5340 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 05283ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 6, (6, 4) [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 4 [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7' Request 102: Found asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7' Request 102: Found asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/610-08201890 asterisk*CLI> -- SIP/610-08201890 is ringing asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 610 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 610 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/610 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:50] DEBUG[9307]: app_queue.c:546 changethread: Device 'SIP/610' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7' Request 102: Found asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/611-082057f8 asterisk*CLI> -- SIP/611-082057f8 is ringing asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 611 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 611 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/611 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:50] DEBUG[9308]: app_queue.c:546 changethread: Device 'SIP/611' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 101 to standard invite asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 00430 DCall: 00021 [192.168.1.162:4569] [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 4) [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> [Mar 15 17:59:50] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5360 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d408d0158416210251a0cd934211d4a@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Mar 15 17:59:50] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/600-081f5658 asterisk*CLI> -- SIP/600-081f5658 is ringing asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 600 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 600 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/600 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:50] DEBUG[9309]: app_queue.c:546 changethread: Device 'SIP/600' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' Request 102: Found [Mar 15 17:59:50] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Mar 15 17:59:50] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/601-081fd928 asterisk*CLI> -- SIP/601-081fd928 is ringing asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 601 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 601 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/601 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:50] DEBUG[9310]: app_queue.c:546 changethread: Device 'SIP/601' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:50] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5380 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=5400 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=5420 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=5440 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=5460 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=5480 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=5500 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=5520 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=5540 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5560 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5580 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=5600 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=5620 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=5640 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=5660 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=5680 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=5700 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=5720 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=5740 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5760 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5780 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=5800 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=5820 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=5840 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=5860 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=5880 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=5900 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=5920 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=5940 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=5960 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=5980 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6000 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6020 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=6040 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=6060 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=6080 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=6100 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=6120 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=6140 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=6160 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=6180 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6200 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6220 asterisk*CLI> [Mar 15 17:59:50] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=6240 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=6260 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=6280 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=6300 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=6320 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=6340 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=6360 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=6380 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6400 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6420 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=6440 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=6460 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACCEPT Timestamp: 01000ms SCall: 00430 DCall: 00021 [192.168.1.162:4569] FORMAT : 256 [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 7) [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:6688 socket_process: IAX subclass 7 received [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:6697 socket_process: For call=21, set last=1000 -- Call accepted by 192.168.1.162 (format g729) -- Format for call is g729 [Mar 15 17:59:51] DEBUG[8774]: channel.c:2845 set_format: Set channel IAX2/608-21 to write format g729 [Mar 15 17:59:51] DEBUG[8774]: channel.c:2845 set_format: Set channel IAX2/608-21 to read format g729 [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 1000 on 21/430 to 192.168.1.162:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 01000ms SCall: 00021 DCall: 00430 [192.168.1.162:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass: RINGING Timestamp: 01000ms SCall: 00430 DCall: 00021 [192.168.1.162:4569] [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 1, (4, 3) [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 1000 on 21/430 to 192.168.1.162:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 01000ms SCall: 00021 DCall: 00430 [192.168.1.162:4569] [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:7582 socket_process: Received out of order packet... (type=4, subclass 3, ts = 1000, last = 1000) asterisk*CLI> -- IAX2/608-21 is ringing asterisk*CLI> [Mar 15 17:59:51] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=6480 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=6500 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=6520 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=6540 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6560 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6580 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=6600 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=6620 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=6640 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=6660 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=6680 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=6700 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=6720 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=6740 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6760 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6780 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=6800 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=6820 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=6840 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=6860 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=6880 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=6900 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=6920 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=6940 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=6960 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=6980 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=7000 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=7020 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=7040 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=7060 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=7080 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=7100 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8776]: chan_iax2.c:7593 socket_process: For call=15, set last=7120 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8775]: chan_iax2.c:7593 socket_process: For call=15, set last=7140 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8770]: chan_iax2.c:7593 socket_process: For call=15, set last=7160 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8767]: chan_iax2.c:7593 socket_process: For call=15, set last=7180 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8773]: chan_iax2.c:7593 socket_process: For call=15, set last=7200 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8771]: chan_iax2.c:7593 socket_process: For call=15, set last=7220 asterisk*CLI> [Mar 15 17:59:51] DEBUG[8774]: chan_iax2.c:7593 socket_process: For call=15, set last=7240 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8768]: chan_iax2.c:7593 socket_process: For call=15, set last=7260 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8769]: chan_iax2.c:7593 socket_process: For call=15, set last=7280 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8772]: chan_iax2.c:7593 socket_process: For call=15, set last=7300 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX Subclass: HANGUP Timestamp: 07320ms SCall: 00007 DCall: 00015 [85.119.188.2:4569] CAUSE CODE : 16 [Mar 15 17:59:52] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 6, (6, 5) [Mar 15 17:59:52] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 5 received [Mar 15 17:59:52] DEBUG[8776]: chan_iax2.c:6697 socket_process: For call=15, set last=7320 [Mar 15 17:59:52] DEBUG[8776]: chan_iax2.c:6942 socket_process: Immediately destroying 15, having received hangup [Mar 15 17:59:52] DEBUG[8776]: chan_iax2.c:1650 send_packet: Sending 7320 on 15/7 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 007 Type: IAX Subclass: ACK Timestamp: 07320ms SCall: 00015 DCall: 00007 [85.119.188.2:4569] asterisk*CLI> [Mar 15 17:59:52] DEBUG[9302]: rtp.c:1468 ast_rtp_early_bridge: Channel 'IAX2/28889302-15' has no RTP, not doing anything [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/611-082057f8' [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3312 sip_hangup: Hangup call SIP/611-082057f8, SIP callid 39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3335 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7' of Request 102: Match Not Found [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/611-082057f8 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/610-08201890' [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3312 sip_hangup: Hangup call SIP/610-08201890, SIP callid 15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3335 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7' of Request 102: Match Not Found [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/610-08201890 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'IAX2/608-21' [Mar 15 17:59:52] DEBUG[9302]: chan_iax2.c:2940 iax2_hangup: We're hanging up IAX2/608-21 now... -- Hungup 'IAX2/608-21' [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/608-21 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'IAX2/607-17' [Mar 15 17:59:52] DEBUG[9302]: chan_iax2.c:2940 iax2_hangup: We're hanging up IAX2/607-17 now... -- Hungup 'IAX2/607-17' [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/607-17 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'IAX2/606-16' [Mar 15 17:59:52] DEBUG[9302]: chan_iax2.c:2940 iax2_hangup: We're hanging up IAX2/606-16 now... -- Hungup 'IAX2/606-16' [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/606-16 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/601-081fd928' [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3312 sip_hangup: Hangup call SIP/601-081fd928, SIP callid 044b789d59a55a7c303a2ee553f1e4de@192.168.1.7) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3335 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' of Request 102: Match Not Found [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/601-081fd928 [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/600-081f5658' [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3312 sip_hangup: Hangup call SIP/600-081f5658, SIP callid 7d408d0158416210251a0cd934211d4a@192.168.1.7) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:3335 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:59:52] DEBUG[9302]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7d408d0158416210251a0cd934211d4a@192.168.1.7' of Request 102: Match Not Found [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/600-081f5658 [Mar 15 17:59:52] DEBUG[9302]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Mar 15 17:59:52] DEBUG[9302]: app_macro.c:261 _macro_exec: Spawn extension (macro-reception_appel,s,6) exited non-zero on 'IAX2/28889302-15' in macro 'reception_appel' asterisk*CLI> [Mar 15 17:59:52] DEBUG[9302]: pbx.c:2389 __ast_pbx_run: Spawn extension (macro-reception_appel,s,6) exited non-zero on 'IAX2/28889302-15' == Spawn extension (macro-reception_appel, s, 6) exited non-zero on 'IAX2/28889302-15' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0473883858' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0473883858' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 's' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'incoming' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'IAX2/28889302-15' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/611-082057f8' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'Dial' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/600&SIP/601&IAX2/606&IAX2/607&IAX2/608&SIP/610&SIP/611|60|TtrHg' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:59:44' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:59:44' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:59:52' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '8' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '8' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1173977984.8' [Mar 15 17:59:52] DEBUG[9302]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' asterisk*CLI> [Mar 15 17:59:52] DEBUG[9302]: channel.c:1693 ast_hangup: Hanging up channel 'IAX2/28889302-15' [Mar 15 17:59:52] DEBUG[9302]: chan_iax2.c:2940 iax2_hangup: We're hanging up IAX2/28889302-15 now... [Mar 15 17:59:52] DEBUG[9302]: chan_iax2.c:2950 iax2_hangup: Really destroying IAX2/28889302-15 now... asterisk*CLI> [Mar 15 17:59:52] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 2012 on 21/430 to 192.168.1.162:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: HANGUP Timestamp: 02012ms SCall: 00021 DCall: 00430 [192.168.1.162:4569] CAUSE CODE : 0 [Mar 15 17:59:52] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 2012 on 17/0 to 192.168.1.12:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP Timestamp: 02012ms SCall: 00017 DCall: 00000 [192.168.1.12:4569] CAUSE CODE : 0 [Mar 15 17:59:52] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 2012 on 16/0 to 192.168.1.20:4569 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP Timestamp: 02012ms SCall: 00016 DCall: 00000 [192.168.1.20:4569] CAUSE CODE : 0 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: -- Hungup 'IAX2/28889302-15' asterisk*CLI> No provider found, checking channel drivers for SIP - 611 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 611 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/611 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 610 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 610 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/610 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 608 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 608 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 608? addr=-1576949568, defaddr=0 maxms=2000, lastms=6 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/608 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[9302]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/28889302-15 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7' of Request 102: Match Not Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7' of Request 102: Match Not Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[9311]: app_queue.c:546 changethread: Device 'SIP/611' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9312]: app_queue.c:546 changethread: Device 'SIP/610' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9313]: app_queue.c:546 changethread: Device 'IAX2/608' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 607 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 607 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 607? addr=201435328, defaddr=0 maxms=2000, lastms=0 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/607 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 606 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 606 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '39b12ff11e4b23e0226cf0780ee29a10@192.168.1.7' of Request 102: Match Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 487 to standard invite asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '15d2bdff2ca60afb3595393d443d8cb1@192.168.1.7' of Request 102: Match Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 487 to standard invite asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 606? addr=335653056, defaddr=0 maxms=2000, lastms=0 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/606 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 601 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 601 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/601 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 600 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 600 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/600 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 28889302 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9635 iax2_devicestate: Checking device state for device 28889302 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: chan_iax2.c:9643 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 28889302? addr=45905749, defaddr=0 maxms=2000, lastms=11 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for IAX2/28889302 - state 1 (Not in use) asterisk*CLI> [Mar 15 17:59:52] DEBUG[9314]: app_queue.c:546 changethread: Device 'IAX2/607' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9315]: app_queue.c:546 changethread: Device 'IAX2/606' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9316]: app_queue.c:546 changethread: Device 'SIP/601' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9317]: app_queue.c:546 changethread: Device 'SIP/600' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[9318]: app_queue.c:546 changethread: Device 'IAX2/28889302' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' of Request 102: Match Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 487 to standard invite asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call asterisk*CLI> [Mar 15 17:59:52] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 15 on 16/0 to 192.168.1.20:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00015ms SCall: 00016 DCall: 00000 [192.168.1.20:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (ulaw|alaw|ilbc|gsm) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : LANGUAGE : fr FORMAT : 2 CAPABILITY : 58382 ADSICPE : 2 DATE TIME : 2007-03-15 17:59:50 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 16 on 17/0 to 192.168.1.12:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00016ms SCall: 00017 DCall: 00000 [192.168.1.12:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (ulaw|alaw|ilbc|gsm) CALLING NUMBER : 0473883858 CALLING PRESNTN : 3 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : LANGUAGE : fr FORMAT : 2 CAPABILITY : 58382 ADSICPE : 2 DATE TIME : 2007-03-15 17:59:50 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '044b789d59a55a7c303a2ee553f1e4de@192.168.1.7' of Request 102: Match Not Found asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 02012ms SCall: 00430 DCall: 00021 [192.168.1.162:4569] [Mar 15 17:59:52] DEBUG[8771]: chan_iax2.c:6494 socket_process: Received packet 2, (6, 4) [Mar 15 17:59:52] DEBUG[8771]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 1 [Mar 15 17:59:52] DEBUG[8771]: chan_iax2.c:6600 socket_process: Really destroying 21, having been acked on final message asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7d408d0158416210251a0cd934211d4a@192.168.1.7' of Request 102: Match Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:11641 handle_response_invite: SIP response 487 to standard invite asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7d408d0158416210251a0cd934211d4a@192.168.1.7' of Request 102: Match Not Found asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.33 with 192.168.1.0 asterisk*CLI> [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.33 is not local, substituting externip [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:52] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.32 with 192.168.1.0 [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.32 is not local, substituting externip [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:52] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.31 with 192.168.1.0 [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.31 is not local, substituting externip [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:52] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.30 with 192.168.1.0 [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.30 is not local, substituting externip [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:59:52] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.29 with 192.168.1.0 [Mar 15 17:59:52] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.29 is not local, substituting externip asterisk*CLI> [Mar 15 17:59:53] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 18 [Mar 15 17:59:53] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 3 [Mar 15 17:59:53] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 18 [Mar 15 17:59:53] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 4 [Mar 15 17:59:53] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 23 [Mar 15 17:59:53] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 22 [Mar 15 17:59:53] DEBUG[8772]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 24 [Mar 15 17:59:53] DEBUG[8772]: chan_iax2.c:1258 find_callno: Creating new call structure 23 [Mar 15 17:59:53] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 25 [Mar 15 17:59:53] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 24 asterisk*CLI> [Mar 15 17:59:53] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 3/0 to 81.201.84.34:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00003 DCall: 00000 [81.201.84.34:4569] [Mar 15 17:59:53] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 4/0 to 81.201.82.29:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00004 DCall: 00000 [81.201.82.29:4569] [Mar 15 17:59:53] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 22/0 to 81.201.84.33:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00022 DCall: 00000 [81.201.84.33:4569] [Mar 15 17:59:53] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 3 on 23/0 to 81.201.84.30:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00023 DCall: 00000 [81.201.84.30:4569] [Mar 15 17:59:53] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 4 on 24/0 to 81.201.84.31:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00004ms SCall: 00024 DCall: 00000 [81.201.84.31:4569] asterisk*CLI> [Mar 15 17:59:54] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 2012 on 17/0 to 192.168.1.12:4569 Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP Timestamp: 02012ms SCall: 00017 DCall: 00000 [192.168.1.12:4569] CAUSE CODE : 0 [Mar 15 17:59:54] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 2012 on 16/0 to 192.168.1.20:4569 Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP Timestamp: 02012ms SCall: 00016 DCall: 00000 [192.168.1.20:4569] CAUSE CODE : 0 asterisk*CLI> [Mar 15 17:59:54] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 3 on 3/0 to 81.201.84.34:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00003 DCall: 00000 [81.201.84.34:4569] [Mar 15 17:59:54] DEBUG[8771]: chan_iax2.c:1650 send_packet: Sending 3 on 4/0 to 81.201.82.29:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00004 DCall: 00000 [81.201.82.29:4569] [Mar 15 17:59:54] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 3 on 22/0 to 81.201.84.33:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00022 DCall: 00000 [81.201.84.33:4569] [Mar 15 17:59:54] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 3 on 23/0 to 81.201.84.30:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00003ms SCall: 00023 DCall: 00000 [81.201.84.30:4569] [Mar 15 17:59:54] DEBUG[8769]: chan_iax2.c:1650 send_packet: Sending 4 on 24/0 to 81.201.84.31:4569 Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00004ms SCall: 00024 DCall: 00000 [81.201.84.31:4569] asterisk*CLI>