NUT package (2.8.0 and below)

cybrnook

@cybrnook you are most welcome.

It’s really nice when people say thank you.

Absolutely! It's my pleasure. Now just to figure out how to add multiple source IP's to the NAT rule, since I have 3 x clients I want to be able to phone home. Maybe it's just as simple as creating one NAT rule per IP :-) And see if you baked in "monuser" for Synology by default :-) since that will be my third.

EDIT: Synology was no problem. Just had to add monuser to the upsd.users with secret, and rename the UPS to "ups" in pfsense. Redid my Unraid systems with the same info, and it's all back online

tman222

Hi @dennypage - a big thank you from me as well! I came across a blog post today that detailed installing the NUT package on pfSense. Looking at the NUT compatibility list I saw that the the CyberPower UPS that I am using is actually supported. So I went ahead and hooked up the USB connection from the UPS to the firewall, installed the NUT package, and got everything setup and working inside pfSense. After that I also configured my Proxmox box and Synology NAS as slaves (thanks to everyone for all the great tips and advice in this thread!). Everything is working great so far. I went over two years with this same hardware not realizing that I could actually setup and utilize NUT -- very happy I found about the project today and the pfSense package.

I do have one basic quick question for everyone: When setting up NUT (e.g. slaves and on the master) how is the UPS critical battery threshold or shutdown time to determined (i.e. when connected devices are given the signal to shut down)? If this parameter adjustable in the configuration files (e.g. on the master) or is there a default value that's used? In other words, with the default out of the box NUT setup and configuration, will connected devices be given plenty of time to shut down? Thanks in advance for your help, I really appreciate it.

dennypage

@tman222 By default, the level at which shutdown will occur is under control of the ups. The ups sends a "low battery" signal, and nut initiates a shutdown.

Generally the low battery signal is sufficient for single host systems, however if you find the ups runs out of battery before shutdown completes you can override the behavior. See the nut variables "battery.charge.low"
and "battery.runtime.low".

Important note... some slaves, particularly Synology, take a long time to shutdown. After changing the runtime values, you will want to increase the "HOSTSYNC" variable. The default of 15 is far too short to allow a Synology to complete a shutdown.

Here is what I use on my server:

[Extra Arguments to driver]
override.battery.charge.low = 20
override.battery.runtime.low = 300

[Additional configuration lines for upsmon.conf]
HOSTSYNC 120

tman222

@dennypage - thanks a bunch for this additional information. I was able to find a reference to the variables you mentioned and read up a bit:

https://networkupstools.org/docs/user-manual.chunked/apcs01.html

I had a one quick follow up question: Regarding the two variables you overrode (battery.charge.low and battery.runtime.low): Is it whichever of the two occurs first that then triggers the LB state and causes NUT to issues the shutdown signal? That is to say, in your case, when the battery drops to 20% charge OR has 300 seconds of run time remaining, the LB state is triggered and NUT begins shutdown process begins?

Thanks again for the help and clarification, I really appreciate it.

dennypage

@tman222 said in NUT package:

Regarding the two variables you overrode (battery.charge.low and battery.runtime.low): Is it whichever of the two occurs first that then triggers the LB state and causes NUT to issues the shutdown signal? That is to say, in your case, when the battery drops to 20% charge OR has 300 seconds of run time remaining, the LB state is triggered and NUT begins shutdown process begins?

Thanks again for the help and clarification, I really appreciate it.

Yes, you are correct. 20% or 300 seconds, whichever happens first.

You're welcome!

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

Doing a quick test yielded a "done and passed" result for the last test result field. However, when I tried doing a deep test, the CLI returned an OK message but the UPS did nothing. Does that mean that the command is not supported by my UPS? I'm still receiving low battery message notifications in my email regarding this UPS.

Have to try it with your other UPS, but my guess would be that the UPS is declining to initiate the deep test (which usually includes a battery calibration) because it has a low battery condition. Usually a deep test will not initiate on anything other than a completely full battery.

Best suggestion that I could make is to completely power off the UPS and restart it from the ground up. If that doesn't fix it, I would say that it's likely that the UPS or battery is defective.

I have yet to test this with my other working UPS but with the problematic UPS I also get this:

So I get input voltage out of range even though the input is around 228V now, both in the UPS display and using a voltmeter. So what gives? It looks like the UPS is transferring to battery even though it shouldn't?

kevindd992002

@dennypage said in NUT package:

@kevindd992002 In your case it looks like a change of state for OpenVPN interfaces. I'm sorry I don't know much beyond this. If you want to explore more, I'd suggest asking in the General pfSense Questions or OpenVPN groups.

I'm not sure if the upsmon parent process died error was the one causing this, but my Synology NUT slave did not shutdown properly when there was a blackout earlier. I was not on-site so I'm just depending on the logs and email notifications I get. First of all, I got pfsense email notifications of the following:

