Date: Wed, 13 Sep 2017 13:03:04 -0700 From: Matthew Lear <matt@bubblegen.co.uk> To: freebsd-questions@freebsd.org Subject: apcupsd comms issues with APC UPS Back-UPS XS 950U and NUT server Message-ID: <CAJFxaw-zBFFoFx03p0yPEhsEh2xQdWHrFxxR9OJ_5ugnHjibJg@mail.gmail.com>
next in thread | raw e-mail | index | archive | help
Hi. I have 10.3-RELEASE running on an HP Proliant Micro Server Gen8. I've
had the machine a few years, but not as long as my trusty APC UPC Back RS
800 which recently packed in. I bought an APC Back-UPS XS 950U to replace
it. I run apcupsd on the Proliant and also NUT in server mode. Connection
to the UPS is via USB. NUT is used so other machines on my LAN, such as my
Synology Diskstation, can be be 'power aware'. This setup has served me
very well for years and I'm happy. A day after installing the new XS 950U
UPS I started to wonder why FreeBSD was constantly notifying me by email
that 'Communications with UPS restored'. I've read some posts in the last
year or so about some issues with apcupsd and how some people wondered if
the communications protocol had changed subtly. Those posts involved
apcupsd running on the OS notifying users that power had failed when power
had not failed at all. On the surface it seemed like I was suffering a
similar problem with my new UPS...
apcupsd invokes various scripts in ${prefix}/etc/apcupsd/ (eg commfailure) when
it detects various conditions. For example, loss of power, power returned,
comms fail etc. Those scripts send an email to notify syadmin of the
condition.
Here's tail of /var/log/apcupsd.events with a few lines:
2017-09-12 20:30:11 +0100 Communications with UPS restored.
2017-09-12 21:41:47 +0100 Communications with UPS restored.
2017-09-12 22:00:16 +0100 Communications with UPS restored.
2017-09-12 22:20:10 +0100 Communications with UPS restored.
2017-09-12 22:44:39 +0100 Communications with UPS restored.
2017-09-12 23:05:14 +0100 Communications with UPS restored.
2017-09-12 23:15:45 +0100 Communications with UPS restored.
2017-09-12 23:27:36 +0100 Communications with UPS restored.
2017-09-13 00:21:21 +0100 Communications with UPS restored.
2017-09-13 00:58:53 +0100 Communications with UPS restored.
2017-09-13 01:36:16 +0100 Communications with UPS restored.
2017-09-13 02:02:05 +0100 Communications with UPS restored.
My Diskstation emailed me at 0207 telling me it had lost connection to the
UPS.
>From 02:02:05 to now (~ 2030) I have not seen any more 'restored events'.
>From what I can tell, there is actually nothing wrong. There is no
notification of communications being lost - only comms being restored. And
the frequency of these seems irregular, too.
Restarting apcupsd doesn't change the behaviour.
If I look in syslog something strange is going on:
Sep 12 20:30:10 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 20:30:11 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 21:41:46 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 21:41:47 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 22:00:15 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 22:00:16 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 22:20:09 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 22:20:10 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 22:44:37 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 22:44:39 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 23:05:13 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 23:05:14 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 23:15:44 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 23:15:45 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 12 23:27:35 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 12 23:27:36 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 13 00:21:20 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 13 00:21:21 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 13 00:58:52 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 13 00:58:53 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 13 01:36:15 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 13 01:36:16 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 13 02:02:04 <user.notice> neon devd: Executing 'kldload -n uhid'
Sep 13 02:02:05 <daemon.warn> neon apcupsd[8770]: Communications with UPS
restored.
Sep 13 02:02:07 <daemon.notice> neon upsd[767]: Data for UPS [ups] is stale
- check driver
devd is trying to (re)load uhid every so often and this is triggering the
comms restored event in apcupsd.
The message from upsd likely explains why the Synology box is no longer
able to communicate with the NUT server instance.
I can only assume that the 'stale data' message is because of the repeated
communications messages and somehow this causing confusion so upsd has
decided it has had enough.
After upsd flagged it was unhappy at 0202 I've not see any more comms
restored messages and apcupsd seems happy.
I'm running apcupsd-3.14.14_2 and nut-2.7.4
Does anybody have any idea why this could be happening? It appears like the
cause of the problem is related to NUT somehow but I'm really not sure why.
Some config file snippets:
apcupsd.conf:
UPSCABLE usb
UPSTYPE usb
DEVICE
LOCKFILE /var/spool/lock
SCRIPTDIR /usr/local/etc/apcupsd
PWRFAILDIR /var/run
NOLOGINDIR /var/run
ONBATTERYDELAY 6
BATTERYLEVEL 5
MINUTES 3
TIMEOUT 0
ANNOY 300
ANNOYDELAY 60
NOLOGON disable
KILLDELAY 0
NETSERVER on
NISIP 0.0.0.0
NISPORT 3551
EVENTSFILE /var/log/apcupsd.events
EVENTSFILEMAX 10
UPSCLASS standalone
UPSMODE disable
STATTIME 0
STATFILE /var/log/apcupsd.status
LOGSTATS off
DATATIME 0
nut.conf:
MODE=netserver
ups.conf:
[ups]
driver = usbhid-ups
port = /dev/ugen0.3
desc = "APC Back-UPS XS 950U"
dmesg.boot:
ugen0.3: <American Power Conversion> at usbus0
Cheers,
-- Matt (happy FreeBSD user since 6.2)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAJFxaw-zBFFoFx03p0yPEhsEh2xQdWHrFxxR9OJ_5ugnHjibJg>