Changing NUT daemon debug verbosity

Overview

Table of Contents

• Current development version (future NUT v2.8.1+)
• NUT v2.8.0
• NUT v2.7.4 and older

NUT programs emit many messages to trace progress and provide other hints as deemed needed by developers and other contributors, with somewhat arbitrarily assigned verbosity levels for each message: 0 being (almost) silent, 1 being the top-level overview of activity, and greater numbers adding more levels of detail (or noise). When NUT programs are started, a debug verbosity level can be configured by command-line arguments or other means (depending on NUT version), which means that messages with that or lower (closer to 0) level become visible on standard error channel and/or syslog.

The way to configure the verbosity setting depends on NUT version: with 2.8.0 or newer (e.g. custom builds) there are debug_min NUM settings for ups.conf, upsd.conf, upsmon.conf so it suffices just to edit the suitable config and reload/restart the daemon. For 2.7.4 and older releases, you have to edit their init-scripts or systemd units to add a -D parameter for one more level (max practical verbosity is 6, so -DDDDDD is common) and keep in mind that debug enabled via command-line puts the program into foreground mode (you may have to add & in init scripts, change Type in systemd units, etc.)

Current development version (future NUT v2.8.1+)

Since issue #1903 and a series of later pull requests, there is limited support for driver reloading to change configuration of running daemons for options which are known to not require thorough re-initialization — including the debug_min verbosity setting. This is integrated with the new drivername -c reload* and upsdrvctl command-line options, as well as with nut-daemon-enumerator script and service (systemd, SMF) which would previously only support restarting a driver if its configuration has changed.

From development perspective, this is supported via signals (POSIX builds) and Unix-socket/Windows-pipe protocol intended for driver to data server chatter.

