[2007-03-28 16:09:07] DEBUG[15858] app_voicemail.c: /var/spool/asterisk/voicemail/default/5050/busy doesn't exist, doing what we can
[2007-03-28 16:09:07] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:07] DEBUG[15858] rtp.c: Ooh, format changed from unknown to alaw
[2007-03-28 16:09:07] DEBUG[15858] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[2007-03-28 16:09:08] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:08] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:09] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:09] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:10] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:10] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:10] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:10] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:11] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:11] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:13] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:13] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:19] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:19] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format gsm
[2007-03-28 16:09:19] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:19] DEBUG[15858] app.c: play_and_record: <None>, /var/spool/asterisk/voicemail/default/5050/tmp/PpLEGj, 'wav49'
[2007-03-28 16:09:19] DEBUG[15858] app.c: Recording Formats: sfmts=wav49
[2007-03-28 16:09:19] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to read format slin
[2007-03-28 16:09:20] DEBUG[15858] chan_sip.c: = No match Their Call ID: 3592725E-1DD2-11B2-A471-EA1B060FDA0B@172.16.0.192 Their Tag 25791850171320264860 Our tag: as0dcdb883
[2007-03-28 16:09:20] DEBUG[15858] chan_sip.c: = No match Their Call ID: 7BE4991E-1DD2-11B2-A470-EA1B060FDA0B@172.16.0.192 Their Tag 25791757061514971557 Our tag: as3c02cd42
[2007-03-28 16:09:20] DEBUG[15858] chan_sip.c: = Found Their Call ID: 861BDD8E-1DD2-11B2-A470-EA1B060FDA0B@172.16.0.192 Their Tag 2578461141636026303 Our tag: as24aa43a3
[2007-03-28 16:09:20] DEBUG[15858] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192
[2007-03-28 16:09:24] DTMF[15858] channel.c: DTMF begin '#' received on SIP/5050-085e1950
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: Sending dtmf: 35 (#), at 172.16.0.192
[2007-03-28 16:09:24] DTMF[15858] channel.c: DTMF end '#' received on SIP/5050-085e1950, duration 280 ms
[2007-03-28 16:09:24] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to read format alaw
[2007-03-28 16:09:24] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: Difference is 39976, ms is 5017
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:24] DEBUG[15858] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[2007-03-28 16:09:25] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:25] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:27] DEBUG[15858] chan_sip.c: Auto destroying SIP dialog '7BE4991E-1DD2-11B2-A470-EA1B060FDA0B@172.16.0.192'
[2007-03-28 16:09:27] DEBUG[15858] chan_sip.c: Destroying SIP dialog 7BE4991E-1DD2-11B2-A470-EA1B060FDA0B@172.16.0.192
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: Sending dtmf: 50 (2), at 172.16.0.192
[2007-03-28 16:09:30] DTMF[15858] channel.c: DTMF begin '2' received on SIP/5050-085e1950
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: Sending dtmf: 50 (2), at 172.16.0.192
[2007-03-28 16:09:30] DTMF[15858] channel.c: DTMF end '2' received on SIP/5050-085e1950, duration 280 ms
[2007-03-28 16:09:30] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:30] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format gsm
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:30] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: Sending dtmf: 49 (1), at 172.16.0.192
[2007-03-28 16:09:32] DTMF[15858] channel.c: DTMF begin '1' received on SIP/5050-085e1950
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:32] DEBUG[15858] rtp.c: Sending dtmf: 49 (1), at 172.16.0.192
[2007-03-28 16:09:32] DTMF[15858] channel.c: DTMF end '1' received on SIP/5050-085e1950, duration 280 ms
[2007-03-28 16:09:32] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:33] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format slin
[2007-03-28 16:09:33] DEBUG[15858] rtp.c: Difference is 680, ms is 105
[2007-03-28 16:09:33] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:33] DEBUG[15858] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[2007-03-28 16:09:35] DEBUG[15858] channel.c: Set channel SIP/5050-085e1950 to write format alaw
[2007-03-28 16:09:35] WARNING[15858] app_voicemail.c: SQL Execute error!
[DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

[2007-03-28 16:09:35] DEBUG[15858] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/INBOX'
[2007-03-28 16:09:35] DEBUG[15858] app_voicemail.c: The recorded media file is gone, so we should remove the .txt file too!
[2007-03-28 16:09:35] DEBUG[15858] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/5050/INBOX'
[2007-03-28 16:09:35] DEBUG[15858] pbx.c: Launching 'Goto'
[2007-03-28 16:09:35] DEBUG[15858] pbx.c: Launching 'ResetCDR'
[2007-03-28 16:09:35] DEBUG[15858] cdr_radius.c: Unable to create RADIUS record. CDR not recorded!
[2007-03-28 16:09:35] DEBUG[15858] pbx.c: Launching 'NoCDR'
[2007-03-28 16:09:35] NOTICE[15858] cdr.c: CDR on channel 'SIP/5050-085e1950' not posted
[2007-03-28 16:09:35] NOTICE[15858] cdr.c: CDR on channel 'SIP/5050-085e1950' lacks end
[2007-03-28 16:09:35] DEBUG[15858] pbx.c: Launching 'Wait'
[2007-03-28 16:09:36] DEBUG[15858] pbx.c: Launching 'Hangup'
[2007-03-28 16:09:36] DEBUG[15858] pbx.c: Spawn extension (hangupcall,s,4) exited non-zero on 'SIP/5050-085e1950'
[2007-03-28 16:09:36] DEBUG[15858] channel.c: Hanging up channel 'SIP/5050-085e1950'