Hi Benjamin,
On 10/6/23 09:29, Benjamin Tissoires wrote:
> Hi Hans,
>
> On Oct 05 2023, Hans de Goede wrote:
>> hidpp_connect_event() has *four* time-of-check vs time-of-use (TOCTOU)
>> races when it races with itself.
>>
>> hidpp_connect_event() primarily runs from a workqueue but it also runs
>> on probe() and if a "device-connected" packet is received by the hw
>> when the thread running hidpp_connect_event() from probe() is waiting on
>> the hw, then a second thread running hidpp_connect_event() will be
>> started from the workqueue.
>>
>> This opens the following races (note the below code is simplified):
>>
>> 1. Retrieving + printing the protocol (harmless race):
>>
>> if (!hidpp->protocol_major) {
>> hidpp_root_get_protocol_version()
>> hidpp->protocol_major = response.rap.params[0];
>> }
>>
>> We can actually see this race hit in the dmesg in the abrt output
>> attached to rhbz#2227968:
>>
>> [ 3064.624215] logitech-hidpp-device 0003:046D:4071.0049: HID++ 4.5 device connected.
>> [ 3064.658184] logitech-hidpp-device 0003:046D:4071.0049: HID++ 4.5 device connected.
>>
>> Testing with extra logging added has shown that after this the 2 threads
>> take turn grabbing the hw access mutex (send_mutex) so they ping-pong
>> through all the other TOCTOU cases managing to hit all of them:
>>
>> 2. Updating the name to the HIDPP name (harmless race):
>>
>> if (hidpp->name == hdev->name) {
>> ...
>> hidpp->name = new_name;
>> }
>>
>> 3. Initializing the power_supply class for the battery (problematic!):
>>
>> hidpp_initialize_battery()
>> {
>> if (hidpp->battery.ps)
>> return 0;
>>
>> probe_battery(); /* Blocks, threads take turns executing this */
>>
>> hidpp->battery.desc.properties =
>> devm_kmemdup(dev, hidpp_battery_props, cnt, GFP_KERNEL);
>>
>> hidpp->battery.ps =
>> devm_power_supply_register(&hidpp->hid_dev->dev,
>> &hidpp->battery.desc, cfg);
>> }
>>
>> 4. Creating delayed input_device (potentially problematic):
>>
>> if (hidpp->delayed_input)
>> return;
>>
>> hidpp->delayed_input = hidpp_allocate_input(hdev);
>>
>> The really big problem here is 3. Hitting the race leads to the following
>> sequence:
>>
>> hidpp->battery.desc.properties =
>> devm_kmemdup(dev, hidpp_battery_props, cnt, GFP_KERNEL);
>>
>> hidpp->battery.ps =
>> devm_power_supply_register(&hidpp->hid_dev->dev,
>> &hidpp->battery.desc, cfg);
>>
>> ...
>>
>> hidpp->battery.desc.properties =
>> devm_kmemdup(dev, hidpp_battery_props, cnt, GFP_KERNEL);
>>
>> hidpp->battery.ps =
>> devm_power_supply_register(&hidpp->hid_dev->dev,
>> &hidpp->battery.desc, cfg);
>>
>> So now we have registered 2 power supplies for the same battery,
>> which looks a bit weird from userspace's pov but this is not even
>> the really big problem.
>>
>> Notice how:
>>
>> 1. This is all devm-maganaged
>> 2. The hidpp->battery.desc struct is shared between the 2 power supplies
>> 3. hidpp->battery.desc points to the result from the second devm_kmemdup()
>>
>> This causes a use after free scenario on USB disconnect of the receiver:
>> 1. The last registered power supply class device gets unregistered
>> 2. The memory from the last devm_kmemdup() call gets freed,
>> hidpp->battery.desc.properties now points to freed memory
>> 3. The first registered power supply class device gets unregistered,
>> this involves sending a remove uevent to userspace which invokes
>> power_supply_uevent() to fill the uevent data
>> 4. power_supply_uevent() uses hidpp->battery.desc.properties which
>> now points to freed memory leading to backtraces like this one:
>>
>> Sep 22 20:01:35 eric kernel: BUG: unable to handle page fault for address: ffffb2140e017f08
>> ...
>> Sep 22 20:01:35 eric kernel: Workqueue: usb_hub_wq hub_event
>> Sep 22 20:01:35 eric kernel: RIP: 0010:power_supply_uevent+0xee/0x1d0
>> ...
>> Sep 22 20:01:35 eric kernel: ? asm_exc_page_fault+0x26/0x30
>> Sep 22 20:01:35 eric kernel: ? power_supply_uevent+0xee/0x1d0
>> Sep 22 20:01:35 eric kernel: ? power_supply_uevent+0x10d/0x1d0
>> Sep 22 20:01:35 eric kernel: dev_uevent+0x10f/0x2d0
>> Sep 22 20:01:35 eric kernel: kobject_uevent_env+0x291/0x680
>> Sep 22 20:01:35 eric kernel: power_supply_unregister+0x8e/0xa0
>> Sep 22 20:01:35 eric kernel: release_nodes+0x3d/0xb0
>> Sep 22 20:01:35 eric kernel: devres_release_group+0xfc/0x130
>> Sep 22 20:01:35 eric kernel: hid_device_remove+0x56/0xa0
>> Sep 22 20:01:35 eric kernel: device_release_driver_internal+0x19f/0x200
>> Sep 22 20:01:35 eric kernel: bus_remove_device+0xc6/0x130
>> Sep 22 20:01:35 eric kernel: device_del+0x15c/0x3f0
>> Sep 22 20:01:35 eric kernel: ? __queue_work+0x1df/0x440
>> Sep 22 20:01:35 eric kernel: hid_destroy_device+0x4b/0x60
>> Sep 22 20:01:35 eric kernel: logi_dj_remove+0x9a/0x100 [hid_logitech_dj 5c91534a0ead2b65e04dd799a0437e3b99b21bc4]
>> Sep 22 20:01:35 eric kernel: hid_device_remove+0x44/0xa0
>> Sep 22 20:01:35 eric kernel: device_release_driver_internal+0x19f/0x200
>> Sep 22 20:01:35 eric kernel: bus_remove_device+0xc6/0x130
>> Sep 22 20:01:35 eric kernel: device_del+0x15c/0x3f0
>> Sep 22 20:01:35 eric kernel: ? __queue_work+0x1df/0x440
>> Sep 22 20:01:35 eric kernel: hid_destroy_device+0x4b/0x60
>> Sep 22 20:01:35 eric kernel: usbhid_disconnect+0x47/0x60 [usbhid 727dcc1c0b94e6b4418727a468398ac3bca492f3]
>> Sep 22 20:01:35 eric kernel: usb_unbind_interface+0x90/0x270
>> Sep 22 20:01:35 eric kernel: device_release_driver_internal+0x19f/0x200
>> Sep 22 20:01:35 eric kernel: bus_remove_device+0xc6/0x130
>> Sep 22 20:01:35 eric kernel: device_del+0x15c/0x3f0
>> Sep 22 20:01:35 eric kernel: ? kobject_put+0xa0/0x1d0
>> Sep 22 20:01:35 eric kernel: usb_disable_device+0xcd/0x1e0
>> Sep 22 20:01:35 eric kernel: usb_disconnect+0xde/0x2c0
>> Sep 22 20:01:35 eric kernel: usb_disconnect+0xc3/0x2c0
>> Sep 22 20:01:35 eric kernel: hub_event+0xe80/0x1c10
>>
>> There have been quite a few bug reports (see Link tags) about this crash.
>>
>> Fix all the TOCTOU issues, including the really bad power-supply related
>> system crash on USB disconnect, by making probe() use the workqueue for
>> running hidpp_connect_event() too, so that it can never run more then once.
>>
>> Link: https://bugzilla.redhat.com/show_bug.cgi?id=2227221
>> Link: https://bugzilla.redhat.com/show_bug.cgi?id=2227968
>> Link: https://bugzilla.redhat.com/show_bug.cgi?id=2227968
>> Link: https://bugzilla.redhat.com/show_bug.cgi?id=2242189
>> Link: https://bugzilla.kernel.org/show_bug.cgi?id=217412#c58
>
> Many thanks for finding out the root cause of this. And sorry that you
> had to do it :(
>
> Out of curiosity, do you have an idea on when this was introduced?
> From these logs it seem that the symptoms started to appear in July in
> distributions, but I can not quickly reproduce it locally and so I'm a
> little bit puzzled.
I think this may be triggered more easily after commit 699fb50d99039
from 2023-07-20, but the root cause of this seems to be have been
with us all along ...
> Anyway, with or without a Fixes tag, I think I'll apply it today and
> send this and the other patch from Johan to Linus ASAP.
Note I realized this morning that there is another small race between
probe() and hidpp_connect_event() which should not cause a crahs but which
may cause functional issues..
So I'm preparing a follow up patch. I actually just finished testing
the follow up patch. Please also include that patch (assuming you agree
with the fix from it).
Regards,
Hans
>> Cc: stable@xxxxxxxxxxxxxxx
>> Signed-off-by: Hans de Goede <hdegoede@xxxxxxxxxx>
>> ---
>> drivers/hid/hid-logitech-hidpp.c | 3 ++-
>> 1 file changed, 2 insertions(+), 1 deletion(-)
>>
>> diff --git a/drivers/hid/hid-logitech-hidpp.c b/drivers/hid/hid-logitech-hidpp.c
>> index ff077df0babf..a209d51bd247 100644
>> --- a/drivers/hid/hid-logitech-hidpp.c
>> +++ b/drivers/hid/hid-logitech-hidpp.c
>> @@ -4515,7 +4515,8 @@ static int hidpp_probe(struct hid_device *hdev, const struct hid_device_id *id)
>> goto hid_hw_init_fail;
>> }
>>
>> - hidpp_connect_event(hidpp);
>> + schedule_work(&hidpp->work);
>> + flush_work(&hidpp->work);
>>
>> if (will_restart) {
>> /* Reset the HID node state */
>> --
>> 2.41.0
>>
>
