unscheduled reboot - but it's power failure

[proto]

This week I had two power failures due to storms and my FreeNAS server suffered an unscheduled system reboot.
Actually my FreeNAS server is attached to a pfSense box via NUT and should get notification in case of power failures.
UPS model is a Riello VSD 3000, connected via usb-serial.

I need to find a better solution, because it seems unreliable in my current setup.
Should I connect my main UPS directly to me FreeNAS server or do you have any suggestions?

Meanwhile, this is what happened:

I got this email notification only *after* a system power on and working network connection:

Code:

From: me@DOMAIN.com
To: me@DOMAIN.com
Date: Thu, 23 May 2019 05:05:31 -0000
Subject: bestia.INTERNAL.prv: Unscheduled system reboot

bestia.INTERNAL.prv had an unscheduled system reboot.
The operating system successfully came back online at Thu May 23 05:05:31 2019.

I checked in /var/log/maillog and found that my ups went ONBATT @ 01:37:33, but email failed:

Code:

May 23 01:37:33 bestia /find_alias_for_smtplib.py[33334]: sending mail to me@DOMAIN.com
To: me@DOMAIN.com
Subject: UPS report generated by bestia.INTERNAL.prv

ONBATT - ups@10.10.10.1:3493
May 22 23:38:07 bestia /middlewared[310]: Failed to send email to me@DOMAIN.com: [Errno 8] hostname nor servname provided, or not known

I guess pfSense has been powered off and could not offer any services and networking... I could only check that around 01:40:00 my pfSense box stopped any activity as it had been shut down.

In /var/log/messages I can see UPS is ONLINE, so NUT didn't initiate the shutdown:

Code:

May 23 00:00:00 bestia newsyslog[27981]: logfile turned over due to size>200K
May 23 00:00:00 bestia syslog-ng[2911]: Configuration reload request received, reloading configuration;
May 23 00:00:00 bestia syslog-ng[2911]: Configuration reload finished;
May 23 01:37:32 bestia upsmon[3551]: UPS ups@10.10.10.1:3493 on battery
May 23 01:38:02 bestia upssched-cmd: Shutdown not initiated as ups.status indicates ups@10.10.10.1:3493 is ONLINE (OL)
May 23 07:05:51 bestia syslog-ng[2917]: syslog-ng starting up; version='3.20.1'
May 23 07:05:51 bestia Copyright (c) 1992-2018 The FreeBSD Project.

But /var/log/ups.log shows:

Code:

20190523 012720 100 229 10 [OL] 45 50.00
20190523 013220 100 228 10 [OL] 45 50.00
20190523 013720 100 232 10 [OL] 45 50.00      # POWER is ON
20190523 014221 76 0 14 [OB] 32 0.00             # POWER is DOWN
20190523 014720 73 0 12 [OB] 31 0.00
[...]
20190523 023720 14 0 13 [OB] 31 0.00
20190523 024220 13 0 11 [OB] 31 0.00
20190523 024720 8 0 12 [OB] 31 0.00
20190523 025220 5 0 12 [OB] 31 0.00              # @ 02:52 POWER charge is 5%
20190523 070552 22 221 10 [OL CHRG] 31 50.00    # manual power ON

But I dont't understand why /var/log/maillog is reporting this line:

Code:

May 23 05:15:38 bestia /middlewared[310]: sending mail to me@DOMAIN.com

So what I really don't realize is what time exactly FreeNAS has been shut down! Is not possible that an UPS with 5% only can sustain all that workload even if it's not "really" working at that time of the day: it's just powered on. One log (ups.log) is telling me, hey I'm dead and I have only 5%, maillog is saying I'm still alive two hours later... 05:15 - 02:52 is a big delta.
When I say all that workload is because, there are switches and other stuff connected to the UPS.

Time for middlewared.log:

Code:

[2019/05/22 23:47:32] (DEBUG) MailService.send_mail_queue():356 - Sending message from queue failed
[2019/05/22 23:57:32] (DEBUG) MailService.send_mail_queue():356 - Sending message from queue failed
[2019/05/23 00:07:33] (DEBUG) MailService.send_mail_queue():356 - Sending message from queue failed

Error is networking here: socket.gaierror: [Errno 8] hostname nor servname provided, or not known
pfSense is down, so no net!

But middlewared.log is telling more, but I don't know what happened here:

Code:

[2019/05/23 05:05:27] (DEBUG) raven.base.Client.set_dsn():265 - Configuring Raven for host: https://sentry.ixsystems.com
[2019/05/23 05:05:31] (DEBUG) middlewared.__plugins_load():809 - All plugins loaded

So probably FreeNAS has been restarted... but I don't see evidence and last is saying this:

Code:

root@bestia[~]# last | head -30
root       pts/0    10.10.20.13            Thu May 23 12:01   still logged in
root       pts/0    10.10.20.13            Thu May 23 11:41 - 11:45  (00:03)
root       pts/0    10.10.20.13            Thu May 23 08:52 - 09:08  (00:15)
root       pts/0    10.10.20.13            Thu May 23 07:34 - 07:46  (00:11)
root       pts/1                           Thu May 23 07:10 - 07:11  (00:00)
root       pts/0    10.10.20.13            Thu May 23 07:06 - 07:20  (00:14)
boot time                                  Thu May 23 07:05  ### HERE is when I pressed the button! ###
root       pts/2    10.10.20.13            Wed May 22 21:03 - 21:17  (00:13)
root       pts/0    10.10.20.13            Wed May 22 20:59 - 21:17  (00:18)
root       pts/3                           Wed May 22 17:55 - 17:55  (00:00)

No shutdown in last messages... I'm stuck, or maybe I'm a bit tired and I don't see what happened.

 

[ethereal]

i think this is a bug i had the same problem this morning and so did somebody else

https://www.ixsystems.com/community...shutting-down-freenas-after-30-seconds.76653/
https://www.ixsystems.com/community...ot-initiated-status-not-read-correctly.76655/

 

[proto]

i think this is a bug i had the same problem this morning and so did somebody else

oh! I see. And we are running U4.1 : - )

The only difference is that my FreeNAS is a SLAVE and I don't have other logs after the line Shutdown not initiated . I'm a little worried now and if my FreeNAS is a network SLAVE, it could be configured to shutdown after a NN minutes if communication is lost with the MASTER, but as far as I know we cannot edit upssched to pass custom commands directly, maybe its CMDSCRIPT /usr/local/bin/custom-upssched-cmd.

I'll try to set up my ups to reach low battery as @bluew suggested as a workaround.

Well... another oddity in debug.log:

Code:

May 25 07:08:45 bestia uwsgi: [services.forms:1383] Failed to decrypt UPS mon password
Traceback (most recent call last):
  File "./freenasUI/services/models.py", line 1381, in __init__
    self.ups_monpwd = notifier().pwenc_decrypt(self.ups_monpwd)
  File "./freenasUI/middleware/notifier.py", line 3173, in pwenc_decrypt
    encrypted = base64.b64decode(encrypted)
  File "/usr/local/lib/python3.6/base64.py", line 87, in b64decode
    return binascii.a2b_base64(s)
binascii.Error: Incorrect padding