Bug 532775 - pulseaudio doesn't deal well with irregular clock intervals inside a VM
Summary: pulseaudio doesn't deal well with irregular clock intervals inside a VM
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: pulseaudio
Version: 12
Hardware: i686
OS: Linux
low
medium
Target Milestone: ---
Assignee: Lennart Poettering
QA Contact: Fedora Extras Quality Assurance
URL: http://www.alsa-project.org/db/?f=9d4...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-11-03 19:34 UTC by d. johnson
Modified: 2009-12-01 04:27 UTC (History)
7 users (show)

Fixed In Version: 0.9.21-1.fc12
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2009-11-27 22:00:20 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
pulseaudio -vvvv output (139.09 KB, text/plain)
2009-11-04 06:23 UTC, d. johnson
no flags Details

Description d. johnson 2009-11-03 19:34:06 UTC
Description of problem:

Run "aplay /usr/share/sounds/ekiga/ring.wav" and watch the messages pile up.

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

alsa-lib-1.0.21-3.fc12.i686
pulseaudio-0.9.19-1.fc12.i686

How reproducible:

Attempt to play any audio file.

Steps to Reproduce:
1.  "aplay /usr/share/sounds/ekiga/ring.wav"
2. ...
3.  review /var/log/messages and note the many lines of output.
  
Actual results:

Nov  3 13:13:10 fedora12 pulseaudio[1719]: ratelimit.c: 7 events suppressed
Nov  3 13:14:22 fedora12 pulseaudio[6766]: socket-server.c: bind(): Address already in use
Nov  3 13:14:22 fedora12 pulseaudio[6766]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:14:22 fedora12 pulseaudio[6766]: main.c: Module load failed.
Nov  3 13:14:22 fedora12 pulseaudio[6766]: main.c: Failed to initialize daemon.
Nov  3 13:14:23 fedora12 kernel: ALSA sound/usb/usbaudio.c:934: timeout: still 3 active urbs..
Nov  3 13:14:31 fedora12 pulseaudio[6766]: ratelimit.c: 759 events suppressed
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 20158464 bytes (114277 ms).
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_ens1371'. Please report this issue to the ALSA developers.
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: snd_pcm_dump():
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Hardware PCM card 0 'Ensoniq AudioPCI' device 0 subdevice 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Its setup is:
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   stream       : PLAYBACK
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   access       : MMAP_INTERLEAVED
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   format       : S16_LE
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   subformat    : STD
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   channels     : 2
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   rate         : 44100
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   exact rate   : 44101 (1445100000/32768)
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   msbits       : 16
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   buffer_size  : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_size  : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_time  : 371510
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   tstamp_mode  : ENABLE
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_step  : 1
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   avail_min    : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_event : 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   start_threshold  : -1
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   stop_threshold   : 1073741824
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   silence_threshold: 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   silence_size : 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   boundary     : 1073741824
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   appl_ptr     : 6967296
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   hw_ptr       : 11990528
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: -19437568 bytes (-110190 ms).
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_ens1371'. Please report this issue to the ALSA developers.
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: snd_pcm_dump():
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Hardware PCM card 0 'Ensoniq AudioPCI' device 0 subdevice 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: Its setup is:
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   stream       : PLAYBACK
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   access       : MMAP_INTERLEAVED
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   format       : S16_LE
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   subformat    : STD
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   channels     : 2
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   rate         : 44100
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   exact rate   : 44101 (1445100000/32768)
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   msbits       : 16
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   buffer_size  : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_size  : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_time  : 371510
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   tstamp_mode  : ENABLE
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_step  : 1
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   avail_min    : 16384
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   period_event : 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   start_threshold  : -1
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   stop_threshold   : 1073741824
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   silence_threshold: 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   silence_size : 0
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   boundary     : 1073741824
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   appl_ptr     : 7131136
Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c:   hw_ptr       : 11990528
Nov  3 13:14:37 fedora12 pulseaudio[6776]: socket-server.c: bind(): Address already in use
Nov  3 13:14:37 fedora12 pulseaudio[6776]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:14:37 fedora12 pulseaudio[6776]: main.c: Module load failed.
Nov  3 13:14:37 fedora12 pulseaudio[6776]: main.c: Failed to initialize daemon.
Nov  3 13:14:37 fedora12 pulseaudio[6774]: main.c: Daemon startup failed.

