foo_out_pulse icon indicating copy to clipboard operation
foo_out_pulse copied to clipboard

foobar2000 stops the playback randomly

Open perHub opened this issue 3 years ago • 11 comments

Hello, I would like to report a bug I am experiencing since a recent PulseAudio update. As the title says, foobar2000 stops the playback randomly (it doesn't matter what the song file type is or what time it is currently playing at) I've checked the foobar console and found:

Foobar console: Error: Pulseaudio: connection failed: Connection terminated

Since that message doens't provide enough information (except for the fact pulseaudio is involved) I decided to check the PA console log when the bug occurs:

W: [pulseaudio] pstream.c: Received memblock frame with invalid seek mode.

Of course I'm not sure if it is right to report this as a foo_out_pulse bug since it started happening after a PA update (I'm at 14.2 at this moment) but I want to at least know if someone else is experiencing this issue.

Thanks for this awesome plugin!

perHub avatar Jun 11 '21 23:06 perHub

Just started noticing this recently myself.

System config:

  • Arch Linux
  • Zen kernel v5.12.10
  • FB2k v1.6.6 via AUR
  • Wine v6.10
  • Pulseaudio v14.2

tullo-x86 avatar Jun 16 '21 00:06 tullo-x86

Update: I noticed this happening FAR more often when playing 96KHz/24bit 6-channel audio, which leads me to suspect that a TCP throughput limitation could be causing the issue. After adding the SSRC resampler set to 48kHz (the sample rate used by my USB DAC, and the default sample rate for my PA configuration), I was able to play 280 seconds of audio (up from 14 seconds) before playback stopped.

Curiously, my pulseaudio log shows the following:

WITHOUT resampler

Jun 23 08:58:30 pulseaudio[29830]: Created 8 "Native client (TCP/IP client from 127.0.0.1:57350)"
Jun 23 08:58:30 pulseaudio[29830]: Client authenticated by IP ACL.
Jun 23 08:58:30 pulseaudio[29830]: Trying to change sample spec
Jun 23 08:58:30 pulseaudio[29830]: Restoring volume for sink input sink-input-by-application-id:foobar2000.
Jun 23 08:58:30 pulseaudio[29830]: Restoring mute state for sink input sink-input-by-application-id:foobar2000.
Jun 23 08:58:30 pulseaudio[29830]: Trying resume...
Jun 23 08:58:30 pulseaudio[29830]: Cannot disable ALSA period wakeups
Jun 23 08:58:30 pulseaudio[29830]: ALSA period wakeups were not disabled
Jun 23 08:58:30 pulseaudio[29830]: Time scheduling watermark is 5.00ms
Jun 23 08:58:30 pulseaudio[29830]: Resumed successfully...
Jun 23 08:58:30 pulseaudio[29830]: Starting playback.
Jun 23 08:58:30 pulseaudio[29830]: Using generic matrix remapping
Jun 23 08:58:30 pulseaudio[29830]: Choosing speex quality setting 9.
Jun 23 08:58:30 pulseaudio[29830]: Created input 3 "Audio" on alsa_output.usb-Sennheiser_GSX_1000_Main_Audio_5698800279039916-00.analog-output-surround71 with sample spec float32le 6ch 96000Hz and channel map front-left,front-right,front-center,lfe,rear-left,rear-right
Jun 23 08:58:30 pulseaudio[29830]:     media.name = "Audio"
Jun 23 08:58:30 pulseaudio[29830]:     application.name = "foobar2000"
Jun 23 08:58:30 pulseaudio[29830]:     native-protocol.peer = "TCP/IP client from 127.0.0.1:57350"
Jun 23 08:58:30 pulseaudio[29830]:     native-protocol.version = "33"
Jun 23 08:58:30 pulseaudio[29830]:     application.id = "foobar2000"
Jun 23 08:58:30 pulseaudio[29830]:     application.icon_name = "foobar2000"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.id = "1340"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.user = "tully"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.host = "REDACTED"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.binary = "foobar2000.exe"
Jun 23 08:58:30 pulseaudio[29830]:     application.language = "C"
Jun 23 08:58:30 pulseaudio[29830]:     window.x11.display = ":0"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.machine_id = "REDACTED"
Jun 23 08:58:30 pulseaudio[29830]:     application.process.session_id = "2"
Jun 23 08:58:30 pulseaudio[29830]:     module-stream-restore.id = "sink-input-by-application-id:foobar2000"
Jun 23 08:58:30 pulseaudio[29830]: Requested tlength=1550.00 ms, minreq=775.00 ms
Jun 23 08:58:30 pulseaudio[29830]: Final latency 1550.50 ms = 0.00 ms + 2*775.00 ms + 0.50 ms
Jun 23 08:58:30 pulseaudio[29830]: Underrun!
Jun 23 08:58:30 pulseaudio[29830]: Increasing minimal latency to 1.00 ms
Jun 23 08:58:30 pulseaudio[29830]: Underrun!
Jun 23 08:58:30 pulseaudio[29830]: Increasing minimal latency to 2.00 ms
Jun 23 08:58:30 pulseaudio[29830]: Underrun!
Jun 23 08:58:30 pulseaudio[29830]: Increasing minimal latency to 4.00 ms
Jun 23 08:58:30 pulseaudio[29830]: Underrun!
Jun 23 08:58:30 pulseaudio[29830]: Increasing minimal latency to 8.00 ms
Jun 23 08:58:48 pulseaudio[29830]: Received invalid frame size: 3380824636
*** NOTE: AUDIO HALTED HERE ***
Jun 23 08:58:48 pulseaudio[29830]: Freeing input 3 "Audio"
Jun 23 08:58:48 pulseaudio[29830]: Freed 8 "foobar2000"
Jun 23 08:58:48 pulseaudio[29830]: Connection died.
Jun 23 08:58:53 pulseaudio[29830]: Sink alsa_output.usb-Sennheiser_GSX_1000_Main_Audio_5698800279039916-00.analog-output-surround71 idle for too long, suspending ...
Jun 23 08:58:53 pulseaudio[29830]: Device suspended...

