search

networkupstools / nut

The Network UPS Tools repository. UPS management protocol Informational RFC 9271 published by IETF at https://www.rfc-editor.org/info/rfc9271 Please star NUT on GitHub, this helps with sponsorships!
https://networkupstools.org/
Other
1.99k stars 349 forks source link

NUT systemd unit journals duplicate some lines #2394

Closed jimklimov closed 2 months ago

jimklimov commented 6 months ago

There is often some noise to be seen in NUT daemons wrapped as systemd service units, e.g.:

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.

_Originally posted by @jimklimov in https://github.com/networkupstools/nut/issues/2384#issuecomment-2053622089_

Other samples:

* `nut-server` (`upsd`) without debug:

Apr 13 13:52:11 pve systemd[1]: Starting Network UPS Tools - power devices information server... Apr 13 13:52:11 pve nut-server[1817645]: Network UPS Tools upsd 2.8.2-49-ge9f513331 Apr 13 13:52:11 pve nut-server[1817645]: Could not find PID file '/var/state/ups/upsd.pid' to see if previous upsd instance is already running! Apr 13 13:52:11 pve nut-server[1817645]: listening on ::0 port 3493 Apr 13 13:52:11 pve nut-server[1817645]: listening on 0.0.0.0 port 3493 Apr 13 13:52:11 pve upsd[1817645]: listening on ::0 port 3493 Apr 13 13:52:11 pve upsd[1817645]: listening on 0.0.0.0 port 3493 Apr 13 13:52:11 pve nut-server[1817645]: Connected to UPS [eco650]: usbhid-ups-eco650 Apr 13 13:52:11 pve nut-server[1817645]: Can't connect to UPS [dummy] (dummy-ups-dummy): Connection refused Apr 13 13:52:11 pve nut-server[1817645]: Found 2 UPS defined in ups.conf Apr 13 13:52:11 pve upsd[1817645]: Connected to UPS [eco650]: usbhid-ups-eco650 Apr 13 13:52:11 pve nut-server[1817645]: Running as foreground process, but saving a PID file anyway Apr 13 13:52:11 pve upsd[1817645]: Can't connect to UPS [dummy] (dummy-ups-dummy): Connection refused Apr 13 13:52:11 pve upsd[1817645]: Found 2 UPS defined in ups.conf Apr 13 13:52:11 pve upsd[1817645]: Running as foreground process, but saving a PID file anyway Apr 13 13:52:11 pve nut-server[1817645]: upsnotify: logged the systemd watchdog situation once, will not spam more about it Apr 13 13:52:11 pve upsd[1817645]: upsnotify: logged the systemd watchdog situation once, will not spam more about it Apr 13 13:52:11 pve nut-server[1817646]: Limit Soft Limit Hard Limit Units Apr 13 13:52:11 pve nut-server[1817646]: Max open files 1048576 1048576 files Apr 13 13:52:11 pve systemd[1]: Started Network UPS Tools - power devices information server.

* `nut-server` (`upsd`) with debug:

...

