Issues with Bookworm and NUT upscode2 > 2.7.4

[rdukes6514]

Issues with Bookworm and NUT upscode2 > 2.7.4

[jimklimov]

Hello, sorry to hear about the issue.

Is it possible for you to try running directly the NUT v2.7.4 and newer driver programs with elevated debug verbosity, to see at what point the driver decides it can or can not connect to the device? See https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity for details.

Also I wonder if your drivers actually got started as automatically created service instances, hence the attempts with upsdrvctl fail (device is busy) - see https://github.com/networkupstools/nut/wiki/nut%E2%80%90driver%E2%80%90enumerator-(NDE)

[rdukes6514]

Hi Jim, and thanks.

I am currently running a Pi Zero 2 with RaspiOS Bookworm installed. The available NUT claims to be 2.8.0.

Thanks to your response , I finally figured out where those -D's go...

It looks like Debian automatically creates the services as noted by the following section of the install:

...
Setting up nut-server (2.8.0-7) ...
Created symlink /etc/systemd/system/nut.target.wants/nut-driver-enumerator.path → /lib/systemd/system/nut-driver-enum
erator.path.
Created symlink /etc/systemd/system/nut.target.wants/nut-driver-enumerator.service → /lib/systemd/system/nut-driver-e
numerator.service.
Created symlink /etc/systemd/system/nut.target.wants/nut-driver.target → /lib/systemd/system/nut-driver.target.
Created symlink /etc/systemd/system/nut.target.wants/nut-server.service → /lib/systemd/system/nut-server.service.
...

And the fact they turn up in /etc/systemd/system...

...
root@newups-l:~# find / -name nut-server*
/etc/systemd/system/network-online.target.wants/nut-server.service
/etc/systemd/system/nut.target.wants/nut-server.service
/etc/systemd/system/multi-user.target.wants/nut-server.service
/etc/init.d/nut-server
/etc/nut/nut-server.service.apc
/usr/lib/systemd/system/nut-server.service
/usr/lib/systemd/system/nut-server.service.orig
/usr/lib/tmpfiles.d/nut-server.conf
/usr/share/doc/nut-server
/usr/share/lintian/overrides/nut-server
/sys/fs/cgroup/system.slice/nut-server.service
/var/lib/systemd/deb-systemd-helper-enabled/nut-server.service.dsh-also
/var/lib/systemd/deb-systemd-helper-enabled/nut.target.wants/nut-server.service
/var/lib/dpkg/info/nut-server.prerm
/var/lib/dpkg/info/nut-server.conffiles
/var/lib/dpkg/info/nut-server.preinst
/var/lib/dpkg/info/nut-server.list
/var/lib/dpkg/info/nut-server.postinst
/var/lib/dpkg/info/nut-server.postrm
/var/lib/dpkg/info/nut-server.md5sums
...

And here is the Debug info:

...
root@newups-l:# systemctl daemon-reload
root@newups-l:# systemctl restart nut-server
root@newups-l:~# systemctl status nut-server
● nut-server.service - Network UPS Tools - power devices information server
Loaded: loaded (/lib/systemd/system/nut-server.service; enabled; preset: enabled)
Active: active (running) since Thu 2024-04-04 11:40:35 CDT; 7s ago
Main PID: 2912 (upsd)
Tasks: 1 (limit: 380)
CPU: 21ms
CGroup: /system.slice/nut-server.service
└─2912 /lib/nut/upsd -DDDDDD

Apr 04 11:40:42 newups-l upsd[2912]: 7.251318 [D3] Got PONG from UPS [heartbeat]
Apr 04 11:40:42 newups-l upsd[2912]: 7.251384 [D3] sstate_dead: driver for UPS [UPS] says data is stale
Apr 04 11:40:42 newups-l upsd[2912]: 7.251439 [D2] mainloop: polling 3 filedescriptors
Apr 04 11:40:42 newups-l upsd[2912]: [D2] mainloop: no data available
Apr 04 11:40:42 newups-l upsd[2912]: [D3] sstate_dead: driver for UPS [UPS] says data is stale
Apr 04 11:40:42 newups-l upsd[2912]: [D3] Pinging UPS [heartbeat]
Apr 04 11:40:42 newups-l upsd[2912]: [D2] mainloop: polling 3 filedescriptors
Apr 04 11:40:42 newups-l upsd[2912]: [D3] Got PONG from UPS [heartbeat]
Apr 04 11:40:42 newups-l upsd[2912]: [D3] sstate_dead: driver for UPS [UPS] says data is stale
Apr 04 11:40:42 newups-l upsd[2912]: [D2] mainloop: polling 3 filedescriptors
...

