<div dir="ltr">Hello,<br><div><br>Looking at "udevadm[666]: systemd-udev-settle.service is deprecated. Please fix
nut-driver@ups.service, multipathd.service not to pull it in" above and <a href="https://github.com/openzfs/zfs/issues/10891#issuecomment-749479690">https://github.com/openzfs/zfs/issues/10891#issuecomment-749479690</a> quote about the deprecation in particular, I wonder if in fact your OS tries to start NUT device driver before UDEV somehow -- so the access rights to USB devfs node are not yet assigned to the NUT run-time user account? At least, "usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything
" messages point strongly to something like that.</div><div><br></div><div>On a side note, I see "CPS" mentioned above, and there's a plethora of issues discussions (on NUT GitHub and elsewhere) about how these devices tend to act for a while and disconnect (power-saving maybe?...) And the system then finds the electric links, picks them up as a new connection initially owned by kernel, then udev must hand it off to NUT, driver must reconnect etc.) Don't remember all of it, but more frequent polling might help IIRC. Some things about reconnections could have been addressed in master branch after NUT v2.8.0 release, also.</div><div><br></div><div>Jim<br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Sat, Jan 28, 2023 at 1:38 AM Eyal Lebedinsky <<a href="mailto:eyal@eyal.emu.id.au">eyal@eyal.emu.id.au</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On up-to-date f36, with latest kernel 6.1.7-100.fc36.x86_64.<br>
<br>
After receiving a few of these messages<br>
Broadcast message from <a href="mailto:nut@e7.eyal.emu.id.au" target="_blank">nut@e7.eyal.emu.id.au</a> (somewhere)<br>
UPS ups@ups is unavailable<br>
I noticed and ran<br>
sudo systemctl restart nut-driver@ups.service<br>
which triggered<br>
Broadcast message from <a href="mailto:nut@e7.eyal.emu.id.au" target="_blank">nut@e7.eyal.emu.id.au</a> (somewhere)<br>
Communications with UPS ups@ups established<br>
<br>
I now added the restart to rc.local.<br>
<br>
Is there a better/correct way to ensure nut starts at boot time?<br>
<br>
Below is what I consider relevant to the situation in the boot log.<br>
<br>
Looking at the boot log I see<br>
$ sudo journalctl -b 0 -o short-iso --no-hostname | egrep -i '[^a-zA-Z](ups|nut)'<br>
2023-01-28T09:06:57+1100 kernel: usb 1-5.2: Product: UPS VALUE<br>
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<br>
2023-01-28T09:07:06+1100 kernel: usb 1-5.2: Product: UPS VALUE<br>
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<br>
2023-01-28T09:07:12+1100 systemd[1]: Created slice system-nut\x2ddriver.slice - Slice /system/nut-driver.<br>
2023-01-28T09:07:12+1100 udevadm[666]: systemd-udev-settle.service is deprecated. Please fix nut-driver@ups.service, multipathd.service not to pull it in.<br>
2023-01-28T09:07:15+1100 systemd[1]: Starting nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'...<br>
2023-01-28T09:07:15+1100 kernel: usb 1-5.2: Product: UPS VALUE<br>
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<br>
2023-01-28T09:07:15+1100 nut-driver@ups[1289]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)<br>
2023-01-28T09:07:15+1100 nut-driver@ups[1289]: USB communication driver (libusb 1.0) 0.43<br>
2023-01-28T09:07:15+1100 nut-driver@ups[1289]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:07:15+1100 nut-driver@ups[1289]: No matching HID UPS found<br>
2023-01-28T09:07:15+1100 nut-driver@ups[1259]: Driver failed to start (exit status=1)<br>
2023-01-28T09:07:20+1100 nut-driver@ups[1580]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)<br>
2023-01-28T09:07:20+1100 nut-driver@ups[1580]: USB communication driver (libusb 1.0) 0.43<br>
2023-01-28T09:07:20+1100 nut-driver@ups[1580]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:07:20+1100 nut-driver@ups[1580]: No matching HID UPS found<br>
2023-01-28T09:07:20+1100 nut-driver@ups[1259]: Driver failed to start (exit status=1)<br>
2023-01-28T09:07:25+1100 nut-driver@ups[2378]: Using subdriver: CyberPower HID 0.6<br>
2023-01-28T09:07:25+1100 nut-driver@ups[2378]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)<br>
2023-01-28T09:07:25+1100 nut-driver@ups[2378]: USB communication driver (libusb 1.0) 0.43<br>
2023-01-28T09:07:25+1100 nut-driver@ups[2378]: nut_libusb_get_string: Pipe error<br>
2023-01-28T09:07:25+1100 nut-driver@ups[2378]: cps_adjust_battery_scale: battery readings will be scaled by 2/3<br>
2023-01-28T09:07:25+1100 usbhid-ups[2399]: Startup successful<br>
2023-01-28T09:07:25+1100 nut-driver@ups[1259]: Network UPS Tools - UPS driver controller 2.8.0<br>
2023-01-28T09:07:25+1100 systemd[1]: Started nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'.<br>
2023-01-28T09:07:25+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver@ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>
2023-01-28T09:07:25+1100 systemd[1]: Reached target nut-driver.target - Network UPS Tools - target for power device drivers on this system.<br>
2023-01-28T09:07:25+1100 systemd[1]: Started nut-server.service - Network UPS Tools - power devices information server.<br>
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'<br>
2023-01-28T09:07:25+1100 nut-server[2400]: fopen /run/nut/upsd.pid: No such file or directory<br>
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!<br>
2023-01-28T09:07:25+1100 systemd[1]: Starting nut-monitor.service - Network UPS Tools - power device monitor and shutdown controller...<br>
2023-01-28T09:07:25+1100 nut-server[2400]: listening on 192.168.3.7 port 3493<br>
2023-01-28T09:07:25+1100 nut-server[2400]: listening on 127.0.0.1 port 3493<br>
2023-01-28T09:07:25+1100 upsd[2400]: listening on 192.168.3.7 port 3493<br>
2023-01-28T09:07:25+1100 upsd[2400]: listening on 127.0.0.1 port 3493<br>
2023-01-28T09:07:25+1100 nut-server[2400]: Connected to UPS [ups]: usbhid-ups-ups<br>
2023-01-28T09:07:25+1100 upsd[2400]: Connected to UPS [ups]: usbhid-ups-ups<br>
2023-01-28T09:07:25+1100 usbhid-ups[2399]: sock_connect: enabling asynchronous mode (auto)<br>
2023-01-28T09:07:25+1100 nut-server[2400]: Running as foreground process, not saving a PID file<br>
2023-01-28T09:07:25+1100 upsd[2400]: Running as foreground process, not saving a PID file<br>
2023-01-28T09:07:26+1100 systemd[1]: Started nut-monitor.service - Network UPS Tools - power device monitor and shutdown controller.<br>
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'<br>
2023-01-28T09:07:26+1100 nut-monitor[2402]: fopen /run/nut/upsmon.pid: No such file or directory<br>
2023-01-28T09:07:26+1100 nut-monitor[2402]: Could not find PID file to see if previous upsmon instance is already running!<br>
2023-01-28T09:07:26+1100 nut-monitor[2402]: UPS: ups@ups (primary) (power value 1)<br>
2023-01-28T09:07:26+1100 nut-monitor[2402]: Using power down flag file /etc/killpower<br>
2023-01-28T09:07:27+1100 nut-server[2400]: User <a href="mailto:upsmon@192.168.3.7" target="_blank">upsmon@192.168.3.7</a> logged into UPS [ups]<br>
2023-01-28T09:07:27+1100 upsd[2400]: User <a href="mailto:upsmon@192.168.3.7" target="_blank">upsmon@192.168.3.7</a> logged into UPS [ups]<br>
2023-01-28T09:07:57+1100 usbhid-ups[2399]: nut_libusb_get_string: Pipe error<br>
>>> this repeats every minute, probably when my collection script runs 'upsc ups@e7'. Then later<br>
2023-01-28T09:22:19+1100 usbhid-ups[2399]: nut_libusb_get_report: Input/Output Error<br>
2023-01-28T09:22:19+1100 usbhid-ups[2399]: nut_libusb_get_report: No such device (it may have been disconnected)<br>
2023-01-28T09:22:21+1100 usbhid-ups[2399]: nut_libusb_get_interrupt: No such device (it may have been disconnected)<br>
2023-01-28T09:22:23+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:22:23+1100 upsd[2400]: Data for UPS [ups] is stale - check driver<br>
2023-01-28T09:22:23+1100 nut-server[2400]: Data for UPS [ups] is stale - check driver<br>
2023-01-28T09:22:25+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:22:27+1100 nut-monitor[2403]: Poll UPS [ups@ups] failed - Data stale<br>
2023-01-28T09:22:27+1100 nut-monitor[2403]: Communications with UPS ups@ups lost<br>
2023-01-28T09:22:27+1100 nut-monitor[15991]: Network UPS Tools upsmon 2.8.0<br>
2023-01-28T09:22:27+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:22:29+1100 kernel: usb 1-5.2: Product: UPS VALUE<br>
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<br>
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'<br>
2023-01-28T09:22:29+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:22:31+1100 usbhid-ups[2399]: libusb1: Could not open any HID devices: insufficient permissions on everything<br>
2023-01-28T09:22:32+1100 nut-monitor[2403]: Poll UPS [ups@ups] failed - Data stale<br>
>>> thiese last 3 lines repeat many times, until I run<br>
2023-01-28T09:55:11+1100 sudo[26694]: eyal : TTY=pts/8 ; PWD=/home/eyal ; USER=root ; COMMAND=/usr/bin/systemctl restart nut-driver@ups.service<br>
2023-01-28T09:55:11+1100 systemd[1]: Stopping nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'...<br>
2023-01-28T09:55:11+1100 nut-driver@ups[26697]: Network UPS Tools - UPS driver controller 2.8.0<br>
2023-01-28T09:55:11+1100 nut-server[2400]: Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory<br>
2023-01-28T09:55:11+1100 usbhid-ups[2399]: Signal 15: exiting<br>
2023-01-28T09:55:11+1100 upsd[2400]: Can't connect to UPS [ups] (usbhid-ups-ups): No such file or directory<br>
2023-01-28T09:55:11+1100 systemd[1]: nut-driver@ups.service: Deactivated successfully.<br>
2023-01-28T09:55:11+1100 systemd[1]: Stopped nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'.<br>
2023-01-28T09:55:11+1100 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver@ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>
2023-01-28T09:55:11+1100 systemd[1]: nut-driver@ups.service: Consumed 1.448s CPU time.<br>
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@ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>
2023-01-28T09:55:11+1100 systemd[1]: Starting nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'...<br>
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'<br>
2023-01-28T09:55:11+1100 nut-driver@ups[26755]: Using subdriver: CyberPower HID 0.6<br>
2023-01-28T09:55:11+1100 nut-driver@ups[26755]: Network UPS Tools - Generic HID driver 0.47 (2.8.0)<br>
2023-01-28T09:55:11+1100 nut-driver@ups[26755]: USB communication driver (libusb 1.0) 0.43<br>
2023-01-28T09:55:11+1100 nut-driver@ups[26755]: cps_adjust_battery_scale: battery readings will be scaled by 2/3<br>
2023-01-28T09:55:12+1100 usbhid-ups[26758]: Startup successful<br>
2023-01-28T09:55:12+1100 nut-driver@ups[26727]: Network UPS Tools - UPS driver controller 2.8.0<br>
2023-01-28T09:55:12+1100 systemd[1]: Started nut-driver@ups.service - Network UPS Tools - device driver for NUT device 'ups'.<br>
2023-01-28T09:55:12+1100 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=nut-driver@ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>
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@ups comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>
2023-01-28T09:55:12+1100 nut-server[2400]: Connected to UPS [ups]: usbhid-ups-ups<br>
2023-01-28T09:55:12+1100 upsd[2400]: Connected to UPS [ups]: usbhid-ups-ups<br>
2023-01-28T09:55:12+1100 nut-monitor[2403]: Poll UPS [ups@ups] failed - Driver not connected<br>
2023-01-28T09:55:12+1100 usbhid-ups[26758]: sock_connect: enabling asynchronous mode (auto)<br>
2023-01-28T09:55:17+1100 nut-monitor[2403]: Communications with UPS ups@ups established<br>
2023-01-28T09:55:17+1100 nut-monitor[26759]: Network UPS Tools upsmon 2.8.0<br>
>>> and I now get readings.<br>
>>> interestingly, I later see<br>
2023-01-28T10:12:46+1100 usbhid-ups[26758]: nut_libusb_get_string: Pipe error<br>
>>> this message is not seen in /var/log/messages...<br>
>>> but I still get readings.<br>
>>> maybe an intermittent error?<br>
<br>
-- <br>
Eyal Lebedinsky (<a href="mailto:eyal@eyal.emu.id.au" target="_blank">eyal@eyal.emu.id.au</a>)<br>
<br>
_______________________________________________<br>
Nut-upsuser mailing list<br>
<a href="mailto:Nut-upsuser@alioth-lists.debian.net" target="_blank">Nut-upsuser@alioth-lists.debian.net</a><br>
<a href="https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser" rel="noreferrer" target="_blank">https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser</a><br>
</blockquote></div>