and here are some debugs of when I leave a voicemail. I also get voice distortion on the voicemail prompts. They seem to clear up whenever I see a "rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes" in the debugs Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 2 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 1 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 1 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 3 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 2 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 2 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 10 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 9 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 9 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 1/0 to 198.22.67.67:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 2/0 to 198.22.67.70:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 9/0 to 66.225.202.72:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 16) Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 16 received Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=9, set last=16 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 9/62 to 66.225.202.72:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 16) Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 16 received Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=1, set last=7 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 1/6 to 198.22.67.67:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 14) Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 14 received Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=2, set last=7 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 43 on 2/277 to 198.22.67.70:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 11 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 10 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 10/0 to 72.1.157.36:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 3) Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 3 received Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 10/24 to 72.1.157.36:4569 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 15) Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 15 received Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=2, set last=42 Aug 7 22:39:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 2/277 to 198.22.67.70:4569 Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:2902 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: OPTIONS sip:72.1.157.34 SIP/2.0 (31) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4081999f (56) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: "asterisk" ;tag=as766e9cde (58) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: (21) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Contact: (35) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 372d928d2586265151121bb301f9f756@72.1.157.37 (53) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 102 OPTIONS (17) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: User-Agent: JetSpeak (20) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 02:39:01 GMT (35) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY (55) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 0 (17) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) 11 headers, 0 lines Reliably Transmitting (no NAT) to 72.1.157.34:5060: OPTIONS sip:72.1.157.34 SIP/2.0 Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4081999f From: "asterisk" ;tag=as766e9cde To: Contact: Call-ID: 372d928d2586265151121bb301f9f756@72.1.157.37 CSeq: 102 OPTIONS User-Agent: JetSpeak Date: Mon, 08 Aug 2005 02:39:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY Content-Length: 0 --- switch2*CLI> <-- SIP read from 72.1.157.34:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4081999f From: "asterisk" ;tag=as766e9cde To: ;tag=1AFDC38-478 Date: Mon, 08 Aug 2005 06:40:55 GMT Call-ID: 372d928d2586265151121bb301f9f756@72.1.157.37 Server: Cisco-SIPGateway/IOS-12.x Content-Type: application/sdp CSeq: 102 OPTIONS Supported: 100rel Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO Accept: application/sdp Allow-Events: telephone-event Content-Length: 163 v=0 o=CiscoSystemsSIP-GW-UserAgent 2420 287 IN IP4 72.1.157.34 s=SIP Call c=IN IP4 72.1.157.34 t=0 0 m=audio 0 RTP/AVP 18 0 8 4 2 15 3 c=IN IP4 72.1.157.34 Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: SIP/2.0 200 OK (14) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4081999f (56) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: "asterisk" ;tag=as766e9cde (58) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: ;tag=1AFDC38-478 (37) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 06:40:55 GMT (35) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 372d928d2586265151121bb301f9f756@72.1.157.37 (53) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Server: Cisco-SIPGateway/IOS-12.x (33) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Type: application/sdp (29) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 102 OPTIONS (17) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Supported: 100rel (17) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO (86) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Accept: application/sdp (23) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow-Events: telephone-event (29) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 163 (19) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: v=0 (3) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 2420 287 IN IP4 72.1.157.34 (58) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: s=SIP Call (10) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: t=0 0 (5) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: m=audio 0 RTP/AVP 18 0 8 4 2 15 3 (33) Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) --- (14 headers 7 lines)--- Aug 7 22:39:01 DEBUG[5400]: chan_sip.c:1205 __sip_ack: Stopping retransmission on '372d928d2586265151121bb301f9f756@72.1.157.37' of Request 102: Found Destroying call '372d928d2586265151121bb301f9f756@72.1.157.37' Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 12 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 11 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 30) Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 30 received Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=11, set last=10 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 11/25 to 72.1.157.36:4569 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 4) Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 11, having been acked on final message Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 13 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 12 Aug 7 22:39:05 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 12/0 to 67.137.224.13:4569 Aug 7 22:39:06 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 3) Aug 7 22:39:06 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:06 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 3 received Aug 7 22:39:06 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 12/74 to 67.137.224.13:4569 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 4 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 3 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=3, set last=18 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 18 on 3/2 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 3/2 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 5 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 4 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=4, set last=18 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 18 on 4/19 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 4/19 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 14 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 13 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=13, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 13/20 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 13/20 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247211 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247211 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247211 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247210 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247210 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247210 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297825 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297825 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297825 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15512]: app_queue.c:429 changethread: Device 'IAX2/4435247211' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15513]: app_queue.c:429 changethread: Device 'IAX2/4435247210' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15514]: app_queue.c:429 changethread: Device 'IAX2/4105297825' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 15 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 14 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=14, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 14/21 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 14/21 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 16 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 15 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=15, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 15/22 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 15/22 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297824 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297824 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297824 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297823 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297823 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297823 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15515]: app_queue.c:429 changethread: Device 'IAX2/4105297824' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15516]: app_queue.c:429 changethread: Device 'IAX2/4105297823' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 17 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 16 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=16, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 16/23 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 16/23 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 18 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 17 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=17, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 17/24 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 17/24 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 18 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=18, set last=19 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 18/25 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 18/25 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297822 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297822 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297822 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297821 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297821 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297821 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297820 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297820 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297820 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15519]: app_queue.c:429 changethread: Device 'IAX2/4105297820' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15517]: app_queue.c:429 changethread: Device 'IAX2/4105297822' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15518]: app_queue.c:429 changethread: Device 'IAX2/4105297821' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=3, set last=39 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 39 on 3/2 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 32 on 3/2 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247211 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247211 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247211 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15520]: app_queue.c:429 changethread: Device 'IAX2/4435247211' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=4, set last=41 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 41 on 4/19 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 34 on 4/19 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=13, set last=42 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 13/20 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 34 on 13/20 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247210 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247210 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247210 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297825 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297825 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297825 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15521]: app_queue.c:429 changethread: Device 'IAX2/4435247210' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15522]: app_queue.c:429 changethread: Device 'IAX2/4105297825' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=14, set last=44 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 44 on 14/21 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 14/21 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=15, set last=46 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 46 on 15/22 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 15/22 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=16, set last=49 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 49 on 16/23 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 18 on 16/23 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297824 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297824 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297824 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297823 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297823 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297823 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297822 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297822 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297822 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15523]: app_queue.c:429 changethread: Device 'IAX2/4105297824' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15524]: app_queue.c:429 changethread: Device 'IAX2/4105297823' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[15525]: app_queue.c:429 changethread: Device 'IAX2/4105297822' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=17, set last=52 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 52 on 17/24 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 22 on 17/24 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297821 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297821 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297821 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15526]: app_queue.c:429 changethread: Device 'IAX2/4105297821' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=18, set last=57 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 57 on 18/25 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 28 on 18/25 to 66.93.54.225:20002 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297820 Aug 7 22:39:10 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297820 Aug 7 22:39:10 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297820 - state 1 (Not in use) Aug 7 22:39:10 DEBUG[15527]: app_queue.c:429 changethread: Device 'IAX2/4105297820' changed to state '1' (Not in use) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 3, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 4, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 13, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 14, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 15, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 16, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 17, having been acked on final message Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:10 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 18, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 20 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 19 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=19, set last=11 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 19/1 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 19/1 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 21 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 20 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=20, set last=11 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 20/5 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 20/5 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 22 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 21 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=21, set last=11 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 21/6 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 21/6 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 48 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 47 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=47, set last=11 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 47/21 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 47/21 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 49 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 48 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=48, set last=11 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 48/22 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 48/22 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 50 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 49 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=49, set last=12 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 49/29 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 49/29 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 51 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 50 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=50, set last=12 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 50/30 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 50/30 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 52 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 51 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=51, set last=12 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 51/31 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 51/31 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 53 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 52 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=52, set last=12 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 52/32 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 52/32 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 54 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 53 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=53, set last=12 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 53/33 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 53/33 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=19, set last=13 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 19/1 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 19/1 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=20, set last=13 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 20/5 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 20/5 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=21, set last=14 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 21/6 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 21/6 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=47, set last=14 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 47/21 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 47/21 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=48, set last=14 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 48/22 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 48/22 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=49, set last=15 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 15 on 49/29 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 49/29 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=50, set last=15 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 15 on 50/30 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 50/30 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=51, set last=16 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 51/31 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 51/31 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=52, set last=16 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 52/32 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 52/32 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=53, set last=16 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 53/33 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 53/33 to 72.1.157.50:4569 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 19, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 20, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 21, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 47, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 48, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 49, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 50, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 51, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 52, having been acked on final message Aug 7 22:39:17 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:39:17 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:39:17 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:39:17 DEBUG[15529]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15530]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15531]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15532]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15533]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15534]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15535]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15536]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15537]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15538]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15539]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15540]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15541]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15542]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15543]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15544]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15545]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15546]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15547]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:39:17 DEBUG[15548]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: INVITE sip:4435246542@72.1.157.37:5060 SIP/2.0 (46) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.34:5060 (34) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: ;tag=1B021FC-91F (50) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: (32) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 06:41:13 GMT (35) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 (55) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Supported: timer,100rel (23) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Min-SE: 1800 (13) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Cisco-Guid: 1059834557-118362586-2267190453-2121011248 (54) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: User-Agent: Cisco-SIPGateway/IOS-12.x (37) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO (86) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 101 INVITE (16) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Max-Forwards: 6 (15) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Remote-Party-ID: ;party=calling;screen=yes;privacy=off (82) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Timestamp: 1123483273 (21) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Contact: (42) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Diversion: ;reason=user-busy (56) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Expires: 180 (12) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow-Events: telephone-event (29) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Type: application/sdp (29) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 301 (19) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: v=0 (3) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 7219 2926 IN IP4 72.1.157.34 (59) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: s=SIP Call (10) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: t=0 0 (5) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: m=audio 17186 RTP/AVP 0 121 101 (31) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=rtpmap:121 frf-dialed-digit/8000 (34) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=fmtp:121 0-15 (15) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=fmtp:101 0-16 (15) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: a=ptime:10 (10) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:2902 sip_alloc: Allocating new SIP dialog for 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 - INVITE (With RTP) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:9913 handle_request: **** Received INVITE (5) - Command in SIP INVITE Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:877 parse_sip_options: Begin: parsing SIP "Supported: timer,100rel" Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:889 parse_sip_options: Found SIP option: -timer- Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:895 parse_sip_options: Matched SIP option: timer Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:889 parse_sip_options: Found SIP option: -100rel- Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:895 parse_sip_options: Matched SIP option: 100rel Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:906 parse_sip_options: * SIP extension value: 6 for call 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:6267 check_user_full_peer: Setting NAT on RTP to 0 Found RTP audio format 0 Found RTP audio format 121 Found RTP audio format 101 Peer audio RTP is at port 72.1.157.34:17186 Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3274 process_sdp: Peer audio RTP is at port 72.1.157.34:17186 Found description format PCMU Found description format frf-dialed-digit Found description format telephone-event Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x5 (telephone-event), combined - 0x1 (telephone-event) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:9399 handle_request_invite: Checking SIP call limits for device Looking for 4435246542 in didswitching Aug 7 22:39:19 DEBUG[5400]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '1' Aug 7 22:39:19 DEBUG[5400]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. RDNIS is 4439568899 Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:5412 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 72.1.157.34:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 72.1.157.34:5060 From: ;tag=1B021FC-91F To: Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 CSeq: 101 INVITE User-Agent: JetSpeak Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY Contact: Content-Length: 0 --- Aug 7 22:39:19 DEBUG[5397]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM users WHERE name = '72.1.157.34' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '1' Aug 7 22:39:19 DEBUG[5397]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for SIP/72.1.157.34 - state 2 (In use) Aug 7 22:39:19 DEBUG[15550]: app_queue.c:429 changethread: Device 'SIP/72.1.157.34' changed to state '2' (In use) Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '1' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '1' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '1' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Answer("SIP/72.1.157.34-081a8c68", "") Aug 7 22:39:19 DEBUG[15549]: chan_sip.c:2332 sip_answer: sip_answer(SIP/72.1.157.34-081a8c68) We're at 72.1.157.37 port 18366 Answering with preferred capability 0x4 (ulaw) Answering with non-codec capability 0x1 (telephone-event) Reliably Transmitting (no NAT) to 72.1.157.34:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 72.1.157.34:5060 From: ;tag=1B021FC-91F To: ;tag=as0ddda3af Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 CSeq: 101 INVITE User-Agent: JetSpeak Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY Contact: Content-Type: application/sdp Content-Length: 214 v=0 o=root 15549 15549 IN IP4 72.1.157.37 s=session c=IN IP4 72.1.157.37 t=0 0 m=audio 18366 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '2' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '2' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '2' Aug 7 22:39:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Wait("SIP/72.1.157.34-081a8c68", "1") Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: ACK sip:4435246542@72.1.157.37:5060 SIP/2.0 (43) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.34:5060 (34) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: ;tag=1B021FC-91F (50) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: ;tag=as0ddda3af (47) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 06:41:13 GMT (35) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 (55) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Max-Forwards: 6 (15) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 0 (17) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 101 ACK (13) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:9913 handle_request: **** Received ACK (6) - Command in SIP ACK Aug 7 22:39:19 DEBUG[5400]: chan_sip.c:1205 __sip_ack: Stopping retransmission on '3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34' of Response 101: Found Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: pbx.c:1526 pbx_substitute_variables_helper_full: Expression is '0' -- Executing GotoIf("SIP/72.1.157.34-081a8c68", "0?1000") Aug 7 22:39:20 DEBUG[15549]: pbx.c:5821 pbx_builtin_gotoif: Not taking any branch Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '4' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '4' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '4' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Setvar("SIP/72.1.157.34-081a8c68", "DEST=4439568899") Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '5' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '5' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '4435246542' AND context = 'didswitching' AND priority = '5' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Goto("SIP/72.1.157.34-081a8c68", "functions|8501|1") -- Goto (functions,8501,1) Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '1' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '1' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '1' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing NoOp("SIP/72.1.157.34-081a8c68", "This Function records a voicemail on no answer") Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '2' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '2' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '2' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Answer("SIP/72.1.157.34-081a8c68", "") Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '3' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Voicemail("SIP/72.1.157.34-081a8c68", "4439568899") Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM voicemail_users WHERE mailbox = '4439568899' AND context = 'default' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = 'o' AND context = 'functions' AND priority = '1' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:231 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten LIKE '\_%' AND context = 'functions' AND priority = '1' ORDER BY exten Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = 'a' AND context = 'functions' AND priority = '1' Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:231 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten LIKE '\_%' AND context = 'functions' AND priority = '1' ORDER BY exten Aug 7 22:39:20 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:39:20 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm Aug 7 22:39:20 DEBUG[15549]: rtp.c:1263 ast_rtp_write: Ooh, format changed from unknown to ulaw -- Playing 'vm-intro' (language 'en') Aug 7 22:39:21 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 23 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 22 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=22, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 22/3 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 22/3 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 24 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 23 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=23, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 23/4 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 23/4 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4104671300 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4104671300 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4104671300 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108896011 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108896011 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108896011 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15551]: app_queue.c:429 changethread: Device 'IAX2/4104671300' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15552]: app_queue.c:429 changethread: Device 'IAX2/4108896011' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 25 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 24 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=24, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 24/5 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106627007 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106627007 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106627007 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 24/5 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[15553]: app_queue.c:429 changethread: Device 'IAX2/4106627007' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 26 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 25 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=25, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 25/9 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 25/9 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246556 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246556 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246556 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 27 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 26 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=26, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 26/11 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 26/11 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246549 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246549 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246549 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15554]: app_queue.c:429 changethread: Device 'IAX2/4435246556' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15555]: app_queue.c:429 changethread: Device 'IAX2/4435246549' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 28 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 27 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=27, set last=12 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 27/13 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 27/13 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246548 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246548 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246548 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 29 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 28 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=28, set last=13 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 28/15 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 28/15 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247208 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247208 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247208 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 30 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 29 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=29, set last=13 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 29/17 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 29/17 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 55 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 54 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=54, set last=13 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 54/19 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 54/19 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106621800 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106621800 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106621800 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108894667 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108894667 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108894667 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15556]: app_queue.c:429 changethread: Device 'IAX2/4435246548' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15557]: app_queue.c:429 changethread: Device 'IAX2/4435247208' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15558]: app_queue.c:429 changethread: Device 'IAX2/4106621800' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15559]: app_queue.c:429 changethread: Device 'IAX2/4108894667' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=22, set last=35 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 35 on 22/3 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 31 on 22/3 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4104671300 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4104671300 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4104671300 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15560]: app_queue.c:429 changethread: Device 'IAX2/4104671300' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=23, set last=39 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 39 on 23/4 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 34 on 23/4 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108896011 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108896011 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108896011 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15561]: app_queue.c:429 changethread: Device 'IAX2/4108896011' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=24, set last=42 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 24/5 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 24/5 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106627007 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106627007 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106627007 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15562]: app_queue.c:429 changethread: Device 'IAX2/4106627007' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=25, set last=48 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 48 on 25/9 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 43 on 25/9 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246556 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246556 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246556 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15563]: app_queue.c:429 changethread: Device 'IAX2/4435246556' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=26, set last=51 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 51 on 26/11 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 44 on 26/11 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246549 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246549 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246549 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15564]: app_queue.c:429 changethread: Device 'IAX2/4435246549' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=27, set last=54 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 54 on 27/13 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 28 on 27/13 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246548 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246548 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246548 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15565]: app_queue.c:429 changethread: Device 'IAX2/4435246548' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=28, set last=57 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 57 on 28/15 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 33 on 28/15 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247208 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247208 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247208 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15566]: app_queue.c:429 changethread: Device 'IAX2/4435247208' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=29, set last=60 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 60 on 29/17 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 36 on 29/17 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=54, set last=61 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 61 on 54/19 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 36 on 54/19 to 66.92.46.208:4569 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106621800 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106621800 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106621800 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108894667 Aug 7 22:39:21 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108894667 Aug 7 22:39:21 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108894667 - state 1 (Not in use) Aug 7 22:39:21 DEBUG[15567]: app_queue.c:429 changethread: Device 'IAX2/4106621800' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[15568]: app_queue.c:429 changethread: Device 'IAX2/4108894667' changed to state '1' (Not in use) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 22, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 23, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 24, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 25, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 26, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 27, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 28, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 29, having been acked on final message Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:21 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 54, having been acked on final message Aug 7 22:39:23 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:26 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:39:26 DEBUG[15549]: app.c:1129 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/4439568899/INBOX' Aug 7 22:39:26 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm -- Playing 'beep' (language 'en') Aug 7 22:39:26 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw -- Recording the message Aug 7 22:39:26 DEBUG[15549]: app.c:543 ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/default/4439568899/INBOX/msg0001, 'wav49' Aug 7 22:39:26 DEBUG[15549]: app.c:560 ast_play_and_record: Recording Formats: sfmts=wav49 -- x=0, open writing: /var/spool/asterisk/voicemail/default/4439568899/INBOX/msg0001 format: wav49, 0x81ab998 Aug 7 22:39:27 DEBUG[15549]: app.c:1141 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/4439568899/INBOX' Aug 7 22:39:27 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to read format slin Aug 7 22:39:28 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 6 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 5 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=5, set last=4 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 5/1 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 5/1 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107966461 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107966461 Aug 7 22:39:32 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107966461 - state 1 (Not in use) Aug 7 22:39:32 DEBUG[15570]: app_queue.c:429 changethread: Device 'IAX2/4107966461' changed to state '1' (Not in use) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 7 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 6 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=6, set last=5 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 6/7 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 6/7 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107965851 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107965851 Aug 7 22:39:32 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107965851 - state 1 (Not in use) Aug 7 22:39:32 DEBUG[15571]: app_queue.c:429 changethread: Device 'IAX2/4107965851' changed to state '1' (Not in use) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=5, set last=35 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 35 on 5/1 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 47 on 5/1 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107966461 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107966461 Aug 7 22:39:32 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107966461 - state 1 (Not in use) Aug 7 22:39:32 DEBUG[15572]: app_queue.c:429 changethread: Device 'IAX2/4107966461' changed to state '1' (Not in use) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=6, set last=42 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 6/7 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 32 on 6/7 to 68.55.212.198:63121 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107965851 Aug 7 22:39:32 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107965851 Aug 7 22:39:32 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107965851 - state 1 (Not in use) Aug 7 22:39:32 DEBUG[15573]: app_queue.c:429 changethread: Device 'IAX2/4107965851' changed to state '1' (Not in use) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 5, having been acked on final message Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:32 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 6, having been acked on final message Aug 7 22:39:34 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 108 bytes Aug 7 22:39:36 DEBUG[15549]: rtp.c:159 send_dtmf: Sending dtmf: 35 (#), at 72.1.157.34 -- User ended message by pressing # Aug 7 22:39:36 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to read format ulaw Aug 7 22:39:36 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm Aug 7 22:39:36 DEBUG[15549]: rtp.c:1180 ast_rtp_raw_write: Difference is 82656, ms is 10352 -- Playing 'auth-thankyou' (language 'en') Aug 7 22:39:38 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:39:38 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm -- Playing 'vm-review' (language 'en') Aug 7 22:39:39 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:46 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:46 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 8 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 7 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 7 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 9 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 8 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 8 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7462 iax2_do_register: Sending registration request for 'jscivoip' Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7465 iax2_do_register: Allocate call number Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 31 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 30 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:7471 iax2_do_register: Registration created on call 30 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 7/0 to 198.22.67.67:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 8/0 to 198.22.67.70:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 30/0 to 66.225.202.72:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 16) Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 16 received Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=7, set last=16 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 7/1 to 198.22.67.67:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 16) Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 16 received Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=30, set last=1 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 30/85 to 66.225.202.72:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 14) Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 14 received Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=8, set last=17 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 48 on 8/430 to 198.22.67.70:4569 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 15) Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 15 received Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=8, set last=52 Aug 7 22:39:50 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 52 on 8/430 to 198.22.67.70:4569 Aug 7 22:39:53 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm Aug 7 22:39:53 DEBUG[15549]: rtp.c:1180 ast_rtp_raw_write: Difference is 52248, ms is 6551 -- Playing 'vm-review' (language 'en') Aug 7 22:39:53 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:39:57 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 32 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 31 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 31/0 to 72.1.157.36:4569 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 3) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 3 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 31/1 to 72.1.157.36:4569 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 33 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 32 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=32, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 32/1 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 32/1 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 34 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 33 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=33, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 33/3 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 33/3 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 35 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 34 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=34, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 34/4 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 34/4 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247211 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247211 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247211 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247210 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247210 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247210 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297825 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297825 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297825 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15587]: app_queue.c:429 changethread: Device 'IAX2/4435247211' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15588]: app_queue.c:429 changethread: Device 'IAX2/4435247210' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15589]: app_queue.c:429 changethread: Device 'IAX2/4105297825' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 36 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 35 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=35, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 35/5 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 15 on 35/5 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 37 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 36 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=36, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 36/6 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 36/6 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297824 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297824 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297824 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297823 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297823 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297823 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15590]: app_queue.c:429 changethread: Device 'IAX2/4105297824' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15591]: app_queue.c:429 changethread: Device 'IAX2/4105297823' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 38 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 37 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=37, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 37/7 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 37/7 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 39 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 38 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=38, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 38/8 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 38/8 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 40 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 39 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=39, set last=19 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 19 on 39/9 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 39/9 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297822 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297822 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297822 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297821 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297821 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297821 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297820 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297820 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297820 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15594]: app_queue.c:429 changethread: Device 'IAX2/4105297820' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15592]: app_queue.c:429 changethread: Device 'IAX2/4105297822' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15593]: app_queue.c:429 changethread: Device 'IAX2/4105297821' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=32, set last=39 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 39 on 32/1 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 32 on 32/1 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=33, set last=41 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 41 on 33/3 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 32 on 33/3 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=34, set last=42 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 34/4 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 33 on 34/4 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247211 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247211 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247211 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247210 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247210 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247210 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297825 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297825 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297825 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15595]: app_queue.c:429 changethread: Device 'IAX2/4435247211' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15596]: app_queue.c:429 changethread: Device 'IAX2/4435247210' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15597]: app_queue.c:429 changethread: Device 'IAX2/4105297825' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=35, set last=44 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 44 on 35/5 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 38 on 35/5 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=36, set last=46 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 46 on 36/6 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 38 on 36/6 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297824 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297824 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297824 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297823 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297823 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297823 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15598]: app_queue.c:429 changethread: Device 'IAX2/4105297824' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[15599]: app_queue.c:429 changethread: Device 'IAX2/4105297823' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=37, set last=49 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 49 on 37/7 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 41 on 37/7 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297822 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297822 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297822 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15600]: app_queue.c:429 changethread: Device 'IAX2/4105297822' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=38, set last=52 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 52 on 38/8 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 23 on 38/8 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297821 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297821 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297821 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15601]: app_queue.c:429 changethread: Device 'IAX2/4105297821' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=39, set last=57 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 57 on 39/9 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 27 on 39/9 to 66.93.54.225:20002 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4105297820 Aug 7 22:40:00 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4105297820 Aug 7 22:40:00 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4105297820 - state 1 (Not in use) Aug 7 22:40:00 DEBUG[15602]: app_queue.c:429 changethread: Device 'IAX2/4105297820' changed to state '1' (Not in use) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 32, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 33, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 34, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 35, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 36, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 37, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 38, having been acked on final message Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:00 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 39, having been acked on final message Aug 7 22:40:01 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:2902 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: OPTIONS sip:72.1.157.34 SIP/2.0 (31) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4a679a17 (56) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: "asterisk" ;tag=as1deb3204 (58) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: (21) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Contact: (35) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 75c8b9067f9f13016ec37167759886e2@72.1.157.37 (53) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 102 OPTIONS (17) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: User-Agent: JetSpeak (20) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 02:40:01 GMT (35) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY (55) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 0 (17) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) 11 headers, 0 lines Reliably Transmitting (no NAT) to 72.1.157.34:5060: OPTIONS sip:72.1.157.34 SIP/2.0 Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4a679a17 From: "asterisk" ;tag=as1deb3204 To: Contact: Call-ID: 75c8b9067f9f13016ec37167759886e2@72.1.157.37 CSeq: 102 OPTIONS User-Agent: JetSpeak Date: Mon, 08 Aug 2005 02:40:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY Content-Length: 0 --- switch2*CLI> <-- SIP read from 72.1.157.34:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4a679a17 From: "asterisk" ;tag=as1deb3204 To: ;tag=1B0C6A8-A8E Date: Mon, 08 Aug 2005 06:41:55 GMT Call-ID: 75c8b9067f9f13016ec37167759886e2@72.1.157.37 Server: Cisco-SIPGateway/IOS-12.x Content-Type: application/sdp CSeq: 102 OPTIONS Supported: 100rel Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO Accept: application/sdp Allow-Events: telephone-event Content-Length: 164 v=0 o=CiscoSystemsSIP-GW-UserAgent 1244 2744 IN IP4 72.1.157.34 s=SIP Call c=IN IP4 72.1.157.34 t=0 0 m=audio 0 RTP/AVP 18 0 8 4 2 15 3 c=IN IP4 72.1.157.34 Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: SIP/2.0 200 OK (14) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK4a679a17 (56) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: "asterisk" ;tag=as1deb3204 (58) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: ;tag=1B0C6A8-A8E (37) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 06:41:55 GMT (35) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 75c8b9067f9f13016ec37167759886e2@72.1.157.37 (53) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Server: Cisco-SIPGateway/IOS-12.x (33) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Type: application/sdp (29) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 102 OPTIONS (17) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Supported: 100rel (17) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO (86) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Accept: application/sdp (23) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Allow-Events: telephone-event (29) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 164 (19) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: v=0 (3) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 1244 2744 IN IP4 72.1.157.34 (59) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: s=SIP Call (10) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: t=0 0 (5) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: m=audio 0 RTP/AVP 18 0 8 4 2 15 3 (33) Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:3127 parse_request: Line: c=IN IP4 72.1.157.34 (20) --- (14 headers 7 lines)--- Aug 7 22:40:01 DEBUG[5400]: chan_sip.c:1205 __sip_ack: Stopping retransmission on '75c8b9067f9f13016ec37167759886e2@72.1.157.37' of Request 102: Found Destroying call '75c8b9067f9f13016ec37167759886e2@72.1.157.37' Aug 7 22:40:02 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:40:03 DEBUG[15549]: rtp.c:159 send_dtmf: Sending dtmf: 50 (2), at 72.1.157.34 -- Reviewing the message Aug 7 22:40:03 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm Aug 7 22:40:03 DEBUG[15549]: rtp.c:1180 ast_rtp_raw_write: Difference is 13160, ms is 1665 -- Playing '/var/spool/asterisk/voicemail/default/4439568899/INBOX/msg0001' (language 'en') Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 2 Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 1 Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 30) Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 30 received Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=1, set last=10 Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 10 on 1/24 to 72.1.157.36:4569 Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 4) Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:05 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 1, having been acked on final message Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 3 Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 2 Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 2/0 to 67.137.224.13:4569 Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 3) Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 3 received Aug 7 22:40:06 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 2/70 to 67.137.224.13:4569 Aug 7 22:40:07 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 10 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 9 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=9, set last=11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 9/4 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 9/4 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 10 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=10, set last=11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 10/7 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 10/7 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=11, set last=11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 11/8 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 11/8 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 13 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=12, set last=11 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 12/9 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 12/9 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 41 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 40 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=40, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 40/10 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 40/10 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 42 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 41 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=41, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 41/16 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 41/16 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 43 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 42 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=42, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 42/17 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 3 on 42/17 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 44 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 43 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=43, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 43/18 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 43/18 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 45 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 44 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=44, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 44/19 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 4 on 44/19 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 46 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 45 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=45, set last=12 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 12 on 45/20 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 45/20 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=9, set last=13 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 9/4 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 9/4 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=10, set last=13 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 10/7 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 10/7 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=11, set last=14 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 11/8 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 11/8 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=12, set last=14 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 12/9 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 6 on 12/9 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=40, set last=15 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 15 on 40/10 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 40/10 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=41, set last=15 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 15 on 41/16 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 7 on 41/16 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=42, set last=16 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 42/17 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 42/17 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=43, set last=16 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 43/18 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 43/18 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=44, set last=17 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 44/19 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 44/19 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=45, set last=17 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 45/20 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 45/20 to 72.1.157.50:4569 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 9, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 10, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 11, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 12, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 40, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 41, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 42, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 43, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 44, having been acked on final message Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:07 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 45, having been acked on final message Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246543 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246543 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246543 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246540 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246540 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246540 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662291542 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662291542 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662291542 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 8662855921 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 8662855921 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/8662855921 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247200 Aug 7 22:40:07 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247200 Aug 7 22:40:07 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247200 - state 1 (Not in use) Aug 7 22:40:07 DEBUG[15616]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15617]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15618]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15619]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15620]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15621]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15622]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15623]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15624]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15625]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15626]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15627]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15628]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15629]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15630]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15631]: app_queue.c:429 changethread: Device 'IAX2/4435246543' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15632]: app_queue.c:429 changethread: Device 'IAX2/4435246540' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15633]: app_queue.c:429 changethread: Device 'IAX2/8662291542' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15634]: app_queue.c:429 changethread: Device 'IAX2/8662855921' changed to state '1' (Not in use) Aug 7 22:40:07 DEBUG[15635]: app_queue.c:429 changethread: Device 'IAX2/4435247200' changed to state '1' (Not in use) Aug 7 22:40:09 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:40:09 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm -- Playing 'vm-review' (language 'en') Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 4 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 3 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=3, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 3/2 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 3/2 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4104671300 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4104671300 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4104671300 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15636]: app_queue.c:429 changethread: Device 'IAX2/4104671300' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 5 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 4 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=4, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 4/21 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 4/21 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 14 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=13, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 13/22 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 11 on 13/22 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108896011 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108896011 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108896011 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106627007 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106627007 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106627007 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15637]: app_queue.c:429 changethread: Device 'IAX2/4108896011' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15638]: app_queue.c:429 changethread: Device 'IAX2/4106627007' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 15 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 14 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=14, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 14/26 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 16 on 14/26 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246556 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246556 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246556 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 16 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 15 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=15, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 15/28 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 17 on 15/28 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246549 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246549 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246549 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15639]: app_queue.c:429 changethread: Device 'IAX2/4435246556' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15640]: app_queue.c:429 changethread: Device 'IAX2/4435246549' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 17 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 16 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=16, set last=13 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 13 on 16/30 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 16/30 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246548 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246548 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246548 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 18 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 17 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=17, set last=14 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 17/32 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 1 on 17/32 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 19 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 18 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=18, set last=14 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 18/34 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 2 on 18/34 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247208 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247208 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247208 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106621800 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106621800 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106621800 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15641]: app_queue.c:429 changethread: Device 'IAX2/4435246548' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15642]: app_queue.c:429 changethread: Device 'IAX2/4435247208' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15643]: app_queue.c:429 changethread: Device 'IAX2/4106621800' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 47 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 46 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=46, set last=14 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 14 on 46/36 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 9 on 46/36 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108894667 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108894667 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108894667 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=3, set last=37 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 3/2 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 29 on 3/2 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4104671300 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4104671300 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4104671300 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15644]: app_queue.c:429 changethread: Device 'IAX2/4108894667' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15645]: app_queue.c:429 changethread: Device 'IAX2/4104671300' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=4, set last=40 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 40 on 4/21 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 33 on 4/21 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108896011 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108896011 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108896011 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15646]: app_queue.c:429 changethread: Device 'IAX2/4108896011' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=13, set last=43 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 43 on 13/22 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 13/22 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106627007 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106627007 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106627007 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15647]: app_queue.c:429 changethread: Device 'IAX2/4106627007' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=14, set last=49 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 49 on 14/26 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 14/26 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=15, set last=49 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 49 on 15/28 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 42 on 15/28 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246556 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246556 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246556 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246549 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246549 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246549 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15648]: app_queue.c:429 changethread: Device 'IAX2/4435246556' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15649]: app_queue.c:429 changethread: Device 'IAX2/4435246549' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=16, set last=55 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 55 on 16/30 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 29 on 16/30 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435246548 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435246548 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435246548 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15650]: app_queue.c:429 changethread: Device 'IAX2/4435246548' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=17, set last=58 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 58 on 17/32 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 32 on 17/32 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4435247208 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4435247208 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4435247208 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15651]: app_queue.c:429 changethread: Device 'IAX2/4435247208' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=18, set last=61 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 61 on 18/34 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 18/34 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=46, set last=62 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 62 on 46/36 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 37 on 46/36 to 66.92.46.208:4569 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4106621800 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4106621800 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4106621800 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4108894667 Aug 7 22:40:11 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4108894667 Aug 7 22:40:11 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4108894667 - state 1 (Not in use) Aug 7 22:40:11 DEBUG[15652]: app_queue.c:429 changethread: Device 'IAX2/4106621800' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[15653]: app_queue.c:429 changethread: Device 'IAX2/4108894667' changed to state '1' (Not in use) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 3, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 4, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 13, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 14, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 15, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 16, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 17, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 18, having been acked on final message Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:11 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 46, having been acked on final message Aug 7 22:40:12 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:40:17 DEBUG[15549]: rtp.c:159 send_dtmf: Sending dtmf: 49 (1), at 72.1.157.34 Aug 7 22:40:17 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw -- Saving message as is Aug 7 22:40:17 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format gsm -- Playing 'vm-msgsaved' (language 'en') Aug 7 22:40:19 DEBUG[15549]: rtp.c:363 ast_rtcp_read: Got RTCP report of 132 bytes Aug 7 22:40:19 DEBUG[15549]: channel.c:2023 set_format: Set channel SIP/72.1.157.34-081a8c68 to write format ulaw Aug 7 22:40:19 DEBUG[15549]: app_voicemail.c:1552 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/4439568899/INBOX/msg0001', format 'WAV', uservm is '2048', global is 2048 Aug 7 22:40:19 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for **Unkown** - state 4 (Invalid) Aug 7 22:40:19 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for **Unkown** - state 4 (Invalid) Aug 7 22:40:19 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for **Unkown** - state 4 (Invalid) Aug 7 22:40:19 DEBUG[15549]: app_voicemail.c:1685 sendmail: Sent mail to jvm@istx.net with command '/usr/sbin/sendmail -t' Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '4' Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:231 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten LIKE '\_%' AND context = 'functions' AND priority = '4' ORDER BY exten Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = '8501' AND context = 'functions' AND priority = '1' Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. == Auto fallthrough, channel 'SIP/72.1.157.34-081a8c68' status is 'UNKNOWN' Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten = 'h' AND context = 'functions' AND priority = '1' Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:231 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM dialplan WHERE exten LIKE '\_%' AND context = 'functions' AND priority = '1' ORDER BY exten Aug 7 22:40:19 DEBUG[15549]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:40:19 DEBUG[15549]: cdr_addon_mysql.c:179 mysql_log: cdr_mysql: inserting a CDR record. Aug 7 22:40:19 DEBUG[15549]: cdr_addon_mysql.c:198 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2005-08-07 22:39:19','4439568899','4439568899','8501','functions', 'SIP/72.1.157.34-081a8c68','','VoiceMail','4439568899',60,60,'ANSWERED',3,'','') Aug 7 22:40:19 DEBUG[15549]: channel.c:1023 ast_hangup: Hanging up channel 'SIP/72.1.157.34-081a8c68' Aug 7 22:40:19 DEBUG[15549]: chan_sip.c:2220 sip_hangup: Hangup call SIP/72.1.157.34-081a8c68, SIP callid 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34) Aug 7 22:40:19 DEBUG[15549]: chan_sip.c:2232 sip_hangup: update_user_counter() - decrement inUse counter set_destination: Parsing for address/port to send to set_destination: set destination to 72.1.157.34, port 5060 Reliably Transmitting (no NAT) to 72.1.157.34:5060: BYE sip:4439568899@72.1.157.34:5060 SIP/2.0 Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK638795d2;rport From: ;tag=as0ddda3af To: ;tag=1B021FC-91F Contact: Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 CSeq: 102 BYE User-Agent: JetSpeak Content-Length: 0 --- Aug 7 22:40:19 DEBUG[5397]: res_config_mysql.c:120 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM users WHERE name = '72.1.157.34' Aug 7 22:40:19 DEBUG[5397]: res_config_mysql.c:613 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 7 22:40:19 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for SIP/72.1.157.34 - state 0 (Unknown) Aug 7 22:40:19 DEBUG[15661]: app_queue.c:429 changethread: Device 'SIP/72.1.157.34' changed to state '0' (Unknown) switch2*CLI> <-- SIP read from 72.1.157.34:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK638795d2;rport From: ;tag=as0ddda3af To: ;tag=1B021FC-91F Date: Mon, 08 Aug 2005 06:42:13 GMT Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 CSeq: 102 BYE Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: SIP/2.0 200 OK (14) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Via: SIP/2.0/UDP 72.1.157.37:5060;branch=z9hG4bK638795d2;rport (62) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: From: ;tag=as0ddda3af (49) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: To: ;tag=1B021FC-91F (48) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Date: Mon, 08 Aug 2005 06:42:13 GMT (35) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Call-ID: 3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34 (55) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Server: Cisco-SIPGateway/IOS-12.x (33) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: Content-Length: 0 (17) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: CSeq: 102 BYE (13) Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:3098 parse_request: Header: (0) --- (9 headers 0 lines)--- Aug 7 22:40:19 DEBUG[5400]: chan_sip.c:1205 __sip_ack: Stopping retransmission on '3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34' of Request 102: Found Response message BYE arrived Destroying call '3F2D030D-70E11DA-872594B5-7E6C1030@72.1.157.34' Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 20 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 19 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=19, set last=5 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 19/3 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 19/3 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:948 update_max_nontrunk: New max nontrunk callno is 21 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1047 find_callno: Creating new call structure 20 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 0, (6, 13) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=20, set last=5 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 5 on 20/4 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 8 on 20/4 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107966461 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107966461 Aug 7 22:40:22 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107966461 - state 1 (Not in use) Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107965851 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107965851 Aug 7 22:40:22 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107965851 - state 1 (Not in use) Aug 7 22:40:22 DEBUG[15663]: app_queue.c:429 changethread: Device 'IAX2/4107966461' changed to state '1' (Not in use) Aug 7 22:40:22 DEBUG[15664]: app_queue.c:429 changethread: Device 'IAX2/4107965851' changed to state '1' (Not in use) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=19, set last=49 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 49 on 19/3 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 38 on 19/3 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107966461 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107966461 Aug 7 22:40:22 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107966461 - state 1 (Not in use) Aug 7 22:40:22 DEBUG[15665]: app_queue.c:429 changethread: Device 'IAX2/4107966461' changed to state '1' (Not in use) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 1, (6, 13) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 0 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6562 socket_read: IAX subclass 13 received Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6571 socket_read: For call=20, set last=51 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 51 on 20/4 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:1448 send_packet: Sending 48 on 20/4 to 68.55.212.198:63121 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9077 iax2_devicestate: Checking device state for device 4107965851 Aug 7 22:40:22 DEBUG[5397]: chan_iax2.c:9084 iax2_devicestate: Found peer. Now checking device state for peer 4107965851 Aug 7 22:40:22 DEBUG[5397]: devicestate.c:166 do_state_change: Changing state for IAX2/4107965851 - state 1 (Not in use) Aug 7 22:40:22 DEBUG[15666]: app_queue.c:429 changethread: Device 'IAX2/4107965851' changed to state '1' (Not in use) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 19, having been acked on final message Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6368 socket_read: Received packet 2, (6, 4) Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6465 socket_read: Cancelling transmission of packet 1 Aug 7 22:40:22 DEBUG[5401]: chan_iax2.c:6474 socket_read: Really destroying 20, having been acked on final message switch2*CLI> exit Executing last minute cleanups switch2 ~ #