PulseAudio opens too many files, locks up, and fills up root fs (/var/log)

[Michael B. Trausch]

--- SRU information follows ---

Impact: 9.10 users may experience a local denial of service due to fd exhaustion caused by alsa-lib failing to properly free timers upon closing slave pcm devices.

10.04 resolution: http://bazaar.launchpad.net/~ubuntu-core-dev/alsa-lib/ubuntu.new/annotate/head%3A/debian/patches/Dont_leak_timer_fd_on_pcm_slave_close.patch has been applied.

Minimal 9.10 patch: http://launchpadlibrarian.net/37016945/alsa-lib_1.0.20-3ubuntu6.1.debdiff_2

TEST CASE: Choose a multichannel surround profile in Sound Preferences > Hardware > Profile

Regression potential: low to none -- all pcm (including slave pcm) devices will properly free associated timers

--- original bug report follows ---

Binary package hint: pulseaudio

First: note that this is not bug 446355, though it is similar. The message in the system log is:

Oct 13 14:25:51 zest pulseaudio[3578]: alsa-util.c: Unable to set sw params: Too many open files
Oct 13 14:25:51 zest pulseaudio[3578]: alsa-sink.c: Failed to set software parameters: Too many open files

Infinitely, repeatedly, until the /var/log/syslog and /var/log/user.log files fill up the partition that they are on. I have had to clear my log files 3 times now in the past day because my root filesystem was full, which started breaking various things (like my postfix installation which gets my mail delivered directly to me).

The log files are available on request privately, they contain information that I do not want published on the bug report, and due to their size, I cannot be sure to filter them and not accidentally remove anything relevant. There may be more in the log files than I have seen, simply because of the amount of stuff there. For anyone who requests the files, I'll email them: note that the log files are to 4 MB. However, they will expand to somewhere around 9 GB; compression on my system (4x 2.2 GHz 64-bit cores) took 300 minutes each, compressing with pbzip2. If you have a multiple-core system, decompression will go a lot more quickly if you use pbzip2 instead of bzip2 (and note also that compression took about 5 hours, I'd expect decompression to be similar). I will attached trimmed-down versions of these files as well, shortly after uploading the full log files.

This bug causes denial of service of anything in /var or on /, so I am classifying this as a security bug.

ProblemType: Bug
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC0: mbt 27536 F.... pulseaudio
 /dev/snd/timer: mbt 27536 f.... pulseaudio
Card0.Amixer.info:
 Card hw:0 'Live'/'SB Live! 5.1 [SB0060] (rev.7, serial:0x80611102) at 0xdc00, irq 19'
   Mixer name : 'SigmaTel STAC9708,11'
   Components : 'AC97a:83847608'
   Controls : 224
   Simple ctrls : 45
Date: Thu Oct 15 00:42:33 2009
DistroRelease: Ubuntu 9.10
NonfreeKernelModules: nvidia
Package: pulseaudio 1:0.9.19-0ubuntu1
ProcEnviron:
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: pulseaudio
Uname: Linux 2.6.31.3-bfs303 x86_64

[Michael B. Trausch (mtrausch)]

Hi Marc,

I'm wondering why you removed the security vulnerability flag. This causes a denial of service for at least MTA software and probably any other software that relies on /var or / not being full.

PulseAudio is opening /dev/snd/timer until its maximum number of open files is reached. At that point. PulseAudio logs the same two messages until /var/log's available space is full. This causes subsequent log messages to be lost, and provides opportunities for several security-related events to occur without even a remote chance of detection. Furthermore, it causes the failure of MTA software even if /var/mail is _not_ full.

[Michael B. Trausch (mtrausch)]

It would appear that the best way to trigger it is to play lots of sounds. Every time a new system event sound plays, for example, PA opens /dev/snd/timer 3 more times. I have no log messages to indicate why, nor can I otherwise explain this highly odd behavior. This means that the time to syslog beginning to fill up depends on how many events are played through the speakers.

