NUT package (2.8.0 and below)

dennypage

@kevindd992002 Are these happening at start up? Or are they happening sporadically?

kevindd992002

@dennypage These happen intermittently. As an example, here are the ups and usb logs for today when there was no power interruption of any kind:

ups logs:

Nov 27 13:38:48	upsd	41381	User local-monitor@::1 logged into UPS [ups]
Nov 27 13:38:47	upsd	41381	User monuser@192.168.10.10 logged into UPS [ups]
Nov 27 13:38:47	upsd	41381	Connected to UPS [ups]: usbhid-ups-ups
Nov 27 13:38:46	upsd	41166	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:38:43	upsd	37228	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:38:42	upsd	57752	User local-monitor@::1 logged out from UPS [ups]
Nov 27 13:38:07	upsd	57752	User monuser@192.168.10.10 logged into UPS [ups]
Nov 27 13:38:03	upsd	57752	User local-monitor@::1 logged into UPS [ups]
Nov 27 13:38:03	upsd	57752	Connected to UPS [ups]: usbhid-ups-ups
Nov 27 13:38:01	upsd	57439	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:37:58	upsd	53471	Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory
Nov 27 13:37:57	upsd	12981	User local-monitor@::1 logged out from UPS [ups]

usb logs:

Nov 27 13:38:47	upsd	41381	Connected to UPS [ups]: usbhid-ups-ups
Nov 27 13:38:46	upsd	41166	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:38:43	upsd	37228	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:38:03	upsd	57752	Connected to UPS [ups]: usbhid-ups-ups
Nov 27 13:38:01	upsd	57439	Can't connect to UPS [ups] (usbhid-ups-ups): Connection refused
Nov 27 13:37:58	upsd	53471	Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory

kevindd992002

@dennypage

I tested my new UPS again and had these results:

If you check under UPS details, my battery.charge.low is set to 60% and battery.runtime.low is set to 396s. I unplugged the UPS from the wall outlet to recreate a blackout and I was expecting NUT to issue an FSD when either charge.low or runtime.low is reached, whichever comes first. But if you check the UPS Status, the actual charge is at 47% already and the runtime at 300s, yet I'm not still seeing it sending an FSD to the slaves.

The FSD was sent until the UPS' built-in "low battery" meter is reached and my Synology was notified to shutdown. Why is this?

dennypage

@kevindd992002 said in NUT package:

@dennypage These happen intermittently. As an example, here are the ups and usb logs for today when there was no power interruption of any kind:

Can't give you much guidance without the corresponding system logs. USB bus disconnects, WAN link changes, DHCP events, etc. can all cause a restart of NUT. You need to look at the entire system state of the system at the time of the event.

dennypage

@kevindd992002 Did you have ignorelb set?

kevindd992002

@dennypage no I didn't. Is it required so that the overrides will work? I thought otherwise.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

@dennypage These happen intermittently. As an example, here are the ups and usb logs for today when there was no power interruption of any kind:

Can't give you much guidance without the corresponding system logs. USB bus disconnects, WAN link changes, DHCP events, etc. can all cause a restart of NUT. You need to look at the entire system state of the system at the time of the event.

Would you want a copy of all system logs at that time frame? I'm not sure what to check specifically because I have two pfsense boxes with roughly the same settings but I only encounter it with one box that has the APC SUA750.

dennypage

@kevindd992002 said in NUT package:

@dennypage no I didn't. Is it required so that the overrides will work? I thought otherwise.

Yes. The description in the ignorelb section of the ups.conf man page tries to say this.

While the description in the documentation is somewhat vague, the code in drivers/dstate.c makes it clear:

void status_commit(void)
{
    while (ignorelb) {
        const char  *val, *low;

        val = dstate_getinfo("battery.charge");
        low = dstate_getinfo("battery.charge.low");

        if (val && low && (strtol(val, NULL, 10) < strtol(low, NULL, 10))) {
            snprintfcat(status_buf, sizeof(status_buf), " LB");
            upsdebugx(2, "%s: appending LB flag [charge '%s' below '%s']", __func__, val, low);
            break;
        }

        val = dstate_getinfo("battery.runtime");
        low = dstate_getinfo("battery.runtime.low");

        if (val && low && (strtol(val, NULL, 10) < strtol(low, NULL, 10))) {
            snprintfcat(status_buf, sizeof(status_buf), " LB");
            upsdebugx(2, "%s: appending LB flag [runtime '%s' below '%s']", __func__, val, low);
            break;
        }

        /* LB condition not detected */
        break;
    }

    if (alarm_active) {
        dstate_setinfo("ups.status", "ALARM %s", status_buf);
    } else {
        dstate_setinfo("ups.status", "%s", status_buf);
    }
}

