Bug 1279139 - Unreliable Bluetooth headset audio channeling.
Summary: Unreliable Bluetooth headset audio channeling.
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: pulseaudio
Version: 23
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Lennart Poettering
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-11-08 04:10 UTC by Edward O'Callaghan
Modified: 2016-12-20 15:30 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-12-20 15:30:47 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Edward O'Callaghan 2015-11-08 04:10:30 UTC
Description of problem:

OK, this bug report is unfortunately going to have to start off very descriptive in nature until I am able to determine where the actual problem lies.

Essentially the issue is that I have a Bluetooth speaker that will pair and connect fine'ish (sometimes disconnects or takes ages) but no audio is emitted from it, I tried this multiple times.

I figured perhaps the audio stack was at fault somehow so I ran:

$ pulseaudio -k

and then reconnected the device, then <magic> it randomly started working?

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

$ uname -a
Linux localhost.localdomain 4.2.5-300.fc23.x86_64 #1 SMP Tue Oct 27 04:29:56 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

$ rpm -q pulseaudio bluez
pulseaudio-7.0-1.fc23.x86_64
bluez-5.35-1.fc23.x86_64

How reproducible:

Steps to Reproduce:
1. Fresh install of Fedora 23/KDE + apply all patches + reboot.
2. Try to connect Bluetooth speaker


Additional info:

$ bluetoothctl 
[NEW] Controller 28:E3:47:27:16:41 localhost.localdomain [default]
[NEW] Device 58:51:00:54:B9:9B MD315
[bluetooth]# info 58:51:00:54:B9:9B
Device 58:51:00:54:B9:9B
        Name: MD315
        Alias: MD315
        Class: 0x242404
        Icon: audio-card
        Paired: yes
        Trusted: yes
        Blocked: no
        Connected: yes
        LegacyPairing: no
        UUID: Headset                   (00001108-0000-1000-8000-00805f9b34fb)
        UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
        UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
        UUID: Handsfree                 (0000111e-0000-1000-8000-00805f9b34fb)

$ lsusb | grep Blue
Bus 004 Device 003: ID 0cf3:3004 Atheros Communications, Inc. AR3012 Bluetooth 4.0

Some random messages in dmesg:

[55554.991899] Bluetooth: hci0 SCO packet for unknown connection handle 31
[55768.741159] Bluetooth: hci0 SCO packet for unknown connection handle 31
[55798.714117] Bluetooth: hci0 SCO packet for unknown connection handle 31


Please let me know how I can find more details on tracing this down?
Kind Regards,
Edward.

Comment 1 Edward O'Callaghan 2015-11-08 04:29:41 UTC
Hi Lennart,

Something interesting is that if I try to play audio and choice the Bluetooth device as the preferred sink, upon connection it sometimes works fine. Thus this could be a firmware bug in the device, it feels a little wonky though so without more concrete information it's hard to say at the moment.

Look forward to hear from you,
Edward.

Comment 2 Edward O'Callaghan 2015-11-08 05:41:57 UTC
Here is some random/interesting things I found in journalctl while trying to connect without audio playing and with audio play.

<-- snip -->

