Asterisk SVN-branch-1.4-r58906, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= == Parsing '/etc/asterisk/asterisk.conf': Found == Parsing '/etc/asterisk/extconfig.conf': Found Connected to Asterisk SVN-branch-1.4-r58906 currently running on asterisk (pid = 8762) asterisk*CLI> Verbosity is at least 4 Core debug is at least 4 asterisk*CLI> [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:30] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.33 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.33 is not local, substituting externip [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:30] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.32 with 192.168.1.0 [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.32 is not local, substituting externip [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:30] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.31 with 192.168.1.0 [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.31 is not local, substituting externip [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:30] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.30 with 192.168.1.0 [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.30 is not local, substituting externip [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:30] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.29 with 192.168.1.0 [Mar 15 18:01:30] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.29 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:32] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 85.119.188.3 with 192.168.1.0 [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 85.119.188.3 is not local, substituting externip [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 7462e3b9078031412d4d187d392d34b3@85.119.188.3 - INVITE (With RTP) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:14629 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x50e (gsm|ulaw|alaw|g729|ilbc) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:13401 handle_request_invite: Checking SIP call limits for device 028883282 [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3805 sip_new: *** Our native formats are 0x100 (g729) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x50e (gsm|ulaw|alaw|g729|ilbc) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:7951 build_route: build_route: Record-Route hop: [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:13476 handle_request_invite: SIP/028883282-08200428: New call is still down.... Trying... [Mar 15 18:01:32] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/028883282-08200428 asterisk*CLI> [Mar 15 18:01:32] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 028883282 [Mar 15 18:01:32] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 028883282 [Mar 15 18:01:32] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/028883282 - state 4 (Invalid) asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Macro' asterisk*CLI> -- Executing [s@incoming:1] Macro("SIP/028883282-08200428", "reception_appel") in new stack asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Answer' asterisk*CLI> -- Executing [s@macro-reception_appel:1] Answer("SIP/028883282-08200428", "") in new stack asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/028883282-08200428 asterisk*CLI> [Mar 15 18:01:32] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 028883282 [Mar 15 18:01:32] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 028883282 [Mar 15 18:01:32] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/028883282 - state 4 (Invalid) asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:3463 sip_answer: SIP answering channel: SIP/028883282-08200428 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:6188 add_sdp: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: True asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0473883858' asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' asterisk*CLI> -- Executing [s@macro-reception_appel:2] NoOp("SIP/028883282-08200428", "Incoming call from 0473883858") in new stack asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Set' asterisk*CLI> -- Executing [s@macro-reception_appel:3] Set("SIP/028883282-08200428", "TIMEOUT(digit)=5") in new stack asterisk*CLI> -- Digit timeout set to 5 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Set' asterisk*CLI> -- Executing [s@macro-reception_appel:4] Set("SIP/028883282-08200428", "TIMEOUT(response)=20") in new stack asterisk*CLI> -- Response timeout set to 20 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'BackGround' asterisk*CLI> -- Executing [s@macro-reception_appel:5] BackGround("SIP/028883282-08200428", "user_defined/bienvenue") in new stack asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to write format gsm asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to g729 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: rtp.c:2706 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 asterisk*CLI> -- Playing 'user_defined/bienvenue' (language 'fr') asterisk*CLI> [Mar 15 18:01:32] DEBUG[9361]: app_queue.c:546 changethread: Device 'SIP/028883282' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:32] DEBUG[9362]: app_queue.c:546 changethread: Device 'SIP/028883282' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:14629 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 15 18:01:32] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7462e3b9078031412d4d187d392d34b3@85.119.188.3' of Response 102: Match Not Found asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: chan_sip.c:4092 sip_rtp_read: Oooh, format changed to 4 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to read format g729 asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to write format gsm asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: rtp.c:2689 ast_rtp_write: Ooh, format changed from g729 to ulaw asterisk*CLI> [Mar 15 18:01:32] DEBUG[9360]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 6 [Mar 15 18:01:34] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 5 [Mar 15 18:01:34] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 7 [Mar 15 18:01:34] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 6 [Mar 15 18:01:34] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 14 [Mar 15 18:01:34] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 13 [Mar 15 18:01:34] DEBUG[8772]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 15 [Mar 15 18:01:34] DEBUG[8772]: chan_iax2.c:1258 find_callno: Creating new call structure 14 [Mar 15 18:01:34] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 17 [Mar 15 18:01:34] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 16 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 1 on 5/0 to 81.201.84.34:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00001ms SCall: 00005 DCall: 00000 [81.201.84.34:4569] [Mar 15 18:01:34] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 1 on 6/0 to 81.201.82.29:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00001ms SCall: 00006 DCall: 00000 [81.201.82.29:4569] [Mar 15 18:01:34] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 1 on 13/0 to 81.201.84.33:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00001ms SCall: 00013 DCall: 00000 [81.201.84.33:4569] [Mar 15 18:01:34] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 2 on 14/0 to 81.201.84.30:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00002ms SCall: 00014 DCall: 00000 [81.201.84.30:4569] [Mar 15 18:01:34] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 2 on 16/0 to 81.201.84.31:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00002ms SCall: 00016 DCall: 00000 [81.201.84.31:4569] asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 48802f3f3b0c0c912420ea6566c6b708@81.242.238.174 asterisk*CLI> Really destroying SIP dialog '48802f3f3b0c0c912420ea6566c6b708@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.33 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 729b9a1929e53a8d5e7dc890192c6bb5@81.242.238.174 asterisk*CLI> Really destroying SIP dialog '729b9a1929e53a8d5e7dc890192c6bb5@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.32 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 0654676c433e48945add522624205464@81.242.238.174 asterisk*CLI> Really destroying SIP dialog '0654676c433e48945add522624205464@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.31 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 26895dfa1178672c787737b03b8a2dd3@81.242.238.174 asterisk*CLI> Really destroying SIP dialog '26895dfa1178672c787737b03b8a2dd3@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.30 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 3a7f316777f6bdd20d623b8212f91617@81.242.238.174 asterisk*CLI> Really destroying SIP dialog '3a7f316777f6bdd20d623b8212f91617@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:34] DEBUG[8783]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/81.201.82.29 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.33 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.33 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.33 - state 1 (Not in use) asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.32 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.32 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.32 - state 1 (Not in use) asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.31 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.31 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.31 - state 1 (Not in use) asterisk*CLI> [Mar 15 18:01:34] DEBUG[9363]: app_queue.c:546 changethread: Device 'SIP/81.201.82.33' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:34] DEBUG[9364]: app_queue.c:546 changethread: Device 'SIP/81.201.82.32' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.30 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.30 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.30 - state 1 (Not in use) asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 81.201.82.29 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 81.201.82.29 asterisk*CLI> [Mar 15 18:01:34] DEBUG[8765]: devicestate.c:287 do_state_change: Changing state for SIP/81.201.82.29 - state 1 (Not in use) asterisk*CLI> [Mar 15 18:01:34] DEBUG[9365]: app_queue.c:546 changethread: Device 'SIP/81.201.82.31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:34] DEBUG[9366]: app_queue.c:546 changethread: Device 'SIP/81.201.82.30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:34] DEBUG[9367]: app_queue.c:546 changethread: Device 'SIP/81.201.82.29' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk*CLI> [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Mar 15 18:01:34] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 85.119.188.2 [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) asterisk*CLI> [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Mar 15 18:01:34] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 85.119.188.2 [Mar 15 18:01:34] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to write format g729 [Mar 15 18:01:34] DEBUG[9360]: app_macro.c:245 _macro_exec: Oooh, got something to jump out with ('4')! [Mar 15 18:01:34] DEBUG[9360]: pbx.c:2374 __ast_pbx_run: Oooh, got something to jump out with ('4')! [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Mar 15 18:01:34] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) asterisk*CLI> [Mar 15 18:01:35] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 1 on 5/0 to 81.201.84.34:4569 asterisk*CLI> Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00001ms SCall: 00005 DCall: 00000 [81.201.84.34:4569] asterisk*CLI> [Mar 15 18:01:35] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 1 on 6/0 to 81.201.82.29:4569 asterisk*CLI> Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00001ms SCall: 00006 DCall: 00000 [81.201.82.29:4569] asterisk*CLI> [Mar 15 18:01:35] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 1 on 13/0 to 81.201.84.33:4569 asterisk*CLI> Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00001ms SCall: 00013 DCall: 00000 [81.201.84.33:4569] asterisk*CLI> [Mar 15 18:01:35] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 2 on 14/0 to 81.201.84.30:4569 asterisk*CLI> Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00002ms SCall: 00014 DCall: 00000 [81.201.84.30:4569] asterisk*CLI> [Mar 15 18:01:35] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 2 on 16/0 to 81.201.84.31:4569 asterisk*CLI> Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00002ms SCall: 00016 DCall: 00000 [81.201.84.31:4569] asterisk*CLI> [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 15 18:01:35] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 85.119.188.2 [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) asterisk*CLI> [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 15 18:01:35] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 85.119.188.2 [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 15 18:01:35] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) asterisk*CLI> [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 15 18:01:36] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at 85.119.188.2 [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 15 18:01:36] DEBUG[9360]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at 85.119.188.2 == CDR updated on SIP/028883282-08200428 [Mar 15 18:01:36] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Goto' -- Executing [456@incoming:1] Goto("SIP/028883282-08200428", "custom-incoming|s|2") in new stack -- Goto (custom-incoming,s,2) [Mar 15 18:01:36] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0473883858' [Mar 15 18:01:36] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' -- Executing [s@custom-incoming:2] NoOp("SIP/028883282-08200428", "Incoming call from 0473883858 ") in new stack [Mar 15 18:01:36] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Set' -- Executing [s@custom-incoming:3] Set("SIP/028883282-08200428", "CALLERID(num)=32473883858") in new stack [Mar 15 18:01:36] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'BackGround' -- Executing [s@custom-incoming:4] BackGround("SIP/028883282-08200428", "user_defined/raccrochez-callback") in new stack [Mar 15 18:01:36] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to write format gsm [Mar 15 18:01:36] DEBUG[9360]: rtp.c:2559 ast_rtp_raw_write: Difference is 15896, ms is 2007 -- Playing 'user_defined/raccrochez-callback' (language 'fr') [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 15 18:01:36] DEBUG[9360]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) asterisk*CLI> [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 18 [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 17 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 1 on 17/0 to 192.168.1.162:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00001ms SCall: 00017 DCall: 00000 [192.168.1.162:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00001ms SCall: 00432 DCall: 00017 [192.168.1.162:4569] [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 4) [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 4 received asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00001ms SCall: 00432 DCall: 00017 [192.168.1.162:4569] RR_JITTER : 0 [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:1650 send_packet: Sending 1 on 17/432 to 192.168.1.162:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00001ms SCall: 00017 DCall: 00432 [192.168.1.162:4569] [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:7110 socket_process: Peer 608: got pong, lastms 6, historicms 6, maxms 2000 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 19 [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:1258 find_callno: Creating new call structure 18 [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 20 [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 19 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 13 on 18/0 to 81.201.82.28:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00013ms SCall: 00018 DCall: 00000 [81.201.82.28:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 13 on 19/0 to 81.201.82.21:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00013ms SCall: 00019 DCall: 00000 [81.201.82.21:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00013ms SCall: 00002 DCall: 00018 [81.201.82.28:4569] [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 13 on 18/2 to 81.201.82.28:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00013ms SCall: 00018 DCall: 00002 [81.201.82.28:4569] [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.82.28: got pong, lastms 7, historicms 7, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00013ms SCall: 00002 DCall: 00019 [81.201.82.21:4569] [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 13 on 19/2 to 81.201.82.21:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00013ms SCall: 00019 DCall: 00002 [81.201.82.21:4569] [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:7110 socket_process: Peer 81.201.82.21: got pong, lastms 8, historicms 8, maxms 2000 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 21 [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:1258 find_callno: Creating new call structure 20 [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 36 [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:1258 find_callno: Creating new call structure 35 [Mar 15 18:01:39] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 37 [Mar 15 18:01:39] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 36 [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 38 [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 37 [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 43 [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 42 [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 44 [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 43 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 5 on 20/0 to 81.201.82.27:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00005ms SCall: 00020 DCall: 00000 [81.201.82.27:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 5 on 35/0 to 81.201.82.25:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00005ms SCall: 00035 DCall: 00000 [81.201.82.25:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 5 on 36/0 to 81.201.82.23:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00005ms SCall: 00036 DCall: 00000 [81.201.82.23:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 6 on 37/0 to 81.201.82.22:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 00037 DCall: 00000 [81.201.82.22:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 6 on 42/0 to 81.201.82.26:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 00042 DCall: 00000 [81.201.82.26:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 6 on 43/0 to 81.201.82.24:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 00043 DCall: 00000 [81.201.82.24:4569] asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00005ms SCall: 00002 DCall: 00020 [81.201.82.27:4569] [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 5 on 20/2 to 81.201.82.27:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00005ms SCall: 00020 DCall: 00002 [81.201.82.27:4569] [Mar 15 18:01:39] DEBUG[8772]: chan_iax2.c:7110 socket_process: Peer 81.201.82.27: got pong, lastms 8, historicms 8, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00005ms SCall: 00001 DCall: 00036 [81.201.82.23:4569] [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:1650 send_packet: Sending 5 on 36/1 to 81.201.82.23:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00005ms SCall: 00036 DCall: 00001 [81.201.82.23:4569] [Mar 15 18:01:39] DEBUG[8776]: chan_iax2.c:7110 socket_process: Peer 81.201.82.23: got pong, lastms 9, historicms 9, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00006ms SCall: 00002 DCall: 00037 [81.201.82.22:4569] [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 6 on 37/2 to 81.201.82.22:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00006ms SCall: 00037 DCall: 00002 [81.201.82.22:4569] [Mar 15 18:01:39] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.82.22: got pong, lastms 8, historicms 8, maxms 2000 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00005ms SCall: 00002 DCall: 00035 [81.201.82.25:4569] [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 5 on 35/2 to 81.201.82.25:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00005ms SCall: 00035 DCall: 00002 [81.201.82.25:4569] [Mar 15 18:01:39] DEBUG[8775]: chan_iax2.c:7110 socket_process: Peer 81.201.82.25: got pong, lastms 10, historicms 10, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00006ms SCall: 00003 DCall: 00042 [81.201.82.26:4569] [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 6 on 42/3 to 81.201.82.26:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00006ms SCall: 00042 DCall: 00003 [81.201.82.26:4569] [Mar 15 18:01:39] DEBUG[8773]: chan_iax2.c:7110 socket_process: Peer 81.201.82.26: got pong, lastms 9, historicms 9, maxms 2000 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00006ms SCall: 00003 DCall: 00043 [81.201.82.24:4569] [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 6 on 43/3 to 81.201.82.24:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00006ms SCall: 00043 DCall: 00003 [81.201.82.24:4569] [Mar 15 18:01:39] DEBUG[8767]: chan_iax2.c:7110 socket_process: Peer 81.201.82.24: got pong, lastms 10, historicms 10, maxms 2000 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 45 [Mar 15 18:01:39] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 44 [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 46 [Mar 15 18:01:39] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 45 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 13 on 44/0 to 85.119.188.2:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00013ms SCall: 00044 DCall: 00000 [85.119.188.2:4569] [Mar 15 18:01:39] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 13 on 45/0 to 80.92.86.39:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00013ms SCall: 00045 DCall: 00000 [80.92.86.39:4569] asterisk*CLI> [Mar 15 18:01:39] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:39] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.5 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:39] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5d71d099443887a164373eba3033fa98@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '5d71d099443887a164373eba3033fa98@192.168.1.7' Method: OPTIONS asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00013ms SCall: 00004 DCall: 00044 [85.119.188.2:4569] [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 13 on 44/4 to 85.119.188.2:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00013ms SCall: 00044 DCall: 00004 [85.119.188.2:4569] [Mar 15 18:01:39] DEBUG[8768]: chan_iax2.c:7110 socket_process: Peer 28889302: got pong, lastms 11, historicms 11, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00013ms SCall: 00167 DCall: 00045 [80.92.86.39:4569] [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:1650 send_packet: Sending 13 on 45/167 to 80.92.86.39:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00013ms SCall: 00045 DCall: 00167 [80.92.86.39:4569] [Mar 15 18:01:39] DEBUG[8769]: chan_iax2.c:7110 socket_process: Peer pchretien: got pong, lastms 14, historicms 14, maxms 2000 asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.161 with 192.168.1.0 [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.160 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7357b4bc0c8420717acba8a62fa4566e@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '7357b4bc0c8420717acba8a62fa4566e@192.168.1.7' Method: OPTIONS [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '686a2ee00c8a83441e5615be313adad0@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '686a2ee00c8a83441e5615be313adad0@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6e4ccfd129d6fda449440d5b7eab4bc4@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '6e4ccfd129d6fda449440d5b7eab4bc4@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:40] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 192.168.1.6 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '507e6fe3637785fa43f746ad5167fc18@192.168.1.7' of Request 102: Match Not Found Really destroying SIP dialog '507e6fe3637785fa43f746ad5167fc18@192.168.1.7' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:14629 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7462e3b9078031412d4d187d392d34b3@85.119.188.3 [Mar 15 18:01:40] DEBUG[8783]: chan_sip.c:14190 handle_request_bye: Received bye, issuing owner hangup asterisk*CLI> [Mar 15 18:01:40] WARNING[9360]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 15 18:01:40] DEBUG[9360]: channel.c:2845 set_format: Set channel SIP/028883282-08200428 to write format g729 [Mar 15 18:01:40] DEBUG[9360]: pbx.c:2389 __ast_pbx_run: Spawn extension (custom-incoming,s,4) exited non-zero on 'SIP/028883282-08200428' == Spawn extension (custom-incoming, s, 4) exited non-zero on 'SIP/028883282-08200428' [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' -- Executing [h@custom-incoming:1] System("SIP/028883282-08200428", "echo channel: SIP/voipcheap/0032473883858 >> /tmp/32473883858") in new stack asterisk*CLI> [Mar 15 18:01:40] NOTICE[9360]: pbx.c:1684 pbx_substitute_variables_helper_full: Error in extension logic (missing ']') [Mar 15 18:01:40] NOTICE[9360]: pbx.c:1609 pbx_substitute_variables_helper_full: Error in extension logic (missing '}') [Mar 15 18:01:40] WARNING[9360]: pbx.c:1508 func_args: Can't find trailing parenthesis? [Mar 15 18:01:40] ERROR[9360]: func_callerid.c:91 callerid_read: Unknown callerid data type 'n'. [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@custom-incoming:2] GotoIf("SIP/028883282-08200428", "") in new stack [Mar 15 18:01:40] WARNING[9360]: pbx.c:5957 pbx_builtin_gotoif: Ignoring, since there is no variable to check [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' -- Executing [h@custom-incoming:3] System("SIP/028883282-08200428", "echo context: pch-callback >> /tmp/32473883858") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'Goto' asterisk*CLI> -- Executing [h@custom-incoming:4] Goto("SIP/028883282-08200428", "6") in new stack asterisk*CLI> -- Goto (custom-incoming,h,6) asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:6] System("SIP/028883282-08200428", "echo extension: 32473883858 >> /tmp/32473883858") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:7] System("SIP/028883282-08200428", "echo priority: 1 >> /tmp/32473883858") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:8] System("SIP/028883282-08200428", "echo sleep 15 > /tmp/32473883858.2") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:9] System("SIP/028883282-08200428", "echo mv /tmp/32473883858 /var/spool/asterisk/outgoing >> /tmp/32473883858.2") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:10] System("SIP/028883282-08200428", "chmod 775 /tmp/32473883858.2") in new stack asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '32473883858' asterisk*CLI> [Mar 15 18:01:40] DEBUG[9360]: pbx.c:1791 pbx_extension_helper: Launching 'System' asterisk*CLI> -- Executing [h@custom-incoming:11] System("SIP/028883282-08200428", "/tmp/32473883858.2") in new stack asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.28 with 192.168.1.0 asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.28 is not local, substituting externip [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.20 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.20 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '1c0402d268ef579d227fd54b3f26c5e1@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '1c0402d268ef579d227fd54b3f26c5e1@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '71f9328c3dc1649031ee4d0a49a227f3@81.242.238.174' of Request 102: Match Not Found asterisk*CLI> Really destroying SIP dialog '71f9328c3dc1649031ee4d0a49a227f3@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 34 [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:1258 find_callno: Creating new call structure 33 [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 35 [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:1258 find_callno: Creating new call structure 34 [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 39 [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:1258 find_callno: Creating new call structure 38 [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 47 [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:1258 find_callno: Creating new call structure 46 [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 48 [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:1258 find_callno: Creating new call structure 47 [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 49 [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:1258 find_callno: Creating new call structure 48 [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 50 [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:1258 find_callno: Creating new call structure 49 [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 51 [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:1258 find_callno: Creating new call structure 50 [Mar 15 18:01:41] DEBUG[8769]: chan_iax2.c:1154 update_max_nontrunk: New max nontrunk callno is 52 [Mar 15 18:01:41] DEBUG[8769]: chan_iax2.c:1258 find_callno: Creating new call structure 51 asterisk*CLI> [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 17 on 33/0 to 81.201.84.29:4569 asterisk*CLI> Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00017ms SCall: 00033 DCall: 00000 [81.201.84.29:4569] asterisk*CLI> [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 17 on 34/0 to 81.201.84.26:4569 asterisk*CLI> Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00017ms SCall: 00034 DCall: 00000 [81.201.84.26:4569] asterisk*CLI> [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 17 on 38/0 to 81.201.84.28:4569 asterisk*CLI> Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00017ms SCall: 00038 DCall: 00000 [81.201.84.28:4569] asterisk*CLI> [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 18 on 46/0 to 81.201.84.27:4569 asterisk*CLI> Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00018ms SCall: 00046 DCall: 00000 [81.201.84.27:4569] asterisk*CLI> [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 18 on 47/0 to 81.201.84.23:4569 asterisk*CLI> Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE asterisk*CLI> Timestamp: 00018ms SCall: 00047 DCall: 00000 [81.201.84.23:4569] [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 18 on 48/0 to 81.201.84.25:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00018ms SCall: 00048 DCall: 00000 [81.201.84.25:4569] [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 18 on 49/0 to 81.201.84.21:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00018ms SCall: 00049 DCall: 00000 [81.201.84.21:4569] [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 18 on 50/0 to 81.201.84.22:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00018ms SCall: 00050 DCall: 00000 [81.201.84.22:4569] [Mar 15 18:01:41] DEBUG[8778]: chan_iax2.c:1650 send_packet: Sending 19 on 51/0 to 81.201.84.24:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00019ms SCall: 00051 DCall: 00000 [81.201.84.24:4569] asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.26 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.26 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2bd18b9c4779fb192ee527c1748aefee@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '2bd18b9c4779fb192ee527c1748aefee@81.242.238.174' Method: OPTIONS asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00017ms SCall: 00004 DCall: 00033 [81.201.84.29:4569] [Mar 15 18:01:41] DEBUG[8772]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8772]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8772]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8772]: chan_iax2.c:1650 send_packet: Sending 17 on 33/4 to 81.201.84.29:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 00033 DCall: 00004 [81.201.84.29:4569] [Mar 15 18:01:41] DEBUG[8772]: chan_iax2.c:7110 socket_process: Peer 81.201.84.29: got pong, lastms 89, historicms 89, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00017ms SCall: 00001 DCall: 00034 [81.201.84.26:4569] [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:1650 send_packet: Sending 17 on 34/1 to 81.201.84.26:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 00034 DCall: 00001 [81.201.84.26:4569] [Mar 15 18:01:41] DEBUG[8776]: chan_iax2.c:7110 socket_process: Peer 81.201.84.26: got pong, lastms 90, historicms 90, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00017ms SCall: 00003 DCall: 00038 [81.201.84.28:4569] [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:1650 send_packet: Sending 17 on 38/3 to 81.201.84.28:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 00038 DCall: 00003 [81.201.84.28:4569] [Mar 15 18:01:41] DEBUG[8770]: chan_iax2.c:7110 socket_process: Peer 81.201.84.28: got pong, lastms 91, historicms 91, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00018ms SCall: 00003 DCall: 00046 [81.201.84.27:4569] [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:1650 send_packet: Sending 18 on 46/3 to 81.201.84.27:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00018ms SCall: 00046 DCall: 00003 [81.201.84.27:4569] [Mar 15 18:01:41] DEBUG[8775]: chan_iax2.c:7110 socket_process: Peer 81.201.84.27: got pong, lastms 90, historicms 90, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00018ms SCall: 00003 DCall: 00048 [81.201.84.25:4569] [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:1650 send_packet: Sending 18 on 48/3 to 81.201.84.25:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00018ms SCall: 00048 DCall: 00003 [81.201.84.25:4569] [Mar 15 18:01:41] DEBUG[8773]: chan_iax2.c:7110 socket_process: Peer 81.201.84.25: got pong, lastms 91, historicms 91, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00018ms SCall: 00004 DCall: 00047 [81.201.84.23:4569] [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:1650 send_packet: Sending 18 on 47/4 to 81.201.84.23:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00018ms SCall: 00047 DCall: 00004 [81.201.84.23:4569] [Mar 15 18:01:41] DEBUG[8767]: chan_iax2.c:7110 socket_process: Peer 81.201.84.23: got pong, lastms 92, historicms 92, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00018ms SCall: 00001 DCall: 00049 [81.201.84.21:4569] [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:1650 send_packet: Sending 18 on 49/1 to 81.201.84.21:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00018ms SCall: 00049 DCall: 00001 [81.201.84.21:4569] [Mar 15 18:01:41] DEBUG[8774]: chan_iax2.c:7110 socket_process: Peer 81.201.84.21: got pong, lastms 92, historicms 92, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00018ms SCall: 00001 DCall: 00050 [81.201.84.22:4569] [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:1650 send_packet: Sending 18 on 50/1 to 81.201.84.22:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00018ms SCall: 00050 DCall: 00001 [81.201.84.22:4569] [Mar 15 18:01:41] DEBUG[8771]: chan_iax2.c:7110 socket_process: Peer 81.201.84.22: got pong, lastms 93, historicms 93, maxms 2000 asterisk*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00019ms SCall: 00001 DCall: 00051 [81.201.84.24:4569] [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:6494 socket_process: Received packet 0, (6, 3) [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:6591 socket_process: Cancelling transmission of packet 0 [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:6688 socket_process: IAX subclass 3 received [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:1650 send_packet: Sending 19 on 51/1 to 81.201.84.24:4569 Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00019ms SCall: 00051 DCall: 00001 [81.201.84.24:4569] [Mar 15 18:01:41] DEBUG[8768]: chan_iax2.c:7110 socket_process: Peer 81.201.84.24: got pong, lastms 92, historicms 92, maxms 2000 asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.25 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.25 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '3ecfac27669dbdbe56d0bd65712ebe79@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '3ecfac27669dbdbe56d0bd65712ebe79@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.24 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.24 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4454acf25ad179d84038bae10d2d3b53@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '4454acf25ad179d84038bae10d2d3b53@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.23 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.23 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0eb6f84c46a7a8c97e2fef7d6ce2c920@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '0eb6f84c46a7a8c97e2fef7d6ce2c920@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.22 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.22 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '3cab2f360b3465fc0f824725121501f0@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '3cab2f360b3465fc0f824725121501f0@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 81.201.82.21 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 81.201.82.21 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '31ec51d03b4a53da3d016d6929ad3897@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '31ec51d03b4a53da3d016d6929ad3897@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 85.119.188.3 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 85.119.188.3 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '345abc2112cf27fb353dc08f21faed49@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '345abc2112cf27fb353dc08f21faed49@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:41] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 85.119.188.3 with 192.168.1.0 [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 85.119.188.3 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:41] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6939a1c335748c123f83495b2def3798@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '6939a1c335748c123f83495b2def3798@81.242.238.174' Method: OPTIONS asterisk*CLI> [Mar 15 18:01:42] DEBUG[8783]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 18:01:42] DEBUG[8783]: acl.c:215 ast_apply_ha: ##### Testing 194.120.0.193 with 192.168.1.0 [Mar 15 18:01:42] DEBUG[8783]: chan_sip.c:1799 ast_sip_ouraddrfor: Target address 194.120.0.193 is not local, substituting externip asterisk*CLI> [Mar 15 18:01:42] DEBUG[8783]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '1359e62339d3b5b670f3ca70733955b9@81.242.238.174' of Request 102: Match Not Found Really destroying SIP dialog '1359e62339d3b5b670f3ca70733955b9@81.242.238.174' Method: OPTIONS asterisk*CLI>