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
2.09k stars 351 forks source link

Mac OS X Sonoma / Sequoia on Mac Mini M2 - NUT 2.8.2 upsdrvctl / usbhid-ups fail to fork the driver as a daemon process. #2642

Open pjkerly opened 1 month ago

pjkerly commented 1 month ago

Mac OS X Sonoma / Sequoia (I have not tried other OS versions) on Mac Mini M2 - NUT 2.8.2 - I can start both upsdrvctl / usbhid-ups as long as it runs in the foreground. As long as I use -D -F -FF with runs in foreground all works as expected. If I try to run in background mode default or with -B, the driver will find the UPS device and run correctly all the way up until it forks the process. Right now, I have workaround but it does not work as expected.

:; sudo ../sbin/upsdrvctl -FF start CP1500PFCLCD 

Network UPS Tools - UPS driver controller 2.8.2
Network UPS Tools - Generic HID driver 0.53 (2.8.2)
USB communication driver (libusb 1.0) 0.47
Using subdriver: CyberPower HID 0.80
Running as foreground process, but saving a PID file anyway
upsnotify: failed to notify about state 2: no notification tech defined, will not spam more about it
sock_connect: enabling asynchronous mode (auto)

Then I can stop it successfully using sudo ../sbin/upsdrvctl stop which means that it is generating the PID file success and can use it to stop the driver.

I can also start the usbhid-ups driver manually as well as long as it runs in the foreground. You can see that the driver does find the UPS device and processes correctly just to the point when it would fork the process.

:; sudo ../bin/usbhid-ups -D -B -u root -a CP1500PFCLCD                                                         
Password:
Network UPS Tools - Generic HID driver 0.53 (2.8.2)
USB communication driver (libusb 1.0) 0.47
   0.000000 [D1] upsdrv_makevartable...
   0.000185 [D1] Using USB implementation: libusb-1.0.27 (API: 0x100010a)
   0.000193 [D1] Built-in default or configured user for drivers '_nut' was ignored due to 'root' specified on command line
   0.000534 [D1] Network UPS Tools version 2.8.2 (release/snapshot of 2.8.2) built with Apple clang version 16.0.0 (clang-1600.0.26.3); Target: arm64-apple-darwin24.0.0; Thread model: posix and configured with flags: --prefix=/opt/local --with-serial=no --with-usb=auto --with-snmp=no --with-hal=auto --with-cgi=no --with-neonxml=no --with-ssl=yes --with-ipv6=no --with-statepath=/opt/local/var/db/ups --with-pidpath=/opt/local/var/run --with-hotplug-dir=/opt/local/etc/nut/hotplug --with-udev-dir=/opt/local/etc/nut/udev --with-user=_nut --with-group=_nut
   0.000539 [D1] debug level is '1'
   0.001381 [D1] Succeeded to become_user(root): now UID=0 GID=0
   0.001442 [D1] Saving PID 2939 into /opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD.pid
   0.001485 [D1] upsdrv_initups (non-SHUT)...
   0.029139 Using subdriver: CyberPower HID 0.80
   0.029144 [D1] 53 HID objects found
   0.032078 [D1] Path: UPS.PowerSummary.iProduct, Type: Feature, ReportID: 0x01, Offset: 0, Size: 8, Value: 1
   0.035025 [D1] Path: UPS.PowerSummary.iSerialNumber, Type: Feature, ReportID: 0x02, Offset: 0, Size: 8, Value: 2
   0.038078 [D1] Path: UPS.PowerSummary.ff0100d0, Type: Feature, ReportID: 0x1b, Offset: 0, Size: 8, Value: 5
   0.041063 [D1] Path: UPS.PowerSummary.iDeviceChemistry, Type: Feature, ReportID: 0x03, Offset: 0, Size: 8, Value: 4
   0.044084 [D1] Path: UPS.PowerSummary.iOEMInformation, Type: Feature, ReportID: 0x04, Offset: 0, Size: 8, Value: 3
   0.047075 [D1] Path: UPS.PowerSummary.Rechargeable, Type: Feature, ReportID: 0x05, Offset: 0, Size: 8, Value: 1
   0.050041 [D1] Path: UPS.PowerSummary.CapacityMode, Type: Feature, ReportID: 0x06, Offset: 0, Size: 8, Value: 2
   0.053027 [D1] Path: UPS.PowerSummary.DesignCapacity, Type: Feature, ReportID: 0x07, Offset: 0, Size: 8, Value: 100
   0.053037 [D1] Path: UPS.PowerSummary.CapacityGranularity1, Type: Feature, ReportID: 0x07, Offset: 8, Size: 8, Value: 5
   0.053045 [D1] Path: UPS.PowerSummary.CapacityGranularity2, Type: Feature, ReportID: 0x07, Offset: 16, Size: 8, Value: 10
   0.053053 [D1] Path: UPS.PowerSummary.WarningCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 24, Size: 8, Value: 20
   0.053060 [D1] Path: UPS.PowerSummary.RemainingCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 32, Size: 8, Value: 10
   0.053064 [D1] Path: UPS.PowerSummary.FullChargeCapacity, Type: Feature, ReportID: 0x07, Offset: 40, Size: 8, Value: 100
   0.056030 [D1] Path: UPS.PowerSummary.RemainingCapacity, Type: Input, ReportID: 0x08, Offset: 0, Size: 8, Value: 100
   0.056040 [D1] Path: UPS.PowerSummary.RemainingCapacity, Type: Feature, ReportID: 0x08, Offset: 0, Size: 8, Value: 100
   0.056049 [D1] Path: UPS.PowerSummary.RunTimeToEmpty, Type: Input, ReportID: 0x08, Offset: 8, Size: 16, Value: 8970
   0.056056 [D1] Path: UPS.PowerSummary.RunTimeToEmpty, Type: Feature, ReportID: 0x08, Offset: 8, Size: 16, Value: 8970
   0.056064 [D1] Path: UPS.PowerSummary.RemainingTimeLimit, Type: Input, ReportID: 0x08, Offset: 24, Size: 16, Value: 300
   0.056066 [D1] Path: UPS.PowerSummary.RemainingTimeLimit, Type: Feature, ReportID: 0x08, Offset: 24, Size: 16, Value: 300
   0.059028 [D1] Path: UPS.PowerSummary.ConfigVoltage, Type: Feature, ReportID: 0x09, Offset: 0, Size: 8, Value: 24
   0.062021 [D1] Path: UPS.PowerSummary.Voltage, Type: Feature, ReportID: 0x0a, Offset: 0, Size: 8, Value: 24
   0.065036 [D1] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1
   0.065047 [D1] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0
   0.065053 [D1] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0
   0.065059 [D1] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0
   0.065066 [D1] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1
   0.065068 [D1] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Input, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0
   0.065070 [D1] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1
   0.065072 [D1] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0
   0.065074 [D1] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0
   0.065076 [D1] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0
   0.065078 [D1] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Feature, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1
   0.065080 [D1] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Feature, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0
   0.068052 [D1] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2
   0.068059 [D1] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Input, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2
   0.070990 [D1] Path: UPS.PowerSummary.iManufacturer, Type: Feature, ReportID: 0x0d, Offset: 0, Size: 8, Value: 3
   0.074033 [D1] Path: UPS.Input.ConfigVoltage, Type: Feature, ReportID: 0x0e, Offset: 0, Size: 8, Value: 120
   0.077031 [D1] Path: UPS.Input.Voltage, Type: Feature, ReportID: 0x0f, Offset: 0, Size: 16, Value: 119
   0.080036 [D1] Path: UPS.Input.LowVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 0, Size: 16, Value: 88
   0.080042 [D1] Path: UPS.Input.LowVoltageTransfer, Type: Input, ReportID: 0x10, Offset: 0, Size: 16, Value: 88
   0.080046 [D1] Path: UPS.Input.HighVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 16, Size: 16, Value: 139
   0.080050 [D1] Path: UPS.Input.HighVoltageTransfer, Type: Input, ReportID: 0x10, Offset: 16, Size: 16, Value: 139
   0.083005 [D1] Path: UPS.Output.Voltage, Type: Feature, ReportID: 0x12, Offset: 0, Size: 16, Value: 119
   0.086030 [D1] Path: UPS.Output.PercentLoad, Type: Feature, ReportID: 0x13, Offset: 0, Size: 8, Value: 3
   0.089029 [D1] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6
   0.089033 [D1] Path: UPS.Output.Test, Type: Input, ReportID: 0x14, Offset: 0, Size: 8, Value: 6
   0.092024 [D1] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60
   0.095017 [D1] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60
   0.098029 [D1] Path: UPS.Output.Boost, Type: Feature, ReportID: 0x17, Offset: 0, Size: 1, Value: 0
   0.098034 [D1] Path: UPS.Output.Overload, Type: Feature, ReportID: 0x17, Offset: 1, Size: 1, Value: 0
   0.100998 [D1] Path: UPS.Output.ConfigActivePower, Type: Feature, ReportID: 0x18, Offset: 0, Size: 16, Value: 900
   0.104010 [D1] Path: UPS.Output.ff010043, Type: Feature, ReportID: 0x1a, Offset: 0, Size: 8, Value: 1
   0.104013 [D1] Path: UPS.Output.ff010043, Type: Input, ReportID: 0x1a, Offset: 0, Size: 8, Value: 1
   0.104021 [D1] Detected a UPS: CPS/CP1500PFCLCD
   0.113121 [D1] upsdrv_initinfo...
   0.113126 [D1] upsdrv_updateinfo...
   0.119052 [D1] Got 6 HID objects...
   0.119064 [D1] Quick update...
   0.119565 [D1] Group and/or user account for this driver was customized ('root:_nut') compared to built-in defaults. Fixing socket '/opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD' ownership/access.
   0.119574 [D1] WARNING: opening socket file for stat/chown failed (102), which is rather typical for Unix socket handling: Operation not supported on socket
   0.119604 [D1] Group access for this driver successfully fixed (using file name based methods)
jimklimov commented 1 month ago

Can you please try that later command with more verbosity e.g. -DDDDDD?

Trying to reproduce it on a VM from the CI farm, so with a dummy-ups driver in a setup made by make check-NIT-sandbox - and it forks well...

Abuild-iMac-Pro:nut abuild$ sudo -E /Users/abuild/nut/drivers/dummy-ups -a dummy -DDDDDD -B -u root
   0.000000     [D5:70761] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools 2.8.2.1081-1081-g78e0525d3 (development iteration after 2.8.2) - Device simulation and repeater driver 0.19
   0.000102     [D5:70761] do_upsconf_args: confupsname=(null), var=maxretry, val=3
   0.000108     [D5:70761] do_upsconf_args: call do_global_args()
   0.000115     [D3:70761] do_global_args: var='maxretry' val='3'
   0.000125     [D5:70761] do_upsconf_args: confupsname=(null), var=driverpath, val=/Users/abuild/nut/drivers
   0.000129     [D5:70761] do_upsconf_args: call do_global_args()
   0.000134     [D3:70761] do_global_args: var='driverpath' val='/Users/abuild/nut/drivers'
   0.000141     [D5:70761] do_upsconf_args: confupsname=dummy, var=driver, val=dummy-ups
   0.000146     [D5:70761] do_upsconf_args: call main_arg()
   0.000150     [D3:70761] main_arg: var='driver' val='dummy-ups'
   0.000154     [D5:70761] do_upsconf_args: not a main_arg()
   0.000158     [D5:70761] do_upsconf_args: this is a 'driver' setting, may we proceed?
   0.000164     [D6:70761] testval_reloadable: var=driver, oldval=dummy-ups, newval=dummy-ups, reloadable=0, reload_flag=0
   0.000172     [D6:70761] testval_reloadable: verdict for (re)loading var=driver value: -1
   0.000177     [D5:70761] do_upsconf_args: 'driver' setting already applied with this value
   0.000198     [D5:70761] do_upsconf_args: confupsname=dummy, var=desc, val=Crash Dummy
   0.000203     [D5:70761] do_upsconf_args: call main_arg()
   0.000207     [D3:70761] main_arg: var='desc' val='Crash Dummy'
   0.000218     [D5:70761] do_upsconf_args: confupsname=dummy, var=port, val=dummy.seq
   0.000223     [D5:70761] do_upsconf_args: call main_arg()
   0.000227     [D3:70761] main_arg: var='port' val='dummy.seq'
   0.000232     [D6:70761] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=dummy.seq, reloadable=0, reload_flag=0
   0.000237     [D6:70761] testinfo_reloadable: verdict for (re)loading var=port value: 1
   0.000247     [D5:70761] send_to_all: SETINFO driver.parameter.port "dummy.seq"
   0.000265     [D5:70761] do_upsconf_args: confupsname=UPS1, var=driver, val=dummy-ups
   0.000273     [D5:70761] do_upsconf_args: confupsname=UPS1, var=desc, val=Example event sequence
   0.000280     [D5:70761] do_upsconf_args: confupsname=UPS1, var=port, val=evolution500.seq
   0.000295     [D5:70761] do_upsconf_args: confupsname=UPS2, var=driver, val=dummy-ups
   0.000303     [D5:70761] do_upsconf_args: confupsname=UPS2, var=desc, val=Example ePDU data dump
   0.000314     [D5:70761] do_upsconf_args: confupsname=UPS2, var=port, val=epdu-managed.dev
   0.000321     [D5:70761] do_upsconf_args: confupsname=UPS2, var=mode, val=dummy-once
   0.000339     [D1:70761] Built-in default or configured user for drivers 'nobody' was ignored due to 'root' specified on command line
   0.000351     [D1] Network UPS Tools version 2.8.2.1081-1081-g78e0525d3 (development iteration after 2.8.2) built with Apple clang version 14.0.0 (clang-1400.0.29.202); Target: x86_64-apple-darwin21.6.0; Thread model: posix and configured with flags: --with-snmp-includes='-isystem /usr/local/opt/net-snmp/include -I/usr/local/opt/net-snmp/include -isystem /usr/local/include -I/usr/local/include' --with-snmp-libs='-L/usr/local/opt/net-snmp/lib -lnetsnmp' --with-libltdl-includes='-isystem /usr/local/include -I/usr/local/include' --with-libltdl-libs='-L/usr/local/lib -lltdl' PKG_CONFIG_PATH=/Users/abuild/nut/tmp/lib/pkgconfig:/usr/local/lib/pkgconfig:/usr/local/opt/net-snmp/lib/pkgconfig CFLAGS='-I/Users/abuild/nut/tmp/include  -Wno-poison-system-directories -Wno-deprecated-declarations -isystem /usr/local/include -I/usr/local/include' CPPFLAGS='-I/Users/abuild/nut/tmp/include ' CXXFLAGS='-I/Users/abuild/nut/tmp/include  -Wno-poison-system-directories -isystem /usr/local/include -I/usr/local/include' LDFLAGS='-L/Users/abuild/nut/tmp/lib  -L/usr/local/lib' --enable-keep_nut_report_feature --prefix=/Users/abuild/nut/tmp --sysconfdir=/Users/abuild/nut/tmp/etc/nut --with-udev-dir=/Users/abuild/nut/tmp/etc/udev --with-devd-dir=/Users/abuild/nut/tmp/etc/devd --with-hotplug-dir=/Users/abuild/nut/tmp/etc/hotplug --enable-check-NIT --with-nut_monitor=force --with-pynut=auto --with-nut-scanner=auto --with-nutconf=auto --with-doc=man CC=/usr/local/opt/ccache/libexec/clang CXX=/usr/local/opt/ccache/libexec/clang++ CPP='clang -E' --enable-Wcolor
   0.000394     [D1:70761] debug level is '6'
   0.000406     [D5:70761] send_to_all: SETINFO driver.debug "6"
   0.000416     [D5:70761] send_to_all: SETFLAGS driver.debug RW NUMBER
   0.001908     [D1:70761] Succeeded to become_user(root): now UID=0 GID=0
   0.001937     [D1:70761] Signalling UPS [dummy]: driver.exit (quietly, no fuss if no driver is running or responding)
   0.001948     Can't open /Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy: No such file or directory
   0.001951     [D1:70761] Request for other driver to exit returned code -1
   0.001956     [D1:70761] Socket dialog with the other driver instance (may be absent) failed: No such file or directory
   0.001974     [D1:70761] PID file /Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy.pid not found; stat() returned -1: No such file or directory
   0.002052     [D1:70761] Saving PID 70761 into /Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy.pid
   0.002187     [D5:70761] send_to_all: SETINFO device.type "ups"
   0.002197     [D5:70761] send_to_all: SETINFO driver.state "init.device"
   0.002205     [D2:70761] Dummy (simulation) mode with a sequence file name pattern (looping infinitely)
   0.002208     [D1:70761] Dummy (simulation) mode looping infinitely
   0.002211     [D5:70761] send_to_all: SETINFO driver.parameter.mode "dummy-loop"
   0.002226     [D2:70761] Located dummy.seq for device simulation data: /Users/abuild/nut/tests/NIT/tmp/etc/dummy.seq
   0.002232     [D5:70761] send_to_all: SETINFO driver.state "init.quiet"
   0.002241     [D5:70761] send_to_all: SETINFO driver.version "2.8.2.1081-1081-g78e0525d3"
   0.002246     [D5:70761] send_to_all: SETINFO driver.version.internal "0.19"
   0.002251     [D5:70761] send_to_all: SETINFO driver.name "dummy-ups"
   0.002256     [D5:70761] send_to_all: SETINFO driver.state "init.info"
   0.002264     [D5:70761] send_to_all: SETINFO ups.mfr "Dummy Manufacturer"
   0.002269     [D5:70761] send_to_all: SETFLAGS ups.mfr RW STRING
   0.002274     [D5:70761] send_to_all: SETAUX ups.mfr 32
   0.002280     [D5:70761] send_to_all: SETINFO ups.model "Dummy UPS"
   0.002284     [D5:70761] send_to_all: SETFLAGS ups.model RW STRING
   0.002287     [D5:70761] send_to_all: SETAUX ups.model 32
   0.002290     [D5:70761] send_to_all: SETINFO ups.status "OL"
   0.002293     [D5:70761] send_to_all: SETFLAGS ups.status RW STRING
   0.002296     [D5:70761] send_to_all: SETAUX ups.status 32
   0.002299     [D1:70761] entering parse_data_file()
   0.002328     [D3:70761] parse_data_file: variable "ups.status" with 2 args
   0.002332     [D5:70761] send_to_all: SETINFO ups.status "OB"
   0.002336     [D1:70761] suspending execution for 5 seconds...
   0.002339     [D5:70761] send_to_all: DATAOK
   0.002342     [D5:70761] send_to_all: ADDCMD load.off
   0.002345     [D5:70761] send_to_all: SETINFO driver.state "init.updateinfo"
   0.002348     [D1:70761] upsdrv_updateinfo...
   1.012404     [D1:70761] entering parse_data_file()
   1.012430     [D1:70761] leaving (paused)...
   1.012440     [D5:70761] send_to_all: SETINFO driver.state "init.quiet"
   1.012625     [D2:70761] dstate_init: sock /Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy open on fd 4
   1.014856     [D1:70761] Group and/or user account for this driver was customized ('root:nobody') compared to built-in defaults. Fixing socket '/Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy' ownership/access.
   1.014877     [D1:70761] WARNING: opening socket file for stat/chown failed, which is rather typical for Unix socket handling: Operation not supported on socket
   1.014927     [D1:70761] Group access for this driver successfully fixed (using file name based methods)
   1.014937     [D5:70761] send_to_all: SETINFO driver.parameter.pollinterval "2"
   1.014941     [D5:70761] send_to_all: SETINFO driver.parameter.synchronous "auto"
   1.014945     [D5:70761] send_to_all: SETINFO device.mfr "Dummy Manufacturer"
   1.014949     [D5:70761] send_to_all: SETINFO device.model "Dummy UPS"
   1.015590     Startup successful
   1.015729     [D1:70775] Saving PID 70775 into /Users/abuild/nut/tests/NIT/tmp/run/dummy-ups-dummy.pid
   1.015989     [D5:70775] send_to_all: SETINFO driver.flag.allow_killpower "0"
   1.016011     [D5:70775] send_to_all: SETFLAGS driver.flag.allow_killpower RW NUMBER
   1.016032     [D5:70775] send_to_all: ADDCMD driver.killpower
   1.016041     [D5:70775] send_to_all: ADDCMD driver.reload
   1.016049     [D5:70775] send_to_all: ADDCMD driver.reload-or-exit
   1.016057     [D5:70775] send_to_all: ADDCMD driver.reload-or-error
   1.016067     [D5:70775] send_to_all: SETINFO driver.state "quiet"
   1.016122     [D1:70775] Driver initialization completed, beginning regular infinite loop
   1.016181     [D1:70775] upsnotify: failed to notify about state 2: no notification tech defined, will not spam more about it
   1.016225     [D5:70775] send_to_all: SETINFO driver.state "updateinfo"
   1.016244     [D1:70775] upsdrv_updateinfo...
