Nut upsdev - Apr 2010 - Too much logging from libusb.c (patch supplied)

I recently installed NUT 2.4.3 and found that the USB drivers were logging
an insane amount of data to syslog:

usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error

(and so on and so on)

I found the location where this is happening and did the following patch:

diff --git a/drivers/libusb.c b/drivers/libusb.c
index 50bfc7f..3eae478 100644
--- a/drivers/libusb.c
+++ b/drivers/libusb.c
@@ -353,7 +353,7 @@ static int libusb_open(usb_dev_handle **udevp, USBDevice_t
*curDevice, USBDevice
  */
 static int libusb_strerror(const int ret, const char *desc)
 {
-       if (ret > 0) {
+       if (ret >= 0) {
                return ret;
        }
 

  I've been running that patched version since April 16th, monitoring two
UPSes (APC Back UPS XS 1000 and Cyber Power 1000AVRLCD) with no issues.

  -spc

Citeren Sean Conner <sean op conman.org>:
>
>   I recently installed NUT 2.4.3 and found that the USB drivers were
logging
> an insane amount of data to syslog:
>
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
> usbhid-ups | daemon  debug | Apr 16 18:29:40 | libusb_get_report: No error
>
> (and so on and so on)
>
> I found the location where this is happening and did the following patch:
>
> diff --git a/drivers/libusb.c b/drivers/libusb.c
> index 50bfc7f..3eae478 100644
> --- a/drivers/libusb.c
> +++ b/drivers/libusb.c
> @@ -353,7 +353,7 @@ static int libusb_open(usb_dev_handle **udevp,  
> USBDevice_t *curDevice, USBDevice
>   */
>  static int libusb_strerror(const int ret, const char *desc)
>  {
> -       if (ret > 0) {
> +       if (ret >= 0) {
>                 return ret;
>         }
No.

The above *is* an error condition (despite the 'No error' message),  
most likely due to buggy UPS firmware. Normally, we should not expect  
that when asking for a report, the UPS returns nothing. After all it  
is 'advertising' the report in the report descriptor, so silently  
ignoring this would be a grievous mistake. At the very least, if  
someone is debugging the we should provide some indication why this  
fails.

As you can see, this is logged at LOG_DEBUG level. If you don't want  
to see this message, don't log messages at this level (there usually  
is no reason to do so on production systems). The development version  
(and the next stable release) will allow you to raise the log level  
threshold by adding '-q' (in a similar fashion as the '-D' flag)
to
the startup command line.

But do remember, that this is an error condition and you really should  
ask yourself what problem you're attempting to mask out, before doing  
so. Running the driver in debug mode might help in determining where  
the UPS is lying to us. We're not logging this without reason.

Best regards, Arjen
-- 
Please keep list traffic on the list

Citeren Sean Conner <sean op conman.org>:
>   Well, the comment above that function reads:
>
> /*
>  * Error handler for usb_get/set_* functions. Return value > 0 success,
>  * 0 unknown or temporary failure (ignored), < 0 permanent failure  
> (reconnect)
>  */
And this is exactly what happens.
> You might want to have a custom message for the 0 case, as usb_strerror()
> (which I suppose is a wrapper for strerror(), but I haven't checked)
just
> returns "No error" for a value of 0, which to me, is misleading
(and the
> comment says it's ignored anyway, so either the code is wrong, or the
> comment).  All I saw logged were countless "No error" messages.
You misunderstood the 'ignored' part here. The driver just doesn't  
know what to do to resolve the error condition (and most likely can't  
do anything about it anyway). That still doesn't make it a
'non-error'
condition and still may result in abnormal behavior that we want to be  
informed about. Depending on the HID path that returns this error,  
this may be an insignificant problem (reading serial number of the  
device) or a critical one (line/battery status). There is no way to  
tell at this point.
> The problem is I'm monitoring two UPSes via USB and the logging
> information is insufficient to determine which UPS is giving the bogus
> information.
The driver should also log the PID in the log message (at least,  
that's what it is configured to do so). If you're running multiple  
drivers, you should still be able to tell them apart by the PID.

Best regards, Arjen
-- 
Please keep list traffic on the list