"Bluetooth: hci0: HCI_REQ-0xfcf0" errors in dmesg

"Bluetooth: hci0: HCI_REQ-0xfcf0" errors in dmesg

[Mateusz Jończyk]

Hello,

On 6.1.0-rc3, I have been seeing this error message in dmesg:

        Bluetooth: hci0: HCI_REQ-0xfcf0

It is printed on every boot, resume from suspend and rfkill unblock of the Bluetooth device.
The device seems to be functioning normally though (but I have done limited testing only).

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 that function is executed.

I have added dump_stack() to hci_req_add() and got the following backtraces:

On boot:

[   18.487766] Bluetooth: hci0: RTL: fw version 0xab6b705c
[   18.548951] Bluetooth: hci0: HCI_REQ-0xfcf0
[   18.548961] CPU: 3 PID: 108 Comm: kworker/u9:0 Not tainted 6.1.0-rc3unif4-00001-gb33a0948e932 #86
[   18.548965] Hardware name: HP HP Laptop 17-by0xxx/84CA, BIOS F.66 03/29/2022
[   18.548968] Workqueue: hci0 hci_power_on [bluetooth]
[   18.549018] Call Trace:
[   18.549020]  <TASK>
[   18.549022]  dump_stack_lvl+0x38/0x4d
[   18.549030]  dump_stack+0x10/0x16
[   18.549035]  hci_req_add+0x47/0x70 [bluetooth]
[   18.549093]  msft_set_filter_enable+0x59/0x90 [bluetooth]
[   18.549147]  msft_do_open+0x131/0x220 [bluetooth]
[   18.549198]  hci_dev_open_sync+0x646/0xc20 [bluetooth]
[   18.549249]  hci_dev_do_open+0x2a/0x60 [bluetooth]
[   18.549282]  hci_power_on+0x53/0x210 [bluetooth]
[   18.549317]  process_one_work+0x21f/0x3f0
[   18.549323]  worker_thread+0x4a/0x3c0
[   18.549328]  ? process_one_work+0x3f0/0x3f0
[   18.549332]  kthread+0xff/0x130
[   18.549336]  ? kthread_complete_and_exit+0x20/0x20
[   18.549340]  ret_from_fork+0x22/0x30
[   18.549347]  </TASK>
[   21.165060] EXT4-fs (dm-7): mounted filesystem with ordered data mode. Quota mode: none.

on rfkill unblock:

[ 1671.040970] Bluetooth: hci0: HCI_REQ-0xfcf0
[ 1671.040992] CPU: 3 PID: 5006 Comm: kworker/u9:2 Not tainted 6.1.0-rc3unif4-00001-gb33a0948e932 #86
[ 1671.041005] Hardware name: HP HP Laptop 17-by0xxx/84CA, BIOS F.66 03/29/2022
[ 1671.041012] Workqueue: hci0 hci_cmd_sync_work [bluetooth]
[ 1671.041194] Call Trace:
[ 1671.041200]  <TASK>
[ 1671.041208]  dump_stack_lvl+0x38/0x4d
[ 1671.041227]  dump_stack+0x10/0x16
[ 1671.041241]  hci_req_add+0x47/0x70 [bluetooth]
[ 1671.041408]  msft_set_filter_enable+0x59/0x90 [bluetooth]
[ 1671.041579]  msft_do_open+0x131/0x220 [bluetooth]
[ 1671.041683]  hci_dev_open_sync+0x646/0xc20 [bluetooth]
[ 1671.041787]  hci_set_powered_sync+0xd4/0x240 [bluetooth]
[ 1671.041887]  set_powered_sync+0x20/0x60 [bluetooth]
[ 1671.041975]  hci_cmd_sync_work+0xa8/0x150 [bluetooth]
[ 1671.042079]  process_one_work+0x21f/0x3f0
[ 1671.042092]  worker_thread+0x4a/0x3c0
[ 1671.042102]  ? process_one_work+0x3f0/0x3f0
[ 1671.042111]  kthread+0xff/0x130
[ 1671.042119]  ? kthread_complete_and_exit+0x20/0x20
[ 1671.042128]  ret_from_fork+0x22/0x30
[ 1671.042142]  </TASK>

My hardware: HP laptop 17-by0001nw, device is a Realtek combo card:

"Realtek RTL8822BE 802.11 ac 2×2 WiFi + Bluetooth 4.2 Combo Adapter (MU-MIMO supported)"

I am ready to provide additional information and testing, if need be.

Greetings,

Mateusz Jończyk

