Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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 this issue Sep 26, 2024 · 45 comments
Labels
impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) macOS service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug USB

Comments

@pjkerly
Copy link

pjkerly commented Sep 26, 2024

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 jimklimov added USB macOS service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) labels Sep 26, 2024
@jimklimov
Copy link
Member

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
Copy link
Member

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
Copy link
Author

pjkerly commented Sep 26, 2024

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
Copy link
Author

pjkerly commented Sep 26, 2024

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

@pjkerly
Copy link
Author

pjkerly commented Sep 26, 2024

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
Copy link
Member

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
Copy link
Author

pjkerly commented Sep 27, 2024

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
Copy link
Member

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
Copy link
Author

pjkerly commented Sep 28, 2024

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
Copy link
Author

pjkerly commented Sep 28, 2024

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
Copy link
Member

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

@pjkerly
Copy link
Author

pjkerly commented Sep 28, 2024

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
Copy link
Member

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
Copy link
Member

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
Copy link
Member

clepple commented Sep 30, 2024

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
Copy link
Author

pjkerly commented Sep 30, 2024

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
Copy link

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
Copy link

Kraiggers commented Oct 19, 2024

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
Copy link
Member

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:

  • Note that for upsdrvctl the -D option(s) apply to logging from the tool itself; an additional -d passes the selected level to the driver(s) also. For more details, see https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity
  • the PID files should be there (unless running with a single -F foreground option), at least FS permissions permitting (check who owns /opt/homebrew/var/state/ups and if that matches the run-time user which you or the package builder configure'd; in debug mode that would be seen around become_user log lines).
    ** It does say Running as foreground process, but saving a PID file anyway... Again, debug might show more.
  • Permissions should not be a problem when you troubleshoot to run as root though.
    ** You may want to constrain the configuration files to only be readable by e.g. root:nut and only writable by owner root.

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
Copy link
Member

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.

  • Looking at it, there may have been a step about installing XCode if it was not part of the OS. In the CI cloud, it was there.
  • https://github.com/networkupstools/nut/blob/master/.circleci/config.yml is the complete automation used in the cloud builds.
  • You may have to export HOMEBREW_PREFIX for ci_build.sh to know to apply some hacks for this build, and avoid distrust to system headers, e.g. as
HOMEBREW_PREFIX="`brew config | grep HOMEBREW_PREFIX: | awk '{print $2}'`"

@jimklimov
Copy link
Member

jimklimov commented Oct 19, 2024

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
Copy link

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
Copy link
Author

pjkerly commented Oct 19, 2024

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
Copy link
Member

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
Copy link
Member

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
Copy link
Member

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
Copy link
Author

pjkerly commented Oct 19, 2024

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
Copy link
Author

pjkerly commented Oct 19, 2024

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

@jimklimov
Copy link
Member

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
Copy link

Kraiggers commented Oct 19, 2024

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
Copy link

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
Copy link
Author

pjkerly commented Oct 19, 2024

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
Copy link

Oh I didn't know upsmon could do that.

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

@pjkerly
Copy link
Author

pjkerly commented Oct 19, 2024

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" [email protected]
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 [email protected]
You may need to install the mail command if it’s not available:

bash
Copy code
brew install mailutils
2. 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 [email protected]
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" [email protected]
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="[email protected]"
set smtp-auth-password="your-password"
set ssl-verify=ignore
set from="[email protected]"
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('[email protected]', 'your-password')
server.sendmail('[email protected]', '[email protected]', 'Subject: Test\nThis is the body of the email.')
server.quit()
"
This method gives you flexibility to use Gmail or other SMTP services.

@pjkerly
Copy link
Author

pjkerly commented Oct 19, 2024

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
Copy link
Member

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
Copy link

Kraiggers commented Oct 19, 2024

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
Copy link
Author

pjkerly commented Oct 19, 2024

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
Copy link

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
Copy link

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
Copy link

Screenshot 2024-10-19 at 14 30 26 Screenshot 2024-10-19 at 14 30 58

@Kraiggers
Copy link

Kraiggers commented Oct 19, 2024

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
Copy link
Member

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
Copy link
Author

pjkerly commented Oct 20, 2024

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
Copy link
Member

clepple commented Oct 20, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) macOS service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug USB
Projects
None yet
Development

No branches or pull requests

4 participants