upsdrvctl start returns before dummy driver is really started

[bigon]

Hello,

In the debian package, we have several tests using the dummy driver.

The dummy driver is started (via the sysV initscript) by the upsdrvctl start command, but for some reasons, it seems that the tests sometimes fail because the dummy driver is not started.

Isn't the driver supposed to be started when upsdrvctl start returns

[jimklimov]

For cross-reference, you can look at tests/NIT/nit.sh which embeds a similar test suite into NUT's make check-NIT (with a configure option to call it from common make check), and helped make a fair amount of improvements.

Failing "sometimes" indicates to me a race condition, perhaps variable lagging under build-time stress. I'd wager that upsdrvctl does complete honestly when the driver was launched, but having the process started does not immediately mean it is talking to upsd. Non-scientifically, a sleep would likely reduce occurrence of errors. Otherwise, a time-limited loop of retries with upsc -l or similar to make sure test proceeds when driver is in fact ready (and as soon as it is, unlike a single fixed sleep).

Note: At the moment #1590 was not addressed - this could help systemd integration complete each driver instance's unit startup when it is actually usable (initialized device data and ready to talk to upsd - not necessarily connected to it though, to avoid dependency cycles for systems who start nut-server only after nut-driver's). PRs are welcome to get it to happen faster :)

BTW, beside bug tracker and script comments saying that "something in NUT upstream systemd changes broke tests, so we quickly change to init-scripts", I found no details on what went different vs. older expectations... hoped to suggest a better fix :)

[jimklimov]

Hello again; just got to try some experiments about this issue and found that although after #1287 / #1036 I can pass debug options to trace start-up of the wrapper program and the driver (to see when the two stages separate), a naive upsdrvctl -DDDDDDd dummy was not helpful since the driver with debug mode by default stayed foreground - so the two never separated ;)

Cleanly, it probably needs an equivalent of #683 to accept and pass the foreground/background CLI options.

For now, will quickly try with a debug_min in the ups.conf and no pass-through of debug options instead.

[jimklimov]

So, that quick try worked, it seems - with dummy-ups backgrounding AND printing debug data :)

So here is the mix of two program logs and nut-server journal in the console, as they came:

root@srv:~# time upsdrvctl -DDDDDD start dummy
Network UPS Tools - UPS driver controller 2.8.0-Windows-58-g326f90866
   0.000000     [D2]
If you're not a NUT core developer, chances are that you're told to enable debugging
to see why a driver isn't working for you. We're sorry for the confusion, but this is
the 'upsdrvctl' wrapper, not the driver you're interested in.

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

Alternately, provide an additional '-d' (lower-case) parameter to 'upsdrvctl' to
pass its current debug level to the launched driver.

   0.000080     [D1] Starting UPS: dummy
   0.000090     [D2] 1 remaining attempts
   0.000094     [D2] exec:  /usr/local/ups/bin/dummy-ups -a dummy
Network UPS Tools - Device simulation and repeater driver 0.15 (2.8.0-Windows-58-g326f90866)
   0.000000     [D1] debug level is '6'
   0.000468     [D1] Succeeded to become_user(nut): now UID=77 GID=77
   0.000576     [D1] Saving PID 3097982 into /var/state/ups/dummy-ups-dummy.pid
   0.000604     [D5] send_to_all: SETINFO device.type "ups"
   0.000611     [D2] Dummy (simulation) mode with a device data dump file name pattern (read once)
   0.000618     [D1] Dummy (simulation) mode using data read once
   0.000622     [D5] send_to_all: SETINFO driver.parameter.mode "dummy-once"
   0.000628     [D2] Can't open dummy.dev currently
   0.000632     [D5] send_to_all: SETINFO driver.version "2.8.0-Windows-58-g326f90866"
   0.000636     [D5] send_to_all: SETINFO driver.version.internal "0.15"
   0.000639     [D5] send_to_all: SETINFO driver.name "dummy-ups"
   0.000643     [D5] send_to_all: SETINFO ups.mfr "Dummy Manufacturer"
   0.000647     [D5] send_to_all: SETFLAGS ups.mfr RW STRING
   0.000650     [D5] send_to_all: SETAUX ups.mfr 32
   0.000654     [D5] send_to_all: SETINFO ups.model "Dummy UPS"
   0.000657     [D5] send_to_all: SETFLAGS ups.model RW STRING
   0.000661     [D5] send_to_all: SETAUX ups.model 32
   0.000664     [D5] send_to_all: SETINFO ups.status "OL"
   0.000668     [D5] send_to_all: SETFLAGS ups.status RW STRING
   0.000671     [D5] send_to_all: SETAUX ups.status 32
   0.000675     [D1] entering parse_data_file()
   0.000701     [D3] parse_data_file: variable "battery.date" with 2 args
   0.000705     [D2] entering setvar(battery.date, 2020-12-01)
   0.000709     [D2] find_info: unknown variable: battery.date

   0.000712     [D1] Unknown data. Committing anyway...
   0.000716     [D2] find_info: unknown variable: battery.date

   0.000719     [D1] Unknown data. Committing value anyway...
   0.000723     [D5] send_to_all: SETINFO battery.date "2020-12-01"
   0.000726     [D2] find_info: unknown variable: battery.date

   0.000730     [D2] setvar: unknown variable (battery.date), using default flags
   0.000737     [D5] send_to_all: SETFLAGS battery.date RW STRING
   0.000740     [D5] send_to_all: SETAUX battery.date 32
   0.000744     [D3] parse_data_file: added "battery.date" with value "2020-12-01"
   0.000748     [D1] suspending execution for 60 seconds...
   0.000751     [D5] send_to_all: DATAOK
   0.000755     [D5] send_to_all: ADDCMD load.off
   0.000757     [D1] upsdrv_updateinfo...

   1.000826     [D1] entering parse_data_file()
   1.000846     [D1] leaving (paused)...
   1.000987     [D2] dstate_init: sock /var/state/ups/dummy-ups-dummy open on fd 5
   1.000997     [D5] send_to_all: SETINFO driver.parameter.pollinterval "2"
   1.001002     [D5] send_to_all: SETINFO driver.parameter.synchronous "auto"
   1.001006     [D5] send_to_all: SETINFO device.mfr "Dummy Manufacturer"
   1.001013     [D5] send_to_all: SETINFO device.model "Dummy UPS"