Abuild-iMac-Pro:nut abuild$    2.018299 [D1:70775] entering parse_data_file()
   2.018320     [D1:70775] leaving (paused)...
   2.018328     [D5:70775] send_to_all: SETINFO driver.state "quiet"
   3.018255     [D5:70775] send_to_all: SETINFO driver.state "updateinfo"
   3.018276     [D1:70775] upsdrv_updateinfo...

So the part where your log ends, in mine is followed by the Startup successful line and saving the other PID file after it forks to (IIRC) detach from console.

jimklimov commented 1 month ago

https://stackoverflow.com/questions/31045575/how-to-trace-system-calls-of-a-program-in-mac-os-x has some suggestions about tracing programs (ktrace, dtruss, lowering system protection to be able to trace). Maybe this would expose what the forking in your system blocks on.

The CI farm worker is on Monterey, I think, so maybe something in the platform has changed?..

pjkerly commented 1 month ago

Thanks Jim for looking at this. Here's the full log. Want me to try the dummy-ups on Sequoia? what ups.conf are you using?

sudo -E ../bin/usbhid-ups -a CP1500PFCLCD -DDDDDD -B -u root 0.000000 [D5] send_to_all: SETINFO driver.state "init.starting" Network UPS Tools - Generic HID driver 0.53 (2.8.2) USB communication driver (libusb 1.0) 0.47 0.000419 [D1] upsdrv_makevartable... 0.000637 [D5] send_to_all: SETINFO driver.version.usb "libusb-1.0.27 (API: 0x100010a)" 0.000641 [D1] Using USB implementation: libusb-1.0.27 (API: 0x100010a) 0.000966 [D5] do_upsconf_args: confupsname=(null), var=user, val=root 0.000970 [D5] do_upsconf_args: call do_global_args() 0.000972 [D3] do_global_args: var='user' val='root' 0.000974 [D6] testval_reloadable: var=user, oldval=_nut, newval=root, reloadable=0, reload_flag=0 0.000977 [D1] testval_reloadable: setting 'user' exists and differs: new value 'root' vs. '_nut' 0.000978 [D6] testval_reloadable: verdict for (re)loading var=user value: 1 0.000980 [D1] Overriding previously specified user '_nut' with 'root' specified in global section 0.000984 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=driver, val=usbhid-ups 0.000986 [D5] do_upsconf_args: call main_arg() 0.000988 [D3] main_arg: var='driver' val='usbhid-ups' 0.000990 [D5] do_upsconf_args: not a main_arg() 0.000991 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed? 0.000993 [D6] testval_reloadable: var=driver, oldval=usbhid-ups, newval=usbhid-ups, reloadable=0, reload_flag=0 0.000995 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1 0.000996 [D5] do_upsconf_args: 'driver' setting already applied with this value 0.000999 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=port, val=auto 0.001000 [D5] do_upsconf_args: call main_arg() 0.001001 [D3] main_arg: var='port' val='auto' 0.001003 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=auto, reloadable=0, reload_flag=0 0.001005 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1 0.001007 [D5] send_to_all: SETINFO driver.parameter.port "auto" 0.001011 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=desc, val=Cyber Power CP1500PFCLCD 0.001012 [D5] do_upsconf_args: call main_arg() 0.001014 [D3] main_arg: var='desc' val='Cyber Power CP1500PFCLCD' 0.001270 [D1] Built-in default or configured user for drivers 'root' was ignored due to 'root' specified on command line 0.001272 [D1] Network UPS Tools version 2.8.2 (release/snapshot of 2.8.2) built with Apple clang version 16.0.0 (clang-1600.0.26.3); Target: arm64-apple-darwin24.0.0; Thread model: posix and configured with flags: --prefix=/opt/local --with-serial=no --with-usb=auto --with-snmp=no --with-hal=auto --with-cgi=no --with-neonxml=no --with-ssl=yes --with-ipv6=no --with-statepath=/opt/local/var/db/ups --with-pidpath=/opt/local/var/run --with-hotplug-dir=/opt/local/etc/nut/hotplug --with-udev-dir=/opt/local/etc/nut/udev --with-user=_nut --with-group=_nut 0.001276 [D1] debug level is '6' 0.001278 [D5] send_to_all: SETINFO driver.debug "6" 0.001281 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER 0.002581 [D1] Succeeded to become_user(root): now UID=0 GID=0 0.002606 Duplicate driver instance detected (PID file /opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD.pid exists)! Terminating other driver! kill: No such process 0.002863 [D1] Saving PID 3443 into /opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD.pid 0.002928 [D5] send_to_all: SETINFO device.type "ups" 0.002931 [D5] send_to_all: SETINFO driver.state "init.device" 0.002933 [D1] upsdrv_initups (non-SHUT)... 0.002935 [D2] Initializing an USB-connected UPS with library libusb-1.0.27 (API: 0x100010a) (NUT subdriver name='USB communication driver (libusb 1.0)' ver='0.47') 0.012647 [D2] Checking device 1 of 1 (0764/0501) 0.020040 [D2] - VendorID: 0764 0.020045 [D2] - ProductID: 0501 0.020046 [D2] - Manufacturer: CPS 0.020047 [D2] - Product: CP1500PFCLCD 0.020049 [D2] - Serial Number: 000000000000 0.020050 [D2] - Bus: 002 0.020052 [D2] - Bus Port: 004 0.020053 [D2] - Device: 001 0.020054 [D2] - Device release number: 0001 0.020055 [D2] Trying to match device 0.020058 [D2] match_function_subdriver (non-SHUT mode): matching a device... 0.020272 [D3] match_function_regex: matching a device... 0.020276 [D2] Device matches 0.020278 [D2] Reading configuration descriptor 1 of 1 0.020324 [D3] libusb_kernel_driver_active() returned 0: Success 0.020570 [D2] Claimed interface 0 successfully 0.020574 [D3] nut_usb_set_altinterface: skipped libusb_set_interface_alt_setting(udev, 0, 0) 0.023024 [D2] Retrieved HID descriptor (expected 9, got 9) 0.023039 [D3] HID descriptor, method 1: (9 bytes) => 09 21 10 01 21 01 22 b7 01 0.023041 [D3] HID descriptor length (method 1) 439 0.023043 [D4] i=0, extra[i]=09, extra[i+1]=21 0.023045 [D3] HID descriptor, method 2: (9 bytes) => 09 21 10 01 21 01 22 b7 01 0.023046 [D3] HID descriptor length (method 2) 439 0.023047 [D2] HID descriptor length 439 0.032017 [D2] Report Descriptor size = 439 0.032027 [D3] Report Descriptor: (439 bytes) => 05 84 09 04 a1 01 09 24 a1 00 85 01 09 fe 0.032036 [D3] 75 08 95 01 15 00 26 ff 00 b1 23 85 02 09 ff b1 23 85 1b 06 01 ff 09 d0 b1 0.032043 [D3] 22 85 03 05 85 09 89 b1 23 85 04 09 8f b1 23 85 05 09 8b b1 23 85 06 09 2c 0.032046 [D3] b1 23 85 07 75 08 95 06 25 64 09 83 09 8d 09 8e 09 8c 09 29 09 67 b1 23 85 0.032049 [D3] 08 75 08 95 01 65 00 09 66 81 23 09 66 b1 a3 09 68 75 10 27 ff ff 00 00 66 0.032052 [D3] 01 10 81 23 09 68 b1 a3 09 2a 26 58 02 81 23 09 2a b1 a2 85 09 75 08 26 ff 0.032055 [D3] 00 05 84 09 40 67 21 d1 f0 00 55 06 b1 23 85 0a 09 30 b1 a3 09 02 a1 02 65 0.032058 [D3] 00 55 00 85 0b 75 01 95 06 25 01 05 85 09 d0 09 44 09 45 09 42 09 46 09 43 0.032061 [D3] 81 23 09 d0 09 44 09 45 09 42 09 46 09 43 b1 a3 75 02 95 01 81 01 b1 01 c0 0.032064 [D3] 85 0c 05 84 09 5a 75 08 15 01 25 03 b1 a2 09 5a 81 22 85 0d 09 fd 15 00 26 0.032068 [D3] ff 00 b1 23 c0 05 84 09 1a a1 00 85 0e 05 84 09 40 75 08 67 21 d1 f0 00 55 0.032071 [D3] 07 b1 23 85 0f 75 10 09 30 b1 a3 85 10 09 53 15 4e 25 58 b1 a2 09 53 81 23 0.032074 [D3] 09 54 16 88 00 26 8e 00 b1 a2 09 54 81 23 c0 09 1c a1 00 85 12 09 30 b1 a3 0.032077 [D3] 75 08 15 00 26 ff 00 65 00 55 00 85 13 09 35 b1 a3 85 14 09 58 25 06 b1 a2 0.032079 [D3] 09 58 81 22 85 15 09 57 75 10 15 ff 26 ff 7f 35 c4 47 c4 ff 1d 00 66 01 10 0.032083 [D3] b1 a2 85 16 09 56 b1 a2 85 17 09 6e 75 01 15 00 25 01 35 00 45 00 65 00 b1 0.032085 [D3] a3 09 65 b1 a3 75 06 b1 01 85 18 75 10 09 44 26 84 03 66 21 d1 55 07 b1 a3 0.032089 [D3] 85 1a 06 01 ff 65 00 55 00 75 08 15 00 25 02 09 43 b1 a2 09 43 81 23 c0 c0 0.032118 Using subdriver: CyberPower HID 0.80 0.032122 [D3] Attempting Report Descriptor fix for UPS: Vendor: 0764, Product: 0501 0.032124 [D4] Report Descriptor: hvt input LogMin: 136 LogMax: 142 0.032126 [D4] Report Descriptor: output LogMin: 136 LogMax: 142 0.032127 [D3] Fixing Report Descriptor. Set Output Voltage LogMin = 0, LogMax = 511 0.032129 [D4] Report Descriptor: input LogMin: 0 LogMax: 255 0.032131 [D3] Fixing Report Descriptor. Set Input Voltage LogMin = 0, LogMax = 511 0.032132 [D2] Report Descriptor Fixed 0.032134 [D1] 53 HID objects found 0.032136 [D4] Entering libusb_get_report 0.035003 [D3] Report[get]: (2 bytes) => 01 01 0.035008 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.035010 [D5] Unit = 00000000, UnitExp = 0 0.035012 [D5] Exponent = 0 0.035014 [D5] hid_lookup_path: 00840004 -> UPS 0.035017 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.035018 [D5] hid_lookup_path: 008400fe -> iProduct 0.035021 [D1] Path: UPS.PowerSummary.iProduct, Type: Feature, ReportID: 0x01, Offset: 0, Size: 8, Value: 1 0.035023 [D4] Entering libusb_get_report 0.038013 [D3] Report[get]: (2 bytes) => 02 02 0.038021 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.038024 [D5] Unit = 00000000, UnitExp = 0 0.038026 [D5] Exponent = 0 0.038028 [D5] hid_lookup_path: 00840004 -> UPS 0.038030 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.038031 [D5] hid_lookup_path: 008400ff -> iSerialNumber 0.038034 [D1] Path: UPS.PowerSummary.iSerialNumber, Type: Feature, ReportID: 0x02, Offset: 0, Size: 8, Value: 2 0.038036 [D4] Entering libusb_get_report 0.041010 [D3] Report[get]: (2 bytes) => 1b 05 0.041015 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.041018 [D5] Unit = 00000000, UnitExp = 0 0.041020 [D5] Exponent = 0 0.041023 [D5] hid_lookup_path: 00840004 -> UPS 0.041026 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.041030 [D5] hid_lookup_path: ff0100d0 -> not found in lookup table 0.041035 [D1] Path: UPS.PowerSummary.ff0100d0, Type: Feature, ReportID: 0x1b, Offset: 0, Size: 8, Value: 5 0.041037 [D4] Entering libusb_get_report 0.044004 [D3] Report[get]: (2 bytes) => 03 04 0.044008 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.044010 [D5] Unit = 00000000, UnitExp = 0 0.044012 [D5] Exponent = 0 0.044014 [D5] hid_lookup_path: 00840004 -> UPS 0.044016 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.044019 [D5] hid_lookup_path: 00850089 -> iDeviceChemistry 0.044022 [D1] Path: UPS.PowerSummary.iDeviceChemistry, Type: Feature, ReportID: 0x03, Offset: 0, Size: 8, Value: 4 0.044024 [D4] Entering libusb_get_report 0.046999 [D3] Report[get]: (2 bytes) => 04 03 0.047003 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.047005 [D5] Unit = 00000000, UnitExp = 0 0.047007 [D5] Exponent = 0 0.047009 [D5] hid_lookup_path: 00840004 -> UPS 0.047011 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.047014 [D5] hid_lookup_path: 0085008f -> iOEMInformation 0.047017 [D1] Path: UPS.PowerSummary.iOEMInformation, Type: Feature, ReportID: 0x04, Offset: 0, Size: 8, Value: 3 0.047019 [D4] Entering libusb_get_report 0.049995 [D3] Report[get]: (2 bytes) => 05 01 0.049999 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.050001 [D5] Unit = 00000000, UnitExp = 0 0.050002 [D5] Exponent = 0 0.050004 [D5] hid_lookup_path: 00840004 -> UPS 0.050006 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.050008 [D5] hid_lookup_path: 0085008b -> Rechargeable 0.050010 [D1] Path: UPS.PowerSummary.Rechargeable, Type: Feature, ReportID: 0x05, Offset: 0, Size: 8, Value: 1 0.050012 [D4] Entering libusb_get_report 0.053006 [D3] Report[get]: (2 bytes) => 06 02 0.053011 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.053013 [D5] Unit = 00000000, UnitExp = 0 0.053015 [D5] Exponent = 0 0.053017 [D5] hid_lookup_path: 00840004 -> UPS 0.053019 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.053022 [D5] hid_lookup_path: 0085002c -> CapacityMode 0.053025 [D1] Path: UPS.PowerSummary.CapacityMode, Type: Feature, ReportID: 0x06, Offset: 0, Size: 8, Value: 2 0.053027 [D4] Entering libusb_get_report 0.056046 [D3] Report[get]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056055 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056057 [D5] Unit = 00000000, UnitExp = 0 0.056059 [D5] Exponent = 0 0.056061 [D5] hid_lookup_path: 00840004 -> UPS 0.056063 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056065 [D5] hid_lookup_path: 00850083 -> DesignCapacity 0.056068 [D1] Path: UPS.PowerSummary.DesignCapacity, Type: Feature, ReportID: 0x07, Offset: 0, Size: 8, Value: 100 0.056071 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056072 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056074 [D5] Unit = 00000000, UnitExp = 0 0.056076 [D5] Exponent = 0 0.056077 [D5] hid_lookup_path: 00840004 -> UPS 0.056079 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056081 [D5] hid_lookup_path: 0085008d -> CapacityGranularity1 0.056083 [D1] Path: UPS.PowerSummary.CapacityGranularity1, Type: Feature, ReportID: 0x07, Offset: 8, Size: 8, Value: 5 0.056085 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056087 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056088 [D5] Unit = 00000000, UnitExp = 0 0.056090 [D5] Exponent = 0 0.056091 [D5] hid_lookup_path: 00840004 -> UPS 0.056093 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056095 [D5] hid_lookup_path: 0085008e -> CapacityGranularity2 0.056097 [D1] Path: UPS.PowerSummary.CapacityGranularity2, Type: Feature, ReportID: 0x07, Offset: 16, Size: 8, Value: 10 0.056099 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056101 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056102 [D5] Unit = 00000000, UnitExp = 0 0.056104 [D5] Exponent = 0 0.056105 [D5] hid_lookup_path: 00840004 -> UPS 0.056107 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056109 [D5] hid_lookup_path: 0085008c -> WarningCapacityLimit 0.056110 [D1] Path: UPS.PowerSummary.WarningCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 24, Size: 8, Value: 20 0.056112 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056114 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056116 [D5] Unit = 00000000, UnitExp = 0 0.056117 [D5] Exponent = 0 0.056118 [D5] hid_lookup_path: 00840004 -> UPS 0.056120 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056122 [D5] hid_lookup_path: 00850029 -> RemainingCapacityLimit 0.056124 [D1] Path: UPS.PowerSummary.RemainingCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 32, Size: 8, Value: 10 0.056126 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.056127 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.056129 [D5] Unit = 00000000, UnitExp = 0 0.056130 [D5] Exponent = 0 0.056132 [D5] hid_lookup_path: 00840004 -> UPS 0.056133 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.056135 [D5] hid_lookup_path: 00850067 -> FullChargeCapacity 0.056137 [D1] Path: UPS.PowerSummary.FullChargeCapacity, Type: Feature, ReportID: 0x07, Offset: 40, Size: 8, Value: 100 0.056139 [D4] Entering libusb_get_report 0.059038 [D3] Report[get]: (6 bytes) => 08 64 dc 23 2c 01 0.059047 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.059051 [D5] Unit = 00000000, UnitExp = 0 0.059055 [D5] Exponent = 0 0.059056 [D5] hid_lookup_path: 00840004 -> UPS 0.059058 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059060 [D5] hid_lookup_path: 00850066 -> RemainingCapacity 0.059062 [D1] Path: UPS.PowerSummary.RemainingCapacity, Type: Input, ReportID: 0x08, Offset: 0, Size: 8, Value: 100 0.059064 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.059066 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.059068 [D5] Unit = 00000000, UnitExp = 0 0.059069 [D5] Exponent = 0 0.059071 [D5] hid_lookup_path: 00840004 -> UPS 0.059072 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059074 [D5] hid_lookup_path: 00850066 -> RemainingCapacity 0.059076 [D1] Path: UPS.PowerSummary.RemainingCapacity, Type: Feature, ReportID: 0x08, Offset: 0, Size: 8, Value: 100 0.059078 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.059079 [D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0 0.059081 [D5] Unit = 00001001, UnitExp = 0 0.059083 [D5] Exponent = 0 0.059084 [D5] hid_lookup_path: 00840004 -> UPS 0.059086 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059088 [D5] hid_lookup_path: 00850068 -> RunTimeToEmpty 0.059090 [D1] Path: UPS.PowerSummary.RunTimeToEmpty, Type: Input, ReportID: 0x08, Offset: 8, Size: 16, Value: 9180 0.059092 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.059093 [D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0 0.059095 [D5] Unit = 00001001, UnitExp = 0 0.059096 [D5] Exponent = 0 0.059098 [D5] hid_lookup_path: 00840004 -> UPS 0.059099 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059101 [D5] hid_lookup_path: 00850068 -> RunTimeToEmpty 0.059103 [D1] Path: UPS.PowerSummary.RunTimeToEmpty, Type: Feature, ReportID: 0x08, Offset: 8, Size: 16, Value: 9180 0.059105 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.059107 [D5] PhyMax = 0, PhyMin = 0, LogMax = 600, LogMin = 0 0.059108 [D5] Unit = 00001001, UnitExp = 0 0.059109 [D5] Exponent = 0 0.059111 [D5] hid_lookup_path: 00840004 -> UPS 0.059112 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059114 [D5] hid_lookup_path: 0085002a -> RemainingTimeLimit 0.059116 [D1] Path: UPS.PowerSummary.RemainingTimeLimit, Type: Input, ReportID: 0x08, Offset: 24, Size: 16, Value: 300 0.059119 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.059120 [D5] PhyMax = 0, PhyMin = 0, LogMax = 600, LogMin = 0 0.059122 [D5] Unit = 00001001, UnitExp = 0 0.059123 [D5] Exponent = 0 0.059125 [D5] hid_lookup_path: 00840004 -> UPS 0.059126 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.059128 [D5] hid_lookup_path: 0085002a -> RemainingTimeLimit 0.059130 [D1] Path: UPS.PowerSummary.RemainingTimeLimit, Type: Feature, ReportID: 0x08, Offset: 24, Size: 16, Value: 300 0.059131 [D4] Entering libusb_get_report 0.062030 [D3] Report[get]: (2 bytes) => 09 f0 0.062039 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.062044 [D5] Unit = 00f0d121, UnitExp = 6 0.062049 [D5] Exponent = -1 0.062051 [D5] hid_lookup_path: 00840004 -> UPS 0.062053 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.062054 [D5] hid_lookup_path: 00840040 -> ConfigVoltage 0.062056 [D1] Path: UPS.PowerSummary.ConfigVoltage, Type: Feature, ReportID: 0x09, Offset: 0, Size: 8, Value: 24 0.062058 [D4] Entering libusb_get_report 0.065030 [D3] Report[get]: (2 bytes) => 0a f0 0.065039 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.065044 [D5] Unit = 00f0d121, UnitExp = 6 0.065049 [D5] Exponent = -1 0.065051 [D5] hid_lookup_path: 00840004 -> UPS 0.065052 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.065054 [D5] hid_lookup_path: 00840030 -> Voltage 0.065056 [D1] Path: UPS.PowerSummary.Voltage, Type: Feature, ReportID: 0x0a, Offset: 0, Size: 8, Value: 24 0.065059 [D4] Entering libusb_get_report 0.068038 [D3] Report[get]: (2 bytes) => 0b 11 0.068047 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068052 [D5] Unit = 00000000, UnitExp = 0 0.068056 [D5] Exponent = 0 0.068058 [D5] hid_lookup_path: 00840004 -> UPS 0.068060 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068062 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068064 [D5] hid_lookup_path: 008500d0 -> ACPresent 0.068066 [D1] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1 0.068068 [D3] Report[buf]: (2 bytes) => 0b 11 0.068070 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068072 [D5] Unit = 00000000, UnitExp = 0 0.068073 [D5] Exponent = 0 0.068075 [D5] hid_lookup_path: 00840004 -> UPS 0.068077 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068079 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068081 [D5] hid_lookup_path: 00850044 -> Charging 0.068083 [D1] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0 0.068085 [D3] Report[buf]: (2 bytes) => 0b 11 0.068087 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068089 [D5] Unit = 00000000, UnitExp = 0 0.068090 [D5] Exponent = 0 0.068092 [D5] hid_lookup_path: 00840004 -> UPS 0.068094 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068096 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068098 [D5] hid_lookup_path: 00850045 -> Discharging 0.068100 [D1] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0 0.068102 [D3] Report[buf]: (2 bytes) => 0b 11 0.068104 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068106 [D5] Unit = 00000000, UnitExp = 0 0.068107 [D5] Exponent = 0 0.068109 [D5] hid_lookup_path: 00840004 -> UPS 0.068111 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068113 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068115 [D5] hid_lookup_path: 00850042 -> BelowRemainingCapacityLimit 0.068117 [D1] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0 0.068119 [D3] Report[buf]: (2 bytes) => 0b 11 0.068121 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068123 [D5] Unit = 00000000, UnitExp = 0 0.068124 [D5] Exponent = 0 0.068126 [D5] hid_lookup_path: 00840004 -> UPS 0.068128 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068129 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068132 [D5] hid_lookup_path: 00850046 -> FullyCharged 0.068134 [D1] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1 0.068136 [D3] Report[buf]: (2 bytes) => 0b 11 0.068138 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068140 [D5] Unit = 00000000, UnitExp = 0 0.068141 [D5] Exponent = 0 0.068143 [D5] hid_lookup_path: 00840004 -> UPS 0.068144 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068146 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068148 [D5] hid_lookup_path: 00850043 -> RemainingTimeLimitExpired 0.068151 [D1] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Input, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0 0.068153 [D3] Report[buf]: (2 bytes) => 0b 11 0.068155 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068157 [D5] Unit = 00000000, UnitExp = 0 0.068159 [D5] Exponent = 0 0.068160 [D5] hid_lookup_path: 00840004 -> UPS 0.068162 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068164 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068166 [D5] hid_lookup_path: 008500d0 -> ACPresent 0.068168 [D1] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1 0.068170 [D3] Report[buf]: (2 bytes) => 0b 11 0.068172 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068173 [D5] Unit = 00000000, UnitExp = 0 0.068175 [D5] Exponent = 0 0.068177 [D5] hid_lookup_path: 00840004 -> UPS 0.068179 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068181 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068183 [D5] hid_lookup_path: 00850044 -> Charging 0.068185 [D1] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0 0.068187 [D3] Report[buf]: (2 bytes) => 0b 11 0.068189 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068191 [D5] Unit = 00000000, UnitExp = 0 0.068193 [D5] Exponent = 0 0.068194 [D5] hid_lookup_path: 00840004 -> UPS 0.068196 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068198 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068200 [D5] hid_lookup_path: 00850045 -> Discharging 0.068202 [D1] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0 0.068205 [D3] Report[buf]: (2 bytes) => 0b 11 0.068207 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068208 [D5] Unit = 00000000, UnitExp = 0 0.068210 [D5] Exponent = 0 0.068212 [D5] hid_lookup_path: 00840004 -> UPS 0.068213 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068215 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068217 [D5] hid_lookup_path: 00850042 -> BelowRemainingCapacityLimit 0.068219 [D1] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0 0.068222 [D3] Report[buf]: (2 bytes) => 0b 11 0.068224 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068225 [D5] Unit = 00000000, UnitExp = 0 0.068227 [D5] Exponent = 0 0.068229 [D5] hid_lookup_path: 00840004 -> UPS 0.068231 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068233 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068235 [D5] hid_lookup_path: 00850046 -> FullyCharged 0.068237 [D1] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Feature, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1 0.068239 [D3] Report[buf]: (2 bytes) => 0b 11 0.068241 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.068242 [D5] Unit = 00000000, UnitExp = 0 0.068244 [D5] Exponent = 0 0.068245 [D5] hid_lookup_path: 00840004 -> UPS 0.068247 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.068249 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.068251 [D5] hid_lookup_path: 00850043 -> RemainingTimeLimitExpired 0.068253 [D1] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Feature, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0 0.068255 [D4] Entering libusb_get_report 0.070999 [D3] Report[get]: (2 bytes) => 0c 02 0.071005 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.071007 [D5] Unit = 00000000, UnitExp = 0 0.071009 [D5] Exponent = 0 0.071012 [D5] hid_lookup_path: 00840004 -> UPS 0.071014 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.071017 [D5] hid_lookup_path: 0084005a -> AudibleAlarmControl 0.071020 [D1] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.071023 [D3] Report[buf]: (2 bytes) => 0c 02 0.071025 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.071027 [D5] Unit = 00000000, UnitExp = 0 0.071028 [D5] Exponent = 0 0.071030 [D5] hid_lookup_path: 00840004 -> UPS 0.071032 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.071034 [D5] hid_lookup_path: 0084005a -> AudibleAlarmControl 0.071036 [D1] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Input, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.071038 [D4] Entering libusb_get_report 0.074019 [D3] Report[get]: (2 bytes) => 0d 03 0.074027 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.074031 [D5] Unit = 00000000, UnitExp = 0 0.074033 [D5] Exponent = 0 0.074036 [D5] hid_lookup_path: 00840004 -> UPS 0.074038 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.074040 [D5] hid_lookup_path: 008400fd -> iManufacturer 0.074042 [D1] Path: UPS.PowerSummary.iManufacturer, Type: Feature, ReportID: 0x0d, Offset: 0, Size: 8, Value: 3 0.074044 [D4] Entering libusb_get_report 0.076992 [D3] Report[get]: (2 bytes) => 0e 78 0.076996 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.076998 [D5] Unit = 00f0d121, UnitExp = 7 0.077000 [D5] Exponent = 0 0.077002 [D5] hid_lookup_path: 00840004 -> UPS 0.077004 [D5] hid_lookup_path: 0084001a -> Input 0.077006 [D5] hid_lookup_path: 00840040 -> ConfigVoltage 0.077008 [D1] Path: UPS.Input.ConfigVoltage, Type: Feature, ReportID: 0x0e, Offset: 0, Size: 8, Value: 120 0.077010 [D4] Entering libusb_get_report 0.079980 [D3] Report[get]: (3 bytes) => 0f 79 00 0.079984 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.079986 [D5] Unit = 00f0d121, UnitExp = 7 0.079988 [D5] Exponent = 0 0.079989 [D5] hid_lookup_path: 00840004 -> UPS 0.079991 [D5] hid_lookup_path: 0084001a -> Input 0.079994 [D5] hid_lookup_path: 00840030 -> Voltage 0.079996 [D1] Path: UPS.Input.Voltage, Type: Feature, ReportID: 0x0f, Offset: 0, Size: 16, Value: 121 0.079998 [D4] Entering libusb_get_report 0.082986 [D3] Report[get]: (5 bytes) => 10 58 00 8b 00 0.082990 [D5] PhyMax = 0, PhyMin = 0, LogMax = 88, LogMin = 78 0.082992 [D5] Unit = 00f0d121, UnitExp = 7 0.082994 [D5] Exponent = 0 0.082995 [D5] hid_lookup_path: 00840004 -> UPS 0.082997 [D5] hid_lookup_path: 0084001a -> Input 0.083000 [D5] hid_lookup_path: 00840053 -> LowVoltageTransfer 0.083003 [D1] Path: UPS.Input.LowVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 0, Size: 16, Value: 88 0.083005 [D3] Report[buf]: (5 bytes) => 10 58 00 8b 00 0.083007 [D5] PhyMax = 0, PhyMin = 0, LogMax = 88, LogMin = 78 0.083009 [D5] Unit = 00f0d121, UnitExp = 7 0.083011 [D5] Exponent = 0 0.083012 [D5] hid_lookup_path: 00840004 -> UPS 0.083014 [D5] hid_lookup_path: 0084001a -> Input 0.083016 [D5] hid_lookup_path: 00840053 -> LowVoltageTransfer 0.083018 [D1] Path: UPS.Input.LowVoltageTransfer, Type: Input, ReportID: 0x10, Offset: 0, Size: 16, Value: 88 0.083021 [D3] Report[buf]: (5 bytes) => 10 58 00 8b 00 0.083023 [D5] PhyMax = 0, PhyMin = 0, LogMax = 142, LogMin = 136 0.083025 [D5] Unit = 00f0d121, UnitExp = 7 0.083026 [D5] Exponent = 0 0.083028 [D5] hid_lookup_path: 00840004 -> UPS 0.083030 [D5] hid_lookup_path: 0084001a -> Input 0.083032 [D5] hid_lookup_path: 00840054 -> HighVoltageTransfer 0.083034 [D1] Path: UPS.Input.HighVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 16, Size: 16, Value: 139 0.083037 [D3] Report[buf]: (5 bytes) => 10 58 00 8b 00 0.083039 [D5] PhyMax = 0, PhyMin = 0, LogMax = 142, LogMin = 136 0.083041 [D5] Unit = 00f0d121, UnitExp = 7 0.083042 [D5] Exponent = 0 0.083044 [D5] hid_lookup_path: 00840004 -> UPS 0.083046 [D5] hid_lookup_path: 0084001a -> Input 0.083048 [D5] hid_lookup_path: 00840054 -> HighVoltageTransfer 0.083050 [D1] Path: UPS.Input.HighVoltageTransfer, Type: Input, ReportID: 0x10, Offset: 16, Size: 16, Value: 139 0.083052 [D4] Entering libusb_get_report 0.085990 [D3] Report[get]: (3 bytes) => 12 79 00 0.085993 [D5] PhyMax = 0, PhyMin = 0, LogMax = 511, LogMin = 0 0.085995 [D5] Unit = 00f0d121, UnitExp = 7 0.085996 [D5] Exponent = 0 0.085998 [D5] hid_lookup_path: 00840004 -> UPS 0.085999 [D5] hid_lookup_path: 0084001c -> Output 0.086001 [D5] hid_lookup_path: 00840030 -> Voltage 0.086003 [D1] Path: UPS.Output.Voltage, Type: Feature, ReportID: 0x12, Offset: 0, Size: 16, Value: 121 0.086005 [D4] Entering libusb_get_report 0.089011 [D3] Report[get]: (2 bytes) => 13 03 0.089015 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.089017 [D5] Unit = 00000000, UnitExp = 0 0.089019 [D5] Exponent = 0 0.089020 [D5] hid_lookup_path: 00840004 -> UPS 0.089022 [D5] hid_lookup_path: 0084001c -> Output 0.089024 [D5] hid_lookup_path: 00840035 -> PercentLoad 0.089027 [D1] Path: UPS.Output.PercentLoad, Type: Feature, ReportID: 0x13, Offset: 0, Size: 8, Value: 3 0.089028 [D4] Entering libusb_get_report 0.091976 [D3] Report[get]: (2 bytes) => 14 06 0.091982 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.091983 [D5] Unit = 00000000, UnitExp = 0 0.091985 [D5] Exponent = 0 0.091987 [D5] hid_lookup_path: 00840004 -> UPS 0.091989 [D5] hid_lookup_path: 0084001c -> Output 0.091991 [D5] hid_lookup_path: 00840058 -> Test 0.091993 [D1] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.091995 [D3] Report[buf]: (2 bytes) => 14 06 0.091996 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.091998 [D5] Unit = 00000000, UnitExp = 0 0.092000 [D5] Exponent = 0 0.092001 [D5] hid_lookup_path: 00840004 -> UPS 0.092003 [D5] hid_lookup_path: 0084001c -> Output 0.092004 [D5] hid_lookup_path: 00840058 -> Test 0.092006 [D1] Path: UPS.Output.Test, Type: Input, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.092008 [D4] Entering libusb_get_report 0.095003 [D3] Report[get]: (3 bytes) => 15 ff ff 0.095006 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.095008 [D5] Unit = 00001001, UnitExp = 0 0.095009 [D5] Exponent = 0 0.095011 [D5] hid_lookup_path: 00840004 -> UPS 0.095012 [D5] hid_lookup_path: 0084001c -> Output 0.095014 [D5] hid_lookup_path: 00840057 -> DelayBeforeShutdown 0.095016 [D1] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60 0.095018 [D4] Entering libusb_get_report 0.098003 [D3] Report[get]: (3 bytes) => 16 ff ff 0.098005 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.098007 [D5] Unit = 00001001, UnitExp = 0 0.098008 [D5] Exponent = 0 0.098009 [D5] hid_lookup_path: 00840004 -> UPS 0.098011 [D5] hid_lookup_path: 0084001c -> Output 0.098012 [D5] hid_lookup_path: 00840056 -> DelayBeforeStartup 0.098014 [D1] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60 0.098016 [D4] Entering libusb_get_report 0.100996 [D3] Report[get]: (2 bytes) => 17 00 0.100999 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.101000 [D5] Unit = 00000000, UnitExp = 0 0.101001 [D5] Exponent = 0 0.101003 [D5] hid_lookup_path: 00840004 -> UPS 0.101004 [D5] hid_lookup_path: 0084001c -> Output 0.101005 [D5] hid_lookup_path: 0084006e -> Boost 0.101007 [D1] Path: UPS.Output.Boost, Type: Feature, ReportID: 0x17, Offset: 0, Size: 1, Value: 0 0.101009 [D3] Report[buf]: (2 bytes) => 17 00 0.101010 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.101011 [D5] Unit = 00000000, UnitExp = 0 0.101012 [D5] Exponent = 0 0.101014 [D5] hid_lookup_path: 00840004 -> UPS 0.101015 [D5] hid_lookup_path: 0084001c -> Output 0.101016 [D5] hid_lookup_path: 00840065 -> Overload 0.101018 [D1] Path: UPS.Output.Overload, Type: Feature, ReportID: 0x17, Offset: 1, Size: 1, Value: 0 0.101019 [D4] Entering libusb_get_report 0.103994 [D3] Report[get]: (3 bytes) => 18 84 03 0.103996 [D5] PhyMax = 0, PhyMin = 0, LogMax = 900, LogMin = 0 0.103998 [D5] Unit = 0000d121, UnitExp = 7 0.103999 [D5] Exponent = 0 0.104000 [D5] hid_lookup_path: 00840004 -> UPS 0.104001 [D5] hid_lookup_path: 0084001c -> Output 0.104003 [D5] hid_lookup_path: 00840044 -> ConfigActivePower 0.104005 [D1] Path: UPS.Output.ConfigActivePower, Type: Feature, ReportID: 0x18, Offset: 0, Size: 16, Value: 900 0.104006 [D4] Entering libusb_get_report 0.106991 [D3] Report[get]: (2 bytes) => 1a 01 0.106994 [D5] PhyMax = 0, PhyMin = 0, LogMax = 2, LogMin = 0 0.106995 [D5] Unit = 00000000, UnitExp = 0 0.106996 [D5] Exponent = 0 0.106997 [D5] hid_lookup_path: 00840004 -> UPS 0.106998 [D5] hid_lookup_path: 0084001c -> Output 0.107000 [D5] hid_lookup_path: ff010043 -> not found in lookup table 0.107001 [D1] Path: UPS.Output.ff010043, Type: Feature, ReportID: 0x1a, Offset: 0, Size: 8, Value: 1 0.107003 [D3] Report[buf]: (2 bytes) => 1a 01 0.107004 [D5] PhyMax = 0, PhyMin = 0, LogMax = 2, LogMin = 0 0.107005 [D5] Unit = 00000000, UnitExp = 0 0.107006 [D5] Exponent = 0 0.107007 [D5] hid_lookup_path: 00840004 -> UPS 0.107008 [D5] hid_lookup_path: 0084001c -> Output 0.107010 [D5] hid_lookup_path: ff010043 -> not found in lookup table 0.107011 [D1] Path: UPS.Output.ff010043, Type: Input, ReportID: 0x1a, Offset: 0, Size: 8, Value: 1 0.107015 [D5] send_to_all: SETINFO ups.mfr "CPS" 0.107017 [D5] send_to_all: SETINFO ups.model "CP1500PFCLCD" 0.107019 [D5] send_to_all: SETINFO ups.serial "000000000000" 0.107020 [D5] send_to_all: SETINFO ups.vendorid "0764" 0.107022 [D5] send_to_all: SETINFO ups.productid "0501" 0.107024 [D2] Report descriptor retrieved (Reportlen = 439) 0.107025 [D2] Found HID device 0.107026 [D3] Using default, detected or customized USB HID numbers: usb_config_index=0 usb_hid_rep_index=0 usb_hid_desc_index=0 usb_hid_ep_in=1 usb_hid_ep_out=1 0.107029 [D1] Detected a UPS: CPS/CP1500PFCLCD 0.107032 [D5] hid_lookup_usage: UPS -> 00840004 0.107034 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.107036 [D5] hid_lookup_usage: iDeviceChemistry -> 00850089 0.107037 [D4] string_to_path: depth = 3 0.107044 [D3] Report[buf]: (2 bytes) => 03 04 0.107045 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.107047 [D5] Unit = 00000000, UnitExp = 0 0.107048 [D5] Exponent = 0 0.107049 [D2] Path: UPS.PowerSummary.iDeviceChemistry, Type: Feature, ReportID: 0x03, Offset: 0, Size: 8, Value: 4 0.113041 [D5] send_to_all: SETINFO battery.type "PbAcid" 0.113052 [D5] hid_lookup_usage: UPS -> 00840004 0.113054 [D5] hid_lookup_usage: Battery -> 00840012 0.113058 [D5] hid_lookup_usage: ManufacturerDate -> 00850085 0.113060 [D4] string_to_path: depth = 3 0.113064 [D5] hid_lookup_usage: UPS -> 00840004 0.113067 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.113071 [D5] hid_lookup_usage: iOEMInformation -> 0085008f 0.113073 [D4] string_to_path: depth = 3 0.113076 [D3] Report[buf]: (2 bytes) => 04 03 0.113078 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.113080 [D5] Unit = 00000000, UnitExp = 0 0.113082 [D5] Exponent = 0 0.113084 [D2] Path: UPS.PowerSummary.iOEMInformation, Type: Feature, ReportID: 0x04, Offset: 0, Size: 8, Value: 3 0.116059 [D5] send_to_all: SETINFO battery.mfr.date "CPS" 0.116063 [D5] hid_lookup_usage: UPS -> 00840004 0.116066 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116069 [D5] hid_lookup_usage: WarningCapacityLimit -> 0085008c 0.116071 [D4] string_to_path: depth = 3 0.116075 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.116078 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.116080 [D5] Unit = 00000000, UnitExp = 0 0.116081 [D5] Exponent = 0 0.116084 [D2] Path: UPS.PowerSummary.WarningCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 24, Size: 8, Value: 20 0.116088 [D5] send_to_all: SETINFO battery.charge.warning "20" 0.116090 [D5] hid_lookup_usage: UPS -> 00840004 0.116092 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116096 [D5] hid_lookup_usage: RemainingCapacityLimit -> 00850029 0.116098 [D4] string_to_path: depth = 3 0.116101 [D3] Report[buf]: (7 bytes) => 07 64 05 0a 14 0a 64 0.116103 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.116105 [D5] Unit = 00000000, UnitExp = 0 0.116107 [D5] Exponent = 0 0.116110 [D2] Path: UPS.PowerSummary.RemainingCapacityLimit, Type: Feature, ReportID: 0x07, Offset: 32, Size: 8, Value: 10 0.116113 [D5] send_to_all: SETINFO battery.charge.low "10" 0.116116 [D5] send_to_all: SETFLAGS battery.charge.low RW STRING 0.116119 [D5] send_to_all: SETAUX battery.charge.low 10 0.116121 [D5] hid_lookup_usage: UPS -> 00840004 0.116123 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116127 [D5] hid_lookup_usage: RemainingCapacity -> 00850066 0.116129 [D4] string_to_path: depth = 3 0.116132 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.116134 [D5] PhyMax = 0, PhyMin = 0, LogMax = 100, LogMin = 0 0.116136 [D5] Unit = 00000000, UnitExp = 0 0.116138 [D5] Exponent = 0 0.116141 [D2] Path: UPS.PowerSummary.RemainingCapacity, Type: Feature, ReportID: 0x08, Offset: 0, Size: 8, Value: 100 0.116144 [D5] send_to_all: SETINFO battery.charge "100" 0.116147 [D5] hid_lookup_usage: UPS -> 00840004 0.116149 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116152 [D5] hid_lookup_usage: RunTimeToEmpty -> 00850068 0.116154 [D4] string_to_path: depth = 3 0.116157 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.116160 [D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0 0.116162 [D5] Unit = 00001001, UnitExp = 0 0.116164 [D5] Exponent = 0 0.116167 [D2] Path: UPS.PowerSummary.RunTimeToEmpty, Type: Feature, ReportID: 0x08, Offset: 8, Size: 16, Value: 9180 0.116170 [D5] send_to_all: SETINFO battery.runtime "9180" 0.116173 [D5] hid_lookup_usage: UPS -> 00840004 0.116175 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116178 [D5] hid_lookup_usage: RemainingTimeLimit -> 0085002a 0.116180 [D4] string_to_path: depth = 3 0.116183 [D3] Report[buf]: (6 bytes) => 08 64 dc 23 2c 01 0.116185 [D5] PhyMax = 0, PhyMin = 0, LogMax = 600, LogMin = 0 0.116187 [D5] Unit = 00001001, UnitExp = 0 0.116189 [D5] Exponent = 0 0.116192 [D2] Path: UPS.PowerSummary.RemainingTimeLimit, Type: Feature, ReportID: 0x08, Offset: 24, Size: 16, Value: 300 0.116195 [D5] send_to_all: SETINFO battery.runtime.low "300" 0.116198 [D5] send_to_all: SETFLAGS battery.runtime.low RW STRING 0.116201 [D5] send_to_all: SETAUX battery.runtime.low 10 0.116203 [D5] hid_lookup_usage: UPS -> 00840004 0.116205 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116208 [D5] hid_lookup_usage: ConfigVoltage -> 00840040 0.116210 [D4] string_to_path: depth = 3 0.116213 [D3] Report[buf]: (2 bytes) => 09 f0 0.116215 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.116217 [D5] Unit = 00f0d121, UnitExp = 6 0.116219 [D5] Exponent = -1 0.116221 [D2] Path: UPS.PowerSummary.ConfigVoltage, Type: Feature, ReportID: 0x09, Offset: 0, Size: 8, Value: 24 0.116224 [D5] send_to_all: SETINFO battery.voltage.nominal "24" 0.116227 [D5] hid_lookup_usage: UPS -> 00840004 0.116229 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116231 [D5] hid_lookup_usage: Voltage -> 00840030 0.116233 [D4] string_to_path: depth = 3 0.116236 [D3] Report[buf]: (2 bytes) => 0a f0 0.116238 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.116240 [D5] Unit = 00f0d121, UnitExp = 6 0.116242 [D5] Exponent = -1 0.116244 [D2] Path: UPS.PowerSummary.Voltage, Type: Feature, ReportID: 0x0a, Offset: 0, Size: 8, Value: 24 0.116248 [D5] cps_battvolt_fun: battery_scale = 1.000 0.116251 [D5] send_to_all: SETINFO battery.voltage "24.0" 0.116254 [D5] hid_lookup_usage: UPS -> 00840004 0.116256 [D5] hid_lookup_usage: Output -> 0084001c 0.116259 [D5] hid_lookup_usage: PercentLoad -> 00840035 0.116260 [D4] string_to_path: depth = 3 0.116264 [D3] Report[buf]: (2 bytes) => 13 03 0.116266 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.116268 [D5] Unit = 00000000, UnitExp = 0 0.116269 [D5] Exponent = 0 0.116272 [D2] Path: UPS.Output.PercentLoad, Type: Feature, ReportID: 0x13, Offset: 0, Size: 8, Value: 3 0.116275 [D5] send_to_all: SETINFO ups.load "3" 0.116277 [D5] hid_lookup_usage: UPS -> 00840004 0.116279 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116282 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.116284 [D4] string_to_path: depth = 3 0.116287 [D3] Report[buf]: (2 bytes) => 0c 02 0.116289 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.116291 [D5] Unit = 00000000, UnitExp = 0 0.116293 [D5] Exponent = 0 0.116295 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.116298 [D5] hu_find_infoval: found enabled (value: 2) 0.116301 [D5] send_to_all: SETINFO ups.beeper.status "enabled" 0.116303 [D5] hid_lookup_usage: UPS -> 00840004 0.116305 [D5] hid_lookup_usage: Output -> 0084001c 0.116308 [D5] hid_lookup_usage: Test -> 00840058 0.116310 [D4] string_to_path: depth = 3 0.116313 [D3] Report[buf]: (2 bytes) => 14 06 0.116315 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.116317 [D5] Unit = 00000000, UnitExp = 0 0.116319 [D5] Exponent = 0 0.116321 [D2] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.116324 [D5] hu_find_infoval: found No test initiated (value: 6) 0.116327 [D5] send_to_all: SETINFO ups.test.result "No test initiated" 0.116329 [D5] hid_lookup_usage: UPS -> 00840004 0.116331 [D5] hid_lookup_usage: Output -> 0084001c 0.116334 [D5] hid_lookup_usage: ConfigActivePower -> 00840044 0.116336 [D4] string_to_path: depth = 3 0.116340 [D3] Report[buf]: (3 bytes) => 18 84 03 0.116342 [D5] PhyMax = 0, PhyMin = 0, LogMax = 900, LogMin = 0 0.116344 [D5] Unit = 0000d121, UnitExp = 7 0.116345 [D5] Exponent = 0 0.116348 [D2] Path: UPS.Output.ConfigActivePower, Type: Feature, ReportID: 0x18, Offset: 0, Size: 16, Value: 900 0.116351 [D5] send_to_all: SETINFO ups.realpower.nominal "900" 0.116354 [D5] hid_lookup_usage: UPS -> 00840004 0.116356 [D5] hid_lookup_usage: Output -> 0084001c 0.116359 [D5] hid_lookup_usage: DelayBeforeStartup -> 00840056 0.116361 [D4] string_to_path: depth = 3 0.116364 [D5] send_to_all: SETINFO ups.delay.start "30" 0.116366 [D5] send_to_all: SETFLAGS ups.delay.start RW STRING 0.116369 [D5] send_to_all: SETAUX ups.delay.start 10 0.116371 [D5] hid_lookup_usage: UPS -> 00840004 0.116373 [D5] hid_lookup_usage: Output -> 0084001c 0.116376 [D5] hid_lookup_usage: DelayBeforeShutdown -> 00840057 0.116378 [D4] string_to_path: depth = 3 0.116381 [D5] send_to_all: SETINFO ups.delay.shutdown "20" 0.116384 [D5] send_to_all: SETFLAGS ups.delay.shutdown RW STRING 0.116386 [D5] send_to_all: SETAUX ups.delay.shutdown 10 0.116388 [D5] hid_lookup_usage: UPS -> 00840004 0.116391 [D5] hid_lookup_usage: Output -> 0084001c 0.116393 [D5] hid_lookup_usage: DelayBeforeStartup -> 00840056 0.116395 [D4] string_to_path: depth = 3 0.116398 [D3] Report[buf]: (3 bytes) => 16 ff ff 0.116400 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.116402 [D5] Unit = 00001001, UnitExp = 0 0.116404 [D5] Exponent = 0 0.116407 [D2] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60 0.116410 [D5] send_to_all: SETINFO ups.timer.start "-60" 0.116412 [D5] hid_lookup_usage: UPS -> 00840004 0.116414 [D5] hid_lookup_usage: Output -> 0084001c 0.116417 [D5] hid_lookup_usage: DelayBeforeShutdown -> 00840057 0.116419 [D4] string_to_path: depth = 3 0.116422 [D3] Report[buf]: (3 bytes) => 15 ff ff 0.116424 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.116426 [D5] Unit = 00001001, UnitExp = 0 0.116428 [D5] Exponent = 0 0.116430 [D2] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60 0.116433 [D5] send_to_all: SETINFO ups.timer.shutdown "-60" 0.116436 [D5] hid_lookup_usage: UPS -> 00840004 0.116438 [D5] hid_lookup_usage: Output -> 0084001c 0.116440 [D5] hid_lookup_usage: DelayBeforeReboot -> 00840055 0.116442 [D4] string_to_path: depth = 3 0.116445 [D5] hid_lookup_usage: UPS -> 00840004 0.116447 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116449 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116452 [D5] hid_lookup_usage: ACPresent -> 008500d0 0.116454 [D4] string_to_path: depth = 4 0.116457 [D3] Report[buf]: (2 bytes) => 0b 11 0.116459 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116461 [D5] Unit = 00000000, UnitExp = 0 0.116463 [D5] Exponent = 0 0.116465 [D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1 0.116468 [D5] hu_find_infoval: found online (value: 1) 0.116470 [D5] process_boolean_info: online 0.116472 [D5] hid_lookup_usage: UPS -> 00840004 0.116474 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116477 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116480 [D5] hid_lookup_usage: Charging -> 00850044 0.116482 [D4] string_to_path: depth = 4 0.116485 [D3] Report[buf]: (2 bytes) => 0b 11 0.116487 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116489 [D5] Unit = 00000000, UnitExp = 0 0.116491 [D5] Exponent = 0 0.116493 [D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0 0.116495 [D5] hu_find_infoval: found !chrg (value: 0) 0.116497 [D5] process_boolean_info: !chrg 0.116500 [D5] hid_lookup_usage: UPS -> 00840004 0.116502 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116504 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116508 [D5] hid_lookup_usage: Discharging -> 00850045 0.116509 [D4] string_to_path: depth = 4 0.116512 [D3] Report[buf]: (2 bytes) => 0b 11 0.116514 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116516 [D5] Unit = 00000000, UnitExp = 0 0.116518 [D5] Exponent = 0 0.116520 [D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0 0.116522 [D5] hu_find_infoval: found !dischrg (value: 0) 0.116524 [D5] process_boolean_info: !dischrg 0.116527 [D5] hid_lookup_usage: UPS -> 00840004 0.116529 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116531 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116534 [D5] hid_lookup_usage: BelowRemainingCapacityLimit -> 00850042 0.116537 [D4] string_to_path: depth = 4 0.116539 [D3] Report[buf]: (2 bytes) => 0b 11 0.116541 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116543 [D5] Unit = 00000000, UnitExp = 0 0.116545 [D5] Exponent = 0 0.116547 [D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0 0.116550 [D5] hu_find_infoval: found !lowbatt (value: 0) 0.116552 [D5] process_boolean_info: !lowbatt 0.116554 [D5] hid_lookup_usage: UPS -> 00840004 0.116556 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116558 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116561 [D5] hid_lookup_usage: FullyCharged -> 00850046 0.116563 [D4] string_to_path: depth = 4 0.116565 [D3] Report[buf]: (2 bytes) => 0b 11 0.116567 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116569 [D5] Unit = 00000000, UnitExp = 0 0.116571 [D5] Exponent = 0 0.116573 [D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Feature, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1 0.116576 [D5] hu_find_infoval: found fullycharged (value: 1) 0.116578 [D5] process_boolean_info: fullycharged 0.116580 [D5] hid_lookup_usage: UPS -> 00840004 0.116583 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.116585 [D5] hid_lookup_usage: PresentStatus -> 00840002 0.116588 [D5] hid_lookup_usage: RemainingTimeLimitExpired -> 00850043 0.116590 [D4] string_to_path: depth = 4 0.116593 [D3] Report[buf]: (2 bytes) => 0b 11 0.116595 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116596 [D5] Unit = 00000000, UnitExp = 0 0.116598 [D5] Exponent = 0 0.116601 [D2] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Feature, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0 0.116603 [D5] hu_find_infoval: found !timelimitexp (value: 0) 0.116605 [D5] process_boolean_info: !timelimitexp 0.116607 [D5] hid_lookup_usage: UPS -> 00840004 0.116609 [D5] hid_lookup_usage: Output -> 0084001c 0.116612 [D5] hid_lookup_usage: Boost -> 0084006e 0.116614 [D4] string_to_path: depth = 3 0.116617 [D3] Report[buf]: (2 bytes) => 17 00 0.116619 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116621 [D5] Unit = 00000000, UnitExp = 0 0.116623 [D5] Exponent = 0 0.116625 [D2] Path: UPS.Output.Boost, Type: Feature, ReportID: 0x17, Offset: 0, Size: 1, Value: 0 0.116627 [D5] hu_find_infoval: found !boost (value: 0) 0.116629 [D5] process_boolean_info: !boost 0.116631 [D5] hid_lookup_usage: UPS -> 00840004 0.116634 [D5] hid_lookup_usage: Output -> 0084001c 0.116636 [D5] hid_lookup_usage: Overload -> 00840065 0.116638 [D4] string_to_path: depth = 3 0.116641 [D3] Report[buf]: (2 bytes) => 17 00 0.116643 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.116645 [D5] Unit = 00000000, UnitExp = 0 0.116647 [D5] Exponent = 0 0.116649 [D2] Path: UPS.Output.Overload, Type: Feature, ReportID: 0x17, Offset: 1, Size: 1, Value: 0 0.116651 [D5] hu_find_infoval: found !overload (value: 0) 0.116653 [D5] process_boolean_info: !overload 0.116656 [D5] hid_lookup_usage: UPS -> 00840004 0.116658 [D5] hid_lookup_usage: Input -> 0084001a 0.116660 [D5] hid_lookup_usage: Frequency -> 00840032 0.116662 [D4] string_to_path: depth = 3 0.116665 [D5] hid_lookup_usage: UPS -> 00840004 0.116667 [D5] hid_lookup_usage: Input -> 0084001a 0.116669 [D5] hid_lookup_usage: ConfigVoltage -> 00840040 0.116671 [D4] string_to_path: depth = 3 0.116674 [D3] Report[buf]: (2 bytes) => 0e 78 0.116676 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.116678 [D5] Unit = 00f0d121, UnitExp = 7 0.116680 [D5] Exponent = 0 0.116682 [D2] Path: UPS.Input.ConfigVoltage, Type: Feature, ReportID: 0x0e, Offset: 0, Size: 8, Value: 120 0.116685 [D5] send_to_all: SETINFO input.voltage.nominal "120" 0.116688 [D5] hid_lookup_usage: UPS -> 00840004 0.116690 [D5] hid_lookup_usage: Input -> 0084001a 0.116692 [D5] hid_lookup_usage: Voltage -> 00840030 0.116694 [D4] string_to_path: depth = 3 0.116697 [D3] Report[buf]: (3 bytes) => 0f 79 00 0.116699 [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0 0.116701 [D5] Unit = 00f0d121, UnitExp = 7 0.116703 [D5] Exponent = 0 0.116705 [D2] Path: UPS.Input.Voltage, Type: Feature, ReportID: 0x0f, Offset: 0, Size: 16, Value: 121 0.116709 [D5] send_to_all: SETINFO input.voltage "121.0" 0.116711 [D5] hid_lookup_usage: UPS -> 00840004 0.116713 [D5] hid_lookup_usage: Input -> 0084001a 0.116716 [D5] hid_lookup_usage: LowVoltageTransfer -> 00840053 0.116718 [D4] string_to_path: depth = 3 0.116721 [D3] Report[buf]: (5 bytes) => 10 58 00 8b 00 0.116723 [D5] PhyMax = 0, PhyMin = 0, LogMax = 88, LogMin = 78 0.116725 [D5] Unit = 00f0d121, UnitExp = 7 0.116727 [D5] Exponent = 0 0.116729 [D2] Path: UPS.Input.LowVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 0, Size: 16, Value: 88 0.116732 [D5] send_to_all: SETINFO input.transfer.low "88" 0.116736 [D5] send_to_all: SETFLAGS input.transfer.low RW STRING 0.116738 [D5] send_to_all: SETAUX input.transfer.low 10 0.116740 [D5] hid_lookup_usage: UPS -> 00840004 0.116742 [D5] hid_lookup_usage: Input -> 0084001a 0.116745 [D5] hid_lookup_usage: HighVoltageTransfer -> 00840054 0.116747 [D4] string_to_path: depth = 3 0.116750 [D3] Report[buf]: (5 bytes) => 10 58 00 8b 00 0.116752 [D5] PhyMax = 0, PhyMin = 0, LogMax = 142, LogMin = 136 0.116754 [D5] Unit = 00f0d121, UnitExp = 7 0.116756 [D5] Exponent = 0 0.116758 [D2] Path: UPS.Input.HighVoltageTransfer, Type: Feature, ReportID: 0x10, Offset: 16, Size: 16, Value: 139 0.116761 [D5] send_to_all: SETINFO input.transfer.high "139" 0.116764 [D5] send_to_all: SETFLAGS input.transfer.high RW STRING 0.116766 [D5] send_to_all: SETAUX input.transfer.high 10 0.116769 [D5] hid_lookup_usage: UPS -> 00840004 0.116771 [D5] hid_lookup_usage: Output -> 0084001c 0.116773 [D5] hid_lookup_usage: Frequency -> 00840032 0.116775 [D4] string_to_path: depth = 3 0.116777 [D5] hid_lookup_usage: UPS -> 00840004 0.116779 [D5] hid_lookup_usage: Output -> 0084001c 0.116781 [D5] hid_lookup_usage: Voltage -> 00840030 0.116783 [D4] string_to_path: depth = 3 0.117812 [D3] Report[buf]: (3 bytes) => 12 79 00 0.117816 [D5] PhyMax = 0, PhyMin = 0, LogMax = 511, LogMin = 0 0.117818 [D5] Unit = 00f0d121, UnitExp = 7 0.117821 [D5] Exponent = 0 0.117825 [D2] Path: UPS.Output.Voltage, Type: Feature, ReportID: 0x12, Offset: 0, Size: 16, Value: 121 0.117829 [D5] send_to_all: SETINFO output.voltage "121.0" 0.117833 [D5] hid_lookup_usage: UPS -> 00840004 0.117835 [D5] hid_lookup_usage: Output -> 0084001c 0.117838 [D5] hid_lookup_usage: ConfigVoltage -> 00840040 0.117840 [D4] string_to_path: depth = 3 0.117843 [D5] hid_lookup_usage: UPS -> 00840004 0.117846 [D5] hid_lookup_usage: Output -> 0084001c 0.117848 [D5] hid_lookup_usage: Test -> 00840058 0.117850 [D4] string_to_path: depth = 3 0.117853 [D3] Report[buf]: (2 bytes) => 14 06 0.117855 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.117858 [D5] Unit = 00000000, UnitExp = 0 0.117859 [D5] Exponent = 0 0.117862 [D2] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.117865 [D3] Adding command 'test.battery.start.quick' using Path 'UPS.Output.Test' 0.117867 [D5] send_to_all: ADDCMD test.battery.start.quick 0.117869 [D5] hid_lookup_usage: UPS -> 00840004 0.117872 [D5] hid_lookup_usage: Output -> 0084001c 0.117874 [D5] hid_lookup_usage: Test -> 00840058 0.117876 [D4] string_to_path: depth = 3 0.117879 [D3] Report[buf]: (2 bytes) => 14 06 0.117966 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.117969 [D5] Unit = 00000000, UnitExp = 0 0.117971 [D5] Exponent = 0 0.117974 [D2] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.117976 [D3] Adding command 'test.battery.start.deep' using Path 'UPS.Output.Test' 0.117979 [D5] send_to_all: ADDCMD test.battery.start.deep 0.117982 [D5] hid_lookup_usage: UPS -> 00840004 0.117984 [D5] hid_lookup_usage: Output -> 0084001c 0.117986 [D5] hid_lookup_usage: Test -> 00840058 0.117988 [D4] string_to_path: depth = 3 0.117991 [D3] Report[buf]: (2 bytes) => 14 06 0.117993 [D5] PhyMax = 0, PhyMin = 0, LogMax = 6, LogMin = 0 0.117995 [D5] Unit = 00000000, UnitExp = 0 0.117997 [D5] Exponent = 0 0.118000 [D2] Path: UPS.Output.Test, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 6 0.118002 [D3] Adding command 'test.battery.stop' using Path 'UPS.Output.Test' 0.118004 [D5] send_to_all: ADDCMD test.battery.stop 0.118006 [D5] hid_lookup_usage: UPS -> 00840004 0.118009 [D5] hid_lookup_usage: Output -> 0084001c 0.118012 [D5] hid_lookup_usage: DelayBeforeShutdown -> 00840057 0.118014 [D4] string_to_path: depth = 3 0.118017 [D3] Report[buf]: (3 bytes) => 15 ff ff 0.118019 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.118022 [D5] Unit = 00001001, UnitExp = 0 0.118023 [D5] Exponent = 0 0.118026 [D2] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60 0.118028 [D3] Adding command 'load.off.delay' using Path 'UPS.Output.DelayBeforeShutdown' 0.118031 [D5] send_to_all: ADDCMD load.off.delay 0.118033 [D5] hid_lookup_usage: UPS -> 00840004 0.118035 [D5] hid_lookup_usage: Output -> 0084001c 0.118038 [D5] hid_lookup_usage: DelayBeforeStartup -> 00840056 0.118040 [D4] string_to_path: depth = 3 0.118043 [D3] Report[buf]: (3 bytes) => 16 ff ff 0.118046 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.118048 [D5] Unit = 00001001, UnitExp = 0 0.118049 [D5] Exponent = 0 0.118052 [D2] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60 0.118054 [D3] Adding command 'load.on.delay' using Path 'UPS.Output.DelayBeforeStartup' 0.118057 [D5] send_to_all: ADDCMD load.on.delay 0.118059 [D5] hid_lookup_usage: UPS -> 00840004 0.118061 [D5] hid_lookup_usage: Output -> 0084001c 0.118064 [D5] hid_lookup_usage: DelayBeforeShutdown -> 00840057 0.118066 [D4] string_to_path: depth = 3 0.118069 [D3] Report[buf]: (3 bytes) => 15 ff ff 0.118071 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.118073 [D5] Unit = 00001001, UnitExp = 0 0.118075 [D5] Exponent = 0 0.118077 [D2] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60 0.118079 [D3] Adding command 'shutdown.stop' using Path 'UPS.Output.DelayBeforeShutdown' 0.118082 [D5] send_to_all: ADDCMD shutdown.stop 0.118084 [D5] hid_lookup_usage: UPS -> 00840004 0.118086 [D5] hid_lookup_usage: Output -> 0084001c 0.118089 [D5] hid_lookup_usage: DelayBeforeReboot -> 00840055 0.118091 [D4] string_to_path: depth = 3 0.118093 [D5] hid_lookup_usage: UPS -> 00840004 0.118096 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.118099 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.118101 [D4] string_to_path: depth = 3 0.118104 [D3] Report[buf]: (2 bytes) => 0c 02 0.118106 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.118108 [D5] Unit = 00000000, UnitExp = 0 0.118110 [D5] Exponent = 0 0.118112 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.118115 [D3] Adding command 'beeper.on' using Path 'UPS.PowerSummary.AudibleAlarmControl' 0.118117 [D5] send_to_all: ADDCMD beeper.on 0.118119 [D5] hid_lookup_usage: UPS -> 00840004 0.118122 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.118124 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.118126 [D4] string_to_path: depth = 3 0.118129 [D3] Report[buf]: (2 bytes) => 0c 02 0.118131 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.118133 [D5] Unit = 00000000, UnitExp = 0 0.118135 [D5] Exponent = 0 0.118137 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.118140 [D3] Adding command 'beeper.off' using Path 'UPS.PowerSummary.AudibleAlarmControl' 0.118142 [D5] send_to_all: ADDCMD beeper.off 0.118144 [D5] hid_lookup_usage: UPS -> 00840004 0.118146 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.118149 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.118151 [D4] string_to_path: depth = 3 0.118153 [D3] Report[buf]: (2 bytes) => 0c 02 0.118156 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.118158 [D5] Unit = 00000000, UnitExp = 0 0.118160 [D5] Exponent = 0 0.118162 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.118164 [D3] Adding command 'beeper.enable' using Path 'UPS.PowerSummary.AudibleAlarmControl' 0.118166 [D5] send_to_all: ADDCMD beeper.enable 0.118168 [D5] hid_lookup_usage: UPS -> 00840004 0.118171 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.118173 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.118175 [D4] string_to_path: depth = 3 0.118178 [D3] Report[buf]: (2 bytes) => 0c 02 0.118180 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.118182 [D5] Unit = 00000000, UnitExp = 0 0.118184 [D5] Exponent = 0 0.118186 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.118188 [D3] Adding command 'beeper.disable' using Path 'UPS.PowerSummary.AudibleAlarmControl' 0.118191 [D5] send_to_all: ADDCMD beeper.disable 0.118193 [D5] hid_lookup_usage: UPS -> 00840004 0.118195 [D5] hid_lookup_usage: PowerSummary -> 00840024 0.118198 [D5] hid_lookup_usage: AudibleAlarmControl -> 0084005a 0.118200 [D4] string_to_path: depth = 3 0.118202 [D3] Report[buf]: (2 bytes) => 0c 02 0.118204 [D5] PhyMax = 0, PhyMin = 0, LogMax = 3, LogMin = 1 0.118206 [D5] Unit = 00000000, UnitExp = 0 0.118208 [D5] Exponent = 0 0.118210 [D2] Path: UPS.PowerSummary.AudibleAlarmControl, Type: Feature, ReportID: 0x0c, Offset: 0, Size: 8, Value: 2 0.118213 [D3] Adding command 'beeper.mute' using Path 'UPS.PowerSummary.AudibleAlarmControl' 0.118215 [D5] send_to_all: ADDCMD beeper.mute 0.118219 [D5] send_to_all: ADDCMD load.off 0.118223 [D5] send_to_all: ADDCMD load.on 0.118226 [D5] send_to_all: ADDCMD shutdown.return 0.118228 [D5] send_to_all: ADDCMD shutdown.stayoff 0.118232 [D5] send_to_all: SETINFO driver.state "init.quiet" 0.118242 [D5] send_to_all: SETINFO driver.version "2.8.2" 0.118245 [D5] send_to_all: SETINFO driver.version.internal "0.53" 0.118248 [D5] send_to_all: SETINFO driver.name "usbhid-ups" 0.118251 [D5] send_to_all: SETINFO driver.state "init.info" 0.118253 [D1] upsdrv_initinfo... 0.118256 [D5] send_to_all: SETINFO driver.version.data "CyberPower HID 0.80" 0.118259 [D5] send_to_all: SETINFO driver.parameter.pollfreq "30" 0.118262 [D5] send_to_all: SETINFO driver.state "init.updateinfo" 0.118265 [D1] upsdrv_updateinfo... 0.125067 [D2] file_report_buffer: expected 2 bytes, but got 512 instead 0.125078 [D3] Report[err]: (512 bytes) => 0b 11 09 04 62 00 41 00 63 00 69 00 64 00 75 08 0.125084 [D3] 95 01 15 00 26 ff 00 b1 23 85 02 09 ff b1 23 85 1b 06 01 ff 09 d0 b1 22 85 0.125089 [D3] 03 05 85 09 89 b1 23 85 04 09 8f b1 23 85 05 09 8b b1 23 85 06 09 2c b1 23 0.125093 [D3] 85 07 75 08 95 06 25 64 09 83 09 8d 09 8e 09 8c 09 29 09 67 b1 23 85 08 75 0.125098 [D3] 08 95 01 65 00 09 66 81 23 09 66 b1 a3 09 68 75 10 27 ff ff 00 00 66 01 10 0.125103 [D3] 81 23 09 68 b1 a3 09 2a 26 58 02 81 23 09 2a b1 a2 85 09 75 08 26 ff 00 05 0.125107 [D3] 84 09 40 67 21 d1 f0 00 55 06 b1 23 85 0a 09 30 b1 a3 09 02 a1 02 65 00 55 0.125112 [D3] 00 85 0b 75 01 95 06 25 01 05 85 09 d0 09 44 09 45 09 42 09 46 09 43 81 23 0.125117 [D3] 09 d0 09 44 09 45 09 42 09 46 09 43 b1 a3 75 02 95 01 81 01 b1 01 c0 85 0c 0.125121 [D3] 05 84 09 5a 75 08 15 01 25 03 b1 a2 09 5a 81 22 85 0d 09 fd 15 00 26 ff 00 0.125126 [D3] b1 23 c0 05 84 09 1a a1 00 85 0e 05 84 09 40 75 08 67 21 d1 f0 00 55 07 b1 0.125130 [D3] 23 85 0f 75 10 09 30 b1 a3 85 10 09 53 15 4e 25 58 b1 a2 09 53 81 23 09 54 0.125135 [D3] 16 88 00 26 8e 00 b1 a2 09 54 81 23 c0 09 1c a1 00 85 12 09 30 b1 a3 75 08 0.125139 [D3] 15 00 26 ff 00 65 00 55 00 85 13 09 35 b1 a3 85 14 09 58 25 06 b1 a2 09 58 0.125144 [D3] 81 22 85 15 09 57 75 10 15 ff 26 ff 7f 35 c4 47 c4 ff 1d 00 66 01 10 b1 a2 0.125148 [D3] 85 16 09 56 b1 a2 85 17 09 6e 75 01 15 00 25 01 35 00 45 00 65 00 b1 a3 09 0.125153 [D3] 65 b1 a3 75 06 b1 01 85 18 75 10 09 44 26 84 03 66 21 d1 55 07 b1 a3 85 1a 0.125158 [D3] 06 01 ff 65 00 55 00 75 08 15 00 25 02 09 43 b1 a2 09 43 81 23 c0 c0 00 00 0.125163 [D3] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0.125167 [D3] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0.125172 [D3] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0.125175 [D1] Got 6 HID objects... 0.125177 [D3] Report[buf]: (2 bytes) => 0b 11 0.125179 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125182 [D5] Unit = 00000000, UnitExp = 0 0.125184 [D5] Exponent = 0 0.125186 [D5] hid_lookup_path: 00840004 -> UPS 0.125188 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125191 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125193 [D5] hid_lookup_path: 008500d0 -> ACPresent 0.125196 [D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1 0.125199 [D5] hu_find_infoval: found online (value: 1) 0.125201 [D5] process_boolean_info: online 0.125204 [D3] Report[buf]: (2 bytes) => 0b 11 0.125206 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125208 [D5] Unit = 00000000, UnitExp = 0 0.125209 [D5] Exponent = 0 0.125212 [D5] hid_lookup_path: 00840004 -> UPS 0.125214 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125216 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125219 [D5] hid_lookup_path: 00850044 -> Charging 0.125221 [D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0 0.125225 [D5] hu_find_infoval: found !chrg (value: 0) 0.125227 [D5] process_boolean_info: !chrg 0.125229 [D3] Report[buf]: (2 bytes) => 0b 11 0.125231 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125234 [D5] Unit = 00000000, UnitExp = 0 0.125236 [D5] Exponent = 0 0.125238 [D5] hid_lookup_path: 00840004 -> UPS 0.125240 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125242 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125245 [D5] hid_lookup_path: 00850045 -> Discharging 0.125247 [D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0 0.125250 [D5] hu_find_infoval: found !dischrg (value: 0) 0.125252 [D5] process_boolean_info: !dischrg 0.125254 [D3] Report[buf]: (2 bytes) => 0b 11 0.125256 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125258 [D5] Unit = 00000000, UnitExp = 0 0.125260 [D5] Exponent = 0 0.125262 [D5] hid_lookup_path: 00840004 -> UPS 0.125264 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125267 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125269 [D5] hid_lookup_path: 00850042 -> BelowRemainingCapacityLimit 0.125272 [D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0 0.125274 [D5] hu_find_infoval: found !lowbatt (value: 0) 0.125277 [D5] process_boolean_info: !lowbatt 0.125279 [D3] Report[buf]: (2 bytes) => 0b 11 0.125281 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125283 [D5] Unit = 00000000, UnitExp = 0 0.125285 [D5] Exponent = 0 0.125287 [D5] hid_lookup_path: 00840004 -> UPS 0.125289 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125292 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125294 [D5] hid_lookup_path: 00850046 -> FullyCharged 0.125297 [D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x0b, Offset: 4, Size: 1, Value: 1 0.125299 [D5] hu_find_infoval: found fullycharged (value: 1) 0.125301 [D5] process_boolean_info: fullycharged 0.125304 [D3] Report[buf]: (2 bytes) => 0b 11 0.125306 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125308 [D5] Unit = 00000000, UnitExp = 0 0.125310 [D5] Exponent = 0 0.125312 [D5] hid_lookup_path: 00840004 -> UPS 0.125314 [D5] hid_lookup_path: 00840024 -> PowerSummary 0.125316 [D5] hid_lookup_path: 00840002 -> PresentStatus 0.125319 [D5] hid_lookup_path: 00850043 -> RemainingTimeLimitExpired 0.125322 [D2] Path: UPS.PowerSummary.PresentStatus.RemainingTimeLimitExpired, Type: Input, ReportID: 0x0b, Offset: 5, Size: 1, Value: 0 0.125324 [D5] hu_find_infoval: found !timelimitexp (value: 0) 0.125326 [D5] process_boolean_info: !timelimitexp 0.125329 [D1] Quick update... 0.125332 [D3] Report[buf]: (3 bytes) => 16 ff ff 0.125334 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.125336 [D5] Unit = 00001001, UnitExp = 0 0.125338 [D5] Exponent = 0 0.125341 [D2] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60 0.125345 [D3] Report[buf]: (3 bytes) => 15 ff ff 0.125347 [D5] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1 0.125349 [D5] Unit = 00001001, UnitExp = 0 0.125351 [D5] Exponent = 0 0.125354 [D2] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60 0.125357 [D3] Report[buf]: (2 bytes) => 0b 11 0.125359 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125361 [D5] Unit = 00000000, UnitExp = 0 0.125363 [D5] Exponent = 0 0.125365 [D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1 0.125367 [D5] hu_find_infoval: found online (value: 1) 0.125369 [D5] process_boolean_info: online 0.125372 [D3] Report[buf]: (2 bytes) => 0b 11 0.125374 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125376 [D5] Unit = 00000000, UnitExp = 0 0.125378 [D5] Exponent = 0 0.125380 [D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0 0.125382 [D5] hu_find_infoval: found !chrg (value: 0) 0.125384 [D5] process_boolean_info: !chrg 0.125386 [D3] Report[buf]: (2 bytes) => 0b 11 0.125388 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125390 [D5] Unit = 00000000, UnitExp = 0 0.125392 [D5] Exponent = 0 0.125394 [D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0 0.125397 [D5] hu_find_infoval: found !dischrg (value: 0) 0.125399 [D5] process_boolean_info: !dischrg 0.125401 [D3] Report[buf]: (2 bytes) => 0b 11 0.125403 [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0 0.125405 [D5] Unit = 00000000, UnitExp = 0 0.125407 [D5] Exponent = 0 0.125409 [D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0 0.125412 [D5] hu_find_infoval: found !lowbatt (value: 0) 0.125413 [D5] process_boolean_info: !lowbatt 0.125416 [D5] send_to_all: SETINFO ups.status "OL" 0.125418 [D5] send_to_all: DATAOK 0.125420 [D5] send_to_all: SETINFO driver.state "init.quiet" 0.126548 [D2] dstate_init: sock /opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD open on fd 5 0.126887 [D1] Group and/or user account for this driver was customized ('root:_nut') compared to built-in defaults. Fixing socket '/opt/local/var/db/ups/usbhid-ups-CP1500PFCLCD' ownership/access. 0.126896 [D1] WARNING: opening socket file for stat/chown failed (102), which is rather typical for Unix socket handling: Operation not supported on socket 0.126926 [D1] Group access for this driver successfully fixed (using file name based methods) 0.126930 [D5] send_to_all: SETINFO driver.parameter.pollinterval "2" 0.126932 [D5] send_to_all: SETINFO driver.parameter.synchronous "auto" 0.126934 [D5] send_to_all: SETINFO device.mfr "CPS" 0.126937 [D5] send_to_all: SETINFO device.model "CP1500PFCLCD" 0.126939 [D5] send_to_all: SETINFO device.serial "000000000000"

pjkerly commented 1 month ago

BTW, I also disable System Integrity Protection ... have the same issue enabled or disabled.

pjkerly commented 1 month ago

I tried your dummy-ups and it still fails on the fork. I'll have to look into dtrace.

sudo -E ../bin/dummy-ups -a dummyups -DDDDDD -B -u root 0.000000 [D5] send_to_all: SETINFO driver.state "init.starting" Network UPS Tools - Device simulation and repeater driver 0.19 (2.8.2) 0.000378 [D5] do_upsconf_args: confupsname=(null), var=user, val=root 0.000383 [D5] do_upsconf_args: call do_global_args() 0.000385 [D3] do_global_args: var='user' val='root' 0.000387 [D6] testval_reloadable: var=user, oldval=_nut, newval=root, reloadable=0, reload_flag=0 0.000389 [D1] testval_reloadable: setting 'user' exists and differs: new value 'root' vs. '_nut' 0.000390 [D6] testval_reloadable: verdict for (re)loading var=user value: 1 0.000392 [D1] Overriding previously specified user '_nut' with 'root' specified in global section 0.000396 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=driver, val=usbhid-ups 0.000398 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=port, val=auto 0.000402 [D5] do_upsconf_args: confupsname=CP1500PFCLCD, var=desc, val=Cyber Power CP1500PFCLCD 0.000405 [D5] do_upsconf_args: confupsname=dummyups, var=driver, val=dummy-ups 0.000406 [D5] do_upsconf_args: call main_arg() 0.000408 [D3] main_arg: var='driver' val='dummy-ups' 0.000409 [D5] do_upsconf_args: not a main_arg() 0.000411 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed? 0.000412 [D6] testval_reloadable: var=driver, oldval=dummy-ups, newval=dummy-ups, reloadable=0, reload_flag=0 0.000414 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1 0.000416 [D5] do_upsconf_args: 'driver' setting already applied with this value 0.000418 [D5] do_upsconf_args: confupsname=dummyups, var=port, val=/dev/null 0.000419 [D5] do_upsconf_args: call main_arg() 0.000421 [D3] main_arg: var='port' val='/dev/null' 0.000422 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=/dev/null, reloadable=0, reload_flag=0 0.000424 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1 0.000427 [D5] send_to_all: SETINFO driver.parameter.port "/dev/null" 0.000429 [D5] do_upsconf_args: confupsname=dummyups, var=desc, val=dummy 0.000430 [D5] do_upsconf_args: call main_arg() 0.000432 [D3] main_arg: var='desc' val='dummy' 0.000687 [D1] Built-in default or configured user for drivers 'root' was ignored due to 'root' specified on command line 0.000689 [D1] Network UPS Tools version 2.8.2 (release/snapshot of 2.8.2) built with Apple clang version 16.0.0 (clang-1600.0.26.3); Target: arm64-apple-darwin24.0.0; Thread model: posix and configured with flags: --prefix=/opt/local --with-serial=no --with-usb=auto --with-snmp=no --with-hal=auto --with-cgi=no --with-neonxml=no --with-ssl=yes --with-ipv6=no --with-statepath=/opt/local/var/db/ups --with-pidpath=/opt/local/var/run --with-hotplug-dir=/opt/local/etc/nut/hotplug --with-udev-dir=/opt/local/etc/nut/udev --with-user=_nut --with-group=_nut 0.000693 [D1] debug level is '6' 0.000695 [D5] send_to_all: SETINFO driver.debug "6" 0.000697 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER 0.001941 [D1] Succeeded to become_user(root): now UID=0 GID=0 0.002171 [D1] Saving PID 3519 into /opt/local/var/db/ups/dummy-ups-dummyups.pid 0.002237 [D5] send_to_all: SETINFO device.type "ups" 0.002241 [D5] send_to_all: SETINFO driver.state "init.device" 0.002244 [D1] Dummy (simulation) mode default (looping infinitely) 0.002246 [D5] send_to_all: SETINFO driver.parameter.mode "dummy" 0.002251 [D2] Located /dev/null for device simulation data: /dev/null 0.002253 [D5] send_to_all: SETINFO driver.state "init.quiet" 0.002258 [D5] send_to_all: SETINFO driver.version "2.8.2" 0.002260 [D5] send_to_all: SETINFO driver.version.internal "0.19" 0.002262 [D5] send_to_all: SETINFO driver.name "dummy-ups" 0.002264 [D5] send_to_all: SETINFO driver.state "init.info" 0.002266 [D5] send_to_all: SETINFO ups.mfr "Dummy Manufacturer" 0.002267 [D5] send_to_all: SETFLAGS ups.mfr RW STRING 0.002269 [D5] send_to_all: SETAUX ups.mfr 32 0.002271 [D5] send_to_all: SETINFO ups.model "Dummy UPS" 0.002272 [D5] send_to_all: SETFLAGS ups.model RW STRING 0.002274 [D5] send_to_all: SETAUX ups.model 32 0.002276 [D5] send_to_all: SETINFO ups.status "OL" 0.002277 [D5] send_to_all: SETFLAGS ups.status RW STRING 0.002279 [D5] send_to_all: SETAUX ups.status 32 0.002280 [D1] entering parse_data_file() 0.002311 [D5] send_to_all: DATAOK 0.002314 [D5] send_to_all: ADDCMD load.off 0.002316 [D5] send_to_all: SETINFO driver.state "init.updateinfo" 0.002317 [D1] upsdrv_updateinfo... 1.007412 [D1] entering parse_data_file() 1.007740 [D5] send_to_all: SETINFO driver.state "init.quiet" 1.009418 [D2] dstate_init: sock /opt/local/var/db/ups/dummy-ups-dummyups open on fd 3 1.010395 [D1] Group and/or user account for this driver was customized ('root:_nut') compared to built-in defaults. Fixing socket '/opt/local/var/db/ups/dummy-ups-dummyups' ownership/access. 1.010425 [D1] WARNING: opening socket file for stat/chown failed (102), which is rather typical for Unix socket handling: Operation not supported on socket 1.010524 [D1] Group access for this driver successfully fixed (using file name based methods) 1.010539 [D5] send_to_all: SETINFO driver.parameter.pollinterval "2" 1.010545 [D5] send_to_all: SETINFO driver.parameter.synchronous "auto" 1.010550 [D5] send_to_all: SETINFO device.mfr "Dummy Manufacturer" 1.010554 [D5] send_to_all: SETINFO device.model "Dummy UPS"

jimklimov commented 1 month ago

For dummy-ups setup, I used NUT sources and prepared the prerequisites for MacOS/Homebrew combo per https://github.com/networkupstools/nut/wiki/Building-NUT-for-in%E2%80%90place-upgrades-or-non%E2%80%90disruptive-tests and referenced docs.

Then after building NUT, I just make check-NIT-sandbox and it prepares upsd and some dummies, and prints where to source an env file with needed variables to run NUT programs from the build area using the mock setup.

Afterwards I killed one of the spawned dummy-ups'es and started one with that config name manually.

pjkerly commented 1 month ago

Another quick update ...

Using dtrace for fork entry / exit results ... From the results below, it looks like the fork return is actually successful and returns PID of the forked usbhid-ups which matches the PID found in the usbhid-ups-CP1500PFCLCD.PID file.

So I assume the child process is created and then must crash after forking.

syscall::fork:entry ' matched 10 probes CPU ID FUNCTION:NAME 2 173 fork:return 480 zsh fork returned 3764 2 173 fork:return

4 173 fork:return 3764 sudo fork returned 3765 4 173 fork:return

5 173 fork:return 3765 usbhid-ups fork returned 3766 5 173 fork:return

jimklimov commented 1 month ago

Thinking of it, your "2.8.2" version of NUT is likely from packaging? Are you in position to build from git per instructions liked above? On one hand, there were some fixes and changes generally since the last release, on another - maybe the tooling/settings/libs used for package build differ from whatever the documented Homebrew-based approach provides.

pjkerly commented 1 month ago

Further investigation ...

So it appears that the usbhib-ups driver is crashing on a null pointer (Faulting instruction pointer: 0). Based on the error info, I assume it is using dynamic function pointer(s) into Core Foundation. Seeing this in the write sys call. I assume this is being write to an error or system log. But I looked in logs and did see any errors before I started debugging.

But my take is that some functionality in CoreFoundation can't be used by a forked process. Sound likes it needs to an exec() call in order to use that functionality. I will look to see if there are any limitations using fork and Apple libraries.

The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: SETINFO driver.state "updateinfo"

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: SETINFO driver.state "reconnect.trying"

1 176 write:entry PID 16949 TID 1526720 syscall write called Data:

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec().

1 176 write:entry PID 16949 TID 1526720 syscall write called Data: Break on __THE_PROCESS_HAS_FORKED_AND_YOU_CANNOT_USE_THIS_COREFOUNDATION_FUNCTIONALITY_YOU_MUST_EXEC() to debug.

1 395514 .:fault Fault detected in process: usbhid-ups (PID: 16949, TID: 1526720) Fault type: 1 Faulting address: fffffe24d9fc5658 Faulting instruction pointer: 0 Timestamp: 143417880310375 Generated signal: 1

          0x1957232dc
          0x104e8e2f8
          0x104e88630
          0x104e08fc8
          0x104e15578
          0x19514c274

1 395786 .:exit Process exited: PID=16949, TID=1526720, Executable=usbhid-ups, Exit Status=1

usbhid-ups.pdf

pjkerly commented 1 month ago

Let me know if someone can make these changes. If not, I'll need to spend some time getting a build/debug environment setup to build NUT for Mac. I'm not really familiar with the requirements to build/test any changes.

Thanks, Phil

From ChatGPT so need to take that into account ... but it sounds reasonable especially since I was getting those messages in my dtrace output.

The error message "The process has forked and you cannot use this CoreFoundation functionality safely. You MUST exec()" is typically seen in macOS (or any system using CoreFoundation) when a process uses certain CoreFoundation functions after a fork() but before an exec().

Why This Happens: Fork-Exec Model: In Unix-like operating systems, when a process forks, the child process is an exact copy of the parent, sharing most of its memory and resources. However, after the fork, the child should typically replace its memory space by calling exec(), which loads a new program into memory. CoreFoundation's Limitations: CoreFoundation (and related libraries, like Cocoa or AppKit) maintain internal state and rely on various resources that aren’t safely copied or reset in the child process after a fork. Forking a process that uses these libraries and not immediately calling exec() to replace the process image can cause issues, as the child process might access shared or inconsistent states, leading to crashes or undefined behavior. To prevent these unsafe operations, macOS and CoreFoundation actively block such functionality after a fork() and warn you that you must call exec() immediately after forking, which replaces the child process' memory space with a new executable image and safely resets the state.

Key Points: fork() without exec(): If you fork and do not follow it immediately with exec(), you risk running into issues with CoreFoundation, which is not fork-safe. Internal Resources: CoreFoundation maintains internal resources (file descriptors, memory allocators, threads, etc.) that are not properly re-initialized in a child process created via fork(). Thread Safety: CoreFoundation is not thread-safe across fork() boundaries because threads are not copied over to the child process, but their related states might remain in a broken state. How to Fix This: You must ensure that after calling fork(), the child process immediately calls exec() to replace its memory space with a new process image. Here's how you can fix the issue:

Call exec() After fork(): When you fork a process, follow it immediately by calling exec() in the child process. The exec() family of functions replaces the current process image with a new one, ensuring a fresh environment and avoiding conflicts with CoreFoundation. Avoid Using CoreFoundation Functions After fork(): If you cannot use exec() immediately, make sure to avoid any CoreFoundation (or Cocoa/AppKit) function calls in the child process. Example of Proper Fork-Exec Pattern:

pid_t pid = fork(); if (pid == -1) { // Handle fork error } else if (pid == 0) { // This is the child process // Replace current process image with a new one execvp("/path/to/executable", argv); // Replace with actual exec call // If execvp() fails: perror("exec"); exit(1); } else { // This is the parent process, continue as normal }

jimklimov commented 1 month ago

Not really versed with Mac ecosystem, sorry. CC @clepple comes to mind, if there would be any more ideas or people to poll?

pjkerly commented 1 month ago

OK ... do you have any references/links on how to setup a build/debug environment for MacPorts and how someone goes about submitting / recommending any changes. I don't have a full suite of Mac OS versions so I would be limited to testing on a small number of systems / OS.

jimklimov commented 1 month ago

If ChatGPT is right :) then we might have to add some #ifdef NUT_PLATFORM_APPLE_OSX blocks in drivers/main.c (and probably all other NUT daemon programs) to detect the path to program binary (its argv[0] if nobody fiddled with it, possibly relative to initial value of current working directory), and when we fork() to detach from console - re-exec() the same program.

I have no firm idea what it would do to the C variables already collected and expected to be populated post-detachment, but probably nothing good, given that it would cause execution of a new process from scratch, essentially. Some research may be needed to check what exactly is not fork-safe, perhaps it may suffice to close/open the syslog socket, or something.

Given that forking to detach from console and go into background (or other sort of multi-threading purposes) is common practice for decades, probably there's a gazillion other programs that have solved this one way or another, including open-source ones to take inspiration from. I'd probably start at known multi-process stuff like Apache httpd, perhaps nginx or sendmail - staples of the ecosystem.

Sadly, so far I have zero knowledge of MacPorts beside the name; setting up a cloud VM for CI and going with HomeBrew as the first option I saw is as much as I know of the platform.

That said, if you do unravel this - additions to docs/config-prereqs.txt, and possibly tweaks into ci_build.sh (needed HOMEBREW_PREFIX to work around some header and pkg-config issues), configure.ac etc. would be most welcome.

If those two ecosystems can co-exist on the same VM - I might add scenarios to NUT CI farm as well then...

jimklimov commented 1 month ago

Also, if the two ecosystems can co-exist (or if you can spawn a Sonoma VM for experiments), and if you can check if current NUT source built with Homebrew works or not, it can help rule out OS problems (something in common libs shared by both ecosystems) vs. ecosystem problems (e.g. HomeBrew might have libs with an implementation of fork() that behaves as expected by other systems, and that can inspire solutions that would help on MacPorts?)

clepple commented 1 month ago

Why not just run the driver in the foreground under launchd? I thought libusb had some better protections against using CF in the wrong process, but I also haven't been doing much OS X + USB in the past few years.

pjkerly commented 1 month ago

Exactly what I'm doing now ... but without documentation that I could find it was a process to get to this point to figure why upsdrvctl and usbhid-ups failed. BTW the forking in uspd and upsmon don't have the same issue. In this case, I'm using -FF option to force generating the PID so that my LaunchDaemon can shutdown the usbhid-ups driver.

Kraiggers commented 4 weeks ago

I ran into this, using the brew package. (As well some additional issues.) I've been tearing my hair out trying to figure out why I can't get the driver and upsd to run in background. It's almost a relief that there is a bug of some kind.

Like the OP, I am able to run upsdrvctl, (only in the foreground):

jks4e@Athena ~ % sudo upsdrvctl -u root -FF start Network UPS Tools - UPS driver controller 2.8.2 Network UPS Tools - Generic HID driver 0.53 (2.8.2) USB communication driver (libusb 1.0) 0.47 Using subdriver: CyberPower HID 0.80 Running as foreground process, but saving a PID file anyway upsnotify: failed to notify about state 2: no notification tech defined, will not spam more about it sock_connect: enabling asynchronous mode (auto)

And, I am also able to run upsd:

jks4e@Athena ~ % sudo upsd -u root Network UPS Tools upsd 2.8.2 fopen /opt/homebrew/var/state/ups/upsd.pid: No such file or directory Could not find PID file '/opt/homebrew/var/state/ups/upsd.pid' to see if previous upsd instance is already running! /opt/homebrew/etc/nut/upsd.conf is world readable listening on 127.0.0.1 port 3493 /opt/homebrew/var/state/ups is world readable Connected to UPS [CyberPower]: usbhid-ups-CyberPower Found 1 UPS defined in ups.conf /opt/homebrew/etc/nut/upsd.users is world readable

However, when I try to stop upsdrvctl, I do get a sigterm, but I also get this:

jks4e@Athena ~ % sudo upsdrvctl stop Network UPS Tools - UPS driver controller 2.8.2 fopen /opt/homebrew/var/state/ups/usbhid-ups-CyberPower.pid: No such file or directory

There should be a .pid file, shouldn't there?

And I don't know if it's related, but I also am baffled by the permissions. I seem to only be able to start upsdrvctl (or usbhid-ups directly) and upsd successfully if I use sudo and -u root.

What am I doing wrong (but almost right)?

Kraiggers commented 4 weeks ago

And, by the by, how did you get upsdrvctl and upsd to run as a launch agents? I've been struggling with that too... my .plists seems like they should work, but they're not. Maybe a permissions thing again?

jimklimov commented 3 weeks ago

Can't really speak to MacOS as a platform to run things; in the cloud I only have a (Monterey?) VM to build them in CI. It may well be that by Sonoma (v12 vs. v14 major) they changed a lot of things that I might test on that VM and would "work for me" there :\

That said, so now regarding the general NUT code and behavior:

I am not sure if and how Apple limits access to USB devices. On most of the Unix-like platforms, there is eventually a device file system and each device has a file-like "node" there, with POSIX permissions attached (maybe ACL somewhere, haven't seen that).

Most frequently the problem about starting not as root (or dropping privileges to a run-time nut or similar user account) is about not having I/O permission to a USB/serial/... port at that low level. OS facilities like devd, udev and some others usually allow to manage such permissions as part of plug-and-play; persistent devfs or init-scripts and cron jobs calling chown+chmod take care of it on others (at least where some path name to the devfs/sysfs node is predictable).

With USB there may be a separate layer of complexity, that some other program or kernel handler grabbed the device node (especially if it poses as a HID - Human Interface Device) exclusively, and so won't let the NUT driver have a piece. This is also part that udev and the likes usually solve.

jimklimov commented 3 weeks ago

Let me know if someone can make these changes. If not, I'll need to spend some time getting a build/debug environment setup to build NUT for Mac. I'm not really familiar with the requirements to build/test any changes.

Unfortunately, my practice with the platform is limited to setting up the CI build agent.

That said, I think the experience should be all documented at https://networkupstools.org/docs/user-manual.chunked/_build_prerequisites_to_make_nut_from_scratch_on_various_operating_systems.html#_macos_with_homebrew for the platform setup (with Homebrew as the one I tried - a chapter with Fink etc. would be welcome), and then running ./ci_build.sh for the common building and testing.

jimklimov commented 3 weeks ago

With the tests prepared, you can make check-NIT to run the NUT Integration Tests with upsd talking to some dummy-ups instances and different scenarios about having and not having configs, as well as testing the Python/C++/etc. client implementations (if enabled).

This would at least rule out where exactly the forking problem is - NUT daemons themselves, or some third party code (e.g. libusb vs. CF as suggested above).

With make check-NIT-sandbox you can prepare an environment to run other built NUT programs against these upsd + dummy-ups or to edit the generated config files in tests/NIT/tmp/etc/ and e.g. test a built drivers/usbhid-ups program. The sandbox will suggest to source a generated env file with the random $NUT_PORT and configuration paths and stuff, into your current shell. I think it would prepare the LD_LIBRARY_PATH using the built artifacts, too - not fully sure though.

Note that depending on tooling, your actual libs and programs may be in .libs subdirs, e.g. drivers/.libs/usbhid-ups and the ones near the sources being GNU libtool wrappers to set up paths and debugging. For tracing or GDB stepping, you need the actual binaries (and manually reproduce the path setup that libtool does); it might work or not to try forking support (so the debugger does start the wrapper script and then does see the actual NUT program) - I did not have much success in that generally.

Kraiggers commented 3 weeks ago

So, the command

sudo upsdrvctl -u root -FF start

does start usbhid-ups in the foreground successfully, and it does spawn

/opt/homebrew/var/state/ups/usbhid-ups-CyberPower.pid

with the correct process ID, owned by system. And, the foreground process receives a signal 15: exiting. But I still get

jks4e@Athena StartupItems % sudo upsdrvctl stop Password: Network UPS Tools - UPS driver controller 2.8.2 fopen /opt/homebrew/var/state/ups/usbhid-ups-CyberPower.pid: No such file or directory

Maybe that's an erroneous error message? How else could the process be terminated successfully?

pjkerly commented 3 weeks ago

I get the same behavior with MacPorts ... I also wondered about this message. I concluded that it is expected behavior. I've noticed that I don't get the fopen message until after the upsdrvctl with start has already exited before the upsdrvctl with stop gets the message. I concluded that the original upsdrvctl that was started once it receives the SIGTERM, it checks for and removes the PID file. The upsdrvctl that is executed with the stop command is following the same path on exit to clean up the PID file but it has already been removed and not finding it is expected if all goes well.

I didn't pursue it further since it works without any issues.

BTW, I'm using MacPorts daemondo to start and stop both upsdrvctl and upsd in the background on Mac OS X boot and shutdown which works out really well for clean startup and shutdown.

I've uploaded what I'm using to start and stop at OS boot / shutdown.

org.macports.upsdrvctl.plist.txt org.macports.upsd.plist.txt

upsdrvctl.wrapper.txt upsd.wrapper.txt

jimklimov commented 3 weeks ago

How else could the process be terminated successfully?

If you ran those tools and drivers with debug, it would be a bit less of guesswork. But in recent releases, NUT grew some ways to not depend on PID files (e.g. using the same socket/pipe as the one for driver-to-upsd communications, to send an exit command).

Conversely, recent versions also try to check the file name associated with a PID, to not signal/kill unsuspecting bystanders that happen to have the same PID (e.g. if a PID-file is written into location which survives a reboot).

jimklimov commented 3 weeks ago

Hm, I wonder which program and when complains about /opt/homebrew/var/state/ups/usbhid-ups-CyberPower.pid - upsdrvctl or the driver? Maybe one deletes it before the other one checks for it?

jimklimov commented 3 weeks ago

I've uploaded what I'm using to start and stop at OS boot / shutdown.

@pjkerly : would you care to make a PR in your name, e.g. adding these files and a README to a new scripts/macos/macports location, as a reference for future adventurers?

pjkerly commented 3 weeks ago

What's a PR? I'm not really familiar with MacPorts other than as a user. I would have attempted to actually fix both upsdrvctl and upsd (at least for the Mac OS fork bug) but I'm not familiar with how to actually setup a build environment, process for getting changes accepted, nor can I test on many different platforms.

pjkerly commented 3 weeks ago

OK ... So a PR ... Pull Request. Let me look into it. Would you be the reviewer / maintainer to merge in?

jimklimov commented 3 weeks ago

Yes. The "how to set up" is in this thread less than 10 posts above, at least as much as I know about MacOS as seen on workers for CI :)

Kraiggers commented 3 weeks ago

OK. I managed to get launch agents to run successfully, but I had to add a user-level sudo permission for upsd & upsdrvctl in order to do it. There is something funky that I'm definitely not seeing/understanding/both about the permissions.

This is almost assuredly a dumb question, but how do I force the upsdrvctl agent to run before the upsd agent?

Finally, after many days of farting around with this, it appears that the CyberPower oem software service can't connect to the UPS concurrently with the NUT service.

What I wanted, was for the oem software to alert me with its (local) email notification service (is there another way to get this kind of notification?), and then be able to use an app I found (Mac, iOS) that connects to NUT so I can get real-time status information. Because, of course, the Cyber Power cloud service that does this is both 1) incredibly ugly and 2) behind a paywall.

Ugh.

Kraiggers commented 3 weeks ago

FYI

https://apps.apple.com/us/app/ups-power-monitor/id1500563567

https://apps.apple.com/us/app/ups-power-monitor/id1500180529?mt=12

I don't see any specific information regarding notifications...

pjkerly commented 3 weeks ago

Order shouldn't matter ... They should sync up in either order. I used the oem software but haven't since switching. Have you look at upsmon - can use a command option to send e-mail or (to text)? Or have you looked at the UPS Power Monitor and Power Guard (from App Store for Mac). I personally have a Home Assistant setup with an integration for ups ...

Kraiggers commented 3 weeks ago

Oh I didn't know upsmon could do that.

Christ, another NUT service to try to figure out how to run...

pjkerly commented 3 weeks ago

several options for command line mail notifications ...

  1. Using mail Command The mail command is a simple tool you can use to send an email. Here's an example:

bash Copy code echo "This is the body of the email" | mail -s "Subject of the Email" recipient@example.com To attach a file, use the -A option:

bash Copy code echo "This is the body of the email" | mail -s "Subject of the Email" -A /path/to/file.txt recipient@example.com You may need to install the mail command if it’s not available:

bash Copy code brew install mailutils

  1. Using sendmail Command Another option is sendmail, which provides more flexibility but requires configuration. Here's an example command:

bash Copy code echo -e "Subject: Test Email\n\nThis is a test email" | sendmail recipient@example.com This assumes sendmail is correctly configured on your system.

  1. Using s-nail or mailx You can use s-nail (or mailx), which is similar to mail but has more options and is often available by default on macOS. Here's an example:

bash Copy code echo "This is the body" | s-nail -s "Subject of the email" recipient@example.com For sending through SMTP (if needed, for external services like Gmail), you’ll need to configure s-nail or mailx by editing the ~/.mailrc file:

bash Copy code set smtp="smtp://smtp.gmail.com:587" set smtp-auth=login set smtp-auth-user="your-email@gmail.com" set smtp-auth-password="your-password" set ssl-verify=ignore set from="your-email@gmail.com" After configuration, you can send emails using s-nail as shown earlier.

  1. Using Python If you have Python installed, you can use a simple Python script to send an email via the command line:

bash Copy code python3 -c " import smtplib server = smtplib.SMTP('smtp.gmail.com', 587) server.starttls() server.login('your-email@gmail.com', 'your-password') server.sendmail('from-email@gmail.com', 'to-email@example.com', 'Subject: Test\nThis is the body of the email.') server.quit() " This method gives you flexibility to use Gmail or other SMTP services.

pjkerly commented 3 weeks ago

sysmon was easier since it doesn't have the same fork() bug that upsd and upsdrvctl has. But I still used the daemondo, plist, and wrapper approach just to keep all of them consistent in implementation.

jimklimov commented 3 weeks ago

I'll be off for today but it seems you've started a fruitful discussion here, so just adding a few bits :)

it appears that the CyberPower oem software service can't connect to the UPS concurrently with the NUT service.

On most systems only one program can fully attach to a USB device (or serial port), so yes - either one or another. Part of the issues discussed above with udev/devd/... part where something in the OS would grab a HID device by default, because why not.

As for upsmon - not sure I get the surprise in the discovery. It is the NUT client daemon which drives the safe shutdown of your system in case of outage, which is why you run NUT, right? So I suppose it should be available in the packaging or made to run otherwise. And yes, it can send notifications (syslog, wall, script e.g. for mail)...

Kraiggers commented 3 weeks ago

actually, I was just running it for upsd; the upsmon is superfluous for connecting to the software mentioned above.

MacOS has a facility in the OS which talks to a UPS and can gracefully shut down. It just doesn't expose any of the granular information nor is it available remotely.

But, I will now take a look at using upsmon as well and rolling my own notification, I guess. I gotta say, for a noob this is right on the border of what I can (maybe) manage... Not the upsmon specifically, just the whole thing. NUT is finicky AF.

pjkerly commented 3 weeks ago

I spent many days debugging / root causing the background / fork() issue so I understand. I use sysmon because I actually have two systems plugged in my UPS. One is a server which I want to run longer. The other isn't critical so that if the UPS is running on battery for ~10 minutes, I have it shutdown more quickly to conserve battery. The server on the other hand runs longer until the battery is down to the last 15% and then it shutdowns a VM cleanly which is running my Home Assistant and shuts down the server cleanly. I can check the status of the UPS through my Home Assistant remotely. Notification is actually secondary because if I lose power, it's unlikely I will be able to send any notifications. I also have my internet router and cable modem on the UPS but the ISP may also be impacted. But if the internet is still available it notifies me if running on battery for more than 10 minutes and just before shutdown. When power is restored I have the UPS send power to the devices only if the power has been restored continuously for more than 10 minutes.

Kraiggers commented 3 weeks ago

Nice. I don't need any of that.

This started off as just, hmmm I wonder if I can NOT use the Cyber Power dumpster fire OEM software, that also has a subscription (of course it does).

I wan't really intending to get eyeballs deep in a terminal / launch agent project... But here we are.

Kraiggers commented 3 weeks ago

All right. Well, I've got upsmon going as well, set up to text me on NOTIFY events as per upsmon.conf. I won't lie it was pretty satisfying. It's not perfectly clean, as I'm basically sending messages to myself through iMessage, but I think I can live with that. Better than emails. Yuck.

AND I even got the UPS Power Monitor software working on my phone (bounced through my DDNS). So that's pretty neat.

I'm not super pumped about running the three processes via sudo, but I don't see what harm it could cause...?

Kraiggers commented 3 weeks ago
Screenshot 2024-10-19 at 14 30 26 Screenshot 2024-10-19 at 14 30 58
Kraiggers commented 3 weeks ago

Semi-related question. I did the pull-the-plug test and I got the text messages (huzzah) but I noticed my run-time dropped from 47 min to 20 minutes and the unit was unplugged for like 30s. I assume that means the battery is toast? (It is 6 years old...)

Do you have any experience or opinions about putting a LifePO4 batter in place of a Pb Acid? Im' thinking specifically of the Dakota Lithium: https://dakotalithium.com/product/dakota-lithium-12v-10ah-battery/

I pull about 100 watts at normal browsing usage and maybe 150 if both pcs are running at the same time at idle. Maybe 230+ if I'm doing stuff? What happens to a UPS with a 12v Dakota battery (rated to max 20a) if it tries to pull more than 240 watts...?

jimklimov commented 3 weeks ago

Run-time estimates depend on calibration results that should be done with same sort of load as you're running, and repeated (becaude batteries do age). If the device supports such a test, you may be able to upscmd the battery.test.start (beware that if the UPS does overestimate itself, load like computers may be suddenly powered off). If not, with some drivers there's a runtimecal setting with estimates you measure and record there (see man pages).

pjkerly commented 3 weeks ago

It's not unusual for a UPS to drop estimated runtime soon after it switches to battery particularly for an older battery as it ages. You have to start with what are your requirements / needs. My requirements are simple... 1) A must - Prevent system corruptions from catastrophic and instantaneous power failures. 2) A must / highly desirable - bridge power interruptions / flickers that last a few seconds to tens of minutes. If the power interruption last more than ~10 minutes, it's likely to be longer than my UPS will support any way. 3). Nice to have - Maintain internet connectivity for as long as possible for use with laptop / iPad / iPhones with no specific time-frame.

If your projected run time drops from 47 minutes to 20 minutes, then I wouldn't call the battery toast. After the initial drop, do the rate of runtime seem constant with wall clock time? A shutdown sequence should be on the order of 60 secs or so depending on what you are running. And 20 minutes is definitely enough time to bridge power flickers/fluctuations during storms as well as support clean shutdown. But your requirements on how long you want to run at your desired load will dictate the size and performance of the UPS you needs.

I'm not familiar with the battery you listed nor whether it is compatible with your UPS. I have a a CyberPower CP1500PFCLCD UPS from Costco which meets my needs. I can find replacement batteries on Amazon for it but haven't done so. My system is also probably ~4 yrs old. I also see a good drop in initial runtime right after switching to battery.

clepple commented 3 weeks ago

Do you have any experience or opinions about putting a LifePO4 batter in place of a Pb Acid?

from the product page: "LiFePO4 charger recommended" which I'm guessing doesn't include most consumer Pb-acid UPSes.

6 years is beyond the usual 3-5 year lifetime for an UPS battery. Maybe 20 minutes is still sufficient for your purposes, but it's like driving on old tires: they're not going to get any better over time, and you've hit the wear indicator.