atar-axis / xpadneo

Advanced Linux Driver for Xbox One Wireless Controller (shipped with Xbox One S)
https://atar-axis.github.io/xpadneo/
GNU General Public License v3.0
2.01k stars 113 forks source link

"consumer controls not detected" spamming journal #276

Closed TheEpeeist closed 3 years ago

TheEpeeist commented 3 years ago

Version of xpadneo

v0.9-23-g6162dbc

Severity / Impact

Minor

Describe the bug

After connection is established, journal is flooded with "consumer controls not detected" message between 3 and 27 per second.

Steps to Reproduce

Connect the controller through bluetooth; touch a joystick.

Expected behavior

A single message in the log, or at least a limited number.

Screenshots/Gifs

System information

# uname -a
Linux hugh-desktop-Arch 5.11.4-arch1-1-l2cap #1 SMP PREEMPT Mon, 08 Mar 2021 23:46:57 +0000 x86_64 GNU/Linux

My kernel is 5.11.4 with only the L2CAP patch applied.

# xxd -c20 -g1 /sys/module/hid_xpadneo/drivers/hid:xpadneo/0005:045E:*/report_descriptor | tee >(cksum)
00000000: 05 01 09 05 a1 01 85 01 09 01 a1 00 09 30 09 31 15 00 27 ff  .............0.1..'.
00000014: ff 00 00 95 02 75 10 81 02 c0 09 01 a1 00 09 33 09 34 15 00  .....u.........3.4..
00000028: 27 ff ff 00 00 95 02 75 10 81 02 c0 05 01 09 32 15 00 26 ff  '......u.......2..&.
0000003c: 03 95 01 75 0a 81 02 15 00 25 00 75 06 95 01 81 03 05 01 09  ...u.....%.u........
00000050: 35 15 00 26 ff 03 95 01 75 0a 81 02 15 00 25 00 75 06 95 01  5..&....u.....%.u...
00000064: 81 03 05 01 09 39 15 01 25 08 35 00 46 3b 01 66 14 00 75 04  .....9..%.5.F;.f..u.
00000078: 95 01 81 42 75 04 95 01 15 00 25 00 35 00 45 00 65 00 81 03  ...Bu.....%.5.E.e...
0000008c: 05 09 19 01 29 0c 15 00 25 01 75 01 95 0c 81 02 15 00 25 00  ....)...%.u.......%.
000000a0: 75 01 95 04 81 03 05 0c 0a b2 00 15 00 25 01 95 01 75 01 81  u............%...u..
000000b4: 02 15 00 25 00 75 07 95 01 81 03 05 0f 09 21 85 03 a1 02 09  ...%.u........!.....
000000c8: 97 15 00 25 01 75 04 95 01 91 02 15 00 25 00 75 04 95 01 91  ...%.u.......%.u....
000000dc: 03 09 70 15 00 25 64 75 08 95 04 91 02 09 50 66 01 10 55 0e  ..p..%du......Pf..U.
000000f0: 15 00 26 ff 00 75 08 95 01 91 02 09 a7 15 00 26 ff 00 75 08  ..&..u.........&..u.
00000104: 95 01 91 02 65 00 55 00 09 7c 15 00 26 ff 00 75 08 95 01 91  ....e.U..|..&..u....
00000118: 02 c0 c0                                                     ...
2986910699 1363

Controller and Bluetooth information

xpadneo-btmon.txt xpadneo-dmesg.txt xpadneo-lsusb.txt

Additional context

This seems minor but as I don't know what "consumer controls" are, I really cannot tell. Like many others I have had great trouble getting the controller to connect and even with the L2CAP patch it still seems to refuse to connect at random. It has never paired with my onboard Intel AX200 bluetooth.

kakra commented 3 years ago

journal is flooded with "consumer controls not detected" message between 3 and 27 per second

Yeah, I was already suspecting that something like this might happen. I've tested two different models and both seemed to work correctly. I think you're using the new Xbox X|S Controller model?

This seems minor but as I don't know what "consumer controls" are, I really cannot tell.

Consumer controls is a category in the HID specification. This includes media buttons (like pause, play, etc) which control consumer devices and do not map properly into keyboard controls (127 buttons) or other input devices (joysticks, mice, touchpads, etc). The gamepad has some of such buttons, that is the Guide button which has no proper equivalent in the keyboard mappings, and also the new Share button which neither has any proper mapping in one of the standard HID categories.

The older models use HID over Bluetooth, and thus split their mappings into up to three categories (gamepad controls, consumer controls, and - with the advent of the Elite controller - also keyboard controls). I suspect that the new controller model isn't HID because it seems to transfer its Bluetooth data in a very different format and it's a BLE (Bluetooth low energy) device. So the kernel somehow maps that to HID but doesn't categorize the buttons.

Apparently, I don't own that controller yet so I cannot test this: It might be a problem in the kernel where it doesn't categorize the mappings properly when it should, or this controller just doesn't present itself as split subdevices. Whatever that is, I still need to figure out how to create missing subdevices on the fly from the driver anyways because we will need another category for mouse controls as part of the mouse emulation which is in the making.

Currently, while parsing the HID descriptor, the kernel will assign sub devices to each category, and when we discover that in the driver, we will store that device handler in our own structures so we'll be able to emit input events on them. But that also means: If a category never shows up when the kernel initializes the lower layers of the device, we will never get a device handle i.e. for consumer controls but still see a button later which belongs there and we cannot emit it - thus the message.

The current situation was somewhat expected (although I was hoping that would never happen for consumer controls). I pushed the driver changes out to get more test coverage. It is somewhat bad that the message spams multiple times per input frame and per second, I should look at a way to fix that. But in short term, I'll not be able to fix the underlying problem which means the consumer control buttons are probably dead for you currently. Maybe it's time to back-port all the stable fixes to the v0.9 branch and release a v0.9.1 version while the v0.10 branch stays in this slightly fragile state for a while - at least for your control model.

kakra commented 3 years ago

Investigating this a little, I wonder what's happening for your controller because it clearly emits consumer controls in the descriptor for its Share button:

0x05, 0x0C,        //   Usage Page (Consumer)
0x0A, 0xB2, 0x00,  //   Usage (Record)
0x15, 0x00,        //   Logical Minimum (0)
0x25, 0x01,        //   Logical Maximum (1)
0x95, 0x01,        //   Report Count (1)
0x75, 0x01,        //   Report Size (1)

Could you try creating a dmesg log just from the controller initializing without touching any of the controls? Turn the controller off, then run dmesg -w, turn it on and wait until it initializes. The command should have logged some lines from xpadneo without spamming a whole lot lines, please post the result.

Maybe you can look out for a line I'm missing, I'm seeing this in your dmesg log:

[26427.827997] xpadneo 0005:045E:0B13.0009: report descriptor size: 283 bytes
[26427.828000] xpadneo 0005:045E:0B13.0009: fixing up Rx axis
[26427.828001] xpadneo 0005:045E:0B13.0009: fixing up Ry axis
[26427.828001] xpadneo 0005:045E:0B13.0009: fixing up Z axis
[26427.828002] xpadneo 0005:045E:0B13.0009: fixing up Rz axis
[26427.828003] xpadneo 0005:045E:0B13.0009: fixing up button mapping
[26427.828076] xpadneo 0005:045E:0B13.0009: gamepad detected
[26427.828077] xpadneo 0005:045E:0B13.0009: pretending XB1S Windows wireless mode (changed PID from 0x0B13 to 0x02E0)
[26427.828078] xpadneo 0005:045E:0B13.0009: working around wrong SDL2 mappings (changed version from 0x00000505 to 0x00000903)
[26427.828079] xpadneo 0005:045E:0B13.0009: disabling dead zones
[26427.828080] xpadneo 0005:045E:0B13.0009: enabling compliance with Linux Gamepad Specification
[26427.828102] input: Xbox Wireless Controller 987A as /devices/virtual/misc/uhid/0005:045E:0B13.0009/input/input30
[26427.828386] xpadneo 0005:045E:0B13.0009: input,hidraw4: BLUETOOTH HID v5.05 Gamepad [Xbox Wireless Controller 987A] on 00:e0:4c:70:4a:03
[26427.828390] xpadneo 0005:045E:0B13.0009: controller quirks: 0x00000050
[26427.828391] xpadneo xpadneo_welcome_rumble start
[26428.819785] xpadneo xpadneo_welcome_rumble took 990ms
[26428.819789] xpadneo 0005:045E:0B13.0009: Xbox Wireless Controller 987A [98:7a:14:d7:c7:2e] connected

But it never says "consumer controls detected" although it should because it is right there in the descriptor.

Another line attracts my attention:

[26429.238774] input: Microsoft X-Box 360 pad as /devices/virtual/input/input31

Did you connect another gamepad? Or is this a result of having Steam running with active Xbox controller support (which enables Steam Input and creates additional virtual devices)? If it is Steam, it may steal control over some device functions from us. You may want to try with Steam Input disabled, or Steam completely stopped.

kakra commented 3 years ago

As a reference for you, this is how it looks like for my Elite 2 controller:

[  118.323810] xpadneo 0005:045E:0B05.0016: report descriptor size: 1038 bytes
[  118.323812] xpadneo 0005:045E:0B05.0016: fixing up report descriptor size
[  118.323813] xpadneo 0005:045E:0B05.0016: fixing up Rx axis
[  118.323813] xpadneo 0005:045E:0B05.0016: fixing up Ry axis
[  118.323814] xpadneo 0005:045E:0B05.0016: fixing up Z axis
[  118.323814] xpadneo 0005:045E:0B05.0016: fixing up Rz axis
[  118.323815] xpadneo 0005:045E:0B05.0016: fixing up button mapping
[  118.324207] xpadneo 0005:045E:0B05.0016: battery detected
[  118.324226] xpadneo 0005:045E:0B05.0016: gamepad detected
[  118.324228] xpadneo 0005:045E:0B05.0016: pretending XB1S Windows wireless mode (changed PID from 0x0B05 to 0x02E0)
[  118.324229] xpadneo 0005:045E:0B05.0016: disabling dead zones
[  118.324230] xpadneo 0005:045E:0B05.0016: enabling compliance with Linux Gamepad Specification
[  118.324280] input: Xbox Elite Wireless Controller as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6.7/2-1.6.7.2/2-1.6.7.2:1.0/bluetooth/hci0/hci0:74/0005:045E:0B05.0016/input/input28
[  118.324343] xpadneo 0005:045E:0B05.0016: consumer controls detected
[  118.324373] input: Xbox Elite Wireless Controller Consumer Control as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6.7/2-1.6.7.2/2-1.6.7.2:1.0/bluetooth/hci0/hci0:74/0005:045E:0B05.0016/input/input29
[  118.324400] xpadneo 0005:045E:0B05.0016: unhandled input application 0xff000005
[  118.324402] xpadneo 0005:045E:0B05.0016: pretending XB1S Windows wireless mode (changed PID from 0x0B05 to 0x02E0)
[  118.324402] xpadneo 0005:045E:0B05.0016: disabling dead zones
[  118.324403] xpadneo 0005:045E:0B05.0016: enabling compliance with Linux Gamepad Specification
[  118.324406] xpadneo 0005:045E:0B05.0016: keyboard detected
[  118.324435] input: Xbox Elite Wireless Controller Keyboard as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6.7/2-1.6.7.2/2-1.6.7.2:1.0/bluetooth/hci0/hci0:74/0005:045E:0B05.0016/input/input31
[  118.324483] xpadneo 0005:045E:0B05.0016: input,hidraw15: BLUETOOTH HID v9.03 Gamepad [Xbox Elite Wireless Controller] on 00:1a:7d:da:71:15
[  118.324486] xpadneo 0005:045E:0B05.0016: controller quirks: 0x00000018
[  118.324487] xpadneo xpadneo_welcome_rumble start
[  119.462195] xpadneo xpadneo_welcome_rumble took 1136ms
[  119.462202] xpadneo 0005:045E:0B05.0016: Xbox Elite Wireless Controller [98:7a:14:61:17:4d] connected
[  119.812289] xpadneo 0005:045E:0B05.0016: battery registered

Ignore the line unhandled input application for now, that's from the Elite 2 profile programming feature which is not yet supported.

kakra commented 3 years ago

BTW: Could you try if the controller connects more reliably when double-tapping the small round connect button while it is trying to connect to Bluetooth?

kakra commented 3 years ago

I've just pushed a commit which should fix the spamming issue. We still need to solve the problem why consumer controls didn't show up, tho.

TheEpeeist commented 3 years ago

Thank you for a remarkably quick and very informative reply. Today I cannot get the controller (which is model 1914) to connect at all. However I have searched through my journal log and it has never logged a message "consumer controls detected". Holding down the small round button puts the controller into its pairing mode. Double tapping seems to have no effect other than turning pairing mode off. I see the same six log messages every time when it fails to connect:

Mar 11 19:26:57 bluetoothd[379760]: profiles/deviceinfo/deviceinfo.c:read_pnpid_cb() Error reading PNP_ID value: Request attribute has encountered an unlikely error
Mar 11 19:26:57 bluetoothd[379760]: profiles/deviceinfo/dis.c:read_pnpid_cb() Error reading PNP_ID value: Request attribute has encountered an unlikely error
Mar 11 19:26:57 bluetoothd[379760]: profiles/input/hog-lib.c:info_read_cb() HID Information read failed: Request attribute has encountered an unlikely error
Mar 11 19:26:57 bluetoothd[379760]: profiles/input/hog-lib.c:report_map_read_cb() Report Map read failed: Request attribute has encountered an unlikely error
Mar 11 19:26:57 bluetoothd[379760]: profiles/input/hog-lib.c:report_reference_cb() Read Report Reference descriptor failed: Request attribute has encountered an unlikely error
Mar 11 19:26:57 bluetoothd[379760]: profiles/input/hog-lib.c:report_reference_cb() Read Report Reference descriptor failed: Request attribute has encountered an unlikely error
kakra commented 3 years ago

Well, the X|S has some semi-official feature (not announced very prominently) to quick switch between Bluetooth and Dongle mode, by double-tapping the connect button for one mode, or holding it for around 1s to switch to the other mode. I'm currently having problems connecting my Elite2 controller properly (it is paired properly, tho, there's a link key stored in the bluetoothd state directory): Connecting would often fail, or take 30-60s, double-tapping the connect button seems to reliably work around that issue and it just takes 2-3s after that to connect.

If it's not properly paired yet, that double-tapping will probably fail.

kakra commented 3 years ago

BTW: Did you update the firmware of the controller? This may be needed as I think I've found some reports about it fixing some Bluetooth connection issues.

kakra commented 3 years ago

A fix has been pushed for this.