udevd drops UPS symlink and I don't understand why

[weedy]

So this seems to be schrodinger's symlink. I'm running sys-fs/eudev-3.2.7-r1.

If I reboot the box it finds the device and makes a symlink. When I run udevadm test $(udevadm info -q path -n /dev/bus/usb/) it finds the device and makes a symlink. If I run udev from the console with --debug it finds the device and makes a symlink.

Validate module index
seq 2429 queued, 'add' 'usb'
seq 2429 forked new worker [25388]
seq 2429 running
no db file to read /run/udev/data/c189:516: No such file or directory
GROUP 85 /lib64/udev/rules.d/40-gentoo.rules:7
IMPORT builtin 'usb_id' /lib64/udev/rules.d/50-udev-default.rules:13
seq 2430 queued, 'add' 'usb'
seq 2431 queued, 'add' 'hid'
seq 2432 queued, 'add' 'class'
seq 2432 forked new worker [25389]
seq 2433 queued, 'add' 'usbmisc'
seq 2434 queued, 'add' 'hidraw'
seq 2435 queued, 'bind' 'hid'
seq 2436 queued, 'bind' 'usb'
seq 2432 running
seq 2437 queued, 'bind' 'usb'
no db file to read /run/udev/data/+class:usbmisc: No such file or directory
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:13
passed 133 byte device to netlink monitor 0x556187cfdfe0
seq 2432 processed
MODE 0664 /lib64/udev/rules.d/50-udev-default.rules:45
GROUP 84 /lib64/udev/rules.d/62-nut-usbups.rules:130
MODE 0664 /lib64/udev/rules.d/62-nut-usbups.rules:130
GROUP 84 /etc/udev/rules.d/94-UPS-permission.rules:17
MODE 0664 /etc/udev/rules.d/94-UPS-permission.rules:17
LINK 'nut-UPS1' /etc/udev/rules.d/94-UPS-permission.rules:17
handling device node '/dev/bus/usb/005/005', devnum=c189:516, mode=0664, uid=0, gid=84
set permissions /dev/bus/usb/005/005, 020664, uid=0, gid=84
creating symlink '/dev/char/189:516' to '../bus/usb/005/005'
creating link '/dev/nut-UPS1' to '/dev/bus/usb/005/005'
creating symlink '/dev/nut-UPS1' to 'bus/usb/005/005'
created db file '/run/udev/data/c189:516' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1'
passed 639 byte device to netlink monitor 0x556187cfe2b0
seq 2429 processed
passed 292 byte device to netlink monitor 0x556187cefad0
seq 2430 running
no db file to read /run/udev/data/+usb:5-1:1.0: No such file or directory
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:14
RUN 'kmod load $env{MODALIAS}' /lib64/udev/rules.d/80-drivers.rules:5
created db file '/run/udev/data/+usb:5-1:1.0' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1/5-1:1.0'
Execute 'load' 'usb:v0764p0501d0001dc00dsc00dp00ic03isc00ip00in00'
Inserted 'usbhid'
passed 392 byte device to netlink monitor 0x556187cfdfe0
seq 2430 processed
passed 341 byte device to netlink monitor 0x556187cefad0
seq 2431 running
no db file to read /run/udev/data/+hid:0003:0764:0501.0006: No such file or directory
passed 230 byte device to netlink monitor 0x556187cefad0
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:14
seq 2433 running
IMPORT builtin 'hwdb' returned non-zero
no db file to read /run/udev/data/c180:96: No such file or directory
RUN 'kmod load $env{MODALIAS}' /lib64/udev/rules.d/80-drivers.rules:5
handling device node '/dev/usb/hiddev0', devnum=c180:96, mode=0600, uid=0, gid=0Execute 'load' 'hid:b0003g0001v00000764p00000501'

