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

apc usb: upsd long update cycle / delay #698

Open spacerunner5 opened 5 years ago

spacerunner5 commented 5 years ago

For some reason, it takes many seconds (>20) to minutes for ups.status to get updated.

No connection errors in logs. Is this a timer or driver related problem? I hope it's not the APC UPS reporting it's status sooooo late?

upsdrvctl common:

phoenix4 ~/tmp # upsdrvctl -DDD start
Network UPS Tools - UPS driver controller 2.7.4
   0.000000
If you're not a NUT core developer, chances are that you're told to enable debugging
to see why a driver isn't working for you. We're sorry for the confusion, but this is
the 'upsdrvctl' wrapper, not the driver you're interested in.

Below you'll find one or more lines starting with 'exec:' followed by an absolute
path to the driver binary and some command line option. This is what the driver
starts and you need to copy and paste that line and append the debug flags to that
line (less the 'exec:' prefix).

   0.000090 Starting UPS: apcsua750
   0.000096 1 remaining attempts
   0.000098 exec:  /lib64/nut/usbhid-ups -a apcsua750
Network UPS Tools - Generic HID driver 0.41 (2.7.4)
USB communication driver 0.33
Using subdriver: APC HID 0.96
using 'battery.charge' to set battery low state
using 'battery.runtime' to set battery low state
phoenix4 ~/tmp #

usbhid-ups driver log detailed:

phoenix4 ~# /lib64/nut/usbhid-ups -DDD -a apcsua750 &> usbhid-ups.log

-> see attachement: usbhid-ups.log

upsc:

phoenix4 ~/tmp # upsc apcsua750@localhost
battery.charge: 100
battery.charge.low: 10
battery.charge.warning: 50
battery.mfr.date: 2008/11/15
battery.runtime: 1740
battery.runtime.low: 120
battery.temperature: 19.3
battery.type: PbAc
battery.voltage: 27.7
battery.voltage.nominal: 24.0
device.mfr: American Power Conversion
device.model: Smart-UPS 750 RM
device.serial: AS0846133692
device.type: ups
driver.flag.ignorelb: enabled
driver.name: usbhid-ups
driver.parameter.bus: 001
driver.parameter.pollfreq: 2
driver.parameter.pollinterval: 2
driver.parameter.port: auto
driver.parameter.product: Smart-UPS 750 RM FW:668.18.I USB FW:7.3
driver.parameter.productid: 0002
driver.parameter.serial: AS0846133692
driver.parameter.synchronous: no
driver.parameter.vendor: American Power Conversion
driver.parameter.vendorid: 051D
driver.version: 2.7.4
driver.version.data: APC HID 0.96
driver.version.internal: 0.41
input.sensitivity: high
input.transfer.high: 253
input.transfer.low: 208
input.transfer.reason: input voltage out of range
input.voltage: 230.4
output.current: 0.29
output.frequency: 50.0
output.voltage: 228.9
output.voltage.nominal: 230.0
ups.beeper.status: enabled
ups.delay.shutdown: 20
ups.delay.start: 30
ups.firmware: 668.18.I
ups.firmware.aux: 7.3
ups.load: 16.9
ups.mfr: American Power Conversion
ups.mfr.date: 2008/11/15
ups.model: Smart-UPS 750 RM
ups.productid: 0002
ups.serial: AS0846133692
ups.status: OL
ups.test.result: No test initiated
ups.timer.reboot: -1
ups.timer.shutdown: -1
ups.timer.start: -1
ups.vendorid: 051d
phoenix4 ~/tmp #

ups.conf:

[apcsua750]
driver = "usbhid-ups"
port = "auto"
vendorid = "051D"
productid = "0002"
product = "Smart-UPS 750 RM FW:668.18.I USB FW:7.3"
serial = "AS0846133692"
vendor = "American Power Conversion"
bus = "001"
pollinterval = 2
ignorelb
override.driver.parameter.pollfreq = 2

system / driver:

nut version: nut-2.7.4
kernel: Linux 4.20.17-gentoo
ups: APC SUA750RMI2U (USB)
clepple commented 5 years ago

What part of ups.status do you expect to change? Did it eventually change in the log you provided? If not, please grab another log, and note the relative time at which, for instance, you cut AC power to the UPS, and wait until ups.status changes. (The log timestamps are in seconds since the driver started.)

I haven't followed the logic to verify this, but I suspect you want to replace override.driver.parameter.pollfreq = 2 with just pollfreq = 2. Otherwise, pollfreq will still default to 30, and the override will just change the value sent to upsd.

clepple commented 5 years ago

Also, I would remove ignorelb for now. Later you may want to add it back with an override for e.g. battery.charge.low.

I realize this may seem to contradict my previous comment about override. The difference is that driver.parameter.pollfreq is not an actual NUT variable, but a copy of the pollfreq value. Overriding the copy does not change the underlying value, but as mentioned, setting it in ups.conf as pollfreq = 2 should do what you want.

spacerunner5 commented 5 years ago

Tried your changes but no much better results. Somehow those timings seem random ;-)

another idea of debugging (pls note my inserted comments). I assume "ACPresent" means that the ups is online.

phoenix4 ~ # /lib64/nut/usbhid-ups -DDDD -a apcsua750 2>&1 | grep Status.ACPresent
   0.270872 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   0.270875 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   1.282213 Path: UPS.PresentStatus.ACPresent, Type: Input, ReportID: 0x33, Offset: 2, Size: 1, Value: 1
   1.282220 Path: UPS.PresentStatus.ACPresent, Type: Feature, ReportID: 0x33, Offset: 2, Size: 1, Value: 1
   1.284272 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   1.328038 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   1.392042 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   3.378901 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   5.870904 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   7.343982 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
   7.344043 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
*** COMMENT: PLUG PULLED NOW (10s) ***
   9.901930 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
  11.375995 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
  11.376107 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
  13.359991 Path: UPS.PresentStatus.ACPresent, Type: Input, ReportID: 0x33, Offset: 2, Size: 1, Value: 1
  13.892409 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  15.343976 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  15.344054 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  17.392034 Path: UPS.PresentStatus.ACPresent, Type: Input, ReportID: 0x33, Offset: 2, Size: 1, Value: 0
  17.902924 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
*** COMMENT: PLUG PULLED NOW (20s) ***
  19.376036 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  21.903336 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  23.408035 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  26.074019 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  27.376040 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  30.064320 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  31.408046 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  34.055191 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  35.376044 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 0
  37.424031 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
  38.020070 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
  39.490377 Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x07, Offset: 2, Size: 1, Value: 1
^C
phoenix4 ~ #

This is hard to debug, always pulling the power plugs ;-)

I will give it another shot tomorrow and report back.