Bug#771105: pulseaudio: Loops on daemon respawn

David Lynam david.lynam at redbrick.dcu.ie
Wed Nov 26 20:26:45 UTC 2014 

Killing/restarting Clementine doesn't make a difference.

I actually just rebooted a few minutes ago. As soon as GNOME loaded,
before doing anything else, I adjusted my volume (it was muted). The
problem appeared immediately. Is PA trying to restore some kind of
broken state?

I have attached a syslog snippet from a couple of minutes ago.

Thanks for the reply, Felipe.

On Wed, Nov 26, 2014 at 05:19:06PM -0300, Felipe Sateler wrote:
> On Wed, Nov 26, 2014 at 4:54 PM, David Ó Laigheanáin
> <david.lynam at redbrick.dcu.ie> wrote:
> > Package: pulseaudio
> > Version: 5.0-13
> > Severity: important
> >
> > Dear Maintainer,
> >
> > If playing a sound (may or may not be a prerequisite) when the Pulseaudio daemon is killed and respawned, it will become unusable. Any sounds thereafter experience an extreme latency and small snippets (< 1 second) are looped over and over rapidly. Changing volume becomes difficult as I assume the PA daemon is choked and is struggling to keep up with requests.
> >
> > My reproduction steps:
> > - Run Clementine (output via PulseAudio).
> > - Play song.
> > - Run 'pulseaudio --kill && pulseaudio --start' as user.
> > - Clementine will fail to play anything else and get stuck at around 0:00 or 0:01, with a tiny snippet of the music being played over and over.
> > - Attempt to change volume. The 'volume change' sound in GNOME will loop over and over rapidly and the volume bar and hotkeys will become unresponsive.
> > - Restart PA again. The problem doesn't go away.
> > - Reboot and the problem is fixed, until the next time.
> >
> > This shouldn't happen. Ideally, you should be able to restart PA as many times as you want at whatever speed and never have it become unusable.
> 
> What happens if you restart clementine? I think the problem is with
> the client that doesn't handle a dying server.
> 
> 
> 
> -- 
> 
> Saludos,
> Felipe Sateler
> 

-- 
Please consider using PGP to encrypt/sign your e-mails so that nobody other than
the intended recipient can read them. Privacy is important.

