NUT Package (2.8.1 and above)

evert

@dennypage said in NUT Package (2.8.1 and above):

@evert said in NUT Package (2.8.1 and above):

@
Can you tell me where I can get the previous package? I'm on 23.05.1 and upgraded NUT to 2.8.2 yesterday. Package management let me do this, even though NUT 2.8.2 apparently doesn't work with 23.05.1. Result: a busted nut...
(I'll upgrade to 23.09 soon, but I can't do this during office hours)

It shouldn’t show up in 23.05.1. Did you switch update streams? Best I can suggest is to remove the package and reinstall.

We are on the regular 'Latest Stable Version' branch. Ah well, I came in early today and updated the whole thing to 23.09 and that resolved my issues

And... Lo and behold! Our UPS is finally having a proper connection to the pfSense box

evert

A bit confused by the versioning: pfSense now has nut 2.8.2, but the official NUT release is 2.8.1 if I interpret this page correctly.

What happens when the official NUT release hits 2.8.2?

dennypage

@evert Yea, we had a little oops at the end, and a commit went in that should not have. The published version of the pfSense package itself shows as 2.8.2. By the time I discovered it, it was too late to change it.

It should stay 2.8.2 (2.8.2_1, 2.8.2_2, 2.8.2_3...) until 2.8.3 or 3.0.0 is released.

Unoptanio

@dennypage

Good morning,
I updated to pfsense 2.7.1 with Nut ver 2.8.2

The quirk is always inserted in the boot loader.
hw.usb.quirk.0="0x04b4 0x5500 0x0000 0xffff UQ_HID_IGNORE"

I confirm that the Riello VST1100 UPS is working well without disconnection of the USB port

Soon I will also let you know for the "Riello Sentinel Pro 2200" and "Riello Sentinel Dual SDU 6Kw" models

For Riello VST1100:

UPS Detail

This table contains all the variables reported by the UPS via the upsc command. Note that many UPSs report only a subset of the available variables. Also note that some UPSs, particularly those using usbhid, may report an incorrect value for a variable. This is generally not a cause for concern. For additional information, see the Network UPS Tools site

Variable	Value
battery.capacity	9
battery.charge	100
battery.runtime	5940
battery.voltage	27.4
battery.voltage.nominal	24
device.mfr	RPS S.p.a.
device.model	ULC2
device.serial	
device.type	ups
driver.debug	0
driver.flag.allow_killpower	0
driver.name	riello_usb
driver.parameter.pollinterval	2
driver.parameter.port	auto
driver.parameter.synchronous	auto
driver.state	updateinfo
driver.version	2.8.0.1
driver.version.internal	0.10
driver.version.usb	libusb-1.0.0 (API: 0x1000102)
input.bypass.frequency	50.00
input.bypass.voltage	230
input.frequency	50.00
input.voltage	230
output.frequency	50.00
output.frequency.nominal	50.0
output.L1.current	0
output.L1.power	0
output.L1.realpower	0
output.L2.current	0
output.L2.power	0
output.L2.realpower	0
output.L3.current	0
output.L3.power	0
output.L3.realpower	0
output.power.percent	12
output.voltage	230
output.voltage.nominal	230
ups.delay.reboot	5
ups.delay.shutdown	5
ups.firmware	SWM039-01-04
ups.load	12
ups.mfr	RPS S.p.a.
ups.model	ULC2
ups.power.nominal	1100
ups.productid	5500
ups.realpower.nominal	880
ups.serial	
ups.status	OL
ups.temperature	42
ups.vendorid	04b4

mlake

Version info:
pfSense: 23.09-RELEASE (amd64)
nut: 2.8.2

I'm running into a strange issue with NUT/upsmon where, when my remote OpenVPN tunnel reconnects (pfSense acting as the client), the router briefly loses connection to my USB-connected UPS and I receive emails like the following from the router:

Notifications in this message: 1
================================

10:17:29 UPS Notification from [PFSENSE_FQDN] - Sun, 03 Dec 2023 10:17:29 -0600

Communications with UPS ups lost

Notifications in this message: 2
================================

10:17:33 UPS Notification from [PFSENSE_FQDN] - Sun, 03 Dec 2023 10:17:33 -0600

Communications with UPS ups lost
10:17:38 UPS Notification from [PFSENSE_FQDN] - Sun, 03 Dec 2023 10:17:38 -0600

Communications with UPS ups established

And here's the relevant portion of the System Log from the same time:

Dec 3 10:17:16	php-fpm	405	/vpn_openvpn_client.php: Configuration Change: [USER]@172.17.37.5 (Local Database): Updated OpenVPN client to server [OPENVPN_REMOTE_SERVER]:1194 RemoteVPN
Dec 3 10:17:17	check_reload_status	446	Syncing firewall
Dec 3 10:17:17	php-fpm	405	OpenVPN terminate old pid: 58538
Dec 3 10:17:18	kernel		ovpnc2: link state changed to DOWN
Dec 3 10:17:18	check_reload_status	446	Reloading filter
Dec 3 10:17:18	php-fpm	405	OpenVPN PID written: 80663
Dec 3 10:17:18	check_reload_status	446	Reloading filter
Dec 3 10:17:23	kernel		ovpnc2: link state changed to UP
Dec 3 10:17:23	check_reload_status	446	rc.newwanip starting ovpnc2
Dec 3 10:17:24	php-fpm	50903	/rc.newwanip: rc.newwanip: Info: starting on ovpnc2.
Dec 3 10:17:24	php-fpm	50903	/rc.newwanip: rc.newwanip: on (IP address: [OVPN_REMOTE_IP]) (interface: REMOTE_VPN[opt5]) (real interface: ovpnc2).
Dec 3 10:17:25	php-fpm	50903	/rc.newwanip: Removing static route for monitor 1.0.0.1 and adding a new route through [OVPN_REMOTE_GW]
Dec 3 10:17:26	php-fpm	50903	/rc.newwanip: The command '/sbin/route -n6 get 'default' 2>/dev/null | /usr/bin/egrep 'flags: <.*PROTO.*>'' returned exit code '1', the output was ''
Dec 3 10:17:26	php-fpm	50903	/rc.newwanip: Creating rrd update script
Dec 3 10:17:28	php-fpm	50903	/rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - [OVPN_REMOTE_IP] -> [OVPN_REMOTE_IP] - Restarting packages.
Dec 3 10:17:28	check_reload_status	446	Starting packages
Dec 3 10:17:28	check_reload_status	446	Reloading filter
Dec 3 10:17:28	snmpd	76516	disk_OS_get_disks: adding device 'mmcsd0boot1' to device list
Dec 3 10:17:28	snmpd	76516	disk_OS_get_disks: adding device 'mmcsd0boot0' to device list
Dec 3 10:17:29	php-fpm	405	/rc.start_packages: Restarting/Starting all packages.
Dec 3 10:17:29	php-fpm	405	/rc.start_packages: Stopping service nut
Dec 3 10:17:29	upsmon	37971	Signal 15: exiting
Dec 3 10:17:29	upsd	22980	User local-monitor@127.0.0.1 logged out from UPS [ups]
Dec 3 10:17:29	upsd	22980	mainloop: Interrupted system call
Dec 3 10:17:29	upsd	22980	Signal 15: exiting
Dec 3 10:17:29	usbhid-ups	54011	Signal 15: exiting
Dec 3 10:17:29	php-fpm	405	/rc.start_packages: Starting service nut
Dec 3 10:17:29	upsmon	94129	Startup successful
Dec 3 10:17:29	upsmon	94715	UPS [ups]: connect failed: Connection failure: Connection refused
Dec 3 10:17:29	upsmon	94715	Communications with UPS ups lost
Dec 3 10:17:29	usbhid-ups	3404	Startup successful
Dec 3 10:17:30	upsd	64401	listening on 127.0.0.1 port 3493
Dec 3 10:17:30	upsd	64401	listening on ::1 port 3493
Dec 3 10:17:30	upsd	64401	not listening on 127.0.0.1 port 3493
Dec 3 10:17:30	upsd	64401	listening on 172.17.37.1 port 3493
Dec 3 10:17:30	upsd	64401	Connected to UPS [ups]: usbhid-ups-ups
Dec 3 10:17:30	upsd	64401	Found 1 UPS defined in ups.conf
Dec 3 10:17:30	upsd	64746	Startup successful
Dec 3 10:17:31	php-cgi	30150	notify_monitor.php: Message sent to [EMAIL_ADDRESS] OK
Dec 3 10:17:32	upsmon	69466	Startup successful
Dec 3 10:17:32	upsmon	70265	UPS [ups]: connect failed: Connection failure: Connection refused
Dec 3 10:17:32	upsmon	70265	Communications with UPS ups lost
Dec 3 10:17:32	php-fpm	405	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Dec 3 10:17:32	check_reload_status	446	Syncing firewall
Dec 3 10:17:33	usbhid-ups	83567	Startup successful
Dec 3 10:17:33	php-fpm	405	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules
Dec 3 10:17:33	check_reload_status	446	Syncing firewall
Dec 3 10:17:33	upsd	53148	listening on 127.0.0.1 port 3493
Dec 3 10:17:33	upsd	53148	listening on ::1 port 3493
Dec 3 10:17:33	upsd	53148	not listening on 127.0.0.1 port 3493
Dec 3 10:17:33	upsd	53148	listening on 172.17.37.1 port 3493
Dec 3 10:17:33	upsd	53148	Connected to UPS [ups]: usbhid-ups-ups
Dec 3 10:17:33	upsd	53148	Found 1 UPS defined in ups.conf
Dec 3 10:17:33	upsd	53361	Startup successful
Dec 3 10:17:33	check_reload_status	446	Reloading filter
Dec 3 10:17:33	tail_pfb	54842	[pfBlockerNG] Firewall Filter Service stopped
Dec 3 10:17:33	php_pfb	55146	[pfBlockerNG] filterlog daemon stopped
Dec 3 10:17:33	php-fpm	405	[pfBlockerNG] Restarting firewall filter daemon
Dec 3 10:17:33	tail_pfb	57941	[pfBlockerNG] Firewall Filter Service stopped
Dec 3 10:17:33	php_pfb	58420	[pfBlockerNG] filterlog daemon stopped
Dec 3 10:17:33	tail_pfb	60618	[pfBlockerNG] Firewall Filter Service started
Dec 3 10:17:34	php_pfb	61034	[pfBlockerNG] filterlog daemon started
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed earlyshellcmd(s).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Installed earlyshellcmd(s).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed interface group (WireGuard).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Installed interface group (WireGuard).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] De-installed Unbound ACL group (WireGuard).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Installed Unbound ACL group (WireGuard).
Dec 3 10:17:34	php-fpm	405	/rc.start_packages: Configuration Change: (system): [pfSense-pkg-WireGuard] Applied package default settings as necessary.
Dec 3 10:17:34	check_reload_status	446	Syncing firewall
Dec 3 10:17:34	tail_pfb	73724	[pfBlockerNG] Firewall Filter Service stopped
Dec 3 10:17:34	php_pfb	74675	[pfBlockerNG] filterlog daemon stopped
Dec 3 10:17:35	tail_pfb	77851	[pfBlockerNG] Firewall Filter Service started
Dec 3 10:17:35	php_pfb	77971	[pfBlockerNG] filterlog daemon started
Dec 3 10:17:35	upsd	53361	User monuser@172.17.37.4 logged into UPS [ups]
Dec 3 10:17:37	upsd	53361	User monuser@172.17.37.50 logged into UPS [ups]
Dec 3 10:17:37	upsd	53361	User local-monitor@127.0.0.1 logged into UPS [ups]
Dec 3 10:17:37	upsmon	70265	Communications with UPS ups established
Dec 3 10:18:03	php-cgi	30150	notify_monitor.php: Message sent to [EMAIL_ADDRESS] OK

