pulseaudio: a52 sink doesn't stream audio from bluez source

[quequotion]

Sorry to beat a dead horse, and double if this is in fact a pulseaudio issue.

I recently configured bluez and pulseaudio to receive streams from devices over bluetooth (eg, to play audio from a phone over the PC's speaker system).

This works when the PC's sound card is set to profiles other than the A52 plugin (ie, pulseaudio's provided digital stereo output and also the DTS alsa plugin).

Only when set to use the AC3 output profile, audio from the bluez source is not produced.

pavucontrol shows the bluez source is producing sound (the level bounces appropriately), but no audio comes out of the sink (no level bounce in pavucontrol either).

Any ideas?

[quequotion]

I wonder if it is not because of using the plugin through a slave{} node.

[quequotion]

uh.. my comment self destructed?

As I was saying, I tried a manual configuration (the provided, autoconfiguration doesn't create a "card", ie that can be listed by aplay -L). At first this had no effect, but then I raised the bitrate (from 448 to 640).

This appeared to have done the trick once, but cut out after a few seconds.

Subsequently, audio from any bluetooth source streams just for an instant and is then cut off.

Manual configuration:

pcm.!a52 {
  @args [CARD]
  @args.CARD {
    type string
  }
  type rate
  slave {
    pcm {
      type a52
      bitrate 640
      channels 6
      card $CARD
    }
  rate 48000
  }
}

[quequotion]

This has evolved:

The above configuration allows for the bluetooth stream to succeed once, per boot. If for some reason the stream is disconnected, fails, or I am not entirely sure what, subsequent attempts to stream music might make a blip before getting cut off.

Take a look at pulse's output when it works (sample; basically this repeats over and over every so many seconds):

D: [pulseaudio] bluez5-util.c: Properties changed in transport /org/bluez/hci0/dev_84_C7_EA_AC_3E_95/fd0
D: [pulseaudio] bluez5-util.c: Transport property State changed
I: [alsa-sink-] module-loopback.c: Dropping 118526 usec of audio from queue
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163240409.98 ms + 82.11 ms + 74.79 ms = -1528163240253.19 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163240253.19 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [alsa-sink-] ratelimit.c: 1304 events suppressed
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163230402.48 ms + 175.52 ms + 75.66 ms = -1528163230151.41 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163230153.17 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163220390.62 ms + 263.77 ms + 85.02 ms = -1528163220041.94 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163220044.57 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163210378.98 ms + 366.87 ms + 84.62 ms = -1528163209927.56 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163209931.23 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163200374.96 ms + 462.95 ms + 81.18 ms = -1528163199830.88 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163199835.51 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163190370.48 ms + 573.22 ms + 79.17 ms = -1528163189718.17 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163189723.91 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1528163180372.31 ms + 660.48 ms + 84.77 ms = -1528163179627.17 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1528163179633.78 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 43659 Hz.
D: [alsa-sink-] ratelimit.c: 9 events suppressed

That latency seems crazy to me.

Then later, when it connects but won't play any sound at all (sometimes there's a blip, often nothing):