Re: "Bluetooth: hci0: HCI_REQ-0xfcf0" errors in dmesg

[Luiz Augusto von Dentz]

Hi,

On Mon, Oct 31, 2022 at 1:15 PM Mateusz Jończyk <mat.jonczyk@o2.pl> wrote:
>
> Hello,
>
> On 6.1.0-rc3, I have been seeing this error message in dmesg:
>
>         Bluetooth: hci0: HCI_REQ-0xfcf0
>
> It is printed on every boot, resume from suspend and rfkill unblock of the Bluetooth device.
> The device seems to be functioning normally though (but I have done limited testing only).
>
> 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 that function is executed.
>
> I have added dump_stack() to hci_req_add() and got the following backtraces:
>
> On boot:
>
> [   18.487766] Bluetooth: hci0: RTL: fw version 0xab6b705c
> [   18.548951] Bluetooth: hci0: HCI_REQ-0xfcf0
> [   18.548961] CPU: 3 PID: 108 Comm: kworker/u9:0 Not tainted 6.1.0-rc3unif4-00001-gb33a0948e932 #86
> [   18.548965] Hardware name: HP HP Laptop 17-by0xxx/84CA, BIOS F.66 03/29/2022
> [   18.548968] Workqueue: hci0 hci_power_on [bluetooth]
> [   18.549018] Call Trace:
> [   18.549020]  <TASK>
> [   18.549022]  dump_stack_lvl+0x38/0x4d
> [   18.549030]  dump_stack+0x10/0x16
> [   18.549035]  hci_req_add+0x47/0x70 [bluetooth]
> [   18.549093]  msft_set_filter_enable+0x59/0x90 [bluetooth]
> [   18.549147]  msft_do_open+0x131/0x220 [bluetooth]
> [   18.549198]  hci_dev_open_sync+0x646/0xc20 [bluetooth]
> [   18.549249]  hci_dev_do_open+0x2a/0x60 [bluetooth]
> [   18.549282]  hci_power_on+0x53/0x210 [bluetooth]
> [   18.549317]  process_one_work+0x21f/0x3f0
> [   18.549323]  worker_thread+0x4a/0x3c0
> [   18.549328]  ? process_one_work+0x3f0/0x3f0
> [   18.549332]  kthread+0xff/0x130
> [   18.549336]  ? kthread_complete_and_exit+0x20/0x20
> [   18.549340]  ret_from_fork+0x22/0x30
> [   18.549347]  </TASK>
> [   21.165060] EXT4-fs (dm-7): mounted filesystem with ordered data mode. Quota mode: none.
>
> on rfkill unblock:
>
> [ 1671.040970] Bluetooth: hci0: HCI_REQ-0xfcf0
> [ 1671.040992] CPU: 3 PID: 5006 Comm: kworker/u9:2 Not tainted 6.1.0-rc3unif4-00001-gb33a0948e932 #86
> [ 1671.041005] Hardware name: HP HP Laptop 17-by0xxx/84CA, BIOS F.66 03/29/2022
> [ 1671.041012] Workqueue: hci0 hci_cmd_sync_work [bluetooth]
> [ 1671.041194] Call Trace:
> [ 1671.041200]  <TASK>
> [ 1671.041208]  dump_stack_lvl+0x38/0x4d
> [ 1671.041227]  dump_stack+0x10/0x16
> [ 1671.041241]  hci_req_add+0x47/0x70 [bluetooth]
> [ 1671.041408]  msft_set_filter_enable+0x59/0x90 [bluetooth]
> [ 1671.041579]  msft_do_open+0x131/0x220 [bluetooth]
> [ 1671.041683]  hci_dev_open_sync+0x646/0xc20 [bluetooth]
> [ 1671.041787]  hci_set_powered_sync+0xd4/0x240 [bluetooth]
> [ 1671.041887]  set_powered_sync+0x20/0x60 [bluetooth]
> [ 1671.041975]  hci_cmd_sync_work+0xa8/0x150 [bluetooth]
> [ 1671.042079]  process_one_work+0x21f/0x3f0
> [ 1671.042092]  worker_thread+0x4a/0x3c0
> [ 1671.042102]  ? process_one_work+0x3f0/0x3f0
> [ 1671.042111]  kthread+0xff/0x130
> [ 1671.042119]  ? kthread_complete_and_exit+0x20/0x20
> [ 1671.042128]  ret_from_fork+0x22/0x30
> [ 1671.042142]  </TASK>
>
> My hardware: HP laptop 17-by0001nw, device is a Realtek combo card:
>
> "Realtek RTL8822BE 802.11 ac 2×2 WiFi + Bluetooth 4.2 Combo Adapter (MU-MIMO supported)"
>
> I am ready to provide additional information and testing, if need be.