It may happen at other times, too. I just restarted PA and already have many open instances of /dev/snd/timer:

mbt@zest:/proc/31224/fd$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 27 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 28 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 29 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 45 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 46 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 47 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 48 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 49 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 50 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 51 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 52 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 53 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 54 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 55 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 58 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 59 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 60 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 64 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 65 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-15 22:16 66 -> /dev/snd/timer
mbt@zest:/proc/31224/fd$ ps -f $(pgrep pulseaudio)
UID PID PPID C STIME TTY STAT TIME CMD
mbt 25546 1 0 22:12 ? Ssl 0:02 /usr/bin/pulseaudio --start -
mbt@zest:/proc/31224/fd$ pulseaudio --version
pulseaudio 0.9.19
mbt@zest:/proc/31224/fd$ apt-cache show pulseaudio
Package: pulseaudio
Priority: optional
Section: sound
Installed-Size: 4268
Maintainer: Ubuntu Core Developers <email address hidden>
Original-Maintainer: Pulseaudio maintenance team <email address hidden>
Architecture: amd64
Version: 1:0.9.19-0ubuntu2

[Daniel T Chen (crimsun)]

Is this symptom reproducible in the Ubuntu Karmic kernel (2.6.31-14.47-generic)?

[Michael B. Trausch (mtrausch)]

On Fri, 2009-10-16 at 03:23 +0000, Daniel T Chen wrote:
> Is this symptom reproducible in the Ubuntu Karmic kernel
> (2.6.31-14.47-generic)?

I suppose I can find out, but if the problem is dependent on the kernel
to be triggered, then this PA bug is a much larger bug than it would
appear to be; PA should not have bugs able to be triggered by dropping
in a newer kernel that fulfills the same interfaces.

Give me some time to switch back as my system is currently working on
some things and I cannot reboot right now.

 --- Mike

--
Blog: http://mike.trausch.us/blog/
Misc. Software: http://mike.trausch.us/software/

“The greater danger for most of us lies not in setting our aim too
high and falling short; but in setting our aim too low, and achieving
our mark.” —Michelangelo

[Michael B. Trausch (mtrausch)]

Daniel,

Yes, it happens with the Ubuntu kernel also:

mbt@zest:~/$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 28 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 29 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 30 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 42 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 43 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 44 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 49 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 50 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 51 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 55 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 56 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 57 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 58 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 59 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 60 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 65 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 66 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 67 -> /dev/snd/timer
mbt@zest:~/$ ps -f $(pgrep pulseaudio)
UID PID PPID C STIME TTY STAT TIME CMD
mbt 3486 1 0 14:08 ? Ssl 0:01 /usr/bin/pulseaudio --start
mbt@zest:~/$ pulseaudio --version
pulseaudio 0.9.19
mbt@zest:~/$ uname -a
Linux zest 2.6.31-14-generic #47-Ubuntu SMP Thu Oct 15 03:42:30 UTC 2009 x86_64 GNU/Linux
mbt@zest:~/$

[Daniel T Chen (crimsun)]

Are you using glitch-free?

On Oct 16, 2009 5:50 PM, "Michael B. Trausch" <email address hidden> wrote:

Daniel,

Yes, it happens with the Ubuntu kernel also:

mbt@zest:~/$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 28 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 29 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 30 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 42 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 43 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 44 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 49 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 50 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 51 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 55 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 56 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 57 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 58 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 59 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:39 60 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 65 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 66 -> /dev/snd/timer
lr-x------ 1 mbt mbt 64 2009-10-16 17:40 67 -> /dev/snd/timer
mbt@zest:~/$ ps -f $(pgrep pulseaudio)

UID PID PPID C STIME TTY STAT TIME CMD
mbt 3486 1 0 14:08 ? Ssl 0:01 /usr/bin/pulseaudio
--start
mbt@zest:~/$ pulseaudio --version
pulseaudio 0.9.19
mbt@zest:~/$ uname -a
Linux zest 2.6.31-14-generic #47-Ubuntu SMP Thu Oct 15 03:42:30 UTC 2009
x86_64 GNU/Linux
mbt@zest:~/$

