May 25 12:56:18 DEBUG[3980] chan_sip.c: = No match Their Call ID: 3b2c07de1c4c07653bf5aa075ea5fe7e@215.188.142.204 Their Tag Our tag: as2a1de9ba May 25 12:56:18 DEBUG[3980] chan_sip.c: Allocating new SIP dialog for f11df202-24a6e588-379af02b@215.188.128.77 - INVITE (With RTP) May 25 12:56:18 DEBUG[3980] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE May 25 12:56:18 DEBUG[3980] chan_sip.c: * SIP extension value: 2 for call f11df202-24a6e588-379af02b@215.188.128.77 May 25 12:56:18 DEBUG[3980] chan_sip.c: Setting NAT on RTP to 0 May 25 12:56:18 DEBUG[3980] chan_sip.c: = Found Their Call ID: f11df202-24a6e588-379af02b@215.188.128.77 Their Tag 9CAB775E-EFDB5229 Our tag: as597b2ede May 25 12:56:18 DEBUG[3980] chan_sip.c: **** Received ACK (6) - Command in SIP ACK May 25 12:56:18 DEBUG[3980] chan_sip.c: Stopping retransmission on 'f11df202-24a6e588-379af02b@215.188.128.77' of Response 1: Match Found May 25 12:56:18 DEBUG[3980] chan_sip.c: = Found Their Call ID: f11df202-24a6e588-379af02b@215.188.128.77 Their Tag 9CAB775E-EFDB5229 Our tag: as597b2ede May 25 12:56:18 DEBUG[3980] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE May 25 12:56:18 DEBUG[3980] chan_sip.c: Setting NAT on RTP to 0 May 25 12:56:18 DEBUG[3980] chan_sip.c: Checking SIP call limits for device 2944093 May 25 12:56:18 DEBUG[3980] chan_sip.c: Updating call counter for incoming call May 25 12:56:18 DEBUG[3980] chan_sip.c: build_route: Contact hop: May 25 12:56:18 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:18 DEBUG[3968] devicestate.c: Changing state for SIP/2944093 - state 2 (In use) May 25 12:56:18 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:18 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:18 DEBUG[3995] app_queue.c: Device 'SIP/2944093' changed to state '2' (In use) May 25 12:56:18 DEBUG[3994] pbx.c: Launching 'AGI' May 25 12:56:18 VERBOSE[3994] logger.c: -- Executing AGI("SIP/2944093-2eaa", "ipt/originator.py") in new stack May 25 12:56:18 VERBOSE[3994] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/ipt/originator.py May 25 12:56:18 VERBOSE[3994] logger.c: -- AGI Script Executing Application: (ChanIsAvail) Options: (SIP/@proxy2) May 25 12:56:18 DEBUG[3994] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) May 25 12:56:18 DEBUG[3994] chan_sip.c: Setting NAT on RTP to 0 May 25 12:56:18 DEBUG[3994] channel.c: Hanging up channel 'SIP/proxy2-fa6e' May 25 12:56:18 DEBUG[3994] chan_sip.c: Hangup call SIP/proxy2-fa6e, SIP callid 404671747ab382f877bb16ae03ca4167@ipt.twoeighty.com) May 25 12:56:18 DEBUG[3994] chan_sip.c: update_call_counter() - decrement call limit counter May 25 12:56:18 DEBUG[3994] chan_sip.c: Updating call counter for incoming call May 25 12:56:18 DEBUG[3968] chan_sip.c: Checking device state for peer proxy2 May 25 12:56:18 DEBUG[3968] devicestate.c: Changing state for SIP/proxy2 - state 1 (Not in use) May 25 12:56:18 VERBOSE[3994] logger.c: -- AGI Script Executing Application: (Dial) Options: (SIP/11101553813033372500@proxy2|180|trg) May 25 12:56:18 DEBUG[3997] app_queue.c: Device 'SIP/proxy2' changed to state '1' (Not in use) May 25 12:56:18 DEBUG[3994] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) May 25 12:56:18 DEBUG[3994] chan_sip.c: Setting NAT on RTP to 0 May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable AVAILSTATUS. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable AVAILORIGCHAN. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable AVAILCHAN. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable Foo. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable SPYGROUP. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable STACK-pbx_one_start-13033372500-1. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable SIPCALLID. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable SIPUSERAGENT. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable SIPDOMAIN. May 25 12:56:18 DEBUG[3994] channel.c: Not copying variable SIPURI. May 25 12:56:18 DEBUG[3994] chan_sip.c: Outgoing Call for 11101553813033372500 May 25 12:56:18 DEBUG[3994] chan_sip.c: Updating call counter for outgoing call May 25 12:56:18 VERBOSE[3994] logger.c: -- Called 11101553813033372500@proxy2 May 25 12:56:18 DEBUG[3980] chan_sip.c: = Found Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag Our tag: as375fe45e May 25 12:56:18 DEBUG[3980] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com' Request 102: Found May 25 12:56:18 DEBUG[3980] chan_sip.c: SIP response 100 to standard invite May 25 12:56:18 DEBUG[3980] chan_sip.c: = Found Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag Our tag: as375fe45e May 25 12:56:18 DEBUG[3980] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com' Request 102: Found May 25 12:56:18 DEBUG[3980] chan_sip.c: SIP response 100 to standard invite May 25 12:56:21 DEBUG[3980] chan_sip.c: = Found Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag 1c1731190080 Our tag: as375fe45e May 25 12:56:21 DEBUG[3980] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com' Request 102: Found May 25 12:56:21 DEBUG[3980] chan_sip.c: SIP response 180 to standard invite May 25 12:56:21 DEBUG[3968] chan_sip.c: Checking device state for peer proxy2 May 25 12:56:21 DEBUG[3968] channel.c: Avoiding initial deadlock for 'SIP/proxy2-cf3e' May 25 12:56:21 VERBOSE[3994] logger.c: -- SIP/proxy2-cf3e is ringing May 25 12:56:21 VERBOSE[3994] logger.c: -- SIP/proxy2-cf3e is making progress passing it to SIP/2944093-2eaa May 25 12:56:21 DEBUG[3968] devicestate.c: Changing state for SIP/proxy2 - state 6 (Ringing) May 25 12:56:21 DEBUG[3998] app_queue.c: Device 'SIP/proxy2' changed to state '6' (Ringing) May 25 12:56:21 DEBUG[3994] rtp.c: Got RTCP report of 44 bytes May 25 12:56:22 DEBUG[3980] chan_sip.c: = Found Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag 1c1731190080 Our tag: as375fe45e May 25 12:56:22 DEBUG[3980] chan_sip.c: Acked pending invite 102 May 25 12:56:22 DEBUG[3980] chan_sip.c: Stopping retransmission on '0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com' of Request 102: Match Found May 25 12:56:22 DEBUG[3980] chan_sip.c: SIP response 200 to standard invite May 25 12:56:22 DEBUG[3980] chan_sip.c: build_route: Record-Route hop: May 25 12:56:22 DEBUG[3968] chan_sip.c: Checking device state for peer proxy2 May 25 12:56:22 VERBOSE[3994] logger.c: -- SIP/proxy2-cf3e answered SIP/2944093-2eaa May 25 12:56:22 DEBUG[3994] channel.c: Set channel SIP/2944093-2eaa to read format ulaw May 25 12:56:22 DEBUG[3994] channel.c: Set channel SIP/proxy2-cf3e to write format ulaw May 25 12:56:22 DEBUG[3994] channel.c: Set channel SIP/proxy2-cf3e to read format ulaw May 25 12:56:22 DEBUG[3994] channel.c: Set channel SIP/2944093-2eaa to write format ulaw May 25 12:56:22 DEBUG[3968] devicestate.c: Changing state for SIP/proxy2 - state 2 (In use) May 25 12:56:22 DEBUG[3994] chan_sip.c: sip_answer(SIP/2944093-2eaa) May 25 12:56:22 VERBOSE[3994] logger.c: -- Attempting native bridge of SIP/2944093-2eaa and SIP/proxy2-cf3e May 25 12:56:22 DEBUG[3999] app_queue.c: Device 'SIP/proxy2' changed to state '2' (In use) May 25 12:56:22 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:22 DEBUG[3968] devicestate.c: Changing state for SIP/2944093 - state 2 (In use) May 25 12:56:22 DEBUG[4000] app_queue.c: Device 'SIP/2944093' changed to state '2' (In use) May 25 12:56:22 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:22 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:22 DEBUG[3994] rtp.c: Ooh, format changed from unknown to ulaw May 25 12:56:22 DEBUG[3980] chan_sip.c: = No match Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag 1c1731190080 Our tag: as375fe45e May 25 12:56:22 DEBUG[3980] chan_sip.c: = Found Their Call ID: f11df202-24a6e588-379af02b@215.188.128.77 Their Tag 9CAB775E-EFDB5229 Our tag: as219be310 May 25 12:56:22 DEBUG[3980] chan_sip.c: **** Received ACK (6) - Command in SIP ACK May 25 12:56:22 DEBUG[3980] chan_sip.c: Stopping retransmission on 'f11df202-24a6e588-379af02b@215.188.128.77' of Response 2: Match Found May 25 12:56:22 DEBUG[3994] rtp.c: Ooh, format changed from unknown to ulaw May 25 12:56:22 NOTICE[3994] rtp.c: Unknown RTP codec 96 received May 25 12:56:24 DEBUG[3980] chan_sip.c: = No match Their Call ID: 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com Their Tag 1c1731190080 Our tag: as375fe45e May 25 12:56:24 DEBUG[3980] chan_sip.c: = Found Their Call ID: f11df202-24a6e588-379af02b@215.188.128.77 Their Tag 9CAB775E-EFDB5229 Our tag: as219be310 May 25 12:56:24 DEBUG[3980] chan_sip.c: **** Received BYE (8) - Command in SIP BYE May 25 12:56:24 DEBUG[3994] channel.c: Didn't get a frame from channel: SIP/2944093-2eaa May 25 12:56:24 DEBUG[3994] channel.c: Bridge stops bridging channels SIP/2944093-2eaa and SIP/proxy2-cf3e May 25 12:56:24 DEBUG[3994] channel.c: Hanging up channel 'SIP/proxy2-cf3e' May 25 12:56:24 DEBUG[3994] chan_sip.c: Hangup call SIP/proxy2-cf3e, SIP callid 0110fe79696dd8f34bcf83ff31b834c1@ipt.twoeighty.com) May 25 12:56:24 DEBUG[3994] chan_sip.c: update_call_counter(11101553813033372500) - decrement call limit counter May 25 12:56:24 DEBUG[3994] chan_sip.c: Updating call counter for outgoing call May 25 12:56:24 DEBUG[3994] app_dial.c: Exiting with DIALSTATUS=ANSWER. May 25 12:56:24 DEBUG[3968] chan_sip.c: Checking device state for peer proxy2 May 25 12:56:24 DEBUG[3994] res_agi.c: SIP/2944093-2eaa hungup May 25 12:56:24 DEBUG[3968] devicestate.c: Changing state for SIP/proxy2 - state 1 (Not in use) May 25 12:56:24 DEBUG[3994] pbx.c: Spawn extension (pbx_one_start,13033372500,1) exited non-zero on 'SIP/2944093-2eaa' May 25 12:56:24 DEBUG[4001] app_queue.c: Device 'SIP/proxy2' changed to state '1' (Not in use) May 25 12:56:24 DEBUG[3994] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. May 25 12:56:24 DEBUG[3994] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO pbx_ast_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-05-25 12:56:18','\"OneEighty Communications\" <4062944000>','4062944000','13033372500','pbx_one_start', 'SIP/2944093-2eaa','SIP/proxy2-cf3e','Dial','SIP/11101553813033372500@proxy2|180|trg',6,2,'ANSWERED',3,'2944093') May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '"OneEighty Communications" <4062944000>' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '4062944000' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '13033372500' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'pbx_one_start' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'SIP/2944093-2eaa' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'SIP/proxy2-cf3e' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'Dial' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'SIP/11101553813033372500@proxy2|180|trg' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '2006-05-25 12:56:18' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '2006-05-25 12:56:22' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '2006-05-25 12:56:24' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '6' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '2' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'ANSWERED' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is 'DOCUMENTATION' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '2944093' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '1148583378.0' May 25 12:56:24 DEBUG[3994] pbx.c: Function result is '(null)' May 25 12:56:24 DEBUG[3994] channel.c: Hanging up channel 'SIP/2944093-2eaa' May 25 12:56:24 DEBUG[3994] chan_sip.c: Hangup call SIP/2944093-2eaa, SIP callid f11df202-24a6e588-379af02b@215.188.128.77) May 25 12:56:24 DEBUG[3994] chan_sip.c: update_call_counter(2944093) - decrement call limit counter May 25 12:56:24 DEBUG[3994] chan_sip.c: Updating call counter for incoming call May 25 12:56:24 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:24 DEBUG[3968] devicestate.c: Changing state for SIP/2944093 - state 1 (Not in use) May 25 12:56:24 DEBUG[4002] app_queue.c: Device 'SIP/2944093' changed to state '1' (Not in use) May 25 12:56:24 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093 May 25 12:56:24 DEBUG[3968] chan_sip.c: Checking device state for peer 2944093