Abrupt shutdown even though an UPS is attached

flyvert · ‎2015-11-25

My ReadyNAS Ultra 2 running RAIDiator 4.2.27 does not shutdown properly when the UPS (Eaton 3S) is running low on battery.

My house seldomly (practically never) suffer from loss of mains power, but today there were two dropouts, one longer and one shorter. My Ultra 2 was not properly shutdown during the first and longer (>30 minutes) outage, but "survived" on battery during the second and shorter outage.

Battery charge was 100% at the first occurrence and battery life expectancy is listed as 23 minutes.

Wed Nov 25 10:42:44 CET 2015 UPS is on battery power.

Wed Nov 25 11:28:01 CET 2015 System is up.

Wed Nov 25 11:33:54 CET 2015 UPS is on battery power.

Wed Nov 25 11:36:26 CET 2015 UPS is on line power.

After a similar event last year I changed the Battery Low Threshold setting in Frontview from Auto to 30%. This did seemed to not have any effect. Power was lost abruptly and the unit reset itself.

Here are the lines containing "usb" for today (Nov 25th):

NAS2TB:/# grep "Nov 25" /var/log/syslog | grep -i ups
Nov 25 10:42:41 NAS2TB hidups[4697]: UPS has been on battery power >5 seconds.
Nov 25 10:42:44 NAS2TB RAIDiator: ONBATT: UPS is on battery power. -- battery.charge: 100 battery.chemistry: PbAc battery.runtime: 1687 battery.voltage: 2.3 driver.name: hidups driver.parameter.lowbatt_pct: 30 driver.version: 2.0.5 ups.mfr: EATON ups.model: Eaton 3S ups.serial: 000000000 ups.status: OB
Nov 25 10:42:44 NAS2TB RAIDiator: UPS is on battery power.
Nov 25 10:43:25 NAS2TB RAIDiator: UPS event detected. (NAS2TB) : UPS is on battery power.\n[Wed Nov 25 10:42:44 CET 2015]
Nov 25 11:01:08 NAS2TB hidups[4697]: Unhandled event: 0x840060 (1)
Nov 25 11:01:08 NAS2TB hidups[4697]: Unhandled event: 0x84006b (0)
Nov 25 11:01:08 NAS2TB hidups[4697]: Unhandled event: 0x840060 (0)
Nov 25 11:01:08 NAS2TB hidups[4697]: Unhandled event: 0x84006b (0)
Nov 25 11:28:07 NAS2TB hidups[2809]: Startup successful
Nov 25 11:28:09 NAS2TB upsd[2816]: Connected to UPS [UPS]: hidups-hiddev0
Nov 25 11:28:09 NAS2TB upsd[2817]: Startup successful
Nov 25 11:28:10 NAS2TB upsmon[2829]: Startup successful
Nov 25 11:28:10 NAS2TB upsmon[2829]: Warning: running as one big root process by request (upsmon -p)
Nov 25 11:28:10 NAS2TB upsd[2817]: Client monuser@127.0.0.1 logged into UPS [UPS]
Nov 25 11:29:07 NAS2TB upsd[2817]: Data for UPS [UPS] is stale - check driver
Nov 25 11:29:07 NAS2TB upsd[2817]: UPS [UPS] data is no longer stale
Nov 25 11:33:51 NAS2TB hidups[2809]: UPS has been on battery power >5 seconds.
Nov 25 11:33:53 NAS2TB RAIDiator: ONBATT: UPS is on battery power. -- battery.charge: 56 battery.chemistry: PbAc battery.runtime: 876 battery.voltage: 2.3 driver.name: hidups driver.parameter.lowbatt_pct: 30 driver.version: 2.0.5 ups.mfr: EATON ups.model: Eaton 3S ups.serial: 000000000 ups.status: OB
Nov 25 11:33:54 NAS2TB RAIDiator: UPS is on battery power.
Nov 25 11:34:15 NAS2TB hidups[2809]: Unhandled event: 0x840060 (1)
Nov 25 11:34:15 NAS2TB hidups[2809]: Unhandled event: 0x84006b (0)
Nov 25 11:34:15 NAS2TB hidups[2809]: Unhandled event: 0x840060 (0)
Nov 25 11:34:15 NAS2TB hidups[2809]: Unhandled event: 0x84006b (0)
Nov 25 11:34:34 NAS2TB RAIDiator: UPS event detected. (NAS2TB) : UPS is on battery power.\n[Wed Nov 25 11:33:54 CET 2015]
Nov 25 11:36:25 NAS2TB RAIDiator: ONLINE: UPS is on line power. -- battery.charge: 51 battery.chemistry: PbAc battery.runtime: 1560 battery.voltage: 2.3 driver.name: hidups driver.parameter.lowbatt_pct: 30 driver.version: 2.0.5 ups.mfr: EATON ups.model: Eaton 3S ups.serial: 000000000 ups.status: OL
Nov 25 11:36:26 NAS2TB RAIDiator: UPS is on line power.
Nov 25 11:36:36 NAS2TB hidups[2809]: Unhandled event: 0x840060 (1)
Nov 25 11:36:36 NAS2TB hidups[2809]: Unhandled event: 0x84006b (1)
Nov 25 11:36:36 NAS2TB hidups[2809]: Unhandled event: 0x840060 (0)
Nov 25 11:36:36 NAS2TB hidups[2809]: Unhandled event: 0x84006b (0)
Nov 25 11:37:06 NAS2TB RAIDiator: UPS event detected. (NAS2TB) : UPS is on line power.\n[Wed Nov 25 11:36:26 CET 2015]

The "unhandled events" seen at 11:01, about 20 minutes after switching from mains to battery power could very well be the "I'm about to quit on you" UPS events - but they are repeated two more times at the second, shorter event which the UPS survived.

Why isn't a proper shutdown made, neither on "Auto" threshold, nor 30% manual setting?

Can anyone shed some light on this problem please?

StephenB · ‎2015-11-28

Perhaps try connecting the NAS directly to the main, and connecting an alternate load to the UPS.

Then you can unplug the UPS, and see how the NAS behaves w/o risking an unexpected shutdown.

FWIW, it does seem likely that the unhandled events have something to do with this.

Another possiblity is that the UPS power is dropping very quickly at the end, so the NAS doesn't have time to shut down.

Abrupt shutdown even though an UPS is attached

Abrupt shutdown even though an UPS is attached

Re: Abrupt shutdown even though an UPS is attached