battery.charge.low and battery.runtime.low are not used unless ignorelb is set. Probably not how I would have done it, but I don't own the code.

dennypage

@kevindd992002 Look at the system logs for the minute preceding the event. See what's going on. You should be able to identify a trigger. If you aren't having USB disconnects, then it's likely something like an interface flap or DHCP renewal.

kevindd992002

@dennypage

When NUT successfully shuts down my Synology NAS and pfsense itself, will the UPS shut down itself to conserve battery power and cut off output power to all its output terminals?
If so, when the power comes back it should automatically boot everything up as long as the devices connected to it are set to turn on when AC power comes back, right?

I did a test today:

battery.charge.low = 60 and battery.runtime.low = 396

From 100% UPS batt, unplugged input power from mains.
At around 70% UPS batt, plugged it back to mains. So far so good.
After 10 seconds, unplugged input power from mains again.
Waited for FSD to occur and it successfully shuts down both Synology and pfsense.
After pfsense shuts down, I didn't see the UPS shut itself down and the output power from the UPS was not cut (is there a delay or something?). So I decided to plug it back to mains. The Synology NAS started booting up but pfsense stayed shut down.
After 5 seconds on being on mains, the UPS just "resets" itself (output power cut off and then on again) so everything was reset also (including the Synology that was currently in booting state).

So is there something wrong with my setup here? All I have in the extra arguments field are these:

ignorelb
override.battery.charge.warning = 70
override.battery.charge.low = 60
override.battery.runtime.low = 396

I'm not sure if there's something wrong with the UPS itself or just an issue with how I have NUT configured. Please help. Thanks.

Gertjan

@kevindd992002 said in NUT package:

(5) I didn't see the UPS shut itself down and the output power from the UPS was not cut
..... The Synology NAS started booting up but pfsense stayed shut down.

Why would the Syno boot if there was no AC cut out and restore ?

the UPS just "resets" itself (output power cut off and then on again)

Interesting. I'm using several types of APC Backup Xxx myslef for many tears now, but admit I never tested these as you did. Most setups are : "shutdown - and a human will boot you again - no AC restore", but I do have an UPS protecting my pfSEnse (master) and a Syno (slave). I'll do the same test as you didi this week, and report back.

Note : my Syno doesn't return from AC. I will have to re activate it manually - or I or can "WOL" if needed using pfSense (manually or automated - by script ...).

kevindd992002

@Gertjan said in NUT package:

@kevindd992002 said in NUT package:

(5) I didn't see the UPS shut itself down and the output power from the UPS was not cut
..... The Synology NAS started booting up but pfsense stayed shut down.

Why would the Syno boot if there was no AC cut out and restore ?

That's what I don't understand too. As soon as I plugged back the mains to the UPS, thing started to act weird. This is why I was asking how much time is the delay between pfsense shutdown and UPS shutdown? I need to wait for this time before I plug the UPS back to mains.

the UPS just "resets" itself (output power cut off and then on again)

Interesting. I'm using several types of APC Backup Xxx myslef for many tears now, but admit I never tested these as you did. Most setups are : "shutdown - and a human will boot you again - no AC restore", but I do have an UPS protecting my pfSEnse (master) and a Syno (slave). I'll do the same test as you didi this week, and report back.

Note : my Syno doesn't return from AC. I will have to re activate it manually - or I or can "WOL" if needed using pfSense (manually or automated - by script ...).

Yes, please report back. Why don't you like using the "Restart automatically after a power failure" feature in your Syno?

Gertjan

@kevindd992002 said in NUT package:

Why don't you like using the "Restart automatically after a power failure" feature in your Syno?

Because when the power goes down, I like to wait with putting my devices to on. The "Power on" situation is often as bad or even worse as the "power down" moment, with my UPS in bad shape.

dennypage

@kevindd992002 Yes, there is a delay. How this works varies by UPS make/model. Some also have a restart lockout/delay. See the NUT documentation, the NUT mailing list, and your UPS documentation for information. Don’t expect to find easy/obvious answers for this as there are a lot of differences in behavior amongst the hundreds of UPS models that NUT supports.

FWIW, You are better off asking questions about general NUT And UPS behaviors on the NUT mailing list rather than in the pfSense forum.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 Yes, there is a delay. How this works varies by UPS make/model. Some also have a restart lockout/delay. See the NUT documentation, the NUT mailing list, and your UPS documentation for information. Don’t expect to find easy/obvious answers for this as there are a lot of differences in behavior amongst the hundreds of UPS models that NUT supports.

