[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: = No match Their Call ID: 6F0CF8F4-1DD2-11B2-8D89-88C768BD418A@172.16.0.192 Their Tag 666732512426875611 Our tag: as74f09520
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Allocating new SIP dialog for E9147644-1DD1-11B2-8D8B-88C768BD418A@172.16.0.192 - INVITE (With RTP)
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: = Found Their Call ID: E9147644-1DD1-11B2-8D8B-88C768BD418A@172.16.0.192 Their Tag 6673667411299028669 Our tag: as319e41f5
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Stopping retransmission on 'E9147644-1DD1-11B2-8D8B-88C768BD418A@172.16.0.192' of Response 1: Match Found
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: = Found Their Call ID: E9147644-1DD1-11B2-8D8B-88C768BD418A@172.16.0.192 Their Tag 6673667411299028669 Our tag: as319e41f5
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: T38 state changed to 0 on channel <none>
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw)
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Checking SIP call limits for device 5050
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Updating call counter for incoming call
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) 
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: *** Our capabilities are 0x8010c (ulaw|alaw|g729|h263) 
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: This channel will not be able to handle video.
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: build_route: Contact hop: <sip:5050@172.16.0.192:5060>
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: SIP/5050-0865f5c8: New call is still down.... Trying... 
[2007-03-06 12:04:36] DEBUG[24379] devicestate.c: Notification of state change to be queued on device/channel SIP/5050-0865f5c8
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'Macro'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Function result is '5050'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Expression result is '1'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Not taking any branch
[2007-03-06 12:04:36] DEBUG[24379] pbx.c: Launching 'FollowMe'
[2007-03-06 12:04:36] DEBUG[24379] app_followme.c: New profile 5050.
[2007-03-06 12:04:36] DEBUG[24379] app_followme.c: Created a number, 5050, order of , 1, with a timeout of 30.
[2007-03-06 12:04:36] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Setting framing from config on incoming call
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: -- Done with adding codecs to SDP
[2007-03-06 12:04:36] DEBUG[24379] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29)
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[2007-03-06 12:04:36] DEBUG[24379] rtp.c: Ooh, format changed from unknown to ulaw
[2007-03-06 12:04:36] DEBUG[24379] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[2007-03-06 12:04:36] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:36] DEBUG[24379] devicestate.c: No provider found, checking channel drivers for SIP - 5050
[2007-03-06 12:04:36] DEBUG[24379] chan_sip.c: Checking device state for peer 5050
[2007-03-06 12:04:36] DEBUG[24379] devicestate.c: Changing state for SIP/5050 - state 1 (Not in use)
[2007-03-06 12:04:36] DEBUG[24379] app_queue.c: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Scheduling timer at 76 sample intervals
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:41] DEBUG[24379] app.c: play_and_record: vm-rec-name, /var/spool/asterisk/followme.1173193476.9, 'sln'
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin
[2007-03-06 12:04:41] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:41] DEBUG[24379] chan_sip.c: = No match Their Call ID: E9147644-1DD1-11B2-8D8B-88C768BD418A@172.16.0.192 Their Tag 6673667411299028669 Our tag: as0fff4fe3
[2007-03-06 12:04:41] DEBUG[24379] chan_sip.c: = Found Their Call ID: 6F0CF8F4-1DD2-11B2-8D89-88C768BD418A@172.16.0.192 Their Tag 666732512426875611 Our tag: as74f09520
[2007-03-06 12:04:41] DEBUG[24379] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 119 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format gsm
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:45] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:45] DEBUG[24379] app.c: Recording Formats: sfmts=sln
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192
[2007-03-06 12:04:46] DTMF[24379] channel.c: DTMF begin '#' received on SIP/5050-0865f5c8
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192
[2007-03-06 12:04:46] DTMF[24379] channel.c: DTMF end '#' received on SIP/5050-0865f5c8, duration 280 ms
[2007-03-06 12:04:46] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: Difference is 7592, ms is 969
[2007-03-06 12:04:46] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:46] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 149 sample intervals
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin
[2007-03-06 12:04:47] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Scheduling timer at 9 sample intervals
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Prodding channel 'SIP/5050-0865f5c8'
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals
[2007-03-06 12:04:53] DEBUG[24379] app_followme.c: Number 5050 timeout 30
[2007-03-06 12:04:53] DEBUG[24379] app_followme.c: examining 5050
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-macro-dialinexten-s-10.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable MACRO_DEPTH.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-macro-dialinexten-s-9.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-macro-dialinexten-s-5.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-macro-dialinexten-s-2.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-macro-dialinexten-s-1.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable ARG1.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable MACRO_PRIORITY.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable MACRO_CONTEXT.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable MACRO_EXTEN.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable STACK-extensions-5050-1.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable SIPCALLID.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable SIPDOMAIN.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Not copying variable SIPURI.
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'Macro'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Function result is '5050'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Expression result is '0'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Expression result is '1'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'GotoIf'
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Not taking any branch
[2007-03-06 12:04:53] DEBUG[24379] pbx.c: Launching 'FollowMe'
[2007-03-06 12:04:53] DEBUG[24379] app_followme.c: New profile 5050.
[2007-03-06 12:04:53] DEBUG[24379] app_followme.c: Created a number, 5050, order of , 1, with a timeout of 30.
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29)
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Generator got voice, switching to phase locked mode
[2007-03-06 12:04:53] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals