usbhid-ups: allow to throttle or suppress logged messages about OL+DISCHRG situation

NEWS.adoc

@@ -107,6 +107,19 @@ https://github.com/networkupstools/nut/milestone/10
    * `arduino-hid` subdriver was enhanced from "initial bare bones" experimental
      set of mapped data points to support some 20 more mappings to make it more
      useful as an UPS driver, not just a controller developer sandbox. [#2188]
+   * The `onlinedischarge` configuration flag name was too ambiguous and got
+     deprecated (will be supported but no longer promoted by documentation),
+     introducing `onlinedischarge_onbattery` as the meaningful alias. [#2213]
+   * Logged notifications about `OL+DISCHRG` state should now be throttled
+     (see the driver manual page for more details) [#2214, #2215]:
+     - If `battery.charge` is available, make the message when entering the
+       state and then only if the charge differs from that when we posted
+       the earlier message (e.g. really discharging) and is under
+       `onlinedischarge_log_throttle_hovercharge` value (defaults to 100%);
+     - Also can throttle to a time frequency configurable by a new option
+       `onlinedischarge_log_throttle_sec`, by default 30 sec if `battery.charge`
+       is not reported by the device (should be frequent by default, in case
+       the UPS-reported state combination does reflect a bad power condition).
 
 Release notes for NUT 2.8.1 - what's new since 2.8.0
 ----------------------------------------------------

docs/man/usbhid-ups.txt

@@ -114,12 +114,17 @@ If this flag is set, the driver will not use Interrupt In transfers during the
 shorter "pollinterval" cycles (not recommended, but needed if these reports
 are broken on your UPS).
 
-*onlinedischarge*::
-If this flag is set, the driver will treat `OL+DISCHRG` status as offline.
+*onlinedischarge_battery*::
+If this flag is set, the driver will treat `OL+DISCHRG` status as
+offline/on-battery.
++
 For most devices this combination means calibration or similar maintenance;
 however some UPS models (e.g. CyberPower UT series) emit `OL+DISCHRG` when
 wall power is lost -- and need this option to handle shutdowns.
 
+*onlinedischarge*::
+DEPRECATED, old name for `onlinedischarge_battery` described above.
+
 *onlinedischarge_calibration*::
 If this flag is set, the driver will treat `OL+DISCHRG` status as calibration.
 Some UPS models (e.g. APC were seen to do so) report `OL+DISCHRG` when they
@@ -130,6 +135,31 @@ NOTE: If it takes so long on your device that a shutdown gets issued, you may
 want to look at `upsmon` option `OFFDURATION` used to filter out temporary
 values of "administrative OFF" as not a loss of a feed for the powered load.
 
+*onlinedischarge_log_throttle_sec*='num'::
+Set the minimum frequency (in seconds) at which warnings would be emitted
+for an otherwise not handled `OL+DISCHRG` device status combination.
+Negative values disable sequentially repeated messages (when this state
+appears and persists).
++
+If the device does not report `battery.charge`, the default value is 30 seconds
+(fairly frequent, in case the UPS-reported state combination does reflect a
+bad power condition and so the situation is urgent).
++
+If it does report `battery.charge`, by default the repeated notifications
+would only be logged if this charge is different from when the message was
+emitted previously (e.g. when the battery is really discharging).
++
+If both this option is set, and `battery.charge` is correctly reported,
+either of these rules allow the notification to be logged.
+
+*onlinedischarge_log_throttle_hovercharge*='num'::
+See details in `onlinedischarge_log_throttle_sec` and `battery.charge` based
+log message throttling description above.  This option adds a concept of UPS
+"hovering" a battery charge at some level deemed safe for its chemistry, and
+not forcing it to be fully charged all the time.  As long as the current value
+of `battery.charge` remains at or above this threshold percentage (default 100),
+the `OL+DISCHRG` message logging is not triggered by variations of the charge.
+
 *disable_fix_report_desc*::
 Set to disable fix-ups for broken USB encoding, etc. which we apply by default
 on certain models (vendors/products) which were reported as not following the

docs/nut.dict

@@ -1,4 +1,4 @@
-personal_ws-1.1 en 3421 utf-8
+personal_ws-1.1 en 3423 utf-8
 AAC
 AAS
 ABI
@@ -2173,6 +2173,7 @@ hostnames
 hostsfile
 hotplug
 hotplugging
+hovercharge
 hpe
 href
 htaccess
@@ -2661,6 +2662,7 @@ oldmge
 oldnut
 omnios
 onbatt
+onbattery
 onbattwarn
 onclick
 ondelay

drivers/usbhid-ups.c

@@ -145,8 +145,10 @@ hid_dev_handle_t udev = HID_DEV_HANDLE_CLOSED;
  * CyberPower UT series sometime need a bit of help deciding their online status.
  * This quirk is to enable the special handling of OL & DISCHRG at the same time
  * as being OB (on battery power/no mains power). Enabled by device config flag.
+ * NOTE: Also known by legacy alias "onlinedischarge", deprecated but tolerated
+ * since NUT v2.8.2.
  */
-static int onlinedischarge = 0;
+static int onlinedischarge_onbattery = 0;
 
 /**
  * Some UPS models (e.g. APC were seen to do so) report OL & DISCHRG when they
@@ -155,6 +157,44 @@ static int onlinedischarge = 0;
  */
 static int onlinedischarge_calibration = 0;
 
+/**
+ * If/when an UPS reports OL & DISCHRG and we do not use any other special
+ * settings (e.g. they do not match the actual device capabilities/behaviors),
+ * the driver logs messages about the unexpected situation - on every cycle
+ * if must be. This setting allows to throttle frequency of such messages.
+ * A value of 0 is small enough to log on every processing cycle (old noisy
+ * de-facto default before NUT v2.8.2 which this throttle alleviates).
+ * A value of -1 (any negative passed via configuration) disables repeated
+ * messages completely.
+ * Default (-2) below is not final: if this throttle variable is *not* set
+ * in the driver configuration section, and...
+ * - If the device reports a battery.charge, the driver would default to
+ *   only repeat reports about OL & DISCHRG when this charge changes from
+ *   what it was when the previous report was made, independent of time;
+ * - Otherwise 30 sec.
+ * If both the throttle is set and battery.charge is reported (and changes
+ * over time), then hitting either trigger allows the message to be logged.
+ */
+static int onlinedischarge_log_throttle_sec = -2;
+/**
+ * When did we last emit the message?
+ */
+static time_t onlinedischarge_log_throttle_timestamp = 0;
+/**
+ * Last known battery charge (rounded to whole percent units)
+ * as of when we last actually logged about OL & DISCHRG.
+ * Gets reset to -1 whenever this condition is not present.
+ */
+static int onlinedischarge_log_throttle_charge = -1;
+/**
+ * If battery.charge is served and equals or exceeds this value,
+ * suppress logging about OL & DISCHRG if battery.charge varied
+ * since last logged message. Defaults to 100% as some devices
+ * only report this state combo when fully charged (probably
+ * they try to prolong battery life by not over-charging it).
+ */
+static int onlinedischarge_log_throttle_hovercharge = 100;
+
 /* support functions */
 static hid_info_t *find_nut_info(const char *varname);
 static hid_info_t *find_hid_info(const HIDData_t *hiddata);
@@ -944,11 +984,20 @@ void upsdrv_makevartable(void)
 	addvar(VAR_FLAG, "pollonly", "Don't use interrupt pipe, only use polling");
 
 	addvar(VAR_FLAG, "onlinedischarge",
-		"Set to treat discharging while online as being offline");
+		"Set to treat discharging while online as being offline/on-battery (DEPRECATED, use onlinedischarge_onbattery)");
+
+	addvar(VAR_FLAG, "onlinedischarge_onbattery",
+		"Set to treat discharging while online as being offline/on-battery");
 
 	addvar(VAR_FLAG, "onlinedischarge_calibration",
 		"Set to treat discharging while online as doing calibration");
 
+	addvar(VAR_VALUE, "onlinedischarge_log_throttle_sec",
+		"Set to throttle log messages about discharging while online (only so often)");
+
+	addvar(VAR_VALUE, "onlinedischarge_log_throttle_hovercharge",
+		"Set to throttle log messages about discharging while online (only if battery.charge is under this value)");
+
 	addvar(VAR_FLAG, "disable_fix_report_desc",
 		"Set to disable fix-ups for broken USB encoding, etc. which we apply by default on certain vendors/products");
 
@@ -1254,15 +1303,35 @@ void upsdrv_initups(void)
 		interrupt_only = 1;
 	}
 
-	/* Activate Cyberpower tweaks */
-	if (testvar("onlinedischarge")) {
-		onlinedischarge = 1;
+	/* Activate Cyberpower/APC tweaks */
+	if (testvar("onlinedischarge") || testvar("onlinedischarge_onbattery")) {
+		onlinedischarge_onbattery = 1;
 	}
 
 	if (testvar("onlinedischarge_calibration")) {
 		onlinedischarge_calibration = 1;
 	}
 
+	val = getval("onlinedischarge_log_throttle_sec");
+	if (val) {
+		int ipv = atoi(val);
+		if (ipv == 0 && strcmp("0", val)) {
+			onlinedischarge_log_throttle_sec = 30;
+			upslogx(LOG_WARNING,
+				"Warning: invalid value for "
+				"onlinedischarge_log_throttle_sec: %s, "
+				"defaulting to %d",
+				val, onlinedischarge_log_throttle_sec);
+		} else {
+			if (ipv < 0) {
+				/* Has a specific meaning: user said be quiet */
+				onlinedischarge_log_throttle_sec = -1;
+			} else {
+				onlinedischarge_log_throttle_sec = ipv;
+			}
+		}
+	}
+
 	if (testvar("disable_fix_report_desc")) {
 		disable_fix_report_desc = 1;
 	}
@@ -1880,32 +1949,145 @@ static void ups_status_set(void)
 		status_set("CAL");		/* calibration */
 	}
 
+	if ((!(ups_status & STATUS(DISCHRG))) && (
+		onlinedischarge_log_throttle_timestamp != 0
+		|| onlinedischarge_log_throttle_charge != -1
+	)) {
+		upsdebugx(1,
+			"%s: seems that UPS [%s] was in OL+DISCHRG state, "
+			"but no longer is now.",
+			__func__, upsname);
+		onlinedischarge_log_throttle_timestamp = 0;
+		onlinedischarge_log_throttle_charge = -1;
+	}
+
 	if (!(ups_status & STATUS(ONLINE))) {
 		status_set("OB");		/* on battery */
 	} else if ((ups_status & STATUS(DISCHRG))) {
+		int	do_logmsg = 0, current_charge = 0;
+
 		/* if online but discharging */
 		if (onlinedischarge_calibration) {
 			/* if we treat OL+DISCHRG as calibrating */
 			status_set("CAL");	/* calibration */
 		}
 
-		if (onlinedischarge) {
+		if (onlinedischarge_onbattery) {
 			/* if we treat OL+DISCHRG as being offline */
 			status_set("OB");	/* on battery */
 		}
 
-		if (!onlinedischarge && !onlinedischarge_calibration) {
+		if (!onlinedischarge_onbattery && !onlinedischarge_calibration) {
+			/* Some situation not managed by end-user's hints */
 			if (!(ups_status & STATUS(CALIB))) {
-				/* if in OL+DISCHRG unknowingly, warn user */
-				upslogx(LOG_WARNING, "%s: seems that UPS [%s] is in OL+DISCHRG state now. "
-				"Is it calibrating (perhaps you want to set 'onlinedischarge_calibration' option)? "
-				"Note that some UPS models (e.g. CyberPower UT series) emit OL+DISCHRG when "
-				"in fact offline/on-battery (perhaps you want to set 'onlinedischarge' option).",
-				__func__, upsname);
+				/* if in OL+DISCHRG unknowingly, warn user,
+				 * unless we throttle it this time - see below */
+				do_logmsg = 1;
 			}
-			/* if we're calibrating */
+			/* if we're presumably calibrating */
 			status_set("OL");	/* on line */
 		}
+
+		if (do_logmsg) {
+			/* Any throttling to apply? */
+			const char *s;
+
+			/* First disable, then enable if OK for noise*/
+			do_logmsg = 0;
+
+			/* Time or not, did the charge change since last log? */
+			if ((s = dstate_getinfo("battery.charge"))) {
+				/* NOTE: "0" may mean a conversion error: */
+				current_charge = atoi(s);
+				if (current_charge > 0
+				&&  current_charge != onlinedischarge_log_throttle_charge
+				) {
+					/* Charge has changed, but is it
+					 * now low enough to worry? */
+					if (onlinedischarge_log_throttle_hovercharge
+					    < onlinedischarge_log_throttle_charge
+					) {
+						upsdebugx(3, "%s: current "
+							"battery.charge=%d is under "
+							"onlinedischarge_log_throttle_charge=%d",
+							__func__, current_charge,
+							onlinedischarge_log_throttle_charge);
+						do_logmsg = 1;
+					} else {
+						/* All seems OK, don't spam log
+						 * unless running at a really
+						 * high debug verbosity */
+						upsdebugx(5, "%s: current "
+							"battery.charge=%d "
+							"is okay compared to "
+							"onlinedischarge_log_throttle_charge=%d",
+							__func__, current_charge,
+							onlinedischarge_log_throttle_charge);
+					}
+				}
+			} else {
+				/* Should we default the time throttle? */
+				if (onlinedischarge_log_throttle_sec == -2) {
+					onlinedischarge_log_throttle_sec = 30;
+					/* Report once, so almost loud */
+					upsdebugx(1, "%s: seems battery.charge "
+						"is not served by this device "
+						"or subdriver; defaulting "
+						"onlinedischarge_log_throttle_sec "
+						"to %d",
+						__func__,
+						onlinedischarge_log_throttle_sec);
+				}
+			}
+
+			/* Do we track and honor time since last log? */
+			if (onlinedischarge_log_throttle_timestamp > 0
+			&&  onlinedischarge_log_throttle_sec >= 0
+			) {
+				time_t	now;
+				time(&now);
+
+				if ((now - onlinedischarge_log_throttle_timestamp)
+				    >= onlinedischarge_log_throttle_sec
+				) {
+					/* Enough time elapsed */
+					do_logmsg = 1;
+				}
+			}
+		}
+
+		if (do_logmsg) {
+			char	msg_charge[LARGEBUF];
+			msg_charge[0] = '\0';
+
+			/* Remember when we last logged this message */
+			time(&onlinedischarge_log_throttle_timestamp);
+
+			if (current_charge > 0
+			&&  current_charge != onlinedischarge_log_throttle_charge
+			) {
+				/* Charge has changed, report and remember this */
+				if (onlinedischarge_log_throttle_charge < 0) {
+					/* First sequential message like this */
+					snprintf(msg_charge, sizeof(msg_charge),
+						"Battery charge is currently %d. ",
+						current_charge);
+				} else {
+					snprintf(msg_charge, sizeof(msg_charge),
+						"Battery charge changed from %d to %d "
+						"since last such report. ",
+						onlinedischarge_log_throttle_charge,
+						current_charge);
+				}
+				onlinedischarge_log_throttle_charge = current_charge;
+			}
+
+			upslogx(LOG_WARNING, "%s: seems that UPS [%s] is in OL+DISCHRG state now. %s"
+			"Is it calibrating (perhaps you want to set 'onlinedischarge_calibration' option)? "
+			"Note that some UPS models (e.g. CyberPower UT series) emit OL+DISCHRG when "
+			"in fact offline/on-battery (perhaps you want to set 'onlinedischarge_onbattery' option).",
+			__func__, upsname, msg_charge);
+		}
 	} else if ((ups_status & STATUS(ONLINE))) {
 		/* if simply online */
 		status_set("OL");