[Home]

Summary:ASTERISK-12269: setting volgain results in tempfile errors and 0-length email attachments
Reporter:Rick Bradley (rickbradley)Labels:
Date Opened:2008-06-27 11:40:46Date Closed:2008-07-28 16:42:46
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20080728__bug12939.diff.txt
Description:Running on Ubuntu Linux 8.04 (Hardy Heron).  Installed Asterisk 1.4.21 from source.  Everything works fine, including voicemail, until I turn on volgain in voicemail.conf.  At that point, voicemails record, but attachments sent out have 0 byte size, and asterisk -r verbose/debug console logs show the following:

   -- Executing [555@internal:25] VoiceMail("Zap/1-1", "1000@default&1001@default&1002@default") in new stack
   -- <Zap/1-1> Playing 'vm-intro' (language 'en')
   -- <Zap/1-1> Playing 'beep' (language 'en')
   -- Recording the message
   -- x=0, open writing:  /var/spool/asterisk/voicemail/default/1000/tmp/jPJzyw format: wav, 0x81f0fe8
   -- User ended message by pressing #
   -- <Zap/1-1> Playing 'auth-thankyou' (language 'en')
[Jun 27 11:38:05] NOTICE[11365]: app_voicemail.c:2632 copy_message: Copying message from 1000@default to 1001@default
[Jun 27 11:38:05] WARNING[11365]: app_voicemail.c:1652 base_encode: Failed to open file: /var/spool/asterisk/voicemail/default/1001/tmp/bWHwPM.wav: No such file or directory
[Jun 27 11:38:05] NOTICE[11365]: app_voicemail.c:2632 copy_message: Copying message from 1000@default to 1002@default
[Jun 27 11:38:05] WARNING[11365]: app_voicemail.c:1652 base_encode: Failed to open file: /var/spool/asterisk/voicemail/default/1002/tmp/pYh3h3.wav: No such file or directory
   -- Executing [555@internal:26] Playback("Zap/1-1", "vm-goodbye") in new stack
   -- <Zap/1-1> Playing 'vm-goodbye' (language 'en')
   -- Executing [555@internal:27] Hangup("Zap/1-1", "") in new stack
 == Spawn extension (internal, 555, 27) exited non-zero on 'Zap/1-1'
   -- Hungup 'Zap/1-1'



Voicemail.conf has the following directives in it:



****** ADDITIONAL INFORMATION ******

[general]
format=wav49
serveremail=voicemail@eastcore.net
attach=yes
attachfmt=wav49
maxmsg=9999
maxgreet=60
skipms=3000
maxsilence=10
silencethreshold=128
maxlogins=3
fromstring=You Got VoiceMail, Yo
emailsubject= VoiceMail, Yo: [${VM_CALLERID}/${VM_CIDNUM}] message ${VM_MSGNUM}
emailbody=Whatup, yo:\n\n\tjust wanted to let you know you were just left a ${VM_DUR} long message (number ${VM_MSGNUM})\nin mailbox "${VM_MAILBOX}" from "${VM_CALLERID} (${VM_CIDNUM})", on ${VM_DATE}, so you might\nwant to check it when you get a chance.  Thanks!\n\n\t\t\t\t--Asterisk\n
pagerfromstring=5001 Indiana Calling
pagersubject=You Got VoiceMail, Yo
emaildateformat=%A, %B %d, %Y at %r
mailcmd=/usr/sbin/sendmail -t
attach=yes ; Attach the voicemail to the notification email *NOT* the pager email
attachfmt=wav ; Which format to attach to the email.  Normally this is the
saycid=yes ; Say the caller id information before the message. If not described,
sendvoicemail=yes ; Allow the user to compose and send a voicemail while inside
volgain=10.0 ; Emails bearing the voicemail may arrive in a volume too
[zonemessages]
eastern=America/New_York|'vm-received' Q 'digits/at' IMp
central=America/Chicago|'vm-received' Q 'digits/at' IMp
central24=America/Chicago|'vm-received' q 'digits/at' H N 'hours'
military=Zulu|'vm-received' q 'digits/at' H N 'hours' 'phonetic/z_p'
european=Europe/Copenhagen|'vm-received' a d b 'digits/at' HM
[default]
maxmsg=9999
1000 => 8675,5001 Indiana Mailbox,,,delete=1
1001 => 8675,Ali's Mailbox,someone@gmail.com
1002 => 8675,Rick's Mailbox,someone@rickbradley.com
[other]
Comments:By: Brandon Kruse (bkruse) 2008-06-27 14:01:18

