Re: Flood of logitech-hidpp-device messages in v6.7
From: Hans de Goede
Date: Mon Jan 29 2024 - 11:35:07 EST
Hi Oleksandr,
On 1/29/24 17:19, Oleksandr Natalenko wrote:
> On pondělí 29. ledna 2024 17:08:56 CET Hans de Goede wrote:
>> Hi,
>>
>> On 1/29/24 16:58, Oleksandr Natalenko wrote:
>>> Hello.
>>>
>>> On úterý 9. ledna 2024 12:58:10 CET Hans de Goede wrote:
>>>> Hi Oleksandr,
>>>>
>>>> On 1/9/24 12:45, Oleksandr Natalenko wrote:
>>>>> Hello Hans et al.
>>>>>
>>>>> Starting from v6.7 release I get the following messages repeating in `dmesg` regularly:
>>>>>
>>>>> ```
>>>>> Jan 09 10:05:06 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: Disconnected
>>>>> Jan 09 10:07:15 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: Disconnected
>>>>> Jan 09 10:16:51 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: HID++ 4.5 device connected.
>>>>> Jan 09 10:16:55 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 10:16:55 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 10:36:31 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: Disconnected
>>>>> Jan 09 10:37:07 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: HID++ 4.5 device connected.
>>>>> Jan 09 10:46:21 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: Disconnected
>>>>> Jan 09 10:48:23 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: Disconnected
>>>>> Jan 09 11:12:27 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: HID++ 4.5 device connected.
>>>>> Jan 09 11:12:47 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 11:12:47 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 11:38:32 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: Disconnected
>>>>> Jan 09 11:43:32 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: Disconnected
>>>>> Jan 09 11:45:10 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: HID++ 4.5 device connected.
>>>>> Jan 09 11:45:11 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 11:45:11 spock kernel: logitech-hidpp-device 0003:046D:408A.0005: HID++ 4.5 device connected.
>>>>> Jan 09 12:31:48 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: Disconnected
>>>>> Jan 09 12:33:21 spock kernel: logitech-hidpp-device 0003:046D:4051.0006: HID++ 4.5 device connected.
>>>>> ```
>>>>>
>>>>> I've got the following hardware:
>>>>>
>>>>> * Bus 006 Device 004: ID 046d:c52b Logitech, Inc. Unifying Receiver
>>>>> * Logitech MX Keys
>>>>> * Logitech M510v2
>>>>>
>>>>> With v6.6 I do not get those messages.
>>>>>
>>>>> I think this is related to 680ee411a98e ("HID: logitech-hidpp: Fix connect event race").
>>>>>
>>>>> My speculation is that some of the devices enter powersaving state after being idle for some time (5 mins?), and then wake up and reconnect once I touch either keyboard or mouse. I should highlight that everything works just fine, it is the flood of messages that worries me.
>>>>>
>>>>> Is it expected?
>>>>
>>>> Yes this is expected, looking at your logs I see about 10 messages per
>>>> hour which IMHO is not that bad.
>>>>
>>>> I guess we could change things to track we have logged the connect
>>>> message once and if yes then log future connect messages (and all
>>>> disconnect messages) at debug level.
>>>
>>> How granular such a tracking should be? Per-`struct hidpp_device`?
>>
>> Yes per struct hidpp_device we want to log the connect message once
>> per device since it gives info which might be useful for troubleshooting.
>>
>>> Should there be something like `hid_info_once_then_dbg()` macro, or open-code it in each place instead?
>>
>> Since we want something like e.g. a "first_connect" (initialized
>> to true if you use that name) flag per struct hidpp_device this needs
>> to be open coded.
>
> OK, would something like this make sense (not tested)?
Yes, thank you. I would call once_connected connected_once and
you can drop the disconnected flag and just always log
disconnect messages at the dbg level.
Regards,
Hans
>
> ```
> diff --git a/drivers/hid/hid-logitech-hidpp.c b/drivers/hid/hid-logitech-hidpp.c
> index 6ef0c88e3e60a..a9899709d6b74 100644
> --- a/drivers/hid/hid-logitech-hidpp.c
> +++ b/drivers/hid/hid-logitech-hidpp.c
> @@ -203,6 +203,9 @@ struct hidpp_device {
> struct hidpp_scroll_counter vertical_wheel_counter;
>
> u8 wireless_feature_index;
> +
> + bool once_connected;
> + bool once_disconnected;
> };
>
> /* HID++ 1.0 error codes */
> @@ -988,8 +991,13 @@ static int hidpp_root_get_protocol_version(struct hidpp_device *hidpp)
> hidpp->protocol_minor = response.rap.params[1];
>
> print_version:
> - hid_info(hidpp->hid_dev, "HID++ %u.%u device connected.\n",
> - hidpp->protocol_major, hidpp->protocol_minor);
> + if (!hidpp->once_connected) {
> + hid_info(hidpp->hid_dev, "HID++ %u.%u device connected.\n",
> + hidpp->protocol_major, hidpp->protocol_minor);
> + hidpp->once_connected = true;
> + } else
> + hid_dbg(hidpp->hid_dev, "HID++ %u.%u device connected.\n",
> + hidpp->protocol_major, hidpp->protocol_minor);
> return 0;
> }
>
> @@ -4184,7 +4192,11 @@ static void hidpp_connect_event(struct work_struct *work)
> /* Get device version to check if it is connected */
> ret = hidpp_root_get_protocol_version(hidpp);
> if (ret) {
> - hid_info(hidpp->hid_dev, "Disconnected\n");
> + if (!hidpp->once_disconnected) {
> + hid_info(hidpp->hid_dev, "Disconnected\n");
> + hidpp->once_disconnected = true;
> + } else
> + hid_dbg(hidpp->hid_dev, "Disconnected\n");
> if (hidpp->battery.ps) {
> hidpp->battery.online = false;
> hidpp->battery.status = POWER_SUPPLY_STATUS_UNKNOWN;
> ```
>
>>
>> Regards,
>>
>> Hans
>>
>>
>>
>>
>>
>
>