My public PGP key: http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xDA2E99B41C39C7D2
-------------- next part --------------
Nov 26 20:24:31 fuileach pulseaudio[5728]: [pulseaudio] pid.c: Daemon already running.
Nov 26 20:24:31 fuileach pulseaudio[5720]: Created 1 "Native client (UNIX socket client)"
Nov 26 20:24:31 fuileach pulseaudio[5720]: Protocol version: remote 29, local 29
Nov 26 20:24:31 fuileach pulseaudio[5720]: Got credentials: uid=1000 gid=1000 success=1
Nov 26 20:24:31 fuileach pulseaudio[5720]: SHM possible: yes
Nov 26 20:24:31 fuileach pulseaudio[5720]: Negotiated SHM: yes
Nov 26 20:24:31 fuileach pulseaudio[5720]: Looking for .desktop file for gnome-shell
Nov 26 20:24:31 fuileach pulseaudio[5720]: Found /usr/share/applications/gnome-shell.desktop.
Nov 26 20:24:33 fuileach gnome-session[2200]: (gnome-settings-daemon:2261): media-keys-plugin-WARNING **: Unable to get default sink
Nov 26 20:24:33 fuileach pulseaudio[5720]: Created 2 "Native client (UNIX socket client)"
Nov 26 20:24:33 fuileach pulseaudio[5720]: Protocol version: remote 29, local 29
Nov 26 20:24:33 fuileach pulseaudio[5720]: Got credentials: uid=1000 gid=1000 success=1
Nov 26 20:24:33 fuileach pulseaudio[5720]: SHM possible: yes
Nov 26 20:24:33 fuileach pulseaudio[5720]: Negotiated SHM: yes
Nov 26 20:24:33 fuileach pulseaudio[5720]: Looking for .desktop file for gnome-settings-daemon
Nov 26 20:24:33 fuileach gnome-session[2200]: (gnome-settings-daemon:2261): media-keys-plugin-WARNING **: Unable to get default source
Nov 26 20:24:33 fuileach pulseaudio[5720]: Created 3 "Native client (UNIX socket client)"
Nov 26 20:24:33 fuileach pulseaudio[5720]: Protocol version: remote 29, local 29
Nov 26 20:24:33 fuileach pulseaudio[5720]: Got credentials: uid=1000 gid=1000 success=1
Nov 26 20:24:33 fuileach pulseaudio[5720]: SHM possible: yes
Nov 26 20:24:33 fuileach pulseaudio[5720]: Negotiated SHM: yes
Nov 26 20:24:33 fuileach pulseaudio[5720]: Looking for .desktop file for gnome-shell
Nov 26 20:24:36 fuileach pulseaudio[5720]: Source alsa_input.pci-0000_00_14.2.analog-stereo idle for too long, suspending ...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Suspend cause of source alsa_input.pci-0000_00_14.2.analog-stereo is 0x0004, suspending
Nov 26 20:24:36 fuileach pulseaudio[5720]: Device suspended...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Hmm, no streams around, trying to vacuum.
Nov 26 20:24:36 fuileach pulseaudio[5720]: Sink alsa_output.pci-0000_00_14.2.analog-stereo idle for too long, suspending ...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Suspend cause of sink alsa_output.pci-0000_00_14.2.analog-stereo is 0x0004, suspending
Nov 26 20:24:36 fuileach pulseaudio[5720]: Device suspended...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Hmm, no streams around, trying to vacuum.
Nov 26 20:24:36 fuileach pulseaudio[5720]: Sink alsa_output.pci-0000_00_01.1.hdmi-stereo idle for too long, suspending ...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Suspend cause of sink alsa_output.pci-0000_00_01.1.hdmi-stereo is 0x0004, suspending
Nov 26 20:24:36 fuileach pulseaudio[5720]: Device suspended...
Nov 26 20:24:36 fuileach pulseaudio[5720]: Hmm, no streams around, trying to vacuum.
Nov 26 20:24:36 fuileach pulseaudio[5720]: /dev/snd/controlC0 is accessible: yes
Nov 26 20:24:36 fuileach pulseaudio[5720]: Resuming all sinks and sources of card alsa_card.pci-0000_00_01.1.
Nov 26 20:24:36 fuileach pulseaudio[5720]: /dev/snd/controlC1 is accessible: yes
Nov 26 20:24:36 fuileach pulseaudio[5720]: Resuming all sinks and sources of card alsa_card.pci-0000_00_14.2.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Client gnome-shell changes volume of sink alsa_output.pci-0000_00_14.2.analog-stereo.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Requested volume: front-left: 26739 /  41% / -23.36 dB,   front-right: 26739 /  41% / -23.36 dB
Nov 26 20:24:41 fuileach pulseaudio[5720]: Got hardware volume: front-left: 26904 /  41% / -23.20 dB,   front-right: 26904 /  41% / -23.20 dB
Nov 26 20:24:41 fuileach pulseaudio[5720]: Calculated software volume: front-left: 65134 /  99% / -0.16 dB,   front-right: 65134 /  99% / -0.16 dB (accurate-enough=yes)
Nov 26 20:24:41 fuileach pulseaudio[5720]: Volume going down to 26739 at 424200778
Nov 26 20:24:41 fuileach pulseaudio[5720]: Volume change to 26739 at 424200778 was written 8050 usec late
Nov 26 20:24:41 fuileach pulseaudio[5720]: Storing volume/mute for device+port sink:alsa_output.pci-0000_00_14.2.analog-stereo:analog-output-headphones.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Restoring device for stream sink-input-by-media-role:event.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Not setting device for stream audio-volume-change, because already set.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Negotiated format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
Nov 26 20:24:41 fuileach pulseaudio[5720]: Restoring volume for sink input sink-input-by-media-role:event.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Restoring mute state for sink input sink-input-by-media-role:event.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes busy, resuming.
Nov 26 20:24:41 fuileach pulseaudio[5720]: Suspend cause of sink alsa_output.pci-0000_00_14.2.analog-stereo is 0x0000, resuming
Nov 26 20:24:43 fuileach pulseaudio[5720]: Successfully acquired reservation lock on device 'Audio1'
Nov 26 20:24:43 fuileach pulseaudio[5720]: Trying resume...
Nov 26 20:24:43 fuileach pulseaudio[5720]: Maximum hw buffer size is 371 ms
Nov 26 20:24:43 fuileach pulseaudio[5720]: Set buffer size first (to 4416 samples), period size second (to 736 samples).
Nov 26 20:24:43 fuileach pulseaudio[5720]: hwbuf_unused=0
Nov 26 20:24:43 fuileach pulseaudio[5720]: setting avail_min=1
Nov 26 20:24:43 fuileach pulseaudio[5720]: Resumed successfully...
Nov 26 20:24:43 fuileach pulseaudio[5720]: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes idle, timeout in 5 seconds.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Starting playback.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes idle, timeout in 5 seconds.
Nov 26 20:24:43 fuileach pulseaudio[5720]: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
Nov 26 20:24:43 fuileach pulseaudio[5720]: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
Nov 26 20:24:43 fuileach pulseaudio[5720]: Created input 0 "audio-volume-change" on alsa_output.pci-0000_00_14.2.analog-stereo with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Nov 26 20:24:43 fuileach pulseaudio[5720]:     event.mouse.button = "1"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     event.mouse.y = "70"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     event.mouse.x = "1183"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     event.description = "Athraíodh an airde"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     event.id = "audio-volume-change"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     media.role = "event"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     media.name = "audio-volume-change"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     media.filename = "/usr/share//sounds/freedesktop/stereo/audio-volume-change.oga"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.name = "GNOME Shell"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     native-protocol.peer = "UNIX socket client"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     native-protocol.version = "29"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.id = "org.gnome.Shell"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.icon_name = "start-here"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.language = "ga_IE.UTF-8"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     window.x11.screen = "0"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     window.x11.display = ":0"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.id = "2314"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.user = "david"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.host = "fuileach"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.binary = "gnome-shell"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.machine_id = "fb75a029cab0d31b5676ade754660933"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     application.process.session_id = "1"
Nov 26 20:24:43 fuileach pulseaudio[5720]:     module-stream-restore.id = "sink-input-by-media-role:event"
Nov 26 20:24:43 fuileach pulseaudio[5720]: Requested tlength=2000.00 ms, minreq=20.00 ms
Nov 26 20:24:43 fuileach pulseaudio[5720]: Traditional mode enabled, modifying sink usec only for compat with minreq.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Requested latency=1960.00 ms, Received latency=100.14 ms
Nov 26 20:24:43 fuileach pulseaudio[5720]: memblockq requested: maxlength=4194304, tlength=352800, base=4, prebuf=349276, minreq=3528 maxrewind=0
Nov 26 20:24:43 fuileach pulseaudio[5720]: memblockq sanitized: maxlength=4194304, tlength=352800, base=4, prebuf=349276, minreq=3528 maxrewind=0
Nov 26 20:24:43 fuileach pulseaudio[5720]: Final latency 2100.14 ms = 1960.00 ms + 2*20.00 ms + 100.14 ms
Nov 26 20:24:43 fuileach pulseaudio[5720]: Requested volume: front-left: 26272 /  40% / -23.82 dB,   front-right: 26272 /  40% / -23.82 dB
Nov 26 20:24:43 fuileach pulseaudio[5720]: Got hardware volume: front-left: 26291 /  40% / -23.80 dB,   front-right: 26291 /  40% / -23.80 dB
Nov 26 20:24:43 fuileach pulseaudio[5720]: Calculated software volume: front-left: 65489 / 100% / -0.02 dB,   front-right: 65489 / 100% / -0.02 dB (accurate-enough=yes)
Nov 26 20:24:43 fuileach pulseaudio[5720]: Volume going down to 26272 at 426329062
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 90708 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 90304 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 89938 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Dropped redundant event due to change event.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 89547 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 88804 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 88402 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 88037 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 87636 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 87261 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 86442 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Next volume change in 86004 usec
Nov 26 20:24:43 fuileach pulseaudio[5720]: Requesting rewind due to end of underrun.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Requested to rewind 17664 bytes.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Limited to 17268 bytes.
Nov 26 20:24:43 fuileach pulseaudio[5720]: before: 4317
Nov 26 20:24:43 fuileach pulseaudio[5720]: after: 4317
Nov 26 20:24:43 fuileach pulseaudio[5720]: Rewound 17268 bytes.
Nov 26 20:24:43 fuileach pulseaudio[5720]: Processing rewind...
Nov 26 20:24:43 fuileach pulseaudio[5720]: latency = 0
Nov 26 20:24:43 fuileach pulseaudio[5720]: Volume change to 26272 at 426238963 was written 8003 usec late
Nov 26 20:24:45 fuileach pulseaudio[5720]: Have to rewind 17268 bytes on render memblockq.
Nov 26 20:24:45 fuileach pulseaudio[5720]: Processing rewind...
Nov 26 20:24:45 fuileach pulseaudio[5720]: Implicit drain of 'audio-volume-change'
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7240 bytes ago (10424 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7268 bytes ago (10396 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7284 bytes ago (10380 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7300 bytes ago (10364 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7328 bytes ago (10336 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7356 bytes ago (10308 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7376 bytes ago (10288 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7396 bytes ago (10268 bytes ahead in playback buffer)
Nov 26 20:24:45 fuileach pulseaudio[5720]: Found underrun 7420 bytes ago (10244 bytes ahead in playback buffer)
Nov 26 20:24:51 fuileach pulseaudio[5720]: Synced.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: Digital signature
URL: <http://lists.alioth.debian.org/pipermail/pkg-pulseaudio-devel/attachments/20141126/485794a2/attachment.sig>

More information about the pkg-pulseaudio-devel mailing list