-- PulseAudio opens too many files, locks up, and fills up root fs
(/var/log) https://bugs.launchp...

[Michael B. Trausch (mtrausch)]

On Fri, 2009-10-16 at 22:00 +0000, Daniel T Chen wrote:
> Are you using glitch-free?

I haven't the slightest clue what you're asking. I'm using PulseAudio
as it comes with Ubuntu, configured for my number of speakers using the
GNOME Volume control panel.

 --- Mike

>
> On Oct 16, 2009 5:50 PM, "Michael B. Trausch" <email address hidden>
> wrote:
>
> Daniel,
>
> Yes, it happens with the Ubuntu kernel also:
>
> mbt@zest:~/$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 28 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 29 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 30 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 42 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 43 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 44 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 49 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 50 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 51 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 55 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 56 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 57 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 58 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 59 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:39 60 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:40 65 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:40 66 -> /dev/snd/timer
> lr-x------ 1 mbt mbt 64 2009-10-16 17:40 67 -> /dev/snd/timer
> mbt@zest:~/$ ps -f $(pgrep pulseaudio)
>
> UID PID PPID C STIME TTY STAT TIME CMD
> mbt 3486 1 0 14:08 ? Ssl 0:01 /usr/bin/pulseaudio
> --start
> mbt@zest:~/$ pulseaudio --version
> pulseaudio 0.9.19
> mbt@zest:~/$ uname -a
> Linux zest 2.6.31-14-generic #47-Ubuntu SMP Thu Oct 15 03:42:30 UTC 2009
> x86_64 GNU/Linux
> mbt@zest:~/$
>
> -- PulseAudio opens too many files, locks up, and fills up root fs
> (/var/log) https://bugs.launchp...
>
> --
> PulseAudio opens too many files, locks up, and fills up root fs (/var/log)
> https://bugs.launchpad.net/bugs/451893
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in “pulseaudio” package in Ubuntu: New
>
> Bug description:
> Binary package hint: pulseaudio
>
> First: note that this is not bug 446355, though it is similar. The message in the system log is:
>
> Oct 13 14:25:51 zest pulseaudio[3578]: alsa-util.c: Unable to set sw params: Too many open files
> Oct 13 14:25:51 zest pulseaudio[3578]: alsa-sink.c: Failed to set software parameters: Too many open files
>
> Infinitely, repeatedly, until the /var/log/syslog and /var/log/user.log files fill up the partition that they are on. I have had to clear my log files 3 times now in the past day because my root filesystem was full, which started breaking various things (like my postfix installation which gets my mail delivered directly to me).
>
> The log files are available on request privately, they contain information that I do not want published on the bug report, and d...

[Daniel T Chen (crimsun)]

Right, so you are using glitch-free. Let's see if we can narrow down
whether it's linux or PA at issue, or possibly both. There are
definitely workarounds for either/both.

[Michael B. Trausch (mtrausch)]

I'm not sure how to go about doing this, could you provide me with some pointers or a starting point? Deleting my log files and doing "pulseaudio -k" is getting somewhat old, and it makes my CPU run like crazy, thus making my fans step up to maximum and also getting to be very loud.

[Daniel T Chen (crimsun)]

On Mon, Oct 19, 2009 at 4:36 PM, Michael B. Trausch <email address hidden> wrote:
> I'm not sure how to go about doing this, could you provide me with some
> pointers or a starting point?  Deleting my log files and doing

Firstly, are you running current Karmic? The most recent pulseaudio
package Conflicts rtkit, which was spamming syslog due to a patch not
being applied to the Karmic linux source package.

[Michael B. Trausch (mtrausch)]

On Mon, 2009-10-19 at 21:26 +0000, Daniel T Chen wrote:
> Firstly, are you running current Karmic? The most recent pulseaudio
> package Conflicts rtkit, which was spamming syslog due to a patch not
> being applied to the Karmic linux source package.