I: [alsa-sink-] module-loopback.c: Adding 13333 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 2494 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 498 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 181 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 158 usec of silence to queue
I: [alsa-sink-] module-loopback.c: Adding 373086903752879 usec of silence to queue
D: [pulseaudio] module-loopback.c: Loopback overall latency is -1627967452745.36 ms + 373086903657.55 ms + 64.44 ms = -1254880549023.48 ms
D: [pulseaudio] module-loopback.c: Loopback latency at base rate is -1254880549023.48 ms
D: [pulseaudio] module-loopback.c: [ALC892out] Updated sampling rate to 44540 Hz.
D: [alsa-sink-] ratelimit.c: 5253 events suppressed
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)
D: [alsa-sink-] flist.c: ../pulseaudio/src/pulsecore/memblock.c: unused_memblocks flist is full (don't worry)

373086903752879 usec is just shy of 12 years, btw.

Maybe this is a pulseaudio problem, but why only AC3 and why does it sometimes work?

[quequotion]

The code comments in pulseaudio's src/modules/module-loopback.c do not inspire confidence:

241 /* rate controller, called from main context
242  * - maximum deviation from base rate is less than 1%
243  * - can create audible artifacts by changing the rate too quickly
244  * - exhibits hunting with USB or Bluetooth sources
245  */
246 static uint32_t rate_controller(
247                 uint32_t base_rate,
248                 pa_usec_t adjust_time,
249                 int32_t latency_difference_usec) {
250 
251     uint32_t new_rate;
252     double min_cycles;
253 
254     /* Calculate best rate to correct the current latency offset, limit at
255      * slightly below 1% difference from base_rate */
256     min_cycles = (double)abs(latency_difference_usec) / adjust_time / 0.01 + 1;
257     new_rate = base_rate * (1.0 + (double)latency_difference_usec / min_cycles / adjust_time);
258 
259     return new_rate;
260 }
261 
262 /* Called from main thread.
263  * It has been a matter of discussion how to correctly calculate the minimum
264  * latency that module-loopback can deliver with a given source and sink.
265  * The calculation has been placed in a separate function so that the definition
266  * can easily be changed. The resulting estimate is not very exact because it
267  * depends on the reported latency ranges. In cases were the lower bounds of
268  * source and sink latency are not reported correctly (USB) the result will
269  * be wrong. */
270 static void update_minimum_latency(struct userdata *u, pa_sink *sink, bool print_msg) {
271 
272     if (u->underrun_latency_limit)
273         /* If we already detected a real latency limit because of underruns, use it */
274         u->minimum_latency = u->underrun_latency_limit;
275 
276     else {
277         /* Calculate latency limit from latency ranges */
278 
279         u->minimum_latency = u->min_sink_latency;
280         if (u->fixed_alsa_source)
281             /* If we are using an alsa source with fixed latency, we will get a wakeup when
282              * one fragment is filled, and then we empty the source buffer, so the source
283              * latency never grows much beyond one fragment (assuming that the CPU doesn't
284              * cause a bottleneck). */
285             u->minimum_latency += u->core->default_fragment_size_msec * PA_USEC_PER_MSEC;
286 
287         else
288             /* In all other cases the source will deliver new data at latest after one source latency.
289              * Make sure there is enough data available that the sink can keep on playing until new
290              * data is pushed. */
291             u->minimum_latency += u->min_source_latency;
292 
293         /* Multiply by 1.1 as a safety margin for delays that are proportional to the buffer sizes */
294         u->minimum_latency *= 1.1;
295 
296         /* Add 1.5 ms as a safety margin for delays not related to the buffer sizes */
297         u->minimum_latency += 1.5 * PA_USEC_PER_MSEC;
298     }
299 
300     /* Add the latency offsets */
301     if (-(u->sink_latency_offset + u->source_latency_offset) <= (int64_t)u->minimum_latency)
302         u->minimum_latency += u->sink_latency_offset + u->source_latency_offset;
303     else
304         u->minimum_latency = 0;
305 
306     /* If the sink is valid, send a message to update the minimum latency to
307      * the output thread, else set the variable directly */
308     if (sink)
309         pa_asyncmsgq_send(sink->asyncmsgq, PA_MSGOBJECT(u->sink_input), SINK_INPUT_MESSAGE_UPDATE_MIN_LATENCY, NULL, u->minimum_latency, NULL);
310     else
311         u->output_thread_info.minimum_latency = u->minimum_latency;
312 
313     if (print_msg) {
314         pa_log_info("Minimum possible end to end latency: %0.2f ms", (double)u->minimum_latency / PA_USEC_PER_MSEC);
315         if (u->latency < u->minimum_latency)
316             pa_log_warn("Configured latency of %0.2f ms is smaller than minimum latency, using minimum instead", (double)u->latency / PA_USEC_PER_MSEC);
317     }
318 }

[quequotion]

I have filed another issue report with pulseaudio as I am not sure on which end this should be fixed.

[patrakov]

This issue suggests that the "extplug" approach taken by the DTS encoder is more compatible than the "ioplug" approach used by the AC3 plugin.

[quequotion]

Highly anecdotal, "I worked around this once" story.

I worked around this once, sort of. The stream has occasional gaps.

It still does not work out of the box: repeat, no.

Edit: speaking of the box, that has changed: alsa-plugins 1:1.2.6-2 has been released in the Archlinux [extra] repository. Up until this I had been using the development tip.

Tried to connect a bluetooth device while the output was in surround mode, POP... then silence.

So I got creative.

First I configured pulse for digital stereo mode (pavucontrol), and connected a bluetooth source (cellphone, bluetoothctl).

That works as expected, except that bluetooth source:

Source #12
    State: RUNNING
    Name: bluez_source.38_78_62_CD_D9_A9.a2dp_source
    Description: Xperia XZ3
    Driver: module-bluez5-device.c
    Sample Specification: s16le 2ch 44100Hz
    Channel Map: front-left,front-right
    Owner Module: 28
    Mute: no
    Volume: front-left: 50055 /  76% / -7.02 dB,   front-right: 50055 /  76% / -7.02 dB
            balance 0.00
    Base Volume: 65536 / 100% / 0.00 dB
    Monitor of Sink: n/a
    Latency: 81388 usec, configured 68537 usec
    Flags: HARDWARE DECIBEL_VOLUME LATENCY 
    Properties:
        bluetooth.protocol = "a2dp_source"
        bluetooth.codec = "sbc"
        device.description = "Xperia XZ3"
        device.string = "38:78:62:CD:D9:A9"
        device.api = "bluez"
        device.class = "sound"
        device.bus = "bluetooth"
        device.form_factor = "phone"
        bluez.path = "/org/bluez/hci0/dev_38_78_62_CD_D9_A9"
        bluez.class = "0x5a020c"
        bluez.alias = "Xperia XZ3"
        device.icon_name = "audio-card-bluetooth"
    Ports:
        phone-input: Phone (type: Phone, priority: 0, available)
    Active Port: phone-input
    Formats:
        pcm

has latched on to a certain abstraction device, which I call "Square Stereo", via loopback:

Source Output #27
    Driver: module-loopback.c
    Owner Module: 31
    Client: n/a
    Source: 12
    Sample Specification: s16le 2ch 44100Hz
    Channel Map: front-left,front-right
    Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
    Corked: no
    Mute: no
    Volume: front-left: 65536 / 100% / 0.00 dB,   front-right: 65536 / 100% / 0.00 dB
            balance 0.00
    Buffer Latency: 0 usec
    Source Latency: 71707 usec
    Resample method: n/a
    Properties:
        media.role = "abstract"
        module-stream-restore.id = "source-output-by-media-role:abstract"
        media.name = "Loopback to Square Stereo (L->L,rL;R->R,rR;+lfe)"
        media.icon_name = "audio-card"

It attaches to the remapped stream like this even while the output is in "Digital Stereo" mode; not sure why.

But that is what I wanted, anyway; thank you pulseaudio...

Here's that abstraction's config from /etc/pulse/default.pa:

#Square Stereo (downmix to four speakers; mix lfe)
load-module module-remap-sink sink_name=Square-Stereo sink_properties="device.description='Square Stereo (L->L,rL;R->R,rR;+lfe)'" master=ALC892out channels=5 master_channel_map=left,rear-left,right,rear-right,lfe channel_map=left,left,right,right,lfe remix=yes

Next, I switched the card back to surrond mode, and to my surprise the stream continues playing!

And here's some information about pulse running with this "working":

pactl info
Server String: /run/user/1000/pulse/native
Library Protocol Version: 35
Server Protocol Version: 35
Is Local: yes
Client Index: 3
Tile Size: 65472
User Name: zombie
Host Name: Shiroko
Server Name: pulseaudio
Server Version: 15.0
Default Sample Specification: s16le 6ch 48000Hz
Default Channel Map: front-left,front-left-of-center,front-center,front-right,front-right-of-center,rear-center
Default Sink: ALC892out
Default Source: bluez_source.38_78_62_CD_D9_A9.a2dp_source
Cookie: eb45:2e51

My bluetooth source is playing over my 5.1 output--particularly it is being played out of a 2x2.1 output I configured for this but I don't know how pulseaudio knows that.

I'm afraid to reboot, but I worked around it once.

Edit: Got this to work again with a different device. There are gaps in the audio stream. It gets annoying after a while.