Bluetooth: silence a dmesg error message in hci_request.c

  On kernel 6.1-rcX, I have been getting the following dmesg error message
on every boot, resume from suspend and rfkill unblock of the Bluetooth
device:

	Bluetooth: hci0: HCI_REQ-0xfcf0

After some investigation, it turned out to be caused by
commit dd50a864ffae ("Bluetooth: Delete unreferenced hci_request code")
which modified hci_req_add() in net/bluetooth/hci_request.c to always
print an error message when it is executed. In my case, the function was
executed by msft_set_filter_enable() in net/bluetooth/msft.c, which
provides support for Microsoft vendor opcodes.

As explained by Brian Gix, "the error gets logged because it is using a
deprecated (but still working) mechanism to issue HCI opcodes" [1]. So
this is just a debugging tool to show that a deprecated function is
executed. As such, it should not be included in the mainline kernel.
See for example
commit 771c035372a0 ("deprecate the '__deprecated' attribute warnings entirely and for good")
Additionally, this error message is cryptic and the user is not able to
do anything about it.

[1]
Link: https://lore.kernel.org/lkml/beb8dcdc3aee4c5c833aa382f35995f17e7961a1.camel@intel.com/

Fixes: dd50a864ffae ("Bluetooth: Delete unreferenced hci_request code")
Signed-off-by: Mateusz Jończyk <mat.jonczyk@o2.pl>
Cc: Brian Gix <brian.gix@intel.com>
Cc: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Cc: Marcel Holtmann <marcel@holtmann.org>
Cc: Johan Hedberg <johan.hedberg@gmail.com>
---
 net/bluetooth/hci_request.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)


base-commit: 094226ad94f471a9f19e8f8e7140a09c2625abaa
  

Hello:

This patch was applied to bluetooth/bluetooth-next.git (master)
by Luiz Augusto von Dentz <luiz.von.dentz@intel.com>:

On Wed, 16 Nov 2022 21:28:56 +0100 you wrote:
> On kernel 6.1-rcX, I have been getting the following dmesg error message
> on every boot, resume from suspend and rfkill unblock of the Bluetooth
> device:
> 
> 	Bluetooth: hci0: HCI_REQ-0xfcf0
> 
> After some investigation, it turned out to be caused by
> commit dd50a864ffae ("Bluetooth: Delete unreferenced hci_request code")
> which modified hci_req_add() in net/bluetooth/hci_request.c to always
> print an error message when it is executed. In my case, the function was
> executed by msft_set_filter_enable() in net/bluetooth/msft.c, which
> provides support for Microsoft vendor opcodes.
> 
> [...]

Here is the summary with links:
  - Bluetooth: silence a dmesg error message in hci_request.c
    https://git.kernel.org/bluetooth/bluetooth-next/c/c3fd63f7fe5a

You are awesome, thank you!
  

Hi Mateusz,

On Wed, 2022-11-16 at 21:28 +0100, Mateusz Jończyk wrote:
> On kernel 6.1-rcX, I have been getting the following dmesg error
> message
> on every boot, resume from suspend and rfkill unblock of the
> Bluetooth
> device:
> 
>         Bluetooth: hci0: HCI_REQ-0xfcf0
> 

This has a patch that fixes the usage of the deprecated HCI_REQ
mechanism rather than hiding the fact it is being called, as in this
case.

I am still waiting for someone to give me a "Tested-By:" tag to patch:

[PATCH 1/1] Bluetooth: Convert MSFT filter HCI cmd to hci_sync

Which will also stop the dmesg error. If you could try that patch, and
resend it to the list with a Tested-By tag, it can be applied.

We still want to be allerted to deprecated usage situations.

