Nut upsuser - Apr 2017 - APC Back-UPS XS1300 battery behaviour on test shutdown

Hi there,

Seeing an odd behaviour when running upsmon -c fsd to test my Raspberry Pi
(running Jesse Lite) setup as a upsmon master, attached via USB to an APC
Back-UPS XS1300.

The Raspberry Pi is plugged into the Master outlet on the APC.

The UPS clicks onto battery (and the fan spins up) for a few minutes, then
resets, then repeats again, while finally remaining on AC power afterwards.

The result is that my test ESXi server never quite boots up, before losing
power, and finally booting up again once the UPS is stable.

The FINALDELAY is set to 60, everything else is default across the board
(besides LISTEN directive, obviously), mode is set to netserver.

At this point, I don't know if this is an issue with the UPS or if this is
a known behaviour when using -c fsd.

There's another UPS I'm going to try this afternoon (including an
Eaton).


Here's an output of grep -irn 'ups' /var/log/syslog on the Raspberry
Pi:

512:Apr 26 14:21:40 raspberrypi upsmon[566]: Signal 10: User requested FSD

513:Apr 26 14:21:40 raspberrypi upsd[561]: Client upsmon_local at 127.0.0.1
set FSD on UPS [APC]
514:Apr 26 14:21:49 raspberrypi upsd[561]: User upsmon_remote at 10.1.21.102
logged out from UPS [APC]
515:Apr 26 14:21:56 raspberrypi upsmon[566]: Host sync timer expired,
forcing shutdown
516:Apr 26 14:21:56 raspberrypi upsmon[566]: Executing automatic power-fail
shutdown
517:Apr 26 14:21:56 raspberrypi upsmon[566]: Auto logout and shutdown
proceeding


717:Apr 26 14:23:07 raspberrypi systemd[1]: Started Various fixups to make
systemd work better on Debian.
788:Apr 26 14:23:07 raspberrypi kernel: [    4.070522] usb 1-1.4: Product:
Back-UPS XS 1300G FW:864.L8 .D USB FW:L8
791:Apr 26 14:23:07 raspberrypi kernel: [    4.308623] hid-generic
0003:051D:0002.0001: hiddev0,hidraw0: USB HID v1.00 Device [American Power
Conversion Back-UPS XS 1300G FW:864.L8 .D USB FW:L8 ] on
usb-20980000.usb-1.4/input0
893:Apr 26 14:23:12 raspberrypi systemd[1]: Starting Network UPS Tools -
power device driver controller...
901:Apr 26 14:23:12 raspberrypi upsdrvctl[535]: Using subdriver: APC HID
0.95
902:Apr 26 14:23:13 raspberrypi upsdrvctl[535]: Network UPS Tools - Generic
HID driver 0.38 (2.7.2)
903:Apr 26 14:23:13 raspberrypi upsdrvctl[535]: USB communication driver
0.32
904:Apr 26 14:23:13 raspberrypi upsdrvctl[535]: Network UPS Tools - UPS
driver controller 2.7.2
905:Apr 26 14:23:13 raspberrypi usbhid-ups[547]: Startup successful
906:Apr 26 14:23:13 raspberrypi systemd[1]: Started Network UPS Tools -
power device driver controller.
911:Apr 26 14:23:13 raspberrypi systemd[1]: Starting Network UPS Tools -
power devices information server...
927:Apr 26 14:23:13 raspberrypi upsd[557]: listening on 10.1.21.144 port
3493
928:Apr 26 14:23:13 raspberrypi upsd[557]: listening on 127.0.0.1 port 3493
929:Apr 26 14:23:13 raspberrypi upsd[557]: Connected to UPS [APC]:
usbhid-ups-APC
930:Apr 26 14:23:13 raspberrypi upsd[562]: Startup successful
931:Apr 26 14:23:13 raspberrypi upsd[557]: fopen /var/run/nut/upsd.pid: No
such file or directory
932:Apr 26 14:23:13 raspberrypi upsd[557]: listening on 10.1.21.144 port
3493
933:Apr 26 14:23:13 raspberrypi upsd[557]: listening on 127.0.0.1 port 3493
934:Apr 26 14:23:13 raspberrypi systemd[1]: Started Network UPS Tools -
power devices information server.
935:Apr 26 14:23:13 raspberrypi upsd[557]: Connected to UPS [APC]:
usbhid-ups-APC
936:Apr 26 14:23:14 raspberrypi systemd[1]: Starting Network UPS Tools -
power device monitor and shutdown controller...
943:Apr 26 14:23:14 raspberrypi upsmon[563]: fopen /var/run/nut/upsmon.pid:
No such file or directory
944:Apr 26 14:23:14 raspberrypi upsmon[563]: Using power down flag file
/etc/killpower
945:Apr 26 14:23:14 raspberrypi upsmon[563]: UPS: APC at localhost (master)
(power value 1)
946:Apr 26 14:23:14 raspberrypi systemd[1]: PID file
/var/run/nut/upsmon.pid not readable (yet?) after start.
947:Apr 26 14:23:14 raspberrypi upsmon[566]: Startup successful
949:Apr 26 14:23:14 raspberrypi upsmon[567]: Init SSL without certificate
database
950:Apr 26 14:23:14 raspberrypi systemd[1]: Started Network UPS Tools -
power device monitor and shutdown controller.
958:Apr 26 14:23:14 raspberrypi upsd[562]: User upsmon_local at 127.0.0.1
logged into UPS [APC]