I've updated today, I will pull updates again here in a bit. Should
this issue be gone with the latest updates?

 --- Mike

--
Blog: http://mike.trausch.us/blog/
Misc. Software: http://mike.trausch.us/software/

“The greater danger for most of us lies not in setting our aim too
high and falling short; but in setting our aim too low, and achieving
our mark.” —Michelangelo

[chris_c (c-camacho)]

I believe my problem to be the same but with slightly different log spam

Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files
Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files
Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files
Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files
Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files
Nov 1 14:48:07 chris-desktop pulseaudio[3973]: alsa-sink.c: Error opening PCM device surround51:1: Too many open files

after a *year* this is *still* not production ready, really quite embarrassing, you can't blame alsa for pulse audio's
poor error handling, even if alsa totally fails pulse audio should NOT be flooding logs its a potential security flaw...

 #!/bin/bash
killall pulseaudio
pulse-session

use this script as a workaround

[Olaf Lüke (borg)]

I can confirm this bug. I can trigger it with playing quake live ;-), after that i also have no sound in some programs (totem, vlc, xine, mplayer), but others work (rythmbox, flashplugin). I have not yet found a way to fix that without rebooting, restarting pulseaudio doesn't work strangely.

[Dan McCombs (overridex)]

Whew, I just ran into this bug - suddenly I got a message that my file system was almost full, my CPU was pegged by pulseaudio and rsyslogd, and a few minutes later my file system was full with many gigs of /var/log/syslog and /var/log/user.log. About 31 million lines in each file for pulseaudio:

(after i gzipped them and rotated)

overridex@citadel-station:/var/log$ zcat syslog.1.gz | grep pulseaudio | wc -l
31001234
overridex@citadel-station:/var/log$ zcat user.log.1.gz | grep pulseaudio | wc -l
31000642

The lines appear to all (or at least mostly) be:

Nov 29 17:19:30 citadel-station pulseaudio[2365]: socket-server.c: accept(): Too many open files
Nov 29 17:19:30 citadel-station pulseaudio[2365]: socket-server.c: accept(): Too many open files
Nov 29 17:19:30 citadel-station pulseaudio[2365]: socket-server.c: accept(): Too many open files

Cause?:

I've been using karmic on this system without a problem with pulseaudio since the first beta. Last night I changed my speaker configuration in my volume control from "Analog Stereo Duplex" to "Analog Surround 5.1 Output". I have to think that's related based on the timing. I shut this computer off every night, so this isn't something that just built up over time.

I'd be happy to provide any additional information that anyone would like regarding this.

-Dan

[Dan McCombs (overridex)]

I can confirm the file handle leak on /dev/snd/timer only happens if I have the "Analog Surround 5.1 Output" Profile selected instead of "Analog Stereo Duplex". Three file handles to /dev/snd/timer are left open each time a sound is played with the 5.1 profile:

overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer | wc -l
12
overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer | wc -l
15
overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer | wc -l
18

This using a Sound Blaster Audigy sound card.

-Dan

[Michael B. Trausch (mtrausch)]

Hrm... I wonder if maybe the problem has anything to do with the fact that
the cards have hardware mixing and can be opened multiple times?

On Nov 29, 2009 7:05 PM, "Dan McCombs" <email address hidden> wrote:

I can confirm the file handle leak on /dev/snd/timer only happens if I
have the "Analog Surround 5.1 Output" Profile selected instead of
"Analog Stereo Duplex". Three file handles to /dev/snd/timer are left
open each time a sound is played with the 5.1 profile:

overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer |
wc -l
12
overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer |
wc -l
15
overridex@citadel-station:~$ ls -l /proc/$(pgrep pulseaudio)/fd|grep timer |
wc -l
18

This using a Sound Blaster Audigy sound card.

-Dan -- PulseAudio opens too many files, locks up, and fills up root fs
(/var/log) https://bugs.l...

[Daniel T Chen (crimsun)]

