Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be unavailable on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1420792 - Intel 8265 bluetooth doesn't work with Logitech MX anywhere 2
Summary: Intel 8265 bluetooth doesn't work with Logitech MX anywhere 2
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: bluez
Version: 25
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Don Zickus
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-02-09 14:01 UTC by 汪明衡
Modified: 2017-07-18 16:48 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-05-16 14:24:13 UTC
Type: Bug


Attachments (Terms of Use)
Fedora25 bluetooth.service (70.99 KB, text/x-vhdl)
2017-03-09 10:48 UTC, Timothy Rees
no flags Details
Fedora25 usbmon (637.67 KB, text/plain)
2017-03-09 10:49 UTC, Timothy Rees
no flags Details
Fedora25 btmon (923.30 KB, text/plain)
2017-03-09 10:49 UTC, Timothy Rees
no flags Details
wireless errors from bluetooth resets (62.59 KB, text/plain)
2017-03-13 18:39 UTC, Timothy Rees
no flags Details

Description 汪明衡 2017-02-09 14:01:21 UTC
Description of problem:
It stops working shortly after connected. systemctl bluetooth shows 

Feb 09 21:19:02 localhost.spectre bluetoothd[16250]: Endpoint registered: sender=:1.48 path=/MediaEndpoint/A2DPSink
Feb 09 21:19:26 localhost.spectre bluetoothd[16250]: No cache for E4:53:DF:CA:DA:FF
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:19:29 localhost.spectre bluetoothd[16250]: bt_uhid_send: Invalid argument (22)
Feb 09 21:20:05 localhost.spectre bluetoothd[16250]: Failed to set mode: Failed (0x03)


Version-Release number of selected component (if applicable):

5.4.3-2

How reproducible:

must

Steps to Reproduce:
1. Connect to the mouse through bluetooth.
2.
3.

Actual results:

Displayed as connected, but the bluetooth doesn't actually work with the mouse.

Expected results:


Additional info:

This is not my only problem with the bluetooth. It can't receive files from my android phone either.

Comment 1 Timothy Rees 2017-03-05 19:45:15 UTC
I also have this issue.  Have tested the same mouse with identical hardware running RHEL 7.2 and it works fine, so assume this is a regression. Interestingly the disconnect happens on the stroke of the minute, no apparent information pertaining to this in the btmon logs.

More information about this has been posted on the fedora subreddit:

https://www.reddit.com/r/Fedora/comments/5w79uy/anywhere_mouse_2/

Comment 2 Don Zickus 2017-03-06 19:05:51 UTC
Hi,

If you edit /usr/lib/systemd/system/bluetooth.service by adding a -d to the 

ExecStart=/usr/libexec/bluetooth/bluetoothd -d

line and then 'systemctl daemon-reload; systemctl restart bluetooth'.

Move the mouse around a little bit and when things stop working attach the logs, 'journalctl -ru bluetooth' to here.  That usually provides a clue what is going on.

Also, make sure you have the latest linux-firmware, there was firmware issues with bluetooth and intel chipsets in a firmware release a few months ago.

As for the android phone stuff, make sure you have bluez-obexd installed.  That package is needed for your phone to communicate via bluetooth.  You may need to disable selinux too (setenforce 0), as I have an open ticket to fix a permission problem.

Cheers,
Don