real    0m1.003s
user    0m0.002s
sys     0m0.001s

root@srv:~#
root@srv:~# 
Jan 02 14:27:05 srv nut-server[2055866]: Connected to UPS [dummy]: dummy-ups-dummy
Jan 02 14:27:05 srv upsd[2055866]: Connected to UPS [dummy]: dummy-ups-dummy

So it seems that upsdrvctl quietly returned to terminal only after those send_to_all's...

[jimklimov]

While at it, discovered #1753

[jimklimov]

With nowait option I do see upsdrvctl return almost immediately, and first dummy-ups log lines appear after that. But for some reason, a PID file does not appear making it cumbersome to kill the driver :)

[jimklimov]

As a data point, the original problem persists - according to https://ci.debian.net/packages/n/nut/unstable/armel/ there were several fails of this same sort (and several successes generally) with 2.8.0-2 and 2.8.0-5 package builds.

As a New Year's present, a 2.8.0-6 recipe was posted according to https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1023530 but did not yet show up on that platform. However on some others in https://ci.debian.net/packages/n/nut/ matrix it also failed similarly :(

So a longer sleep in https://salsa.debian.org/debian/nut/-/commit/a009ca10a327d7db383f5d7726091050ceb4d60f did not help...

@bigon : did you have luck reproducing the CI build (and failures) locally? In particular then, could you determine if dummy-ups just took time to start (appeared too late, per premise of this issue), or if it completely failed to start or crashed? Maybe worth adding debug_min settings into the script (for driver sections) so CI logs would say more.

Looking at https://salsa.debian.org/debian/nut/-/blob/a009ca10a327d7db383f5d7726091050ceb4d60f/debian/tests/test-nut.py#L232 I first wanted to suggest moving the kill-block to before you unlink/restore configs, and now I wonder if the system under test also runs nut-driver-enumerator path unit by default, and so there is a conflict between NDE detecting config file changes and so restarting services and your test script doing the same?

[jimklimov]

So... while looking at several related issues/RFEs about driver startup, I found that by the time the driver process forks to be backgrounded (unless it chooses not to - and then upsdrvctl is stuck tracking this child forever) at

nut/drivers/main.c

Line 1145 in e28acf8

if (background_flag != 0) {

it should have already completed driver-defined initialization and first data walk at

nut/drivers/main.c

Lines 1024 to 1028 in e28acf8

	/* get the base data established before allowing connections */
	upsdrv_initinfo();
	upsdrv_updateinfo();

Now I am a bit more convinced about the previously posted idea, that in your test environment there may be a race of different mechanisms that restart NUT drivers (e.g. systemd nut-driver-enumerator.service and .path registered by the package, vs. init-script approach of the tests).

[jimklimov]

Also note recent work in #1762 and #1771, and #1777 inspired or nudged by this ticket :)

[jimklimov]

@bigon : bump, any feedback on this? :)

[jimklimov]

Bump?

[jimklimov]

@bigon : I intend to close this issue as a "can't reproduce" sort of situation, at least with "vanilla" NUT. As discussed earlier, this ticket overall led to addition of more live debugging/troubleshooting/config-reloading facilities to the drivers, so that's a good thing and may help with your future investigations if the issue keeps biting Debian QA tests, but IIRC my take on it was either a race condition outside of NUT's control plane, or a race of NUT's NDE script/service picking up config file editions vs. what your test scripts do assuming it is their dedicated sandbox (disable NDE to make it one... or even have two test suites, to be sure NDE does work there too).