[Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Executing [107@WholeExtensions:1] Goto("SIP/106-b6b1d120", "dial-local|107|1") in new stack [Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Goto (dial-local,107,1) [Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Executing [107@dial-local:1] Set("SIP/106-b6b1d120", "GLOBAL(DIALEDNUMBER)=107") in new stack [Jan 24 18:02:54] VERBOSE[21042] logger.c: == Setting global variable 'DIALEDNUMBER' to '107' [Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Executing [107@dial-local:2] Set("SIP/106-b6b1d120", "VoiceMail=u") in new stack [Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Executing [107@dial-local:3] Playback("SIP/106-b6b1d120", "2tai-searchcalledparty") in new stack [Jan 24 18:02:54] VERBOSE[21042] logger.c: -- Playing '2tai-searchcalledparty' (language 'en') [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Executing [107@dial-local:4] Macro("SIP/106-b6b1d120", "rec|") in new stack [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Executing [s@macro-rec:1] GotoIf("SIP/106-b6b1d120", "1?end") in new stack [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Goto (macro-rec,s,5) [Jan 24 18:02:57] DEBUG[21042] app_macro.c: Executed application: GotoIf [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Executing [s@macro-rec:5] MacroExit("SIP/106-b6b1d120", "") in new stack [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Executing [107@dial-local:5] GotoIf("SIP/106-b6b1d120", "0?extendedVM") in new stack [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Executing [107@dial-local:6] Dial("SIP/106-b6b1d120", "SIP/107|40|") in new stack [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- Called 107 [Jan 24 18:02:57] VERBOSE[21042] logger.c: -- SIP/107-08287b68 is ringing [Jan 24 18:02:58] VERBOSE[21042] logger.c: -- SIP/107-08287b68 answered SIP/106-b6b1d120 [Jan 24 18:02:58] VERBOSE[21042] logger.c: -- Packet2Packet bridging SIP/106-b6b1d120 and SIP/107-08287b68 [Jan 24 18:03:00] VERBOSE[21042] logger.c: -- Started music on hold, class 'default', on SIP/106-b6b1d120 [Jan 24 18:03:20] VERBOSE[21042] logger.c: -- Stopped music on hold on SIP/106-b6b1d120 [Jan 24 18:03:20] VERBOSE[21042] logger.c: == Spawn extension (dial-local, 107, 6) exited non-zero on 'SIP/106-b6b1d120' [Jan 24 18:03:20] VERBOSE[21042] logger.c: -- Executing [h@dial-local:1] Hangup("SIP/106-b6b1d120", "") in new stack [Jan 24 18:03:20] VERBOSE[21042] logger.c: == Spawn extension (dial-local, h, 1) exited non-zero on 'SIP/106-b6b1d120' [Jan 24 18:03:40] DEBUG[12861] chan_iax2.c: Allocate call number [Jan 24 18:03:40] DEBUG[12861] chan_iax2.c: Registration created on call 2 [Jan 24 18:03:40] DEBUG[13897] acl.c: ##### Testing 192.168.10.6 with 192.168.0.0 [Jan 24 18:03:40] DEBUG[13897] acl.c: ##### Testing 192.168.10.6 with 83.22.207.232 [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on RTP to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on UDPTL to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Allocating new SIP dialog for f7886649-5cb076c4@192.168.10.6 - INVITE (With RTP) [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on RTP to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on UDPTL to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Stopping retransmission on 'f7886649-5cb076c4@192.168.10.6' of Response 101: Match Not Found [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on RTP to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Setting NAT on UDPTL to Off [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Checking SIP call limits for device 106 [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Call from peer '106' is 1 out of 2 [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: build_route: Contact hop: TOOTAI dh/is [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: SIP/106-b6b08208: New call is still down.... Trying... [Jan 24 18:03:40] DEBUG[21043] pbx.c: Launching 'Goto' [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Executing [107@WholeExtensions:1] Goto("SIP/106-b6b08208", "dial-local|107|1") in new stack [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Goto (dial-local,107,1) [Jan 24 18:03:40] DEBUG[21043] pbx.c: Launching 'Set' [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Executing [107@dial-local:1] Set("SIP/106-b6b08208", "GLOBAL(DIALEDNUMBER)=107") in new stack [Jan 24 18:03:40] VERBOSE[21043] logger.c: == Setting global variable 'DIALEDNUMBER' to '107' [Jan 24 18:03:40] DEBUG[21043] pbx.c: Launching 'Set' [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Executing [107@dial-local:2] Set("SIP/106-b6b08208", "VoiceMail=u") in new stack [Jan 24 18:03:40] DEBUG[21043] pbx.c: Launching 'Playback' [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Executing [107@dial-local:3] Playback("SIP/106-b6b08208", "2tai-searchcalledparty") in new stack [Jan 24 18:03:40] DEBUG[21043] chan_sip.c: SIP answering channel: SIP/106-b6b08208 [Jan 24 18:03:40] DEBUG[21043] chan_sip.c: Setting framing from config on incoming call [Jan 24 18:03:40] DEBUG[21043] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 24 18:03:40] DEBUG[21043] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 24 18:03:40] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format gsm [Jan 24 18:03:40] DEBUG[21043] rtp.c: Ooh, format changed from unknown to ulaw [Jan 24 18:03:40] DEBUG[21043] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 24 18:03:40] DEBUG[21043] channel.c: Scheduling timer at 160 sample intervals [Jan 24 18:03:40] VERBOSE[21043] logger.c: -- Playing '2tai-searchcalledparty' (language 'en') [Jan 24 18:03:40] DEBUG[13897] chan_sip.c: Stopping retransmission on 'f7886649-5cb076c4@192.168.10.6' of Response 102: Match Not Found [Jan 24 18:03:41] DEBUG[13897] chan_sip.c: Auto destroying SIP dialog '358e60567d5a659745c8f8cb6574ae72@217.119.64.58' [Jan 24 18:03:44] DEBUG[21043] channel.c: Scheduling timer at 0 sample intervals [Jan 24 18:03:44] DEBUG[21043] channel.c: Scheduling timer at 0 sample intervals [Jan 24 18:03:44] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format ulaw [Jan 24 18:03:44] DEBUG[21043] pbx.c: Launching 'Macro' [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Executing [107@dial-local:4] Macro("SIP/106-b6b08208", "rec|") in new stack [Jan 24 18:03:44] DEBUG[21043] pbx.c: Expression result is '1' [Jan 24 18:03:44] DEBUG[21043] pbx.c: Launching 'GotoIf' [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Executing [s@macro-rec:1] GotoIf("SIP/106-b6b08208", "1?end") in new stack [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Goto (macro-rec,s,5) [Jan 24 18:03:44] DEBUG[21043] app_macro.c: Executed application: GotoIf [Jan 24 18:03:44] DEBUG[21043] pbx.c: Launching 'MacroExit' [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Executing [s@macro-rec:5] MacroExit("SIP/106-b6b08208", "") in new stack [Jan 24 18:03:44] DEBUG[21043] pbx.c: Function result is '101' [Jan 24 18:03:44] DEBUG[21043] pbx.c: Expression result is '0' [Jan 24 18:03:44] DEBUG[21043] pbx.c: Launching 'GotoIf' [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Executing [107@dial-local:5] GotoIf("SIP/106-b6b08208", "0?extendedVM") in new stack [Jan 24 18:03:44] DEBUG[21043] pbx.c: Not taking any branch [Jan 24 18:03:44] DEBUG[21043] pbx.c: Launching 'Dial' [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Executing [107@dial-local:6] Dial("SIP/106-b6b08208", "SIP/107|40|") in new stack [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Our T38 capability (3856) [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Setting NAT on RTP to Off [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Setting NAT on UDPTL to Off [Jan 24 18:03:44] DEBUG[21043] acl.c: ##### Testing 192.168.10.7 with 192.168.0.0 [Jan 24 18:03:44] DEBUG[21043] acl.c: ##### Testing 192.168.10.7 with 83.22.207.232 [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable MACRO_DEPTH. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable PLAYBACKSTATUS. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable VoiceMail. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable SIPCALLID. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable SIPUSERAGENT. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable SIPDOMAIN. [Jan 24 18:03:44] DEBUG[21043] channel.c: Not copying variable SIPURI. [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Outgoing Call for DH-Poste1 [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Call to peer '107' is 1 out of 4 [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jan 24 18:03:44] DEBUG[21043] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- Called 107 [Jan 24 18:03:44] DEBUG[13897] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b37f9d73127f9727a4409650eec010b@192.168.10.250' Request 102: Found [Jan 24 18:03:44] DEBUG[13897] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b37f9d73127f9727a4409650eec010b@192.168.10.250' Request 102: Found [Jan 24 18:03:44] VERBOSE[21043] logger.c: -- SIP/107-082853f0 is ringing [Jan 24 18:03:44] DEBUG[21043] channel.c: Driver for channel 'SIP/106-b6b08208' does not support indication 3, emulating it [Jan 24 18:03:44] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format slin [Jan 24 18:03:44] DEBUG[21043] channel.c: Scheduling timer at 160 sample intervals [Jan 24 18:03:44] DEBUG[21043] channel.c: Generator got voice, switching to phase locked mode [Jan 24 18:03:44] DEBUG[21043] channel.c: Scheduling timer at 0 sample intervals [Jan 24 18:03:45] DEBUG[13897] chan_sip.c: Acked pending invite 102 [Jan 24 18:03:45] DEBUG[13897] chan_sip.c: Stopping retransmission on '1b37f9d73127f9727a4409650eec010b@192.168.10.250' of Request 102: Match Not Found [Jan 24 18:03:45] DEBUG[13897] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 24 18:03:45] DEBUG[13897] chan_sip.c: build_route: Contact hop: [Jan 24 18:03:45] VERBOSE[21043] logger.c: -- SIP/107-082853f0 answered SIP/106-b6b08208 [Jan 24 18:03:45] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format ulaw [Jan 24 18:03:45] DEBUG[21043] channel.c: Scheduling timer at 0 sample intervals [Jan 24 18:03:45] VERBOSE[21043] logger.c: -- Packet2Packet bridging SIP/106-b6b08208 and SIP/107-082853f0 [Jan 24 18:03:47] DEBUG[12853] chan_iax2.c: Allocate call number [Jan 24 18:03:47] DEBUG[12853] chan_iax2.c: Registration created on call 9 [Jan 24 18:03:47] DEBUG[13897] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jan 24 18:03:47] DEBUG[13897] chan_sip.c: SIP/107-082853f0: This call is UP.... [Jan 24 18:03:47] DEBUG[13897] chan_sip.c: Setting framing from config on incoming call [Jan 24 18:03:47] DEBUG[13897] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 24 18:03:47] DEBUG[13897] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 24 18:03:47] VERBOSE[21043] logger.c: -- Started music on hold, class 'default', on SIP/106-b6b08208 [Jan 24 18:03:47] DEBUG[21043] channel.c: Scheduling timer at 160 sample intervals [Jan 24 18:03:47] DEBUG[21043] channel.c: Generator got voice, switching to phase locked mode [Jan 24 18:03:47] DEBUG[21043] channel.c: Scheduling timer at 0 sample intervals [Jan 24 18:03:47] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format slin [Jan 24 18:03:47] DEBUG[21043] res_musiconhold.c: SIP/106-b6b08208 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine' [Jan 24 18:03:48] DEBUG[13897] chan_sip.c: SIP/107-082853f0: This call is UP.... [Jan 24 18:03:48] DEBUG[13897] chan_sip.c: Setting framing from config on incoming call [Jan 24 18:03:48] DEBUG[13897] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 24 18:03:48] DEBUG[13897] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 24 18:03:50] DEBUG[12871] chan_iax2.c: Allocate call number [Jan 24 18:03:50] DEBUG[12871] chan_iax2.c: Registration created on call 1 [Jan 24 18:03:50] DEBUG[13897] chan_sip.c: SIP/107-082853f0: This call is UP.... [Jan 24 18:03:50] DEBUG[13897] chan_sip.c: Setting framing from config on incoming call [Jan 24 18:03:50] DEBUG[13897] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 24 18:03:50] DEBUG[13897] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 24 18:03:54] DEBUG[13897] chan_sip.c: SIP/107-082853f0: This call is UP.... [Jan 24 18:03:54] DEBUG[13897] chan_sip.c: Setting framing from config on incoming call [Jan 24 18:03:54] DEBUG[13897] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 24 18:03:54] DEBUG[13897] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 24 18:03:56] DEBUG[13897] chan_sip.c: Auto destroying SIP dialog '0afe9e4c279ebdf26940947053aaa88c@192.168.10.250' [Jan 24 18:03:56] DEBUG[13897] chan_sip.c: Call to peer '107' removed from call limit 4 [Jan 24 18:03:56] DEBUG[13897] chan_sip.c: This call did not properly clean up call limits. Call ID 0afe9e4c279ebdf26940947053aaa88c@192.168.10.250 [Jan 24 18:03:57] DEBUG[12884] chan_iax2.c: Allocate call number [Jan 24 18:03:57] DEBUG[12884] chan_iax2.c: Registration created on call 3 [Jan 24 18:03:58] DEBUG[12867] chan_iax2.c: Allocate call number [Jan 24 18:03:58] DEBUG[12867] chan_iax2.c: Registration created on call 10 [Jan 24 18:04:07] DEBUG[21043] rtp.c: Oooh, got a hangup [Jan 24 18:04:07] DEBUG[21043] channel.c: Returning from native bridge, channels: SIP/106-b6b08208, SIP/107-082853f0 [Jan 24 18:04:07] DEBUG[21043] channel.c: Hanging up channel 'SIP/107-082853f0' [Jan 24 18:04:07] DEBUG[21043] chan_sip.c: Hangup call SIP/107-082853f0, SIP callid 1b37f9d73127f9727a4409650eec010b@192.168.10.250) [Jan 24 18:04:07] DEBUG[21043] chan_sip.c: Call to peer '107' removed from call limit 4 [Jan 24 18:04:07] DEBUG[21043] rtp.c: Channel '' has no RTP, not doing anything [Jan 24 18:04:07] DEBUG[21043] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 24 18:04:07] DEBUG[21043] pbx.c: Spawn extension (dial-local,107,6) exited non-zero on 'SIP/106-b6b08208' [Jan 24 18:04:07] VERBOSE[21043] logger.c: == Spawn extension (dial-local, 107, 6) exited non-zero on 'SIP/106-b6b08208' [Jan 24 18:04:07] DEBUG[21043] channel.c: Soft-Hanging up channel 'SIP/106-b6b08208' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Launching 'Hangup' [Jan 24 18:04:07] VERBOSE[21043] logger.c: -- Executing [h@dial-local:1] Hangup("SIP/106-b6b08208", "") in new stack [Jan 24 18:04:07] DEBUG[21043] pbx.c: Spawn extension (dial-local,h,1) exited non-zero on 'SIP/106-b6b08208' [Jan 24 18:04:07] VERBOSE[21043] logger.c: == Spawn extension (dial-local, h, 1) exited non-zero on 'SIP/106-b6b08208' [Jan 24 18:04:07] VERBOSE[21043] logger.c: -- Stopped music on hold on SIP/106-b6b08208 [Jan 24 18:04:07] DEBUG[21043] channel.c: Set channel SIP/106-b6b08208 to write format ulaw [Jan 24 18:04:07] DEBUG[21043] channel.c: Hanging up channel 'SIP/106-b6b08208' [Jan 24 18:04:07] DEBUG[21043] chan_sip.c: Hangup call SIP/106-b6b08208, SIP callid f7886649-5cb076c4@192.168.10.6) [Jan 24 18:04:07] DEBUG[21043] chan_sip.c: Call from peer '106' removed from call limit 2 [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '2008-01-24 18:03:40' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '107' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '2008-01-24 18:03:40' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '2008-01-24 18:04:07' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '27' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is 'ANSWERED' [Jan 24 18:04:07] DEBUG[21043] pbx.c: Function result is '"Tootai" <101>' [Jan 24 18:04:07] DEBUG[13897] chan_sip.c: Call to peer '107' removed from call limit 4 [Jan 24 18:04:07] DEBUG[13897] chan_sip.c: This call did not properly clean up call limits. Call ID 1b37f9d73127f9727a4409650eec010b@192.168.10.250 [Jan 24 18:04:07] DEBUG[13897] chan_sip.c: Stopping retransmission on 'f7886649-5cb076c4@192.168.10.6' of Request 102: Match Not Found