Recent (git HEAD) changes in alsa-lib have added close-on-exec semantics.
I'll hack in a deb for the PPA this week.

On Nov 29, 2009 4:20 PM, "Michael B. Trausch" <email address hidden> wrote:

Hrm... I wonder if maybe the problem has anything to do with the fact that
the cards have hardware mixing and can be opened multiple times?

On Nov 29, 2009 7:05 PM, "Dan McCombs" <email address hidden> wrote: I can
confirm the file handle ...
(/var/log) https://bugs.l...

-- PulseAudio opens too many files, locks up, and fills up root fs
(/var/log) https://bugs.launchp...

[Don (don-redhat-bugs)]

Description of problem:
Received warning that my disk was full (unpartitioned disk inside a KVM virtual machine). Noticed that /var was 2.2G (out of 8G disk). Looked further and saw that /var/log/messages was 2.2G. Tailed it and saw these messages being spammed at high speed over and over:

Dec 3 15:16:02 foo pulseaudio[1465]: socket-server.c: accept(): Too many open files
Dec 3 15:16:02 foo pulseaudio[1465]: socket-server.c: accept(): Too many open files
Dec 3 15:16:02 foo pulseaudio[1465]: socket-server.c: accept(): Too many open files
Dec 3 15:16:02 foo pulseaudio[1465]: socket-server.c: accept(): Too many open files
Dec 3 15:16:02 foo pulseaudio[1465]: socket-server.c: accept(): Too many open files

I had to kill the pulseaudio process and delete other files just to be able to try to compress messages.

Version-Release number of selected component (if applicable):

pulseaudio-0.9.21-1.fc12.x86_64

How reproducible:

Have not yet tried.

Additional info:

When the messages file finishes compressing, I'll reboot the VM and see if the problem occurs. This VM was just created yesterday.

[Don (don-redhat-bugs)]

Finally copied the log to my host wher I have more disk. Here's where the trouble started, just earlier today. These messages are sequential, I haven't deleted any lines from the log, just changed the name of my machine hostname to "foo":

Dec 3 09:21:20 foo pulseaudio[1465]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pc
m_avail() returned 0 or another value < min_avail.
Dec 3 09:31:03 foo avahi-daemon[817]: Received response from host 172.16.30.3 with invalid source port 58346 on in
terface 'eth0.0'
Dec 3 14:05:42 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:05:42 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:08:04 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:11:08 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:11:08 foo pulseaudio[1465]: sink-input.c: Failed to create sink input: sink is suspended.
Dec 3 14:13:10 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:13:29 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:13:36 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:13:57 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:14:27 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:15:36 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:16:32 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:17:24 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:17:36 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:17:47 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:17:58 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:18:04 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:18:12 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:18:20 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:19:41 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:20:01 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:20:26 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:23:33 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:23:46 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:24:12 foo pulseaudio[1465]: alsa-sink.c: Error opening PCM device front:0: Too many open files
Dec 3 14:24:40 foo pulseaudio[1465]: ...

[Don (don-redhat-bugs)]

Happened again today.

First a number of these messages in rapid succession (all with same exact timestamp):
Dec 9 09:42:06 foo pulseaudio[1517]: shm.c: shm_open() failed: Too many open files

Followed by a LOT of these until /var/log/messages fills up the root disk:
Dec 9 09:42:07 foo pulseaudio[1517]: socket-server.c: accept(): Too many open files

Have to kill the pulseaudio pid 1517 and then just truncate /var/log/messages.

[Don (don-redhat-bugs)]

In case it wasn't clear before, this is happening in my Fedora 12 KVM virtual machine. The host is also Fedora 12 with all available stable upgrades. No pulseaudio problems on the host, just in the VM. The VM also has all available Fedora 12 stable upgrades.

I'm more than willing to post whatever information is required, if you are available to help. It seems like a serious bug to me if pulseaudio is allowed to fill up the partition hosting /var/log/messages. In my case, this is the root partition, and it filled 2.2G in around 45 minutes.