WITH SSRC resampler in FB2k set to 48kHz

Jun 23 09:00:01 pulseaudio[29830]: Created 9 "Native client (TCP/IP client from 127.0.0.1:57354)"
Jun 23 09:00:01 pulseaudio[29830]: Client authenticated by IP ACL.
Jun 23 09:00:01 pulseaudio[29830]: Trying to change sample spec
Jun 23 09:00:01 pulseaudio[29830]: Restoring volume for sink input sink-input-by-application-id:foobar2000.
Jun 23 09:00:01 pulseaudio[29830]: Restoring mute state for sink input sink-input-by-application-id:foobar2000.
Jun 23 09:00:01 pulseaudio[29830]: Trying resume...
Jun 23 09:00:01 pulseaudio[29830]: Cannot disable ALSA period wakeups
Jun 23 09:00:01 pulseaudio[29830]: ALSA period wakeups were not disabled
Jun 23 09:00:01 pulseaudio[29830]: Time scheduling watermark is 5.00ms
Jun 23 09:00:01 pulseaudio[29830]: Resumed successfully...
Jun 23 09:00:01 pulseaudio[29830]: Starting playback.
Jun 23 09:00:01 pulseaudio[29830]: Forcing resampler 'copy', because of fixed, identical sample rates.
Jun 23 09:00:01 pulseaudio[29830]: Using generic matrix remapping
Jun 23 09:00:01 pulseaudio[29830]: Created input 4 "Audio" on alsa_output.usb-Sennheiser_GSX_1000_Main_Audio_5698800279039916-00.analog-output-surround71 with sample spec float32le 6ch 48000Hz and channel map front-left,front-right,front-center,lfe,rear-left,rear-right
Jun 23 09:00:01 pulseaudio[29830]:     media.name = "Audio"
Jun 23 09:00:01 pulseaudio[29830]:     application.name = "foobar2000"
Jun 23 09:00:01 pulseaudio[29830]:     native-protocol.peer = "TCP/IP client from 127.0.0.1:57354"
Jun 23 09:00:01 pulseaudio[29830]:     native-protocol.version = "33"
Jun 23 09:00:01 pulseaudio[29830]:     application.id = "foobar2000"
Jun 23 09:00:01 pulseaudio[29830]:     application.icon_name = "foobar2000"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.id = "1340"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.user = "tully"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.host = "REDACTED"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.binary = "foobar2000.exe"
Jun 23 09:00:01 pulseaudio[29830]:     application.language = "C"
Jun 23 09:00:01 pulseaudio[29830]:     window.x11.display = ":0"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.machine_id = "REDACTED"
Jun 23 09:00:01 pulseaudio[29830]:     application.process.session_id = "2"
Jun 23 09:00:01 pulseaudio[29830]:     module-stream-restore.id = "sink-input-by-application-id:foobar2000"
Jun 23 09:00:01 pulseaudio[29830]: Requested tlength=1550.00 ms, minreq=775.00 ms
Jun 23 09:00:01 pulseaudio[29830]: Final latency 1550.50 ms = 0.00 ms + 2*775.00 ms + 0.50 ms
Jun 23 09:00:01 pulseaudio[29830]: Underrun!
Jun 23 09:00:01 pulseaudio[29830]: Increasing minimal latency to 1.00 ms
Jun 23 09:00:01 pulseaudio[29830]: Underrun!
Jun 23 09:00:01 pulseaudio[29830]: Increasing minimal latency to 2.00 ms
Jun 23 09:00:01 pulseaudio[29830]: Underrun!
Jun 23 09:00:01 pulseaudio[29830]: Increasing minimal latency to 4.00 ms
Jun 23 09:00:01 pulseaudio[29830]: Underrun!
Jun 23 09:00:01 pulseaudio[29830]: Increasing minimal latency to 8.00 ms
Jun 23 09:04:23 pulseaudio[29830]: Underrun!
Jun 23 09:04:23 pulseaudio[29830]: Increasing minimal latency to 16.00 ms
Jun 23 09:04:26 pulseaudio[29830]: Underrun!
Jun 23 09:04:26 pulseaudio[29830]: Increasing wakeup watermark to 8.00 ms
Jun 23 09:04:41 pulseaudio[29830]: Received SHM frame on a socket where SHM is disabled.
*** NOTE: AUDIO HALTED HERE ***
Jun 23 09:04:41 pulseaudio[29830]: Freeing input 4 "Audio"
Jun 23 09:04:41 pulseaudio[29830]: Freed 9 "foobar2000"
Jun 23 09:04:41 pulseaudio[29830]: Connection died.
Jun 23 09:04:46 pulseaudio[29830]: Sink alsa_output.usb-Sennheiser_GSX_1000_Main_Audio_5698800279039916-00.analog-output-surround71 idle for too long, suspending ...
Jun 23 09:04:46 pulseaudio[29830]: Device suspended...