ups on battery -> Sat, 15 Jun 2019 12:05:24 +0800
ups on line power -> Sat, 15 Jun 2019 12:17:22 +0800
Bootup complete -> 13:14:05

And here are the pfsense ups logs:

Jun 14 18:55:20 	upsmon 	40927 	UPS ups on battery
Jun 14 19:07:23 	upsmon 	40927 	UPS ups on line power
Jun 14 19:07:33 	upsmon 	40927 	UPS ups on battery
Jun 14 19:10:15 	upsmon 	40927 	UPS ups battery is low
Jun 14 19:10:15 	upsd 	58260 	Client local-monitor@::1 set FSD on UPS [ups]
Jun 14 20:10:29 	kernel 		ugen0.2: <American Power Conversion Back-UPS RS 1500G FW878.L4 .I USB FWL4> at usbus0
Jun 14 20:10:53 	upsd 	78154 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:10:56 	upsd 	24337 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:10:58 	upsd 	25161 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:17 	upsd 	25161 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:18 	upsd 	31254 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:21 	upsd 	24874 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:23 	upsd 	25175 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:24 	upsd 	25175 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:25 	upsd 	93544 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:28 	upsd 	84598 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:30 	upsd 	84882 	User local-monitor@127.0.0.1 logged into UPS [ups]
Jun 14 20:11:30 	upsmon 	55413 	upsmon parent process died - shutdown impossible
Jun 14 20:11:31 	upsd 	12323 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:33 	upsd 	13583 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:34 	upsd 	50344 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:36 	upsd 	52255 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:37 	upsd 	52255 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:39 	upsd 	65039 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:40 	upsd 	65095 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:42 	upsd 	75747 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:44 	upsd 	75891 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:26:07 	upsmon 	73025 	UPS ups on battery
Jun 14 20:26:17 	upsmon 	73025 	UPS ups on line power
Jun 15 13:13:40 	kernel 		ugen0.2: <American Power Conversion Back-UPS RS 1500G FW878.L4 .I USB FWL4> at usbus0
Jun 15 13:14:06 	upsd 	70280 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:10 	upsd 	99152 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:12 	upsd 	99790 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:26 	upsd 	99790 	User local-monitor@::1 logged out from UPS [ups]
Jun 15 13:14:28 	upsd 	12824 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:30 	upsd 	12827 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:31 	upsd 	24418 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:33 	upsd 	24437 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:54 	upsd 	24437 	User local-monitor@::1 logged out from UPS [ups]
Jun 15 13:14:56 	upsd 	74194 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:58 	upsd 	74325 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:59 	upsd 	90516 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:15:01 	upsd 	90761 	User local-monitor@::1 logged into UPS [ups]

As you can see, there are no logs showing that the ups changed to battery power and that initiated a shutdown. I'm assuming that the battery just drained out and did not notify any clients to gracefully shutdown, hence the improper shutdown message I got from my Synology UPS.

Any ideas regarding this?

Also, is it normal that I can't find any logs for the monuser client (the Synology NAS) connecting and disconnecting to the pfsense NUT master? I see logs like that when a Windows machine NUT service is connecting to pfsense master but not when a Synology NAS does it. Don't get me wrong though, the Synology NAS connects to it just fine and shuts down properly until today, but I never got the monuser logs.

dennypage

@kevindd992002 said in NUT package:

I have yet to test this with my other working UPS but with the problematic UPS I also get this:

So I get input voltage out of range even though the input is around 228V now, both in the UPS display and using a voltmeter. So what gives? It looks like the UPS is transferring to battery even though it shouldn't?

This in and of itself isn't problematic. Many of the UPSs I've worked with save the last reason state in perpetuity. This just means that it happened sometime in the past.

dennypage

@kevindd992002 said in NUT package:

Jun 14 19:10:15 upsmon 40927 UPS ups battery is low

There are messaging in the log... but the timestamps don't match what you had for email. If you still have the emails, check in the body of the message for the timestamp as viewed by the pfSense box when the even happened.

As to the Synology, there probably isn't enough time for it to shutdown. See the conversation with @tman222 above about HOSTSYNC.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

I have yet to test this with my other working UPS but with the problematic UPS I also get this:

So I get input voltage out of range even though the input is around 228V now, both in the UPS display and using a voltmeter. So what gives? It looks like the UPS is transferring to battery even though it shouldn't?

This in and of itself isn't problematic. Many of the UPSs I've worked with save the last reason state in perpetuity. This just means that it happened sometime in the past.

Ok, that makes sense. But if it was the battery that's causing the problem, why would it show 100% charge and yet still give me a battery low message? Cosmetics issue perhaps?

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

Jun 14 19:10:15 upsmon 40927 UPS ups battery is low

There are messaging in the log... but the timestamps don't match what you had for email. If you still have the emails, check in the body of the message for the timestamp as viewed by the pfSense box when the even happened.

As to the Synology, there probably isn't enough time for it to shutdown. See the conversation with @tman222 above about HOSTSYNC.

I should've said, the timestamp I gave you were the timestamps in the body of the emails, not the email timestamps themselves. And yes, there are messaging logs like you pointed out and I did receive separate (earlier) emails for those. For some reason, I cannot find the latest messaging logs for the events that I'm referring to but I did get email notifications about them.

As for the Synology issue, well it was shutting down and waking up correctly for the past few months until recently when this whole issue started. Could that still be because of HOSTSYNC? Also, you'd have to consider that I didn't see a message log saying that an auto shutdown was initiated at all. So naturally, the Synology NAS was not given the message to shut itself down. Here's another snippet of the logs showing more:

Jun 14 18:55:20 	upsmon 	40927 	UPS ups on battery
Jun 14 19:07:23 	upsmon 	40927 	UPS ups on line power
Jun 14 19:07:33 	upsmon 	40927 	UPS ups on battery
Jun 14 19:10:15 	upsmon 	40927 	UPS ups battery is low
Jun 14 19:10:15 	upsd 	58260 	Client local-monitor@::1 set FSD on UPS [ups]
Jun 14 19:10:15 	upsmon 	40927 	Executing automatic power-fail shutdown
Jun 14 19:10:15 	upsmon 	40927 	Auto logout and shutdown proceeding
Jun 14 20:10:54 	upsmon 	33616 	Startup successful
Jun 14 20:10:53 	usbhid-ups 	54715 	Startup successful
Jun 14 20:10:53 	upsd 	78154 	listening on 192.168.55.1 port 3493
Jun 14 20:10:53 	upsd 	78154 	listening on 192.168.10.1 port 3493
Jun 14 20:10:53 	upsd 	78154 	listening on ::1 port 3493
Jun 14 20:10:53 	upsd 	78154 	listening on 127.0.0.1 port 3493
Jun 14 20:10:53 	upsd 	78154 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:10:53 	upsd 	78876 	Startup successful
Jun 14 20:10:55 	upsmon 	74846 	Startup successful
Jun 14 20:10:56 	usbhid-ups 	5320 	Startup successful
Jun 14 20:10:56 	upsd 	24337 	listening on 192.168.55.1 port 3493
Jun 14 20:10:56 	upsd 	24337 	listening on 192.168.10.1 port 3493
Jun 14 20:10:56 	upsd 	24337 	listening on ::1 port 3493
Jun 14 20:10:56 	upsd 	24337 	listening on 127.0.0.1 port 3493
Jun 14 20:10:56 	upsd 	24337 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:10:56 	upsd 	25161 	Startup successful
Jun 14 20:10:58 	upsd 	25161 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:17 	upsmon 	75804 	Signal 15: exiting
Jun 14 20:11:17 	upsd 	25161 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:17 	upsd 	25161 	mainloop: Interrupted system call
Jun 14 20:11:17 	upsd 	25161 	Signal 15: exiting
Jun 14 20:11:17 	usbhid-ups 	5320 	Signal 15: exiting
Jun 14 20:11:17 	upsmon 	86305 	Startup successful
Jun 14 20:11:18 	usbhid-ups 	15003 	Startup successful
Jun 14 20:11:18 	upsd 	31254 	listening on 192.168.55.1 port 3493
Jun 14 20:11:18 	upsd 	31254 	listening on 192.168.10.1 port 3493
Jun 14 20:11:18 	upsd 	31254 	listening on ::1 port 3493
Jun 14 20:11:18 	upsd 	31254 	listening on 127.0.0.1 port 3493
Jun 14 20:11:18 	upsd 	31254 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:18 	upsd 	32645 	Startup successful
Jun 14 20:11:20 	upsmon 	7910 	Startup successful
Jun 14 20:11:21 	usbhid-ups 	17613 	Startup successful
Jun 14 20:11:21 	upsd 	24874 	listening on 192.168.55.1 port 3493
Jun 14 20:11:21 	upsd 	24874 	listening on 192.168.10.1 port 3493
Jun 14 20:11:21 	upsd 	24874 	listening on ::1 port 3493
Jun 14 20:11:21 	upsd 	24874 	listening on 127.0.0.1 port 3493
Jun 14 20:11:21 	upsd 	24874 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:21 	upsd 	25175 	Startup successful
Jun 14 20:11:23 	upsd 	25175 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:24 	upsmon 	8776 	Signal 15: exiting
Jun 14 20:11:24 	upsd 	25175 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:24 	upsd 	25175 	mainloop: Interrupted system call
Jun 14 20:11:24 	upsd 	25175 	Signal 15: exiting
Jun 14 20:11:24 	usbhid-ups 	17613 	Signal 15: exiting
Jun 14 20:11:24 	upsmon 	85759 	Startup successful
Jun 14 20:11:25 	usbhid-ups 	90634 	Startup successful
Jun 14 20:11:25 	upsd 	93544 	listening on 192.168.55.1 port 3493
Jun 14 20:11:25 	upsd 	93544 	listening on 192.168.10.1 port 3493
Jun 14 20:11:25 	upsd 	93544 	listening on ::1 port 3493
Jun 14 20:11:25 	upsd 	93544 	listening on 127.0.0.1 port 3493
Jun 14 20:11:25 	upsd 	93544 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:25 	upsd 	93726 	Startup successful
Jun 14 20:11:27 	upsmon 	54332 	Startup successful
Jun 14 20:11:28 	usbhid-ups 	82393 	Startup successful
Jun 14 20:11:28 	upsd 	84598 	listening on 192.168.55.1 port 3493
Jun 14 20:11:28 	upsd 	84598 	listening on 192.168.10.1 port 3493
Jun 14 20:11:28 	upsd 	84598 	listening on ::1 port 3493
Jun 14 20:11:28 	upsd 	84598 	listening on 127.0.0.1 port 3493
Jun 14 20:11:28 	upsd 	84598 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:28 	upsd 	84882 	Startup successful
Jun 14 20:11:30 	upsd 	84882 	User local-monitor@127.0.0.1 logged into UPS [ups]
Jun 14 20:11:30 	upsmon 	55413 	upsmon parent process died - shutdown impossible
Jun 14 20:11:30 	upsmon 	55413 	Parent died - shutdown impossible
Jun 14 20:11:30 	upsd 	84882 	mainloop: Interrupted system call
Jun 14 20:11:30 	upsd 	84882 	Signal 15: exiting
Jun 14 20:11:30 	usbhid-ups 	82393 	Signal 15: exiting
Jun 14 20:11:30 	upsmon 	50205 	Startup successful
Jun 14 20:11:31 	usbhid-ups 	96450 	Startup successful
Jun 14 20:11:31 	upsd 	12323 	listening on 192.168.55.1 port 3493
Jun 14 20:11:31 	upsd 	12323 	listening on 192.168.10.1 port 3493
Jun 14 20:11:31 	upsd 	12323 	listening on ::1 port 3493
Jun 14 20:11:31 	upsd 	12323 	listening on 127.0.0.1 port 3493
Jun 14 20:11:31 	upsd 	12323 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:31 	upsd 	13583 	Startup successful
Jun 14 20:11:33 	upsd 	13583 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:33 	upsmon 	23508 	Startup successful
Jun 14 20:11:34 	usbhid-ups 	29129 	Startup successful
Jun 14 20:11:34 	upsd 	50344 	listening on 192.168.55.1 port 3493
Jun 14 20:11:34 	upsd 	50344 	listening on 192.168.10.1 port 3493
Jun 14 20:11:34 	upsd 	50344 	listening on ::1 port 3493
Jun 14 20:11:34 	upsd 	50344 	listening on 127.0.0.1 port 3493
Jun 14 20:11:34 	upsd 	50344 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:34 	upsd 	52255 	Startup successful
Jun 14 20:11:36 	upsd 	52255 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:37 	upsmon 	23951 	Signal 15: exiting
Jun 14 20:11:37 	upsd 	52255 	User local-monitor@::1 logged out from UPS [ups]
Jun 14 20:11:37 	upsd 	52255 	mainloop: Interrupted system call
Jun 14 20:11:37 	upsd 	52255 	Signal 15: exiting
Jun 14 20:11:37 	usbhid-ups 	29129 	Signal 15: exiting
Jun 14 20:11:37 	upsmon 	55886 	Startup successful
Jun 14 20:11:38 	usbhid-ups 	64728 	Startup successful
Jun 14 20:11:39 	upsd 	65039 	listening on 192.168.55.1 port 3493
Jun 14 20:11:39 	upsd 	65039 	listening on 192.168.10.1 port 3493
Jun 14 20:11:39 	upsd 	65039 	listening on ::1 port 3493
Jun 14 20:11:39 	upsd 	65039 	listening on 127.0.0.1 port 3493
Jun 14 20:11:39 	upsd 	65039 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:39 	upsd 	65095 	Startup successful
Jun 14 20:11:40 	upsd 	65095 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:11:41 	upsmon 	72255 	Startup successful
Jun 14 20:11:41 	usbhid-ups 	74310 	Startup successful
Jun 14 20:11:42 	upsd 	75747 	listening on 192.168.55.1 port 3493
Jun 14 20:11:42 	upsd 	75747 	listening on 192.168.10.1 port 3493
Jun 14 20:11:42 	upsd 	75747 	listening on ::1 port 3493
Jun 14 20:11:42 	upsd 	75747 	listening on 127.0.0.1 port 3493
Jun 14 20:11:42 	upsd 	75747 	Connected to UPS [ups]: usbhid-ups-ups
Jun 14 20:11:42 	upsd 	75891 	Startup successful
Jun 14 20:11:44 	upsd 	75891 	User local-monitor@::1 logged into UPS [ups]
Jun 14 20:26:07 	upsmon 	73025 	UPS ups on battery
Jun 14 20:26:17 	upsmon 	73025 	UPS ups on line power
Jun 15 13:14:07 	upsmon 	57800 	Startup successful
Jun 15 13:14:07 	usbhid-ups 	59029 	Startup successful
Jun 15 13:14:06 	upsd 	70280 	listening on 192.168.55.1 port 3493
Jun 15 13:14:06 	upsd 	70280 	listening on 192.168.10.1 port 3493
Jun 15 13:14:06 	upsd 	70280 	listening on ::1 port 3493
Jun 15 13:14:06 	upsd 	70280 	listening on 127.0.0.1 port 3493
Jun 15 13:14:06 	upsd 	70280 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:06 	upsd 	70814 	Startup successful
Jun 15 13:14:08 	upsmon 	55711 	Startup successful
Jun 15 13:14:09 	usbhid-ups 	85269 	Startup successful
Jun 15 13:14:10 	upsd 	99152 	listening on 192.168.55.1 port 3493
Jun 15 13:14:10 	upsd 	99152 	listening on 192.168.10.1 port 3493
Jun 15 13:14:10 	upsd 	99152 	listening on ::1 port 3493
Jun 15 13:14:10 	upsd 	99152 	listening on 127.0.0.1 port 3493
Jun 15 13:14:10 	upsd 	99152 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:10 	upsd 	99790 	Startup successful
Jun 15 13:14:12 	upsd 	99790 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:26 	upsmon 	55752 	Signal 15: exiting
Jun 15 13:14:26 	upsd 	99790 	User local-monitor@::1 logged out from UPS [ups]
Jun 15 13:14:26 	upsd 	99790 	mainloop: Interrupted system call
Jun 15 13:14:26 	upsd 	99790 	Signal 15: exiting
Jun 15 13:14:26 	usbhid-ups 	85269 	Signal 15: exiting
Jun 15 13:14:27 	upsmon 	4336 	Startup successful
Jun 15 13:14:27 	usbhid-ups 	12301 	Startup successful
Jun 15 13:14:28 	upsd 	12824 	listening on 192.168.55.1 port 3493
Jun 15 13:14:28 	upsd 	12824 	listening on 192.168.10.1 port 3493
Jun 15 13:14:28 	upsd 	12824 	listening on ::1 port 3493
Jun 15 13:14:28 	upsd 	12824 	listening on 127.0.0.1 port 3493
Jun 15 13:14:28 	upsd 	12824 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:28 	upsd 	12827 	Startup successful
Jun 15 13:14:30 	upsd 	12827 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:30 	upsmon 	20757 	Startup successful
Jun 15 13:14:30 	usbhid-ups 	23572 	Startup successful
Jun 15 13:14:31 	upsd 	24418 	listening on 192.168.55.1 port 3493
Jun 15 13:14:31 	upsd 	24418 	listening on 192.168.10.1 port 3493
Jun 15 13:14:31 	upsd 	24418 	listening on ::1 port 3493
Jun 15 13:14:31 	upsd 	24418 	listening on 127.0.0.1 port 3493
Jun 15 13:14:31 	upsd 	24418 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:31 	upsd 	24437 	Startup successful
Jun 15 13:14:33 	upsd 	24437 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:54 	upsmon 	22016 	Signal 15: exiting
Jun 15 13:14:54 	upsd 	24437 	User local-monitor@::1 logged out from UPS [ups]
Jun 15 13:14:54 	upsd 	24437 	mainloop: Interrupted system call
Jun 15 13:14:54 	upsd 	24437 	Signal 15: exiting
Jun 15 13:14:54 	usbhid-ups 	23572 	Signal 15: exiting
Jun 15 13:14:55 	upsmon 	70818 	Startup successful
Jun 15 13:14:55 	usbhid-ups 	72602 	Startup successful
Jun 15 13:14:56 	upsd 	74194 	listening on 192.168.55.1 port 3493
Jun 15 13:14:56 	upsd 	74194 	listening on 192.168.10.1 port 3493
Jun 15 13:14:56 	upsd 	74194 	listening on ::1 port 3493
Jun 15 13:14:56 	upsd 	74194 	listening on 127.0.0.1 port 3493
Jun 15 13:14:56 	upsd 	74194 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:56 	upsd 	74325 	Startup successful
Jun 15 13:14:58 	upsd 	74325 	User local-monitor@::1 logged into UPS [ups]
Jun 15 13:14:58 	upsmon 	87512 	Startup successful
Jun 15 13:14:58 	usbhid-ups 	90187 	Startup successful
Jun 15 13:14:59 	upsd 	90516 	listening on 192.168.55.1 port 3493
Jun 15 13:14:59 	upsd 	90516 	listening on 192.168.10.1 port 3493
Jun 15 13:14:59 	upsd 	90516 	listening on ::1 port 3493
Jun 15 13:14:59 	upsd 	90516 	listening on 127.0.0.1 port 3493
Jun 15 13:14:59 	upsd 	90516 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 13:14:59 	upsd 	90761 	Startup successful
Jun 15 13:15:01 	upsd 	90761 	User local-monitor@::1 logged into UPS [ups]
Jun 15 18:25:18 	upsmon 	88045 	Signal 15: exiting
Jun 15 18:25:18 	upsd 	90761 	User local-monitor@::1 logged out from UPS [ups]
Jun 15 18:25:18 	upsd 	90761 	mainloop: Interrupted system call
Jun 15 18:25:18 	upsd 	90761 	Signal 15: exiting
Jun 15 18:25:18 	upsmon 	60536 	Startup successful
Jun 15 18:25:19 	usbhid-ups 	62298 	Startup successful
Jun 15 18:25:20 	upsd 	62515 	listening on 192.168.55.1 port 3493
Jun 15 18:25:20 	upsd 	62515 	listening on 192.168.10.1 port 3493
Jun 15 18:25:20 	upsd 	62515 	listening on ::1 port 3493
Jun 15 18:25:20 	upsd 	62515 	listening on 127.0.0.1 port 3493
Jun 15 18:25:20 	upsd 	62515 	Connected to UPS [ups]: usbhid-ups-ups
Jun 15 18:25:20 	upsd 	62558 	Startup successful
Jun 15 18:25:21 	upsd 	62558 	User local-monitor@::1 logged into UPS [ups]

