apcupsd comms issues with APC UPS Back-UPS XS 950U and NUT server

[Matthew Lear]

The solution to this was quite simple, although I'm confused as to why it
had been working previously. I changed upsd so it was configured like so...

[ups]
driver = apcupsd-ups
port = localhost
desc = "APC Back-UPS XS 950U"

...and so far, no interruptions or comms problems have occurred. Maybe uhid
and ugen were interfering but seems strange that it started happening.
Maybe I missed something. Now, upsd just gets its info from apcupsd instead
of trying to get it from the UPS directly. Makes sense really... :-)

Hope this helps somebody.
Cheers,
  Matt

On Wed, 13 Sep 2017, 21:03 Matthew Lear <matt at bubblegen.co.uk> wrote:

> 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)
>
>