960:Apr 26 14:24:39 raspberrypi upsmon[567]: Poll UPS [APC at localhost]
failed - Write error: Broken pipe
961:Apr 26 14:24:39 raspberrypi upsmon[567]: Communications with UPS
APC at localhost lost
963:Apr 26 14:24:44 raspberrypi upsd[562]: User upsmon_local at 127.0.0.1
logged into UPS [APC]
964:Apr 26 14:24:44 raspberrypi upsmon[567]: Communications with UPS
APC at localhost established
995:Apr 26 14:23:07 raspberrypi systemd[1]: Started Various fixups to make
systemd work better on Debian.
1207:Apr 26 14:23:07 raspberrypi kernel: [    4.109123] usb 1-1.4: Product:
Back-UPS XS 1300G FW:864.L8 .D USB FW:L8
1210:Apr 26 14:23:07 raspberrypi kernel: [    4.351677] hid-generic
0003:051D:0002.0001: hiddev0,hidraw0: USB HID v1.00 Device [American Power
Conversion Back-UPS XS 1300G FW:864.L8 .D USB FW:L8 ] on
usb-20980000.usb-1.4/input0
1338:Apr 26 14:23:12 raspberrypi systemd[1]: Starting Network UPS Tools -
power device driver controller...
1346:Apr 26 14:23:12 raspberrypi upsdrvctl[532]: Using subdriver: APC HID
0.95
1347:Apr 26 14:23:12 raspberrypi upsdrvctl[532]: Network UPS Tools -
Generic HID driver 0.38 (2.7.2)
1348:Apr 26 14:23:12 raspberrypi upsdrvctl[532]: USB communication driver
0.32
1349:Apr 26 14:23:12 raspberrypi upsdrvctl[532]: Network UPS Tools - UPS
driver controller 2.7.2
1350:Apr 26 14:23:12 raspberrypi usbhid-ups[543]: Startup successful
1351:Apr 26 14:23:12 raspberrypi systemd[1]: Started Network UPS Tools -
power device driver controller.
1356:Apr 26 14:23:13 raspberrypi systemd[1]: Starting Network UPS Tools -
power devices information server...
1365:Apr 26 14:23:13 raspberrypi upsd[554]: fopen /var/run/nut/upsd.pid: No
such file or directory
1366:Apr 26 14:23:13 raspberrypi upsd[554]: listening on 10.1.21.144 port
3493
1367:Apr 26 14:23:13 raspberrypi upsd[554]: listening on 127.0.0.1 port 3493
1369:Apr 26 14:23:13 raspberrypi upsd[554]: Connected to UPS [APC]:
usbhid-ups-APC
1376:Apr 26 14:23:13 raspberrypi upsd[559]: Startup successful
1377:Apr 26 14:23:13 raspberrypi systemd[1]: Started Network UPS Tools -
power devices information server.
1378:Apr 26 14:23:13 raspberrypi upsd[554]: listening on 10.1.21.144 port
3493
1379:Apr 26 14:23:13 raspberrypi upsd[554]: listening on 127.0.0.1 port 3493
1380:Apr 26 14:23:13 raspberrypi upsd[554]: Connected to UPS [APC]:
usbhid-ups-APC
1381:Apr 26 14:23:13 raspberrypi systemd[1]: Starting Network UPS Tools -
power device monitor and shutdown controller...
1388:Apr 26 14:23:13 raspberrypi upsmon[560]: fopen
/var/run/nut/upsmon.pid: No such file or directory
1389:Apr 26 14:23:13 raspberrypi upsmon[560]: Using power down flag file
/etc/killpower
1390:Apr 26 14:23:13 raspberrypi upsmon[560]: UPS: APC at localhost (master)
(power value 1)
1391:Apr 26 14:23:13 raspberrypi systemd[1]: PID file
/var/run/nut/upsmon.pid not readable (yet?) after start.
1392:Apr 26 14:23:13 raspberrypi upsmon[563]: Startup successful
1394:Apr 26 14:23:13 raspberrypi upsmon[564]: Init SSL without certificate
database
1395:Apr 26 14:23:13 raspberrypi systemd[1]: Started Network UPS Tools -
power device monitor and shutdown controller.
1403:Apr 26 14:23:14 raspberrypi upsd[559]: User upsmon_local at 127.0.0.1
logged into UPS [APC]

1405:Apr 26 14:25:50 raspberrypi upsmon[564]: Poll UPS [APC at localhost]
failed - Write error: Broken pipe
1406:Apr 26 14:25:50 raspberrypi upsmon[564]: Communications with UPS
APC at localhost lost
1408:Apr 26 14:25:55 raspberrypi upsd[559]: User upsmon_local at 127.0.0.1
logged into UPS [APC]
1409:Apr 26 14:25:55 raspberrypi upsmon[564]: Communications with UPS
APC at localhost established
1410:Apr 26 14:26:33 raspberrypi upsd[559]: User upsmon_remote at 10.1.21.145
logged into UPS [APC]
1411:Apr 26 14:26:48 raspberrypi upsd[559]: User upsmon_remote at 10.1.21.102
logged into UPS [APC]
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.alioth.debian.org/pipermail/nut-upsuser/attachments/20170426/48527413/attachment.html>