You can see that I had an auto shutdown even occur here:

Jun 14 19:10:15 	upsmon 	40927 	Executing automatic power-fail shutdown
Jun 14 19:10:15 	upsmon 	40927 	Auto logout and shutdown proceeding

But I didn't get those logs for the June 15 event that I'm talking about.

dennypage

@kevindd992002 said in NUT package:

Jun 14 18:55:20 upsmon 40927 UPS ups on battery
Jun 14 19:07:23 upsmon 40927 UPS ups on line power
Jun 14 19:07:33 upsmon 40927 UPS ups on battery
Jun 14 19:10:15 upsmon 40927 UPS ups battery is low

Also possible that the UPS killed the mains before shutdown completed. You may want to up the battery runtime/charge low values.

You definitely want to have a higher HOSTSYNC to give the Synology time for shutdown.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

Jun 14 18:55:20 upsmon 40927 UPS ups on battery
Jun 14 19:07:23 upsmon 40927 UPS ups on line power
Jun 14 19:07:33 upsmon 40927 UPS ups on battery
Jun 14 19:10:15 upsmon 40927 UPS ups battery is low

Also possible that the UPS killed the mains before shutdown completed. You may want to up the battery runtime/charge low values.

You definitely want to have a higher HOSTSYNC to give the Synology time for shutdown.

Regardless though, shouldn't I see an auto shutdown message when NUT reaches the cutoff charge level?

So 120 for HOSTSYNC would be recommended for Synology? What does that parameter really do anyway?

dennypage

@kevindd992002 said in NUT package:

Regardless though, shouldn't I see an auto shutdown message when NUT reaches the cutoff charge level?

It shows a low battery situation, but the UPS could have cut the mains before pfSense had opportunity to perform a shutdown. Was the battery depleted from a prior event perhaps?

So 120 for HOSTSYNC would be recommended for Synology? What does that parameter really do anyway?

HOSTSYNC is how many seconds the master will wait for slaves to initiate their shutdown and disconnect from the master. See the documentation for upsmon.conf for more information.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

Regardless though, shouldn't I see an auto shutdown message when NUT reaches the cutoff charge level?

It shows a low battery situation, but the UPS could have cut the mains before pfSense had opportunity to perform a shutdown. Was the battery depleted from a prior event perhaps?

So 120 for HOSTSYNC would be recommended for Synology? What does that parameter really do anyway?

HOSTSYNC is how many seconds the master will wait for slaves to initiate their shutdown and disconnect from the master. See the documentation for upsmon.conf for more information.

What do you mean by "it shows a low battery situation"? I don't see that in the June 15 logs. Sorry I'm confused. The UPS started charging (on online power) since June 14 8:26PM so I'm pretty sure it's fully charged by the it notified me via email on June 15 12:00PM. I also asked my relatives which are on-site and they confirmed that electricity only went out once on June 15.

dennypage

@kevindd992002 said in NUT package:

What do you mean by "it shows a low battery situation"? I don't see that in the June 15 logs. Sorry I'm confused. The UPS started charging (on online power) since June 14 8:26PM so I'm pretty sure it's fully charged by the it notified me via email on June 15 12:00PM. I also asked my relatives which are on-site and they confirmed that electricity only went out once on June 15.

Sorry, was reading low battery situation on the 14th.

Most likely guess regarding the 15th is that the UPS failed the mains before the system properly flushed the disk log.

Things I would suggest:

If the battery is over three years old, replace it.
If the battery has been through two hundred discharge cycles or more, replace it.
Perform a battery health check (long self test).
Perform a run-time calibration (note this counts as a cycle).
Raise the values for charge.low and runtime.low.

If power outages are common, I would go very high on charge.low (50 or more). Remember that regardless of age, a battery will only last 200 discharge cycles or so, so the higher you set the value the longer your battery will last.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

What do you mean by "it shows a low battery situation"? I don't see that in the June 15 logs. Sorry I'm confused. The UPS started charging (on online power) since June 14 8:26PM so I'm pretty sure it's fully charged by the it notified me via email on June 15 12:00PM. I also asked my relatives which are on-site and they confirmed that electricity only went out once on June 15.

