From owner-freebsd-questions@freebsd.org Wed Sep 13 20:06:20 2017 Return-Path: Delivered-To: freebsd-questions@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 52186E0D375 for ; Wed, 13 Sep 2017 20:06:20 +0000 (UTC) (envelope-from matt@bubblegen.co.uk) Received: from avasout06.plus.net (avasout06.plus.net [212.159.14.18]) (using TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits)) (Client CN "Bizanga Labs SMTP Client Certificate", Issuer "Bizanga Labs CA" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id CEFD574C2B for ; Wed, 13 Sep 2017 20:06:19 +0000 (UTC) (envelope-from matt@bubblegen.co.uk) Received: from mail.bubblegen.co.uk ([80.229.236.194]) by avasout06 with smtp id 98371w0014CLJ5401838gP; Wed, 13 Sep 2017 21:03:08 +0100 X-CM-Score: 0.00 X-CNFS-Analysis: v=2.2 cv=GetnpUfL c=1 sm=1 tr=0 a=G4bc5lkgapKKm1P+Twxy3Q==:117 a=G4bc5lkgapKKm1P+Twxy3Q==:17 a=2JCJgTwv5E4A:10 a=x_r6mTsO0M-w0Wy6CZgA:9 a=QEXdDO2ut3YA:10 a=oqgrfY10Tm37WcaBNroA:9 a=_ZfdCTBDWT0ijPj4:21 Received: from mail-lf0-f52.google.com (mail-lf0-f52.google.com [209.85.215.52]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) (Authenticated sender: matt) by mail.bubblegen.co.uk (Postfix) with ESMTPSA id 8846B4622014 for ; Wed, 13 Sep 2017 21:03:06 +0100 (IST) Received: by mail-lf0-f52.google.com with SMTP id d17so3406145lfe.2 for ; Wed, 13 Sep 2017 13:03:06 -0700 (PDT) X-Gm-Message-State: AHPjjUj3ELET+5XwrsEj+TqAMG7us8vyegzcH6CugPKXvDHcm5TXN6QJ b4b+0Sh7+4FjxjblPw+gGExQ14/e/oxOfiQmKBo= X-Google-Smtp-Source: AOwi7QA/BmIfPXQGFxHuLeFW8dXSiqKw632c8gOm2tWWjn6+wVaiv7yk09apMXVG87JbJR97uZ5Lqcr2sMse/4Xod7g= X-Received: by 10.25.207.6 with SMTP id f6mr7293650lfg.14.1505332984899; Wed, 13 Sep 2017 13:03:04 -0700 (PDT) MIME-Version: 1.0 Received: by 10.25.171.26 with HTTP; Wed, 13 Sep 2017 13:03:04 -0700 (PDT) From: Matthew Lear Date: Wed, 13 Sep 2017 13:03:04 -0700 X-Gmail-Original-Message-ID: Message-ID: Subject: apcupsd comms issues with APC UPS Back-UPS XS 950U and NUT server To: freebsd-questions@freebsd.org Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.23 X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 13 Sep 2017 20:06:20 -0000 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 neon devd: Executing 'kldload -n uhid' Sep 12 20:30:11 neon apcupsd[8770]: Communications with UPS restored. Sep 12 21:41:46 neon devd: Executing 'kldload -n uhid' Sep 12 21:41:47 neon apcupsd[8770]: Communications with UPS restored. Sep 12 22:00:15 neon devd: Executing 'kldload -n uhid' Sep 12 22:00:16 neon apcupsd[8770]: Communications with UPS restored. Sep 12 22:20:09 neon devd: Executing 'kldload -n uhid' Sep 12 22:20:10 neon apcupsd[8770]: Communications with UPS restored. Sep 12 22:44:37 neon devd: Executing 'kldload -n uhid' Sep 12 22:44:39 neon apcupsd[8770]: Communications with UPS restored. Sep 12 23:05:13 neon devd: Executing 'kldload -n uhid' Sep 12 23:05:14 neon apcupsd[8770]: Communications with UPS restored. Sep 12 23:15:44 neon devd: Executing 'kldload -n uhid' Sep 12 23:15:45 neon apcupsd[8770]: Communications with UPS restored. Sep 12 23:27:35 neon devd: Executing 'kldload -n uhid' Sep 12 23:27:36 neon apcupsd[8770]: Communications with UPS restored. Sep 13 00:21:20 neon devd: Executing 'kldload -n uhid' Sep 13 00:21:21 neon apcupsd[8770]: Communications with UPS restored. Sep 13 00:58:52 neon devd: Executing 'kldload -n uhid' Sep 13 00:58:53 neon apcupsd[8770]: Communications with UPS restored. Sep 13 01:36:15 neon devd: Executing 'kldload -n uhid' Sep 13 01:36:16 neon apcupsd[8770]: Communications with UPS restored. Sep 13 02:02:04 neon devd: Executing 'kldload -n uhid' Sep 13 02:02:05 neon apcupsd[8770]: Communications with UPS restored. Sep 13 02:02:07 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: at usbus0 Cheers, -- Matt (happy FreeBSD user since 6.2)