Bug 496281 - PA backend of XINE has issues
PA backend of XINE has issues
Status: CLOSED WONTFIX
Product: Fedora
Classification: Fedora
Component: xine-lib (Show other bugs)
11
All Linux
low Severity medium
: ---
: ---
Assigned To: Lennart Poettering
Fedora Extras Quality Assurance
http://bugs.xine-project.org/show_bug...
:
: 497698 501154 555912 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2009-04-17 11:58 EDT by David Woodhouse
Modified: 2010-06-28 07:52 EDT (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2010-06-28 07:52:53 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
pulseaudio output (44.96 KB, text/plain)
2009-04-26 12:11 EDT, David Woodhouse
no flags Details
pulseaudio output with xine native PA driver (45.64 KB, text/plain)
2009-04-27 04:51 EDT, David Woodhouse
no flags Details

  None (edit)
Description David Woodhouse 2009-04-17 11:58:35 EDT
I was attempting to give a presentation on Free Software this week, and I wanted to play the Stephen Fry video produced for GNU's 25th birthday.

Having failed to get it to work in the OpenOffice.org presentation directly because pulseaudio was actually working (bug #496276), I tried coming out of OOo and using xine to play the video instead.

Sometimes, in testing, I would see that xine would start up but with its volume set to zero -- and I couldn't ever _change_ the volume in gnome-volume-control until the video was already running, so I'd always miss the first few words of his speech.

Other times, it seemed that xine just failed to 'connect' to pulseaudio, and never appeared in gnome-volume-control at all. There was just no audio, with no output from xine telling me why.

I am completely at a loss as to how I should go about debugging this. The only way I got audio working in F-10 was to remove all traces of pulseaudio, but I'm determined to give it more of a chance in F-11...
Comment 1 Lennart Poettering 2009-04-18 12:05:03 EDT
Run pulseaudio -vvvv in a terminal (kill it first with pulseaudio -k). That will spit out a lot of debug output and should give you a hint of what's going on. If you cannot make sense of it paste it here.
Comment 2 David Woodhouse 2009-04-20 07:14:58 EDT
When I kill pulseaudio and restart it, the panel applet and volume/mute hotkeys stop working in my gnome session.
Comment 3 David Woodhouse 2009-04-26 12:09:54 EDT
I've just had this happen again with the flash player. First it just wasn't appearing in the list of applications in the new lobotomised gnome-volume-control. I tried closing the tab in firefox, and firefox locked up without redrawing itself for a minute or so.

Opening the same page in a new tab, it _did_ manage to connect to PA but started up muted. I'll attach pulseaudio -vvvvv output from that run.
Comment 4 David Woodhouse 2009-04-26 12:11:47 EDT
Created attachment 341361 [details]
pulseaudio output

This shows the flash player starting up muted.
Comment 5 David Woodhouse 2009-04-26 12:16:48 EDT
There's no interesting output from pulseaudio -vvvvv when it just fails to connect. Perhaps unsurprisingly. How do we go about debugging that?
Comment 6 David Woodhouse 2009-04-26 13:40:29 EDT
I can reproduce the silent failure mode by killing pulseaudio and restarting it, while the flash player is on the screen. So maybe the first time it happened it was because pulseaudio had crashed?

After that, I don't get sound again until I close the tab -- and that long wait on exit seems to be because it's waiting for a futex.

I'd suggest it could be a bug with failing to try to reconnect to pulse after pulse goes away.... but when this was happening to xine, it was at xine startup.
Comment 7 Lennart Poettering 2009-04-26 21:48:26 EDT
Debugging closed source software is always pain. What I saw from the sources of Flash 9 showed me their audio backend was incredibly racey. I doubt that changed with Flash 10. So I am not surprised if it locks up, even though it might be PA that plays a role here. Which version of Flash are you using btw?

PA saves and restores the volume settings for each client. If you mute Flash in pavucontrol and then restart Flash it will be muted again.

Or are you saying you closed an unmuted Flash and when it came back it was muted?

Is it possible to enable a more verbose debug mode in xine some way?

Can you reproduce this with mplayer? It is much more verbose by default.
Comment 8 David Woodhouse 2009-04-27 02:35:57 EDT
It's flash 10. I don't think I've seen the long delay on exit with other software, so perhaps we can ignore that -- although it definitely only happens when it's failed to connect to pulseaudio.

I've certainly never muted flash in pavucontrol, or muted any of the other software that comes up muted. Yes, I closed an unmuted flash (and xine) and they came back muted. Or didn't come back at all, at various times.

I'll try to get more verbose debugging output from xine for each case. The one where it fails to connect is hard, since every time I'm paying attention, it works.
Comment 9 David Woodhouse 2009-04-27 04:35:48 EDT
This is the output from pulseaudio when I start xine and the audio is garbled and skipping...

I: client.c: Created 76 "Native client (UNIX socket client)"
D: protocol-native.c: Protocol version: remote 15, local 15
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
D: protocol-native.c: SHM possible: yes
D: protocol-native.c: Negotiated SHM: yes
D: module-augment-properties.c: Looking for .desktop file for xine
I: client.c: Freed 76 "ALSA plug-in [xine]"
I: protocol-native.c: Connection died.
I: client.c: Created 77 "Native client (UNIX socket client)"
D: protocol-native.c: Protocol version: remote 15, local 15
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
D: protocol-native.c: SHM possible: yes
D: protocol-native.c: Negotiated SHM: yes
D: module-augment-properties.c: Looking for .desktop file for xine
I: client.c: Freed 77 "ALSA plug-in [xine]"
I: protocol-native.c: Connection died.
I: client.c: Created 78 "Native client (UNIX socket client)"
D: protocol-native.c: Protocol version: remote 15, local 15
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
D: protocol-native.c: SHM possible: yes
D: protocol-native.c: Negotiated SHM: yes
D: module-augment-properties.c: Looking for .desktop file for xine
I: client.c: Freed 78 "ALSA plug-in [xine]"
I: protocol-native.c: Connection died.
I: client.c: Created 79 "Native client (UNIX socket client)"
D: protocol-native.c: Protocol version: remote 15, local 15
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
D: protocol-native.c: SHM possible: yes
D: protocol-native.c: Negotiated SHM: yes
D: module-augment-properties.c: Looking for .desktop file for xine
I: client.c: Created 80 "Native client (UNIX socket client)"
D: protocol-native.c: Protocol version: remote 15, local 15
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
D: protocol-native.c: SHM possible: yes
D: protocol-native.c: Negotiated SHM: yes
D: module-augment-properties.c: Looking for .desktop file for xine
I: alsa-sink.c: Trying resume...
D: alsa-util.c: Maximum hw buffer size is 23777 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=84400
I: alsa-sink.c: Resumed successfully...
I: alsa-sink.c: Starting playback.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes busy.
D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: sink-input.c: Created input 201 "ALSA Playback" on alsa_output.pci_8086_284b_sound_card_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: protocol-native.c: Requested tlength=999.91 ms, minreq=124.99 ms
D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: memblockq.c: memblockq requested: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0
I: protocol-native.c: Final latency 1124.90 ms = 749.93 ms + 2*124.99 ms + 124.99 ms
D: alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100%
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Latency set to 124.99ms
D: alsa-sink.c: hwbuf_unused=330724
D: alsa-sink.c: setting avail_min=84401
D: alsa-sink.c: Requesting rewind due to latency change.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 337344 bytes.
D: alsa-sink.c: before: 84336
D: alsa-sink.c: after: 84336
D: alsa-sink.c: Rewound 337344 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 337344 bytes on render memblockq.
D: source.c: Processing rewind...
D: core-subscribe.c: Dropped redundant event due to change event.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 3580 bytes.
D: alsa-sink.c: before: 895
D: alsa-sink.c: after: 895
D: alsa-sink.c: Rewound 3580 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 3580 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle.
D: alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100%
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=84400
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 4028 bytes.
D: alsa-sink.c: before: 1007
D: alsa-sink.c: after: 1007
D: alsa-sink.c: Rewound 4028 bytes.
D: sink.c: Processing rewind...
D: source.c: Processing rewind...
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle.
I: sink-input.c: Freeing input 201 "ALSA Playback"
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes busy.
D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: sink-input.c: Created input 202 "ALSA Playback" on alsa_output.pci_8086_284b_sound_card_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: protocol-native.c: Requested tlength=999.91 ms, minreq=124.99 ms
D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
D: memblockq.c: memblockq requested: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0
I: protocol-native.c: Final latency 1124.90 ms = 749.93 ms + 2*124.99 ms + 124.99 ms
D: alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100%
D: alsa-sink.c: Latency set to 124.99ms
D: alsa-sink.c: hwbuf_unused=330724
D: alsa-sink.c: setting avail_min=84401
D: alsa-sink.c: Requesting rewind due to latency change.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 335232 bytes.
D: alsa-sink.c: before: 83808
D: alsa-sink.c: after: 83808
D: alsa-sink.c: Rewound 335232 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 335232 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle.
D: alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100%
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=84400
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 6460 bytes.
D: alsa-sink.c: before: 1615
D: alsa-sink.c: after: 1615
D: alsa-sink.c: Rewound 6460 bytes.
D: sink.c: Processing rewind...
D: source.c: Processing rewind...
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle.
I: sink-input.c: Freeing input 202 "ALSA Playback"
I: client.c: Freed 80 "ALSA plug-in [xine]"
I: protocol-native.c: Connection died.
I: client.c: Freed 79 "ALSA plug-in [xine]"
I: protocol-native.c: Connection died.
I: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 idle for too long, suspending ...
I: alsa-sink.c: Device suspended...
Comment 10 David Woodhouse 2009-04-27 04:37:08 EDT
xine says...

video_out_xshm: tried to set unsupported property 0
load_plugins: plugin theora will be used for video streamtype 3e.
load_plugins: plugin vorbis will be used for audio streamtype 09.
audio_alsa_out:open pause_resume=0
output sample rate 44100
av_offset=0 pts
spu_offset=0 pts
xine_play
libtheora:Received an bad packet
diff=1 (pts=1, last_pts=0)
video discontinuity #2, type is 2, disc_off 1
waiting for audio discontinuity #2
audio discontinuity #2, type is 2, disc_off 1
waiting for in_discontinuity update #2
libtheora:Received an bad packet
audio jump, diff=0
video jump
play_internal ...done
fixing sound card drift by 3361 pts
fixing sound card drift by 3448 pts
audio_out: inserting 15243 0-frames to fill a gap of 31157 pts
audio_out: inserting 20326 0-frames to fill a gap of 41545 pts
fixing sound card drift by 1936 pts
audio_out: inserting 11773 0-frames to fill a gap of 24064 pts
audio_out: inserting 19813 0-frames to fill a gap of 40498 pts
audio_out: inserting 9655 0-frames to fill a gap of 19735 pts
fixing sound card drift by 1755 pts
audio_out: inserting 8185 0-frames to fill a gap of 16731 pts
audio_out: inserting 13416 0-frames to fill a gap of 27423 pts
fixing sound card drift by -3523 pts
audio_out: inserting 7751 0-frames to fill a gap of 15844 pts
fixing sound card drift by -1687 pts
audio_out: inserting 8270 0-frames to fill a gap of 16905 pts
fixing sound card drift by 2079 pts
fixing sound card drift by 1741 pts
fixing sound card drift by 2824 pts
fixing sound card drift by 3462 pts
ao_flush (loop running: 1)
input_cache: read calls: 626, main input read calls: 606
input_cache: seek_calls: 38, main input seek calls: 5
xine_dispose
shutdown audio
ao_close
Comment 11 David Woodhouse 2009-04-27 04:37:58 EDT
Now the panel applet isn't working, and neither are the volume up/down and mute hotkeys.
Comment 12 David Woodhouse 2009-04-27 04:51:59 EDT
Created attachment 341405 [details]
pulseaudio output with xine native PA driver

This is the output when I switch xine to the native PA audio driver instead of ALSA. The audio is _still_ garbled this way too, and I get messages like this from xine:

audio_out: inserting 8231 0-frames to fill a gap of 16824 pts
audio_out: inserting 23959 0-frames to fill a gap of 48971 pts
audio_out: inserting 18310 0-frames to fill a gap of 37425 pts
audio_out: inserting 12765 0-frames to fill a gap of 26091 pts
audio_out: inserting 12401 0-frames to fill a gap of 25348 pts
audio_out: inserting 8284 0-frames to fill a gap of 16932 pts
audio_out: inserting 8601 0-frames to fill a gap of 17581 pts
audio_out: inserting 8084 0-frames to fill a gap of 16525 pts
audio_out: inserting 7341 0-frames to fill a gap of 15005 pts

This time it didn't come up muted; it's just that the volume was set to zero.

I increased the volume with the gnome-volume-control, but although it worked xine didn't notice and change its own volume slider. So I turned it up in xine's volume control too. I'm not sure how the two are related.

On quitting xine and restarting it again, it was silent again.
Comment 13 Lennart Poettering 2009-05-17 19:32:42 EDT
*** Bug 497698 has been marked as a duplicate of this bug. ***
Comment 14 Lennart Poettering 2009-05-17 19:32:49 EDT
*** Bug 501154 has been marked as a duplicate of this bug. ***
Comment 15 Lennart Poettering 2009-05-17 19:36:05 EDT
All three of David's bugs seem to expose issues of the PA backend of Xine.

I wrote that backend years ago, so I'll reassign this to xine but keep me as assignee.

Even if the three issues David points out might be unrelated I'd rather keep track of this in a single bug.
Comment 16 David Woodhouse 2009-05-18 05:14:07 EDT
Er, don't most of these bugs use the ALSA back end? I only tried switching to the PA back end to see if that made the skipping, and the complete failures to play audio, go away. It didn't.

And I just chose xine as an example -- this kind of thing is happening with all applications. Do you have an application with which you'd _prefer_ me to reproduce such bugs?
Comment 17 Bug Zapper 2009-06-09 10:00:41 EDT
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 18 Christopher Beland 2010-01-28 12:27:31 EST
With Fedora 12, I haven't seen garbled audio from xine, but I have seen the problem with volume coming up at zero.  I didn't find this bug report with I reported that as Bug 555912, but I did manage to find a way to reproduce it reliably.  It's also been sent upstream at: http://bugs.xine-project.org/show_bug.cgi?id=301
Comment 19 Kevin Kofler 2010-01-28 17:35:40 EST
*** Bug 555912 has been marked as a duplicate of this bug. ***
Comment 20 Bug Zapper 2010-04-27 09:44:07 EDT
This message is a reminder that Fedora 11 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 11.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '11'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 11's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 11 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 21 Bug Zapper 2010-06-28 07:52:53 EDT
Fedora 11 changed to end-of-life (EOL) status on 2010-06-25. Fedora 11 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.

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