Sorry, was reading low battery situation on the 14th.

Most likely guess regarding the 15th is that the UPS failed the mains before the system properly flushed the disk log.

Things I would suggest:

If the battery is over three years old, replace it.

If the battery has been through two hundred discharge cycles or more, replace it.

Perform a battery health check (long self test).

Perform a run-time calibration (note this counts as a cycle).

Raise the values for charge.low and runtime.low.

If power outages are common, I would go very high on charge.low (50 or more). Remember that regardless of age, a battery will only last 200 discharge cycles or so, so the higher you set the value the longer your battery will last.

The battery is less than a year old and I doubt it had already gone to two hundred discharge cycles. The power outages are more frequent than what I would like them to be, yes, but not very frequent to render the batteries useless in less than a year. But yeah, I'll probably do some tests first by changing the charge.low and runtime.low. I had multiple notifications again these past few days and I'm still encountering the same issue. Here's another example of my pfsense logs:

Jun 16 16:24:38 	upsd 	19563 	User local-monitor@::1 logged into UPS [ups]
Jun 16 16:25:33 	upsd 	19563 	User local-monitor@::1 logged out from UPS [ups]
Jun 16 16:28:35 	kernel 		ugen0.2: <American Power Conversion Back-UPS RS 1500G FW878.L4 .I USB FWL4> at usbus0
Jun 16 16:29:05 	upsd 	58612 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:29:08 	upsd 	60154 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:29:10 	upsd 	61918 	User local-monitor@::1 logged into UPS [ups]
Jun 16 16:29:24 	upsd 	61918 	User local-monitor@::1 logged out from UPS [ups]
Jun 16 16:29:25 	upsd 	61474 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:29:28 	upsd 	73800 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:29:30 	upsd 	74128 	User local-monitor@::1 logged into UPS [ups]
Jun 16 16:29:55 	upsd 	74128 	User local-monitor@::1 logged out from UPS [ups]
Jun 16 16:29:56 	upsd 	24686 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:29:59 	upsd 	39315 	Connected to UPS [ups]: usbhid-ups-ups
Jun 16 16:30:01 	upsd 	39480 	User local-monitor@::1 logged into UPS [ups]
Jun 22 11:00:26 	upsmon 	37375 	UPS ups on battery
Jun 22 11:00:31 	upsmon 	37375 	UPS ups on line power
Jun 22 17:03:06 	upsmon 	37375 	UPS ups on battery
Jun 22 17:03:16 	upsmon 	37375 	UPS ups on line power
Jun 22 17:43:38 	upsmon 	37375 	UPS ups on battery
Jun 22 17:43:43 	upsmon 	37375 	UPS ups on line power
Jun 23 09:09:32 	upsmon 	37375 	UPS ups on battery
Jun 23 09:28:27 	upsmon 	37375 	UPS ups battery is low
Jun 23 09:28:27 	upsd 	39480 	Client local-monitor@::1 set FSD on UPS [ups]
Jun 23 12:48:03 	kernel 		ugen0.2: <American Power Conversion Back-UPS RS 1500G FW878.L4 .I USB FWL4> at usbus0
Jun 23 12:48:28 	upsd 	80605 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:48:31 	upsd 	62181 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:48:33 	upsd 	63842 	User local-monitor@::1 logged into UPS [ups]
Jun 23 12:48:50 	upsd 	63842 	User local-monitor@::1 logged out from UPS [ups]
Jun 23 12:48:51 	upsd 	6953 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:48:54 	upsd 	29664 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:48:56 	upsd 	32261 	User local-monitor@::1 logged into UPS [ups]
Jun 23 12:49:01 	upsd 	32261 	User local-monitor@::1 logged out from UPS [ups]
Jun 23 12:49:02 	upsd 	99676 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:05 	upsd 	51055 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:06 	upsd 	52551 	User local-monitor@127.0.0.1 logged into UPS [ups]
Jun 23 12:49:06 	upsmon 	40995 	upsmon parent process died - shutdown impossible
Jun 23 12:49:07 	upsd 	3258 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:10 	upsd 	10461 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:11 	upsd 	11087 	User local-monitor@127.0.0.1 logged into UPS [ups]
Jun 23 12:49:11 	upsmon 	59547 	upsmon parent process died - shutdown impossible
Jun 23 12:49:12 	upsd 	6285 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:15 	upsd 	50671 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:17 	upsd 	50757 	User local-monitor@::1 logged into UPS [ups]
Jun 23 12:49:18 	upsd 	50757 	User local-monitor@::1 logged out from UPS [ups]
Jun 23 12:49:19 	upsd 	74517 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:21 	upsd 	74650 	User local-monitor@::1 logged into UPS [ups]
Jun 23 12:49:22 	upsd 	1480 	Connected to UPS [ups]: usbhid-ups-ups
Jun 23 12:49:24 	upsd 	2139 	User local-monitor@::1 logged into UPS [ups]
Jun 23 13:09:43 	upsmon 	81543 	UPS ups on battery
Jun 23 13:09:48 	upsmon 	81543 	UPS ups on line power

