usbhid-ups should complain if it has no access to USB devices

[AndreKR]

When the proper udev rules are not applied and the nut user cannot access the USB devices, it just segfaults. A better error message would be very helpful.

---

Original details:

This is on Ubuntu 16.04 with an APC Back-UPS CS 500.

ups.conf:

[myups]
        driver = usbhid-ups
        port = auto
        vendorid = "051d"
        productid = "0002"
        bus = "002"

# /lib/nut/usbhid-ups -a myups -DDD
Network UPS Tools - Generic HID driver 0.38 (2.7.2)
USB communication driver 0.32
   0.000000     debug level is '3'
   0.000410     upsdrv_initups...
   0.069589     Checking device (1D6B/0003) (003/001)
   0.069686     - VendorID: 1d6b
   0.069693     - ProductID: 0003
   0.069696     - Manufacturer: unknown
   0.069699     - Product: unknown
   0.069705     - Serial Number: unknown
   0.069708     - Bus: 003
   0.069710     Trying to match device
   0.069717     Device does not match - skipping
   0.069724     Checking device (051D/0002) (002/006)
   0.069745     - VendorID: 051d
   0.069749     - ProductID: 0002
   0.069752     - Manufacturer: unknown
   0.069756     - Product: unknown
   0.069762     - Serial Number: unknown
   0.069765     - Bus: 002
   0.069767     Trying to match device
Segmentation fault (core dumped)

syslog:

usbhid-ups[4649]: segfault at 0 ip 00007f4ebb8e7f37 sp 00007fffc01840f8 error 4 in libc-2.23.so[7f4ebb7a3000+1bf000]

# strace /lib/nut/usbhid-ups -a myups
[...]
open("/dev/bus/usb/003/001", O_RDWR)    = -1 EACCES (Permission denied)
open("/dev/bus/usb/003/001", O_RDONLY)  = 4
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
close(4)                                = 0
open("/dev/bus/usb/002/006", O_RDWR)    = -1 EACCES (Permission denied)
open("/dev/bus/usb/002/006", O_RDONLY)  = 4
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffcdc604500) = -1 EPERM (Operation not permitted)
--- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0} ---
+++ killed by SIGSEGV (core dumped) +++
Segmentation fault (core dumped)

It works with -u root:

# /lib/nut/usbhid-ups -a myups -u root
Network UPS Tools - Generic HID driver 0.38 (2.7.2)
USB communication driver 0.32
kill: No such process
Using subdriver: APC HID 0.95

Only while I collected data for this issue report, I found out that it's a permission problem. I will now go read about how to grant permissions for a USB device to the nut user, but I do think a better error message would have been very helpful.

[clepple]

As noted in the Ubuntu bug LP1483615, "The APC portion of usbhid-ups expects that if it can open the device, it can read the string descriptors." In Launchpad, you can mark that bug as affecting you to give it more visibility.

The Ubuntu revision 2.7.2-4ubuntu1.2 fixes the LP1540008 udev/permissions issue. I would recommend enabling xenial-updates, and if you still have permissions problems out-of-the-box with that revision of the NUT package, please file a new bug on Launchpad, and be sure to indicate anything like upgrade history that would help pinpoint why the udev fix did not work.

Closing this issue since the segfault and permissions issues are being tracked elsewhere.

[AndreKR]

As I understood LP1483615 it is about an issue where although it can open the device (which I guess means the /dev/bus/usb/xxx/xxx file) it cannot read the product descriptor. My issue is about when it cannot open the device file, it segfaults instead of giving an error message.

[jimklimov]

Can you please verify: does the SEGFAULT also happen with current (git master HEAD) code?

If yes - it is our issue, if no (fixed already) it is a distro issue.

[AndreKR]

With the current master the error is now:

device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
No matching HID UPS found

That's better than a segfault, but still doesn't really point at a permissions problem.

Can't open /dev/bus/usb/002/009: permission denied

would be much clearer.

[jimklimov]