Comment 3 Timothy Rees 2017-03-06 19:42:42 UTC
(In reply to Don Zickus from comment #2)
> ....
> Move the mouse around a little bit and when things stop working attach the
> logs, 'journalctl -ru bluetooth' to here.  That usually provides a clue what
> is going on.

Interestingly there is nothing appended to the logs after the mouse stops functioning, this is the log after I reset with 'hciconfig hci0 reset':

Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:dev_class_changed_callback() Class: 0x000000
Mar 06 20:30:34 bluetoothd[2160]: src/device.c:att_disconnected_cb()
Mar 06 20:30:34 bluetoothd[2160]: src/device.c:att_disconnected_cb() Software caused connection abort (103)
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ac50: device DB:0E:52:97:77:4E profile deviceinfo state changed: connected -> disconnecting (0)
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ac50: device DB:0E:52:97:77:4E profile deviceinfo state changed: disconnecting -> disconnected (0)
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ce90: device DB:0E:52:97:77:4E profile gap-profile state changed: connected -> disconnecting (0)
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ce90: device DB:0E:52:97:77:4E profile gap-profile state changed: disconnecting -> disconnected (0)
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a36e60: device DB:0E:52:97:77:4E profile input-hog state changed: connected -> disconnecting (0)
Mar 06 20:30:34 bluetoothd[2160]: attrib/gattrib.c:g_attrib_unref() 0x55b889a2d290: g_attrib_unref=1
Mar 06 20:30:34 bluetoothd[2160]: src/service.c:change_state() 0x55b889a36e60: device DB:0E:52:97:77:4E profile input-hog state changed: disconnecting -> disconnected (0)
Mar 06 20:30:34 bluetoothd[2160]: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up.
Mar 06 20:30:34 bluetoothd[2160]: attrib/gattrib.c:g_attrib_unref() 0x55b889a2d290: g_attrib_unref=0
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:new_settings_callback() Settings: 0x00000ad0
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:settings_changed() Changed settings: 0x00000001
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:cancel_passive_scanning()
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:adapter_remove_connection()
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:adapter_remove_connection()
Mar 06 20:30:34 bluetoothd[2160]: src/adapter.c:adapter_stop() adapter /org/bluez/hci0 has been disabled
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:dev_class_changed_callback() Class: 0x0c010c
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:new_settings_callback() Settings: 0x00000ad1
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:settings_changed() Changed settings: 0x00000001
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:adapter_start() adapter /org/bluez/hci0 has been enabled
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:trigger_passive_scanning()
Mar 06 20:30:36 bluetoothd[2160]: src/adapter.c:connected_callback() hci0 device DB:0E:52:97:77:4E connected eir_len 0
Mar 06 20:30:36 bluetoothd[2160]: src/gatt-database.c:connect_cb() New incoming LE ATT connection
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:device_attach_att() Elevating security level since LTK is available
Mar 06 20:30:36 bluetoothd[2160]: attrib/gattrib.c:g_attrib_ref() 0x55b889a3cdb0: g_attrib_ref=1
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:deviceinfo_accept() deviceinfo profile accept (DB:0E:52:97:77:4E)
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a29-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a24-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a25-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a27-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a26-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a28-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ac50: device DB:0E:52:97:77:4E profile deviceinfo state changed: disconnected -> connected (0)
Mar 06 20:30:36 bluetoothd[2160]: profiles/gap/gas.c:gap_accept() GAP profile accept (DB:0E:52:97:77:4E)
Mar 06 20:30:36 bluetoothd[2160]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a04-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/service.c:change_state() 0x55b889a2ce90: device DB:0E:52:97:77:4E profile gap-profile state changed: disconnected -> connected (0)
Mar 06 20:30:36 bluetoothd[2160]: attrib/gattrib.c:g_attrib_ref() 0x55b889a3cdb0: g_attrib_ref=2
Mar 06 20:30:36 bluetoothd[2160]: src/service.c:change_state() 0x55b889a36e60: device DB:0E:52:97:77:4E profile input-hog state changed: disconnected -> connected (0)
Mar 06 20:30:36 bluetoothd[2160]: plugins/policy.c:service_cb() Added input-hog reconnect 0
Mar 06 20:30:36 bluetoothd[2160]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23
Mar 06 20:30:36 bluetoothd[2160]: profiles/gap/gas.c:read_device_name_cb() GAP Device Name: MX Anywhere 2
Mar 06 20:30:36 bluetoothd[2160]: profiles/gap/gas.c:read_appearance_cb() GAP Appearance: 0x03c2
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() Primary services found: 6
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x0001, end: 0x0007, uuid: 00001800-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x0008, end: 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x000c, end: 0x001a, uuid: 0000180a-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x001b, end: 0x001e, uuid: 0000180f-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x001f, end: 0x003e, uuid: 00001812-0000-1000-8000-00805f9b34fb
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() start: 0x003f, end: 0xffff, uuid: 00010000-0000-1000-8000-011f2000046d
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_client_ready_cb() status: success, error: 0
Mar 06 20:30:36 bluetoothd[2160]: src/gatt-client.c:btd_gatt_client_ready() GATT client ready
Mar 06 20:30:36 bluetoothd[2160]: src/gatt-client.c:create_services() Exporting objects for GATT services: DB:0E:52:97:77:4E
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_DB_0E_52_97_77_4E err 0
Mar 06 20:30:36 bluetoothd[2160]: src/device.c:gatt_debug() Registered handler for "Service Changed": 1
    --- mouse stops functioning, no further messages ---

> 
> Also, make sure you have the latest linux-firmware, there was firmware
> issues with bluetooth and intel chipsets in a firmware release a few months
> ago.
dnf reports up to date:
linux-firmware-20161205-69.git91ddce49.fc25.noarch

Cheers,
Tim

Comment 4 gopal krishna tiwari 2017-03-09 10:26:06 UTC
Hi Tim, 

I am trying to understand the problem I would appreciate if you can run 

1) journalctl -f --unit=bluetooth (once as mentioned by Don

following is enabled 

If you edit /usr/lib/systemd/system/bluetooth.service by adding a -d to the 

ExecStart=/usr/libexec/bluetooth/bluetoothd -d

line and then 'systemctl daemon-reload; systemctl restart bluetooth'.

2) Start btmon in one terminal  

3) Start usbmon as well ( How to usbmon ?)
https://www.kernel.org/doc/Documentation/usb/usbmon.txt

Please share the output ... 

Would appreciate if you could do the above same for RHEL-7.2 working scenario as well.. 

Gopal...

Comment 5 Timothy Rees 2017-03-09 10:48:41 UTC
Created attachment 1261505 [details]
Fedora25 bluetooth.service

Comment 6 Timothy Rees 2017-03-09 10:49:20 UTC
Created attachment 1261506 [details]
Fedora25 usbmon

Comment 7 Timothy Rees 2017-03-09 10:49:55 UTC
Created attachment 1261507 [details]
Fedora25 btmon

Comment 8 Timothy Rees 2017-03-09 10:52:22 UTC
(In reply to gopal krishna tiwari from comment #4)

> 1) journalctl -f --unit=bluetooth (once as mentioned by Don
> 2) Start btmon in one terminal  
> 3) Start usbmon as well ( How to usbmon ?)

All these are attached.  Started capture at the point the service is restarted and running until the mouse stops working.

> 
> Would appreciate if you could do the above same for RHEL-7.2 working
> scenario as well.. 
> 

This may be harder to obtain, I don't have an install on my laptop, I will try to obtain these using a colleagues today.

Comment 9 gopal krishna tiwari 2017-03-10 07:50:03 UTC
I was trying understand the reports ... partial understanding is as follows :



From btmon and journalctl output I can see error start happening from here 


        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                   [hci0] 38.217981
      ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.218254
      ATT: Write Request (0x12) len 4
        Handle: 0x0036
          Data: 0100
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.218591
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000fbffff0000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.218776 <<-=---------
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.219557
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000f5ffff0000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.219702
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.229392
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000fb0f000000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.229635
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 38.229874
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.230195
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000f60f000000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.230341
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                   [hci0] 38.240619
      ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.240920
      ATT: Read Blob Request (0x0c) len 4
        Handle: 0x002b
        Offset: 0x0058
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.252192
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000f80f000000
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.252446
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000fc1f000000

= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.252666 <<-=--------- 
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.252771
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 38.252902
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.253438
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000fb1f000000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.253725
> ACL Data RX: Handle 3585 flags 0x02 dlen 27                  [hci0] 38.263135
      ATT: Read Blob Response (0x0d) len 22
        06 15 81 25 7f 75 08 95 01 09 38 81 06 95 01 05  ...%.u....8.....     <<----------------- (2) 
        0c 0a 38 02 81 06                                ..8...          
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.263304
      ATT: Read Blob Request (0x0c) len 4
        Handle: 0x002b
        Offset: 0x006e
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.263809
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000f53f000000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.264112 <<-=--------- 
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.264973
      ATT: Handle Value Notification (0x1b) len 9
        Handle: 0x0031
          Data: 0000f08f000000
= bluetoothd: bt_uhid_send: Invalid argument (22)                     38.265220
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 38.265937
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 27                  [hci0] 38.274451
      ATT: Read Blob Response (0x0d) len 22
        c0 c0 06 43 ff 0a 02 02 a1 01 85 11 75 08 95 13  ...C........u...   <<<-------------------- (1) 
        15 00 26 ff 00 09                                ..&...          
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.274771
      ATT: Read Blob Request (0x0c) len 4
        Handle: 0x002b
        Offset: 0x0084
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.275061
      ATT: Handle Value Notification (0x1b) len 9



For the above transaction usbmon also 

ffff8ae7cd0f0e40 336162087 C Bo:1:003:2 0 13 >
ffff8ae7a67a4180 336162251 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f8dfff 0000
ffff8ae7a67a4180 336162265 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336162962 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f09fff 0000
ffff8ae7a67a4000 336162976 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336173064 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f9dfff 0000
ffff8ae7a67a4180 336173083 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336173721 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f1bfff 0000
ffff8ae7a67a4000 336173736 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336173912 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336173928 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4180 336184366 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d012910 81020501 1601f826 ff07750c 95020930 093181
ffff8ae7a67a4180 336184380 S Bi:1:003:2 -115 1028 <
ffff8ae9c79ea180 336184610 S Bo:1:003:2 -115 13 = 010e0900 05000400 122e0001 00
ffff8ae9c79ea180 336184663 C Bo:1:003:2 0 13 >
ffff8ae7a67a4000 336184986 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f9efff 0000
ffff8ae7a67a4000 336185004 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336185687 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f9ffff 0000
ffff8ae7a67a4180 336185702 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336185942 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336185958 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4000 336195841 C Bi:1:003:2 0 9 = 012e0500 01000400 13
ffff8ae7a67a4000 336195866 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336195950 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00faefff 0000
ffff8ae7a67a4180 336195959 S Bi:1:003:2 -115 1028 <
ffff8ae7cd0f0c00 336196227 S Bo:1:003:2 -115 13 = 010e0900 05000400 12320001 00
ffff8ae7cd0f0c00 336196332 C Bo:1:003:2 0 13 >
ffff8ae7a67a4000 336196551 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f3dfff 0000
ffff8ae7a67a4000 336196561 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336206993 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fbffff 0000
ffff8ae7a67a4180 336207014 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336207670 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f5ffff 0000
ffff8ae7a67a4000 336207687 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336207870 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336207884 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4180 336217968 C Bi:1:003:2 0 9 = 012e0500 01000400 13
ffff8ae7a67a4180 336217991 S Bi:1:003:2 -115 1028 <
ffff8ae7cd0f0900 336218266 S Bo:1:003:2 -115 13 = 010e0900 05000400 12360001 00
ffff8ae7cd0f0900 336218325 C Bo:1:003:2 0 13 >
ffff8ae7a67a4000 336218587 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fbffff 0000
ffff8ae7a67a4000 336218597 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336219554 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f5ffff 0000
ffff8ae7a67a4180 336219563 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336229383 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fb0f00 0000
ffff8ae7a67a4000 336229398 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336229865 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336229880 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4180 336230188 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f60f00 0000
ffff8ae7a67a4180 336230201 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336240604 C Bi:1:003:2 0 9 = 012e0500 01000400 13
ffff8ae7a67a4000 336240629 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4240 336240936 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b0058 00
ffff8ae7a67a4240 336241016 C Bo:1:003:2 0 13 >
ffff8ae7a67a4180 336252173 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f80f00 0000
ffff8ae7a67a4180 336252203 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336252436 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fc1f00 0000
ffff8ae7a67a4000 336252453 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336252889 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336252914 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4180 336253346 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fb1f00 0000
ffff8ae7a67a4180 336253447 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336263122 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d061581 257f7508 95010938 81069501 050c0a38 028106  <<---------------- (2) 
ffff8ae7a67a4000 336263143 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a46c0 336263338 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b006e 00
ffff8ae7a67a46c0 336263383 C Bo:1:003:2 0 13 >
ffff8ae7a67a4180 336263793 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f53f00 0000
ffff8ae7a67a4180 336263817 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336264959 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f08f00 0000
ffff8ae7a67a4000 336264982 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4480 336265923 C Ii:1:003:1 0:1 7 = 13050101 0e0100
ffff8ae7a67a4480 336265944 S Ii:1:003:1 -115:1 64 <
ffff8ae7a67a4180 336274436 C Bi:1:003:2 0 31 = 012e1b00 17000400 0dc0c006 43ff0a02 02a10185 11750895 13150026 ff0009  <<------------------------ (1) 
ffff8ae7a67a4180 336274458 S Bi:1:003:2 -115 1028 <
ffff8ae7cd0f0480 336274794 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b0084 00
ffff8ae7cd0f0480 336274888 C Bo:1:003:2 0 13 >
ffff8ae7a67a4000 336275052 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fa3f00 0000
ffff8ae7a67a4000 336275067 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4180 336276035 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00f57f00 0000
ffff8ae7a67a4180 336276058 S Bi:1:003:2 -115 1028 <
ffff8ae7a67a4000 336285697 C Bi:1:003:2 0 18 = 012e0e00 0a000400 1b310000 00fa4f00 0000


Though I still could see its the bluez stops not the mouse data ... and doesn't seems any protocol issue other than some random size big packats 

Can you please try one more thing 

1) Please try to run xinput test-xi2 and check that once we have error in bluez reflected over journalctl is the xiputs are  getting the events ? or stops.

Comment 10 gopal krishna tiwari 2017-03-10 08:47:00 UTC
Now let's analyse the tracess further 



< ACL Data TX: Handle 3585 flags 0x00 dlen 7                   [hci0] 38.117065
--
      ATT: Read Blob Response (0x0d) len 22
        01 29 10 81 02 05 01 16 01 f8 26 ff 07 75 0c 95  .)........&..u..
        02 09 30 09 31 81                                ..0.1.          
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.184599
--
      ATT: Read Blob Response (0x0d) len 22
        06 15 81 25 7f 75 08 95 01 09 38 81 06 95 01 05  ...%.u....8.....
        0c 0a 38 02 81 06                                ..8...          
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.263304
--
      ATT: Read Blob Response (0x0d) len 22
        c0 c0 06 43 ff 0a 02 02 a1 01 85 11 75 08 95 13  ...C........u...
        15 00 26 ff 00 09                                ..&...          
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                   [hci0] 38.274771
--
      ATT: Read Blob Response (0x0d) len 8
        02 81 00 09 02 91 00 c0                          ........        <<-------------- (3) 
> ACL Data RX: Handle 3585 flags 0x02 dlen 14                  [hci0] 38.297343


From usbmon 	  

ffff8ae7a67a4000 335723655 C Bi:1:003:2 0 31 = 012e1b00 17000400 09073000 1231004d 2a340012 35004d2a 38000e39 004d2a
ffff8ae7a67a4000 335813097 C Bi:1:003:2 0 31 = 012e1b00 17000400 0b050109 06a10185 01050719 e029e715 00250175 019508
ffff8ae7a67a4000 336015626 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d810295 06750815 0026a400 05071900 2aa40081 00c005
ffff8ae7a67a4180 336116835 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d010902 a1018502 0901a100 95107501 15002501 050919
ffff8ae7a67a4180 336184366 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d012910 81020501 1601f826 ff07750c 95020930 093181
ffff8ae7a67a4000 336263122 C Bi:1:003:2 0 31 = 012e1b00 17000400 0d061581 257f7508 95010938 81069501 050c0a38 028106
ffff8ae7a67a4180 336274436 C Bi:1:003:2 0 31 = 012e1b00 17000400 0dc0c006 43ff0a02 02a10185 11750895 13150026 ff0009
ffff8ae7a67a4000 336296807 C Bi:1:003:2 0 17 = 012e0d00 09000400 0d028100 09029100 c0 <<--------------- (3)


Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb() HoG inspecting report map
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb() Report MAP:
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          05 01
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          09 06
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          a1 01
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          85 01
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          05 07
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          19 e0
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          29 e7
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          15 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          25 01
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          75 01
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          95 08
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          81 02
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          95 06
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          75 08
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          15 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          26 a4 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          05 07
...
...
...
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          75 08
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          95 13
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          15 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          26 ff 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          09 02
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          81 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          09 02
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          91 00
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb()          c0 <<------------------ (3) 
Mar 09 11:41:20 rh0015472.timrees.local bluetoothd[27704]: profiles/input/hog-lib.c:report_map_read_cb() HoG created uHID device <<--------------- Success 


SO looks like there are some Blob responses are coming and successfull as well...

Now from the source code 

  strncpy((char *) ev.u.create.name, hog->name, sizeof(ev.u.create.name));
        ev.u.create.vendor = hog->vendor;
        ev.u.create.product = hog->product;
        ev.u.create.version = hog->version;
        ev.u.create.country = hog->bcountrycode;
        ev.u.create.bus = BUS_BLUETOOTH;
        ev.u.create.rd_data = value;
        ev.u.create.rd_size = vlen;

        err = bt_uhid_send(hog->uhid, &ev);
        if (err < 0) {
                error("bt_uhid_send: %s", strerror(-err)); <<---------- failing here 
                return;
        }


Following looks to be Blob requests forwarded to the BLUETOOTH mouse device  

ffff8ae8f2585a80 336027435 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a3300
ffff8ae8f2585a80 336027484 C Bo:1:003:2 0 11 >
ffff8ae9c79ea900 336049819 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a3700
ffff8ae9c79ea900 336049887 C Bo:1:003:2 0 11 >
ffff8ae7cd0f00c0 336072734 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a3a00
ffff8ae7cd0f00c0 336072830 C Bo:1:003:2 0 11 >
ffff8ae9c79ea6c0 336094728 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b002c 00
ffff8ae9c79ea6c0 336094789 C Bo:1:003:2 0 13 >
ffff8ae9c79ea6c0 336117082 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a2e00
ffff8ae9c79ea6c0 336117138 C Bo:1:003:2 0 11 >
ffff8ae9c79ea900 336128290 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a3200
ffff8ae9c79ea900 336128345 C Bo:1:003:2 0 11 >
ffff8ae9c79ea480 336150739 S Bo:1:003:2 -115 11 = 010e0700 03000400 0a3600
ffff8ae9c79ea480 336150823 C Bo:1:003:2 0 11 >
ffff8ae7cd0f0e40 336162031 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b0042 00
ffff8ae7cd0f0e40 336162087 C Bo:1:003:2 0 13 >
ffff8ae9c79ea180 336184610 S Bo:1:003:2 -115 13 = 010e0900 05000400 122e0001 00
ffff8ae9c79ea180 336184663 C Bo:1:003:2 0 13 >
ffff8ae7cd0f0c00 336196227 S Bo:1:003:2 -115 13 = 010e0900 05000400 12320001 00
ffff8ae7cd0f0c00 336196332 C Bo:1:003:2 0 13 >
ffff8ae7cd0f0900 336218266 S Bo:1:003:2 -115 13 = 010e0900 05000400 12360001 00
ffff8ae7cd0f0900 336218325 C Bo:1:003:2 0 13 >
ffff8ae7a67a4240 336240936 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b0058 00
ffff8ae7a67a4240 336241016 C Bo:1:003:2 0 13 >
ffff8ae7a67a46c0 336263338 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b006e 00
ffff8ae7a67a46c0 336263383 C Bo:1:003:2 0 13 >
ffff8ae7cd0f0480 336274794 S Bo:1:003:2 -115 13 = 010e0900 05000400 0c2b0084 00
ffff8ae7cd0f0480 336274888 C Bo:1:003:2 0 13 >
 