FWIW, You are better off asking questions about general NUT And UPS behaviors on the NUT mailing list rather than in the pfSense forum.

Ok, thanks.

Also, I tried recreating a shutdown sequence by issuing a /usr/local/sbin/upsmon -c fsd command in pfsense (so as to preserve battery lifetime while testing all these) but the weird thing is that my Syno doesn't seem to get a hold of the FSD event. My pfsense master and UPS shuts down properly though. As soon as I issue the FSD, the /var/log/messages in my Syno says this:

2019-12-31T02:05:03+08:00 Synology synoups: [UPS] Check Boot Status.
2019-12-31T02:05:03+08:00 Synology synoups: WARNING: UPS is On-Line

But when I recreate the shutdown sequence by unplugging the mains, all goes well and the Syno picks up the OB LB FSD event properly. Does this mean that Syno needs to see that the UPS is in OB LB state to issue a shutdown even if it sees an FSD event already?

kevindd992002

Also, why does the pfsense NUT package not contain the latest version of NUT?

dennypage

@kevindd992002 said in NUT package:

Also, why does the pfsense NUT package not contain the latest version of NUT?

The pfSense NUT package itself does not contain NUT. Instead, it has a dependency on the FreeBSD NUT package. The FreeBSD NUT package contains NUT 2.7.4, which is the latest stable version of NUT.

If you are asking why the FreeBSD NUT package is still at update 8, it is because the changes in 9-13 have no operational effect with pfSense. Where the examples go and the like just don't matter with pfSense. Eventually the package updates will be pulled in as part of general housekeeping, but there is no reason to do it otherwise.

kevindd992002

@dennypage said in NUT package:

@kevindd992002 said in NUT package:

Also, why does the pfsense NUT package not contain the latest version of NUT?

The pfSense NUT package itself does not contain NUT. Instead, it has a dependency on the FreeBSD NUT package. The FreeBSD NUT package contains NUT 2.7.4, which is the latest stable version of NUT.

If you are asking why the FreeBSD NUT package is still at update 8, it is because the changes in 9-13 have no operational effect with pfSense. Where the examples go and the like just don't matter with pfSense. Eventually the package updates will be pulled in as part of general housekeeping, but there is no reason to do it otherwise.

Ok, makes sense. Thanks.

Do you have any thoughts on my fsd question above?

kevindd992002

@dennypage, I noticed that the nut service is stopped on my pfsense box just today and I manually started it. Here are the ups logs:

Jan 22 13:16:46 	upsd 	45400 	User monuser@192.168.20.22 logged into UPS [ups]
Jan 22 13:16:43 	upsd 	45400 	User local-monitor@::1 logged into UPS [ups]
Jan 22 13:16:41 	upsd 	45400 	Startup successful
Jan 22 13:16:41 	upsd 	45398 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 13:16:41 	upsd 	45398 	listening on 127.0.0.1 port 3493
Jan 22 13:16:41 	upsd 	45398 	listening on ::1 port 3493
Jan 22 13:16:41 	upsd 	45398 	listening on 192.168.20.1 port 3493
Jan 22 13:16:41 	usbhid-ups 	45330 	Startup successful
Jan 22 13:16:40 	upsmon 	44373 	Startup successful
Jan 22 04:20:28 	upsd 	99366 	User monuser@192.168.20.22 logged into UPS [ups]
Jan 22 04:20:23 	upsd 	99366 	Startup successful
Jan 22 04:20:23 	upsd 	99032 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 04:20:23 	upsd 	99032 	listening on 127.0.0.1 port 3493
Jan 22 04:20:23 	upsd 	99032 	listening on ::1 port 3493
Jan 22 04:20:23 	upsd 	99032 	listening on 192.168.20.1 port 3493
Jan 22 04:20:22 	usbhid-ups 	95162 	Startup successful
Jan 22 04:20:22 	upsd 	87824 	User local-monitor@::1 logged into UPS [ups]
Jan 22 04:20:20 	upsd 	87824 	Startup successful
Jan 22 04:20:20 	upsd 	87506 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 04:20:20 	upsd 	87506 	listening on 127.0.0.1 port 3493
Jan 22 04:20:20 	upsd 	87506 	listening on ::1 port 3493
Jan 22 04:20:20 	upsd 	87506 	listening on 192.168.20.1 port 3493
Jan 22 04:20:19 	usbhid-ups 	81258 	Startup successful
Jan 22 04:20:19 	upsmon 	71993 	Startup successful
Jan 22 04:20:19 	usbhid-ups 	2862 	Signal 15: exiting
Jan 22 04:20:18 	upsd 	28531 	Signal 15: exiting
Jan 22 04:20:18 	upsd 	28531 	mainloop: Interrupted system call
Jan 22 04:20:18 	upsd 	28531 	User local-monitor@::1 logged out from UPS [ups]
Jan 22 04:20:18 	upsmon 	98185 	Signal 15: exiting
Jan 22 04:13:59 	upsd 	28531 	User local-monitor@::1 logged into UPS [ups]
Jan 22 04:13:58 	upsd 	28531 	User monuser@192.168.20.22 logged into UPS [ups]
Jan 22 04:13:55 	upsd 	28531 	Startup successful
Jan 22 04:13:55 	upsd 	27776 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 04:13:55 	upsd 	27776 	listening on 127.0.0.1 port 3493
Jan 22 04:13:55 	upsd 	27776 	listening on ::1 port 3493
Jan 22 04:13:55 	upsd 	27776 	listening on 192.168.20.1 port 3493
Jan 22 04:13:54 	usbhid-ups 	2862 	Startup successful
Jan 22 04:13:54 	upsmon 	97914 	Startup successful
Jan 22 04:13:52 	upsd 	90454 	Startup successful
Jan 22 04:13:52 	upsd 	90156 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 04:13:52 	upsd 	90156 	listening on 127.0.0.1 port 3493
Jan 22 04:13:52 	upsd 	90156 	listening on ::1 port 3493
Jan 22 04:13:52 	upsd 	90156 	listening on 192.168.20.1 port 3493
Jan 22 04:13:51 	usbhid-ups 	89839 	Startup successful
Jan 22 04:13:51 	upsmon 	83244 	Startup successful
Jan 22 04:13:51 	usbhid-ups 	71212 	Signal 15: exiting
Jan 22 04:13:51 	upsd 	3561 	Signal 15: exiting
Jan 22 04:13:51 	upsd 	3561 	mainloop: Interrupted system call
Jan 22 04:13:51 	upsd 	3561 	User local-monitor@::1 logged out from UPS [ups]
Jan 22 04:13:51 	upsmon 	69440 	Signal 15: exiting
Jan 22 03:59:08 	upsd 	3561 	User monuser@192.168.20.22 logged into UPS [ups]
Jan 22 03:59:08 	upsd 	3561 	User local-monitor@::1 logged into UPS [ups]
Jan 22 03:59:06 	upsd 	3561 	Startup successful
Jan 22 03:59:06 	upsd 	2944 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 03:59:06 	upsd 	2944 	listening on 127.0.0.1 port 3493
Jan 22 03:59:06 	upsd 	2944 	listening on ::1 port 3493
Jan 22 03:59:06 	upsd 	2944 	listening on 192.168.20.1 port 3493
Jan 22 03:59:05 	usbhid-ups 	71212 	Startup successful
Jan 22 03:59:05 	upsmon 	69088 	Startup successful
Jan 22 03:59:05 	upsd 	59887 	User local-monitor@::1 logged into UPS [ups]
Jan 22 03:59:03 	upsd 	59887 	Startup successful
Jan 22 03:59:03 	upsd 	59792 	Connected to UPS [ups]: usbhid-ups-ups
Jan 22 03:59:03 	upsd 	59792 	listening on 127.0.0.1 port 3493
Jan 22 03:59:03 	upsd 	59792 	listening on ::1 port 3493
Jan 22 03:59:03 	upsd 	59792 	listening on 192.168.20.1 port 3493
Jan 22 03:59:02 	usbhid-ups 	59385 	Startup successful
Jan 22 03:59:02 	upsmon 	53529 	Startup successful
Jan 22 03:59:01 	usbhid-ups 	14878 	Signal 15: exiting
Jan 22 03:59:01 	upsd 	15286 	Signal 15: exiting
Jan 22 03:59:01 	upsd 	15286 	mainloop: Interrupted system call
Jan 22 03:59:01 	upsd 	15286 	User local-monitor@::1 logged out from UPS [ups]
Jan 22 03:59:01 	upsmon 	14537 	Signal 15: exiting

Do you have any ideas as to why it suddenly stopped?

dennypage

@kevindd992002 It looks like it was restarted. Possibly as a result of an interface flap. For answers to these kinds of questions, you need to evaluate the entire system log surrounding an event, not just entries that have the string "ups" in them.