[Don (don-redhat-bugs)]

Found a somewhat similar bug for Ubuntu: https://bugs.launchpad.net/ubuntu/+source/pulseaudio/+bug/451893

I see similar cases of a number of timer links. I have no real idea what it means.

[root@foo ~]# ls -l /proc/$(pgrep pulseaudio)/fd|grep timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 22 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 23 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 29 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 30 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 35 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 36 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 37 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 38 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 39 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 40 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 41 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 42 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 11:03 43 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 11:03 44 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 11:03 45 -> /dev/snd/timer
lr-x------. 1 seiler seiler 64 2009-12-09 10:56 9 -> /dev/snd/timer

[Don (don-redhat-bugs)]

FYI:
# pulseaudio --version
pulseaudio 0.9.21

# rpm -qa | grep pulseaudio
pulseaudio-libs-glib2-0.9.21-1.fc12.x86_64
pulseaudio-module-gconf-0.9.21-1.fc12.x86_64
pulseaudio-utils-0.9.21-1.fc12.x86_64
pulseaudio-0.9.21-1.fc12.x86_64
pulseaudio-libs-0.9.21-1.fc12.x86_64
pulseaudio-module-bluetooth-0.9.21-1.fc12.x86_64
alsa-plugins-pulseaudio-1.0.21-2.fc12.x86_64
pulseaudio-gdm-hooks-0.9.21-1.fc12.x86_64
pulseaudio-module-x11-0.9.21-1.fc12.x86_64

[Drew Fisher (drew-m-fisher)]

I've got the same issue, with a SoundBlaster Live! 5.1 Dell OEM card. I also get a file handle leak when using the "Analog Surround 5.1 Output" profile - 3 handles leak at a time. When I use the "Analog Surround 4.0 Output" profile, only two handles leak each time. When using the (default) "Analog Stereo Duplex" profile, no file handles leak.

I built pulseaudio and alsa-lib from their respective git HEADs, but the issue (leaking file handles to /dev/snd/timer) remains.

Where might I look next to find the origin of the leaked file handles? I have no experience with sound programming, but I'm willing to try out any suggestions.

[Mostafa (mostafa-redhat-bugs)]

I'm seeing this behaviour as well on a fully updated F12 host (no KVM). As far as I can tell, it is usually triggered by flash (flash-plugin-10.0.42.34-release.i386).

Excerpts from /var/log/messages:

Dec 6 13:50:29 batcave pulseaudio[1842]: ratelimit.c: 78 events suppressed
Dec 6 13:51:01 batcave pulseaudio[1842]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Dec 6 13:51:01 batcave pulseaudio[1842]: alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_emu10k1'. Please report this issue to the ALSA devel
opers.
Dec 6 13:51:01 batcave pulseaudio[1842]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value
< min_avail.
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: No such device

[repeats until..]

Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: No such device
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed to set software parameters: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-util.c: Unable to set sw params: Too many open files
Dec 6 14:04:51 batcave pulseaudio[1842]: alsa-sink.c: Failed...

[Dan McCombs (overridex)]

I've done a little more digging and I'm not sure this is a bug in pulseaudio, or a bug in alsa-lib. After poking around pulseaudio with gdb for a while, I narrowed down the line where the extra file handles appear to line 450 in src/modules/alsa/alsa-util.c in the source retrieved via apt-get source pulseaudio. The line is a call to alsa-lib:

    if ((err = snd_pcm_sw_params(pcm, swparams)) < 0) {

I compared some variables around there between using the 5.1 profile and the stereo profile and things seemed to match up, so while I'm not positive as I don't know pulseaudio (or alsa) very well, I think the only difference in what pulseaudio is passing to this function is the pcm device itself, so maybe alsa-lib is to blame?

That's all the time I have to spend on this for now, maybe later this week I'll compile alsa-lib with debugging so I can peak at that as well.

[Lennart (lennart-redhat-bugs)]

Looks as if something is leaking fds in either PA or in libasound.

[Lennart (lennart-redhat-bugs)]

Oh, and one thing really sucks: rsyslog does not automatically rate limit log output from all processes. That's a real disaster if you ask me.

[Dan McCombs (overridex)]

Ok, I had some time to compile alsa-lib with debugging and poke at this a little more. From looking at it, it looks like alsa only opens these timers when using extra channels - like rear and center. So on 5.1 it's opening a timer for front, rear and center, while on 4.1 it opens one for rear and one for front. When pulseaudio suspends (when there hasn't been any audio played for 5 seconds) it calls snd_pcm_close and when it unsuspends (when sound is played again) it opens it back up. The problem is that the file handles for the timers are not being closed when snd_pcm_close is called, and more are opened back up when unsuspending. I'm no alsa or pulseaudio expert, so if any of this is off I apologize.