I am able to 100% reproduce this by restarting the OpenVPN client connection, which seems strange for a USB-connected device. I've had this same UPS connected for about a year without any issues, but I started getting these emails after upgrading to pfSense 23.09 and nut 2.8.2 the other week.

I do have my pfSense system set up as the nut 'master' for a few other devices on my network, including my two Synology NASes. Nothing complicated, but I do have the two "LISTEN" directives in the Additional configuration lines for upsd.conf section:

LISTEN 127.0.0.1
LISTEN 172.17.37.1

And to further confuse things, while going through the logs to debug this, I also see some entries like the following that don't seem to be related to OpenVPN activity, but do suggest some USB issues:

Dec 3 09:02:48	kernel		ugen0.2: <American Power Conversion Back-UPS RS 1000MS FW:950.e3 .D USB FW:e3> at usbus0 (disconnected)
Dec 3 09:02:48	usbhid-ups	77697	Got disconnected by another driver: Device not configured
Dec 3 09:02:50	usbhid-ups	77697	libusb1: Could not open any HID devices: no USB buses found
Dec 3 09:02:50	upsd	22894	Data for UPS [ups] is stale - check driver
Dec 3 09:02:52	usbhid-ups	77697	libusb1: Could not open any HID devices: no USB buses found
Dec 3 09:02:54	usbhid-ups	77697	libusb1: Could not open any HID devices: no USB buses found
Dec 3 09:02:55	upsmon	66759	Poll UPS [ups] failed - Data stale
Dec 3 09:02:55	upsmon	66759	Communications with UPS ups lost
Dec 3 09:02:56	kernel		ugen0.2: <American Power Conversion Back-UPS RS 1000MS FW:950.e3 .D USB FW:e3> at usbus0
Dec 3 09:02:56	upsd	22894	UPS [ups] data is no longer stale
Dec 3 09:03:00	upsmon	66759	Communications with UPS ups established
Dec 3 09:03:22	php-cgi	27865	notify_monitor.php: Message sent to [EMAIL_ADDRESS] OK