Then I receive this in my email:

Sun, 23 Jun 2019 09:28:28 +0800

Auto logout and shutdown proceeding

But in the Synology NAS logs, I see an improper shutdown event for this time. So something's not right because the NAS is not shutting down properly even though I have HOSTSYNC set to 120 already.

Also, is it normal that I can't find any logs for the monuser client (the Synology NAS) connecting and disconnecting to the pfsense NUT master? I see logs like that when a Windows machine NUT service is connecting to pfsense master but not when a Synology NAS does it. Don't get me wrong though, the Synology NAS connects to it just fine and shuts down properly until today, but I never got the monuser logs.

EDIT:

Look at my Synology logs:

So it's interesting that I no longer see a Power supply event that the ups entered battery mode/returned to AC mode/etc. This explains why the NAS isn't shutting down properly. It's not receiving the appropriate signals from the NUT master even though I completely see it connected in the "Device Information" section like so:

What other things can I do to troubleshoot this then?

kevindd992002

@dennypage

Any other ideas to try?

dennypage

@kevindd992002 Sorry, I'm getting ready for a long distance move and haven't had much time lately.

The lack of entries in the pfSense system log regarding the remote client would indicate that the Synology isn't actually connecting to upsd on pfSense. You can do a reboot on your Synology to confirm. You should see log out/in messages in the pfSense system log each time.

Another way to confirm... stop the ups service on pfSense. The Synology should get upset and start sending emails complaining that the ups isn't available.

Lastly, if memory serves, there is a setting in the Synology that allows you to have the Synology shutdown with the server or after a given period of time. If it's not set to match the server then the Synology will ignore the FSD signal from the server.

I haven't had time to set up an experiment with my Synology to see if later versions of DSM have mucked up the nut implementation in some way.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 Sorry, I'm getting ready for a long distance move and haven't had much time lately.

The lack of entries in the pfSense system log regarding the remote client would indicate that the Synology isn't actually connecting to upsd on pfSense. You can do a reboot on your Synology to confirm. You should see log out/in messages in the pfSense system log each time.

Another way to confirm... stop the ups service on pfSense. The Synology should get upset and start sending emails complaining that the ups isn't available.

Lastly, if memory serves, there is a setting in the Synology that allows you to have the Synology shutdown with the server or after a given period of time. If it's not set to match the server then the Synology will ignore the FSD signal from the server.

I haven't had time to set up an experiment with my Synology to see if later versions of DSM have mucked up the nut implementation in some way.

Ok, I just tested this. I stopped the ups service on pfsense and confirmed that the Synology had this message:

You can also see that my UPS setting there is set to "same as server" so it should follow the signal from pfsense.

BUT, I never got any email notification regarding the UPS being disconnected. I'm sure that my notification settings in Synology are working (test email, DSM update notification, etc. are all being received regularly). My notification settings are also set to these:

I then checked my Inbox and it looks like that last message I received from Synology regarding "entering battery mode" was last June 4 even though there were already several power disruptions from that time until now. So there's really something going on with how NUT and Synology is communicating. I just had another power interruption 3 days ago and when I checked the Synology logs I see "improper shutdown" events again even though I already have HOSTSYNC set to 120.

I also checked the Synology logs and it looks like that last "entered in battery mode" event that I see there was also last June 4 which was consistent with the email notification I got.

When do you think will you have time to experiment with the Synology? I can do more tests if you need me to. Just let me know what to do.

Thanks for all the help and good luck with your move!

dennypage

@kevindd992002 It will be a while before I can truly experiment. I won't actually have a UPS again for several weeks.

However, I just brought my Synology up and noticed that I didn't not receive an email indicating that the nut server was not available. Previously I always received notification from the Synology when the nut server went offline so there may indeed be an issue with newer the DSM versions.