[2010-01-13 14:17:18] DEBUG[14166] pbx.c: Launching 'Set'
[2010-01-13 14:17:18] VERBOSE[14166] logger.c:     -- Executing [92299720@default:1] Set("SIP/13321-000007e7", "uniqueid=1263399438.4788") in new stack
[2010-01-13 14:17:18] DEBUG[14166] pbx.c: Launching 'Set'
[2010-01-13 14:17:18] VERBOSE[14166] logger.c:     -- Executing [92299720@default:2] Set("SIP/13321-000007e7", "extension=92299720") in new stack
[2010-01-13 14:17:18] DEBUG[14166] pbx.c: Function result is '13321'
[2010-01-13 14:17:18] DEBUG[14166] pbx.c: Launching 'Set'
[2010-01-13 14:17:18] VERBOSE[14166] logger.c:     -- Executing [92299720@default:3] Set("SIP/13321-000007e7", "callerid=13321") in new stack
[2010-01-13 14:17:18] DEBUG[14166] pbx.c: Launching 'AGI'
[2010-01-13 14:17:18] VERBOSE[14166] logger.c:     -- Executing [92299720@default:4] AGI("SIP/13321-000007e7", "/home/totalip/ipserver/handlers/sip_handler.rb") in new stack
[2010-01-13 14:17:18] VERBOSE[14166] logger.c:     -- Launched AGI Script /home/totalip/ipserver/handlers/sip_handler.rb
[2010-01-13 14:17:19] VERBOSE[14166] logger.c:     -- AGI Script Executing Application: (SETMUSICONHOLD) Options: (12)
[2010-01-13 14:17:19] VERBOSE[14166] logger.c:     -- AGI Script Executing Application: (DIAL) Options: (SIP/mobile2/92299720|60|S(2400)T)
[2010-01-13 14:17:19] VERBOSE[14166] logger.c:     -- Setting call duration limit to 2400 seconds.
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Asked to create a SIP channel with formats: 0x100 (g729)
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Setting NAT on RTP to On
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: *** Our native formats are 0x100 (g729) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: *** Our capabilities are 0x10c (ulaw|alaw|g729) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: *** Our preferred formats from the incoming channel are 0x100 (g729) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: This channel will not be able to handle video.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable DIALEDTIME.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable ANSWEREDTIME.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable DIALEDPEERNAME.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable DIALEDPEERNUMBER.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable DIALSTATUS.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable callerid.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable extension.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable uniqueid.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable SIPCALLID.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable SIPUSERAGENT.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable SIPDOMAIN.
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Not copying variable SIPURI.
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Outgoing Call for 92299720
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Updating call counter for outgoing call
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Call to peer 'mobile2' is 2 out of 4
[2010-01-13 14:17:19] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/mobile2
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: False
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: ** Our prefcodec: 0x100 (g729) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: -- Done with adding codecs to SDP
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729)
[2010-01-13 14:17:19] VERBOSE[14166] logger.c:     -- Called mobile2/92299720
[2010-01-13 14:17:19] VERBOSE[14166] logger.c:     -- SIP/mobile2-000007e9 is making progress passing it to SIP/13321-000007e7
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Setting framing from config on incoming call
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: -- Done with adding codecs to SDP
[2010-01-13 14:17:19] DEBUG[14166] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[2010-01-13 14:17:19] DEBUG[14166] chan_sip.c: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729)
[2010-01-13 14:17:19] DEBUG[14166] rtp.c: Got RTCP report of 132 bytes
[2010-01-13 14:17:19] DEBUG[14166] rtp.c: Ooh, format changed from unknown to alaw
[2010-01-13 14:17:19] DEBUG[14166] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[2010-01-13 14:17:19] DEBUG[14166] rtp.c: Ooh, format changed from unknown to g729
[2010-01-13 14:17:19] DEBUG[14166] rtp.c: Created smoother: format: 256 ms: 20 len: 20
[2010-01-13 14:17:22] DEBUG[14166] rtp.c: Got RTCP report of 176 bytes
[2010-01-13 14:17:24] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:25] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:25] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:26] DEBUG[14166] rtp.c: Got RTCP report of 176 bytes
[2010-01-13 14:17:29] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:29] DEBUG[14166] rtp.c: Got RTCP report of 176 bytes
[2010-01-13 14:17:31] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:31] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:33] DEBUG[14166] rtp.c: Got RTCP report of 176 bytes
[2010-01-13 14:17:34] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:36] DEBUG[14166] rtp.c: Got RTCP report of 176 bytes
[2010-01-13 14:17:37] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:37] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:39] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:39] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/mobile2
[2010-01-13 14:17:39] VERBOSE[14166] logger.c:     -- SIP/mobile2-000007e9 answered SIP/13321-000007e7
[2010-01-13 14:17:39] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/13321
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: SIP answering channel: SIP/13321-000007e7
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: Setting framing from config on incoming call
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: -- Done with adding codecs to SDP
[2010-01-13 14:17:39] DEBUG[14166] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[2010-01-13 14:17:39] DEBUG[14166] chan_sip.c: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729)
[2010-01-13 14:17:40] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:43] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:43] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:43] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:44] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:45] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:45] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:47] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:49] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:49] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:49] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:50] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:51] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:51] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:54] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:54] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:17:55] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:55] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:57] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:17:57] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:17:57] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:17:59] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:18:00] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:18:01] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:18:01] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:18:03] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:18:03] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:18:04] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:18:04] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:18:07] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:18:07] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:18:07] DEBUG[14166] rtp.c: Got RTCP report of 200 bytes
[2010-01-13 14:18:09] DEBUG[14166] rtp.c: Got RTCP report of 64 bytes
[2010-01-13 14:18:09] DEBUG[14166] rtp.c: Got RTCP report of 44 bytes
[2010-01-13 14:18:09] DEBUG[14166] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.2.197:19827
[2010-01-13 14:18:11] DEBUG[14166] rtp.c: Got RTCP report of 208 bytes
[2010-01-13 14:18:11] DEBUG[14166] channel.c: Didn't get a frame from channel: SIP/13321-000007e7
[2010-01-13 14:18:11] DEBUG[14166] channel.c: Bridge stops bridging channels SIP/13321-000007e7 and SIP/mobile2-000007e9
[2010-01-13 14:18:11] DEBUG[14166] cdr.c: CDR detaching from this thread
[2010-01-13 14:18:11] DEBUG[14166] channel.c: Hanging up channel 'SIP/mobile2-000007e9'
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Hangup call SIP/mobile2-000007e9, SIP callid 45bdf017441cc4ad00e020ef528921f9@192.168.1.6)
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Updating call counter for outgoing call
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Call to peer 'mobile2' removed from call limit 4
[2010-01-13 14:18:11] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/mobile2
[2010-01-13 14:18:11] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/mobile2
[2010-01-13 14:18:11] DEBUG[14166] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[2010-01-13 14:18:11] DEBUG[14166] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[2010-01-13 14:18:11] ERROR[14166] utils.c: write() returned error: Broken pipe
[2010-01-13 14:18:11] VERBOSE[14166] logger.c:     -- AGI Script /home/totalip/ipserver/handlers/sip_handler.rb completed, returning 0
[2010-01-13 14:18:11] DEBUG[14166] pbx.c: Extension 92299720, priority 4 returned normally even though call was hung up
[2010-01-13 14:18:11] DEBUG[14166] channel.c: Soft-Hanging up channel 'SIP/13321-000007e7'
[2010-01-13 14:18:11] DEBUG[14166] channel.c: Hanging up channel 'SIP/13321-000007e7'
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Hangup call SIP/13321-000007e7, SIP callid YmE2MmFkMGE0ZjlmNmFkNGZhNTVmZGU4YTIxMzUxMWM.)
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Updating call counter for incoming call
[2010-01-13 14:18:11] DEBUG[14166] chan_sip.c: Call from peer '13321' removed from call limit 6
[2010-01-13 14:18:11] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/13321
[2010-01-13 14:18:11] DEBUG[14166] devicestate.c: Notification of state change to be queued on device/channel SIP/13321