In any case, I was able to fix this by closing the timer in snd_pcm_hw_hw_free which is called for each slave when snd_pcm_close is called. With this change it works as expected, with the 3 file handles to the timer being open while pulseaudio is actively playing sound and 0 when it's not after a few seconds.

I've attached the patch as well as a patched package for amd64 and i386. I had some trouble compiling the lib32 packages on my machine for some reason (unrelated to this fix) so those are not included.

Hope this fixes it for others as well,

-Dan

[Daniel T Chen (crimsun)]

Excellent catch! I've pushed this upstream (http://mailman.alsa-project.org/pipermail/alsa-devel/2009-December/024070.html).

[Launchpad Janitor (janitor)]

This bug was fixed in the package alsa-lib - 1.0.21a-1ubuntu3

---------------
alsa-lib (1.0.21a-1ubuntu3) lucid; urgency=low

  * 0001-ALSA-pcm-Properly-close-timer-when-freeing-slaves.patch:
    Properly free timer fd when closing pcm slaves. Thanks, Dan
    McCombs! (submitted upstream, LP: #451893)
 -- Daniel T Chen <email address hidden> Sun, 20 Dec 2009 15:41:06 -0500

[Lennart (lennart-redhat-bugs)]

OK, seems that alsa-lib is at fault here. Reassigning.

http://git.alsa-project.org/?p=alsa-lib.git;a=commit;h=a256766c10c52cb6667de8a65f5cbb332fad4cc7

[Martin Pitt (pitti)]

Accepted alsa-lib into karmic-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

[Don (don-redhat-bugs)]

This just hit me again. I see that ubuntu has pushed the patch into their repos. Any ETA on Fedora 12 patch?

[Dan McCombs (overridex)]

The 1.0.20-3ubuntu6.1 package in proposed works for me, though I'd like to hear from some other people who were having this problem as well.

-Dan

[Thomas Bruckmaier (thomasbruckmaier)]

Yes, seems to work for me as well. Thanks.

[Drew Fisher (drew-m-fisher)]

I confirm that the 1.0.20-3ubuntu6.1 package in proposed fixes this bug for me as well. Great thanks!

[Launchpad Janitor (janitor)]

This bug was fixed in the package alsa-lib - 1.0.20-3ubuntu6.1

---------------
alsa-lib (1.0.20-3ubuntu6.1) karmic-proposed; urgency=low

  * debian/patches/Dont_leak_timer_fd_on_pcm_slave_close.patch:
    Prevent a local DoS by properly freeing timer fds when closing pcm
    slaves. Backported from upstream master HEAD (LP: #451893)
 -- Daniel T Chen <email address hidden> Mon, 21 Dec 2009 06:33:01 -0500

[Daniel T Chen (crimsun)]

Please do not change bug statuses without a really fine reason attached.

[Jaroslav (jaroslav-redhat-bugs)]

The patch is in alsa-lib-1.0.22-1 package.

[Don (don-redhat-bugs)]

My yum.log shows that I installed that package on Jan 7. I thought I had this occur again on the 8th, but can't be sure now. Anyway I'll be sure to note any re-occurrence.