I'm attempting to build from git, but I'm having to learn as I go...

Thanks again,
Randall Dukes

[rdukes6514]

Same story with a fresh install of Bookworm/Nut 2.8.0, followed by building and installing NUT 2.8.2 over it.

[jimklimov]

Is there a unit for [email protected]? What does its log say about the device communications - why it goes stale?

I strongly suspect there's some weird fallout of warnings fixes (there were already a few places that de-facto relied on broken code) but so far lack a smoking gun...

[rdukes6514]

• FS objects:

root@newups-l:/# find / -name [email protected]
/etc/systemd/system/nut-driver.target.wants/[email protected]
/sys/fs/cgroup/system.slice/system-nut\x2ddriver.slice/[email protected]

• Uncommented parts of /etc/systemd/system/nut-driver.target.wants/[email protected]:

...
[Unit]
Description=Network UPS Tools - device driver for %I
After=local-fs.target
PartOf=nut-driver.target
Environment=NUT_IGNORE_NOWAIT=true
EnvironmentFile=-/etc/nut/nut.conf
SyslogIdentifier=%N
ExecStartPre=-/usr/bin/systemd-tmpfiles --create /usr/lib/tmpfiles.d/nut-common-tmpfiles.conf
ExecStart=/bin/sh -c 'NUTDEV="`/usr/lib/nut/nut-driver-enumerator.sh --get-device-for-service %i`" && [ -n "$NUTDEV" ] || { echo "FATAL: Could not find a NUT device section for service unit %i" >&2 ; exit 1 ; } ; exec /usr/sbin/upsdrvctl  start "$NUTDEV"'
ExecReload=/bin/kill -USR1 $MAINPID
ExecStop=/bin/sh -c 'NUTDEV="`/usr/lib/nut/nut-driver-enumerator.sh --get-device-for-service %i`" && [ -n "$NUTDEV" ] || { echo "FATAL: Could not find a NUT device section for service unit %i" >&2 ; exit 1 ; } ; /usr/sbin/upsdrvctl stop "$NUTDEV"'
StartLimitInterval=0
Restart=always
RestartSec=15s
Type=forking
[Install]
WantedBy=nut-driver.target
...

• /sys/fs/cgroup/system.slice/system-nut\x2ddriver.slice/[email protected] ----- can't be found

• Unit status/log:

root@newups-l:/# systemctl status [email protected]
● [email protected] - Network UPS Tools - device driver for UPS
     Loaded: loaded (/lib/systemd/system/[email protected]; enabled; preset: enabled)
    Drop-In: /etc/systemd/system/[email protected]
             └─nut-driver-enumerator-generated-checksum.conf, nut-driver-enumerator-generated-devicename.conf
     Active: active (running) since Mon 2024-04-08 09:09:06 CDT; 21h ago
   Main PID: 886 (upscode2)
      Tasks: 1 (limit: 380)
        CPU: 17.690s
     CGroup: /system.slice/system-nut\x2ddriver.slice/[email protected]
             └─886 /lib/nut/upscode2 -a UPS

Apr 09 06:54:19 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:19 newups-l upscode2[886]: No contact with UPS, delaying init.
Apr 09 06:54:21 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:21 newups-l upscode2[886]: No contact with UPS, delaying init.
Apr 09 06:54:23 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:23 newups-l upscode2[886]: No contact with UPS, delaying init.
Apr 09 06:54:25 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:25 newups-l upscode2[886]: No contact with UPS, delaying init.
Apr 09 06:54:27 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:27 newups-l upscode2[886]: No contact with UPS, delaying init.
Apr 09 06:54:29 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:29 newups-l upscode2[886]: No contact with UPS, delaying init.

Thanks.

[jimklimov]

