[Jan 23 13:07:50] DEBUG[7060] acl.c: ##### Testing 192.168.10.6 with 192.168.0.0 [Jan 23 13:07:50] DEBUG[7060] acl.c: ##### Testing 192.168.10.6 with 83.22.229.40 [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on RTP to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on UDPTL to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Allocating new SIP dialog for 3164311a-58ef55b8@192.168.10.6 - INVITE (With RTP) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on RTP to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on UDPTL to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: = Found Their Call ID: 3164311a-58ef55b8@192.168.10.6 Their Tag 442649b2d9365600o0 Our tag: as0fed2c73 [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Stopping retransmission on '3164311a-58ef55b8@192.168.10.6' of Response 101: Match Not Found [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: = Found Their Call ID: 3164311a-58ef55b8@192.168.10.6 Their Tag 442649b2d9365600o0 Our tag: as0fed2c73 [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on RTP to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Setting NAT on UDPTL to Off [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: T38 state changed to 0 on channel [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Checking SIP call limits for device 106 [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Updating call counter for incoming call [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Call from peer '106' is 1 out of 2 [Jan 23 13:07:50] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/106 [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: This channel will not be able to handle video. [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: build_route: Contact hop: TOOTAI dh/is [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: SIP/106-0827e8d0: New call is still down.... Trying... [Jan 23 13:07:50] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/106-0827e8d0 [Jan 23 13:07:50] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/106 [Jan 23 13:07:50] DEBUG[7414] pbx.c: Launching 'Goto' [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Executing [107@WholeExtensions:1] Goto("SIP/106-0827e8d0", "dial-local|107|1") in new stack [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Goto (dial-local,107,1) [Jan 23 13:07:50] DEBUG[7414] pbx.c: Launching 'Set' [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Executing [107@dial-local:1] Set("SIP/106-0827e8d0", "GLOBAL(DIALEDNUMBER)=107") in new stack [Jan 23 13:07:50] VERBOSE[7414] logger.c: == Setting global variable 'DIALEDNUMBER' to '107' [Jan 23 13:07:50] DEBUG[7414] pbx.c: Launching 'Set' [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Executing [107@dial-local:2] Set("SIP/106-0827e8d0", "VoiceMail=u") in new stack [Jan 23 13:07:50] DEBUG[7414] pbx.c: Launching 'Playback' [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Executing [107@dial-local:3] Playback("SIP/106-0827e8d0", "2tai-searchcalledparty") in new stack [Jan 23 13:07:50] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/106-0827e8d0 [Jan 23 13:07:50] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/106 [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: SIP answering channel: SIP/106-0827e8d0 [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: Setting framing from config on incoming call [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: -- Done with adding codecs to SDP [Jan 23 13:07:50] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:50] DEBUG[7414] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 23 13:07:50] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format gsm [Jan 23 13:07:50] DEBUG[7414] rtp.c: Ooh, format changed from unknown to ulaw [Jan 23 13:07:50] DEBUG[7414] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 23 13:07:50] DEBUG[7414] channel.c: Scheduling timer at 160 sample intervals [Jan 23 13:07:50] VERBOSE[7414] logger.c: -- Playing '2tai-searchcalledparty' (language 'en') [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: Changing state for SIP/106 - state 2 (In use) [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106-0827e8d0 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106-0827e8d0 [Jan 23 13:07:50] DEBUG[7063] app_queue.c: Device 'SIP/106' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: = Found Their Call ID: 3164311a-58ef55b8@192.168.10.6 Their Tag 442649b2d9365600o0 Our tag: as759855ab [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 23 13:07:50] DEBUG[7060] chan_sip.c: Stopping retransmission on '3164311a-58ef55b8@192.168.10.6' of Response 102: Match Not Found [Jan 23 13:07:50] DEBUG[7016] devicestate.c: Changing state for SIP/106-0827e8d0 - state 4 (Invalid) [Jan 23 13:07:50] DEBUG[7063] app_queue.c: Device 'SIP/106-0827e8d0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: Changing state for SIP/106 - state 2 (In use) [Jan 23 13:07:50] DEBUG[7063] app_queue.c: Device 'SIP/106' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106-0827e8d0 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106-0827e8d0 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: Changing state for SIP/106-0827e8d0 - state 4 (Invalid) [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: Changing state for SIP/106 - state 2 (In use) [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:50] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:50] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:50] DEBUG[7063] app_queue.c: Device 'SIP/106-0827e8d0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:07:50] DEBUG[7063] app_queue.c: Device 'SIP/106' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 23 13:07:53] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:07:53] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:07:53] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format ulaw [Jan 23 13:07:53] DEBUG[7414] pbx.c: Launching 'Macro' [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Executing [107@dial-local:4] Macro("SIP/106-0827e8d0", "rec|") in new stack [Jan 23 13:07:53] DEBUG[7414] pbx.c: Expression result is '1' [Jan 23 13:07:53] DEBUG[7414] pbx.c: Launching 'GotoIf' [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Executing [s@macro-rec:1] GotoIf("SIP/106-0827e8d0", "1?end") in new stack [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Goto (macro-rec,s,5) [Jan 23 13:07:53] DEBUG[7414] app_macro.c: Executed application: GotoIf [Jan 23 13:07:53] DEBUG[7414] pbx.c: Launching 'MacroExit' [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Executing [s@macro-rec:5] MacroExit("SIP/106-0827e8d0", "") in new stack [Jan 23 13:07:53] DEBUG[7414] pbx.c: Function result is '101' [Jan 23 13:07:53] DEBUG[7414] pbx.c: Expression result is '0' [Jan 23 13:07:53] DEBUG[7414] pbx.c: Launching 'GotoIf' [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Executing [107@dial-local:5] GotoIf("SIP/106-0827e8d0", "0?extendedVM") in new stack [Jan 23 13:07:53] DEBUG[7414] pbx.c: Not taking any branch [Jan 23 13:07:53] DEBUG[7414] pbx.c: Launching 'Dial' [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Executing [107@dial-local:6] Dial("SIP/106-0827e8d0", "SIP/107|40|mT") in new stack [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Our T38 capability (3856) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Setting NAT on RTP to Off [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Setting NAT on UDPTL to Off [Jan 23 13:07:53] DEBUG[7414] acl.c: ##### Testing 192.168.10.7 with 192.168.0.0 [Jan 23 13:07:53] DEBUG[7414] acl.c: ##### Testing 192.168.10.7 with 83.22.229.40 [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: This channel will not be able to handle video. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable MACRO_DEPTH. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable PLAYBACKSTATUS. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable VoiceMail. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable SIPCALLID. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable SIPUSERAGENT. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable SIPDOMAIN. [Jan 23 13:07:53] DEBUG[7414] channel.c: Not copying variable SIPURI. [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Outgoing Call for DH-Poste1 [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Updating call counter for outgoing call [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Call to peer '107' is 1 out of 4 [Jan 23 13:07:53] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: -- Done with adding codecs to SDP [Jan 23 13:07:53] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [Jan 23 13:07:53] DEBUG[7414] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Called 107 [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- Started music on hold, class 'default', on SIP/106-0827e8d0 [Jan 23 13:07:53] DEBUG[7414] channel.c: Scheduling timer at 160 sample intervals [Jan 23 13:07:53] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:53] DEBUG[7414] channel.c: Generator got voice, switching to phase locked mode [Jan 23 13:07:53] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:07:53] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format slin [Jan 23 13:07:53] DEBUG[7414] res_musiconhold.c: SIP/106-0827e8d0 Opened file 0 '/var/lib/asterisk/moh/fpm-calm-river' [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 6 (Ringing) [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag Our tag: as3d8d7b70 [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' Request 102: Found [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: SIP response 100 to standard invite [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag Our tag: as3d8d7b70 [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' Request 102: Found [Jan 23 13:07:53] DEBUG[7060] chan_sip.c: SIP response 180 to standard invite [Jan 23 13:07:53] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/107-0823bac0 [Jan 23 13:07:53] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:07:53] VERBOSE[7414] logger.c: -- SIP/107-0823bac0 is ringing [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107-0823bac0 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107-0823bac0 [Jan 23 13:07:53] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:53] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:53] DEBUG[7016] devicestate.c: Changing state for SIP/107-0823bac0 - state 4 (Invalid) [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 6 (Ringing) [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:53] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:53] DEBUG[7063] app_queue.c: Device 'SIP/107-0823bac0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:07:53] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 23 13:07:53] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [...] Lots of this [Jan 23 13:07:56] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: Acked pending invite 102 [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: Stopping retransmission on '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' of Request 102: Match Not Found [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: SIP response 200 to standard invite [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: T38 state changed to 0 on channel SIP/107-0823bac0 [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: We have an owner, now see if we need to change this call [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: Updating call counter for outgoing call [Jan 23 13:07:56] DEBUG[7060] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:07:56] DEBUG[7060] chan_sip.c: build_route: Contact hop: [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 2 (In use) [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107-0823bac0 [Jan 23 13:07:56] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:07:56] VERBOSE[7414] logger.c: -- SIP/107-0823bac0 answered SIP/106-0827e8d0 [Jan 23 13:07:56] VERBOSE[7414] logger.c: -- Stopped music on hold on SIP/106-0827e8d0 [Jan 23 13:07:56] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format ulaw [Jan 23 13:07:56] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:07:56] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107-0823bac0 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107-0823bac0 [Jan 23 13:07:56] DEBUG[7414] rtp.c: Ooh, format changed from unknown to ulaw [Jan 23 13:07:56] DEBUG[7414] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: Changing state for SIP/107-0823bac0 - state 4 (Invalid) [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 2 (In use) [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:07:56] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:07:56] DEBUG[7063] app_queue.c: Device 'SIP/107-0823bac0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:07:56] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 23 13:07:56] DEBUG[7029] chan_iax2.c: Allocate call number [Jan 23 13:07:56] DEBUG[7029] chan_iax2.c: Registration created on call 4 [Jan 23 13:07:57] VERBOSE[7020] logger.c: JABBER: googletalk INCOMING: [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: T38 state changed to 0 on channel SIP/107-0823bac0 [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: We have an owner, now see if we need to change this call [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: SIP/107-0823bac0: This call is UP.... [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: Setting framing from config on incoming call [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: -- Done with adding codecs to SDP [Jan 23 13:07:58] DEBUG[7060] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 23 13:07:58] VERBOSE[7414] logger.c: -- Started music on hold, class 'default', on SIP/106-0827e8d0 [Jan 23 13:07:58] DEBUG[7414] channel.c: Scheduling timer at 160 sample intervals [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 23 13:07:58] DEBUG[7060] chan_sip.c: Stopping retransmission on '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' of Response 55310: Match Found [Jan 23 13:07:58] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:07:58] DEBUG[7414] channel.c: Generator got voice, switching to phase locked mode [Jan 23 13:07:58] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:07:58] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format slin [Jan 23 13:07:58] DEBUG[7414] res_musiconhold.c: SIP/106-0827e8d0 Opened file 0 '/var/lib/asterisk/moh/fpm-calm-river' [Jan 23 13:07:58] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [...] Lots of this [Jan 23 13:08:06] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:06] DEBUG[7039] devicestate.c: Notification of state change to be queued on device/channel IAX2/fax-line2 [Jan 23 13:08:06] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for IAX2 - fax-line2 [Jan 23 13:08:06] DEBUG[7016] chan_iax2.c: Checking device state for device fax-line2 [Jan 23 13:08:06] DEBUG[7016] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax-line2? addr=16777343, defaddr=0 maxms=0, lastms=0 [Jan 23 13:08:06] DEBUG[7016] devicestate.c: Changing state for IAX2/fax-line2 - state 1 (Not in use) [Jan 23 13:08:06] DEBUG[7063] app_queue.c: Device 'IAX2/fax-line2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:06] DEBUG[7039] devicestate.c: Notification of state change to be queued on device/channel IAX2/fax [Jan 23 13:08:06] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for IAX2 - fax [Jan 23 13:08:06] DEBUG[7016] chan_iax2.c: Checking device state for device fax [Jan 23 13:08:06] DEBUG[7016] devicestate.c: Changing state for IAX2/fax - state 4 (Invalid) [Jan 23 13:08:06] DEBUG[7063] app_queue.c: Device 'IAX2/fax' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:08:06] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:06] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:07] DEBUG[7042] devicestate.c: Notification of state change to be queued on device/channel IAX2/fax-line1 [Jan 23 13:08:07] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for IAX2 - fax-line1 [Jan 23 13:08:07] DEBUG[7016] chan_iax2.c: Checking device state for device fax-line1 [Jan 23 13:08:07] DEBUG[7016] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax-line1? addr=16777343, defaddr=0 maxms=0, lastms=0 [Jan 23 13:08:07] DEBUG[7016] devicestate.c: Changing state for IAX2/fax-line1 - state 1 (Not in use) [Jan 23 13:08:07] DEBUG[7063] app_queue.c: Device 'IAX2/fax-line1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:07] DEBUG[7042] devicestate.c: Notification of state change to be queued on device/channel IAX2/fax [Jan 23 13:08:07] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for IAX2 - fax [Jan 23 13:08:07] DEBUG[7016] chan_iax2.c: Checking device state for device fax [Jan 23 13:08:07] DEBUG[7016] devicestate.c: Changing state for IAX2/fax - state 4 (Invalid) [Jan 23 13:08:07] DEBUG[7063] app_queue.c: Device 'IAX2/fax' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:08:07] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [...] Lots of this [Jan 23 13:08:09] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:09] DEBUG[7060] chan_sip.c: Auto destroying SIP dialog '4434656a63f0ad1a146cb0ec2348b40e@192.168.10.250' [Jan 23 13:08:09] DEBUG[7060] chan_sip.c: Destroying SIP dialog 4434656a63f0ad1a146cb0ec2348b40e@192.168.10.250 [Jan 23 13:08:09] VERBOSE[7060] logger.c: Really destroying SIP dialog '4434656a63f0ad1a146cb0ec2348b40e@192.168.10.250' Method: REGISTER [Jan 23 13:08:09] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [...] Lots of this [Jan 23 13:08:13] DEBUG[7414] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: T38 state changed to 0 on channel SIP/107-0823bac0 [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: We have an owner, now see if we need to change this call [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: SIP/107-0823bac0: This call is UP.... [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: Setting framing from config on incoming call [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: -- Done with adding codecs to SDP [Jan 23 13:08:13] DEBUG[7060] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 23 13:08:13] VERBOSE[7414] logger.c: -- Stopped music on hold on SIP/106-0827e8d0 [Jan 23 13:08:13] DEBUG[7414] channel.c: Set channel SIP/106-0827e8d0 to write format ulaw [Jan 23 13:08:13] DEBUG[7414] channel.c: Scheduling timer at 0 sample intervals [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 23 13:08:13] DEBUG[7060] chan_sip.c: Stopping retransmission on '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' of Response 55311: Match Found [Jan 23 13:08:13] DEBUG[7414] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 23 13:08:17] DEBUG[7060] chan_sip.c: = No match Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:08:17] DEBUG[7060] chan_sip.c: = No match Their Call ID: 3164311a-58ef55b8@192.168.10.6 Their Tag 442649b2d9365600o0 Our tag: as759855ab [Jan 23 13:08:17] DEBUG[7060] acl.c: ##### Testing 217.119.64.58 with 192.168.0.0 [Jan 23 13:08:17] DEBUG[7060] acl.c: ##### Testing 217.119.64.58 with 83.22.229.40 [Jan 23 13:08:17] DEBUG[7060] chan_sip.c: Target address 217.119.64.58 is not local, substituting externip [Jan 23 13:08:17] DEBUG[7060] chan_sip.c: Allocating new SIP dialog for 7d2f51d542f977c600d3aea423d3fba1@217.119.64.58 - OPTIONS (No RTP) [Jan 23 13:08:17] DEBUG[7060] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: = No match Their Call ID: 7d2f51d542f977c600d3aea423d3fba1@217.119.64.58 Their Tag as69c1f3d1 Our tag: as2d852453 [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: = Found Their Call ID: 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 Their Tag 828da32eb84c9ddc Our tag: as3d8d7b70 [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250 [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: Received bye, issuing owner hangup [Jan 23 13:08:21] DEBUG[7414] channel.c: Didn't get a frame from channel: SIP/107-0823bac0 [Jan 23 13:08:21] DEBUG[7414] channel.c: Bridge stops bridging channels SIP/106-0827e8d0 and SIP/107-0823bac0 [Jan 23 13:08:21] DEBUG[7414] channel.c: Hanging up channel 'SIP/107-0823bac0' [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Hangup call SIP/107-0823bac0, SIP callid 1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250) [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Updating call counter for outgoing call [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Call to peer '107' removed from call limit 4 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107-0823bac0 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/107 [Jan 23 13:08:21] DEBUG[7414] rtp.c: Channel '' has no RTP, not doing anything [Jan 23 13:08:21] DEBUG[7414] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 23 13:08:21] DEBUG[7414] pbx.c: Spawn extension (dial-local,107,6) exited non-zero on 'SIP/106-0827e8d0' [Jan 23 13:08:21] VERBOSE[7414] logger.c: == Spawn extension (dial-local, 107, 6) exited non-zero on 'SIP/106-0827e8d0' [Jan 23 13:08:21] DEBUG[7414] channel.c: Soft-Hanging up channel 'SIP/106-0827e8d0' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Launching 'Hangup' [Jan 23 13:08:21] VERBOSE[7414] logger.c: -- Executing [h@dial-local:1] Hangup("SIP/106-0827e8d0", "") in new stack [Jan 23 13:08:21] DEBUG[7414] pbx.c: Spawn extension (dial-local,h,1) exited non-zero on 'SIP/106-0827e8d0' [Jan 23 13:08:21] VERBOSE[7414] logger.c: == Spawn extension (dial-local, h, 1) exited non-zero on 'SIP/106-0827e8d0' [Jan 23 13:08:21] DEBUG[7414] channel.c: Hanging up channel 'SIP/106-0827e8d0' [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Hangup call SIP/106-0827e8d0, SIP callid 3164311a-58ef55b8@192.168.10.6) [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Updating call counter for incoming call [Jan 23 13:08:21] DEBUG[7414] chan_sip.c: Call from peer '106' removed from call limit 2 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/106 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/106-0827e8d0 [Jan 23 13:08:21] DEBUG[7414] devicestate.c: Notification of state change to be queued on device/channel SIP/106 [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '2008-01-23 13:07:50' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '107' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '2008-01-23 13:07:50' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '2008-01-23 13:08:21' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '31' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is 'ANSWERED' [Jan 23 13:08:21] DEBUG[7414] pbx.c: Function result is '"Tootai" <101>' [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 1 (Not in use) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107-0823bac0 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107-0823bac0 [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:21] VERBOSE[7060] logger.c: Really destroying SIP dialog '1f3b03875888e1e14d3fe1a33f0a2afb@192.168.10.250' Method: BYE [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: = No match Their Call ID: 7d2f51d542f977c600d3aea423d3fba1@217.119.64.58 Their Tag as69c1f3d1 Our tag: as2d852453 [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: = Found Their Call ID: 3164311a-58ef55b8@192.168.10.6 Their Tag 442649b2d9365600o0 Our tag: as759855ab [Jan 23 13:08:21] DEBUG[7060] chan_sip.c: Stopping retransmission on '3164311a-58ef55b8@192.168.10.6' of Request 102: Match Not Found [Jan 23 13:08:21] VERBOSE[7060] logger.c: Really destroying SIP dialog '3164311a-58ef55b8@192.168.10.6' Method: ACK [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/107-0823bac0 - state 4 (Invalid) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/107 - state 1 (Not in use) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/106 - state 1 (Not in use) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106-0827e8d0 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106-0827e8d0 [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/107-0823bac0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/107' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/106' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/106-0827e8d0 - state 4 (Invalid) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: Changing state for SIP/106 - state 1 (Not in use) [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 101 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 101 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 104 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 104 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 107 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 107 [Jan 23 13:08:21] DEBUG[7016] devicestate.c: No provider found, checking channel drivers for SIP - 106 [Jan 23 13:08:21] DEBUG[7016] chan_sip.c: Checking device state for peer 106 [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/106-0827e8d0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 23 13:08:21] DEBUG[7063] app_queue.c: Device 'SIP/106' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 23 13:08:27] DEBUG[7035] chan_iax2.c: Allocate call number [Jan 23 13:08:27] DEBUG[7035] chan_iax2.c: Registration created on call 7 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Allocating new SIP dialog for 2f9f8ca31210902463875ed958479a05@192.168.10.250 - REGISTER (No RTP) [Jan 23 13:08:28] DEBUG[7060] acl.c: ##### Testing 217.10.79.9 with 192.168.0.0 [Jan 23 13:08:28] DEBUG[7060] acl.c: ##### Testing 217.10.79.9 with 83.22.229.40 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Target address 217.10.79.9 is not local, substituting externip [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Scheduled a registration timeout for sipgate.de id #578 [Jan 23 13:08:28] VERBOSE[7060] logger.c: REGISTER attempt 1 to 5553238@sipgate.de [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Allocating new SIP dialog for 65441d5424000f15244b772456981b3d@192.168.10.250 - REGISTER (No RTP) [Jan 23 13:08:28] DEBUG[7060] acl.c: ##### Testing 213.203.241.243 with 192.168.0.0 [Jan 23 13:08:28] DEBUG[7060] acl.c: ##### Testing 213.203.241.243 with 83.22.229.40 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Target address 213.203.241.243 is not local, substituting externip [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Scheduled a registration timeout for tootaiAUDIO id #580 [Jan 23 13:08:28] VERBOSE[7060] logger.c: REGISTER attempt 1 to tootaiVOIP@tootaiAUDIO [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: = No match Their Call ID: 65441d5424000f15244b772456981b3d@192.168.10.250 Their Tag Our tag: as0fd55828 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: = Found Their Call ID: 2f9f8ca31210902463875ed958479a05@192.168.10.250 Their Tag Our tag: as2bb681c6 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Stopping retransmission on '2f9f8ca31210902463875ed958479a05@192.168.10.250' of Request 140: Match Not Found [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Registration successful [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Cancelling timeout 578 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: = Found Their Call ID: 65441d5424000f15244b772456981b3d@192.168.10.250 Their Tag Our tag: as0fd55828 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '65441d5424000f15244b772456981b3d@192.168.10.250' Request 158: Found [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: = Found Their Call ID: 65441d5424000f15244b772456981b3d@192.168.10.250 Their Tag Our tag: as0fd55828 [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Stopping retransmission on '65441d5424000f15244b772456981b3d@192.168.10.250' of Request 158: Match Not Found [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: Initializing already initialized SIP dialog 65441d5424000f15244b772456981b3d@192.168.10.250 (presumably reinvite) [Jan 23 13:08:28] VERBOSE[7060] logger.c: REGISTER attempt 2 to tootaiVOIP@tootaiAUDIO [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: = Found Their Call ID: 65441d5424000f15244b772456981b3d@192.168.10.250 Their Tag Our tag: as64d51cdd [Jan 23 13:08:28] DEBUG[7060] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '65441d5424000f15244b772456981b3d@192.168.10.250' Request 159: Found [Jan 23 13:08:29] DEBUG[7060] chan_sip.c: = Found Their Call ID: 65441d5424000f15244b772456981b3d@192.168.10.250 Their Tag Our tag: as64d51cdd [Jan 23 13:08:29] DEBUG[7060] chan_sip.c: Stopping retransmission on '65441d5424000f15244b772456981b3d@192.168.10.250' of Request 159: Match Not Found [Jan 23 13:08:29] DEBUG[7060] chan_sip.c: Registration successful