Nut upsuser - Feb 2010 - UPS connection established, lost, established, etc.

I have an APC Back-UPS CS 500 which connects via USB. I am running NUT
2.4.1 under Karmic amd64. The entry in ups.conf is

[apc]
driver = usbhid-ups
port = auto
desc = "APC Back-UPS CS 500"

I left upsd.conf at the default values, nut.conf is "mode standalone",
and in upsmon.conf, the monitor line is

MONITOR apc at localhost 1 ups_local mypassword master

and in upsd.users,

[ups_local]
    password = mypassword
    upsmon master

I start nut with

sudo /etc/init.d/nut start; sudo upsdrvctl start

I am able to connect to the UPS, and the command "upsc apc" returns
the UPS characteristics, so the connection definitely works. However,
after a short period of time, the UPS connection is lost and then
regained, so I get a sequence of messages like this (from syslog):
Any suggestions for debugging this?

Feb 12 14:10:38 fin8344 upsmon[2336]: Communications with UPS
apc at localhost established
Feb 12 14:11:48 fin8344 upsd[2331]: Data for UPS [apc] is stale - check driver
Feb 12 14:11:50 fin8344 upsd[2331]: UPS [apc] data is no longer stale
Feb 12 14:12:58 fin8344 upsd[2331]: Data for UPS [apc] is stale - check driver
Feb 12 14:13:00 fin8344 upsd[2331]: UPS [apc] data is no longer stale
Feb 12 14:16:56 fin8344 upsd[2331]: Data for UPS [apc] is stale - check driver
Feb 12 14:16:58 fin8344 upsmon[2336]: Poll UPS [apc at localhost] failed
- Data stale
Feb 12 14:16:58 fin8344 upsmon[2336]: Communications with UPS apc at localhost
lost
Feb 12 14:17:02 fin8344 upsd[2331]: UPS [apc] data is no longer stale
Feb 12 14:17:03 fin8344 upsmon[2336]: Communications with UPS
apc at localhost established

And then I sometimes get message like this relating to the driver:

Feb 13 13:59:18 fin8344 upsmon[15163]: Communications with UPS
apc at localhost lost
Feb 13 13:59:18 fin8344 usbhid-ups[15176]: Got disconnected by another
driver: Device or resource busy
Feb 13 13:59:18 fin8344 kernel: [85629.405233] usb 2-1.5: usbfs:
process 15176 (usbhid-ups) did not claim interface 0 before use

I have no idea where to begin looking for a configuration problem. Can
anyone offer suggestions? Thanks!

Bob

Citeren Robert McDonald <rmcd1024 op gmail.com>:
> And then I sometimes get message like this relating to the driver:
>
> Feb 13 13:59:18 fin8344 upsmon[15163]: Communications with UPS
> apc op localhost lost
> Feb 13 13:59:18 fin8344 usbhid-ups[15176]: Got disconnected by another
> driver: Device or resource busy
> Feb 13 13:59:18 fin8344 kernel: [85629.405233] usb 2-1.5: usbfs:
> process 15176 (usbhid-ups) did not claim interface 0 before use
>
> I have no idea where to begin looking for a configuration problem. Can
> anyone offer suggestions? Thanks!
Either multiple instances of usbhid-ups running (are you attempting to  
monitor multiple UPS devices at the same time?) Usually the usbhid-ups  
driver will be started before upsmon and on most systems will have a  
lower PID (not a higher one). Could it be that you attempt to start  
the driver again without stopping the previous instance? Or the  
generic (non-NUT) hid-ups driver?

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

> Either multiple instances of usbhid-ups running (are you attempting to
> monitor multiple UPS devices at the same time?) Usually the usbhid-ups
> driver will be started before upsmon and on most systems will have a
> lower PID (not a higher one). Could it be that you attempt to start
> the driver again without stopping the previous instance? Or the
> generic (non-NUT) hid-ups driver?
Thank you for the response. I have been confused about how to start
NUT and at one point I was loading both NUT and ups-monitor at
startup. I believe this may have accounted for the extra instance of
usbhid-ups. However, I now load only NUT at startup and the problem
continues.

To create a clean test, I enabled NUT in sysv-rc-conf and rebooted.
Here are the messages I extracted from syslog after the reboot. It
just continues cycling until I stop NUT. Note that there is one error
message about failing to login on UPS. I don't know if that's relevant

Feb 14 08:45:04 fin8344 usbhid-ups[2512]: Startup successful
Feb 14 08:45:04 fin8344 upsd[2513]: listening on 127.0.0.1 port 3493
Feb 14 08:45:04 fin8344 upsd[2513]: listening on ::1 port 3493
Feb 14 08:45:04 fin8344 upsd[2513]: Connected to UPS [apc]: usbhid-ups-apc
Feb 14 08:45:04 fin8344 upsd[2514]: Startup successful
Feb 14 08:45:04 fin8344 upsmon[2516]: Startup successful
Feb 14 08:45:04 fin8344 upsmon[2519]: Login on UPS [apc at localhost]
failed - got [ERR ACCESS-DENIED]
Feb 14 08:45:16 fin8344 upsd[2514]: Data for UPS [apc] is stale - check driver
Feb 14 08:45:19 fin8344 upsd[2514]: UPS [apc] data is no longer stale
Feb 14 08:46:08 fin8344 upsd[2514]: Data for UPS [apc] is stale - check driver
Feb 14 08:46:09 fin8344 upsmon[2519]: Poll UPS [apc at localhost] failed
- Data stale
Feb 14 08:46:09 fin8344 upsmon[2519]: Communications with UPS apc at localhost
lost
Feb 14 08:46:11 fin8344 upsd[2514]: UPS [apc] data is no longer stale
Feb 14 08:46:14 fin8344 upsmon[2519]: Communications with UPS
apc at localhost established
Feb 14 08:46:42 fin8344 upsd[2514]: Data for UPS [apc] is stale - check driver
Feb 14 08:46:44 fin8344 upsmon[2519]: Poll UPS [apc at localhost] failed
- Data stale
Feb 14 08:46:44 fin8344 upsmon[2519]: Communications with UPS apc at localhost
lost
Feb 14 08:46:49 fin8344 upsmon[2519]: Poll UPS [apc at localhost] failed
- Data stale
Feb 14 08:46:51 fin8344 upsd[2514]: UPS [apc] data is no longer stale
Feb 14 08:46:54 fin8344 upsmon[2519]: Communications with UPS
apc at localhost established

Etc.

What does "ps auxww | grep hid" return?

On Sun, Feb 14, 2010 at 9:58 AM, Charles Lepple <clepple at gmail.com>
wrote:
> What does "ps auxww | grep hid" return?
root       372  0.0  0.0      0     0 ?        S<   10:50   0:00
[usbhid_resumer]
nut       2485  0.0  0.0  14636   836 ?        Ss   10:51   0:00
/lib/nut/usbhid-ups -a apc