@Gix, Brian Can you give a look, we should probably convert the
msft_set_filter_enable to use the cmd_sync instead.

> Greetings,
>
> Mateusz Jończyk
>


-- 
Luiz Augusto von Dentz

Re: "Bluetooth: hci0: HCI_REQ-0xfcf0" errors in dmesg

[Gix, Brian]

On Mon, 2022-10-31 at 13:37 -0700, Luiz Augusto von Dentz wrote:
> On Mon, Oct 31, 2022 at 1:15 PM Mateusz Jończyk <mat.jonczyk@o2.pl>
> wrote:
> > 
> > On 6.1.0-rc3, I have been seeing this error message in dmesg:
> > 
> >         Bluetooth: hci0: HCI_REQ-0xfcf0
> > 
> > It is printed on every boot, resume from suspend and rfkill unblock
> > of the Bluetooth device.
> > The device seems to be functioning normally though (but I have done
> > limited testing only).
> > 
> > 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 that function is executed.
> > 
> > I have added dump_stack() to hci_req_add() and got the following
> > backtraces:
> > 
> > On boot:
> > 
> > [   18.487766] Bluetooth: hci0: RTL: fw version 0xab6b705c
> > [   18.548951] Bluetooth: hci0: HCI_REQ-0xfcf0
> > [   18.548961] CPU: 3 PID: 108 Comm: kworker/u9:0 Not tainted
> > 6.1.0-rc3unif4-00001-gb33a0948e932 #86
> > 
...
> > on rfkill unblock:
> > 
> > [ 1671.040970] Bluetooth: hci0: HCI_REQ-0xfcf0
> > [ 1671.040992] CPU: 3 PID: 5006 Comm: kworker/u9:2 Not tainted
... 
> > My hardware: HP laptop 17-by0001nw, device is a Realtek combo card:
> > 
> > "Realtek RTL8822BE 802.11 ac 2×2 WiFi + Bluetooth 4.2 Combo Adapter
> > (MU-MIMO supported)"
> > 
> > I am ready to provide additional information and testing, if need
> > be.
> 
> @Gix, Brian Can you give a look, we should probably convert the
> msft_set_filter_enable to use the cmd_sync instead.

This, I suspect, will be an ongoing issue, particularily with Vender
Opcodes, which we don't have much direct visability and testing
capabilities.  The error gets logged because it is using a deprecated
(but still working) mechanism to issue HCI opcodes.

If I can get the source code path of the call as it is being
contructed, I can try making you a patch Mateusz...  But you will
probably need to do the testing/verification for me.


> 
> > Greetings,
> > 
> > Mateusz Jończyk

--Brian

Re: "Bluetooth: hci0: HCI_REQ-0xfcf0" errors in dmesg

[Mateusz Jończyk]

W dniu 31.10.2022 o 22:08, Gix, Brian pisze:
> On Mon, 2022-10-31 at 13:37 -0700, Luiz Augusto von Dentz wrote:
>> On Mon, Oct 31, 2022 at 1:15 PM Mateusz Jończyk <mat.jonczyk@o2.pl>
>> wrote:
>>> On 6.1.0-rc3, I have been seeing this error message in dmesg:
>>>
>>>         Bluetooth: hci0: HCI_REQ-0xfcf0
>>>
>>> It is printed on every boot, resume from suspend and rfkill unblock
>>> of the Bluetooth device.
>>> The device seems to be functioning normally though (but I have done
>>> limited testing only).
>>>
>>> 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 that function is executed.
[...]
> This, I suspect, will be an ongoing issue, particularily with Vender
> Opcodes, which we don't have much direct visability and testing
> capabilities.  The error gets logged because it is using a deprecated
> (but still working) mechanism to issue HCI opcodes.
>
> If I can get the source code path of the call as it is being
> contructed, I can try making you a patch Mateusz...  But you will
> probably need to do the testing/verification for me.

Sure, what info would you like me to provide? The MSFT
Vendor Opcode 0xFCF0 is defined in drivers/bluetooth/btrtl.c, line 725.

I'm not sure if I have any additional Bluetooth LE devices around, unfortunately.

Additionally, I think that the error message is a bit cryptic, and perhaps could
be changed and/or demoted to a notice for kernel 6.1.

Greetings,

Mateusz