[Nut-upsuser] nut does not start after reboot
Eyal Lebedinsky
eyal at eyal.emu.id.au
Sat Jan 28 00:13:36 GMT 2023
On up-to-date f36, with latest kernel 6.1.7-100.fc36.x86_64.
After receiving a few of these messages
Broadcast message from nut at e7.eyal.emu.id.au (somewhere)
UPS ups at ups is unavailable
I noticed and ran
sudo systemctl restart nut-driver at ups.service
which triggered
Broadcast message from nut at e7.eyal.emu.id.au (somewhere)
Communications with UPS ups at ups established
I now added the restart to rc.local.
Is there a better/correct way to ensure nut starts at boot time?
Below is what I consider relevant to the situation in the boot log.
Looking at the boot log I see
$ sudo journalctl -b 0 -o short-iso --no-hostname | egrep -i '[^a-zA-Z](ups|nut)'
2023-01-28T09:06:57+1100 kernel: usb 1-5.2: Product: UPS VALUE
2023-01-28T09:06:57+1100 kernel: hid-generic 0003:0764:0501.0003: hiddev96,hidraw2: USB HID v1.10 Device [CPS UPS VALUE] on usb-0000:00:14.0-5.2/input0
2023-01-28T09:07:06+1100 kernel: usb 1-5.2: Product: UPS VALUE
2023-01-28T09:07:06+1100 kernel: hid-generic 0003:0764:0501.0008: hiddev96,hidraw2: USB HID v1.10 Device [CPS UPS VALUE] on usb-0000:00:14.0-5.2/input0
2023-01-28T09:07:12+1100 systemd[1]: Created slice system-nut\x2ddriver.slice - Slice /system/nut-driver.
2023-01-28T09:07:12+1100 udevadm[666]: systemd-udev-settle.service is deprecated. Please fix nut-driver at ups.service, multipathd.service not to pull it in.
2023-01-28T09:07:15+1100 systemd[1]: Starting nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'...
2023-01-28T09:07:15+1100 kernel: usb 1-5.2: Product: UPS VALUE
2023-01-28T09:07:15+1100 kernel: hid-generic 0003:0764:0501.0009: hiddev96,hidraw2: USB HID v1.10 Device [CPS UPS VALUE] on usb-0000:00:14.0-5.2/input0
2023-01-28T09:07:15+1100 nut-driver at ups[1289]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)
2023-01-28T09:07:15+1100 nut-driver at ups[1289]: USB communication driver (libusb 1.0) 0.43
2023-01-28T09:07:15+1100 nut-driver at ups[1289]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:07:15+1100 nut-driver at ups[1289]: No matching HID UPS found
2023-01-28T09:07:15+1100 nut-driver at ups[1259]: Driver failed to start (exit status=1)
2023-01-28T09:07:20+1100 nut-driver at ups[1580]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)
2023-01-28T09:07:20+1100 nut-driver at ups[1580]: USB communication driver (libusb 1.0) 0.43
2023-01-28T09:07:20+1100 nut-driver at ups[1580]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:07:20+1100 nut-driver at ups[1580]: No matching HID UPS found
2023-01-28T09:07:20+1100 nut-driver at ups[1259]: Driver failed to start (exit status=1)
2023-01-28T09:07:25+1100 nut-driver at ups[2378]: Using subdriver: CyberPower HID 0.6
2023-01-28T09:07:25+1100 nut-driver at ups[2378]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)
2023-01-28T09:07:25+1100 nut-driver at ups[2378]: USB communication driver (libusb 1.0) 0.43
2023-01-28T09:07:25+1100 nut-driver at ups[2378]: nut_libusb_get_string: Pipe error
2023-01-28T09:07:25+1100 nut-driver at ups[2378]: cps_adjust_battery_scale: battery readings will be scaled by 2/3
2023-01-28T09:07:25+1100 usbhid-ups[2399]: Startup successful
2023-01-28T09:07:25+1100 nut-driver at ups[1259]: Network UPS Tools - UPS driver controller 2.8.0
2023-01-28T09:07:25+1100 systemd[1]: Started nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'.
2023-01-28T09:07:25+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver at ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:07:25+1100 systemd[1]: Reached target nut-driver.target - Network UPS Tools - target for power device drivers on this system.
2023-01-28T09:07:25+1100 systemd[1]: Started nut-server.service - Network UPS Tools - power devices information server.
2023-01-28T09:07:25+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-server comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:07:25+1100 nut-server[2400]: fopen /run/nut/upsd.pid: No such file or directory
2023-01-28T09:07:25+1100 nut-server[2400]: Could not find PID file '/run/nut/upsd.pid' to see if previous upsd instance is already running!
2023-01-28T09:07:25+1100 systemd[1]: Starting nut-monitor.service - Network UPS Tools - power device monitor and shutdown controller...
2023-01-28T09:07:25+1100 nut-server[2400]: listening on 192.168.3.7 port 3493
2023-01-28T09:07:25+1100 nut-server[2400]: listening on 127.0.0.1 port 3493
2023-01-28T09:07:25+1100 upsd[2400]: listening on 192.168.3.7 port 3493
2023-01-28T09:07:25+1100 upsd[2400]: listening on 127.0.0.1 port 3493
2023-01-28T09:07:25+1100 nut-server[2400]: Connected to UPS [ups]: usbhid-ups-ups
2023-01-28T09:07:25+1100 upsd[2400]: Connected to UPS [ups]: usbhid-ups-ups
2023-01-28T09:07:25+1100 usbhid-ups[2399]: sock_connect: enabling asynchronous mode (auto)
2023-01-28T09:07:25+1100 nut-server[2400]: Running as foreground process, not saving a PID file
2023-01-28T09:07:25+1100 upsd[2400]: Running as foreground process, not saving a PID file
2023-01-28T09:07:26+1100 systemd[1]: Started nut-monitor.service - Network UPS Tools - power device monitor and shutdown controller.
2023-01-28T09:07:26+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-monitor comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:07:26+1100 nut-monitor[2402]: fopen /run/nut/upsmon.pid: No such file or directory
2023-01-28T09:07:26+1100 nut-monitor[2402]: Could not find PID file to see if previous upsmon instance is already running!
2023-01-28T09:07:26+1100 nut-monitor[2402]: UPS: ups at ups (primary) (power value 1)
2023-01-28T09:07:26+1100 nut-monitor[2402]: Using power down flag file /etc/killpower
2023-01-28T09:07:27+1100 nut-server[2400]: User upsmon at 192.168.3.7 logged into UPS [ups]
2023-01-28T09:07:27+1100 upsd[2400]: User upsmon at 192.168.3.7 logged into UPS [ups]
2023-01-28T09:07:57+1100 usbhid-ups[2399]: nut_libusb_get_string: Pipe error
>>> this repeats every minute, probably when my collection script runs 'upsc ups at e7'. Then later
2023-01-28T09:22:19+1100 usbhid-ups[2399]: nut_libusb_get_report: Input/Output Error
2023-01-28T09:22:19+1100 usbhid-ups[2399]: nut_libusb_get_report: No such device (it may have been disconnected)
2023-01-28T09:22:21+1100 usbhid-ups[2399]: nut_libusb_get_interrupt: No such device (it may have been disconnected)
2023-01-28T09:22:23+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:22:23+1100 upsd[2400]: Data for UPS [ups] is stale - check driver
2023-01-28T09:22:23+1100 nut-server[2400]: Data for UPS [ups] is stale - check driver
2023-01-28T09:22:25+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:22:27+1100 nut-monitor[2403]: Poll UPS [ups at ups] failed - Data stale
2023-01-28T09:22:27+1100 nut-monitor[2403]: Communications with UPS ups at ups lost
2023-01-28T09:22:27+1100 nut-monitor[15991]: Network UPS Tools upsmon 2.8.0
2023-01-28T09:22:27+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:22:29+1100 kernel: usb 1-5.2: Product: UPS VALUE
2023-01-28T09:22:29+1100 kernel: hid-generic 0003:0764:0501.000A: hiddev96,hidraw2: USB HID v1.10 Device [CPS UPS VALUE] on usb-0000:00:14.0-5.2/input0
2023-01-28T09:22:29+1100 mythbackend[2710]: 2023-01-28 09:22:29.246967 I [2710/2710] CoreContext platforms/mythpowerdbus.cpp:367:DeviceAdded PowerDBus: Added UPower.Device '/org/freedesktop/UPower/devices/ups_hiddev0'
2023-01-28T09:22:29+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:22:31+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
2023-01-28T09:22:32+1100 nut-monitor[2403]: Poll UPS [ups at ups] failed - Data stale
>>> thiese last 3 lines repeat many times, until I run
2023-01-28T09:55:11+1100 sudo[26694]: eyal : TTY=pts/8 ; PWD=/home/eyal ; USER=root ; COMMAND=/usr/bin/systemctl restart nut-driver at ups.service
2023-01-28T09:55:11+1100 systemd[1]: Stopping nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'...
2023-01-28T09:55:11+1100 nut-driver at ups[26697]: Network UPS Tools - UPS driver controller 2.8.0
2023-01-28T09:55:11+1100 nut-server[2400]: Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory
2023-01-28T09:55:11+1100 usbhid-ups[2399]: Signal 15: exiting
2023-01-28T09:55:11+1100 upsd[2400]: Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory
2023-01-28T09:55:11+1100 systemd[1]: nut-driver at ups.service: Deactivated successfully.
2023-01-28T09:55:11+1100 systemd[1]: Stopped nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'.
2023-01-28T09:55:11+1100 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver at ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:55:11+1100 systemd[1]: nut-driver at ups.service: Consumed 1.448s CPU time.
2023-01-28T09:55:11+1100 kernel: audit: type=1131 audit(1674860111.213:973): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver at ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:55:11+1100 systemd[1]: Starting nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'...
2023-01-28T09:55:11+1100 mythbackend[2710]: 2023-01-28 09:55:11.295944 I [2710/2710] CoreContext platforms/mythpowerdbus.cpp:379:DeviceRemoved Removed UPower.Device '/org/freedesktop/UPower/devices/ups_hiddev0'
2023-01-28T09:55:11+1100 nut-driver at ups[26755]: Using subdriver: CyberPower HID 0.6
2023-01-28T09:55:11+1100 nut-driver at ups[26755]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)
2023-01-28T09:55:11+1100 nut-driver at ups[26755]: USB communication driver (libusb 1.0) 0.43
2023-01-28T09:55:11+1100 nut-driver at ups[26755]: cps_adjust_battery_scale: battery readings will be scaled by 2/3
2023-01-28T09:55:12+1100 usbhid-ups[26758]: Startup successful
2023-01-28T09:55:12+1100 nut-driver at ups[26727]: Network UPS Tools - UPS driver controller 2.8.0
2023-01-28T09:55:12+1100 systemd[1]: Started nut-driver at ups.service - Network UPS Tools - device driver for NUT device 'ups'.
2023-01-28T09:55:12+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver at ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:55:12+1100 kernel: audit: type=1130 audit(1674860112.099:974): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver at ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
2023-01-28T09:55:12+1100 nut-server[2400]: Connected to UPS [ups]: usbhid-ups-ups
2023-01-28T09:55:12+1100 upsd[2400]: Connected to UPS [ups]: usbhid-ups-ups
2023-01-28T09:55:12+1100 nut-monitor[2403]: Poll UPS [ups at ups] failed - Driver not connected
2023-01-28T09:55:12+1100 usbhid-ups[26758]: sock_connect: enabling asynchronous mode (auto)
2023-01-28T09:55:17+1100 nut-monitor[2403]: Communications with UPS ups at ups established
2023-01-28T09:55:17+1100 nut-monitor[26759]: Network UPS Tools upsmon 2.8.0
>>> and I now get readings.
>>> interestingly, I later see
2023-01-28T10:12:46+1100 usbhid-ups[26758]: nut_libusb_get_string: Pipe error
>>> this message is not seen in /var/log/messages...
>>> but I still get readings.
>>> maybe an intermittent error?
--
Eyal Lebedinsky (eyal at eyal.emu.id.au)
More information about the Nut-upsuser
mailing list