-
Version info:
pfSense: 23.09-RELEASE (amd64)
nut: 2.8.2I'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 lostNotifications 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 establishedAnd 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] OKI 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.1And 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] OKAny 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!
-
@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 filterWhen 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.
-
@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.
-
@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 successfulNUT 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.
-
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!
-
@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?
-
@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!
-
@sgnoc I believe there have been a few comments about Suricata flapping interfaces recently...
Edit: here is one: https://forum.netgate.com/post/1138736
-
@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).
-
@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.
-
@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'.
-
@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.
-
@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.
-
@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.
-
@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"; -
@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.
-
@mlake said in NUT Package (2.8.1 and above):
(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.
Use the patches GUI :
Give it a description, like the URL of this fprum thread.
No URL/Commit ID,
Paste the patch as fond above,
Path strip count : set to 1
Base dir = /
Auto apply : free of choice.
save, and the patch is now ready to be applied.
So Apply.
Restart the UPS service as indicated above. -
@Gertjan Ah thanks, yes! (First time applying a manual patch... now the UI makes more sense).
-
@dennypage The patch seems to have solved my Suricata restarting interfaces too. I applied the patch and restarted Suricata, which would normally generate 2 connection lost and one connect established messages when NUT restarted, but the messages were supressed. The sleep delays seem to have done the trick. Thanks a bunch!
-
Im having issues getting pfsense to conect to the NUT server on my Synology whilst that connection work on other servers on my system:
"ld-elf.so.1: Shared object "libssl.so.30" not found, required by "upsmon"
nut sysutils 2.8.2
PfSense Version 2.7.0-RELEASE (amd64). Installed clean, not upgradedSynology 192.168.2.3
"synoups.conf"ups_enabled="yes" ups_mode="usb" ups_safeshutdown="no" ups_acl="192.168.2.1|192.168.2.12||||""upsd.users"
[monuser] password = slaveHome Assistant connects to this and outputs ;
"domain": "nut", "title": "synology.home.lan:3493", "data": { "host": "synology.home.lan", "port": 3493, "username": "**REDACTED**", "password": "**REDACTED**"Home Assistant Status 192.168.2.12 (excert):
"status": { "battery.capacity": "9.00", "battery.charge": "100", "battery.charge.low": "20", "battery.charge.restart": "0", "battery.energysave": "no", "battery.protection": "yes"PfSense config 192.168.2.1
cat /usr/local/etc/nut/upsmon.conf MONITOR ups@192.168.2.3 1 monuser slave slaveLog output when started manually:
starting NUT ld-elf.so.1: Shared object "libssl.so.30" not found, required by "upsmon"
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.