preserve permissions /dev/usb/hiddev0, 020600, uid=0, gid=0
creating symlink '/dev/char/180:96' to '../usb/hiddev0'
No module matches 'hid:b0003g0001v00000764p00000501'
created empty file '/run/udev/data/c180:96' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1/5-1:1.0/usbmisc/hiddev0'
passed 341 byte device to netlink monitor 0x556187cfdfe0
seq 2431 processed
passed 230 byte device to netlink monitor 0x556187cfe2b0
seq 2433 processed
passed 243 byte device to netlink monitor 0x556187cefad0
seq 2434 running
no db file to read /run/udev/data/c248:0: No such file or directory
handling device node '/dev/hidraw0', devnum=c248:0, mode=0600, uid=0, gid=0
preserve permissions /dev/hidraw0, 020600, uid=0, gid=0
creating symlink '/dev/char/248:0' to '../hidraw0'
created empty file '/run/udev/data/c248:0' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1/5-1:1.0/0003:0764:0501.0006/hidraw/hidraw0'
passed 243 byte device to netlink monitor 0x556187cfdfe0
seq 2434 processed
passed 361 byte device to netlink monitor 0x556187cefad0
seq 2435 running
no db file to read /run/udev/data/+hid:0003:0764:0501.0006: No such file or directory
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:14
IMPORT builtin 'hwdb' returned non-zero
passed 361 byte device to netlink monitor 0x556187cfdfe0
seq 2435 processed
passed 307 byte device to netlink monitor 0x556187cefad0
seq 2436 running
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:14
created db file '/run/udev/data/+usb:5-1:1.0' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1/5-1:1.0'
passed 407 byte device to netlink monitor 0x556187cfdfe0
seq 2436 processed
passed 289 byte device to netlink monitor 0x556187cefad0
seq 2437 running
GROUP 85 /lib64/udev/rules.d/40-gentoo.rules:7
IMPORT builtin 'usb_id' /lib64/udev/rules.d/50-udev-default.rules:13
IMPORT builtin 'hwdb' /lib64/udev/rules.d/50-udev-default.rules:13
update old name, '/dev/nut-UPS1' no longer belonging to '/devices/pci0000:00/0000:00:1a.2/usb5/5-1'
no reference left, remove '/dev/nut-UPS1'
handling device node '/dev/bus/usb/005/005', devnum=c189:516, mode=0660, uid=0, gid=85
set permissions /dev/bus/usb/005/005, 020660, uid=0, gid=85
preserve already existing symlink '/dev/char/189:516' to '../bus/usb/005/005'
created db file '/run/udev/data/c189:516' for '/devices/pci0000:00/0000:00:1a.2/usb5/5-1'
passed 615 byte device to netlink monitor 0x556187cfdfe0
seq 2437 processed
cleanup idle workers
Validate module index
Unload module index
Unload module index
worker [25389] exited
worker [25388] exited
^CValidate module index
Unload module index

Everything is fine, unless the box is running for a while. Then suddenly the device drops off the face of the earth and no amount of hot-plugging or udev restarts bring it back. Running udevadm test or udevd --debug instantly brings it back.

How do I debug this when turning on logging stop the bug from happening? Considering it's only the nut/libusb device that breaks I feel like this might not be a 100% udevd bug.

[blueness]

I'm not sure what's going on here. I'm guessing, but I think the device powers down, the kernel driver thinks the device has been removed and udevd removes the link. It gets woken up when udevadm test or udevd --debug causes the kernel to probe for it. I'm sorry I can't really help more without more diagnostics. Can you at least give me the model of the UPS and information about your kernel/distro.

[weedy]

kernel is anything from the past year, currently gentoo-sources-5.0.4 (Or .3, or .5, I forget) Gentoo ~amd64 UPS is a CyberPower full sine wave 1350PFC

[weedy]

So I caught it in the logs. Isn't this a full disconnect? The rules already use ACTION!="add|change", and it went from being device number 2 to device number 3...

I'll probably buy another cable, since CyberPower looks like they shop at the 59 cent store not even the full dollar store. But that's more because of how shit the current one looks and not because I think it will help.

Mar 31 12:47:23 localhost kernel: [68281.379558] usb usb5-port1: disabled by hub (EMI?), re-enabling...
Mar 31 12:47:23 localhost kernel: [68281.379564] usb 5-1: USB disconnect, device number 2
Mar 31 12:47:24 localhost kernel: [68281.636169] usb 5-1: new full-speed USB device number 3 using uhci_hcd
Mar 31 12:47:24 localhost kernel: [68281.823788] usb 5-1: New USB device found, idVendor=0764, idProduct=0501, bcdDevice= 0.01
Mar 31 12:47:24 localhost kernel: [68281.823791] usb 5-1: New USB device strings: Mfr=3, Product=1, SerialNumber=2
Mar 31 12:47:24 localhost kernel: [68281.823792] usb 5-1: Product: CP1350PFCLCD
Mar 31 12:47:24 localhost kernel: [68281.823794] usb 5-1: Manufacturer: CPS
Mar 31 12:47:24 localhost kernel: [68281.823795] usb 5-1: SerialNumber: 000000000000
Mar 31 12:47:24 localhost kernel: [68281.833887] hid-generic 0003:0764:0501.0004: hiddev96,hidraw0: USB HID v1.10 Device [CPS CP1350PFCLCD] on usb-0000:00:1a.2-1/input0

[blueness]

this looks like a normal disconnect + reconnect with a 1 second delay. i'd start looking at hardware issues first.

[bbonev]

Can you please confirm if that is still the case with the latest release?