Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

NUT systemd unit journals duplicate some lines #2394

Open
jimklimov opened this issue Apr 13, 2024 · 0 comments
Open

NUT systemd unit journals duplicate some lines #2394

jimklimov opened this issue Apr 13, 2024 · 0 comments
Labels
enhancement Linux Some issues are specific to Linux as a platform packaging systemd
Milestone
2.8.4

Comments

@jimklimov
Copy link
Member

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

  • nut-driver (unit involves upsdrvctl calling the driver program):
:;  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.

Originally posted by @jimklimov in #2384 (comment)

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 jimklimov added this to the 2.8.4 milestone Apr 13, 2024
@jimklimov jimklimov added enhancement packaging systemd Linux Some issues are specific to Linux as a platform labels Apr 13, 2024
jimklimov added a commit to jimklimov/nut that referenced this issue Jun 4, 2024
@jimklimov
Introduce a NUT_DEBUG_SYSLOG environment variable [networkupstools#…
ed74bc5 
…2394]

Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>
@jimklimov jimklimov mentioned this issue Jun 4, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
enhancement Linux Some issues are specific to Linux as a platform packaging systemd
Projects
None yet
Milestone
2.8.4
Development

No branches or pull requests
1 participant
@jimklimov