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

When starting a driver program to force UPS shutdown, kill off running siblings #2750

Merged
merged 5 commits into from
Jan 8, 2025

Conversation

jimklimov
Copy link
Member

Closes: #2666

…up and variable definitions before code)

Signed-off-by: Jim Klimov <[email protected]>
…_forceshutdown || dump_data) also, just keep it non-fatal [networkupstools#2666]

Signed-off-by: Jim Klimov <[email protected]>
@jimklimov jimklimov added enhancement service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug Windows-not-on-par-with-POSIX Aspect of Windows builds known to be dysfunctional compared to POSIX builds; fix needed to be on par labels Jan 3, 2025
@jimklimov jimklimov added this to the 2.8.3 milestone Jan 3, 2025
@jimklimov jimklimov added the need testing Code looks reasonable, but the feature would better be tested against hardware or OSes label Jan 4, 2025
@jimklimov
Copy link
Member Author

Checking with socket protocol:

:; make check-NIT-sandbox-devel &
# wait until it reports preparedness

:; . /home/jim/nut/tests/NIT/tmp/etc/NIT.env

:; ./drivers/dummy-ups -a dummy -k -DDDDDD
   0.000002     [D5:1472330] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools 2.8.2.1827.18-1845-g181d45680 (development iteration after 2.8.2) - Device simulation and repeater driver 0.20
   0.000101     [D5:1472330] do_upsconf_args: confupsname=(null), var=maxretry, val=3
   0.000127     [D5:1472330] do_upsconf_args: call do_global_args()
   0.000153     [D3:1472330] do_global_args: var='maxretry' val='3'
   0.000211     [D5:1472330] do_upsconf_args: confupsname=(null), var=driverpath, val=/home/jim/nut/drivers
   0.000236     [D5:1472330] do_upsconf_args: call do_global_args()
   0.000263     [D3:1472330] do_global_args: var='driverpath' val='/home/jim/nut/drivers'
   0.000275     [D5:1472330] do_upsconf_args: confupsname=dummy, var=driver, val=dummy-ups
   0.000295     [D5:1472330] do_upsconf_args: call main_arg()
   0.000319     [D3:1472330] main_arg: var='driver' val='dummy-ups'
   0.000347     [D5:1472330] do_upsconf_args: not a main_arg()
   0.000376     [D5:1472330] do_upsconf_args: this is a 'driver' setting, may we proceed?
   0.000399     [D6:1472330] testval_reloadable: var=driver, oldval=dummy-ups, newval=dummy-ups, reloadable=0, reload_flag=0
   0.000424     [D6:1472330] testval_reloadable: verdict for (re)loading var=driver value: -1
   0.000447     [D5:1472330] do_upsconf_args: 'driver' setting already applied with this value
   0.000473     [D5:1472330] do_upsconf_args: confupsname=dummy, var=desc, val=Crash Dummy
   0.000497     [D5:1472330] do_upsconf_args: call main_arg()
   0.000520     [D3:1472330] main_arg: var='desc' val='Crash Dummy'
   0.000546     [D5:1472330] do_upsconf_args: confupsname=dummy, var=port, val=dummy.seq
   0.000570     [D5:1472330] do_upsconf_args: call main_arg()
   0.000596     [D3:1472330] main_arg: var='port' val='dummy.seq'
   0.000618     [D6:1472330] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=dummy.seq, reloadable=0, reload_flag=0
   0.000645     [D6:1472330] testinfo_reloadable: verdict for (re)loading var=port value: 1
   0.000654     [D5:1472330] send_to_all: SETINFO driver.parameter.port "dummy.seq"
   0.000678     [D5:1472330] do_upsconf_args: confupsname=UPS1, var=driver, val=dummy-ups
   0.000706     [D5:1472330] do_upsconf_args: confupsname=UPS1, var=desc, val=Example event sequence
   0.000729     [D5:1472330] do_upsconf_args: confupsname=UPS1, var=port, val=evolution500.seq
   0.000757     [D5:1472330] do_upsconf_args: confupsname=UPS2, var=driver, val=dummy-ups
   0.000782     [D5:1472330] do_upsconf_args: confupsname=UPS2, var=desc, val=Example ePDU data dump
   0.000810     [D5:1472330] do_upsconf_args: confupsname=UPS2, var=port, val=epdu-managed.dev
   0.000833     [D5:1472330] do_upsconf_args: confupsname=UPS2, var=mode, val=dummy-once
   0.000867     [D1] Network UPS Tools version 2.8.2.1827.18-1845-g181d45680 (development iteration after 2.8.2) built with gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 and configured with flags: --enable-Wcolor --enable-warnings --enable-Werror --enable-keep_nut_report_feature --with-all=auto --with-cgi=auto --with-serial=auto --with-dev=auto --with-doc=skip --with-nut_monitor=auto --with-pynut=auto --disable-force-nut-version-header --enable-check-NIT --enable-maintainer-mode --disable-silent-rules --with-debuginfo=auto
   0.000894     [D1:1472330] debug level is '6'
   0.000922     [D5:1472330] send_to_all: SETINFO driver.debug "6"
   0.000946     [D5:1472330] send_to_all: SETFLAGS driver.debug RW NUMBER
   0.001055     [D1:1472330] Can not become_user(nobody): not root initially, remaining UID=1000 GID=1000
   0.001119     [D5:1472330] upsdrvquery_write: write to driver socket: NOBROADCAST

   0.001150     [D5:1472330] upsdrvquery_write: write to driver socket: PING

sock_connect: enabling asynchronous mode (auto)
   0.001200     [D5:1472330] upsdrvquery_prepare: waiting for a while to flush server messages
   0.001244     [D5:1472330] upsdrvquery_read_timeout: tv={sec=3, usec=000000}
   0.001280     [D5:1472330] upsdrvquery_read_timeout: received 5 bytes from driver socket: PONG

   0.001306     [D5:1472330] upsdrvquery_prepare: got expected PONG
   0.001332     [D5:1472330] upsdrvquery_prepare: ready for tracked commands
   0.001342     [D5:1472330] upsdrvquery_write: write to driver socket: SET driver.flag.allow_killpower 1 TRACKING 2DDC5036-F665-4D29-BE4C-0374D091D263

   0.001397     [D5:1472330] upsdrvquery_request: will wait up to 15.000000 sec for response to SET driver.flag.allow_killpower 1

   0.001420     [D5:1472330] upsdrvquery_read_timeout: tv={sec=15, usec=000000}
   0.001483     [D5:1472330] upsdrvquery_read_timeout: received 48 bytes from driver socket: TRACKING 2DDC5036-F665-4D29-BE4C-0374D091D263 0

   0.001511     [D5:1472330] upsdrvquery_request: parsed out command status: 0
   0.001551     [D5:1472330] upsdrvquery_close: closing driver socket, try to say goodbye
   0.001573     [D5:1472330] upsdrvquery_write: write to driver socket: LOGOUT

   0.001602     [D5:1472330] upsdrvquery_close: okay

   1.001768     [D5:1472330] upsdrvquery_write: write to driver socket: NOBROADCAST

   1.001813     [D5:1472330] upsdrvquery_write: write to driver socket: PING

   1.001820     [D5:1472330] upsdrvquery_prepare: waiting for a while to flush server messages
   1.001861     [D5:1472330] upsdrvquery_read_timeout: tv={sec=3, usec=000000}
sock_connect: enabling asynchronous mode (auto)
   2.002259     [D5:1472330] upsdrvquery_read_timeout: received 5 bytes from driver socket: PONG

   2.002465     [D5:1472330] upsdrvquery_prepare: got expected PONG
   2.002502     [D5:1472330] upsdrvquery_prepare: ready for tracked commands
   2.002514     [D5:1472330] upsdrvquery_write: write to driver socket: INSTCMD driver.killpower TRACKING 98C489FD-821C-4132-9D93-4F6590B55E63

Requesting UPS [dummy] to power off, as/if handled by its driver by default (may exit), due to socket protocol request
   2.002618     [D1:1472330] upsdrvquery_request: will wait indefinitely for response to INSTCMD driver.killpower

   2.002657     [D5:1472330] upsdrvquery_read_timeout: tv={sec=-1, usec=-00001} (unlimited timeout)
shutdown not supported
UPS [dummy]: shutdown request was successful with 'shutdown.default'
Signal -2: exiting
   2.002853     [D5:1472330] upsdrvquery_read_timeout: received 48 bytes from driver socket: TRACKING 98C489FD-821C-4132-9D93-4F6590B55E63 0

   2.002869     [D5:1472330] upsdrvquery_request: parsed out command status: 0
   2.002873     [D5:1472330] upsdrvquery_close: closing driver socket, try to say goodbye
   2.002876     [D5:1472330] upsdrvquery_write: write to driver socket: LOGOUT

   2.002914     [D5:1472330] upsdrvquery_close: okay
   3.003085     Request to killpower via running driver returned code 0
   3.003142     [D5:1472330] send_to_all: SETINFO driver.state "cleanup.exit"
   3.003176     [D1:1472330] upsnotify: notify about state NOTIFY_STATE_STOPPING with libsystemd: was requested, but not running as a service unit now, will not spam more about it
   3.003183     [D1:1472330] upsnotify: failed to notify about state NOTIFY_STATE_STOPPING: no notification tech defined, will not spam more about it

Note how the executed driver program reports:

Requesting UPS [dummy] to power off, as/if handled by its driver by default (may exit), due to socket protocol request

...and the backgrounded driver reports:

shutdown not supported
UPS [dummy]: shutdown request was successful with 'shutdown.default'
Signal -2: exiting

@jimklimov
Copy link
Member Author

Checking with signal fallback (thanks to PID file):

:; make check-NIT-sandbox-devel &
# wait until it reports preparedness

:; . /home/jim/nut/tests/NIT/tmp/etc/NIT.env

:; rm -f tests/NIT/tmp/dummy-ups-dummy

:; ./drivers/dummy-ups -a dummy -k -DDDDDD

   0.000002     [D5:1472415] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools 2.8.2.1827.18-1845-g181d45680 (development iteration after 2.8.2) - Device simulation and repeater driver 0.20
   0.000072     [D5:1472415] do_upsconf_args: confupsname=(null), var=maxretry, val=3
   0.000080     [D5:1472415] do_upsconf_args: call do_global_args()
   0.000083     [D3:1472415] do_global_args: var='maxretry' val='3'
   0.000126     [D5:1472415] do_upsconf_args: confupsname=(null), var=driverpath, val=/home/jim/nut/drivers
   0.000136     [D5:1472415] do_upsconf_args: call do_global_args()
   0.000161     [D3:1472415] do_global_args: var='driverpath' val='/home/jim/nut/drivers'
   0.000195     [D5:1472415] do_upsconf_args: confupsname=dummy, var=driver, val=dummy-ups
   0.000217     [D5:1472415] do_upsconf_args: call main_arg()
   0.000222     [D3:1472415] main_arg: var='driver' val='dummy-ups'
   0.000225     [D5:1472415] do_upsconf_args: not a main_arg()
   0.000227     [D5:1472415] do_upsconf_args: this is a 'driver' setting, may we proceed?
   0.000250     [D6:1472415] testval_reloadable: var=driver, oldval=dummy-ups, newval=dummy-ups, reloadable=0, reload_flag=0
   0.000278     [D6:1472415] testval_reloadable: verdict for (re)loading var=driver value: -1
   0.000282     [D5:1472415] do_upsconf_args: 'driver' setting already applied with this value
   0.000306     [D5:1472415] do_upsconf_args: confupsname=dummy, var=desc, val=Crash Dummy
   0.000341     [D5:1472415] do_upsconf_args: call main_arg()
   0.000372     [D3:1472415] main_arg: var='desc' val='Crash Dummy'
   0.000399     [D5:1472415] do_upsconf_args: confupsname=dummy, var=port, val=dummy.seq
   0.000421     [D5:1472415] do_upsconf_args: call main_arg()
   0.000447     [D3:1472415] main_arg: var='port' val='dummy.seq'
   0.000456     [D6:1472415] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=dummy.seq, reloadable=0, reload_flag=0
   0.000476     [D6:1472415] testinfo_reloadable: verdict for (re)loading var=port value: 1
   0.000481     [D5:1472415] send_to_all: SETINFO driver.parameter.port "dummy.seq"
   0.000504     [D5:1472415] do_upsconf_args: confupsname=UPS1, var=driver, val=dummy-ups
   0.000531     [D5:1472415] do_upsconf_args: confupsname=UPS1, var=desc, val=Example event sequence
   0.000554     [D5:1472415] do_upsconf_args: confupsname=UPS1, var=port, val=evolution500.seq
   0.000581     [D5:1472415] do_upsconf_args: confupsname=UPS2, var=driver, val=dummy-ups
   0.000591     [D5:1472415] do_upsconf_args: confupsname=UPS2, var=desc, val=Example ePDU data dump
   0.000613     [D5:1472415] do_upsconf_args: confupsname=UPS2, var=port, val=epdu-managed.dev
   0.000618     [D5:1472415] do_upsconf_args: confupsname=UPS2, var=mode, val=dummy-once
   0.000625     [D1] Network UPS Tools version 2.8.2.1827.18-1845-g181d45680 (development iteration after 2.8.2) built with gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 and configured with flags: --enable-Wcolor --enable-warnings --enable-Werror --enable-keep_nut_report_feature --with-all=auto --with-cgi=auto --with-serial=auto --with-dev=auto --with-doc=skip --with-nut_monitor=auto --with-pynut=auto --disable-force-nut-version-header --enable-check-NIT --enable-maintainer-mode --disable-silent-rules --with-debuginfo=auto
   0.000666     [D1:1472415] debug level is '6'
   0.000673     [D5:1472415] send_to_all: SETINFO driver.debug "6"
   0.000694     [D5:1472415] send_to_all: SETFLAGS driver.debug RW NUMBER
   0.000789     [D1:1472415] Can not become_user(nobody): not root initially, remaining UID=1000 GID=1000
   0.000827     Can't open /home/jim/nut/tests/NIT/tmp/run/dummy-ups-dummy: No such file or directory
   0.000852     [D1:1472415] Socket dialog with the other driver instance: No such file or directory
   0.000878     [D1:1472415] Signalling UPS [dummy]: driver.exit (quietly, no fuss if no driver is running or responding)
   0.000889     Can't open /home/jim/nut/tests/NIT/tmp/run/dummy-ups-dummy: No such file or directory
   0.000911     [D1:1472415] Request for other driver to exit returned code -1
   0.000939     [D1:1472415] Socket dialog with the other driver instance (may be absent) failed: No such file or directory
   0.000965     Duplicate driver instance detected (PID file /home/jim/nut/tests/NIT/tmp/run/dummy-ups-dummy.pid exists)! Terminating other driver!
   0.001030     [D3:1472415] getprocname: /proc is an accessible directory, investigating
   0.001070     [D3:1472415] getprocname: located symlink for PID 1472364 at: /proc/1472364/exe
   0.001104     [D1:1472415] getprocname: determined process name for PID 1472364: /home/jim/nut/drivers/.libs/dummy-ups
   0.001128     [D1:1472415] compareprocname: case-sensitive base name hit for PID 1472364 of '/home/jim/nut/drivers/.libs/dummy-ups'=>'dummy-ups' and checked 'dummy-ups'=>'dummy-ups'
   0.001154     [D1:1472415] Signal sent without errors, allow the other driver instance some time to quit




Signal 15: exiting


Poll UPS [dummy@localhost:12345] failed - Driver not connected
Communications with UPS dummy@localhost:12345 lost
   5.001259     [D1:1472415] PID file /home/jim/nut/tests/NIT/tmp/run/dummy-ups-dummy.pid not found; stat() returned -1: No such file or directory
   5.001298     [D5:1472415] send_to_all: SETINFO device.type "ups"
   5.001326     [D5:1472415] send_to_all: SETINFO driver.state "init.device"
   5.001350     [D2:1472415] Dummy (simulation) mode with a sequence file name pattern (looping infinitely)
   5.001373     [D1:1472415] Dummy (simulation) mode looping infinitely
   5.001381     [D5:1472415] send_to_all: SETINFO driver.parameter.mode "dummy-loop"
   5.001411     [D2:1472415] Located dummy.seq for device simulation data: /home/jim/nut/tests/NIT/tmp/etc/dummy.seq
   5.001435     [D5:1472415] send_to_all: SETINFO driver.state "init.quiet"
   5.001464     [D5:1472415] send_to_all: SETINFO driver.version "2.8.2.1827.18-1845-g181d45680"
   5.001489     [D5:1472415] send_to_all: SETINFO driver.version.internal "0.20"
   5.001494     [D5:1472415] send_to_all: SETINFO driver.name "dummy-ups"
   5.001518     [D5:1472415] send_to_all: SETINFO driver.state "init.info"
   5.001543     [D5:1472415] send_to_all: SETINFO ups.mfr "Dummy Manufacturer"
   5.001568     [D5:1472415] send_to_all: SETFLAGS ups.mfr RW STRING
   5.001572     [D5:1472415] send_to_all: SETAUX ups.mfr 32
   5.001576     [D5:1472415] send_to_all: SETINFO ups.model "Dummy UPS"
   5.001618     [D5:1472415] send_to_all: SETFLAGS ups.model RW STRING
   5.001645     [D5:1472415] send_to_all: SETAUX ups.model 32
   5.001653     [D5:1472415] send_to_all: SETINFO ups.status "OL"
   5.001673     [D5:1472415] send_to_all: SETFLAGS ups.status RW STRING
   5.001678     [D5:1472415] send_to_all: SETAUX ups.status 32
   5.001700     [D1:1472415] entering parse_data_file()
   5.001741     [D3:1472415] parse_data_file: variable "ups.status" with 2 args
   5.001766     [D5:1472415] send_to_all: SETINFO ups.status "OB"
   5.001791     [D1:1472415] suspending execution for 5 seconds...
   5.001815     [D5:1472415] send_to_all: DATAOK
   5.001839     [D5:1472415] send_to_all: ADDCMD load.off
   5.001866     [D5:1472415] send_to_all: ADDCMD shutdown.default
   5.001893     [D5:1472415] send_to_all: SETINFO driver.state "fsd.killpower"
   5.001918     Initiating UPS [dummy] shutdown
   5.001924     [D1:1472415] loop_shutdown_commands: call do_loop_shutdown_commands() with driver-default sdcommands
   5.001946     [D1:1472415] Starting do_loop_shutdown_commands(shutdown.default), call depth 1...
   5.001950     shutdown not supported
   5.001953     [D1:1472415] set_exit_flag: raising exit flag due to signal -1
   5.001977     [D1:1472415] do_loop_shutdown_commands(): command 'shutdown.default' was handled successfully
   5.002014     [D1:1472415] Ending do_loop_shutdown_commands(shutdown.default), call depth 1: return-code 0
   5.002038     UPS [dummy]: shutdown request was successful with 'shutdown.default'
   5.002061     [D1:1472415] set_exit_flag: raising exit flag due to programmatic abort: EXIT_FAILURE
   5.002067     [D5:1472415] send_to_all: SETINFO driver.state "cleanup.upsdrv"
   5.002070     [D5:1472415] send_to_all: SETINFO driver.state "cleanup.exit"
   5.002095     [D1:1472415] upsnotify: notify about state NOTIFY_STATE_STOPPING with libsystemd: was requested, but not running as a service unit now, will not spam more about it
   5.002134     [D1:1472415] upsnotify: failed to notify about state NOTIFY_STATE_STOPPING: no notification tech defined, will not spam more about it

The background driver in this case reports Signal 15: exiting.

@jimklimov
Copy link
Member Author

jimklimov commented Jan 8, 2025

Note: late messages about NOTIFY_STATE_STOPPING from drivername -k might be avoidable, but so far not considered a bug. The "noise" does not happen in non-debug runs, and notifications might be useful when running as a service (e.g. nutshutdown service hook):

:; ./drivers/dummy-ups -a dummy -k
Network UPS Tools 2.8.2.1827.18-1845-g181d45680 (development iteration after 2.8.2) - Device simulation and repeater driver 0.20
sock_connect: enabling asynchronous mode (auto)

sock_connect: enabling asynchronous mode (auto)
Requesting UPS [dummy] to power off, as/if handled by its driver by default (may exit), due to socket protocol request
shutdown not supported
UPS [dummy]: shutdown request was successful with 'shutdown.default'
Signal -2: exiting
Request to killpower via running driver returned code 0

@jimklimov jimklimov merged commit 1a0da2c into networkupstools:master Jan 8, 2025
30 checks passed
@jimklimov jimklimov deleted the issue-2666 branch January 8, 2025 16:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement need testing Code looks reasonable, but the feature would better be tested against hardware or OSes service/daemon start/stop General subject for starting and stopping NUT daemons (drivers, server, monitor); also BG/FG/Debug Windows-not-on-par-with-POSIX Aspect of Windows builds known to be dysfunctional compared to POSIX builds; fix needed to be on par
Projects
None yet
Development

Successfully merging this pull request may close these issues.

NUT 2.8.1-3 "Can't claim USB device [051d:0002]@0/0: Entity not found" using usbhid-ups
1 participant