Any ideas on this? It seems like a lot has changed with the 2.8.x branch and I wasn't having issues until recently, so I'm not sure how relevant some of the old conversations are.

Thanks!

dennypage

@mlake said in NUT Package (2.8.1 and above):

Dec 3 10:17:28 check_reload_status 446 Starting packages
Dec 3 10:17:28 check_reload_status 446 Reloading filter

When you restart OpenVPN, the log shows that the interface (ovpnc2) going down, and then comming back up. pfSense reloads everything when an interface changes state like that. In short, the restart of NUT (and the other packages) is expected behavior.

I am not knowledgeable enough on OpenVPN to know if there has been a change in how OpenVPN deals with interfaces in 23.09.

mlake

@dennypage Right, and that doesn’t surprise me. What I can’t figure out is why reloading the network interfaces causes a connection error for a USB-connected UPS.

dennypage

@mlake said in NUT Package (2.8.1 and above):

Dec 3 10:17:29 upsmon 37971 Signal 15: exiting
Dec 3 10:17:29 upsd 22980 User local-monitor@127.0.0.1 logged out from UPS [ups]
Dec 3 10:17:29 upsd 22980 mainloop: Interrupted system call
Dec 3 10:17:29 upsd 22980 Signal 15: exiting
Dec 3 10:17:29 usbhid-ups 54011 Signal 15: exiting
Dec 3 10:17:29 php-fpm 405 /rc.start_packages: Starting service nut
Dec 3 10:17:29 upsmon 94129 Startup successful
Dec 3 10:17:29 upsmon 94715 UPS [ups]: connect failed: Connection failure: Connection refused
Dec 3 10:17:29 upsmon 94715 Communications with UPS ups lost
Dec 3 10:17:29 usbhid-ups 3404 Startup successful
Dec 3 10:17:30 upsd 64401 listening on 127.0.0.1 port 3493
Dec 3 10:17:30 upsd 64401 listening on ::1 port 3493
Dec 3 10:17:30 upsd 64401 not listening on 127.0.0.1 port 3493
Dec 3 10:17:30 upsd 64401 listening on 172.17.37.1 port 3493
Dec 3 10:17:30 upsd 64401 Connected to UPS [ups]: usbhid-ups-ups
Dec 3 10:17:30 upsd 64401 Found 1 UPS defined in ups.conf
Dec 3 10:17:30 upsd 64746 Startup successful

NUT is being explicitly stopped, as noted by the "Signal 15: exiting" messages. Signal 15 is SIGTERM, which is the default signal. See the rc_stop() function in /usr/local/etc/rc.d/nut.sh.

sgnoc

I managed to figure out my remaining connection lost messages after the package update. It's related to a Suricata issue I'm having. The interfaces are going down and up briefly for Suricata restarting interfaces, and is causing the connection to go down long enough to send 2 connection lost messages followed by a connection established.

Each time this consistently happens over a 9 second period from first lost to the established message. Is there a way to tune nut to continue trying the connection for say 15 seconds before calling it a lost connection? This would eliminate these problems of interfaces going down briefly for an interface restart.

Otherwise over the last week or so I haven't seen a single instance of the connection lost message that wasn't correlated directly to a suricata interface going down and then up. Nut is doing what it is supposed to, so I can't complain, but it would be ideal if there is a way to slow down nut a little before firing off the logs/notices for a connection lost. Nut catches it quickly!

dennypage

@sgnoc said in NUT Package (2.8.1 and above):

The interfaces are going down and up briefly for Suricata restarting interfaces, and is causing the connection to go down long enough to send 2 connection lost messages followed by a connection established.

If the interface is being restarted, It's not just that you are loosing a connection, but that NUT is being completely restarted, yes? Just like the issue posted immediately prior to yours?

sgnoc

@dennypage Thanks, I hadn't connected the dots even after I read that post earlier. I went and checked previous logs for connection lost messages and the timestamps do add up. What's odd is I don't remember receiving messages for interfaces going down/up, although I hadn't previously had another issues causing a core dump and a forced reload of the interfaces, so I may just have not had cause for those messages to be generated previously. If that is expected behavior as stated, then all should be well. I guess it is a good thing to get a connection lost message indicating that there was a suricata core dump causing the interfaces to reload. Thanks and sorry I didn't connect the dots reading the above message!