Can you set debug on in logger.conf to console?

It should tell you the VOLGAIN stored at: settings in a debug message.

(core set debug 10)

Full console debug output of that would be good.

Also, do you have sox installed?

-b


By: Rick Bradley (rickbradley) 2008-06-27 14:26:08

Here is my debug 10 output when doing a voicemail recording attempt.  Also I do have sox installed on that machine:


root@rerun:/etc/asterisk# which sox
/usr/bin/sox
root@rerun:/etc/asterisk# sox
sox: SoX v14.0.0

Failed: Not enough input filenames specified

[... snipped ... ]


----

Asterisk 1.4.21, Copyright (C) 1999 - 2008 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 1.4.21 currently running on rerun (pid = 14807)
rerun*CLI> core set debug 10
Core debug was 0 and is now 10
[Jun 27 14:27:48] DEBUG[14830]: chan_zap.c:6981 do_monitor: Monitor doohicky got event Ring/Answered on channel 1
[Jun 27 14:27:49] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: 5 on Zap/1-1
[Jun 27 14:27:50] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: 5 on Zap/1-1
[Jun 27 14:27:50] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: 5 on Zap/1-1
[Jun 27 14:27:50] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Jun 27 14:27:50] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Jun 27 14:27:50] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Jun 27 14:27:50] DEBUG[14840]: chan_zap.c:1435 zt_enable_ec: Enabled echo cancellation on channel 1
[Jun 27 14:27:50] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'Set'
[Jun 27 14:27:50] DEBUG[14840]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '8008675309'
[Jun 27 14:27:50] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp'
[Jun 27 14:27:50] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'AGI'
[Jun 27 14:27:50] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Jun 27 14:27:50] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Jun 27 14:27:50] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)
[Jun 27 14:27:50] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 27 14:27:50] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 27 14:27:50] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'Wait'
[Jun 27 14:27:51] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'VoiceMail'
[Jun 27 14:27:51] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Jun 27 14:27:51] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Jun 27 14:27:51] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Jun 27 14:27:51] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 27 14:27:51] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Jun 27 14:27:51] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Jun 27 14:27:51] DEBUG[14810]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x81ef178'
[.... bunches of these snipped ....]
[Jun 27 14:27:51] DEBUG[14810]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x81ef178'
[Jun 27 14:27:51] DEBUG[14840]: chan_zap.c:2778 zt_answer: Took Zap/1-1 off hook
[Jun 27 14:27:51] DEBUG[14840]: app_voicemail.c:2860 leave_voicemail: Before find_user
[Jun 27 14:27:51] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)
[Jun 27 14:27:51] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 27 14:27:51] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format slin
[Jun 27 14:27:51] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 137 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format ulaw
[Jun 27 14:27:57] DEBUG[14840]: app.c:1031 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1000/INBOX'
[Jun 27 14:27:57] DEBUG[14840]: app.c:1052 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1000/INBOX'
[Jun 27 14:27:57] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format slin
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 22 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:57] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format ulaw
[Jun 27 14:27:57] DEBUG[14840]: app.c:529 __ast_play_and_record: play_and_record: <None>, /var/spool/asterisk/voicemail/default/1000/tmp/MVrjkr, 'wav'
[Jun 27 14:27:57] DEBUG[14840]: app.c:551 __ast_play_and_record: Recording Formats: sfmts=wav
[Jun 27 14:27:57] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to read format slin
[Jun 27 14:27:57] DEBUG[14840]: chan_zap.c:5030 zt_indicate: Requested indication 18 on channel Zap/1-1
[Jun 27 14:27:58] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: 7 on Zap/1-1
[Jun 27 14:27:58] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: 8 on Zap/1-1
[Jun 27 14:27:58] DEBUG[14840]: chan_zap.c:3609 zt_handle_dtmfup: DTMF digit: # on Zap/1-1
[Jun 27 14:27:58] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to read format ulaw
[Jun 27 14:27:58] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format slin
[Jun 27 14:27:58] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun 27 14:27:59] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 137 sample intervals
[Jun 27 14:27:59] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:59] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:27:59] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format ulaw
[Jun 27 14:27:59] DEBUG[14840]: app.c:1031 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1000/INBOX'
[Jun 27 14:27:59] DEBUG[14840]: app.c:1052 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1000/INBOX'
[Jun 27 14:27:59] NOTICE[14840]: app_voicemail.c:2632 copy_message: Copying message from 1000@default to 1001@default
[Jun 27 14:27:59] DEBUG[14840]: app.c:1031 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Jun 27 14:27:59] DEBUG[14840]: app.c:1052 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1001/INBOX'
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1964 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/1001/INBOX/msg0025', format 'wav', uservm is '2048', global is 2048
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1926 make_email_file: newtmp: /var/spool/asterisk/voicemail/default/1001/tmp/mLkNi1
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1932 make_email_file: VOLGAIN: Stored at: /var/spool/asterisk/voicemail/default/1001/tmp/mLkNi1.wav - Level: 9.0000 - Mailbox: 1001
[Jun 27 14:27:59] WARNING[14840]: app_voicemail.c:1652 base_encode: Failed to open file: /var/spool/asterisk/voicemail/default/1001/tmp/mLkNi1.wav: No such file or directory
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1976 sendmail: Sent mail to artalk@gmail.com with command '/usr/sbin/sendmail -t'
[Jun 27 14:27:59] NOTICE[14840]: app_voicemail.c:2632 copy_message: Copying message from 1000@default to 1002@default
[Jun 27 14:27:59] DEBUG[14840]: app.c:1031 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1002/INBOX'
[Jun 27 14:27:59] DEBUG[14840]: app.c:1052 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1002/INBOX'
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1964 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/1002/INBOX/msg0025', format 'wav', uservm is '2048', global is 2048
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:157 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider SLA with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Meetme with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:230 getproviderstate: Checking provider Park with **Unknown**
[Jun 27 14:27:59] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1926 make_email_file: newtmp: /var/spool/asterisk/voicemail/default/1002/tmp/sheiuB
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1932 make_email_file: VOLGAIN: Stored at: /var/spool/asterisk/voicemail/default/1002/tmp/sheiuB.wav - Level: 9.0000 - Mailbox: 1002
[Jun 27 14:27:59] WARNING[14840]: app_voicemail.c:1652 base_encode: Failed to open file: /var/spool/asterisk/voicemail/default/1002/tmp/sheiuB.wav: No such file or directory
[Jun 27 14:27:59] DEBUG[14840]: app_voicemail.c:1976 sendmail: Sent mail to rick@rickbradley.com with command '/usr/sbin/sendmail -t'
[Jun 27 14:27:59] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'Playback'
[Jun 27 14:27:59] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format slin
[Jun 27 14:27:59] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun 27 14:28:00] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 8 sample intervals
[Jun 27 14:28:00] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:28:00] DEBUG[14840]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 27 14:28:00] DEBUG[14840]: channel.c:2808 set_format: Set channel Zap/1-1 to write format ulaw
[Jun 27 14:28:00] DEBUG[14840]: pbx.c:1842 pbx_extension_helper: Launching 'Hangup'
[Jun 27 14:28:00] DEBUG[14840]: pbx.c:2438 __ast_pbx_run: Spawn extension (internal,555,7) exited non-zero on 'Zap/1-1'
[Jun 27 14:28:00] DEBUG[14840]: channel.c:1384 ast_softhangup_nolock: Soft-Hanging up channel 'Zap/1-1'
[Jun 27 14:28:00] DEBUG[14840]: channel.c:1483 ast_hangup: Hanging up channel 'Zap/1-1'
[Jun 27 14:28:00] DEBUG[14840]: chan_zap.c:2420 zt_hangup: zt_hangup(Zap/1-1)
[Jun 27 14:28:00] DEBUG[14840]: chan_zap.c:2454 zt_hangup: Hangup: channel: 1 index = 0, normal = 19, callwait = -1, thirdcall = -1
[Jun 27 14:28:00] DEBUG[14840]: chan_zap.c:1467 zt_disable_ec: disabled echo cancellation on channel 1
[Jun 27 14:28:00] DEBUG[14840]: chan_zap.c:2884 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1
[Jun 27 14:28:00] DEBUG[14840]: chan_zap.c:1403 update_conf: Updated conferencing on 1, with 0 conference users
[Jun 27 14:28:00] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Jun 27 14:28:00] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Jun 27 14:28:00] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Jun 27 14:28:00] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 27 14:28:00] DEBUG[14840]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Jun 27 14:28:00] DEBUG[14810]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Jun 27 14:28:00] DEBUG[14810]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown)
[Jun 27 14:28:00] DEBUG[14834]: app_queue.c:659 handle_statechange: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 27 14:28:01] DEBUG[14830]: chan_zap.c:6981 do_monitor: Monitor doohicky got event Hook Transition Complete on channel 1
[Jun 27 14:28:01] DEBUG[14830]: chan_zap.c:6981 do_monitor: Monitor doohicky got event On hook on channel 1
[Jun 27 14:28:01] DEBUG[14830]: chan_zap.c:1467 zt_disable_ec: disabled echo cancellation on channel 1
rerun*CLI>
By: Mark Michelson (mmichelson) 2008-07-01 11:09:22