> After some investigation, it turned out to be caused by
> commit dd50a864ffae ("Bluetooth: Delete unreferenced hci_request
> code")
> which modified hci_req_add() in net/bluetooth/hci_request.c to always
> print an error message when it is executed. In my case, the function
> was
> executed by msft_set_filter_enable() in net/bluetooth/msft.c, which
> provides support for Microsoft vendor opcodes.
> 
> As explained by Brian Gix, "the error gets logged because it is using
> a
> deprecated (but still working) mechanism to issue HCI opcodes" [1].
> So
> this is just a debugging tool to show that a deprecated function is
> executed. As such, it should not be included in the mainline kernel.
> See for example
> commit 771c035372a0 ("deprecate the '__deprecated' attribute warnings
> entirely and for good")
> Additionally, this error message is cryptic and the user is not able
> to
> do anything about it.
> 
> [1]
> Link:
> https://lore.kernel.org/lkml/beb8dcdc3aee4c5c833aa382f35995f17e7961a1.camel@intel.com/
> 
> Fixes: dd50a864ffae ("Bluetooth: Delete unreferenced hci_request
> code")
> Signed-off-by: Mateusz Jończyk <mat.jonczyk@o2.pl>
> Cc: Brian Gix <brian.gix@intel.com>
> Cc: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
> Cc: Marcel Holtmann <marcel@holtmann.org>
> Cc: Johan Hedberg <johan.hedberg@gmail.com>
> ---
>  net/bluetooth/hci_request.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/net/bluetooth/hci_request.c
> b/net/bluetooth/hci_request.c
> index 5a0296a4352e..f7e006a36382 100644
> --- a/net/bluetooth/hci_request.c
> +++ b/net/bluetooth/hci_request.c
> @@ -269,7 +269,7 @@ void hci_req_add_ev(struct hci_request *req, u16
> opcode, u32 plen,
>  void hci_req_add(struct hci_request *req, u16 opcode, u32 plen,
>                  const void *param)
>  {
> -       bt_dev_err(req->hdev, "HCI_REQ-0x%4.4x", opcode);
> +       bt_dev_dbg(req->hdev, "HCI_REQ-0x%4.4x", opcode);
>         hci_req_add_ev(req, opcode, plen, param, 0);
>  }
>  
> 
> base-commit: 094226ad94f471a9f19e8f8e7140a09c2625abaa

Regards,
--Brian Gix
  

W dniu 17.11.2022 o 21:34, Gix, Brian pisze:
> Hi Mateusz,
>
> On Wed, 2022-11-16 at 21:28 +0100, Mateusz Jończyk wrote:
>> On kernel 6.1-rcX, I have been getting the following dmesg error
>> message
>> on every boot, resume from suspend and rfkill unblock of the
>> Bluetooth
>> device:
>>
>>         Bluetooth: hci0: HCI_REQ-0xfcf0
>>
> This has a patch that fixes the usage of the deprecated HCI_REQ
> mechanism rather than hiding the fact it is being called, as in this
> case.
>
> I am still waiting for someone to give me a "Tested-By:" tag to patch:
>
> [PATCH 1/1] Bluetooth: Convert MSFT filter HCI cmd to hci_sync
>
> Which will also stop the dmesg error. If you could try that patch, and
> resend it to the list with a Tested-By tag, it can be applied.

Hello,

I did not receive this patch, as I was not on the CC list; I was not
aware of it. I will test it shortly.

Any guidelines how I should test this functionality? I have a Sony Xperia 10 i4113
mobile phone with LineageOS 19.1 / Android 12L, which according to the spec supports
Bluetooth 5.0. Quick Google search tells me that I should do things like 

        hcitool lescan

to discover the phone, then use gatttool to list the services, etc.

Greetings,

Mateusz
  

Hi  Mateusz,

On Thu, 2022-11-17 at 22:27 +0100, Mateusz Jończyk wrote:
> W dniu 17.11.2022 o 21:34, Gix, Brian pisze:
> > On Wed, 2022-11-16 at 21:28 +0100, Mateusz Jończyk wrote:
> > > On kernel 6.1-rcX, I have been getting the following dmesg error
> > > message
> > > on every boot, resume from suspend and rfkill unblock of the
> > > Bluetooth
> > > device:
> > > 
> > >         Bluetooth: hci0: HCI_REQ-0xfcf0
> > > 
> > This has a patch that fixes the usage of the deprecated HCI_REQ
> > mechanism rather than hiding the fact it is being called, as in
> > this
> > case.
> > 
> > I am still waiting for someone to give me a "Tested-By:" tag to
> > patch:
> > 
> > [PATCH 1/1] Bluetooth: Convert MSFT filter HCI cmd to hci_sync
> > 
> > Which will also stop the dmesg error. If you could try that patch,
> > and
> > resend it to the list with a Tested-By tag, it can be applied.
> 
> Hello,
> 
> I did not receive this patch, as I was not on the CC list; I was not
> aware of it. I will test it shortly.
> 
> Any guidelines how I should test this functionality? I have a Sony
> Xperia 10 i4113
> mobile phone with LineageOS 19.1 / Android 12L, which according to
> the spec supports
> Bluetooth 5.0. Quick Google search tells me that I should do things
> like 
> 
>         hcitool lescan
> 

Whatever you were running that produced the

"Bluetooth: hci0: HCI_REQ-0xfcf0"

error in the dmesg log should be sufficient to determine that the error
log is no longer happening. The HCI call is necessary on some
platforms, so the absense of other negative behavior should be
sufficient to verify that the call is still being made.  The code flow
itself has not changed, and new coding enforces the HCI command
sequence, so that it is more deterministric than it was with
hci_request. The hci_request mechanism was an asyncronous request.

> to discover the phone, then use gatttool to list the services, etc.
> 
> Greetings,
> 
> Mateusz
>
  

Hi,

On Thu, Nov 17, 2022 at 1:45 PM Gix, Brian <brian.gix@intel.com> wrote:
>
> Hi  Mateusz,
>
> On Thu, 2022-11-17 at 22:27 +0100, Mateusz Jończyk wrote:
> > W dniu 17.11.2022 o 21:34, Gix, Brian pisze:
> > > On Wed, 2022-11-16 at 21:28 +0100, Mateusz Jończyk wrote:
> > > > On kernel 6.1-rcX, I have been getting the following dmesg error
> > > > message
> > > > on every boot, resume from suspend and rfkill unblock of the
> > > > Bluetooth
> > > > device:
> > > >
> > > >         Bluetooth: hci0: HCI_REQ-0xfcf0
> > > >
> > > This has a patch that fixes the usage of the deprecated HCI_REQ
> > > mechanism rather than hiding the fact it is being called, as in
> > > this
> > > case.
> > >
> > > I am still waiting for someone to give me a "Tested-By:" tag to
> > > patch:
> > >
> > > [PATCH 1/1] Bluetooth: Convert MSFT filter HCI cmd to hci_sync
> > >
> > > Which will also stop the dmesg error. If you could try that patch,
> > > and
> > > resend it to the list with a Tested-By tag, it can be applied.
> >
> > Hello,
> >
> > I did not receive this patch, as I was not on the CC list; I was not
> > aware of it. I will test it shortly.

You can find the patch here:

https://patchwork.kernel.org/project/bluetooth/patch/20221102175927.401091-2-brian.gix@intel.com/

> >
> > Any guidelines how I should test this functionality? I have a Sony
> > Xperia 10 i4113
> > mobile phone with LineageOS 19.1 / Android 12L, which according to
> > the spec supports
> > Bluetooth 5.0. Quick Google search tells me that I should do things
> > like
> >
> >         hcitool lescan
> >
>
> Whatever you were running that produced the
>
> "Bluetooth: hci0: HCI_REQ-0xfcf0"
>
> error in the dmesg log should be sufficient to determine that the error
> log is no longer happening. The HCI call is necessary on some
> platforms, so the absense of other negative behavior should be
> sufficient to verify that the call is still being made.  The code flow
> itself has not changed, and new coding enforces the HCI command
> sequence, so that it is more deterministric than it was with
> hci_request. The hci_request mechanism was an asyncronous request.
>
> > to discover the phone, then use gatttool to list the services, etc.
> >
> > Greetings,
> >
> > Mateusz
> >
>
  

W dniu 16.11.2022 o 22:40, patchwork-bot+bluetooth@kernel.org pisze:
> Hello:
>
> This patch was applied to bluetooth/bluetooth-next.git (master)
> by Luiz Augusto von Dentz <luiz.von.dentz@intel.com>:
>
> On Wed, 16 Nov 2022 21:28:56 +0100 you wrote:
>> On kernel 6.1-rcX, I have been getting the following dmesg error message
>> on every boot, resume from suspend and rfkill unblock of the Bluetooth
>> device:
>>
>> 	Bluetooth: hci0: HCI_REQ-0xfcf0
>>
>> After some investigation, it turned out to be caused by
>> commit dd50a864ffae ("Bluetooth: Delete unreferenced hci_request code")
>> which modified hci_req_add() in net/bluetooth/hci_request.c to always
>> print an error message when it is executed. In my case, the function was
>> executed by msft_set_filter_enable() in net/bluetooth/msft.c, which
>> provides support for Microsoft vendor opcodes.
>>
>> [...]
> Here is the summary with links:
>   - Bluetooth: silence a dmesg error message in hci_request.c
>     https://git.kernel.org/bluetooth/bluetooth-next/c/c3fd63f7fe5a
>
> You are awesome, thank you!

Hello,

Thank you. I would like to ask: is this patch going to be merged for kernel 6.1?

The error message that this patch silences will no doubt confuse some users
if it will be released in Linux 6.1.0.

Greetings,

Mateusz