dennypage

@sgnoc I believe there have been a few comments about Suricata flapping interfaces recently...

Edit: here is one: https://forum.netgate.com/post/1138736

mlake

@dennypage Is NUT supposed to be restarted when an interface changes? Or is the Signal 15 exit unexpected? Something definitely changed between pfSense and NUT after updating to 2.8.2 because I never got the connection errors before and now I get them once or twice a day (when the remote VPN renegotiates).

dennypage

@mlake said in NUT Package (2.8.1 and above):

@dennypage Is NUT supposed to be restarted when an interface changes? Or is the Signal 15 exit unexpected? Something definitely changed between pfSense and NUT after updating to 2.8.2 because I never got the connection errors before and now I get them once or twice a day (when the remote VPN renegotiates).

All pfSense packages are restarted when an interface changes state. This is outside of NUT’s control.

There may have been a change in how OpenVPN manages interfaces in recent releases 23.09/2.7.1, but I don’t know enough about OpenVPN to say. You might ask about interference handling changes in the OpenVPN forum.

mlake

@dennypage Thanks for the clarification. However, the over-notification problem appears to be a NUT/pfSense issue and doesn't seem to have anything to do with OpenVPN specifically. I disabled my OpenVPN connections and am still able to get the the "Communications with UPS ups lost" / "Communications with UPS ups established" emails by simply opening WAN interface page, clicking Save without changing anything, and then clicking Apply Changes.

Did something change in NUT's monitoring/polling system between 2.7.x and 2.8.x? It seems like NUT is now detecting a 'process restart' as a 'UPS disconnect'.

dennypage

@mlake said in NUT Package (2.8.1 and above):

I disabled my OpenVPN connections and am still able to get the the "Communications with UPS ups lost" / "Communications with UPS ups established" emails by simply opening WAN interface page, clicking Save without changing anything, and then clicking Apply Changes.

This is the same thing as above, however in this case you are restarting the WAN interface instead of the OpenVPN interface.

dennypage

@mlake said in NUT Package (2.8.1 and above):

Did something change in NUT's monitoring/polling system between 2.7.x and 2.8.x? It seems like NUT is now detecting a 'process restart' as a 'UPS disconnect'.

Another item of note is that email notifications for non root processes (such as NUT) were broken in 23.05/2.7.0 which would have suppressed the emails. Pushover (and others) worked though.

mlake

@dennypage Curious - this may speak to the reason why I wasn't seeing the emails when a quick change happened in 23.05, but I certainly did get emails when I had a power outage.

For now, I'm going to disable the email notifications because they're not helpful and are just reporting false-positives.

It seems that when restarted by the system, there is a race condition and NUT should probably withhold sending notifications until the system has had time to bring interfaces back up.

Thanks for responding to these and at least clarifying that some of the underlying behavior is expected.

dennypage

@mlake Do me a favor?

Try with this patch and let me know if it suppresses the problem when your OpenVPN connection flaps.

You will need to go into UPS -> settings and press Save in order to activate the change.

--- /usr/local/pkg/nut/nut.inc.org	2023-11-17 05:42:10.000000000 -0800
+++ /usr/local/pkg/nut/nut.inc	2023-12-05 15:20:38.575637000 -0800
@@ -82,14 +82,19 @@
 		$start .= "\n	/usr/bin/killall -q -9 $driver";
 	}
 
-	/* Service status keys off upsmon, so start it first. */
-	$start .= "\n	/usr/local/sbin/upsmon";
 	if (isset($driver)) {
 		$start .= "\n	/usr/local/sbin/upsdrvctl start &";
-		/* Since we are starting the driver in backgroud, give it a moment to start. */
-		$start .= "\n	sleep 1";
 		$start .= "\n	/usr/local/sbin/upsd -u root";
+
+		/*
+		 * Since we are starting the driver in backgroud, give
+		 * the driver and upsd a moment to start.
+		 */
+		$start .= "\n	sleep 1";
 	}
+
+	/* NB: Service status keys off of upsmon. */
+	$start .= "\n	/usr/local/sbin/upsmon";
 	$start .= "\n	return 0";
 
 	$stop = "echo stopping NUT";

mlake

@dennypage Wow, thank you! Got the patch applied (made a "nut.inc.org" copy and had to put "/usr" as the Base Directory to get it to take) and the results look promising. I've tried a few interface resets that normally cause the notifications and I've only gotten it to trigger once. Unplugging the UPS and plugging it back in works as expected. I'm going to let this sit for a few days and I'll check back in.