Quieter start-up of `upsmon`, `upsd` and driver daemons (avoid "scary" `fopen()` failure messages) by jimklimov · Pull Request #2384 · networkupstools/nut

jimklimov · 2024-04-06T16:41:48Z

Follows up from issue #1782 and PR #2383

CC @gdt (is this reasonably quieter?)

Avoid a few lines of text (when running without boosted debug verbosity) here and there, and default to avoid the infamous fopen /var/state/ups/upsd.pid: No such file or directory sort of messages that regularly raise questions/concerns from new NUT users.

With debug, all is seen as before:

:; ./server/upsd -D
Network UPS Tools upsd 2.8.2-29-g422cffad9
   0.000000     fopen /var/state/ups/upsd.pid: No such file or directory
   0.000032     Could not find PID file '/var/state/ups/upsd.pid' to see if previous upsd instance is already running!
   0.000100     stat /home/jim/nut/tmp/etc/nut/upsd.conf: No such file or directory

Default is a little bit quiet(er) but importantly less confusing:

:; ./server/upsd
Network UPS Tools upsd 2.8.2-29-g422cffad9
Could not find PID file '/var/state/ups/upsd.pid' to see if previous upsd instance is already running!

upsmon -K before the change (as of Clarify the value of POWERDOWNFLAG in upsmon -h and document that it must be set #2383 (comment)):

:; ./clients/upsmon -K && echo KILLPOWER
Network UPS Tools upsmon 2.8.1-994-gbff0c6bc9
fopen /run/upsmon.pid: No such file or directory
Could not find PID file to see if previous upsmon instance is already running!
UPS: x (monitoring only)
Using power down flag file /run/nut/killpower
Power down flag is not set

...and after the change (with a longer message if -K is involved):

:; ./clients/upsmon -K && echo KILLPOWER
Network UPS Tools upsmon 2.8.2-29-g422cffad9
Could not find PID file to see if previous upsmon instance is already running! This is okay during OS shutdown, which is when checking POWERDOWNFLAG makes most sense.
Using power down flag file /run/nut/killpower
Power down flag is not set

Note that as done before (in PR Clarify the value of POWERDOWNFLAG in upsmon -h and document that it must be set #2383), there is also special wording now for lack of POWERDOWNFLAG line in upsmon.conf, so the combined troubleshooting effect is:

Network UPS Tools upsmon 2.8.2-29-g422cffad9
Could not find PID file to see if previous upsmon instance is already running! This is okay during OS shutdown, which is when checking POWERDOWNFLAG makes most sense.
No POWERDOWNFLAG value was configured in /usr/local/ups/etc/upsmon.conf!
Should be a path to file that is normally writeable for root user, and remains at least readable late in shutdown after all unmounting completes.
Power down flag is not set

…ietly checking killpower flag [networkupstools#2383] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…evel verbosity toggle [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…sh initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…h initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…ggle to hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…K when checking_flag (for POWERDOWNFLAG) Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov · 2024-04-06T18:12:04Z

Would benefit from some more testing, especially with drivers: while main.c seems to also report the outcomes of signal-sending attempts, it may be not called in all the right places :\

On a system not modified with this PR, the fopen() message in driver program is not followed by clarifications:

:;  systemctl stop nut-driver@eco650
Apr 06 20:08:32 pve systemd[1]: Stopping Network UPS Tools - device driver for NUT device 'eco650'...
Apr 06 20:08:32 pve nut-driver@eco650[4020967]: Signal 15: exiting
Apr 06 20:08:32 pve usbhid-ups[4020967]: Signal 15: exiting
Apr 06 20:08:33 pve nut-driver@eco650[4133136]: fopen /var/state/ups/usbhid-ups-eco650.pid: No such file or directory
Apr 06 20:08:33 pve nut-driver@eco650[4133136]: Network UPS Tools - UPS driver controller 2.8.2-24-g962c15437
Apr 06 20:08:33 pve systemd[1]: nut-driver@eco650.service: Succeeded.
Apr 06 20:08:33 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.

jimklimov · 2024-04-12T09:10:50Z

Some testing with a live driver:

Starting driver program custom-built from this PR, calling it directly while a systemd unit ran a wrapped instance:

:; ./drivers/usbhid-ups -a eco650
Network UPS Tools - Generic HID driver 0.53 (2.8.2-43-g26eca8456)
USB communication driver (libusb 1.0) 0.47
Duplicate driver instance detected (PID file /var/state/ups/usbhid-ups-eco650.pid exists)! Terminating other driver!
Using subdriver: MGE HID 1.46

What the systemd-wrapped instance thinks about this (built from an earlier snapshot of the master branch):

Apr 12 10:26:36 pve nut-driver@eco650[1987208]: Signal 15: exiting
Apr 12 10:26:36 pve usbhid-ups[1987208]: Signal 15: exiting
Apr 12 10:26:36 pve systemd[1]: nut-driver@eco650.service: Succeeded.
Apr 12 10:26:36 pve systemd[1]: nut-driver@eco650.service: Consumed 46.052s CPU time.

Apr 12 10:26:51 pve systemd[1]: nut-driver@eco650.service: Scheduled restart job, restart counter is at 1.
Apr 12 10:26:51 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.
Apr 12 10:26:51 pve systemd[1]: nut-driver@eco650.service: Consumed 46.052s CPU time.
Apr 12 10:26:51 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'eco650'...
Apr 12 10:26:51 pve nut-driver@eco650[3547860]: Network UPS Tools - UPS driver controller 2.8.2-30-g96de317ee
Apr 12 10:26:51 pve nut-driver@eco650[3547860]: Network UPS Tools - Generic HID driver 0.53 (2.8.2-30-g96de317ee)
Apr 12 10:26:51 pve nut-driver@eco650[3547860]: USB communication driver (libusb 1.0) 0.47
Apr 12 10:26:52 pve nut-driver@eco650[3547860]: Can't claim USB device [0463:ffff]@0/0/0: Entity not found
Apr 12 10:26:52 pve systemd[1]: nut-driver@eco650.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 10:26:52 pve systemd[1]: nut-driver@eco650.service: Failed with result 'exit-code'.
Apr 12 10:26:52 pve systemd[1]: Failed to start Network UPS Tools - device driver for NUT device 'eco650'.

Apr 12 10:27:07 pve systemd[1]: nut-driver@eco650.service: Scheduled restart job, restart counter is at 2.
...

The systemd unit is looping in vain restart attempts, and notably dies not kill off the sibling driver started on command line (I'd expect it to try via Unix socket since v2.8.1 changes).

Oddly, there is a /var/state/ups/usbhid-ups-eco650.pid with the actual PID of the program started on command line; the systemd nut-driver units are configured to use a PID file despite not-forking (via -FF option): ExecStart=... exec /usr/local/ups/sbin/upsdrvctl -FF start "$NUTDEV".

FWIW, moving away the PID file did not help the systemd unit to start:

:; mv /var/state/ups/usbhid-ups-eco650.pid{,.x}

# journal:
Apr 12 10:41:40 pve systemd[1]: nut-driver@eco650.service: Scheduled restart job, restart counter is at 58.
Apr 12 10:41:40 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.
Apr 12 10:41:40 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'eco650'...
Apr 12 10:41:40 pve nut-driver@eco650[3593124]: Network UPS Tools - UPS driver controller 2.8.2-30-g96de317ee
Apr 12 10:41:40 pve nut-driver@eco650[3593124]: Network UPS Tools - Generic HID driver 0.53 (2.8.2-30-g96de317ee)
Apr 12 10:41:40 pve nut-driver@eco650[3593124]: USB communication driver (libusb 1.0) 0.47
Apr 12 10:41:40 pve nut-driver@eco650[3593124]: Can't claim USB device [0463:ffff]@0/0/0: Entity not found
Apr 12 10:41:40 pve systemd[1]: nut-driver@eco650.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 10:41:40 pve systemd[1]: nut-driver@eco650.service: Failed with result 'exit-code'.
Apr 12 10:41:40 pve systemd[1]: Failed to start Network UPS Tools - device driver for NUT device 'eco650'.

After bumping debug level for the service:

...
Apr 12 10:47:38 pve systemd[1]: nut-driver@eco650.service: Scheduled restart job, restart counter is at 81.
Apr 12 10:47:38 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.
Apr 12 10:47:38 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'eco650'...
Apr 12 10:47:38 pve nut-driver@eco650[3606708]: Network UPS Tools - UPS driver controller 2.8.2-30-g96de317ee
Apr 12 10:47:38 pve nut-driver@eco650[3606708]: Network UPS Tools - Generic HID driver 0.53 (2.8.2-30-g96de317ee)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]: USB communication driver (libusb 1.0) 0.47
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000000        [D1] debug level is '6'
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000012        [D5] send_to_all: SETINFO driver.debug "6"
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000020        [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000535        [D1] Succeeded to become_user(nut): now UID=77 GID=77
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000548        [D5] send_to_all: SETINFO device.type "ups"
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000554        [D5] send_to_all: SETINFO driver.state "init.device"
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000556        [D1] upsdrv_initups (non-SHUT)...
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.000559        [D2] Initializing an USB-connected UPS with library libusb-1.0.24 (API: 0x1000108) (NUT subdriver name='USB communication driver (libusb 1.0)' ver='0.47')
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003202        [D2] Checking device 1 of 9 (1D6B/0003)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003219        [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003222        [D2] Checking device 2 of 9 (03F0/0D4A)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003227        [D1] Failed to open device (03F0/0D4A), skipping: Access denied (insufficient permissions)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003229        [D2] Checking device 3 of 9 (1D6B/0002)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003233        [D1] Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003234        [D2] Checking device 4 of 9 (1D6B/0003)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003238        [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Apr 12 10:47:38 pve nut-driver@eco650[3606708]:    0.003240        [D2] Checking device 5 of 9 (0463/FFFF)
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444695        [D2] - VendorID: 0463
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444708        [D2] - ProductID: ffff
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444710        [D2] - Manufacturer: EATON
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444712        [D2] - Product: Ellipse ECO
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444713        [D2] - Serial Number: 000000000
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444715        [D2] - Bus: 003
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444716        [D2] - Bus Port: 002
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444718        [D2] - Device: 002
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444719        [D2] - Device release number: 0100
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444720        [D2] Trying to match device
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444723        [D2] match_function_subdriver (non-SHUT mode): matching a device...
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444726        [D3] match_function_regex: matching a device...
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444766        [D2] Device matches
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444768        [D2] Reading configuration descriptor 1 of 6
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444774        [D3] libusb_kernel_driver_active() returned 0: Success
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444777        [D2] failed to claim USB device: Resource busy
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444780        [D2] Kernel driver already detached
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444782        [D2] failed to claim USB device: Resource busy
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444784        [D2] Kernel driver already detached
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444785        [D2] failed to claim USB device: Resource busy
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444787        [D2] Kernel driver already detached
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444788        [D2] failed to claim USB device: Resource busy
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444790        [D2] Kernel driver already detached
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444794        Can't claim USB device [0463:ffff]@0/0/0: Entity not found
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444799        [D5] send_to_all: SETINFO driver.state "cleanup.exit"
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444802        [D6] upsnotify: notify about state 4 with libsystemd: use sd_notify()
Apr 12 10:47:39 pve nut-driver@eco650[3606708]:    0.444807        [D6] upsnotify: posting sd_notify: STATUS=exit_cleanup()
Apr 12 10:47:39 pve nut-driver@eco650[3606708]: STOPPING=1
Apr 12 10:47:39 pve systemd[1]: nut-driver@eco650.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 10:47:39 pve systemd[1]: nut-driver@eco650.service: Failed with result 'exit-code'.
Apr 12 10:47:39 pve systemd[1]: Failed to start Network UPS Tools - device driver for NUT device 'eco650'.
Apr 12 10:47:54 pve systemd[1]: nut-driver@eco650.service: Scheduled restart job, restart counter is at 82.
...

UPDATE: Upon review of drivers/main.c, currently the -FF option (applied in code as foreground=2) to stay foregrounded but still write a PID file takes effect during forking-or-not decision, after initializing the UPS. It does not affect the earlier logic of sending signals to sibling drivers (as when foreground==0 || cmd is in effect), so this bit of mystery is solved.

This also explains why at least the service-wrapped instances of the drivers do not print messages detailing their adventure with the PID file (whether inability to fopen or results of its analysis and use) - they just skip that codepath.

Trying the master-branch build program directly with different options.

Just a start (defaults to backgrounding) - no interaction with PID file is reported:

:; /usr/local/ups/bin/usbhid-ups -a eco650
Network UPS Tools - Generic HID driver 0.53 (2.8.2-30-g96de317ee)
USB communication driver (libusb 1.0) 0.47
Can't claim USB device [0463:ffff]@0/0/0: Entity not found
upsnotify: notify about state 4 with libsystemd: was requested, but not running as a service unit now, will not spam more about it
upsnotify: failed to notify about state 4: no notification tech defined, will not spam more about it

....but it does happen - quietly already:

:; strace -ff /usr/local/ups/bin/usbhid-ups -a eco650 2>&1 | grep '\.pid'
stat("/var/state/ups/usbhid-ups-eco650.pid", 0x7ffe28e348d0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/var/state/ups/usbhid-ups-eco650.pid", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
[pid 3797454] unlink("/var/state/ups/usbhid-ups-eco650.pid") = 0

With -FF the PID file interaction is indeed skipped:

:; strace -ff /usr/local/ups/bin/usbhid-ups -a eco650 -FF 2>&1 | grep '\.pid'
<nothing>

After renaming back the PID file of that still-running driver from the PR build, there is practical interaction:

:; mv /var/state/ups/usbhid-ups-eco650.pid{.x,}
:; /usr/local/ups/bin/usbhid-ups -a eco650
Network UPS Tools - Generic HID driver 0.53 (2.8.2-30-g96de317ee)
USB communication driver (libusb 1.0) 0.47
Duplicate driver instance detected (PID file /var/state/ups/usbhid-ups-eco650.pid exists)! Terminating other driver!
Using subdriver: MGE HID 1.46

As far as this PR is concerned, there seem to be no "scary messages" about fopen() in the driver, whether before or after the PR; there is no layman message about not-seeing an older PID file either, though (which may complicate troubleshooting):

:; ./drivers/usbhid-ups -a eco650
Network UPS Tools - Generic HID driver 0.53 (2.8.2-43-g26eca8456)
USB communication driver (libusb 1.0) 0.47
Duplicate driver instance detected (PID file /var/state/ups/usbhid-ups-eco650.pid exists)! Terminating other driver!
Using subdriver: MGE HID 1.46

:; mv /var/state/ups/usbhid-ups-eco650.pid{,.x}
:; ./drivers/usbhid-ups -a eco650
Network UPS Tools - Generic HID driver 0.53 (2.8.2-43-g26eca8456)
USB communication driver (libusb 1.0) 0.47
Can't claim USB device [0463:ffff]@0/0/0: Entity not found
upsnotify: notify about state 4 with libsystemd: was requested, but not running as a service unit now, will not spam more about it
upsnotify: failed to notify about state 4: no notification tech defined, will not spam more about it

…"Duplicate driver instance" [networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov · 2024-04-12T09:20:30Z

Added some more debug printouts, testing with the build:

Older driver running, no PID file (renamed away):

:; NUT_DEBUG_LEVEL=6 ./drivers/usbhid-ups -a eco650
...
   0.000819     [D1] Succeeded to become_user(nut): now UID=77 GID=77
   0.000835     [D1] PID file /var/state/ups/usbhid-ups-eco650.pid not found; stat() returned -1 (errno=2): No such file or directory
   0.000897     [D1] Saving PID 4084380 into /var/state/ups/usbhid-ups-eco650.pid
...
   0.454088     [D2] failed to claim USB device: Resource busy
   0.454091     [D2] Kernel driver already detached
   0.454097     Can't claim USB device [0463:ffff]@0/0/0: Entity not found
   0.454105     [D5] send_to_all: SETINFO driver.state "cleanup.exit"
...

Old driver running and its matching PID file is present:

...
   0.001184     [D1] Succeeded to become_user(nut): now UID=77 GID=77
   0.001207     Duplicate driver instance detected (PID file /var/state/ups/usbhid-ups-eco650.pid exists)! Terminating other driver!
   0.001251     [D1] Signal sent without errors, allow the other driver instance some time to quit



   5.001325     [D1] PID file /var/state/ups/usbhid-ups-eco650.pid not found; stat() returned -1 (errno=2): No such file or directory
   5.001420     [D1] Saving PID 4182809 into /var/state/ups/usbhid-ups-eco650.pid
...
   5.425297     [D2] Device matches
   5.425300     [D2] Reading configuration descriptor 1 of 6
   5.425307     [D3] libusb_kernel_driver_active() returned 0: Success
   5.425319     [D2] Claimed interface 0 successfully
...

…peting driver instances) same as when backgrounding [networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov · 2024-04-12T09:37:50Z

Updated to handle -FF earlier for PID file interaction. Now with the PR build it goes like this....

With older driver (matching PID file present):

:;  ./drivers/usbhid-ups -a eco650 -FF
Network UPS Tools - Generic HID driver 0.53 (2.8.2-44-g3e6bb04e2)
USB communication driver (libusb 1.0) 0.47
Duplicate driver instance detected (PID file /var/state/ups/usbhid-ups-eco650.pid exists)! Terminating other driver!
Using subdriver: MGE HID 1.46
Running as foreground process, but saving a PID file anyway
upsnotify: notify about state 2 with libsystemd: was requested, but not running as a service unit now, will not spam more about it
upsnotify: failed to notify about state 2: no notification tech defined, will not spam more about it
upsnotify: logged the systemd watchdog situation once, will not spam more about it
sock_connect: enabling asynchronous mode (auto)
...
^C
Signal 2: exiting

With no competition:

:; ./drivers/usbhid-ups -a eco650 -FF
Network UPS Tools - Generic HID driver 0.53 (2.8.2-44-g3e6bb04e2)
USB communication driver (libusb 1.0) 0.47
Using subdriver: MGE HID 1.46
Running as foreground process, but saving a PID file anyway
upsnotify: notify about state 2 with libsystemd: was requested, but not running as a service unit now, will not spam more about it
upsnotify: failed to notify about state 2: no notification tech defined, will not spam more about it
upsnotify: logged the systemd watchdog situation once, will not spam more about it
sock_connect: enabling asynchronous mode (auto)
....
^CSignal 2: exiting

jimklimov · 2024-04-12T09:46:24Z

Interaction over Unix socket protocol is indeed seen (per upsdrvquery finds, see #1922, #1929 and many contemporary issues and PRs) for only do_forceshutdown and SIGCMD_RELOAD_OR_ERROR handling; the latter just before handling the if (cmd || foreground==...) with PID files.

…s of large clauses Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov · 2024-04-12T11:51:18Z

Hah, there's a printout around exit, it seems (or perhaps only then it is flushed?):

:; systemctl restart nut-driver@eco650

...
Apr 12 13:49:19 pve systemd[1]: Stopping Network UPS Tools - device driver for NUT device 'eco650'...
Apr 12 13:49:19 pve nut-driver@eco650[1594698]: Network UPS Tools - UPS driver controller 2.8.2-50-g233a9bd3c
Apr 12 13:49:20 pve nut-driver@eco650[1592511]: Signal 15: exiting
Apr 12 13:49:20 pve usbhid-ups[1592511]: Signal 15: exiting

Apr 12 13:49:21 pve nut-driver@eco650[1594698]: fopen /var/state/ups/usbhid-ups-eco650.pid: No such file or directory

Apr 12 13:49:21 pve systemd[1]: nut-driver@eco650.service: Succeeded.
Apr 12 13:49:21 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.

Apr 12 13:49:21 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'eco650'...
Apr 12 13:49:21 pve nut-driver@eco650[1594798]: Network UPS Tools - UPS driver controller 2.8.2-50-g233a9bd3c
Apr 12 13:49:21 pve nut-driver@eco650[1594798]: Network UPS Tools - Generic HID driver 0.53 (2.8.2-50-g233a9bd3c)
Apr 12 13:49:21 pve nut-driver@eco650[1594798]: USB communication driver (libusb 1.0) 0.47
Apr 12 13:49:25 pve nut-driver@eco650[1594798]: Using subdriver: MGE HID 1.46
Apr 12 13:49:27 pve nut-driver@eco650[1594798]: Running as foreground process, but saving a PID file anyway
Apr 12 13:49:27 pve usbhid-ups[1594798]: Running as foreground process, but saving a PID file anyway
Apr 12 13:49:27 pve systemd[1]: Started Network UPS Tools - device driver for NUT device 'eco650'.
Apr 12 13:49:27 pve nut-driver@eco650[1594798]: upsnotify: logged the systemd watchdog situation once, will not spam more about it
Apr 12 13:49:27 pve usbhid-ups[1594798]: upsnotify: logged the systemd watchdog situation once, will not spam more about it
Apr 12 13:49:28 pve nut-driver@eco650[1594798]: sock_connect: enabling asynchronous mode (auto)
Apr 12 13:49:28 pve usbhid-ups[1594798]: sock_connect: enabling asynchronous mode (auto)
...

jimklimov · 2024-04-12T12:29:16Z

Ok, so this printout is only in the systemd unit, and is due to upsdrvctl also sending signals without the quietness added here, and happens as the program loops sending the signal until success (being the inability to send a signal after initial non-failure to do so - meaning/assuming the target process exited), e.g.:

Apr 12 14:26:17 pve nut-driver@eco650[1799936]:    0.000041        [D1] upsdrvctl commanding one driver (eco650): stop
Apr 12 14:26:17 pve nut-driver@eco650[1799936]:    0.000044        [D1] Stopping UPS: eco650
Apr 12 14:26:17 pve nut-driver@eco650[1799936]:    0.000049        [D2] Sending signal to /var/state/ups/usbhid-ups-eco650.pid
Apr 12 14:26:17 pve nut-driver@eco650[1798869]:   35.157417        [D1] set_exit_flag: raising exit flag due to signal 15
Apr 12 14:26:17 pve nut-driver@eco650[1798869]:   35.157435        Signal 15: exiting
Apr 12 14:26:17 pve nut-driver@eco650[1798869]:   35.157500        [D1] upsdrv_cleanup...
Apr 12 14:26:18 pve nut-driver@eco650[1799936]:    1.000171        fopen /var/state/ups/usbhid-ups-eco650.pid: No such file or directory
Apr 12 14:26:18 pve nut-driver@eco650[1799936]:    1.000184        [D2] Sending signal to /var/state/ups/usbhid-ups-eco650.pid failed, driver is finally down or wrongly owned
Apr 12 14:26:18 pve nut-driver@eco650[1799936]:    1.000187        [D1] upsdrvctl: successfully finished
Apr 12 14:26:18 pve nut-driver@eco650[1799936]:    1.000192        [D1] Completed the job of upsdrvctl tool, cleaning up and exiting now
Apr 12 14:26:18 pve nut-driver@eco650[1799936]:    1.000195        [D1] Completed the job of upsdrvctl tool, clean-up finished, exiting now
Apr 12 14:26:18 pve systemd[1]: nut-driver@eco650.service: Succeeded.
Apr 12 14:26:18 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.

…workupstools#1916 to be solved Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…signal_debug_level verbosity toggle to hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov · 2024-04-13T11:42:21Z

Fixed the upsdrvctl bit, now it looks like this:

:;  systemctl restart nut-driver@eco650
...
Apr 13 13:38:55 pve systemd[1]: Stopping Network UPS Tools - device driver for NUT device 'eco650'...
Apr 13 13:38:55 pve nut-driver@eco650[1730845]: Network UPS Tools - UPS driver controller 2.8.2-49-ge9f513331
Apr 13 13:38:55 pve nut-driver@eco650[1729944]: Signal 15: exiting
Apr 13 13:38:55 pve usbhid-ups[1729944]: Signal 15: exiting
Apr 13 13:38:56 pve systemd[1]: nut-driver@eco650.service: Succeeded.
Apr 13 13:38:56 pve systemd[1]: Stopped Network UPS Tools - device driver for NUT device 'eco650'.

Apr 13 13:38:56 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'eco650'...
Apr 13 13:38:56 pve nut-driver@eco650[1730853]: Network UPS Tools - UPS driver controller 2.8.2-49-ge9f513331
Apr 13 13:38:56 pve nut-driver@eco650[1730853]: Network UPS Tools - Generic HID driver 0.53 (2.8.2-49-ge9f513331)
Apr 13 13:38:56 pve nut-driver@eco650[1730853]: USB communication driver (libusb 1.0) 0.47
Apr 13 13:39:00 pve nut-driver@eco650[1730853]: Using subdriver: MGE HID 1.46
Apr 13 13:39:02 pve nut-driver@eco650[1730853]: Running as foreground process, but saving a PID file anyway
Apr 13 13:39:02 pve usbhid-ups[1730853]: Running as foreground process, but saving a PID file anyway
Apr 13 13:39:02 pve systemd[1]: Started Network UPS Tools - device driver for NUT device 'eco650'.
Apr 13 13:39:02 pve nut-driver@eco650[1730853]: upsnotify: logged the systemd watchdog situation once, will not spam more about it
Apr 13 13:39:02 pve usbhid-ups[1730853]: upsnotify: logged the systemd watchdog situation once, will not spam more about it
Apr 13 13:39:03 pve nut-driver@eco650[1730853]: sock_connect: enabling asynchronous mode (auto)
Apr 13 13:39:03 pve usbhid-ups[1730853]: sock_connect: enabling asynchronous mode (auto)

Note the duplicate messages tagged with nut-driver@eco650 and with usbhid-ups (same PID for both) - this is likely due to systemd also being the syslog, so it captures both stderr and syslog'ed messages (upslogx() can post both, upsdebugx() maybe too?). The log behavior may be changing as part of daemonization.

PRs are welcome regarding unit settings to avoid NUT syslog when running as a systemd service without an explicitly configured (e.g. external) syslog sink.

I'll post an issue but do not intend to address it soon myself.

…rbosity toggle [networkupstools#1782, networkupstools#2392, networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…ush scary noise from attempts to "driver.exit" a sibling [networkupstools#1782, networkupstools#2392, networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

…h "INSTCMD driver.exit" so that we can make that verbose again if dialog started but failed to stop the other driver [networkupstools#2384, networkupstools#2392] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov added 6 commits April 6, 2024 14:32

clients/upsmon.c: do not be verbose in loadconfig() if we are just qu…

643fc77

…ietly checking killpower flag [networkupstools#2383] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

common/common.c, include/common.h: extend with nut_sendsignal_debug_l…

c441056

…evel verbosity toggle [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

clients/upsmon.c: use nut_sendsignal_debug_level verbosity toggle to …

a3525b5

…hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

drivers/main.c: use nut_sendsignal_debug_level verbosity toggle to hu…

2a4deae

…sh initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

server/upsd.c: use nut_sendsignal_debug_level verbosity toggle to hus…

9035898

…h initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

NEWS.adoc, docs/nut.dict: use nut_sendsignal_debug_level verbosity to…

e3631d0

…ggle to hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov added enhancement service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug labels Apr 6, 2024

jimklimov added this to the 2.8.3 milestone Apr 6, 2024

clients/upsmon.c: clarify that lack of a running daemon PID file is O…

00c2494

…K when checking_flag (for POWERDOWNFLAG) Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov added the need testing Code looks reasonable, but the feature would better be tested against hardware or OSes label Apr 6, 2024

jimklimov added 2 commits April 7, 2024 22:25

Merge branch 'master' into issue-321

aef48a4

Merge branch 'master' into issue-321

26eca84

drivers/main.c: add debug tracing for interactions with PID file and …

3e6bb04

…"Duplicate driver instance" [networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

drivers/main.c, NEWS.adoc: handle "-FF" to process PID files (and com…

a74f65a

…peting driver instances) same as when backgrounding [networkupstools#2384] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov changed the title ~~Quieter start-up of upsmon, upsd and driver daemons~~ Quieter start-up of upsmon, upsd and driver daemons (avoid "scary" fopen() failure messages) Apr 12, 2024

jimklimov added 2 commits April 12, 2024 11:51

drivers/main.c: properly indent cmd/pidfile handling and annotate end…

cfdf633

…s of large clauses Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

drivers/main.c: bump (C) year

b50b5df

Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov mentioned this pull request Apr 12, 2024

Driver main.c: use Unix socket protocol to kill off "Duplicate other instance" #2392

Closed

jimklimov mentioned this pull request Apr 12, 2024

Implement an INSTCMD driver.exit as alternative to PID files and signals #2393

Merged

jimklimov added 2 commits April 13, 2024 13:08

drivers/upsdrvctl.c: annotate "ifdef WIN32" locations waiting for net…

4a6cd97

…workupstools#1916 to be solved Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

drivers/upsdrvctl.c: stop_driver(), signal_driver_cmd(): use nut_send…

e9f5133

…signal_debug_level verbosity toggle to hush initial fopen(pidfile) scary noise [networkupstools#1782] Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

jimklimov mentioned this pull request Apr 13, 2024

NUT systemd unit journals duplicate some lines #2394

Closed

jimklimov added the ready / gonna merge The PR is in final cycles leading to merge unless someone logs an objection before we hit the button label Apr 13, 2024

jimklimov merged commit 7f36d49 into networkupstools:master Apr 13, 2024

jimklimov deleted the issue-321 branch April 13, 2024 16:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Quieter start-up of `upsmon`, `upsd` and driver daemons (avoid "scary" `fopen()` failure messages)#2384

Quieter start-up of `upsmon`, `upsd` and driver daemons (avoid "scary" `fopen()` failure messages)#2384
jimklimov merged 15 commits intonetworkupstools:masterfrom
jimklimov:issue-321

jimklimov commented Apr 6, 2024 •

edited

Loading

Uh oh!

jimklimov commented Apr 6, 2024

Uh oh!

jimklimov commented Apr 12, 2024

Uh oh!

jimklimov commented Apr 12, 2024 •

edited

Loading

Uh oh!

jimklimov commented Apr 12, 2024 •

edited

Loading

Uh oh!

jimklimov commented Apr 12, 2024 •

edited

Loading

Uh oh!

jimklimov commented Apr 12, 2024

Uh oh!

jimklimov commented Apr 12, 2024 •

edited

Loading

Uh oh!

jimklimov commented Apr 13, 2024 •

edited

Loading

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Uh oh!

Conversation

jimklimov commented Apr 6, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jimklimov commented Apr 6, 2024

Uh oh!

jimklimov commented Apr 12, 2024

Uh oh!

jimklimov commented Apr 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jimklimov commented Apr 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jimklimov commented Apr 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jimklimov commented Apr 12, 2024

Uh oh!

jimklimov commented Apr 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jimklimov commented Apr 13, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

jimklimov commented Apr 6, 2024 •

edited

Loading

jimklimov commented Apr 12, 2024 •

edited

Loading

jimklimov commented Apr 12, 2024 •

edited

Loading

jimklimov commented Apr 12, 2024 •

edited

Loading

jimklimov commented Apr 12, 2024 •

edited

Loading

jimklimov commented Apr 13, 2024 •

edited

Loading