2020-04-06 15:20:09

by James Belchamber

[permalink] [raw]
Subject: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

When using my Sony WH-H900N headphones and switching from A2DP to
HSP/HFP the following error appears in journalctl:

( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
Function not implemented

And using btmon I can see the HCI command comes back with a failure
(full log attached):

< HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
Handle: 67
Transmit bandwidth: 8000
Receive bandwidth: 8000
Max latency: 10
Setting: 0x0060
Input Coding: Linear
Input Data Format: 2's complement
Input Sample Size: 16-bit
# of bits padding at MSB: 0
Air Coding Format: CVSD
Retransmission effort: Optimize for power consumption (0x01)
Packet type: 0x0380
3-EV3 may not be used
2-EV5 may not be used
3-EV5 may not be used
> HCI Event: Command Status (0x0f) plen 4
Setup Synchronous Connection (0x01|0x0028) ncmd 1
Status: Success (0x00)
> HCI Event: Max Slots Change (0x1b) plen 3
Handle: 67
Max slots: 1
> HCI Event: Synchronous Connect Complete (0x2c) plen 17
Status: Unspecified Error (0x1f)
Handle: 67
Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
Link type: eSCO (0x02)
Transmission interval: 0x00
Retransmission window: 0x00
RX packet length: 0
TX packet length: 0
Air mode: u-law log (0x00)

This works on ChromeOS, which also uses a (modified) BlueZ stack -
though I can't work out why :)


Attachments:
hci_events.log (9.64 kB)

2020-04-22 18:25:10

by James Belchamber

[permalink] [raw]
Subject: Re: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

Just bumping this for visibility, still an issue with the latest kernel.

Happy to test anything thrown my way.

On Mon, 6 Apr 2020 at 16:19, James Belchamber <[email protected]> wrote:
>
> When using my Sony WH-H900N headphones and switching from A2DP to
> HSP/HFP the following error appears in journalctl:
>
> ( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
> transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
> ( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
> ( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
> Function not implemented
>
> And using btmon I can see the HCI command comes back with a failure
> (full log attached):
>
> < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
> Handle: 67
> Transmit bandwidth: 8000
> Receive bandwidth: 8000
> Max latency: 10
> Setting: 0x0060
> Input Coding: Linear
> Input Data Format: 2's complement
> Input Sample Size: 16-bit
> # of bits padding at MSB: 0
> Air Coding Format: CVSD
> Retransmission effort: Optimize for power consumption (0x01)
> Packet type: 0x0380
> 3-EV3 may not be used
> 2-EV5 may not be used
> 3-EV5 may not be used
> > HCI Event: Command Status (0x0f) plen 4
> Setup Synchronous Connection (0x01|0x0028) ncmd 1
> Status: Success (0x00)
> > HCI Event: Max Slots Change (0x1b) plen 3
> Handle: 67
> Max slots: 1
> > HCI Event: Synchronous Connect Complete (0x2c) plen 17
> Status: Unspecified Error (0x1f)
> Handle: 67
> Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
> Link type: eSCO (0x02)
> Transmission interval: 0x00
> Retransmission window: 0x00
> RX packet length: 0
> TX packet length: 0
> Air mode: u-law log (0x00)
>
> This works on ChromeOS, which also uses a (modified) BlueZ stack -
> though I can't work out why :)

2020-04-22 22:35:45

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

Hi James,

On Wed, Apr 22, 2020 at 11:27 AM James Belchamber <[email protected]> wrote:
>
> Just bumping this for visibility, still an issue with the latest kernel.
>
> Happy to test anything thrown my way.
>
> On Mon, 6 Apr 2020 at 16:19, James Belchamber <[email protected]> wrote:
> >
> > When using my Sony WH-H900N headphones and switching from A2DP to
> > HSP/HFP the following error appears in journalctl:
> >
> > ( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
> > transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
> > ( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
> > ( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
> > Function not implemented
> >
> > And using btmon I can see the HCI command comes back with a failure
> > (full log attached):
> >
> > < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
> > Handle: 67
> > Transmit bandwidth: 8000
> > Receive bandwidth: 8000
> > Max latency: 10
> > Setting: 0x0060
> > Input Coding: Linear
> > Input Data Format: 2's complement
> > Input Sample Size: 16-bit
> > # of bits padding at MSB: 0
> > Air Coding Format: CVSD
> > Retransmission effort: Optimize for power consumption (0x01)
> > Packet type: 0x0380
> > 3-EV3 may not be used
> > 2-EV5 may not be used
> > 3-EV5 may not be used
> > > HCI Event: Command Status (0x0f) plen 4
> > Setup Synchronous Connection (0x01|0x0028) ncmd 1
> > Status: Success (0x00)
> > > HCI Event: Max Slots Change (0x1b) plen 3
> > Handle: 67
> > Max slots: 1
> > > HCI Event: Synchronous Connect Complete (0x2c) plen 17
> > Status: Unspecified Error (0x1f)
> > Handle: 67
> > Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
> > Link type: eSCO (0x02)
> > Transmission interval: 0x00
> > Retransmission window: 0x00
> > RX packet length: 0
> > TX packet length: 0
> > Air mode: u-law log (0x00)
> >
> > This works on ChromeOS, which also uses a (modified) BlueZ stack -
> > though I can't work out why :)

It doesn't look like it is a host problem and Ive never seem this
error before, have you tried with the same controller on Chrome OS? It
may be worth trying to capture the logs in Chrome OS so we can compare
if there is something different in the command parameters, but it
could as well be that Chrome uses HFP instead of HSP as PulseAudio
does and the headset is sensitive to that.

--
Luiz Augusto von Dentz

2020-04-23 11:09:20

by James Belchamber

[permalink] [raw]
Subject: Re: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

Only difference in the btmon output is the handle (256 instead of 67)
- otherwise it all looks the same and it connects first time.

What logs are useful? I have the Chromebook in developer mode and so I
can capture whatever you want (hopefully!)

On Wed, 22 Apr 2020 at 23:32, Luiz Augusto von Dentz
<[email protected]> wrote:
>
> Hi James,
>
> On Wed, Apr 22, 2020 at 11:27 AM James Belchamber <[email protected]> wrote:
> >
> > Just bumping this for visibility, still an issue with the latest kernel.
> >
> > Happy to test anything thrown my way.
> >
> > On Mon, 6 Apr 2020 at 16:19, James Belchamber <[email protected]> wrote:
> > >
> > > When using my Sony WH-H900N headphones and switching from A2DP to
> > > HSP/HFP the following error appears in journalctl:
> > >
> > > ( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
> > > transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
> > > ( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
> > > ( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
> > > Function not implemented
> > >
> > > And using btmon I can see the HCI command comes back with a failure
> > > (full log attached):
> > >
> > > < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
> > > Handle: 67
> > > Transmit bandwidth: 8000
> > > Receive bandwidth: 8000
> > > Max latency: 10
> > > Setting: 0x0060
> > > Input Coding: Linear
> > > Input Data Format: 2's complement
> > > Input Sample Size: 16-bit
> > > # of bits padding at MSB: 0
> > > Air Coding Format: CVSD
> > > Retransmission effort: Optimize for power consumption (0x01)
> > > Packet type: 0x0380
> > > 3-EV3 may not be used
> > > 2-EV5 may not be used
> > > 3-EV5 may not be used
> > > > HCI Event: Command Status (0x0f) plen 4
> > > Setup Synchronous Connection (0x01|0x0028) ncmd 1
> > > Status: Success (0x00)
> > > > HCI Event: Max Slots Change (0x1b) plen 3
> > > Handle: 67
> > > Max slots: 1
> > > > HCI Event: Synchronous Connect Complete (0x2c) plen 17
> > > Status: Unspecified Error (0x1f)
> > > Handle: 67
> > > Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
> > > Link type: eSCO (0x02)
> > > Transmission interval: 0x00
> > > Retransmission window: 0x00
> > > RX packet length: 0
> > > TX packet length: 0
> > > Air mode: u-law log (0x00)
> > >
> > > This works on ChromeOS, which also uses a (modified) BlueZ stack -
> > > though I can't work out why :)
>
> It doesn't look like it is a host problem and Ive never seem this
> error before, have you tried with the same controller on Chrome OS? It
> may be worth trying to capture the logs in Chrome OS so we can compare
> if there is something different in the command parameters, but it
> could as well be that Chrome uses HFP instead of HSP as PulseAudio
> does and the headset is sensitive to that.
>
> --
> Luiz Augusto von Dentz

2020-04-23 16:44:55

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

Hi James,

On Thu, Apr 23, 2020 at 4:06 AM James Belchamber <[email protected]> wrote:
>
> Only difference in the btmon output is the handle (256 instead of 67)
> - otherwise it all looks the same and it connects first time.
>
> What logs are useful? I have the Chromebook in developer mode and so I
> can capture whatever you want (hopefully!)

Then I think this is because PulseAudio is using HSP not HFP, the
headset might be expecting a call to exist, or something similar on
HSP, in order to accept the SCO connection so the state machine is not
ready, have a look if Chrome OS is sending any AT command before
trying to connect SCO, or just past the btmon logs in some
pastebing/gist.github.com so we can analyze what is going on.

> On Wed, 22 Apr 2020 at 23:32, Luiz Augusto von Dentz
> <[email protected]> wrote:
> >
> > Hi James,
> >
> > On Wed, Apr 22, 2020 at 11:27 AM James Belchamber <[email protected]> wrote:
> > >
> > > Just bumping this for visibility, still an issue with the latest kernel.
> > >
> > > Happy to test anything thrown my way.
> > >
> > > On Mon, 6 Apr 2020 at 16:19, James Belchamber <[email protected]> wrote:
> > > >
> > > > When using my Sony WH-H900N headphones and switching from A2DP to
> > > > HSP/HFP the following error appears in journalctl:
> > > >
> > > > ( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
> > > > transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
> > > > ( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
> > > > ( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
> > > > Function not implemented
> > > >
> > > > And using btmon I can see the HCI command comes back with a failure
> > > > (full log attached):
> > > >
> > > > < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
> > > > Handle: 67
> > > > Transmit bandwidth: 8000
> > > > Receive bandwidth: 8000
> > > > Max latency: 10
> > > > Setting: 0x0060
> > > > Input Coding: Linear
> > > > Input Data Format: 2's complement
> > > > Input Sample Size: 16-bit
> > > > # of bits padding at MSB: 0
> > > > Air Coding Format: CVSD
> > > > Retransmission effort: Optimize for power consumption (0x01)
> > > > Packet type: 0x0380
> > > > 3-EV3 may not be used
> > > > 2-EV5 may not be used
> > > > 3-EV5 may not be used
> > > > > HCI Event: Command Status (0x0f) plen 4
> > > > Setup Synchronous Connection (0x01|0x0028) ncmd 1
> > > > Status: Success (0x00)
> > > > > HCI Event: Max Slots Change (0x1b) plen 3
> > > > Handle: 67
> > > > Max slots: 1
> > > > > HCI Event: Synchronous Connect Complete (0x2c) plen 17
> > > > Status: Unspecified Error (0x1f)
> > > > Handle: 67
> > > > Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
> > > > Link type: eSCO (0x02)
> > > > Transmission interval: 0x00
> > > > Retransmission window: 0x00
> > > > RX packet length: 0
> > > > TX packet length: 0
> > > > Air mode: u-law log (0x00)
> > > >
> > > > This works on ChromeOS, which also uses a (modified) BlueZ stack -
> > > > though I can't work out why :)
> >
> > It doesn't look like it is a host problem and Ive never seem this
> > error before, have you tried with the same controller on Chrome OS? It
> > may be worth trying to capture the logs in Chrome OS so we can compare
> > if there is something different in the command parameters, but it
> > could as well be that Chrome uses HFP instead of HSP as PulseAudio
> > does and the headset is sensitive to that.
> >
> > --
> > Luiz Augusto von Dentz



--
Luiz Augusto von Dentz

2020-04-23 20:19:14

by James Belchamber

[permalink] [raw]
Subject: Re: Setup Synchronous Connection fails when switching Sony WH-H900N headset to HSP

I got btmon piped to a file on ChromeOS, turned on my headphones,
opened an app that required a mic, closed the app, then disconnected
again.

Paste is here: https://paste.c-net.org/BaldwinMarital

I can't see any AT commands but btmon spits out far too much for me to
be able to parse it without knowing what I'm looking for.

On Thu, 23 Apr 2020 at 17:43, Luiz Augusto von Dentz
<[email protected]> wrote:
>
> Hi James,
>
> On Thu, Apr 23, 2020 at 4:06 AM James Belchamber <[email protected]> wrote:
> >
> > Only difference in the btmon output is the handle (256 instead of 67)
> > - otherwise it all looks the same and it connects first time.
> >
> > What logs are useful? I have the Chromebook in developer mode and so I
> > can capture whatever you want (hopefully!)
>
> Then I think this is because PulseAudio is using HSP not HFP, the
> headset might be expecting a call to exist, or something similar on
> HSP, in order to accept the SCO connection so the state machine is not
> ready, have a look if Chrome OS is sending any AT command before
> trying to connect SCO, or just past the btmon logs in some
> pastebing/gist.github.com so we can analyze what is going on.
>
> > On Wed, 22 Apr 2020 at 23:32, Luiz Augusto von Dentz
> > <[email protected]> wrote:
> > >
> > > Hi James,
> > >
> > > On Wed, Apr 22, 2020 at 11:27 AM James Belchamber <[email protected]> wrote:
> > > >
> > > > Just bumping this for visibility, still an issue with the latest kernel.
> > > >
> > > > Happy to test anything thrown my way.
> > > >
> > > > On Mon, 6 Apr 2020 at 16:19, James Belchamber <[email protected]> wrote:
> > > > >
> > > > > When using my Sony WH-H900N headphones and switching from A2DP to
> > > > > HSP/HFP the following error appears in journalctl:
> > > > >
> > > > > ( 60.063| 0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring
> > > > > transport /org/bluez/hci0/dev_04_5D_4B_E9_C9_90/fd34
> > > > > ( 60.063| 0.000) I: [pulseaudio] backend-native.c: doing connect
> > > > > ( 60.174| 0.111) E: [pulseaudio] backend-native.c: connect():
> > > > > Function not implemented
> > > > >
> > > > > And using btmon I can see the HCI command comes back with a failure
> > > > > (full log attached):
> > > > >
> > > > > < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
> > > > > Handle: 67
> > > > > Transmit bandwidth: 8000
> > > > > Receive bandwidth: 8000
> > > > > Max latency: 10
> > > > > Setting: 0x0060
> > > > > Input Coding: Linear
> > > > > Input Data Format: 2's complement
> > > > > Input Sample Size: 16-bit
> > > > > # of bits padding at MSB: 0
> > > > > Air Coding Format: CVSD
> > > > > Retransmission effort: Optimize for power consumption (0x01)
> > > > > Packet type: 0x0380
> > > > > 3-EV3 may not be used
> > > > > 2-EV5 may not be used
> > > > > 3-EV5 may not be used
> > > > > > HCI Event: Command Status (0x0f) plen 4
> > > > > Setup Synchronous Connection (0x01|0x0028) ncmd 1
> > > > > Status: Success (0x00)
> > > > > > HCI Event: Max Slots Change (0x1b) plen 3
> > > > > Handle: 67
> > > > > Max slots: 1
> > > > > > HCI Event: Synchronous Connect Complete (0x2c) plen 17
> > > > > Status: Unspecified Error (0x1f)
> > > > > Handle: 67
> > > > > Address: 04:5D:4B:E9:C9:90 (Sony Corporation)
> > > > > Link type: eSCO (0x02)
> > > > > Transmission interval: 0x00
> > > > > Retransmission window: 0x00
> > > > > RX packet length: 0
> > > > > TX packet length: 0
> > > > > Air mode: u-law log (0x00)
> > > > >
> > > > > This works on ChromeOS, which also uses a (modified) BlueZ stack -
> > > > > though I can't work out why :)
> > >
> > > It doesn't look like it is a host problem and Ive never seem this
> > > error before, have you tried with the same controller on Chrome OS? It
> > > may be worth trying to capture the logs in Chrome OS so we can compare
> > > if there is something different in the command parameters, but it
> > > could as well be that Chrome uses HFP instead of HSP as PulseAudio
> > > does and the headset is sensitive to that.
> > >
> > > --
> > > Luiz Augusto von Dentz
>
>
>
> --
> Luiz Augusto von Dentz