tullo-x86 avatar Jun 23 '21 14:06 tullo-x86

This is probably not the best workaround but when I reduced the buffer length to 50 ms this issue disappeared completely.

perHub avatar Jun 23 '21 14:06 perHub

when I reduced the buffer length to 50 ms this issue disappeared completely.

FB2k's buffer or PA's?

tullo-x86 avatar Jun 23 '21 22:06 tullo-x86

foobar's.

perHub avatar Jun 23 '21 22:06 perHub

Not sure how that fixed it, but I just listened to over an hour of audio (some multichannel, some stereo) and it hasn't stopped once. Thanks for the tip!

tullo-x86 avatar Jun 24 '21 04:06 tullo-x86

A little follow-up about the issue: I just migrated completely to pipewire and I'm using this plugin thanks to pipewire-pulse and by configuring the tcp port in /etc/pipewire/pipewire-pulse.conf. The good news is that this issue doesn't happen with this configuration, it's not even necessary to use the previous workaround, it works as before the PA update.

perHub avatar Jul 06 '21 07:07 perHub

I'm hesitant to switch to Pipewire since my DAC required a really specific PA configuration to work right, and I really don't feel like repeating that process in an unfamiliar framework. I'll definitely be snapshotting my drive before attempting anything.

tullo-x86 avatar Jul 08 '21 15:07 tullo-x86

yeah, while pipewire-pulse tries to be compatible with pulseaudio I'd guess not all features are available so it's understandable to be way of it but I mentioned it because it's a nice alternative that works with this plugin, which honestly I find it really awesome :P

perHub avatar Jul 09 '21 01:07 perHub

I've also switched to PipeWire and created ~/.config/pipewire/pipewire-pulse.conf.d/foobar2000.conf containing:

pulse.properties = {
    server.address = [
        "unix:native"                      # needed for normal operation
        "tcp:127.0.0.1:4713"               # for foo_out_pulse
    ]
}

pLuster avatar Nov 01 '22 13:11 pLuster

By a twist of fate, my SSD died recently so I'll be rebuilding my system "from scratch", so I've been handed the perfect opportunity to see how much of a bother it is to get my DAC working under Pipewire.

tullo-x86 avatar Dec 01 '22 16:12 tullo-x86