Hello Luiz and Tanuk,
I have been trying to understand a problem when trying to establish a
connection between my Sony MW-600 headset and my laptop (PulseAudio
11.1 + a backport that gives higher priority to A2DP, BlueZ 5.47,
Linux 4.16.9). When the connection is initiated by the peripheral,
after it has already been paired on a previous connection, the
peripheral does not remain connected. When the computer initiates the
connection everything works fine. The problem seems to be that when we
create the card in PulseAudio is created before the AVDTP connection
reaches the OPEN state, the headset decides to abort the AVDTP
connection. In this case the card was created before the transport for
the card profile a2dp_sink is available and headset_head_unit was the
active profile, because WAIT_FOR_PROFILES_TIMEOUT_USEC was reached.
Increasing the timeout to 60s makes the problem go away. The AVDTP
channel becomes connected about 50s after the HSP connection has
started and the card is created with a2dp_sink as the active profile.
I also had to disable module-card-restore, otherwise it tries to
switch to the saved a2dp_sink profile right when the card is created,
which also makes the device abort the AVDTP connection for some
reason.
I have collected btmon dumps with a slightly modified version of btmon
to avoid flooding the logs with SCO data and uploaded to
https://gist.github.com/jprvita/a7482db4601d099788c4f820ea984ba9.
Similar symptoms have been reported by our QA team with another Sony
model (MDR-XB950N1) and with a few Chinese headsets, but the MW-600 is
the only one I have access to where I can reproduce the problem
consistently (works fine on a Sennheiser MM-450 and a JBL Flip 2).
Also, the involvement of module-card-restore in this problem made me
think whether it actually makes sense to restore the active profile
from the previous connection on bluetooth cards, since we already have
module-bluetooth-policy to automatically select the right profile
depending on the stream type.
Please let me know if you can help me understand what is making the
headset decide to disconnect AVDTP in these cases, and what is the
best way to fix this, or any ideas that may help investigating this
further.
Thanks!
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
On Wed, Jun 27, 2018 at 1:15 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Joao,
>>
> Ive pushed the fix, at least MW600 reconnects properly.
>
Thanks, I tested it with my MW600 and it is working great! I'll let
you know once I get results from QA with the other headsets.
On Wed, Jun 27, 2018 at 12:08 AM, Tanu Kaskinen <[email protected]> wrote:
> On Tue, 2018-06-26 at 08:41 -0700, Jo=C3=A3o Paulo Rechi Vita wrote:
>> My initial thought is that module-card-restore does more harm then
>> good for UX with Bluetooth headsets, actually. It sure was useful when
>> module-bluetooth-policy did not exist, but I think a good user
>> experience is based on dynamically adapting according to which streams
>> are active at a certain moment, instead of user input. This is mostly
>> covered by module-bluetooth-policy + module-role-{cork,ducking}, but I
>> don't think anything switches the profile to A2DP when there is a
>> "high-quality" stream playing if module-card-restore initially set the
>> profile to headset_head_sink. Maybe this is more of a UI bug and a
>> user-focused UI should not expose means for the user to manually
>> select the profile, which is aligned with a previous comment from
>> Tanu:
>>
>> > On Thu, Jun 14, 2018 at 4:57 AM, Tanu Kaskinen <[email protected]> wrote:
>> >
>> > If module-bluetooth-policy is sufficient, then module-card-restore
>> > won't do anything anyway, because you never set the profile manually.
>> > If you ever set the profile manually, that's an indication that module=
-
>> > bluetooth-policy isn't always good enough.
>>
>> Still, I think the general user will only manually change the profile
>> either if things go wrong for some reason, or before PulseAudio 12,
>> because HSP/HFP was selected by default. If they leave the setting on
>> the "wrong profile", it affects their experience next time using the
>> headset, despite if it is right afterwards or months later, or if the
>> headset has been removed and paired with a different machine in the
>> meantime. Again, it may be a UI issue after all, but comparing to
>> Android/iPhone (which is what a lot of users are likely to have
>> previous experience with), there is not even a way for users to
>> manually set the active profile for headsets. They can enable/disable
>> a profile for an specific headset on Android tho, which gives them
>> some sort of control. I don't think there is any client API for
>> disabling profiles on cards, but maybe that could be a good
>> alternative?
>
> I agree, it's not nice that setting the profile once will interfere
> with automatic configuration forever. Do you want to make a patch for
> module-card-restore that adds an option (enabled by default) for
> disabling profile restoring for bluetooth?
>
Yes, I can do it.
> Offering a UI for disabling profiles doesn't seem like a better
> alternative to me, at least for this problem. If there's some other use
> case for disabling profiles, I'm not against the idea in principle.
>
I was thinking about users that only want to use their headset for
HSP/HFP with VoIP applications, for example. But maybe
module-stream-restore is enough in this case and I'm over-engineering,
lets just leave this case aside for now.
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
Hi Joao,
On Tue, Jun 26, 2018 at 6:41 PM, Jo=C3=A3o Paulo Rechi Vita
<[email protected]> wrote:
> Hello,
>
> On Tue, Jun 26, 2018 at 3:55 AM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi Joao,
>>
>> On Thu, Jun 21, 2018 at 10:21 PM, Jo=C3=A3o Paulo Rechi Vita
>> <[email protected]> wrote:
>>>
>>> I'm adding some extra debug around the initial profile selection to
>>> have a clear picture of what is going on there and will keep analyzing
>>> this further. I'll get back when I have something, now that I have a
>>> better idea of what to look for, but any insights are welcome in the
>>> meantime.
>>
>> Just a heads up Ive sent a patch for BlueZ that shoud fix this for
>> MW600, it turns out the device did not reconnect A2DP after HFP and
>> would only do that is SCO is connected which is too late.
>
> That is great news, although I don't see any new patch on the list.
> Can you share a link?
>
> Just to add more info (although it may not be super useful at this
> point), on the past few days I've been experimenting with how
> module-card-restore is affecting this problem, combined with
> increasing WAIT_FOR_PROFILES_TIMEOUT_USEC to 60s and got the following
> summary:
>
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s, module-card-restore restores A2DP:
> a2dp_sink available: Yes, headset_head_unit available: Yes, active
> profile: a2dp_sink
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s, module-card-restore restores HSP:
> a2dp_sink available: No, headset_head_unit available: Yes, active
> profile: headset_head_unit
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore restores HSP:
> a2dp_sink available: No, headset_head_unit available: No, active
> profile: None -- card removed
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, no module-card-restore: a2dp_sink
> available: No, headset_head_unit available: No, active profile: None
> -- card removed
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore tries to
> restore a2dp_sink but it does not because it is not available:
> a2dp_sink available: No, headset_head_unit available: No, active
> profile: None, card removed
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore restores A2DP
> (this is without the patch that makes m-c-r ignore unavailble
> profiles, just for testing): a2dp_sink available: Yes,
> headset_head_unit available: Yes, active profile: off
>
> Also, I've tried to make module-bluez5-device avoid acquiring the
> transport right away when the card is created and have the source/sink
> be created suspended, deferring the audio connection establishment to
> when there is an actual stream to be transferred (which should resume
> the sink) or we get an incoming connection. But I looks like I have
> messed up the state machine while doing that and the source/sink was
> never resumed, which is not really useful. I going to try your BlueZ
> fix first (when I find it), and after that we can see if there is
> anything else that needs to be fixed in PulseAudio.
Ive pushed the fix, at least MW600 reconnects properly.
>> Anyway I
>> briefly discussed with Tanu about the ordering of initial profile
>> shall be bluetooth-policy first than restore since that means restore
>> is run last overriding any profile set by bluetooth-policy in case the
>> user has set anything as preference.
>>
>
> In my tests module-bluetooth-policy was not affecting this problem at
> all since it was not taking any actions on these profiles (and I
> didn't have any media.role=3Dphone stream active). Are you trying to
> address a different problem with that change?
>
> My initial thought is that module-card-restore does more harm then
> good for UX with Bluetooth headsets, actually. It sure was useful when
> module-bluetooth-policy did not exist, but I think a good user
> experience is based on dynamically adapting according to which streams
> are active at a certain moment, instead of user input. This is mostly
> covered by module-bluetooth-policy + module-role-{cork,ducking}, but I
> don't think anything switches the profile to A2DP when there is a
> "high-quality" stream playing if module-card-restore initially set the
> profile to headset_head_sink. Maybe this is more of a UI bug and a
> user-focused UI should not expose means for the user to manually
> select the profile, which is aligned with a previous comment from
> Tanu:
>
>> On Thu, Jun 14, 2018 at 4:57 AM, Tanu Kaskinen <[email protected]> wrote:
>>
>> If module-bluetooth-policy is sufficient, then module-card-restore
>> won't do anything anyway, because you never set the profile manually.
>> If you ever set the profile manually, that's an indication that module-
>> bluetooth-policy isn't always good enough.
>
> Still, I think the general user will only manually change the profile
> either if things go wrong for some reason, or before PulseAudio 12,
> because HSP/HFP was selected by default. If they leave the setting on
> the "wrong profile", it affects their experience next time using the
> headset, despite if it is right afterwards or months later, or if the
> headset has been removed and paired with a different machine in the
> meantime. Again, it may be a UI issue after all, but comparing to
> Android/iPhone (which is what a lot of users are likely to have
> previous experience with), there is not even a way for users to
> manually set the active profile for headsets. They can enable/disable
> a profile for an specific headset on Android tho, which gives them
> some sort of control. I don't think there is any client API for
> disabling profiles on cards, but maybe that could be a good
> alternative?
Yep, I guess having only one policy module is actually better in this
case so perhaps restore need to check if bluetooth-policy is loaded
and then ignore any bluetooth card.
> I realized automatic audio routing is a hot-topic and I may be missing
> some alternatives or other previous discussions -- please point me to
> them if that is the case.
>
> --
> Jo=C3=A3o Paulo Rechi Vita
> http://about.me/jprvita
--=20
Luiz Augusto von Dentz
On Tue, 2018-06-26 at 08:41 -0700, João Paulo Rechi Vita wrote:
> My initial thought is that module-card-restore does more harm then
> good for UX with Bluetooth headsets, actually. It sure was useful when
> module-bluetooth-policy did not exist, but I think a good user
> experience is based on dynamically adapting according to which streams
> are active at a certain moment, instead of user input. This is mostly
> covered by module-bluetooth-policy + module-role-{cork,ducking}, but I
> don't think anything switches the profile to A2DP when there is a
> "high-quality" stream playing if module-card-restore initially set the
> profile to headset_head_sink. Maybe this is more of a UI bug and a
> user-focused UI should not expose means for the user to manually
> select the profile, which is aligned with a previous comment from
> Tanu:
>
> > On Thu, Jun 14, 2018 at 4:57 AM, Tanu Kaskinen <[email protected]> wrote:
> >
> > If module-bluetooth-policy is sufficient, then module-card-restore
> > won't do anything anyway, because you never set the profile manually.
> > If you ever set the profile manually, that's an indication that module-
> > bluetooth-policy isn't always good enough.
>
> Still, I think the general user will only manually change the profile
> either if things go wrong for some reason, or before PulseAudio 12,
> because HSP/HFP was selected by default. If they leave the setting on
> the "wrong profile", it affects their experience next time using the
> headset, despite if it is right afterwards or months later, or if the
> headset has been removed and paired with a different machine in the
> meantime. Again, it may be a UI issue after all, but comparing to
> Android/iPhone (which is what a lot of users are likely to have
> previous experience with), there is not even a way for users to
> manually set the active profile for headsets. They can enable/disable
> a profile for an specific headset on Android tho, which gives them
> some sort of control. I don't think there is any client API for
> disabling profiles on cards, but maybe that could be a good
> alternative?
I agree, it's not nice that setting the profile once will interfere
with automatic configuration forever. Do you want to make a patch for
module-card-restore that adds an option (enabled by default) for
disabling profile restoring for bluetooth?
Offering a UI for disabling profiles doesn't seem like a better
alternative to me, at least for this problem. If there's some other use
case for disabling profiles, I'm not against the idea in principle.
--
Tanu
https://liberapay.com/tanuk
https://www.patreon.com/tanuk
Hello,
On Tue, Jun 26, 2018 at 3:55 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Joao,
>
> On Thu, Jun 21, 2018 at 10:21 PM, Jo=C3=A3o Paulo Rechi Vita
> <[email protected]> wrote:
>>
>> I'm adding some extra debug around the initial profile selection to
>> have a clear picture of what is going on there and will keep analyzing
>> this further. I'll get back when I have something, now that I have a
>> better idea of what to look for, but any insights are welcome in the
>> meantime.
>
> Just a heads up Ive sent a patch for BlueZ that shoud fix this for
> MW600, it turns out the device did not reconnect A2DP after HFP and
> would only do that is SCO is connected which is too late.
That is great news, although I don't see any new patch on the list.
Can you share a link?
Just to add more info (although it may not be super useful at this
point), on the past few days I've been experimenting with how
module-card-restore is affecting this problem, combined with
increasing WAIT_FOR_PROFILES_TIMEOUT_USEC to 60s and got the following
summary:
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s, module-card-restore restores A2DP:
a2dp_sink available: Yes, headset_head_unit available: Yes, active
profile: a2dp_sink
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s, module-card-restore restores HSP:
a2dp_sink available: No, headset_head_unit available: Yes, active
profile: headset_head_unit
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore restores HSP:
a2dp_sink available: No, headset_head_unit available: No, active
profile: None -- card removed
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, no module-card-restore: a2dp_sink
available: No, headset_head_unit available: No, active profile: None
-- card removed
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore tries to
restore a2dp_sink but it does not because it is not available:
a2dp_sink available: No, headset_head_unit available: No, active
profile: None, card removed
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s, module-card-restore restores A2DP
(this is without the patch that makes m-c-r ignore unavailble
profiles, just for testing): a2dp_sink available: Yes,
headset_head_unit available: Yes, active profile: off
Also, I've tried to make module-bluez5-device avoid acquiring the
transport right away when the card is created and have the source/sink
be created suspended, deferring the audio connection establishment to
when there is an actual stream to be transferred (which should resume
the sink) or we get an incoming connection. But I looks like I have
messed up the state machine while doing that and the source/sink was
never resumed, which is not really useful. I going to try your BlueZ
fix first (when I find it), and after that we can see if there is
anything else that needs to be fixed in PulseAudio.
> Anyway I
> briefly discussed with Tanu about the ordering of initial profile
> shall be bluetooth-policy first than restore since that means restore
> is run last overriding any profile set by bluetooth-policy in case the
> user has set anything as preference.
>
In my tests module-bluetooth-policy was not affecting this problem at
all since it was not taking any actions on these profiles (and I
didn't have any media.role=3Dphone stream active). Are you trying to
address a different problem with that change?
My initial thought is that module-card-restore does more harm then
good for UX with Bluetooth headsets, actually. It sure was useful when
module-bluetooth-policy did not exist, but I think a good user
experience is based on dynamically adapting according to which streams
are active at a certain moment, instead of user input. This is mostly
covered by module-bluetooth-policy + module-role-{cork,ducking}, but I
don't think anything switches the profile to A2DP when there is a
"high-quality" stream playing if module-card-restore initially set the
profile to headset_head_sink. Maybe this is more of a UI bug and a
user-focused UI should not expose means for the user to manually
select the profile, which is aligned with a previous comment from
Tanu:
> On Thu, Jun 14, 2018 at 4:57 AM, Tanu Kaskinen <[email protected]> wrote:
>
> If module-bluetooth-policy is sufficient, then module-card-restore
> won't do anything anyway, because you never set the profile manually.
> If you ever set the profile manually, that's an indication that module-
> bluetooth-policy isn't always good enough.
Still, I think the general user will only manually change the profile
either if things go wrong for some reason, or before PulseAudio 12,
because HSP/HFP was selected by default. If they leave the setting on
the "wrong profile", it affects their experience next time using the
headset, despite if it is right afterwards or months later, or if the
headset has been removed and paired with a different machine in the
meantime. Again, it may be a UI issue after all, but comparing to
Android/iPhone (which is what a lot of users are likely to have
previous experience with), there is not even a way for users to
manually set the active profile for headsets. They can enable/disable
a profile for an specific headset on Android tho, which gives them
some sort of control. I don't think there is any client API for
disabling profiles on cards, but maybe that could be a good
alternative?
I realized automatic audio routing is a hot-topic and I may be missing
some alternatives or other previous discussions -- please point me to
them if that is the case.
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
Hi Joao,
On Thu, Jun 21, 2018 at 10:21 PM, Jo=C3=A3o Paulo Rechi Vita
<[email protected]> wrote:
> Hello Luiz,
>
> On Thu, Jun 21, 2018 at 3:27 AM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>>
>>> Im trying to reproduce this with sony sbh50 but apparently it doesn't
>>> have the same problem as it worked just fine, one thing I notice
>>> though is that HFP does not connect:
>>>
>>> https://gist.github.com/Vudentz/6f385ededcb00d1d0f4403f06923fd1a
>>>
>>> As you can see locally we only support HSP which means there is no
>>> match for MFP, but perhaps you are running with oFono? Anyway I should
>>> have an mw600 somewhere but that is quite old already, but you
>>> mentioned it did not work with MDR-XB950N1 which is quite new model?
>
> Sorry, I forgot to mention: I was not running oFono, so only
> PulseAudio's HSP implementation was registered with bluetoothd. I
> personally have only been able to reproduce this problem on the Sony
> MW-600, from the headsets I have access to. Our QA team at Endless
> have seen similar symptoms on the Sony MDR-XB950N1, AMP Pulse BXH-300,
> Intopic HM-BT001, and The Coopidea CP-TW-01. I have not able to
> confirm 100% whether that is the exact same problem on all of them, as
> I'm focusing on the MW-600 which is the one I have access to.
>
>>> Anyway if you can gather some logs of bluetoothd that would be useful
>>> to identify where is the problem.
>>
>
> I've actually was not able to reproduce the exact same symptoms
> yesterday: instead of the headset disconnecting A2DP and the card
> being destroyed, the OFF profile ended up being selected. The
> transport for HSP got available first, the card was created 3s
> afterwards (due to WAIT_FOR_PROFILES_TIMEOUT_USEC being reached), but
> a2dp actually got connected about 50s afterwards. Then after looking
> into it for a while I realized a few extra things that I had not
> noticed befofe. PulseAudio logs for this case can be seen right
> bellow, and for the "disconnecting case" afterwards. I can still
> collect bluetoothd logs if needed.
>
> Notice that the "module-card-restore.c: Restoring profile X for card
> Y" message is wrong, as this is from PulseAudio 11 plus some
> backported patches, but it does not contain "card-restore: log the
> correct profile name". I marked it on the logs bellow for attention.
>
> 1. OFF CASE
>
> - org.bluez.Profile1.NewConnection() is called on PulseAudio's
> HSPAGProfile object path:
>
> Jun 20 17:09:11 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: dbus: path=3D/Profile/HSPAGProfile,
> interface=3Dorg.bluez.Profile1, member=3DNewConnection
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: dbus: NewConnection
> path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=3D23, profile
> headset_head_unit
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: doing listen
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state:
> disconnected -> idle
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
> available for profile headset_head_unit
> Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CLIP=3D1
>
> - WAIT_FOR_PROFILES_TIMEOUT_USEC expires:
>
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Timeout expired, and device /org/bluez/hci0/dev_58_17_0C_EA_02_89
> still has disconnected profiles: a2dp_sink
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
> module-bluez5-discover.c: Loading module-bluez5-device
> path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
> module-card-restore.c: Restoring port latency offsets for card
> bluez_card.58_17_0C_EA_02_89.
> ** wrong message here --> Jun 20 17:09:15 endless pulseaudio[899]:
> [pulseaudio] module-card-restore.c: Restoring profile
> 'headset_head_unit' for card bluez_card.58_17_0C_EA_02_89.
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Created
> 1 "bluez_card.58_17_0C_EA_02_89"
> ** and the following message indicates module-card-restore was trying
> to restore a2dp_sink instead
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
> module-bluez5-device.c: Profile a2dp_sink has no transport
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Changed
> profile of card 1 "bluez_card.58_17_0C_EA_02_89" to off
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module.c: Loaded
> "module-bluez5-device" (index: #25; argument:
> "path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0").
>
> - Now the card remains created and idle for a while, since its profile
> has been set to OFF, except for some boring RFCOMM chat.
>
> Jun 20 17:09:22 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CSCS=3D"UTF-8"
> Jun 20 17:09:32 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT*SEAM=3D"MW600",13
> Jun 20 17:09:42 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CLAN?
> Jun 20 17:09:52 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT+COLP=3D1
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CCLK?
>
> - Exact 50s after the NewConnection() call there is a
> org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's
> A2DPSource object path:
>
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Unknown interface org.freedesktop.DBus.Introspectable found, skipping
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Unknown interface org.bluez.MediaTransport1 found, skippingJun 20
> 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Unknown
> interface org.freedesktop.DBus.Properties found, skipping
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> dbus: path=3D/MediaEndpoint/A2DPSource,
> interface=3Dorg.bluez.MediaEndpoint1, member=3DSetConfiguration
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state:
> disconnected -> idle
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
> status unknown
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 available for
> profile a2dp_sink
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Properties changed in transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: idle ->
> playing
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
> status yes
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] device-port.c:
> Setting port headset-output to status yes
> Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Properties changed in transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0
> Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: playing ->
> idle
> Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
> status unknown
> Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] device-port.c:
> Setting port headset-output to status unknown
> Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
>
> 2. DISCONNECTING CASE (here I had WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s,
> so it does not expire):
>
> - org.bluez.Profile1.NewConnection() is called on PulseAudio's
> HSPAGProfile object path:
>
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: dbus: path=3D/Profile/HSPAGProfile,
> interface=3Dorg.bluez.Profile1, member=3DNewConnection
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: dbus: NewConnection
> path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=3D23, profile
> headset_head_unit
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: doing listen
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state:
> disconnected -> idle
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
> available for profile headset_head_unit
> Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CLIP=3D1
> Jun 13 15:22:20 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CSCS=3D"UTF-8"
> Jun 13 15:22:30 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT*SEAM=3D"MW600",13
> Jun 13 15:22:40 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CLAN?
> Jun 13 15:22:50 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+COLP=3D1
> Jun 13 15:23:00 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+CCLK?
>
> - Exact 51s after the NewConnection() call there is a
> org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's
> A2DPSource object path:
>
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> dbus: path=3D/MediaEndpoint/A2DPSource,
> interface=3Dorg.bluez.MediaEndpoint1, member=3DSetConfiguration
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state:
> disconnected -> idle
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-bluez5-discover.c: Loading module-bluez5-device
> path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-card-restore.c: Restoring port latency offsets for card
> bluez_card.58_17_0C_EA_02_89.
> ** wrong message, it is restoring headset_head_unit --> Jun 13
> 15:23:01 endless pulseaudio[809]: [pulseaudio] module-card-restore.c:
> Restoring profile 'a2dp_sink' for card bluez_card.58_17_0C_EA_02_89.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Created
> 2 "bluez_card.58_17_0C_EA_02_89"
>
> - SCO is established
>
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-bluez5-device.c: Acquiring transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: doing connect
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-bluez5-device.c: Transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 acquired: fd 13
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: idle ->
> playing
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to
> availability status yes
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c:
> Setting port headset-output to status yes
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c:
> Setting port headset-input to status yes
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: Created
> sink 2 "bluez_sink.58_17_0C_EA_02_89.headset_head_unit" with sample
> spec s16le 1ch 8000Hz and channel map mono
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> bluetooth.protocol =3D "headset_head_unit"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.intended_roles =3D "phone"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.description =3D "MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.string =3D "58:17:0C:EA:02:89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.api =3D "bluez"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.class =3D "sound"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.bus =3D "bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.form_factor =3D "headset"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> bluez.class =3D "0x240404"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> bluez.alias =3D "MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
> device.icon_name =3D "audio-headset-bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> Created source 3
> "bluez_sink.58_17_0C_EA_02_89.headset_head_unit.monitor" with sample
> spec s16le 1ch 8000Hz and channel map mono
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.description =3D "Monitor of MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.class =3D "monitor"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.string =3D "58:17:0C:EA:02:89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.api =3D "bluez"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.bus =3D "bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.form_factor =3D "headset"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.class =3D "0x240404"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.alias =3D "MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.icon_name =3D "audio-headset-bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.intended_roles =3D "phone"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> Created source 4 "bluez_source.58_17_0C_EA_02_89.headset_head_unit"
> with sample spec s16le 1ch 8000Hz and channel map mono
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluetooth.protocol =3D "headset_head_unit"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.intended_roles =3D "phone"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.description =3D "MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.string =3D "58:17:0C:EA:02:89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.api =3D "bluez"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.class =3D "sound"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.bus =3D "bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.form_factor =3D "headset"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.class =3D "0x240404"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> bluez.alias =3D "MW600"
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
> device.icon_name =3D "audio-headset-bluetooth"
> Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
> module-bluez5-device.c: IO Thread starting up
> Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c:
> RealtimeKit worked.
> Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c:
> Successfully enabled SCHED_RR scheduling for thread, with priority 5.
> Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
> module-bluez5-device.c: Transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 resuming
> Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
> module-bluez5-device.c: Stream properly set up, we're ready to roll!
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-device-restore.c: Could not set format on sink
> bluez_sink.58_17_0C_EA_02_89.headset_head_unit
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-bluetooth-policy.c: Profile headset_head_unit cannot be
> selected for loopback
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-suspend-on-idle.c: Sink
> bluez_sink.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout
> in 5 seconds.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c:
> default_sink: alsa_output.pci-0000_00_1f.3.analog-stereo ->
> bluez_sink.58_17_0C_EA_02_89.headset_head_unit
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM >> +VGS=3D15
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-bluetooth-policy.c: Profile headset_head_unit cannot be
> selected for loopback
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> module-suspend-on-idle.c: Source
> bluez_source.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout
> in 5 seconds.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c:
> default_source: alsa_input.pci-0000_00_1f.3.analog-stereo ->
> bluez_source.58_17_0C_EA_02_89.headset_head_unit
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM >> +VGM=3D15
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module.c: Loaded
> "module-bluez5-device" (index: #27; argument:
> "path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0").
>
> - org.bluez.MediaTransport1.ClearConfiguration() call on PulseAudio's
> A2DPSource object path, makes a2dp_sink unavailable:
>
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 available for
> profile a2dp_sink
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> dbus: path=3D/MediaEndpoint/A2DPSource,
> interface=3Dorg.bluez.MediaEndpoint1, member=3DClearConfiguration
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Clearing transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 profile
> a2dp_sink
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state: idle ->
> disconnected
> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
> status no
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
> module-suspend-on-idle.c: Source
> bluez_source.58_17_0C_EA_02_89.headset_head_unit idle for too long,
> suspending ...
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] source.c:
> Suspend cause of source
> bluez_source.58_17_0C_EA_02_89.headset_head_unit is 0x0004, suspending
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no
> streams around, trying to vacuum.
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
> module-suspend-on-idle.c: Sink
> bluez_sink.58_17_0C_EA_02_89.headset_head_unit idle for too long,
> suspending ...
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] sink.c: Suspend
> cause of sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit is
> 0x0004, suspending
> Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth]
> module-bluez5-device.c: Releasing transport
> /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
> Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth] backend-native.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 released
> Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth]
> module-bluez5-device.c: Audio stream torn down
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no
> streams around, trying to vacuum.
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
> Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: playing ->
> idle
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] card.c: Setting
> card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to
> availability status unknown
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c:
> Setting port headset-output to status unknown
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c:
> Setting port headset-input to status unknown
> Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
> core-subscribe.c: Dropped redundant event due to change event.
> Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM << AT+VGS=3D15
> Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio]
> backend-native.c: RFCOMM >> OK
>
> There was still another situation I've seen, which is the RFCOMM
> getting disconnected at this point with
> WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s (which makes we create the card
> without all profiles connected), but I don't have logs for it atm.
>
>> Managed to reproduce the issue, if I recall correctly MW600 don't like
>> that SCO is open before A2DP is configured which is caused by:
>>
>
> That is aligned with my observations when debugging this over the past
> few days, and with I've seen on the logs above.
>
>>
>> /* Ignore card if has already set other initial profile than a2dp */
>> if (card->active_profile &&
>> !pa_streq(card->active_profile->name, "a2dp") &&
>> !pa_streq(card->active_profile->name, "a2dp_sink"))
>> return PA_HOOK_OK;
>>
>> /* Set initial profile to hsp */
>> card_set_profile(u, card, false);
>>
>> If I get it correctly the first if statement will not return in case
>> of A2DP, which basically negates restored profile?, and then it sets
>> HSP which I find to be the opposite of what we should be doing except
>> if there already an stream tagged with voice otherwise we shall really
>> prefer A2DP.
>>
>
> I'm reading this correctly, this code path is reached only when there
> is a source-output which is tagged with media.role=3Dphone (unless some
> extra heuristic is enabled by passing "auto_switch=3D2" to
> module-bluetooth-policy, which is not the case here), which is
> controlled by the "if (source_output_count(c, userdata) =3D=3D 0)" branch
> about 8 lines above the ones you pasted.
>
> I'm adding some extra debug around the initial profile selection to
> have a clear picture of what is going on there and will keep analyzing
> this further. I'll get back when I have something, now that I have a
> better idea of what to look for, but any insights are welcome in the
> meantime.
Just a heads up Ive sent a patch for BlueZ that shoud fix this for
MW600, it turns out the device did not reconnect A2DP after HFP and
would only do that is SCO is connected which is too late. Anyway I
briefly discussed with Tanu about the ordering of initial profile
shall be bluetooth-policy first than restore since that means restore
is run last overriding any profile set by bluetooth-policy in case the
user has set anything as preference.
--=20
Luiz Augusto von Dentz
Hello Luiz,
On Thu, Jun 21, 2018 at 3:27 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
>
>> Im trying to reproduce this with sony sbh50 but apparently it doesn't
>> have the same problem as it worked just fine, one thing I notice
>> though is that HFP does not connect:
>>
>> https://gist.github.com/Vudentz/6f385ededcb00d1d0f4403f06923fd1a
>>
>> As you can see locally we only support HSP which means there is no
>> match for MFP, but perhaps you are running with oFono? Anyway I should
>> have an mw600 somewhere but that is quite old already, but you
>> mentioned it did not work with MDR-XB950N1 which is quite new model?
Sorry, I forgot to mention: I was not running oFono, so only
PulseAudio's HSP implementation was registered with bluetoothd. I
personally have only been able to reproduce this problem on the Sony
MW-600, from the headsets I have access to. Our QA team at Endless
have seen similar symptoms on the Sony MDR-XB950N1, AMP Pulse BXH-300,
Intopic HM-BT001, and The Coopidea CP-TW-01. I have not able to
confirm 100% whether that is the exact same problem on all of them, as
I'm focusing on the MW-600 which is the one I have access to.
>> Anyway if you can gather some logs of bluetoothd that would be useful
>> to identify where is the problem.
>
I've actually was not able to reproduce the exact same symptoms
yesterday: instead of the headset disconnecting A2DP and the card
being destroyed, the OFF profile ended up being selected. The
transport for HSP got available first, the card was created 3s
afterwards (due to WAIT_FOR_PROFILES_TIMEOUT_USEC being reached), but
a2dp actually got connected about 50s afterwards. Then after looking
into it for a while I realized a few extra things that I had not
noticed befofe. PulseAudio logs for this case can be seen right
bellow, and for the "disconnecting case" afterwards. I can still
collect bluetoothd logs if needed.
Notice that the "module-card-restore.c: Restoring profile X for card
Y" message is wrong, as this is from PulseAudio 11 plus some
backported patches, but it does not contain "card-restore: log the
correct profile name". I marked it on the logs bellow for attention.
1. OFF CASE
- org.bluez.Profile1.NewConnection() is called on PulseAudio's
HSPAGProfile object path:
Jun 20 17:09:11 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
backend-native.c: dbus: path=3D/Profile/HSPAGProfile,
interface=3Dorg.bluez.Profile1, member=3DNewConnection
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
backend-native.c: dbus: NewConnection
path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=3D23, profile
headset_head_unit
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
backend-native.c: doing listen
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state:
disconnected -> idle
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
available for profile headset_head_unit
Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT+CLIP=3D1
- WAIT_FOR_PROFILES_TIMEOUT_USEC expires:
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Timeout expired, and device /org/bluez/hci0/dev_58_17_0C_EA_02_89
still has disconnected profiles: a2dp_sink
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
module-bluez5-discover.c: Loading module-bluez5-device
path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
module-card-restore.c: Restoring port latency offsets for card
bluez_card.58_17_0C_EA_02_89.
** wrong message here --> Jun 20 17:09:15 endless pulseaudio[899]:
[pulseaudio] module-card-restore.c: Restoring profile
'headset_head_unit' for card bluez_card.58_17_0C_EA_02_89.
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Created
1 "bluez_card.58_17_0C_EA_02_89"
** and the following message indicates module-card-restore was trying
to restore a2dp_sink instead
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
module-bluez5-device.c: Profile a2dp_sink has no transport
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Changed
profile of card 1 "bluez_card.58_17_0C_EA_02_89" to off
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module.c: Loaded
"module-bluez5-device" (index: #25; argument:
"path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0").
- Now the card remains created and idle for a while, since its profile
has been set to OFF, except for some boring RFCOMM chat.
Jun 20 17:09:22 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT+CSCS=3D"UTF-8"
Jun 20 17:09:32 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT*SEAM=3D"MW600",13
Jun 20 17:09:42 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT+CLAN?
Jun 20 17:09:52 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT+COLP=3D1
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio]
backend-native.c: RFCOMM << AT+CCLK?
- Exact 50s after the NewConnection() call there is a
org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's
A2DPSource object path:
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Unknown interface org.freedesktop.DBus.Introspectable found, skipping
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Unknown interface org.bluez.MediaTransport1 found, skippingJun 20
17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Unknown
interface org.freedesktop.DBus.Properties found, skipping
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
dbus: path=3D/MediaEndpoint/A2DPSource,
interface=3Dorg.bluez.MediaEndpoint1, member=3DSetConfiguration
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state:
disconnected -> idle
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
status unknown
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 available for
profile a2dp_sink
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Properties changed in transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: idle ->
playing
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
status yes
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] device-port.c:
Setting port headset-output to status yes
Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Properties changed in transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0
Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: playing ->
idle
Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
status unknown
Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] device-port.c:
Setting port headset-output to status unknown
Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
2. DISCONNECTING CASE (here I had WAIT_FOR_PROFILES_TIMEOUT_USEC=3D60s,
so it does not expire):
- org.bluez.Profile1.NewConnection() is called on PulseAudio's
HSPAGProfile object path:
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: dbus: path=3D/Profile/HSPAGProfile,
interface=3Dorg.bluez.Profile1, member=3DNewConnection
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: dbus: NewConnection
path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=3D23, profile
headset_head_unit
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: doing listen
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state:
disconnected -> idle
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
available for profile headset_head_unit
Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+CLIP=3D1
Jun 13 15:22:20 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+CSCS=3D"UTF-8"
Jun 13 15:22:30 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT*SEAM=3D"MW600",13
Jun 13 15:22:40 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+CLAN?
Jun 13 15:22:50 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+COLP=3D1
Jun 13 15:23:00 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+CCLK?
- Exact 51s after the NewConnection() call there is a
org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's
A2DPSource object path:
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
dbus: path=3D/MediaEndpoint/A2DPSource,
interface=3Dorg.bluez.MediaEndpoint1, member=3DSetConfiguration
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state:
disconnected -> idle
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-bluez5-discover.c: Loading module-bluez5-device
path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-card-restore.c: Restoring port latency offsets for card
bluez_card.58_17_0C_EA_02_89.
** wrong message, it is restoring headset_head_unit --> Jun 13
15:23:01 endless pulseaudio[809]: [pulseaudio] module-card-restore.c:
Restoring profile 'a2dp_sink' for card bluez_card.58_17_0C_EA_02_89.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Created
2 "bluez_card.58_17_0C_EA_02_89"
- SCO is established
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-bluez5-device.c: Acquiring transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
backend-native.c: doing connect
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-bluez5-device.c: Transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 acquired: fd 13
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: idle ->
playing
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to
availability status yes
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c:
Setting port headset-output to status yes
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c:
Setting port headset-input to status yes
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: Created
sink 2 "bluez_sink.58_17_0C_EA_02_89.headset_head_unit" with sample
spec s16le 1ch 8000Hz and channel map mono
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
bluetooth.protocol =3D "headset_head_unit"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.intended_roles =3D "phone"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.description =3D "MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.string =3D "58:17:0C:EA:02:89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.api =3D "bluez"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.class =3D "sound"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.bus =3D "bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.form_factor =3D "headset"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
bluez.class =3D "0x240404"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
bluez.alias =3D "MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c:
device.icon_name =3D "audio-headset-bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
Created source 3
"bluez_sink.58_17_0C_EA_02_89.headset_head_unit.monitor" with sample
spec s16le 1ch 8000Hz and channel map mono
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.description =3D "Monitor of MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.class =3D "monitor"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.string =3D "58:17:0C:EA:02:89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.api =3D "bluez"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.bus =3D "bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.form_factor =3D "headset"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.class =3D "0x240404"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.alias =3D "MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.icon_name =3D "audio-headset-bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.intended_roles =3D "phone"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
Created source 4 "bluez_source.58_17_0C_EA_02_89.headset_head_unit"
with sample spec s16le 1ch 8000Hz and channel map mono
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluetooth.protocol =3D "headset_head_unit"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.intended_roles =3D "phone"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.description =3D "MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.string =3D "58:17:0C:EA:02:89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.api =3D "bluez"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.class =3D "sound"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.bus =3D "bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.form_factor =3D "headset"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.path =3D "/org/bluez/hci0/dev_58_17_0C_EA_02_89"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.class =3D "0x240404"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
bluez.alias =3D "MW600"
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c:
device.icon_name =3D "audio-headset-bluetooth"
Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
module-bluez5-device.c: IO Thread starting up
Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c:
RealtimeKit worked.
Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c:
Successfully enabled SCHED_RR scheduling for thread, with priority 5.
Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
module-bluez5-device.c: Transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 resuming
Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth]
module-bluez5-device.c: Stream properly set up, we're ready to roll!
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-device-restore.c: Could not set format on sink
bluez_sink.58_17_0C_EA_02_89.headset_head_unit
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-bluetooth-policy.c: Profile headset_head_unit cannot be
selected for loopback
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-suspend-on-idle.c: Sink
bluez_sink.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout
in 5 seconds.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c:
default_sink: alsa_output.pci-0000_00_1f.3.analog-stereo ->
bluez_sink.58_17_0C_EA_02_89.headset_head_unit
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM >> +VGS=3D15
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-bluetooth-policy.c: Profile headset_head_unit cannot be
selected for loopback
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
module-suspend-on-idle.c: Source
bluez_source.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout
in 5 seconds.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c:
default_source: alsa_input.pci-0000_00_1f.3.analog-stereo ->
bluez_source.58_17_0C_EA_02_89.headset_head_unit
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM >> +VGM=3D15
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module.c: Loaded
"module-bluez5-device" (index: #27; argument:
"path=3D/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=3D0").
- org.bluez.MediaTransport1.ClearConfiguration() call on PulseAudio's
A2DPSource object path, makes a2dp_sink unavailable:
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 available for
profile a2dp_sink
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
dbus: path=3D/MediaEndpoint/A2DPSource,
interface=3Dorg.bluez.MediaEndpoint1, member=3DClearConfiguration
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Clearing transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 profile
a2dp_sink
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state: idle ->
disconnected
Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability
status no
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
module-suspend-on-idle.c: Source
bluez_source.58_17_0C_EA_02_89.headset_head_unit idle for too long,
suspending ...
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] source.c:
Suspend cause of source
bluez_source.58_17_0C_EA_02_89.headset_head_unit is 0x0004, suspending
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no
streams around, trying to vacuum.
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
module-suspend-on-idle.c: Sink
bluez_sink.58_17_0C_EA_02_89.headset_head_unit idle for too long,
suspending ...
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] sink.c: Suspend
cause of sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit is
0x0004, suspending
Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth]
module-bluez5-device.c: Releasing transport
/org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23
Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth] backend-native.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 released
Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth]
module-bluez5-device.c: Audio stream torn down
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no
streams around, trying to vacuum.
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] bluez5-util.c:
Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: playing ->
idle
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] card.c: Setting
card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to
availability status unknown
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c:
Setting port headset-output to status unknown
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c:
Setting port headset-input to status unknown
Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio]
core-subscribe.c: Dropped redundant event due to change event.
Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM << AT+VGS=3D15
Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio]
backend-native.c: RFCOMM >> OK
There was still another situation I've seen, which is the RFCOMM
getting disconnected at this point with
WAIT_FOR_PROFILES_TIMEOUT_USEC=3D3s (which makes we create the card
without all profiles connected), but I don't have logs for it atm.
> Managed to reproduce the issue, if I recall correctly MW600 don't like
> that SCO is open before A2DP is configured which is caused by:
>
That is aligned with my observations when debugging this over the past
few days, and with I've seen on the logs above.
>
> /* Ignore card if has already set other initial profile than a2dp */
> if (card->active_profile &&
> !pa_streq(card->active_profile->name, "a2dp") &&
> !pa_streq(card->active_profile->name, "a2dp_sink"))
> return PA_HOOK_OK;
>
> /* Set initial profile to hsp */
> card_set_profile(u, card, false);
>
> If I get it correctly the first if statement will not return in case
> of A2DP, which basically negates restored profile?, and then it sets
> HSP which I find to be the opposite of what we should be doing except
> if there already an stream tagged with voice otherwise we shall really
> prefer A2DP.
>
I'm reading this correctly, this code path is reached only when there
is a source-output which is tagged with media.role=3Dphone (unless some
extra heuristic is enabled by passing "auto_switch=3D2" to
module-bluetooth-policy, which is not the case here), which is
controlled by the "if (source_output_count(c, userdata) =3D=3D 0)" branch
about 8 lines above the ones you pasted.
I'm adding some extra debug around the initial profile selection to
have a clear picture of what is going on there and will keep analyzing
this further. I'll get back when I have something, now that I have a
better idea of what to look for, but any insights are welcome in the
meantime.
Thanks for the help!
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
Hi Joao,
On Wed, Jun 20, 2018 at 5:47 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Joao,
>
> On Fri, Jun 15, 2018 at 2:33 AM, Jo=C3=A3o Paulo Rechi Vita
> <[email protected]> wrote:
>> On Thu, Jun 14, 2018 at 8:27 AM, Tanu Kaskinen <[email protected]> wrote:
>>> On Thu, 2018-06-14 at 08:05 -0700, Jo=C3=A3o Paulo Rechi Vita wrote:
>>>> > > I also had to disable module-card-restore, otherwise it tries to
>>>> > > switch to the saved a2dp_sink profile right when the card is creat=
ed,
>>>> > > which also makes the device abort the AVDTP connection for some
>>>> > > reason.
>>>> >
>>>> > This is without increasing the timeout, right, so the problem is tha=
t
>>>> > module-card-restore is trying to restore a2dp_sink before it's
>>>> > available? module-card-restore has been fixed to not to try to resto=
re
>>>> > unavailable profiles:
>>>> > https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=3Dd659=
74d8501052bafb03e65f5df954511e9949a2
>>>> >
>>>>
>>>> No, this is in addition to increasing the timeout. To have things
>>>> working I need to increase the timeout AND disable
>>>> module-card-restore. Sorry for not being clear about it before.
>>>>
>>>> I will try the commit you pointed, but I don't think it will help
>>>> since, if I'm following this right, the transport is already marked as
>>>> available at this point (I need to double-check on this point though
>>>> -- sorry, too many moving parts).
>>>
>>> If you confirm that module-card-restore indeed has to be disabled even
>>> with the increased timeout, then it would be very interesting to know
>>> what effect module-card-restore has in the card initialization. To me
>>> it seems that it should make no difference, because the a2dp profile is
>>> the default anyway, and all the module does is to choose the initial
>>> profile.
>>>
>>
>> Ok, I have done more testing focusing on this specific point and
>> confirmed we indeed don't need to disable module-card-restore. With
>> the 60s timeout the headset was able to connect successfully 6 times
>> in a row. So for now the only open point is if there is any better fix
>> for these headsets than increasing the timeout.
>
> Im trying to reproduce this with sony sbh50 but apparently it doesn't
> have the same problem as it worked just fine, one thing I notice
> though is that HFP does not connect:
>
> https://gist.github.com/Vudentz/6f385ededcb00d1d0f4403f06923fd1a
>
> As you can see locally we only support HSP which means there is no
> match for MFP, but perhaps you are running with oFono? Anyway I should
> have an mw600 somewhere but that is quite old already, but you
> mentioned it did not work with MDR-XB950N1 which is quite new model?
> Anyway if you can gather some logs of bluetoothd that would be useful
> to identify where is the problem.
Managed to reproduce the issue, if I recall correctly MW600 don't like
that SCO is open before A2DP is configured which is caused by:
/* Ignore card if has already set other initial profile than a2dp */
if (card->active_profile &&
!pa_streq(card->active_profile->name, "a2dp") &&
!pa_streq(card->active_profile->name, "a2dp_sink"))
return PA_HOOK_OK;
/* Set initial profile to hsp */
card_set_profile(u, card, false);
If I get it correctly the first if statement will not return in case
of A2DP, which basically negates restored profile?, and then it sets
HSP which I find to be the opposite of what we should be doing except
if there already an stream tagged with voice otherwise we shall really
prefer A2DP.
--=20
Luiz Augusto von Dentz
Hi Joao,
On Fri, Jun 15, 2018 at 2:33 AM, Jo=C3=A3o Paulo Rechi Vita
<[email protected]> wrote:
> On Thu, Jun 14, 2018 at 8:27 AM, Tanu Kaskinen <[email protected]> wrote:
>> On Thu, 2018-06-14 at 08:05 -0700, Jo=C3=A3o Paulo Rechi Vita wrote:
>>> > > I also had to disable module-card-restore, otherwise it tries to
>>> > > switch to the saved a2dp_sink profile right when the card is create=
d,
>>> > > which also makes the device abort the AVDTP connection for some
>>> > > reason.
>>> >
>>> > This is without increasing the timeout, right, so the problem is that
>>> > module-card-restore is trying to restore a2dp_sink before it's
>>> > available? module-card-restore has been fixed to not to try to restor=
e
>>> > unavailable profiles:
>>> > https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=3Dd6597=
4d8501052bafb03e65f5df954511e9949a2
>>> >
>>>
>>> No, this is in addition to increasing the timeout. To have things
>>> working I need to increase the timeout AND disable
>>> module-card-restore. Sorry for not being clear about it before.
>>>
>>> I will try the commit you pointed, but I don't think it will help
>>> since, if I'm following this right, the transport is already marked as
>>> available at this point (I need to double-check on this point though
>>> -- sorry, too many moving parts).
>>
>> If you confirm that module-card-restore indeed has to be disabled even
>> with the increased timeout, then it would be very interesting to know
>> what effect module-card-restore has in the card initialization. To me
>> it seems that it should make no difference, because the a2dp profile is
>> the default anyway, and all the module does is to choose the initial
>> profile.
>>
>
> Ok, I have done more testing focusing on this specific point and
> confirmed we indeed don't need to disable module-card-restore. With
> the 60s timeout the headset was able to connect successfully 6 times
> in a row. So for now the only open point is if there is any better fix
> for these headsets than increasing the timeout.
Im trying to reproduce this with sony sbh50 but apparently it doesn't
have the same problem as it worked just fine, one thing I notice
though is that HFP does not connect:
https://gist.github.com/Vudentz/6f385ededcb00d1d0f4403f06923fd1a
As you can see locally we only support HSP which means there is no
match for MFP, but perhaps you are running with oFono? Anyway I should
have an mw600 somewhere but that is quite old already, but you
mentioned it did not work with MDR-XB950N1 which is quite new model?
Anyway if you can gather some logs of bluetoothd that would be useful
to identify where is the problem.
>
> --
> Jo=C3=A3o Paulo Rechi Vita
> http://about.me/jprvita
--=20
Luiz Augusto von Dentz
On Thu, Jun 14, 2018 at 8:27 AM, Tanu Kaskinen <[email protected]> wrote:
> On Thu, 2018-06-14 at 08:05 -0700, Jo=C3=A3o Paulo Rechi Vita wrote:
>> > > I also had to disable module-card-restore, otherwise it tries to
>> > > switch to the saved a2dp_sink profile right when the card is created=
,
>> > > which also makes the device abort the AVDTP connection for some
>> > > reason.
>> >
>> > This is without increasing the timeout, right, so the problem is that
>> > module-card-restore is trying to restore a2dp_sink before it's
>> > available? module-card-restore has been fixed to not to try to restore
>> > unavailable profiles:
>> > https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=3Dd65974=
d8501052bafb03e65f5df954511e9949a2
>> >
>>
>> No, this is in addition to increasing the timeout. To have things
>> working I need to increase the timeout AND disable
>> module-card-restore. Sorry for not being clear about it before.
>>
>> I will try the commit you pointed, but I don't think it will help
>> since, if I'm following this right, the transport is already marked as
>> available at this point (I need to double-check on this point though
>> -- sorry, too many moving parts).
>
> If you confirm that module-card-restore indeed has to be disabled even
> with the increased timeout, then it would be very interesting to know
> what effect module-card-restore has in the card initialization. To me
> it seems that it should make no difference, because the a2dp profile is
> the default anyway, and all the module does is to choose the initial
> profile.
>
Ok, I have done more testing focusing on this specific point and
confirmed we indeed don't need to disable module-card-restore. With
the 60s timeout the headset was able to connect successfully 6 times
in a row. So for now the only open point is if there is any better fix
for these headsets than increasing the timeout.
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
On Thu, 2018-06-14 at 08:05 -0700, João Paulo Rechi Vita wrote:
> > > I also had to disable module-card-restore, otherwise it tries to
> > > switch to the saved a2dp_sink profile right when the card is created,
> > > which also makes the device abort the AVDTP connection for some
> > > reason.
> >
> > This is without increasing the timeout, right, so the problem is that
> > module-card-restore is trying to restore a2dp_sink before it's
> > available? module-card-restore has been fixed to not to try to restore
> > unavailable profiles:
> > https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=d65974d8501052bafb03e65f5df954511e9949a2
> >
>
> No, this is in addition to increasing the timeout. To have things
> working I need to increase the timeout AND disable
> module-card-restore. Sorry for not being clear about it before.
>
> I will try the commit you pointed, but I don't think it will help
> since, if I'm following this right, the transport is already marked as
> available at this point (I need to double-check on this point though
> -- sorry, too many moving parts).
If you confirm that module-card-restore indeed has to be disabled even
with the increased timeout, then it would be very interesting to know
what effect module-card-restore has in the card initialization. To me
it seems that it should make no difference, because the a2dp profile is
the default anyway, and all the module does is to choose the initial
profile.
--
Tanu
https://liberapay.com/tanuk
https://www.patreon.com/tanuk
Hello Tanu!
On Thu, Jun 14, 2018 at 4:57 AM, Tanu Kaskinen <[email protected]> wrote:
> On Thu, 2018-06-14 at 00:05 -0700, Jo=C3=A3o Paulo Rechi Vita wrote:
>> Hello Luiz and Tanuk,
>>
>> I have been trying to understand a problem when trying to establish a
>> connection between my Sony MW-600 headset and my laptop (PulseAudio
>> 11.1 + a backport that gives higher priority to A2DP, BlueZ 5.47,
>> Linux 4.16.9). When the connection is initiated by the peripheral,
>> after it has already been paired on a previous connection, the
>> peripheral does not remain connected. When the computer initiates the
>> connection everything works fine. The problem seems to be that when we
>> create the card in PulseAudio is created before the AVDTP connection
>> reaches the OPEN state, the headset decides to abort the AVDTP
>> connection. In this case the card was created before the transport for
>> the card profile a2dp_sink is available and headset_head_unit was the
>> active profile, because WAIT_FOR_PROFILES_TIMEOUT_USEC was reached.
>>
>> Increasing the timeout to 60s makes the problem go away. The AVDTP
>> channel becomes connected about 50s after the HSP connection has
>> started and the card is created with a2dp_sink as the active profile.
>
> Maybe we could increase the timeout. A long timeout doesn't matter with
> properly working hardware, because the wait is terminated as soon as
> all advertised profiles have become connected.
>
Yes, I thought about it, but first I wanted to hear from Luiz (who
knows the audio specs inside out) if something in this flow might be
hitting the headset to terminate the connection, and if we could
improve it. I'm wondering iif the fact that creating the sink/source
right away, which leads to the SCO channel being established, is what
is making the headset decide it should disconnect A2DP. But I still
don't understand why the headset would also disconnect the RFCOMM link
(changing the transport in PulseAudio from idle to disconnected) after
we change the transport from playing to idle and release the SCO fd
when the sink/source get suspended (in my experience, this only
happens if A2DP is also not connected due to the failure mentioned
above).
>> I also had to disable module-card-restore, otherwise it tries to
>> switch to the saved a2dp_sink profile right when the card is created,
>> which also makes the device abort the AVDTP connection for some
>> reason.
>
> This is without increasing the timeout, right, so the problem is that
> module-card-restore is trying to restore a2dp_sink before it's
> available? module-card-restore has been fixed to not to try to restore
> unavailable profiles:
> https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=3Dd65974d85=
01052bafb03e65f5df954511e9949a2
>
No, this is in addition to increasing the timeout. To have things
working I need to increase the timeout AND disable
module-card-restore. Sorry for not being clear about it before.
I will try the commit you pointed, but I don't think it will help
since, if I'm following this right, the transport is already marked as
available at this point (I need to double-check on this point though
-- sorry, too many moving parts).
>> I have collected btmon dumps with a slightly modified version of btmon
>> to avoid flooding the logs with SCO data and uploaded to
>> https://gist.github.com/jprvita/a7482db4601d099788c4f820ea984ba9.
>>
>> Similar symptoms have been reported by our QA team with another Sony
>> model (MDR-XB950N1) and with a few Chinese headsets, but the MW-600 is
>> the only one I have access to where I can reproduce the problem
>> consistently (works fine on a Sennheiser MM-450 and a JBL Flip 2).
>>
>> Also, the involvement of module-card-restore in this problem made me
>> think whether it actually makes sense to restore the active profile
>> from the previous connection on bluetooth cards, since we already have
>> module-bluetooth-policy to automatically select the right profile
>> depending on the stream type.
>
> If module-bluetooth-policy is sufficient, then module-card-restore
> won't do anything anyway, because you never set the profile manually.
> If you ever set the profile manually, that's an indication that module-
> bluetooth-policy isn't always good enough.
>
I agree with the theory behind this argument, but in practice most
users will switch from HSP/HFP to A2DP after the first connection,
since it has higher priority until PulseAudio 11. So there will be an
entry for it in module-card-restore's DB, which I believe does not get
removed when the user "un-pairs" the headset and the computer.
>> Please let me know if you can help me understand what is making the
>> headset decide to disconnect AVDTP in these cases, and what is the
>> best way to fix this, or any ideas that may help investigating this
>> further.
>
> This is outside of my area of expertise. Could you just clarify one
> thing: did I understand correctly that if you increase the profile
> waiting timeout, then the headset doesn't disconnect AVDTP? So
> everything works perfectly, except that the connection takes a very
> long time?
>
If I increase the timeout AND disable module-bluetooth-restore,
everything works as expected except that it takes 50-60s for the audio
card to appear after turning the headset on.
Thanks for the help!
--
Jo=C3=A3o Paulo Rechi Vita
http://about.me/jprvita
On Thu, 2018-06-14 at 00:05 -0700, João Paulo Rechi Vita wrote:
> Hello Luiz and Tanuk,
>
> I have been trying to understand a problem when trying to establish a
> connection between my Sony MW-600 headset and my laptop (PulseAudio
> 11.1 + a backport that gives higher priority to A2DP, BlueZ 5.47,
> Linux 4.16.9). When the connection is initiated by the peripheral,
> after it has already been paired on a previous connection, the
> peripheral does not remain connected. When the computer initiates the
> connection everything works fine. The problem seems to be that when we
> create the card in PulseAudio is created before the AVDTP connection
> reaches the OPEN state, the headset decides to abort the AVDTP
> connection. In this case the card was created before the transport for
> the card profile a2dp_sink is available and headset_head_unit was the
> active profile, because WAIT_FOR_PROFILES_TIMEOUT_USEC was reached.
>
> Increasing the timeout to 60s makes the problem go away. The AVDTP
> channel becomes connected about 50s after the HSP connection has
> started and the card is created with a2dp_sink as the active profile.
Maybe we could increase the timeout. A long timeout doesn't matter with
properly working hardware, because the wait is terminated as soon as
all advertised profiles have become connected.
> I also had to disable module-card-restore, otherwise it tries to
> switch to the saved a2dp_sink profile right when the card is created,
> which also makes the device abort the AVDTP connection for some
> reason.
This is without increasing the timeout, right, so the problem is that
module-card-restore is trying to restore a2dp_sink before it's
available? module-card-restore has been fixed to not to try to restore
unavailable profiles:
https://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=d65974d8501052bafb03e65f5df954511e9949a2
> I have collected btmon dumps with a slightly modified version of btmon
> to avoid flooding the logs with SCO data and uploaded to
> https://gist.github.com/jprvita/a7482db4601d099788c4f820ea984ba9.
>
> Similar symptoms have been reported by our QA team with another Sony
> model (MDR-XB950N1) and with a few Chinese headsets, but the MW-600 is
> the only one I have access to where I can reproduce the problem
> consistently (works fine on a Sennheiser MM-450 and a JBL Flip 2).
>
> Also, the involvement of module-card-restore in this problem made me
> think whether it actually makes sense to restore the active profile
> from the previous connection on bluetooth cards, since we already have
> module-bluetooth-policy to automatically select the right profile
> depending on the stream type.
If module-bluetooth-policy is sufficient, then module-card-restore
won't do anything anyway, because you never set the profile manually.
If you ever set the profile manually, that's an indication that module-
bluetooth-policy isn't always good enough.
> Please let me know if you can help me understand what is making the
> headset decide to disconnect AVDTP in these cases, and what is the
> best way to fix this, or any ideas that may help investigating this
> further.
This is outside of my area of expertise. Could you just clarify one
thing: did I understand correctly that if you increase the profile
waiting timeout, then the headset doesn't disconnect AVDTP? So
everything works perfectly, except that the connection takes a very
long time?
--
Tanu
https://liberapay.com/tanuk
https://www.patreon.com/tanuk