Apr 13 13:47:56 pve upsd[1727516]: [D2] mainloop: polling 5 filedescriptors Apr 13 13:47:56 pve nut-server[1727516]: 654.307409 [D2] write: [destfd=8] [len=27] [ERR FEATURE-NOT-CONFIGURED] Apr 13 13:47:56 pve nut-server[1727516]: 654.307419 [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve nut-server[1727516]: 654.307423 [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve nut-server[1727516]: 654.307433 [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve nut-server[1727516]: 654.307440 [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve nut-server[1727516]: 654.307444 [D2] mainloop: polling 5 filedescriptors Apr 13 13:47:56 pve nut-server[1727516]: 654.307460 [D2] write: [destfd=8] [len=32] [VAR eco650 battery.charge "100"] Apr 13 13:47:56 pve nut-server[1727516]: 654.307465 [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve nut-server[1727516]: 654.307469 [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve upsd[1727516]: [D2] write: [destfd=8] [len=27] [ERR FEATURE-NOT-CONFIGURED] Apr 13 13:47:56 pve nut-server[1727516]: 654.307478 [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve nut-server[1727516]: 654.307483 [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve nut-server[1727516]: 654.307488 [D2] mainloop: polling 5 filedescriptors Apr 13 13:47:56 pve nut-server[1727516]: 654.307578 [D2] write: [destfd=8] [len=11] [OK Goodbye] Apr 13 13:47:56 pve nut-server[1727516]: 654.307585 [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve nut-server[1727516]: 654.307589 [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve nut-server[1727516]: 654.307599 [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve nut-server[1727516]: 654.307605 [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve nut-server[1727516]: 654.307609 [D2] Disconnect from 127.0.0.1 Apr 13 13:47:56 pve nut-server[1727516]: 654.307616 [D2] mainloop: polling 4 filedescriptors Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve upsd[1727516]: [D2] mainloop: polling 5 filedescriptors Apr 13 13:47:56 pve upsd[1727516]: [D2] write: [destfd=8] [len=32] [VAR eco650 battery.charge "100"] Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve upsd[1727516]: [D2] mainloop: polling 5 filedescriptors Apr 13 13:47:56 pve upsd[1727516]: [D2] write: [destfd=8] [len=11] [OK Goodbye] Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:56 pve upsd[1727516]: [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:56 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:56 pve upsd[1727516]: [D2] Disconnect from 127.0.0.1 Apr 13 13:47:56 pve upsd[1727516]: [D2] mainloop: polling 4 filedescriptors Apr 13 13:47:57 pve upsd[1727516]: [D2] write: [destfd=7] [len=27] [VAR eco650 ups.status "OL"] Apr 13 13:47:57 pve nut-server[1727516]: 655.043011 [D2] write: [destfd=7] [len=27] [VAR eco650 ups.status "OL"] Apr 13 13:47:57 pve nut-server[1727516]: 655.043037 [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:57 pve nut-server[1727516]: 655.043045 [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:57 pve nut-server[1727516]: 655.043067 [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:57 pve nut-server[1727516]: 655.043077 [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:57 pve nut-server[1727516]: 655.043082 [D2] mainloop: polling 4 filedescriptors Apr 13 13:47:57 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:57 pve upsd[1727516]: [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:57 pve upsd[1727516]: [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:57 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:57 pve upsd[1727516]: [D2] mainloop: polling 4 filedescriptors Apr 13 13:47:57 pve nut-server[1727516]: 655.074843 [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:57 pve nut-server[1727516]: 655.074863 [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:57 pve nut-server[1727516]: 655.074886 [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:57 pve nut-server[1727516]: 655.074896 [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:57 pve nut-server[1727516]: 655.074902 [D2] mainloop: polling 4 filedescriptors Apr 13 13:47:57 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is not currently connected, trying to reconnect Apr 13 13:47:57 pve upsd[1727516]: [D2] sstate_connect: preparing UNIX socket dummy-ups-dummy Apr 13 13:47:57 pve upsd[1727516]: [D2] sstate_connect: failed to connect() UNIX socket dummy-ups-dummy (dummy-ups-dummy) Apr 13 13:47:57 pve upsd[1727516]: [D1] mainloop: UPS [dummy] is still not connected (FD -1) Apr 13 13:47:57 pve upsd[1727516]: [D2] mainloop: polling 4 filedescriptors


* On the contrary, `nut-monitor` (`upsmon`) is rather single-minded about its logging:

Apr 13 13:37:02 pve systemd[1]: Starting Network UPS Tools - power device monitor and shutdown controller... Apr 13 13:37:02 pve nut-monitor[1727519]: Network UPS Tools upsmon 2.8.2-49-ge9f513331 Apr 13 13:37:02 pve nut-monitor[1727519]: Defaulting debug verbosity to NUT_DEBUG_LEVEL=3 since none was requested by command-line options Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000014 fopen /run/upsmon.pid: No such file or directory Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000020 Could not find PID file to see if previous upsmon instance is already running! Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000033 [D1:1727519] loadconfig: Loading /etc/nut/upsmon.conf Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000061 UPS: eco650 (primary) (power value 1) Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000087 Using power down flag file /etc/killpower Apr 13 13:37:02 pve nut-monitor[1727519]: 0.000124 [D1:1727519] debug level is '6' Apr 13 13:37:02 pve nut-monitor[1727520]: 0.000398 [D1:1727520] Saving PID 1727520 into /run/upsmon.pid Apr 13 13:37:02 pve nut-monitor[1727520]: 0.000764 [D1:1727520] Succeeded to become_user(nut): now UID=77 GID=77 Apr 13 13:37:02 pve nut-monitor[1727520]: 0.001688 [D6:1727520] upsnotify: notify about state 2 with libsystemd: use sd_notify() Apr 13 13:37:02 pve nut-monitor[1727520]: 0.001696 [D6:1727520] upsnotify: notifying systemd about MAINPID=1727520 Apr 13 13:37:02 pve nut-monitor[1727520]: 0.001701 [D6:1727520] upsnotify: posting sd_notify: READY=1 Apr 13 13:37:02 pve nut-monitor[1727520]: MAINPID=1727520 Apr 13 13:37:02 pve nut-monitor[1727520]: MONOTONIC_USEC=1868540402392 Apr 13 13:37:02 pve nut-monitor[1727520]: 0.001725 [D6:1727520] upsnotify: wait for NOTIFY_STATE_READY_WITH_PID to be handled by systemd Apr 13 13:37:02 pve systemd[1]: nut-monitor.service: Supervising process 1727520 which is not our child. We'll most likely not notice when it exits. Apr 13 13:37:02 pve systemd[1]: Started Network UPS Tools - power device monitor and shutdown controller. Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002162 [D6:1727520] upsnotify: notify about state 6 with libsystemd: use sd_notify() Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002169 [D6:1727520] upsnotify: sd_enabled_watchdog query returned: 0 (0msec remain) Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002172 [D6:1727520] upsnotify: WATCHDOG_USEC=(null) Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002175 [D6:1727520] upsnotify: failed to tickle the watchdog: not enabled for this unit Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002177 [D6:1727520] upsnotify: failed to notify about state 6 Apr 13 13:37:02 pve nut-monitor[1727520]: 0.002178 upsnotify: logged the systemd watchdog situation once, will not spam more about it ...

jimklimov commented 2 months ago

Ended up addressing the problem myself. Once I saw it, reading the NUT journals during dev-testing became very annoying :)