• In fact, after issue #1285 got solved, the driver debug verbosity can be changed at run-time using the NUT client upsrw (with credentials per server upsd.users configuration file) like this for the maximum practical verbosity of 6:

  :; upsrw -u admin -p passw0rd -s driver.debug=6 myups
  OK

  Note that to see the resulting log information, you may have to tap into system logs or journals, as applicable to your operating system setup (also note that systemd journal tends to record nearby both console messages from nut-driver@myups and syslog protocol messages from e.g. usbhid-ups, if both are issued by a daemon), e.g.:

  :;  journalctl -flu nut-driver@myups
  -- Journal begins at Thu 2023-07-13 17:48:37 CEST. --
  Aug 05 12:13:36 pve systemd[1]: Starting Network UPS Tools - device driver for NUT device 'myups'...
  Aug 05 12:13:36 pve nut-driver@myups[2790307]: Debug level is 0, dump data count is off, but backgrounding mode requested as off
  Aug 05 12:13:40 pve nut-driver@myups[2790307]: Using subdriver: MGE HID 1.46
  Aug 05 12:13:40 pve nut-driver@myups[2790307]: Network UPS Tools - Generic HID driver 0.50 (2.8.0-2271-gd52971ecd)
  Aug 05 12:13:40 pve nut-driver@myups[2790307]: USB communication driver (libusb 1.0) 0.45
  Aug 05 12:13:42 pve nut-driver@myups[2790307]: Running as foreground process, but saving a PID file anyway
  Aug 05 12:13:42 pve systemd[1]: Started Network UPS Tools - device driver for NUT device 'myups'.
  Aug 05 12:13:43 pve nut-driver@myups[2790307]: sock_connect: enabling asynchronous mode (auto)
  
  Aug 05 12:18:23 pve nut-driver@myups[2790307]: Applying debug level 6 received during run-time via socket protocol, ignoring other settings
  Aug 05 12:18:23 pve nut-driver@myups[2790307]:  286.841999        [D1] debug level is '6'
  Aug 05 12:18:23 pve nut-driver@myups[2790307]:  286.842017        [D5] send_to_all: SETINFO driver.debug "6"
  Aug 05 12:18:23 pve nut-driver@myups[2790307]:  286.842025        [D6] send_to_all: write 25 bytes to socket 10 succeeded (ret=25): SETINFO driver.debug "6"
  Aug 05 12:18:24 pve nut-driver@myups[2790307]:  287.951842        [D5] send_to_all: SETINFO driver.state "updateinfo"
  Aug 05 12:18:24 pve nut-driver@myups[2790307]:  287.951877        [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
  Aug 05 12:18:24 pve nut-driver@myups[2790307]:  287.951886        [D1] upsdrv_updateinfo...
  Aug 05 12:18:25 pve nut-driver@myups[2790307]:  288.702002        [D2] nut_libusb_get_interrupt: Connection timed out
  Aug 05 12:18:25 pve nut-driver@myups[2790307]:  288.702033        [D1] Got 0 HID objects...
  Aug 05 12:18:25 pve nut-driver@myups[2790307]:  288.702044        [D1] Quick update...
  Aug 05 12:18:25 pve nut-driver@myups[2790307]:  288.702053        [D4] Entering libusb_get_report
  ...

  To disable, set the variable back to 0:

  :; upsrw -u admin -p passw0rd -s driver.debug=0 myups
  OK
  
  ### From journal:
  Aug 05 12:26:21 pve nut-driver@myups[2790307]:  765.039687        [D6] Driver on /var/state/ups/usbhid-ups-myups is now handling SET with 3 args
  Aug 05 12:26:21 pve nut-driver@myups[2790307]:  765.039692        [D2] entering main_setvar(driver.debug, 0) for [myups] on socket 10
  Aug 05 12:26:21 pve nut-driver@myups[2790307]:  765.039698        [D1] NOTE: Will disable verbose debug now, due to socket protocol request
  Aug 05 12:26:21 pve nut-driver@myups[2790307]:  765.039703        Applying debug level 0 received during run-time via socket protocol, ignoring other settings
  Aug 05 12:26:21 pve usbhid-ups[2790307]: [D6] Driver on /var/state/ups/usbhid-ups-myups is now handling SET with 3 args
  Aug 05 12:26:21 pve usbhid-ups[2790307]: [D2] entering main_setvar(driver.debug, 0) for [myups] on socket 10
  Aug 05 12:26:21 pve usbhid-ups[2790307]: [D1] NOTE: Will disable verbose debug now, due to socket protocol request
  Aug 05 12:26:21 pve usbhid-ups[2790307]: Applying debug level 0 received during run-time via socket protocol, ignoring other settings

Also since PR #1915, numerous daemons (upsd, upsmon, drivers, upsdrvctl, upssched) which accepted -D option for debug setting previously, now can also honour a NUT_DEBUG_LEVEL=NUM environment variable if no -D arguments were provided. Unlike those arguments, the environment variable does not enforce that daemons run in foreground mode by default.

• For systemd units as well as init scripts which parse the nut.conf file (or similar collection of shell environment variable settings), a NUT_DEBUG_LEVEL=NUM can be set there. Note it would have effect after restarting any NUT daemons (drivers, server, monitor…​) which use this file, and persist after commenting the setting away until all such daemons are restarted again.

NUT v2.8.0

Since PR #683 many NUT daemons support a debug_min NUMBER setting (with upper-/lower-casing to match other keywords in respective configuration files) which allows to set a non-zero initial debug verbosity for the respective program, without affecting the fore-/back-ground mode. That effort also added explicit -F and -B CLI options to many daemons, to request a fore-/back-ground mode explicitly, with default behavior remaining backwards-compatible (go to background unless debugging).

In particular, this allows to (temporarily) change verbosity for production services without editing or otherwise impacting their service methods, init-scripts, etc. For upsd and upsmon daemons (but not for drivers) the -c reload activity or equivalent reaction to SIGHUP should take the modified setting into account "on the fly".

NUT v2.7.4 and older

A typical change to bump debug verbosity would look like this:

• …​for init-scripts:

 start)
-    /usr/local/ups/bin/upsd
+    /usr/local/ups/bin/upsd -DDDDDD &
     ;;

• …​for systemd units you are encouraged to add a drop-in configuration file to override original lines, but it is technically possible to edit the original unit files for short-lived changes. In either case, don’t forget to systemd daemon-reload after editing and before restarting the unit. The effective change would be like:

-Type=forking
-ExecStart=/usr/local/ups/bin/upsd
+Type=simple
+ExecStart=/usr/local/ups/bin/upsd -DDDDDD