[asterisk-bugs] [Asterisk 0016754]: Multiple segfaults in leave_voicemail at app_voicemail.c:4451 Asterisk 1.4.29
Asterisk Bug Tracker
noreply at bugs.digium.com
Fri Feb 5 09:25:18 CST 2010
A NOTE has been added to this issue.
======================================================================
https://issues.asterisk.org/view.php?id=16754
======================================================================
Reported By: aragon
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 16754
Category: Applications/app_voicemail
Reproducibility: always
Severity: crash
Priority: normal
Status: acknowledged
Asterisk Version: 1.4.29
JIRA: SWP-844
Regression: No
Reviewboard Link:
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2010-02-02 13:08 CST
Last Modified: 2010-02-05 09:25 CST
======================================================================
Summary: Multiple segfaults in leave_voicemail at
app_voicemail.c:4451 Asterisk 1.4.29
Description:
Asterisk 1.4.27 was locking at leave_voicemail and after upgrading to
1.4.29 in a desperate attempt to clear the locking Asterisk 1.4.29 started
segfaulting every 2 or 3 minutes. I had to downgrade to 1.4.27 to prevent
the segfaults.
Here is the evidence of the lock in the ast CLI
app.c: Failed to lock path
'/var/spool/asterisk/voicemail/customer/3329/INBOX': File exists.
The permissions on this folder look normal.
Under 1.4.27 core show locks was useless, core show channels was useless.
When voicemail directories start locking htop showed CPU utilization at
300 where normal load is about 1 on 1.4.27
Attaching Asterisk CLI history.
Ran 1.4.29 under Valgrind for a few minutes until it crashed so I could
upload valgrind capture.
Uploading gdb file with bt, bt full, thread apply all bt full
I believe that while Asterisk was locked on mailbox leaving a message in
mailbox 3329 caused the segfault. Other mailboxes display similar locking
symptoms in Asterisk CLI.
======================================================================
----------------------------------------------------------------------
(0117784) aragon (reporter) - 2010-02-05 09:25
https://issues.asterisk.org/view.php?id=16754#c117784
----------------------------------------------------------------------
This is unbelievably easy to reproduce:
create a .lock file in any voicemail inbox folder like
/var/spool/asterisk/voicemail/default/6010/INBOX/.lock
Try to leave a message in mailbox 6010.
After you hangup to finish leaving message in 6010 Asterisk will segfault
every time.
Attaching GDB to running Asterisk PID spits out some output like:
Attaching to program: /usr/sbin/asterisk, process 13064
warning: .dynamic section for "/lib/librt.so.1" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libvorbis.so.0" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libvorbisenc.so.2" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libodbc.so.1" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libcrypt.so.1" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libnsl.so.1" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libssl.so.6" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libodbcinst.so.1" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libkrb5.so.3" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libk5crypto.so.3" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libselinux.so.1" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libsepol.so.1" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libpopt.so.0" is not at the
expected address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/lib/libutil.so.1" is not at the expected
address
warning: difference appears to be caused by prelink, adjusting
expectations
warning: .dynamic section for "/usr/lib/libbz2.so.1" is not at the
expected address
The Asterisk CLI during the test looks like:
-- Executing [*980 at default-super:1] Answer("SIP/6010-00000000", "") in
new stack
-- Executing [*980 at default-super:2] Wait("SIP/6010-00000000", "1") in
new stack
lab*CLI>
-- Executing [*980 at default-super:3] Read("SIP/6010-00000000",
"VMBOX|vm-extension") in new stack
-- <SIP/6010-00000000> Playing 'vm-extension' (language 'en')
Really destroying SIP dialog 'cfa1a9b3-673aee68-91ed215 at 192.168.30.188'
Method: SUBSCRIBE
-- User entered '6010'
-- Executing [*980 at default-super:4] GotoIf("SIP/6010-00000000",
"0?10") in new stack
-- Executing [*980 at default-super:5] Dial("SIP/6010-00000000",
"Local/6010 at default-local-voicemail") in new stack
-- Called 6010 at default-local-voicemail
-- Executing [6010 at default-local-voicemail:1]
VoiceMail("Local/6010 at default-local-voicemail-d3b2,2", "6010 at default|b") in
new stack
-- Local/6010 at default-local-voicemail-d3b2,1 answered
SIP/6010-00000000
-- <Local/6010 at default-local-voicemail-d3b2,2> Playing
'/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
Really destroying SIP dialog '494937892 at 192.168.30.90' Method: REGISTER
Really destroying SIP dialog 'e208bd1f-b2f77ce8-f9d6ce3d at 192.168.30.194'
Method: SUBSCRIBE
[Feb 5 10:22:34] WARNING[17703]: channel.c:946 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/6010 at default-local-voicemail-d3b2,2
[Feb 5 10:22:35] WARNING[17703]: channel.c:946 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/6010 at default-local-voicemail-d3b2,2
== Spawn extension (default-super, *980, 5) exited non-zero on
'SIP/6010-00000000'
Extension Changed 6010[default-local] new state Idle for Notify User
6010
Extension Changed 6010[default-local] new state Idle for Notify User
6000
[Feb 5 10:22:37] WARNING[17710]: app.c:1048 ast_lock_path: Failed to lock
path '/var/spool/asterisk/voicemail/default/6010/INBOX': File exists
[Feb 5 10:22:37] WARNING[17710]: file.c:764 ast_readaudio_callback:
Failed to write frame
-- <Local/6010 at default-local-voicemail-d3b2,2> Playing 'beep'
(language 'en')
-- Recording the message
-- x=0, open writing:
/var/spool/asterisk/voicemail/default/6010/tmp/zLJiMc format: wav49,
0x9a24b98
-- User hung up
-- Recording was 0 seconds long but needs to be at least 4 -
abandoning
The interesting part of the CLI is that the actual duration of time spent
recording the voicemail was about 10 seconds of spoken message and CLI
reports 0 seconds. Then the crash is immediate.
Same results in CentOS 5.4 with kernel 2.6.18-92.1.22.el5
https://issues.asterisk.org/view.php?id=1 SMP
Issue History
Date Modified Username Field Change
======================================================================
2010-02-05 09:25 aragon Note Added: 0117784
======================================================================
More information about the asterisk-bugs
mailing list