Hi Oliver,
On Wed, Jan 12, 2022 at 12:07 PM Oliver Hartkopp <[email protected]> wrote:
>
> Hi all,
>
> after upgrading from Linus' tree 5.16.0-rc7-00108-g800829388818 to the
> current merge window version 5.16.0-05432-g6f38be8f2ccd my BT mouse is
> not working anymore.
>
> I now get two new error messages:
>
> hci0: unexpected event 0xff length: 5 > 0
>
> and
>
> hci0: unexpected event 0xff length: 7 > 0
These are vendor events which I don't think were being handled anyway,
so it is likely something else that is preventing it to work.
> Any idea? Any new firmware required?
>
> Best regards,
> Oliver
>
> [ 8.790201] Bluetooth: Core ver 2.22
> [ 8.847435] Bluetooth: hci0: Bootloader revision 0.0 build 26 week 38
> 2015
> [ 8.853022] Bluetooth: hci0: Device revision is 16
> [ 8.853025] Bluetooth: hci0: Secure boot is enabled
> [ 8.853026] Bluetooth: hci0: OTP lock is enabled
> [ 8.853027] Bluetooth: hci0: API lock is enabled
> [ 8.853028] Bluetooth: hci0: Debug lock is disabled
> [ 8.853028] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
> [ 8.855879] Bluetooth: hci0: Found device firmware: intel/ibt-12-16.sfi
>
> [ 9.422098] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
> [ 9.423532] Bluetooth: BNEP filters: protocol multicast
> [ 9.423537] Bluetooth: BNEP socket layer initialized
> [ 9.439281] iwlwifi 0000:01:00.0 wlp1s0: renamed from wlan0
> [ 10.391796] Bluetooth: hci0: Waiting for firmware download to complete
> [ 10.392752] Bluetooth: hci0: unexpected event 0xff length: 5 > 0
> [ 10.392789] Bluetooth: hci0: Firmware loaded in 1492456 usecs
> [ 10.392985] Bluetooth: hci0: Waiting for device to boot
> [ 10.404942] Bluetooth: hci0: unexpected event 0xff length: 7 > 0
> [ 10.404971] Bluetooth: hci0: Device booted in 11747 usecs
> [ 10.405416] Bluetooth: hci0: Found Intel DDC parameters:
> intel/ibt-12-16.ddc
> [ 10.407835] Bluetooth: hci0: Applying Intel DDC parameters completed
> [ 10.408848] Bluetooth: hci0: Firmware revision 0.1 build 50 week 12 2019
> [ 10.468582] NET: Registered PF_ALG protocol family
> [ 11.277319] Bluetooth: RFCOMM TTY layer initialized
> [ 11.277343] Bluetooth: RFCOMM socket layer initialized
> [ 11.277367] Bluetooth: RFCOMM ver 1.11
Can you attach the bluetoothd and btmon logs when you attempt to
connect the mouse, at least for the logs above it does seem the
firmware is being loaded properly.
>
--
Luiz Augusto von Dentz
Hi Luiz,
On 12.01.22 21:55, Luiz Augusto von Dentz wrote:
> Hi Oliver,
>
> On Wed, Jan 12, 2022 at 12:07 PM Oliver Hartkopp <[email protected]> wrote:
>>
>> Hi all,
>>
>> after upgrading from Linus' tree 5.16.0-rc7-00108-g800829388818 to the
>> current merge window version 5.16.0-05432-g6f38be8f2ccd my BT mouse is
>> not working anymore.
>>
>> I now get two new error messages:
>>
>> hci0: unexpected event 0xff length: 5 > 0
>>
>> and
>>
>> hci0: unexpected event 0xff length: 7 > 0
>
> These are vendor events which I don't think were being handled anyway,
> so it is likely something else that is preventing it to work.
>
In the working 5.16.0-rc7 daemon log there are tons of warning messages
instead that do not show up in 5.16.0-05432-g6f38be8f2ccd ...
>> Any idea? Any new firmware required?
>>
>> Best regards,
>> Oliver
>>
>> [ 8.790201] Bluetooth: Core ver 2.22
>> [ 8.847435] Bluetooth: hci0: Bootloader revision 0.0 build 26 week 38
>> 2015
>> [ 8.853022] Bluetooth: hci0: Device revision is 16
>> [ 8.853025] Bluetooth: hci0: Secure boot is enabled
>> [ 8.853026] Bluetooth: hci0: OTP lock is enabled
>> [ 8.853027] Bluetooth: hci0: API lock is enabled
>> [ 8.853028] Bluetooth: hci0: Debug lock is disabled
>> [ 8.853028] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
>> [ 8.855879] Bluetooth: hci0: Found device firmware: intel/ibt-12-16.sfi
>>
>> [ 9.422098] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
>> [ 9.423532] Bluetooth: BNEP filters: protocol multicast
>> [ 9.423537] Bluetooth: BNEP socket layer initialized
>> [ 9.439281] iwlwifi 0000:01:00.0 wlp1s0: renamed from wlan0
>> [ 10.391796] Bluetooth: hci0: Waiting for firmware download to complete
>> [ 10.392752] Bluetooth: hci0: unexpected event 0xff length: 5 > 0
>> [ 10.392789] Bluetooth: hci0: Firmware loaded in 1492456 usecs
>> [ 10.392985] Bluetooth: hci0: Waiting for device to boot
>> [ 10.404942] Bluetooth: hci0: unexpected event 0xff length: 7 > 0
>> [ 10.404971] Bluetooth: hci0: Device booted in 11747 usecs
>> [ 10.405416] Bluetooth: hci0: Found Intel DDC parameters:
>> intel/ibt-12-16.ddc
>> [ 10.407835] Bluetooth: hci0: Applying Intel DDC parameters completed
>> [ 10.408848] Bluetooth: hci0: Firmware revision 0.1 build 50 week 12 2019
>> [ 10.468582] NET: Registered PF_ALG protocol family
>> [ 11.277319] Bluetooth: RFCOMM TTY layer initialized
>> [ 11.277343] Bluetooth: RFCOMM socket layer initialized
>> [ 11.277367] Bluetooth: RFCOMM ver 1.11
>
> Can you attach the bluetoothd and btmon logs when you attempt to
> connect the mouse, at least for the logs above it does seem the
> firmware is being loaded properly.
>
The BT mouse just is not connecting at all and the btmon says nothing
(with the latest tree) - whatever I do with the mouse.
So this is the deamon.log output of the BROKEN
5.16.0-05432-g6f38be8f2ccd (grepped for "blue"):
Jan 13 08:12:02 silver bluetoothd[540]: Bluetooth daemon 5.55
Jan 13 08:12:02 silver bluetoothd[540]: Starting SDP server
Jan 13 08:12:02 silver blueman-mechanism[465]: Unable to init server:
Could not connect: Connection refused
Jan 13 08:12:02 silver bluetoothd[540]: Bluetooth management interface
1.21 initialized
Jan 13 08:12:02 silver blueman-mechanism[465]: Unable to init server:
Could not connect: Connection refused
Jan 13 08:12:02 silver NetworkManager[478]: <info> [1642057922.9396]
Loaded device plugin: NMBluezManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.30.0/libnm-device-plugin-bluetooth.so)
Jan 13 08:12:04 silver bluetoothd[540]:
profiles/sap/server.c:sap_server_register() Sap driver initialization
failed.
Jan 13 08:12:04 silver bluetoothd[540]: sap-server: Operation not
permitted (1)
Jan 13 08:12:05 silver bluetoothd[540]: Endpoint registered:
sender=:1.26 path=/MediaEndpoint/A2DPSink/sbc
Jan 13 08:12:05 silver bluetoothd[540]: Endpoint registered:
sender=:1.26 path=/MediaEndpoint/A2DPSource/sbc
Jan 13 08:12:13 silver bluetoothd[540]: Endpoint unregistered:
sender=:1.26 path=/MediaEndpoint/A2DPSink/sbc
Jan 13 08:12:13 silver bluetoothd[540]: Endpoint unregistered:
sender=:1.26 path=/MediaEndpoint/A2DPSource/sbc
Jan 13 08:12:13 silver bluetoothd[540]: Endpoint registered:
sender=:1.40 path=/MediaEndpoint/A2DPSink/sbc
Jan 13 08:12:13 silver bluetoothd[540]: Endpoint registered:
sender=:1.40 path=/MediaEndpoint/A2DPSource/sbc
Jan 13 08:12:15 silver dbus-daemon[1235]: [session uid=1000 pid=1235]
Activating via systemd: service name='org.bluez.obex'
unit='obex.service' requested by ':1.47' (uid=1000 pid=1416
comm="/usr/bin/python3 /usr/bin/blueman-applet ")
Jan 13 08:12:15 silver dbus-daemon[1235]: [session uid=1000 pid=1235]
Successfully activated service 'org.bluez.obex'
Jan 13 08:12:45 silver systemd[1]: blueman-mechanism.service: Succeeded.
And this is the deamon.log output of the WORKING
5.16.0-rc7-00108-g800829388818 (grepped for "blue"):
Jan 12 19:11:38 silver bluetoothd[578]: Bluetooth daemon 5.55
Jan 12 19:11:38 silver bluetoothd[578]: Starting SDP server
Jan 12 19:11:38 silver bluetoothd[578]: Bluetooth management interface
1.21 initialized
Jan 12 19:11:38 silver dbus-daemon[484]: [system] Activating via
systemd: service name='org.freedesktop.hostname1'
unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0
pid=578 comm="/usr/libexec/bluetooth/bluetoothd ")
Jan 12 19:11:39 silver blueman-mechanism[479]: Unable to init server:
Could not connect: Connection refused
Jan 12 19:11:39 silver blueman-mechanism[479]: Unable to init server:
Could not connect: Connection refused
Jan 12 19:11:39 silver NetworkManager[490]: <info> [1642011099.0811]
Loaded device plugin: NMBluezManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.30.0/libnm-device-plugin-bluetooth.so)
Jan 12 19:11:40 silver bluetoothd[578]:
profiles/sap/server.c:sap_server_register() Sap driver initialization
failed.
Jan 12 19:11:40 silver bluetoothd[578]: sap-server: Operation not
permitted (1)
Jan 12 19:11:40 silver bluetoothd[578]: Endpoint registered:
sender=:1.26 path=/MediaEndpoint/A2DPSink/sbc
Jan 12 19:11:40 silver bluetoothd[578]: Endpoint registered:
sender=:1.26 path=/MediaEndpoint/A2DPSource/sbc
Jan 12 19:12:08 silver systemd[1]: blueman-mechanism.service: Succeeded.
Jan 12 19:12:23 silver bluetoothd[578]: Endpoint unregistered:
sender=:1.26 path=/MediaEndpoint/A2DPSink/sbc
Jan 12 19:12:23 silver bluetoothd[578]: Endpoint unregistered:
sender=:1.26 path=/MediaEndpoint/A2DPSource/sbc
Jan 12 19:12:23 silver bluetoothd[578]: Endpoint registered:
sender=:1.40 path=/MediaEndpoint/A2DPSink/sbc
Jan 12 19:12:23 silver bluetoothd[578]: Endpoint registered:
sender=:1.40 path=/MediaEndpoint/A2DPSource/sbc
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:24 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:25 silver dbus-daemon[484]: [system] Activating via
systemd: service name='org.blueman.Mechanism'
unit='blueman-mechanism.service' requested by ':1.51' (uid=1000 pid=1407
comm="/usr/bin/python3 /usr/bin/blueman-applet ")
Jan 12 19:12:25 silver blueman-mechanism[1542]: Unable to init server:
Could not connect: Connection refused
Jan 12 19:12:25 silver dbus-daemon[1232]: [session uid=1000 pid=1232]
Activating via systemd: service name='org.blueman.Applet'
unit='blueman-applet.service' requested by ':1.52' (uid=1000 pid=1538
comm="/usr/bin/python3 /usr/bin/blueman-tray ")
Jan 12 19:12:25 silver blueman-mechanism[1542]: Unable to init server:
Could not connect: Connection refused
Jan 12 19:12:25 silver dbus-daemon[484]: [system] Successfully activated
service 'org.blueman.Mechanism'
Jan 12 19:12:25 silver dbus-daemon[1232]: [session uid=1000 pid=1232]
Successfully activated service 'org.blueman.Applet'
Jan 12 19:12:25 silver dbus-daemon[1232]: [session uid=1000 pid=1232]
Activating via systemd: service name='org.bluez.obex'
unit='obex.service' requested by ':1.43' (uid=1000 pid=1407
comm="/usr/bin/python3 /usr/bin/blueman-applet ")
Jan 12 19:12:25 silver dbus-daemon[1232]: [session uid=1000 pid=1232]
Successfully activated service 'org.bluez.obex'
Jan 12 19:12:25 silver blueman-applet[1546]: blueman-applet version
2.1.4 starting
Jan 12 19:12:25 silver blueman-applet[1546]: There is an instance
already running
Jan 12 19:12:25 silver systemd[1208]: blueman-applet.service: Succeeded.
Jan 12 19:12:56 silver systemd[1]: blueman-mechanism.service: Succeeded.
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 19:12:56 silver bluetoothd[578]:
profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid
argument (22)
Jan 12 22:11:55 silver bluetoothd[578]: Terminating
Best regards,
Oliver