Skip to content

UPSD too eager to report Data stale #661

@jimklimov

Description

@jimklimov

On our relatively busy NAS server there are occasionally console messages that Data for UPS X is stale. In original default settings, the messages for data is no longer stale do not get to the console (which looked worrysome, to see only lots of failures, until I updated logging settings).

Now that both types of messages are here, I see that stale and not-stale often happen in the same second, so with a bit of patience much of this spam could be avoided :)

To me it seems like some off-by-one math error in patience calculation, or perhaps a hint to induce one to avoid spurious messages on systems a bit too busy to context-switch fast?

Guessing from cases I've seen before in different codebases, maybe there is a rounding error of sec/msec/usec (including granularity of time reports from an OS - more pronounced for filesystem objects which may be off by 1-2 seconds) and comparisons of those numbers assuming infinite (or at least same) precision?

Also sometimes, less often, there are connection losses and re-establishments logged by upsmon some 9-10 seconds apart (probably hitting a 10-second frequency of status evaluation somewhere)... I am not sure how those could be avoided. Perhaps, upsmon could do some double-check (and/or tell upsd to do so) before resorting to a verdict of connection loss.

Example "screenshot" below:

Feb 10 16:42:04 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 17:40:53 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 17:40:53 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 17:41:04 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 18:10:41 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 18:10:42 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 18:10:44 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 18:10:44 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 18:10:58 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 18:11:09 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 18:11:11 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 18:11:11 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 18:11:15 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 18:11:26 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 18:12:55 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 18:12:55 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 19:54:37 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 19:54:40 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:24:08 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 20:24:08 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 20:24:08 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:24:08 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:24:26 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:24:26 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:24:35 bios-backup upsmon[930]: [ID 702911 daemon.error] Set password on [eaton@localhost] failed: Server disconnected
Feb 10 20:24:45 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Driver not connected
Feb 10 20:24:45 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:24:55 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:25:01 bios-backup upsmon[930]: [ID 702911 daemon.error] Set username on [eaton@localhost] failed: Server disconnected
Feb 10 20:25:01 bios-backup upsd[922]: [ID 702911 daemon.notice] write() failed for ::1: Broken pipe
Feb 10 20:25:08 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Driver not connected
Feb 10 20:25:18 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:25:18 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 20:25:31 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 20:25:42 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:25:42 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 20:25:59 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 20:25:59 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 20:26:00 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:26:11 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:26:22 bios-backup upsmon[930]: [ID 702911 daemon.error] Set username on [eaton@localhost] failed: Server disconnected
Feb 10 20:26:22 bios-backup upsd[922]: [ID 702911 daemon.notice] write() failed for ::1: Broken pipe
Feb 10 20:26:29 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:26:29 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:26:34 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Driver not connected
Feb 10 20:26:45 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:26:45 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 20:26:57 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 20:27:08 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:27:08 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 20:28:19 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:28:20 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 20:28:20 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 20:28:25 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 20:28:30 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 20:39:37 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 20:39:37 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 21:10:18 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Server disconnected
Feb 10 21:10:18 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 21:10:29 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 10 23:25:35 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 10 23:25:35 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 10 23:25:36 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 10 23:25:36 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 10 23:25:45 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 11 01:10:36 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 01:10:38 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 01:10:40 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 11 01:10:40 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 11 01:10:50 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 11 01:11:04 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 01:11:04 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 02:25:37 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 02:25:37 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 02:55:28 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 02:55:32 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 02:55:34 bios-backup upsmon[930]: [ID 702911 daemon.error] Poll UPS [eaton@localhost] failed - Data stale
Feb 11 02:55:34 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost lost
Feb 11 02:55:44 bios-backup upsmon[930]: [ID 702911 daemon.notice] Communications with UPS eaton@localhost established
Feb 11 03:47:40 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 03:47:40 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 04:46:58 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 04:46:58 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 06:35:46 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 06:35:46 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale
Feb 11 07:18:59 bios-backup upsd[922]: [ID 702911 daemon.notice] Data for UPS [eaton] is stale - check driver
Feb 11 07:18:59 bios-backup upsd[922]: [ID 702911 daemon.notice] UPS [eaton] data is no longer stale

Metadata

Metadata

Assignees

No one assigned

    Labels

    Connection stability issuesIssues about driver<->device and/or networked connections (upsd<->upsmon...) going AWOL over timeimpacts-release-2.7.4Issues reported against NUT release 2.7.4 (maybe vanilla or with minor packaging tweaks)

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions