Message-ID: <4894984.31r3eYUQgx@natalenko.name>
Date: Mon, 29 Jan 2024 17:19:54 +0100
From: Oleksandr Natalenko <oleksandr@...alenko.name>
To: linux-kernel@...r.kernel.org, Hans de Goede <hdegoede@...hat.com>
Cc: linux-input@...r.kernel.org,
 Filipe Laíns <lains@...eup.net>,
 Bastien Nocera <hadess@...ess.net>, Jiri Kosina <jikos@...nel.org>,
 Benjamin Tissoires <benjamin.tissoires@...hat.com>
Subject: Re: Flood of logitech-hidpp-device messages in v6.7

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)?

```
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
> 
> 
> 
> 
> 


-- 
Oleksandr Natalenko (post-factum)
Download attachment "signature.asc" of type "application/pgp-signature" (834 bytes)

Powered by blists - more mailing lists