Yes, probably. Thanks for the test. Can you run the driver with deeper debug (many -D options) to see if it sees and reports the issue at some level?

[AndreKR]

Doesn't seem so:

Network UPS Tools - Generic HID driver 0.42 (2.7.4-427-g57b8185)
USB communication driver 0.33
   0.000000     [D1] debug level is '16'
   0.034507     [D5] send_to_all: SETINFO device.type "ups"
   0.034523     [D1] upsdrv_initups...
   0.101791     [D2] Checking device (1D6B/0003) (003/001)
   0.101999     [D2] - VendorID: 1d6b
   0.102006     [D2] - ProductID: 0003
   0.102009     [D2] - Manufacturer: unknown
   0.102012     [D2] - Product: unknown
   0.102015     [D2] - Serial Number: unknown
   0.102018     [D2] - Bus: 003
   0.102021     [D2] - Device release number: 0408
   0.102024     [D2] Trying to match device
   0.102033     [D2] Device does not match - skipping
   0.102041     [D2] Checking device (051D/0002) (002/011)
   0.102068     [D2] - VendorID: 051d
   0.102072     [D2] - ProductID: 0002
   0.102075     [D2] - Manufacturer: unknown
   0.102077     [D2] - Product: unknown
   0.102080     [D2] - Serial Number: unknown
   0.102083     [D2] - Bus: 002
   0.102086     [D2] - Device release number: 0006
   0.102089     [D2] Trying to match device
   0.102092     device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
   0.102124     [D2] Device does not match - skipping
[...]

strace:

write(2, "   0.235205\t", 12   0.235205 )           = 12
write(2, "[D2] Device does not match - ski"..., 38[D2] Device does not match - skipping
) = 38
close(4)                                = 0
write(2, "   0.235279\t", 12   0.235279 )           = 12
write(2, "[D2] Checking device (051D/0002)"..., 43[D2] Checking device (051D/0002) (002/011)
) = 43
open("/dev/bus/usb/002/011", O_RDWR)    = -1 EACCES (Permission denied)
open("/dev/bus/usb/002/011", O_RDONLY)  = 4
ioctl(4, USBDEVFS_CONTROL, 0x7ffde281e0d0) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffde281e0d0) = -1 EPERM (Operation not permitted)
ioctl(4, USBDEVFS_CONTROL, 0x7ffde281e0d0) = -1 EPERM (Operation not permitted)
write(2, "   0.235452\t", 12   0.235452 )           = 12
write(2, "[D2] - VendorID: 051d\n", 22[D2] - VendorID: 051d
) = 22
write(2, "   0.235497\t", 12   0.235497 )           = 12
write(2, "[D2] - ProductID: 0002\n", 23[D2] - ProductID: 0002
) = 23
write(2, "   0.235538\t", 12   0.235538 )           = 12
write(2, "[D2] - Manufacturer: unknown\n", 29[D2] - Manufacturer: unknown
) = 29
write(2, "   0.235578\t", 12   0.235578 )           = 12
write(2, "[D2] - Product: unknown\n", 24[D2] - Product: unknown
) = 24
write(2, "   0.235618\t", 12   0.235618 )           = 12
write(2, "[D2] - Serial Number: unknown\n", 30[D2] - Serial Number: unknown
) = 30
write(2, "   0.235658\t", 12   0.235658 )           = 12
write(2, "[D2] - Bus: 002\n", 16[D2] - Bus: 002
)       = 16
write(2, "   0.235700\t", 12   0.235700 )           = 12
write(2, "[D2] - Device release number: 00"..., 35[D2] - Device release number: 0006
) = 35
write(2, "   0.235741\t", 12   0.235741 )           = 12
write(2, "[D2] Trying to match device\n", 28[D2] Trying to match device
) = 28
write(2, "   0.235789\t", 12   0.235789 )           = 12
write(2, "device->Product is NULL so it is"..., 106device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
) = 106
write(2, "   0.235891\t", 12   0.235891 )           = 12
write(2, "[D2] Device does not match - ski"..., 38[D2] Device does not match - skipping
) = 38
close(4)                                = 0
write(2, "   0.235974\t", 12   0.235974 )           = 12
write(2, "[D2] Checking device (05E3/0608)"..., 43[D2] Checking device (05E3/0608) (002/004)

[jimklimov]

Thanks for the details, I hope to look at adding a few checks there soon.

[jimklimov]

Looking at libusb.c, around lines 178-255, I see that the call NUT makes is for usb_open which is part of libusb. It returns a non-NULL value which causes NUT to proceed rather than report an error. There are then calls for three detailed bits of USB data, probably responsible for those other 3 errors in strace.

NUT code does not work with /dev paths directly, so apparently the third-party library hides its inability to contact the device and the reason.

Not sure if libusb-0.1 native, 0.1 compat in 1.x, or 1.x modern would make a difference. Just in case, can you please try compiling against newer libusb? (There's a git branch for that, currently in experimental/vote-gathering phase)

[AndreKR]

With the libusb-1.0 branch and the libusb-1.0-0-dev package the output is now:

Network UPS Tools - Generic HID driver 0.42 (2.7.4-418-gb1314c69)
USB communication driver (libusb 1.0) 0.02
No matching HID UPS found

With at least two D's the ouput is:

Network UPS Tools - Generic HID driver 0.42 (2.7.4-418-gb1314c69)
USB communication driver (libusb 1.0) 0.02
   0.000000     [D1] debug level is '2'
   0.000391     [D1] upsdrv_initups...
   0.003939     [D2] Checking device (8087/8000)
   0.003968     [D2] Failed to open device, skipping. (Access denied (insufficient permissions))
   0.003972     [D2] Checking device (1D6B/0002)
   0.003978     [D2] Failed to open device, skipping. (Access denied (insufficient permissions))
[...]

(Build on Travis from this)

[jimklimov]

Thanks for the tests. So the problem seems two-fold: that libusb 0.1 fails to report the problem, and I'm not sure how much we can do about that, and that NUT logging priority for the error which is reported can be bumped to a more visible number (e.g. 0 or 1)?

[jimklimov]

@AndreKR : hello again, can you check if a build of https://github.com/jimklimov/nut/tree/libusb-1.0 does what you want? :)

[AndreKR]

The problem seems to be more complicated than I initially realized.

Now we have bogus error message for all the non-UPS devices:

Network UPS Tools - Generic HID driver 0.42 (2.7.4-493-gc1c6947a)
USB communication driver (libusb 1.0) 0.02
Failed to open device (8087/8000), skipping: Access denied (insufficient permissions)
Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Using subdriver: APC HID 0.96

In order to solve this I guess the matching would have to be split up into two parts, one that only used vendor/product ID and one that actually requires access to the device.

However, maybe that is unnecessarily complicated. While I was trying to diagnose the problem I did run it with one -D (Although I tried -v, then -h and -q first.) and I did compare the vendor/product IDs, so in my case it would have actually been enough if the "access denied" would have appeared in loglevel D1.

[jimklimov]

Posted an updated PR to log those errors at debug-level 1.

As for matching the vendor/product IDs before opening the USB device - the current API does not provide for that easily: AFAIU the generic routine is used to open each USB device and invoke a callback to match this device for the driver in question (where the callback recognizes a device's metadata as supported), I guess.

Details about devices we were able to open, and whether they matched or were skipped, are still available at debug level 2.

[AndreKR]

Yep, works as expected.

[jimklimov]

FWIW, we can count how many errors we had and if there were any not about access rights.

However it seems that with libusb-0.1 API we can only evaluate the string value of usb_strerror() return values - in the library source there is magic about tracking errors in their string buffer or as a printable errno, and no reliably usable way to learn of an EACCESS otherwise.

With libusb-1.0 however the libusb_open() returns an int which can convey an error code usefully.