Yesterday afternoon, I opened this bug report and started working on fixing it. I also was having the 0-length files attached to e-mails (but I was not having the base_encode WARNING message alerting that the specified file did not exist).

Today, I came up with some new ideas to debug the issue, and magically, the problem doesn't exist anymore for me! Argh! Anyway, I'll see if I can figure this out.
By: Tilghman Lesher (tilghman) 2008-07-28 15:08:31

I think I know why.  Hardy Heron will install sox (the command line program) with no support for any actual codec, unless you specifically tell it to install the codecs.  You can install all of them with the package name 'libsox-fmt-all'.  The inability for sox to decode or reencode any of the formats would cause this exact error.

I have uploaded a patch that should detect this error and print an error to the screen, as well as attaching the (non-volume-gained) file, thus eliminating this issue in the future.  Please test it out and confirm that it at least fixes the problem of 0-byte attachments.
By: Rick Bradley (rickbradley) 2008-07-28 16:34:30

Corydon76 -- verified:  installing the libsox-fmt-all package on Ubuntu fixes the problem.  Thanks!
By: Digium Subversion (svnbot) 2008-07-28 16:42:42

Repository: asterisk
Revision: 134161

U   branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r134161 | tilghman | 2008-07-28 16:42:41 -0500 (Mon, 28 Jul 2008) | 7 lines

Detect when sox fails to raise the volume, because sox can't read the file.
(closes issue ASTERISK-12269)
Reported by: rickbradley
Patches:
      20080728__bug12939.diff.txt uploaded by Corydon76 (license 14)
Tested by: rickbradley

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=134161