Some USB storage devices will be blocked from registering with USB storage by BPF

[thomas-zimmerman]

I've only seen this on some HP Dev One customer reports, but the system logs look like this:

Sep  6 08:29:02 large kernel: [816771.384370] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("+usb:2-2")): usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd
Sep  6 08:29:02 large kernel: [816771.406614] usb 2-2: New USB device found, idVendor=0480, idProduct=0825, bcdDevice= 3.22
Sep  6 08:29:02 large kernel: [816771.406623] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep  6 08:29:02 large kernel: [816771.406626] usb 2-2: Product: EXTERNAL_USB
Sep  6 08:29:02 large kernel: [816771.406629] usb 2-2: Manufacturer: TOSHIBA
Sep  6 08:29:02 large kernel: [816771.406630] usb 2-2: SerialNumber: 20230603003391F
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("c189:130")): usb 2-2: New USB device found, idVendor=0480, idProduct=0825, bcdDevice= 3.22
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("c189:130")): usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("c189:130")): usb 2-2: Product: EXTERNAL_USB
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("c189:130")): usb 2-2: Manufacturer: TOSHIBA
Sep  6 08:29:02 large hp-vendor[856]: RECORD(Some("usb"), Some("c189:130")): usb 2-2: SerialNumber: 20230603003391F
Sep  6 08:29:02 large mtp-probe: checking bus 2, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:03:00.3/usb2/2-2"
Sep  6 08:29:02 large mtp-probe: bus: 2, device: 3 was not an MTP device
Sep  6 08:29:02 large hp-vendor[856]: HwPeripheralUsb(
Sep  6 08:29:02 large hp-vendor[856]:     PeripheralUSB {
Sep  6 08:29:02 large hp-vendor[856]:         manufacturer: Some(
Sep  6 08:29:02 large hp-vendor[856]:             "TOSHIBA",
Sep  6 08:29:02 large hp-vendor[856]:         ),
Sep  6 08:29:02 large hp-vendor[856]:         manufacturer_id: Some(
Sep  6 08:29:02 large hp-vendor[856]:             "0480",
Sep  6 08:29:02 large hp-vendor[856]:         ),
Sep  6 08:29:02 large hp-vendor[856]:         message: None,
Sep  6 08:29:02 large hp-vendor[856]:         product: Some(
Sep  6 08:29:02 large hp-vendor[856]:             "EXTERNAL_USB",
Sep  6 08:29:02 large hp-vendor[856]:         ),
Sep  6 08:29:02 large hp-vendor[856]:         product_id: Some(
Sep  6 08:29:02 large hp-vendor[856]:             "0825",
Sep  6 08:29:02 large hp-vendor[856]:         ),
Sep  6 08:29:02 large hp-vendor[856]:         state: Added,
Sep  6 08:29:02 large hp-vendor[856]:         timestamp: "2023-09-06T13:29:02Z",
Sep  6 08:29:02 large hp-vendor[856]:         usb_bus_id: 2,
Sep  6 08:29:02 large hp-vendor[856]:         usb_device_id: "3",
Sep  6 08:29:02 large hp-vendor[856]:         usb_speed: "5000",
Sep  6 08:29:02 large hp-vendor[856]:     },
Sep  6 08:29:02 large hp-vendor[856]: )
Sep  6 08:29:02 large kernel: [816771.412934] BPF:       type_id=13 bits_offset=928
Sep  6 08:29:02 large kernel: [816771.412937] BPF:
Sep  6 08:29:02 large kernel: [816771.412938] BPF: Invalid name
Sep  6 08:29:02 large kernel: [816771.412939] BPF:
Sep  6 08:29:02 large kernel: [816771.412940] failed to validate module [usb_storage] BTF: -22
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF: \x09 type_id=13 bits_offset=928
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF:
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF: Invalid name
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF:
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): failed to validate module [usb_storage] BTF: -22
Sep  6 08:29:02 large kernel: [816771.482553] BPF:       type_id=13 bits_offset=928
Sep  6 08:29:02 large kernel: [816771.482558] BPF:
Sep  6 08:29:02 large kernel: [816771.482559] BPF: Invalid name
Sep  6 08:29:02 large kernel: [816771.482560] BPF:
Sep  6 08:29:02 large kernel: [816771.482561] failed to validate module [usb_storage] BTF: -22
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF: \x09 type_id=13 bits_offset=928
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF:
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF: Invalid name
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): BPF:
Sep  6 08:29:02 large hp-vendor[856]: RECORD(None, None): failed to validate module [usb_storage] BTF: -22
Sep  6 08:29:02 large mtp-probe: checking bus 2, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:03:00.3/usb2/2-2"
Sep  6 08:29:02 large mtp-probe: bus: 2, device: 3 was not an MTP device

Disabling the scheduler service and rebooting and the external USB drive works:

sudo systemctl stop com.system76.Scheduler.service
sudo systemctl mask com.system76.Scheduler.service

[jackpot51]

Are you sure this is scheduler related? I see this when reboots are not done after kernel updates.

[thomas-zimmerman]

In the logs that I was looking at this happened not long after a fresh kernel boot. I did not see any kernel updates done by the Pop Shop! but I can't be certain that they did not have a further kernel update on back to back reboots.

[mmstick]

It'd be odd for this to have an affect since it's mainly changing process priorities.