Thanks, I've updated formatting in your post for "text screenshots" to be more readable.

The /etc/systemd/system/nut-driver.target.wants/[email protected] seems like what NDE (nut-driver-enumerator) generates from the ups.conf sections, so https://github.com/networkupstools/nut/wiki/nut%E2%80%90driver%E2%80%90enumerator-(NDE) wiki page's notes about its potential conflict with a manually-executed driver program or upsdrvctl do apply. In short - if you want to run the driver manually, e.g. to experiment with debug or custom builds where you add more places for it to print debug info, be sure to temporarily stop the systemd unit. If you just want more debugging with the existing program (and in the context it has as a service), temporarily setting debug_min = 6 in its ups.conf section can help: https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity

The /sys/fs/cgroup/... is an internal detail of how systemd manages and constrains the services/units, so not much of practical interest. Still, the "can't be found" part may be due to the backslash in \x (should be two separate characters in the path name AFAIK) -- did you single/double-quote the pathname when you looked for it? Try escaping that slash as \\x (otherwise it is interpreted as an escaped "x" character sequence).

Finally the service log is the interesting part and seeing how the driver lifetime started (more so with boosted debug verbosity) would be of interest for troubleshooting. So far I see just the initialization faults, retried every 2 seconds:

Apr 09 06:54:19 newups-l upscode2[886]: Missing UPCL after UPCL
Apr 09 06:54:19 newups-l upscode2[886]: No contact with UPS, delaying init.

You can look at existing unit journal via journalctl -lu [email protected] or watch it scroll when you restart the service with e.g. journalctl -flu [email protected] & systemctl restart [email protected] (both as root).

I wonder if there is some permissions issue for the serial port devfs node (e.g. owned by nut vs. nobody or root or dialout etc. - more so if you rebuilt NUT without specifying same user/group/... settings as applied by packaging earlier), and/or if it has a different pathname after the OS upgrade? As a quick hack for permissions, you can try user=root in the ups.conf section for the device, so the driver does not drop privileges (potentially insecure, so if this is the problem -- better find a way to store/re-apply the needed ownership in devfs across reboots).

[rdukes6514]

Jim,

Not sure how to do the formatting, but...

A new install of Bookworm on a Pi Zero 2w, was made and NUT (2.8.0/stable) was setup for an APC smart ups 620 using the apcsmart protocol, and I get a working system:

...
root@apc620:~# systemctl status nut-server
● nut-server.service - Network UPS Tools - power devices information server
     Loaded: loaded (/lib/systemd/system/nut-server.service; enabled; preset: e>
     Active: active (running) since Wed 2024-04-10 04:37:19 CDT; 1h 8min ago
   Main PID: 1076 (upsd)
      Tasks: 1 (limit: 380)
        CPU: 401ms
     CGroup: /system.slice/nut-server.service
             └─1076 /lib/nut/upsd -F

Apr 10 04:37:20 apc620 upsd[1076]: Running as foreground process, not saving a >
Apr 10 04:37:20 apc620 nut-server[1076]: Running as foreground process, not sav>
Apr 10 04:37:20 apc620 nut-server[1076]: User [email protected] logged into U>
Apr 10 04:37:20 apc620 upsd[1076]: User [email protected] logged into UPS [UP>
Apr 10 04:37:20 apc620 nut-server[1076]: User [email protected] logged into U>
Apr 10 04:37:20 apc620 upsd[1076]: User [email protected] logged into UPS [he>
Apr 10 04:37:56 apc620 nut-server[1076]: Data for UPS [heartbeat] is stale - ch>
Apr 10 04:37:56 apc620 upsd[1076]: Data for UPS [heartbeat] is stale - check dr>
Apr 10 04:37:57 apc620 nut-server[1076]: UPS [heartbeat] data is no longer stale
Apr 10 04:37:57 apc620 upsd[1076]: UPS [heartbeat] data is no longer stale
...

If I take an identical image and setup for the upscode2 protocol (the only changes being in ups.conf for upscode2, with the added debug_min = 6) for a Powervar PRC1000-a/NS I get:
Note results are about the same whether After=network-online.target and Requires=network.target have been uncommented or not (in /etc/systemd/system/nut.target.wants/nut-server.service).

...

● nut-server.service - Network UPS Tools - power devices information server
     Loaded: loaded (/lib/systemd/system/nut-server.service; enabled; preset: enabled)
     Active: active (running) since Wed 2024-04-10 05:38:37 CDT; 25s ago
    Process: 1458 ExecReload=/sbin/upsd -c reload -P $MAINPID (code=exited, status=0/SUCCESS)
   Main PID: 1447 (upsd)
      Tasks: 1 (limit: 380)
        CPU: 55ms
     CGroup: /system.slice/nut-server.service
             └─1447 /lib/nut/upsd -F -DDDDDD

Apr 10 05:39:00 powervar2 upsd[1447]: [D2] write: [destfd=6] [len=24] [VAR UPS ups.status "OL"]
Apr 10 05:39:00 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors
Apr 10 05:39:00 powervar2 upsd[1447]: [D6] Entering check_command: GET
Apr 10 05:39:00 powervar2 upsd[1447]: [D6] check_command: Calling command handler for GET
Apr 10 05:39:00 powervar2 upsd[1447]: [D2] write: [destfd=8] [len=30] [VAR heartbeat ups.status "OB"]
Apr 10 05:39:00 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors
Apr 10 05:39:02 powervar2 nut-server[1447]:   25.110534        [D3] Pinging UPS [heartbeat]
Apr 10 05:39:02 powervar2 nut-server[1447]:   25.110590        [D2] mainloop: polling 5 filedescriptors
Apr 10 05:39:02 powervar2 upsd[1447]: [D3] Pinging UPS [heartbeat]
Apr 10 05:39:02 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors

Apr 10 05:40:21 powervar2 nut-server[1447]:  103.711951        [D2] mainloop: polling 5 filedescriptors
Apr 10 05:40:21 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors
Apr 10 05:40:21 powervar2 nut-server[1447]:  104.021653        [D3] Pinging UPS [heartbeat]
Apr 10 05:40:21 powervar2 nut-server[1447]:  104.021713        [D2] mainloop: polling 5 filedescriptors
Apr 10 05:40:21 powervar2 nut-server[1447]:  104.021760        [D3] Got PONG from UPS [heartbeat]
Apr 10 05:40:21 powervar2 nut-server[1447]:  104.021802        [D2] mainloop: polling 5 filedescriptors
Apr 10 05:40:21 powervar2 upsd[1447]: [D3] Pinging UPS [heartbeat]
Apr 10 05:40:21 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors
Apr 10 05:40:21 powervar2 upsd[1447]: [D3] Got PONG from UPS [heartbeat]
Apr 10 05:40:21 powervar2 upsd[1447]: [D2] mainloop: polling 5 filedescriptors
...

This kind of points right back to the upscode2 driver itself

[jimklimov]

Not sure how to do the formatting, but...

Surround by identical lines of 3 or 4 backticks.

As for the log, can you look at [email protected]? The nut-server is the upsd data server which relays info from drivers to networked protocol.

[rdukes6514]

Jim,
Sorry, I had to step away.

After a couple of reboots the upscode2 driver appears to be working "correctly" with NUT 2.8.0. These are the changes made so far:

1. /usr/lib/systemd/system/nut-server.service
   a. Uncomment After=network-online.target and Requires=network.target.
   These appear to be uncommented by the enumerator for apcsmart, but not for upscode2.
   I think this was required for NUT 2.7.4 as well.
   b. Change "ExecStart=/sbin/upsd -F" to "ExecStart=/sbin/upsd -F -DDDDDD"

2. Add "debug_min = 6" to under upscode driver section of /etc/nut/ups.conf

3. Reboot. systemctl stop nut-server / systemctl daemon-reload / systemctl restart nut-server didn't appear to do the trick.

I have one more ups to update to to setup, so I'll start at square one to check the whole install process.

Thanks,
Randall

Edit: Part of the problem was the rs232 level shifter I was using was checking in and out. replaced with a new one and both the Powervar UPSs are working. Both changes to nut-server.service and the change to ups.conf appear to be required to get NUT 2.8.0 upscode2 communicating.

Jim,

I think you mark this as solved.