Nov 08 16:15:24 localhost.localdomain bluetoothd[1396]: Failed to disconnect device: Not Powered (0x0f)
Nov 08 16:15:41 localhost.localdomain rtkit-daemon[860]: Supervising 4 threads of 1 processes of 1 users.
Nov 08 16:15:41 localhost.localdomain rtkit-daemon[860]: Successfully made thread 2317 of process 1660 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Nov 08 16:15:41 localhost.localdomain rtkit-daemon[860]: Supervising 5 threads of 1 processes of 1 users.
Nov 08 16:16:11 localhost.localdomain bluetoothd[1396]: connect error: Connection timed out (110)
Nov 08 16:16:11 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 31
Nov 08 16:16:11 localhost.localdomain bluetoothd[1396]: Unable to get io data for Headset Voice gateway: getpeername: Transport endpoint is not connected (107)
Nov 08 16:16:11 localhost.localdomain bluetoothd[1396]: (bluetoothd:1396): GLib-CRITICAL **: Source ID 158 was not found when attempting to remove it
Nov 08 16:16:13 localhost.localdomain bluetoothd[1396]: (bluetoothd:1396): GLib-CRITICAL **: Source ID 209 was not found when attempting to remove it
Nov 08 16:16:14 localhost.localdomain bluetoothd[1396]: /org/bluez/hci0/dev_58_51_00_54_B9_9B/fd0: fd(34) ready
Nov 08 16:16:14 localhost.localdomain rtkit-daemon[860]: Supervising 4 threads of 1 processes of 1 users.
Nov 08 16:16:14 localhost.localdomain rtkit-daemon[860]: Successfully made thread 2323 of process 1660 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Nov 08 16:16:14 localhost.localdomain rtkit-daemon[860]: Supervising 5 threads of 1 processes of 1 users.
Nov 08 16:16:14 localhost.localdomain kernel: input: 58:51:00:54:B9:9B as /devices/virtual/input/input13
Nov 08 16:16:19 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:16:27 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:16:30 localhost.localdomain cupsd[1902]: PID 1903 (/usr/lib/cups/notifier/dbus) exited with no errors.
Nov 08 16:16:35 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:17:27 localhost.localdomain dbus[843]: [system] Rejected send message, 10 matched rules; type="method_return", sender=":1.36" (uid=1000 pid=1660 comm="/usr/bin/pulseaudio --start --log-target=syslog ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=0 pid=1396 comm="/usr/libexec/bluetooth/bluetoothd ")

...

Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 31
Nov 08 16:21:35 localhost.localdomain rtkit-daemon[860]: Supervising 4 threads of 1 processes of 1 users.
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 7936
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 48
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:21:35 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0

....

Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain kernel: Bluetooth: hci0 SCO packet for unknown connection handle 0
Nov 08 16:22:05 localhost.localdomain bluetoothd[1396]: connect error: Connection timed out (110)
Nov 08 16:22:05 localhost.localdomain bluetoothd[1396]: Unable to get io data for Headset Voice gateway: getpeername: Transport endpoint is not connected (107)
Nov 08 16:22:08 localhost.localdomain bluetoothd[1396]: (bluetoothd:1396): GLib-CRITICAL **: Source ID 346 was not found when attempting to remove it
Nov 08 16:22:08 localhost.localdomain bluetoothd[1396]: /org/bluez/hci0/dev_58_51_00_54_B9_9B/fd1: fd(34) ready
Nov 08 16:22:08 localhost.localdomain rtkit-daemon[860]: Supervising 4 threads of 1 processes of 1 users.
Nov 08 16:22:08 localhost.localdomain rtkit-daemon[860]: Successfully made thread 2553 of process 1660 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Nov 08 16:22:08 localhost.localdomain rtkit-daemon[860]: Supervising 5 threads of 1 processes of 1 users.
Nov 08 16:22:08 localhost.localdomain kernel: input: 58:51:00:54:B9:9B as /devices/virtual/input/input14
Nov 08 16:22:14 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:22:22 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:22:30 localhost.localdomain bluetoothd[1396]: Unknown seq type
Nov 08 16:22:38 localhost.localdomain bluetoothd[1396]: Unknown seq type

<-- snip -->

My conjecture is that the device is going into some kind of power saving mode while a audio bitstream isn't being shoved into it possibly because we are missing a packet or something upon initial connection? I have no read the Bluetooth spec so this could be just rubbish? It certainly looks like some resource vanishes somewhere below the getpeername() syscall and perhaps Pulse continues on assuming its still there hence no audio?

But the the problem is definitely trigger if you don't play audio at the same time as trying to connect to the device. For example,

1.) connect to the device without playing audio
2.) then play audio after it says it is connected
3.) then run: $ pactl list sinks

you get a indication that everything 'seems' to be working fine yet no audio:

Sink #2
        State: RUNNING
        Name: bluez_sink.58_51_00_54_B9_9B
        Description: MD315
        Driver: module-bluez5-device.c
        Sample Specification: s16le 1ch 8000Hz
        Channel Map: mono
        Owner Module: 27
        Mute: no
        Volume: mono: 43691 /  67%
                balance 0.00
        Base Volume: 65536 / 100%
        Monitor Source: bluez_sink.58_51_00_54_B9_9B.monitor
        Latency: 0 usec, configured 128000 usec
        Flags: HARDWARE HW_VOLUME_CTRL LATENCY 
        Properties:
                bluetooth.protocol = "headset_head_unit"
                device.intended_roles = "phone"
                device.description = "MD315"
                device.string = "58:51:00:54:B9:9B"
                device.api = "bluez"
                device.class = "sound"
                device.bus = "bluetooth"
                device.form_factor = "headset"
                bluez.path = "/org/bluez/hci0/dev_58_51_00_54_B9_9B"
                bluez.class = "0x242404"
                bluez.alias = "MD315"
                device.icon_name = "audio-headset-bluetooth"
        Ports:
                headset-output: Headset (priority: 0)
        Active Port: headset-output
        Formats:
                pcm

Really weird eh..

Comment 3 Fedora End Of Life 2016-11-24 13:11:23 UTC
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. 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 EOL if it remains open with a Fedora  'version'
of '23'.

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.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 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, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

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.

Comment 4 Fedora End Of Life 2016-12-20 15:30:47 UTC
Fedora 23 changed to end-of-life (EOL) status on 2016-12-20. Fedora 23 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. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

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.