Expected results:

Any sound.   Currently there is none at all.

Additional info:

alsa-info url attached for reference.   Volume for both master and pcm were adjusted to 100% with no additional results.

Comment 1 Lennart Poettering 2009-11-03 23:29:33 UTC
Nov  3 13:14:37 fedora12 pulseaudio[6776]: socket-server.c: bind(): Address
already in use
Nov  3 13:14:37 fedora12 pulseaudio[6776]: module.c: Failed to load  module
"module-esound-protocol-unix" (argument: ""): initialization failed.

This means that you already have esd or pa running, and PA cannot be started. Please make sure that no other PA or esd is running for the user.

Comment 2 d. johnson 2009-11-04 01:59:39 UTC
There is no additional copy running. This is just a basic F12 install.  Only *ONE* copy of pulse running, no ESD at all.

Comment 3 d. johnson 2009-11-04 05:45:34 UTC
Unplugging the usb device is worse:

$ time aplay /usr/share/sounds/ekiga/ring.wav 
Playing WAVE '/usr/share/sounds/ekiga/ring.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
underrun!!! (at least 18.263 ms long)

real	0m0.091s
user	0m0.023s
sys	0m0.013s

This .wav is not that brief.

Rebooted to clear up any potential conflicts from earlier.

Messages file still spews forth:

Nov  3 23:38:21 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1523 of process 1523 (/usr/bin/pulseaudio) owned by '42' high priority at nice level -11.
Nov  3 23:38:22 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1529 of process 1523 (/usr/bin/pulseaudio) owned by '42' RT at priority 5.
Nov  3 23:38:22 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1530 of process 1523 (/usr/bin/pulseaudio) owned by '42' RT at priority 5.
Nov  3 23:38:27 fedora12 pulseaudio[1523]: ratelimit.c: 788 events suppressed
Nov  3 23:38:44 fedora12 pulseaudio[1523]: ratelimit.c: 4 events suppressed
Nov  3 23:38:49 fedora12 pulseaudio[1523]: ratelimit.c: 817 events suppressed
Nov  3 23:38:57 fedora12 kernel: fuse init (API version 7.12)
Nov  3 23:38:58 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1696 of process 1696 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Nov  3 23:38:58 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1702 of process 1696 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Nov  3 23:38:58 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1703 of process 1696 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Nov  3 23:38:59 fedora12 rtkit-daemon[1525]: Sucessfully made thread 1709 of process 1709 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Nov  3 23:38:59 fedora12 pulseaudio[1709]: pid.c: Daemon already running.
Nov  3 23:39:03 fedora12 pulseaudio[1696]: ratelimit.c: 753 events suppressed
Nov  3 23:39:33 fedora12 pulseaudio[1696]: ratelimit.c: 28 events suppressed
Nov  3 23:39:38 fedora12 pulseaudio[1696]: ratelimit.c: 818 events suppressed
Nov  3 23:39:49 fedora12 pulseaudio[1696]: ratelimit.c: 1 events suppressed
Nov  3 23:39:49 fedora12 pulseaudio[1696]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Nov  3 23:39:49 fedora12 pulseaudio[1696]: alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_ens1371'. Please report this issue to the ALSA developers.
Nov  3 23:39:49 fedora12 pulseaudio[1696]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Nov  3 23:39:54 fedora12 pulseaudio[1696]: ratelimit.c: 812 events suppressed

Comment 4 d. johnson 2009-11-04 06:20:55 UTC
With Adam's assistance:

$ echo 'autospawn = no' > ~/.pulse/client.conf

$ ps aux |egrep -cw '(pulseaudio|esd)'
1

$ ps aux |egrep -w '(pulseaudio|esd)'
dj        2237  0.0  0.1   4240   704 pts/2    R+   00:06   0:00 egrep -w (pulseaudio|esd)

$ pulseaudio -vvvv

[ log saved, will include shortly ]

In another tab:

$ time aplay /usr/share/sounds/ekiga/ring.wav 
ALSA lib pulse.c:229:(pulse_connect) PulseAudio: Unable to connect: Connection refused
 
aplay: main:608: audio open error: Connection refused
 
real	0m0.024s
user	0m0.005s
sys	0m0.006s


-- Additional /var/log/messages since above --
Nov  4 00:08:33 fedora12 rtkit-daemon[1525]: Sucessfully made thread 2279 of process 2279 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Nov  4 00:08:33 fedora12 rtkit-daemon[1525]: Sucessfully made thread 2281 of process 2279 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Nov  4 00:08:34 fedora12 rtkit-daemon[1525]: Sucessfully made thread 2282 of process 2279 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Nov  4 00:09:00 fedora12 kernel: usb 2-1: new full speed USB device using uhci_hcd and address 3
Nov  4 00:09:01 fedora12 kernel: usb 2-1: New USB device found, idVendor=0d8c, idProduct=000c
Nov  4 00:09:01 fedora12 kernel: usb 2-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
Nov  4 00:09:01 fedora12 kernel: usb 2-1: Product: C-Media USB Headphone Set  
Nov  4 00:09:01 fedora12 kernel: usb 2-1: configuration #1 chosen from 1 choice
Nov  4 00:09:01 fedora12 kernel: input: C-Media USB Headphone Set   as /devices/pci0000:00/0000:00:11.0/0000:02:00.0/usb2/2-1/2-1:1.3/input/input5
Nov  4 00:09:01 fedora12 kernel: generic-usb 0003:0D8C:000C.0001: input,hidraw0: USB HID v1.00 Device [C-Media USB Headphone Set  ] on usb-0000:02:00.0-1/input3
Nov  4 00:09:01 fedora12 kernel: usbcore: registered new interface driver snd-usb-audio
Nov  4 00:09:02 fedora12 rtkit-daemon[1525]: Sucessfully made thread 2313 of process 2279 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Nov  4 00:09:02 fedora12 rtkit-daemon[1525]: Sucessfully made thread 2314 of process 2279 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.

-- pulseaudio -vvvv output --

... too long to include here.  will attach.

Comment 5 d. johnson 2009-11-04 06:23:32 UTC
Created attachment 367412 [details]
pulseaudio -vvvv output

Comment 6 Lennart Poettering 2009-11-04 15:48:21 UTC
Have you modified your pulseaudio configuration files in any way? The error messages you get suggest that.

Also, the lines:

Nov  3 13:14:31 fedora12 pulseaudio[6766]: alsa-util.c: snd_pcm_avail()
returned a value that is exceptionally large: 20158464 bytes (114277 ms).

show that your audio driver is broken, the timing is not reliable and overflows.

Is this in a VM?

You bug report above shows a couple of issues. If the issue with the conflicting esd socket is gone now, then at least the driver issue remain.

Comment 7 d. johnson 2009-11-04 15:55:32 UTC
No, I have not modified the pulseaudio config other than what was stated in comment 4.

Yes, this one is in a vm.  I removed pulseaudio and problems instantly vanish.  Clear audio, no pops, scrapes, drags, lag, clipping, nothing.  Works.  NTP shows that the clock is very stable in the vm.

The conflicting socket was "fixed" by change made in comment 4.  ie: Pulse no longer starts up without manual intervention.  If i remove that config change, it reoccurs.

Please let me know what you would like changed or what output you would like to see.

Comment 8 Adam Williamson 2009-11-04 17:07:38 UTC
when lennart says the 'timing' he's talking about the timing in the audio driver, not the system clock.

"The conflicting socket was "fixed" by change made in comment 4.  ie: Pulse no
longer starts up without manual intervention.  If i remove that config change,
it reoccurs."

Can you clarify what you mean by that? Do you just mean you no longer get multiple PA processes running? *One* copy of PA ought to start 'without manual intervention' when you log in to the graphical environment. That's what's supposed to happen.

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 9 d. johnson 2009-11-04 18:28:17 UTC
If I remove ~/.pulse/client.conf, logout, and back in again:

$ ps -ef|grep pulse
gdm      14293     1  1 12:24 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
dj       14455     1  3 12:25 ?        00:00:00 /usr/bin/pulseaudio --start
dj       14469 14455  0 12:25 ?        00:00:00 /usr/libexec/pulse/gconf-helper
dj       14738 14530  0 12:25 pts/3    00:00:00 grep pulse

Two copies are running.

Comment 10 Adam Williamson 2009-11-04 18:37:20 UTC
ah, OK. as I mentioned on IRC, that's interesting and a bug somewhere, but probably not *this* bug, since you still have this bug without the two copies running, so please file that separately. thanks.

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 11 d. johnson 2009-11-04 20:26:38 UTC
Sort of partially made it work:

diff --git a/pulse/daemon.conf b/pulse/daemon.conf
index 941775f..d359f7f 100644
--- a/pulse/daemon.conf
+++ b/pulse/daemon.conf
@@ -34,6 +34,7 @@
 ; nice-level = -11
 
 ; realtime-scheduling = yes
+; ### FIXME
 realtime-scheduling = yes
 ; realtime-priority = 5
 
@@ -80,4 +81,5 @@ realtime-scheduling = yes
 
 ; default-fragments = 4
 ; default-fragment-size-msec = 25
+; ### FIXME
 default-fragment-size-msec = 10
diff --git a/pulse/default.pa b/pulse/default.pa
index efbf210..0eea73f 100644
--- a/pulse/default.pa
+++ b/pulse/default.pa
@@ -48,12 +48,10 @@ load-module module-augment-properties
 #load-module module-null-sink
 #load-module module-pipe-sink
 
 ### Automatically load driver modules depending on the hardware available
 .ifexists module-udev-detect.so
 #load-module module-udev-detect
+### FIXME
+ load-module module-udev-detect tsched=0
 .else
 ### Alternatively use the static hardware detection module (for systems that


Made this change to my user:

# usermod -aG jackuser $USERID


Installed these:

pavucontrol-0.9.10-1.fc12                     Wed 04 Nov 2009 01:36:48 PM CST
padevchooser-0.9.4-0.10.svn20070925.fc12      Wed 04 Nov 2009 01:36:48 PM CST
pulseaudio-module-zeroconf-0.9.19-1.fc12      Wed 04 Nov 2009 01:36:47 PM CST
pavumeter-0.9.3-4.fc12                        Wed 04 Nov 2009 01:36:47 PM CST
paprefs-0.9.9-4.fc12                          Wed 04 Nov 2009 01:36:47 PM CST
paman-0.9.4-4.fc12                            Wed 04 Nov 2009 01:36:47 PM CST
pulseaudio-esound-compat-0.9.19-1.fc12        Wed 04 Nov 2009 01:36:46 PM CST
pulseaudio-libs-zeroconf-0.9.19-1.fc12        Wed 04 Nov 2009 01:36:45 PM CST


Rebooted.

Now, audio only works via one card:

02:02.0 Multimedia audio controller: Ensoniq ES1371 [AudioPCI-97] (rev 02)

The USB does not play:

Bus 002 Device 003: ID 0d8c:000c C-Media Electronics, Inc. Audio Adapter.

Suggestions welcome on how to isolate what actually helped.

Comment 12 d. johnson 2009-11-04 20:57:20 UTC
Additional output from /var/log/messages:

Nov  3 13:14:37 fedora12 pulseaudio[6776]: socket-server.c: bind(): Address already in use
Nov  3 13:14:37 fedora12 pulseaudio[6776]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:14:37 fedora12 pulseaudio[6776]: main.c: Module load failed.
Nov  3 13:14:37 fedora12 pulseaudio[6776]: main.c: Failed to initialize daemon.
Nov  3 13:14:37 fedora12 pulseaudio[6774]: main.c: Daemon startup failed.
Nov  3 13:24:40 fedora12 yum: Erased: alsa-plugins-pulseaudio
Nov  3 13:24:59 fedora12 setroubleshoot: SELinux is preventing the /usr/bin/iceauth from using potentially mislabeled files (.xfsm-ICE-RVNN2U). For complete SELinux messages. run sealert -l 19d7572e-016f-4b72-aa08-28d59c34e9be
Nov  3 13:25:09 fedora12 pulseaudio[7577]: ratelimit.c: 744 events suppressed
Nov  3 13:25:11 fedora12 pulseaudio[7739]: socket-server.c: bind(): Address already in use
Nov  3 13:25:11 fedora12 pulseaudio[7739]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:11 fedora12 pulseaudio[7739]: main.c: Module load failed.
Nov  3 13:25:11 fedora12 pulseaudio[7739]: main.c: Failed to initialize daemon.
Nov  3 13:25:11 fedora12 restorecond: Unable to watch (/home/dj/public_html/*) No such file or directory
Nov  3 13:25:12 fedora12 kernel: ALSA sound/usb/usbaudio.c:934: timeout: still 3 active urbs..
Nov  3 13:25:13 fedora12 pulseaudio[7837]: socket-server.c: bind(): Address already in use
Nov  3 13:25:13 fedora12 pulseaudio[7837]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:13 fedora12 pulseaudio[7837]: main.c: Module load failed.
Nov  3 13:25:13 fedora12 pulseaudio[7837]: main.c: Failed to initialize daemon.
Nov  3 13:25:14 fedora12 kernel: ALSA sound/usb/usbaudio.c:934: timeout: still 3 active urbs..
Nov  3 13:25:14 fedora12 pulseaudio[7754]: main.c: Daemon startup failed.
Nov  3 13:25:15 fedora12 setroubleshoot: SELinux is preventing the /usr/bin/iceauth from using potentially mislabeled files (.xfsm-ICE-QA362U). For complete SELinux messages. run sealert -l 055e89b4-bcc2-4774-b6da-12dd15bb839f
Nov  3 13:25:19 fedora12 pulseaudio[7985]: socket-server.c: bind(): Address already in use
Nov  3 13:25:19 fedora12 pulseaudio[7985]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:19 fedora12 pulseaudio[7985]: main.c: Module load failed.
Nov  3 13:25:19 fedora12 pulseaudio[7985]: main.c: Failed to initialize daemon.
Nov  3 13:25:19 fedora12 pulseaudio[7983]: main.c: Daemon startup failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: socket-server.c: bind(): Address already in use
Nov  3 13:25:27 fedora12 pulseaudio[7998]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: main.c: Module load failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: main.c: Failed to initialize daemon.
Nov  3 13:25:27 fedora12 pulseaudio[7996]: main.c: Daemon startup failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: socket-server.c: bind(): Address already in use
Nov  3 13:25:32 fedora12 pulseaudio[8007]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: main.c: Module load failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: main.c: Failed to initialize daemon.
Nov  3 13:25:32 fedora12 pulseaudio[8005]: main.c: Daemon startup failed.
Nov  3 13:25:40 fedora12 pulseaudio[8016]: socket-server.c: bind(): Address already in use
Nov  3 13:25:40 fedora12 pulseaudio[8016]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: socket-server.c: bind(): Address already in use
Nov  3 13:25:27 fedora12 pulseaudio[7998]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: main.c: Module load failed.
Nov  3 13:25:27 fedora12 pulseaudio[7998]: main.c: Failed to initialize daemon.
Nov  3 13:25:27 fedora12 pulseaudio[7996]: main.c: Daemon startup failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: socket-server.c: bind(): Address already in use
Nov  3 13:25:32 fedora12 pulseaudio[8007]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: main.c: Module load failed.
Nov  3 13:25:32 fedora12 pulseaudio[8007]: main.c: Failed to initialize daemon.
Nov  3 13:25:32 fedora12 pulseaudio[8005]: main.c: Daemon startup failed.
Nov  3 13:25:40 fedora12 pulseaudio[8016]: socket-server.c: bind(): Address already in use
Nov  3 13:25:40 fedora12 pulseaudio[8016]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:40 fedora12 pulseaudio[8016]: main.c: Module load failed.
Nov  3 13:25:40 fedora12 pulseaudio[8016]: main.c: Failed to initialize daemon.
Nov  3 13:25:40 fedora12 pulseaudio[8014]: main.c: Daemon startup failed.
Nov  3 13:25:45 fedora12 pulseaudio[8025]: socket-server.c: bind(): Address already in use
Nov  3 13:25:45 fedora12 pulseaudio[8025]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:45 fedora12 pulseaudio[8025]: main.c: Module load failed.
Nov  3 13:25:45 fedora12 pulseaudio[8025]: main.c: Failed to initialize daemon.
Nov  3 13:25:45 fedora12 pulseaudio[8023]: main.c: Daemon startup failed.
Nov  3 13:25:53 fedora12 pulseaudio[8034]: socket-server.c: bind(): Address already in use
Nov  3 13:25:53 fedora12 pulseaudio[8034]: module.c: Failed to load  module "module-esound-protocol-unix" (argument: ""): initialization failed.
Nov  3 13:25:53 fedora12 pulseaudio[8034]: main.c: Module load failed.
Nov  3 13:25:53 fedora12 pulseaudio[8034]: main.c: Failed to initialize daemon.

Comment 13 d. johnson 2009-11-04 21:00:02 UTC
"fixfiles check" shows no mislabeled files.  selinux report shows:

# sealert -l 19d7572e-016f-4b72-aa08-28d59c34e9be

Summary:

SELinux is preventing the /usr/bin/iceauth from using potentially mislabeled
files (.xfsm-ICE-RVNN2U).

Detailed Description:

[SELinux is in permissive mode. This access was not denied.]

SELinux has denied iceauth access to potentially mislabeled file(s)
(.xfsm-ICE-RVNN2U). This means that SELinux will not allow iceauth to use these
files. It is common for users to edit files in their home directory or tmp
directories and then move (mv) them to system directories. The problem is that
the files end up with the wrong file context which confined applications are not
allowed to access.

Allowing Access:

If you want iceauth to access this files, you need to relabel them using
restorecon -v '.xfsm-ICE-RVNN2U'. You might want to relabel the entire directory
using restorecon -R -v ''.

Additional Information:

Source Context                unconfined_u:unconfined_r:iceauth_t:s0-s0:c0.c1023
Target Context                unconfined_u:object_r:user_tmp_t:s0
Target Objects                .xfsm-ICE-RVNN2U [ file ]
Source                        iceauth
Source Path                   /usr/bin/iceauth
Port                          <Unknown>
Host                          fedora12.ether.net
Source RPM Packages           xorg-x11-server-utils-7.4-13.fc12
Target RPM Packages           
Policy RPM                    selinux-policy-3.6.32-35.fc12
Selinux Enabled               True
Policy Type                   targeted
MLS Enabled                   True
Enforcing Mode                Permissive
Plugin Name                   home_tmp_bad_labels
Host Name                     fedora12.ether.net
Platform                      Linux fedora12.ether.net 2.6.31.5-96.fc12.i686.PAE
                              #1 SMP Fri Oct 23 19:39:36 EDT 2009 i686 i686
Alert Count                   1
First Seen                    Tue Nov  3 13:24:56 2009
Last Seen                     Tue Nov  3 13:24:56 2009
Local ID                      19d7572e-016f-4b72-aa08-28d59c34e9be
Line Numbers                  

Raw Audit Messages            

node=fedora12.ether.net type=AVC msg=audit(1257276296.661:24326): avc:  denied  { read } for  pid=7518 comm="iceauth" name=".xfsm-ICE-RVNN2U" dev=sda2 ino=10714 scontext=unconfined_u:unconfined_r:iceauth_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_tmp_t:s0 tclass=file

node=fedora12.ether.net type=SYSCALL msg=audit(1257276296.661:24326): arch=40000003 syscall=5 success=yes exit=3 a0=bfa2dab7 a1=0 a2=1b6 a3=804bbae items=0 ppid=1667 pid=7518 auid=500 uid=500 gid=500 euid=500 suid=500 fsuid=500 egid=500 sgid=500 fsgid=500 tty=(none) ses=1 comm="iceauth" exe="/usr/bin/iceauth" subj=unconfined_u:unconfined_r:iceauth_t:s0-s0:c0.c1023 key=(null)

Comment 14 Lennart Poettering 2009-11-04 21:22:49 UTC
Hmm, I wonder if sshould simply detect that we are running in a VM and then disable the timer-based scheduling, under the assumption that the OS scheduling cannot be trusted then, anyway...

(In reply to comment #9)
> If I remove ~/.pulse/client.conf, logout, and back in again:
> 
> $ ps -ef|grep pulse
> gdm      14293     1  1 12:24 ?        00:00:00 /usr/bin/pulseaudio --start
> --log-target=syslog
> dj       14455     1  3 12:25 ?        00:00:00 /usr/bin/pulseaudio --start

One is user gdm, the other is user dj. They use different esd sockets (unless configured otherwise), so this is not what could cause this issue.

Anyway, the title of this bug report does not really reflect what this bug report is about. I'll now declare that this bug is about the instability of the timing and scheduling in a VM and that PA should handle that better. Please open a seperate bug report for the other issues, if they persist

Comment 15 Lennart Poettering 2009-11-04 21:23:39 UTC
Which VM is this btw? kvm?

Comment 16 d. johnson 2009-11-04 21:33:44 UTC
I've no idea what these messages mean, but I have a large number of them:

     11 count:
fedora12 pulseaudio[1710]: asyncq.c: q overrun, queuing locally

  50277 count:
fedora12 pulseaudio[1710]: alsa-source.c: Resume failed, couldn't restore
original fragment settings. (Old: 7052/1760, New 3101120/1756)

The last message repeats about 767 times per second.  I'm not currently playing
any audio.

Suggestions welcome on what it means and how to resolve it.

Comment 17 Richard W.M. Jones 2009-11-04 21:39:32 UTC
You can use virt-what to tell if you are virtualized.

However that just works around the real issue which is that
you're not getting good scheduling from your virtual kernel.
It seems it would be better to understand that problem.

Do you have some simple test program which we could use to
demonstrate the scheduling problem?  And/or which syscalls
does this involve?

Comment 18 d. johnson 2009-11-04 21:44:16 UTC
Rebooted.  Now I'm back to square 1.  No audio at all.

Comment 19 d. johnson 2009-11-05 01:10:17 UTC
Some interesting test results.

On login, "sleep 30; pulseaudio -k; pulseaudio" - and I have working sound.  Why sleep 30s?  Because two copies of pa are running on login.  It takes at least 30s for one to die.  After the first dies, the second refuses to play audio.  Restarting it appears to make audio work again.

On a suggestion, did a 'echo DISPLAYMANAGER=/usr/bin/slim-dynwm > /etc/sysconfig/desktop' and audio works without the above kludge.

Comment 20 Matthias Clasen 2009-11-05 19:01:01 UTC
If you are using an alternative display manager, it could be that it does not do the right things with ConsoleKit to make the acl switch happen ?

Comment 21 Lennart Poettering 2009-11-10 02:46:37 UTC
PA upstream now detects if we are running in a VM btw.

Comment 22 Fedora Update System 2009-11-11 05:07:31 UTC
pulseaudio-0.9.20-1.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/pulseaudio-0.9.20-1.fc12

Comment 23 Fedora Update System 2009-11-12 00:58:11 UTC
pulseaudio-0.9.20-1.fc12 has been pushed to the Fedora 12 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update pulseaudio'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F12/FEDORA-2009-11428

Comment 24 Bug Zapper 2009-11-16 15:00:47 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 12 development cycle.
Changing version to '12'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 25 Fedora Update System 2009-11-23 05:23:50 UTC
pulseaudio-0.9.21-1.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/pulseaudio-0.9.21-1.fc12

Comment 26 Fedora Update System 2009-11-25 15:02:26 UTC
pulseaudio-0.9.21-1.fc12 has been pushed to the Fedora 12 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update pulseaudio'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F12/FEDORA-2009-12057

Comment 27 Fedora Update System 2009-11-27 21:59:56 UTC
pulseaudio-0.9.21-1.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 28 Fedora Update System 2009-12-01 04:27:26 UTC
pulseaudio-0.9.21-1.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.