[PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Mateusz Jończyk]

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(-)

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
-- 
2.25.1

RE: Bluetooth: silence a dmesg error message in hci_request.c

[bluez.test.bot]

[-- Attachment #1: Type: text/plain, Size: 2616 bytes --]

This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=696145

---Test result---

Test Summary:
CheckPatch                    FAIL      1.33 seconds
GitLint                       FAIL      0.82 seconds
SubjectPrefix                 PASS      0.62 seconds
BuildKernel                   PASS      34.06 seconds
BuildKernel32                 PASS      30.56 seconds
Incremental Build with patchesPASS      45.40 seconds
TestRunner: Setup             PASS      510.92 seconds
TestRunner: l2cap-tester      PASS      17.45 seconds
TestRunner: iso-tester        PASS      16.50 seconds
TestRunner: bnep-tester       PASS      6.56 seconds
TestRunner: mgmt-tester       PASS      106.15 seconds
TestRunner: rfcomm-tester     PASS      10.48 seconds
TestRunner: sco-tester        PASS      9.87 seconds
TestRunner: ioctl-tester      PASS      11.07 seconds
TestRunner: mesh-tester       PASS      7.99 seconds
TestRunner: smp-tester        PASS      9.72 seconds
TestRunner: userchan-tester   PASS      6.74 seconds

Details
##############################
Test: CheckPatch - FAIL - 1.33 seconds
Run checkpatch.pl script with rule in .checkpatch.conf
Bluetooth: silence a dmesg error message in hci_request.c\WARNING:COMMIT_LOG_LONG_LINE: Possible unwrapped commit description (prefer a maximum 75 chars per line)
#78: 
commit 771c035372a0 ("deprecate the '__deprecated' attribute warnings entirely and for good")

total: 0 errors, 1 warnings, 0 checks, 8 lines checked

NOTE: For some of the reported defects, checkpatch may be able to
      mechanically convert to the typical style using --fix or --fix-inplace.

/github/workspace/src/13045717.patch has style problems, please review.

NOTE: Ignored message types: UNKNOWN_COMMIT_ID

NOTE: If any of the errors are false positives, please report
      them to the maintainer, see CHECKPATCH in MAINTAINERS.


##############################
Test: GitLint - FAIL - 0.82 seconds
Run gitlint with rule in .gitlint
Bluetooth: silence a dmesg error message in hci_request.c
7: B3 Line contains hard tab characters (\t): "	Bluetooth: hci0: HCI_REQ-0xfcf0"
21: B1 Line exceeds max length (93>80): "commit 771c035372a0 ("deprecate the '__deprecated' attribute warnings entirely and for good")"
26: B1 Line exceeds max length (92>80): "Link: https://lore.kernel.org/lkml/beb8dcdc3aee4c5c833aa382f35995f17e7961a1.camel@intel.com/"




---
Regards,
Linux Bluetooth

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[patchwork-bot+bluetooth]

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!
-- 
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Mateusz Jończyk]

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

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Gix, Brian]

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

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Mateusz Jończyk]

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

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Gix, Brian]

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
> 

Re: [PATCH] Bluetooth: silence a dmesg error message in hci_request.c

[Luiz Augusto von Dentz]

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
> >
>


-- 
Luiz Augusto von Dentz