You are not logged in.

#1 2015-07-21 15:20:37

mk-fg
Member
From: Yekaterinburg, RU
Registered: 2015-07-21
Posts: 1
Website

Bluetooth and vg-kbd1000 (wireless keyboard) "device_bonding_failed()"

Hi,

As bluez doesn't seem to have a dedicated *-users list these days, I wonder if someone can help me with this issue here.

I'm running Arch, have bluez 5.32, vanilla Linux 3.18.16 kernel and BR/EDR dongle (0a12:0001), and trying to use Samsung Wireless Keyboard VG-KBD1000 with this setup.
Keyboard in question is a bit weird in that it's intended for SmartTV and mobile-ish devices, and has a touchpad in addition to the actual keys.

I did the pairing through bluetoothctl, with the usual "power on - agent on - default-agent - pairable on - scan on - pair ... - trust ...", with no noticeable issues there, keyboard blinks its ack.
"connect" immediately after has failed though, and despite being paired, devices can't seem to connect and communicate.

Connection attempts from keyboard happen automatically on keypress (as they should), and this is what gets printed into logs with bluetoothd running with --debug option:

daemon.debug bluetoothd[3170]: src/adapter.c:connected_callback() hci0 device C4:57:6E:FA:9E:D1 connected eir_len 32
daemon.debug bluetoothd[3170]: profiles/input/server.c:connect_event_cb() Incoming connection from C4:57:6E:FA:9E:D1 on PSM 17
daemon.debug bluetoothd[3170]: profiles/input/device.c:input_device_set_channel() idev 0x10c27d0 psm 17
daemon.debug bluetoothd[3170]: profiles/input/server.c:confirm_event_cb()
daemon.debug bluetoothd[3170]: profiles/input/server.c:connect_event_cb() Incoming connection from C4:57:6E:FA:9E:D1 on PSM 19
daemon.debug bluetoothd[3170]: profiles/input/device.c:input_device_set_channel() idev 0x10c27d0 psm 19
daemon.debug bluetoothd[3170]: profiles/input/device.c:encrypt_notify()
kern.err kernel[-]: [ 6192.628783] hid-generic 0005:04E8:2080.000F: unknown main item tag 0x0
kern.info kernel[-]: [ 6197.625770] input: Samsung Wireless Keyboard as /devices/pci0000:00/0000:00:12.0/usb6/6-2/6-2:1.0/bluetooth/hci0/hci0:44/0005:04E8:2080.000F/input/input26
kern.info kernel[-]: [ 6197.625939] hid-generic 0005:04E8:2080.000F: input,hidraw3: BLUETOOTH HID v19.01 Keyboard [Samsung Wireless Keyboard] on f2:d9:6d:cf:eb:af
daemon.info xorg[1289]: (II) config/udev: Adding input device Samsung Wireless Keyboard (/dev/input/mouse1)
daemon.info xorg[1289]: (II) config/udev: Adding input device Samsung Wireless Keyboard (/dev/input/event12)
... (lots of xorg chatter about adding these new devices)

--- Exactly 15 seconds pass here ---

daemon.debug bluetoothd[3170]: src/adapter.c:dev_disconnected() Device C4:57:6E:FA:9E:D1 disconnected, reason 1
daemon.debug bluetoothd[3170]: src/adapter.c:adapter_remove_connection()
daemon.debug bluetoothd[3170]: plugins/policy.c:disconnect_cb() reason 1
daemon.debug bluetoothd[3170]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr C4:57:6E:FA:9E:D1 type 0 status 0xe
daemon.debug bluetoothd[3170]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
daemon.debug bluetoothd[3170]: src/device.c:device_bonding_failed() status 14
daemon.debug bluetoothd[3170]: src/adapter.c:resume_discovery()
daemon.info xorg[1289]: (II) config/udev: removing device Samsung Wireless Keyboard
daemon.debug bluetoothd[3170]: profiles/input/device.c:ctrl_watch_cb() Device C4:57:6E:FA:9E:D1 disconnected
daemon.debug bluetoothd[3170]: profiles/input/device.c:intr_watch_cb() Device C4:57:6E:FA:9E:D1 disconnected
daemon.debug bluetoothd[3170]: profiles/input/device.c:input_device_enter_reconnect_mode() path=/org/bluez/hci0/dev_C4_57_6E_FA_9E_D1 reconnect_mode=device
daemon.info xorg[1289]: (II) evdev: Samsung Wireless Keyboard: Close

Event that caused keyboard to initiate connection (pressing a key) doesn't get through into X, and after exactly 15 seconds it seem to disconnect on some timeout.
"src/device.c:device_bonding_failed() status 14" seem to be error there, but can't really tell for sure.

Looking into "btmon" output running during the same process, I see invariably this (right before timeout/disconnect):

... (connection happens, see link below for full log, it's a bit long)

> ACL Data RX: Handle 44 flags 0x02 dlen 16                                                                                                  [hci0] 2595.950692
      L2CAP: Configure Request (0x04) ident 5 len 8
        Destination CID: 65
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 700
< ACL Data TX: Handle 44 flags 0x00 dlen 18                                                                                                  [hci0] 2595.950764
      L2CAP: Configure Response (0x05) ident 5 len 10
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 700
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                       [hci0] 2595.951708
        Num handles: 1
        Handle: 44
        Count: 1  
> ACL Data RX: Handle 44 flags 0x02 dlen 14                                                                                                  [hci0] 2595.954728
      L2CAP: Configure Response (0x05) ident 4 len 6
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2595.956875
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                       [hci0] 2595.958692
        Num handles: 1
        Handle: 44
        Count: 1  
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                       [hci0] 2595.961693
        Num handles: 1
        Handle: 44
        Count: 1  

--- Here comes the timeout ---

< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2600.956568
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              
< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2605.956455
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              
< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2610.957262
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              
< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2615.956484
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                               [hci0] 2615.964130
        Status: Success (0x00)
        Handle: 44
        Reason: Connection Timeout (0x08)
@ Device Disconnected: C4:57:6E:FA:9E:D1 (0) reason 1
< HCI Command: Write Scan Enable (0x03|0x001a) plen 1                                                                                        [hci0] 2616.016473
        Scan enable: Page Scan (0x02)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                  [hci0] 2616.021136
      Write Scan Enable (0x03|0x001a) ncmd 1
        Status: Success (0x00)

Full btmon log for the connection attempt (~300 lines) can be found here: https://ncry.pt/p/3GAn#BicSEODqV-Pzt6OC … aY4SdcQS5g

Given how well btmon seem to be decoding all the protocols, I'm a bit puzzled about what are these:

< ACL Data TX: Handle 44 flags 0x00 dlen 6                                                                                                   [hci0] 2595.956875
      Channel: 64 len 2 [PSM 17 mode 0] {chan 2}
        41 03                                            A.              

Which seem to be sent by bluez (if I'm understanding "TX" correctly) exactly 5 times (with ~5s interval at most) right before bluez seem to be discarding connection as timed-out.
There are no changes in this "41 03" payload regardless of the event from the keyboard (i.e. same whichever key I press), so I assume it's some kind of standard protocol thing, making it doubly-weird that it's the only thing btmon doesn't seem to decode.

Maybe someone with better knowledge of Bluetooth protocols can take a peek and say what seem to be going wrong there?
Maybe confirm whether it looks like some kind of bug?
Maybe keyboard does something obviously bogus (or someone can tell if it does not)?

Bluetooth dongle in question seem to be working otherwise, even with another somewhat-similar BT keyboard (Apple Wireless). Did try to power-cycle all the devices involved, retry pairing, etc, no luck.
My knowledge of bluetooth stack and protocols is, unfortunately, at a "user" level, i.e. nothing deeper than basic concepts and how to use software involved.

Would appreciate any suggestions, thanks in advance!

Offline

Board footer

Powered by FluxBB