[Nut-upsuser] nut does not start after reboot

Sat Jan 28 11:22:38 GMT 2023

Hello,

Looking at "udevadm[666]: systemd-udev-settle.service is deprecated. Please
fix nut-driver at ups.service, multipathd.service not to pull it in" above and
https://github.com/openzfs/zfs/issues/10891#issuecomment-749479690 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.

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.

Jim

On Sat, Jan 28, 2023 at 1:38 AM Eyal Lebedinsky <eyal at eyal.emu.id.au> wrote:

> 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)
>
> _______________________________________________
> Nut-upsuser mailing list
> Nut-upsuser at alioth-lists.debian.net
> https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20230128/c602ebc7/attachment-0001.htm>