[2007-03-06 11:59:01] 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 11:59:01] DEBUG[24379] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [2007-03-06 11:59:03] 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 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Allocating new SIP dialog for 22BE63EC-1DD2-11B2-8D8A-88C768BD418A@172.16.0.192 - INVITE (With RTP) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: = Found Their Call ID: 22BE63EC-1DD2-11B2-8D8A-88C768BD418A@172.16.0.192 Their Tag 6670339882051972020 Our tag: as4df25123 [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Stopping retransmission on '22BE63EC-1DD2-11B2-8D8A-88C768BD418A@172.16.0.192' of Response 1: Match Found [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: = Found Their Call ID: 22BE63EC-1DD2-11B2-8D8A-88C768BD418A@172.16.0.192 Their Tag 6670339882051972020 Our tag: as4df25123 [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on RTP to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting NAT on UDPTL to Off [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: T38 state changed to 0 on channel [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Checking SIP call limits for device 5050 [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Updating call counter for incoming call [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: *** Our capabilities are 0x8010c (ulaw|alaw|g729|h263) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: This channel will not be able to handle video. [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: build_route: Contact hop: [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: SIP/5050-0865f5c8: New call is still down.... Trying... [2007-03-06 11:59:03] DEBUG[24379] devicestate.c: Notification of state change to be queued on device/channel SIP/5050-0865f5c8 [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'Macro' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Expression result is '0' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'GotoIf' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Expression result is '0' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'GotoIf' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Function result is '5050' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Expression result is '0' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'GotoIf' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Expression result is '1' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'GotoIf' [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Not taking any branch [2007-03-06 11:59:03] DEBUG[24379] pbx.c: Launching 'FollowMe' [2007-03-06 11:59:03] DEBUG[24379] app_followme.c: New profile 5050. [2007-03-06 11:59:03] DEBUG[24379] app_followme.c: Created a number, 5050, order of , 1, with a timeout of 30. [2007-03-06 11:59:03] WARNING[24379] file.c: File followme/status does not exist in any format [2007-03-06 11:59:03] WARNING[24379] file.c: Unable to open followme/status (format 0x4 (ulaw)): No such file or directory [2007-03-06 11:59:03] DEBUG[24379] app.c: play_and_record: vm-rec-name, /var/spool/asterisk/followme.1173193143.8, 'sln' [2007-03-06 11:59:03] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Setting framing from config on incoming call [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: -- Done with adding codecs to SDP [2007-03-06 11:59:03] DEBUG[24379] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [2007-03-06 11:59:03] DEBUG[24379] rtp.c: Ooh, format changed from unknown to ulaw [2007-03-06 11:59:03] DEBUG[24379] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2007-03-06 11:59:03] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals [2007-03-06 11:59:03] DEBUG[24379] devicestate.c: No provider found, checking channel drivers for SIP - 5050 [2007-03-06 11:59:03] DEBUG[24379] chan_sip.c: Checking device state for peer 5050 [2007-03-06 11:59:03] DEBUG[24379] devicestate.c: Changing state for SIP/5050 - state 1 (Not in use) [2007-03-06 11:59:03] 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 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 119 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw [2007-03-06 11:59:07] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format gsm [2007-03-06 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:07] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw [2007-03-06 11:59:07] DEBUG[24379] app.c: Recording Formats: sfmts=sln [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192 [2007-03-06 11:59:09] DTMF[24379] channel.c: DTMF begin '#' received on SIP/5050-0865f5c8 [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192 [2007-03-06 11:59:09] DTMF[24379] channel.c: DTMF end '#' received on SIP/5050-0865f5c8, duration 280 ms [2007-03-06 11:59:09] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin [2007-03-06 11:59:09] DEBUG[24379] rtp.c: Difference is 12016, ms is 1522 [2007-03-06 11:59:09] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:09] DEBUG[24379] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [2007-03-06 11:59:10] DEBUG[24379] channel.c: Scheduling timer at 149 sample intervals [2007-03-06 11:59:10] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:10] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:10] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw [2007-03-06 11:59:10] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format slin [2007-03-06 11:59:10] DEBUG[24379] channel.c: Scheduling timer at 160 sample intervals [2007-03-06 11:59:10] DEBUG[24379] channel.c: Scheduling timer at 0 sample intervals [2007-03-06 11:59:10] DEBUG[24379] channel.c: Set channel SIP/5050-0865f5c8 to write format ulaw [2007-03-06 11:59:10] WARNING[24379] file.c: File followme/pls-hold-while-try does not exist in any format [2007-03-06 11:59:10] WARNING[24379] file.c: Unable to open followme/pls-hold-while-try (format 0x4 (ulaw)): No such file or directory [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Launching 'Goto' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Launching 'ResetCDR' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '"Caio Begotti" <5050>' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '5050' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '5050' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'extensions' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'SIP/5050-0865f5c8' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'ResetCDR' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'w' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '2007-03-06 11:59:03' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '2007-03-06 11:59:10' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '7' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '0' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'NO ANSWER' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is 'DOCUMENTATION' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '1173193143.8' [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Function result is '' [2007-03-06 11:59:10] DEBUG[24379] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Launching 'NoCDR' [2007-03-06 11:59:10] NOTICE[24379] cdr.c: CDR on channel 'SIP/5050-0865f5c8' not posted [2007-03-06 11:59:10] NOTICE[24379] cdr.c: CDR on channel 'SIP/5050-0865f5c8' lacks end [2007-03-06 11:59:10] DEBUG[24379] pbx.c: Launching 'Wait' [2007-03-06 11:59:11] DEBUG[24379] pbx.c: Launching 'Hangup' [2007-03-06 11:59:11] DEBUG[24379] pbx.c: Spawn extension (hangupcall,s,4) exited non-zero on 'SIP/5050-0865f5c8' [2007-03-06 11:59:11] DEBUG[24379] channel.c: Hanging up channel 'SIP/5050-0865f5c8' [2007-03-06 11:59:11] DEBUG[24379] chan_sip.c: Hangup call SIP/5050-0865f5c8, SIP callid 22BE63EC-1DD2-11B2-8D8A-88C768BD418A@172.16.0.192) [2007-03-06 11:59:11] DEBUG[24379] chan_sip.c: Hanging up channel in state Ring (not UP) [2007-03-06 11:59:11] DEBUG[24379] chan_sip.c: AST hangup cause 16 (no match found in SIP)