usbmon says all success but bluez is some how failing over anyone of .... which one I am not sure though even I am not sure it is listed above ...could be discarded by bluez as well ... but it looks like problem lies with blob Requests.

I still have to dig in to the requests ... 

Gopal ..

Comment 16 Timothy Rees 2017-03-13 18:38:37 UTC
(In reply to gopal krishna tiwari from comment #9)
> Can you please try one more thing 
> 
> 1) Please try to run xinput test-xi2 and check that once we have error in
> bluez reflected over journalctl is the xiputs are  getting the events ? or
> stops.

The mouse continues to function whilst the errors or showing in bluez, it does not stop immediately at this time, also this is demonstrated with the xinput output.

The logs I uploaded earlier stop at the exact time the mouse stops functioning.  Whilst I was retesting your ask I have found that restarting the bluetooth device multiple times does cause my wireless nic to stop functioning.  I will attach the dmesg output (dmesg_wifi), I have to restart to fix this.  I do not know if it is related.

Comment 17 Timothy Rees 2017-03-13 18:39:30 UTC
Created attachment 1262545 [details]
wireless errors from bluetooth resets

Comment 19 gopal krishna tiwari 2017-03-14 06:28:46 UTC
(In reply to Timothy Rees from comment #16)
> (In reply to gopal krishna tiwari from comment #9)
> > Can you please try one more thing 
> > 
> > 1) Please try to run xinput test-xi2 and check that once we have error in
> > bluez reflected over journalctl is the xiputs are  getting the events ? or
> > stops.
> 
> The mouse continues to function whilst the errors or showing in bluez, it
> does not stop immediately at this time, also this is demonstrated with the
> xinput output.
> 
> The logs I uploaded earlier stop at the exact time the mouse stops
> functioning.  Whilst I was retesting your ask I have found that restarting
> the bluetooth device multiple times does cause my wireless nic to stop
> functioning.  I will attach the dmesg output (dmesg_wifi), I have to restart
> to fix this.  I do not know if it is related.

This is interesting ... 

To segregate the issue would you mind in switching off the wifi and try to use the BT only and reproduce see does this works ? 

Gopal...

Comment 20 gopal krishna tiwari 2017-03-14 06:29:38 UTC
(In reply to Timothy Rees from comment #16)
> (In reply to gopal krishna tiwari from comment #9)
> > Can you please try one more thing 
> > 
> > 1) Please try to run xinput test-xi2 and check that once we have error in
> > bluez reflected over journalctl is the xiputs are  getting the events ? or
> > stops.
> 
> The mouse continues to function whilst the errors or showing in bluez, it
> does not stop immediately at this time, also this is demonstrated with the
> xinput output.
> 
> The logs I uploaded earlier stop at the exact time the mouse stops
> functioning.  Whilst I was retesting your ask I have found that restarting
> the bluetooth device multiple times does cause my wireless nic to stop
> functioning.  I will attach the dmesg output (dmesg_wifi), I have to restart
> to fix this.  I do not know if it is related.

This is interesting ... 

To segregate the issue would you mind in switching off the wifi and try to use the BT only and reproduce see does this works ? 

Gopal...

Comment 22 Timothy Rees 2017-03-14 09:41:12 UTC
(In reply to gopal krishna tiwari from comment #20)

> To segregate the issue would you mind in switching off the wifi and try to
> use the BT only and reproduce see does this works ? 

Disabling NetworkManager with 'systemctl stop NetworkManager' results in the mouse connecting over bluetooth and continuing to function as expected.  I tested the mouse for at least 10 minutes earlier and it worked fine!  I then started network manager again and the mouse immediately stopped functioning.

Comment 23 Timothy Rees 2017-03-14 11:06:27 UTC
To follow on from this, disabling only the wireless adapter using the XFCE nm-applet also results in the mouse working fine.  So, even with NetworkManager running and wlp4s0 device disabled, the mouse connects and works on bluetooth with no issues:.

# nmcli dev   
DEVICE      TYPE      STATE        CONNECTION 
docker0     bridge    connected    docker0    
virbr0      bridge    connected    virbr0     
virbr3      bridge    connected    virbr3     
enp0s31f6   ethernet  connected    enp0s31f6  
tun0        tun       connected    tun0       
wlp4s0      wifi      unavailable  --         
lo          loopback  unmanaged    --         
virbr0-nic  tun       unmanaged    --         
virbr3-nic  tun       unmanaged    --         
# systemctl status NetworkManager
● NetworkManager.service - Network Manager
   Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2017-03-14 10:33:44 CET; 1h 30min ago
     Docs: man:NetworkManager(8)
 Main PID: 26355 (NetworkManager)

Comment 24 Don Zickus 2017-03-14 15:09:15 UTC
(adding Stanislaw to cc list)

Hi Stanislaw,

Have you seen an issue where disabling wifi makes the bluetooth work again? This is with the Intel 8265 chip.

Gopal found upstream bug

https://bugzilla.kernel.org/show_bug.cgi?id=194815

thinking this is a firmware issue.

Thoughts?

Cheers,
Don

Comment 25 Timothy Rees 2017-03-21 17:22:48 UTC
Is there anything more I can retrieve through testing to help with further analysis?

Comment 26 Don Zickus 2017-03-22 15:13:49 UTC
Hi,

I think having you notice 'disabling wifi, makes bluetooth work' was a huge
step forward.  Currently we are waiting for Intel to get back to us. We
are expecting a status next week hopefully.  I can't think of anything else
to test right now.

Feel free to poke us again in a couple of weeks?  Hopefully we will have some
good news. :-)

Cheers,
Don

Comment 27 Timothy Rees 2017-04-07 14:46:43 UTC
Hi, any progress on this one?

Comment 28 Don Zickus 2017-04-07 15:31:54 UTC
Hi Timothy,

We asked Intel a few days ago and they responded with they are
working the issue through

https://bugzilla.kernel.org/show_bug.cgi?id=194759#c3

You might want to follow that bz for future updates.  Once that is resolved,
we will try to apply that fix here and see if that resolves your issue too.

Or feel free to jump into that bz and try that debug firmware to assist.

Cheers,
Don

Comment 29 Timothy Rees 2017-04-27 12:05:59 UTC
This issue is now resolved.  I have updated my system numerous times so I do not know exactly which package/kernel fixes the issue.  I am currently running:

kernel - 4.10.8-200.fc25.x86_64

bluez-5.44-1.fc25.x86_64
bluez-cups-5.44-1.fc25.x86_64
bluez-obexd-5.44-1.fc25.x86_64
bluez-libs-5.44-1.fc25.x86_64

Comment 30 Peter Robinson 2017-05-16 14:24:13 UTC
(In reply to Timothy Rees from comment #29)
> This issue is now resolved.  I have updated my system numerous times so I do
> not know exactly which package/kernel fixes the issue.  I am currently
> running:

I think it was a new firmware shipped in linux-firmware

Comment 31 ioana rebeca 2017-07-18 16:48:11 UTC
Hi there,

I own a Thinkpad Edge E578 14", and have just upgraded to Fedora 26. But my MX Anywhere 2 is still not detectable from the Bluetooth app. Do you have any advice for me of what I should check?

Thank you,
ioana


Note You need to log in before you can comment on or make changes to this bug.