upssched and other NUT daemons: fix Windows state pipe permissions

[jimklimov]

Generalize the fix from PR #3479, hoping it would help with issue #3525.

CC @mbv06 : a cursory review would be welcome :) Also, as I've just asked in your PR trail - would similar fixes be useful in "client" side of the connections (CreateFile)?

CC @alexdruqn-cpu : when/if Appveyor CI produces a build of this PR (in roughly an hour if all goes well; it should post a link in a comment below), a practical test would be welcome to see if this change impacts the issue you've seen on your system.

[github-actions]

A ZIP file with standard source tarball and another tarball with pre-built docs for commit 3b3145c is temporarily available: NUT-tarballs-PR-3527.zip.

[AppVeyorBot]

✅ Build nut 2.8.5.4920-master completed (commit dd08c4a91c by @jimklimov)

• artifacts
• A 7-zip archive with built NUT for Windows debug binaries is temporarily available: NUT-for-Windows-x86_64-SNAPSHOT-2.8.5.4920-master.7z

[mbv06]

Looks good overall.
Similar changes are not needed on the client side. For CreateFile(..., OPEN_EXISTING, ...), Windows ignores lpSecurityDescriptor when opening an existing object;

CreateFile ignores the lpSecurityDescriptor member when opening an existing file or device, but continues to use the bInheritHandle member.

One security concern is that the NULL DACL allows any client to connect with full access. I think we should at least add PIPE_REJECT_REMOTE_CLIENTS to the dwPipeMode of all affected CreateNamedPipe calls. This would preserve the unrestricted local access required by the compatibility fix while preventing connections via \\host\pipe....

[alexdruqn-cpu]

when/if Appveyor CI produces a build of this PR (in roughly an hour if all goes well; it should post a link in a comment below), a practical test would be welcome to see if this change impacts the issue you've seen on your system.

No, in this version, upsdhed may be running, but I don't see the console output of its messages and I know for sure that as a result, my event handling script C:\NUT\cmd\upssched-cmd.ps1is not executed.
I did not launch nut.exe -N, and just started upsmon.exe -DDDDD

#upsmon.conf
MONITOR testups@192.168.1.1 1 user user secondary
MINSUPPLIES 1
SHUTDOWNCMD "C:\\Windows\\System32\\shutdown.exe /s /t 0 /f"
POLLFREQ 15
POLLFREQALERT 5
HOSTSYNC 15
DEADTIME 15
FINALDELAY 5
POWERDOWNFLAG "C:\\NUT\\killpower"
NOTIFYCMD "C:\\NUT\\sbin\\upssched.exe -DDDDD"
NOTIFYMSG ONLINE	"UPS %s on line power"
NOTIFYMSG ONBATT	"UPS %s on battery"
NOTIFYMSG LOWBATT	"UPS %s battery is low"
NOTIFYFLAG ONLINE EXEC
NOTIFYFLAG ONBATT EXEC
NOTIFYFLAG LOWBATT SYSLOG+WALL

#upssched.conf
CMDSCRIPT "C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\powershell.exe -NoProfile -ExecutionPolicy Bypass -File C:\\NUT\\cmd\\upssched-cmd.ps1"
PIPEFN "\\\\.\\pipe\\upssched"
LOCKFN "C:\\NUT\\upssched.lock"

AT ONBATT * START-TIMER onbatt_shutdown 120
AT ONLINE * CANCEL-TIMER onbatt_shutdown online_returned
AT LOWBATT * EXECUTE lowbatt_shutdown

c:\NUT\sbin>upsmon -DDDDD
Network UPS Tools upsmon 2.8.5.588.4-592+gdd08c4a91 (development iteration after 2.8.5) using a dynamic libnutprivate*
   0.000688     [D3] setproctag: starting first tagging as 'init'...
   0.000869     [D5] setproctag: registered nut_common_atexit(proctag_cleanup)
   0.001050     [D3:libupsclient] setproctag: starting first tagging as 'init'...
   0.001250     [D1:libupsclient:init] upscli_init_default_connect_timeout: upscli_default_connect_timeout=10.000000 sec assigned from: default_secs
   0.001426     [D1:init] Just failed to send signal, no daemon was running
   0.001600     [D1:init] loadconfig: Loading c:\NUT\sbin\..\etc/upsmon.conf
   0.002070     UPS: testups@192.168.1.1 (secondary) (power value 1)
   0.002267     Using power down flag file C:\NUT\killpower
   0.002530     [D1:init] debug level is '5'
   0.002676     [D1:init] will use a shutdown command (SHUTDOWNCMD): 'C:\Windows\System32\shutdown.exe /s /t 0 /f'
   0.002825     [D1:init] will use custom notification command (NOTIFYCMD): 'C:\NUT\sbin\upssched.exe -DDDDD'
   0.003057     [D1:mono] common.c:2198::writepid() : this method was not fully ported for WIN32: may be not applicable to the platform
   0.006195     Init SSL without certificate database
   0.010451     [D1:libupsclient:mono] upscli_init2: completed
   0.010626     [D2:mono] pipe_create: creating NAMED_PIPE (listener): '\\.\pipe\upsmon'
   0.010843     upsnotify: failed to notify about state NOTIFY_STATE_READY_WITH_PID: no notification tech defined, will not spam more about it
   0.010985     [D1:mono] On systems without service units, consider `export NUT_QUIET_INIT_UPSNOTIFY=true`
   0.011141     [D1:mono] Trying to connect to UPS [testups@192.168.1.1]
   0.022994     [D3:libupsclient:mono] upscli_sslinit: Trying to STARTTLS
   0.025245     [D3:libupsclient:mono] upscli_sslinit: STARTTLS not supported or init error: ERR FEATURE-NOT-CONFIGURED
   0.025392     [D3:libupsclient:mono] Can not connect to NUT server 192.168.1.1 in SSL, continue unencrypted
   0.027668     [D1:mono] Logged into UPS testups@192.168.1.1
   0.027813     [D2:mono] pollups: testups@192.168.1.1
   0.027949     [D1:mono] upsmon.c:1216::set_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
   0.028087     [D3:mono] get_var: testups@192.168.1.1 / status
   0.028739     [D3:mono] get_var: testups@192.168.1.1 / buzzword
   0.029448     [D3:mono] get_var: testups@192.168.1.1 / X-buzzword
   0.030144     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
   0.030291     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
   0.030429     [D2:mono] parse_status: [OL]
   0.030566     [D3:mono] parsing: [OL]
   0.030698     [D3:mono] ups_on_line: testups@192.168.1.1 (first time)
   0.030831     [D3:mono] Handled 1 status tokens
   0.030963     [D3:mono] Current power value: 1
   0.031096     [D3:mono] Minimum power value: 1
   0.031228     [D4:mono] Beginning 15-sec delay between main loop cycles
  15.028565     [D4:mono] 15-sec delay between main loop cycles finished, took 14.997295
  .............
 150.109202     [D4:mono] 15-sec delay between main loop cycles finished, took 14.997828
 150.109601     [D2:mono] pollups: testups@192.168.1.1
 150.113062     [D1:mono] upsmon.c:1216::set_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 150.113280     [D3:mono] get_var: testups@192.168.1.1 / status
 150.114637     [D3:mono] get_var: testups@192.168.1.1 / buzzword
 150.115754     [D3:mono] get_var: testups@192.168.1.1 / X-buzzword
 150.116763     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 150.117037     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 150.117349     [D2:mono] parse_status: [OB DISCHRG]
 150.117553     [D3:mono] parsing: [OB]
 150.117749     [D3:mono] ups_on_batt: testups@192.168.1.1 (first time)
 150.117948     [D2:mono] do_notify: ntype 0x0001 (ONBATT)
 150.121016     [D3:mono] do_notify: ntype 0x0001 (ONBATT) finished
 150.121286     [D3:mono] parsing: [DISCHRG]
 150.121575     [D4:mono] Known and ignored status token: [DISCHRG]
 150.121793     [D3:mono] Handled 2 status tokens
 150.122003     [D3:mono] Current power value: 1
 150.122213     [D3:mono] Minimum power value: 1
 150.122451     [D4:mono] Beginning 5-sec delay between main loop cycles
 150.121644     [D4:mono] win_system: calling CreateProcess: C:\NUT\sbin\upssched.exe -DDDDD "UPS testups@192.168.1.1 on battery"
   0.000002     [D2] Remaining argn=5 of argc=3
   0.001017     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   0.003511     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   --- skipped 646 lines
   0.139916     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   0.140054     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
 155.118550     [D4:mono] 5-sec delay between main loop cycles finished, took 4.996066
 155.118834     [D2:mono] pollups: testups@192.168.1.1
 155.120960     [D1:mono] upsmon.c:1216::set_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 155.121123     [D3:mono] get_var: testups@192.168.1.1 / status
 155.122286     [D3:mono] get_var: testups@192.168.1.1 / buzzword
 155.123229     [D3:mono] get_var: testups@192.168.1.1 / X-buzzword
 155.124156     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 155.124388     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 155.124601     [D2:mono] parse_status: [OB DISCHRG]
 155.124755     [D3:mono] parsing: [OB]
 155.124903     [D4:mono] ups_on_batt: testups@192.168.1.1 (no change)
 155.125052     [D3:mono] parsing: [DISCHRG]
 155.125199     [D4:mono] Known and ignored status token: [DISCHRG]
 155.125392     [D3:mono] Handled 2 status tokens
 155.125540     [D3:mono] Current power value: 1
 155.125686     [D3:mono] Minimum power value: 1
 155.125833     [D4:mono] Beginning 5-sec delay between main loop cycles
 160.123587     [D4:mono] 5-sec delay between main loop cycles finished, took 4.997735
 ---------
 200.196749     [D4:mono] 5-sec delay between main loop cycles finished, took 5.005378
 200.197130     [D2:mono] pollups: testups@192.168.1.1
 200.200328     [D1:mono] upsmon.c:1216::set_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 200.200543     [D3:mono] get_var: testups@192.168.1.1 / status
 200.201825     [D3:mono] get_var: testups@192.168.1.1 / buzzword
 200.202945     [D3:mono] get_var: testups@192.168.1.1 / X-buzzword
 200.203985     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 200.204227     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 200.204496     [D2:mono] parse_status: [OL]
 200.204675     [D3:mono] parsing: [OL]
 200.204847     [D3:mono] ups_on_line: testups@192.168.1.1 (first time)
 200.205076     [D2:mono] do_notify: ntype 0x0000 (ONLINE)
 200.205410     [D3:mono] do_notify: ntype 0x0000 (ONLINE) finished
 200.205597     [D3:mono] Handled 1 status tokens
 200.205827     [D3:mono] Current power value: 1
 200.206019     [D3:mono] Minimum power value: 1
 200.206206     [D4:mono] Beginning 15-sec delay between main loop cycles
 200.205831     [D4:mono] win_system: calling CreateProcess: C:\NUT\sbin\upssched.exe -DDDDD "UPS testups@192.168.1.1 on line power"
   0.000002     [D2] Remaining argn=5 of argc=3
   0.001089     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   0.001960     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   ---- skipped 658 lines 
   0.171616     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
   0.171795     [D1] syslog: SKIP: can't open existing event log NAMED_PIPE: '\\.\pipe\nut': No error [═х єфрхЄё  эрщЄш єърчрээ√щ Їрщы. ]
 215.211854     [D4:mono] 15-sec delay between main loop cycles finished, took 15.005610
 215.212246     [D2:mono] pollups: testups@192.168.1.1
 215.215403     [D1:mono] upsmon.c:1216::set_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 215.215655     [D3:mono] get_var: testups@192.168.1.1 / status
 215.216950     [D3:mono] get_var: testups@192.168.1.1 / buzzword
 215.218117     [D3:mono] get_var: testups@192.168.1.1 / X-buzzword
 215.219295     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 215.219597     [D1:mono] upsmon.c:1233::clear_alarm() : this method was not fully ported for WIN32: may be not applicable to the platform
 215.219906     [D2:mono] parse_status: [OL]
 215.220110     [D3:mono] parsing: [OL]
 215.220307     [D4:mono] ups_on_line: testups@192.168.1.1 (no change)
 215.220507     [D3:mono] Handled 1 status tokens
 215.220789     [D3:mono] Current power value: 1
 215.220993     [D3:mono] Minimum power value: 1
 215.221189     [D4:mono] Beginning 15-sec delay between main loop cycles

c:\NUT\sbin>

[jimklimov]

Thanks @alexdruqn-cpu for the logs.

What I think happens here regarding \\.\pipe\nut is that as you did not use nut.exe (which opens that pipe to forward messages into Windows Event Log) the syslog-equivalent shim fails.

I am not sure yet why ...upssched.exe -DDDDD is not getting handled for logging into stderr; should review what this part in main() does (namely if it disables common logging):

        /* normally we don't have stderr, so get this going to syslog early */
        open_syslog(prog);
        syslogbit_set();

I think the tons of syslog attempts do mean that the program tries to post those messages according to log verbosity, even if to the "wrong" channel. I still wonder if exporting NUT_DEBUG_LEVEL or using other means of setting the verbosity (e.g. DEBUG_MIN in upssched.conf) would fare better?..

• UPDATE after second thoughts: Technically speaking, upsdebugx() commands ARE actually handled here in upssched.exe log for stderr, reporting the timestamp of process uptime and the debug verbosity level (the e.g. 0.001089 [D1] prefixes); just that they log practically useless snippets when faced with the syslog errors, I guess. More puzzling is why it does not happen for upsmon.exe proper.

[jimklimov]

This test exposed another flaw, I suppose. I stumbled upon this log entry: Remaining argn=5 of argc=3 and it seems that while main() started with 3 CLI arguments:

• argv[0] = process name C:\NUT\sbin\upssched.exe,
• argv[1] = -DDDDD and
• argv[2] = UPS testups@192.168.1.1 on line power

However then as we parse the command line with getopt() we count the hits to supported optstring, so each D character is accounted as a known option and no unknown options (prefixed by a dash) are seen. Those five D's are accounted as argn=5 which then contributes to some misleading decisions about notify_msg value. This should probably rely on optind instead.

Until this flaw gets fixed, please do use DEBUG_MIN in config file or the envvar.

For other messages, also look up NUT_DEBUG_SYSLOG (envvar) setting which might impact the messages seen in log.

[jimklimov]

Posted a couple of prospective fixes...

[alexdruqn-cpu]

For other messages, also look up NUT_DEBUG_SYSLOG (envvar) setting which might impact the messages seen in log.

Yes, I set the NUT_DEBUG_SYSLOG=stderr environment variable and set the debugging level in the configs. And I started receiving messages in the console from upssched.exe
Also, if I start upsmon using nut.exe -N, upsmon immediately crashes APP CRASH entries in windows eventlog
when starting manually via upsmon.exe the app is working. Behavior upssched.exe exactly the same as the release build - multiple process starts upssched.exe , launching parallel timers for one event and hundreds of user script runs from CMDSCRIPT. It feels like he doesn't see the flag of an already running process and starts repeatedly.

Here is the full log of the nightmare that was happening in the system, the timers eventually went crazy and the station left at some point due to the shutdown event.
console_log.zip

#testups.conf
ups.status: OL
battery.charge: 100
TIMER 120

ups.status: OB
battery.charge: 98
TIMER 45

PS: In the launch option that I gave above (upsmon -DDDDD, upssched.exe -DDDDD), upssched.exe definitely didn't start because I didn't observe six processes upssched.exe and dozens of running my powershell script processes.

[AppVeyorBot]

✅ Build nut 2.8.5.4922-master completed (commit 5e65207f12 by @jimklimov)

• artifacts
• A 7-zip archive with built NUT for Windows debug binaries is temporarily available: NUT-for-Windows-x86_64-SNAPSHOT-2.8.5.4922-master.7z

[AppVeyorBot]

✅ Build nut 2.8.5.4922-master completed (commit 5e65207f12 by @jimklimov)

[AppVeyorBot]

❌ Build nut 2.8.5.4923-master failed (commit ee673f076d by @jimklimov)

• artifacts (if any)

[AppVeyorBot]

❌ Build nut 2.8.5.4923-master failed (commit ee673f076d by @jimklimov)

[jimklimov]

@alexdruqn-cpu : Thanks, I'll try to figure those out. Which Windows version is it? Are there any special group policies, domain settings or other security hardening that might put sticks into wheels, compared to basic systems that Appceyor CI runs on?

@mbv06 : it seems that when I added the flag against remote connections in the last commit, tests failed to run on Appveyor machines at least - can't connect (see latest build's log linked above for details).

[mbv06]

@jimklimov looks like PIPE_REJECT_REMOTE_CLIENTS was added to the wrong CreateNamedPipe argument. It is a dwPipeMode flag, so it should be moved from the second argument to the third one, alongside PIPE_TYPE_*, PIPE_READMODE_*, and PIPE_WAIT.

[alexdruqn-cpu]

@alexdruqn-cpu : Thanks, I'll try to figure those out. Which Windows version is it? Are there any special group policies, domain settings or other security hardening that might put sticks into wheels, compared to basic systems that Appceyor CI runs on?

@jimklimov This is a test computer with a freshly installed system and all current updates. Workgroup, local user with admin priv, no group policies, no other software, except 7z, notepad++, far and etc. Windows 11 IoT LTSC 24H2 (26100.8737)

[jimklimov]

@mbv06 : (facepalm) Thanks! I've misread the https://learn.microsoft.com/en-us/windows/win32/api/winbase/nf-winbase-createnamedpipea as I rushed to post the fix, I guess.

[AppVeyorBot]

✅ Build nut 2.8.5.4924-master completed (commit bd13519795 by @jimklimov)

• artifacts
• A 7-zip archive with built NUT for Windows debug binaries is temporarily available: NUT-for-Windows-x86_64-SNAPSHOT-2.8.5.4924-master.7z

[AppVeyorBot]

✅ Build nut 2.8.5.4924-master completed (commit bd13519795 by @jimklimov)

[jimklimov]

@alexdruqn-cpu : were the logs from your latest post made with the latest build (reported by appveyor just before that report of yours?)

One log file says Network UPS Tools upsmon 2.8.5 release using a dynamic libnutprivate*, and the later (zip log) Network UPS Tools upsmon 2.8.5.588.4-592+gdd08c4a91 (development iteration after 2.8.5) using a dynamic libnutprivate* (dd08c4a being the ephemeral merge-commit of master and original submission of this PR), so I guess that test does not include the later "prospective fixes".

Can you please check if https://ci.appveyor.com/api/buildjobs/93af8njpxkif2wdx/artifacts/NUT-for-Windows-x86_64-SNAPSHOT-2.8.5.4924-master.7z behaves better?

[alexdruqn-cpu]

@jimklimov I've already tried 4924, in a nutshell - it's all the same, multiple timers running and an event parsing script for event transition OL->OB->OL. I'll post the logs tomorrow.

[alexdruqn-cpu]

I can't run this build today - the executable files are not signed and the launch is blocked by windows device guard.

Message          : Code Integrity determined that a process (\Device\HarddiskVolume3\Windows\System32\cmd.exe) attempte
                   d to load \Device\HarddiskVolume3\NUT\sbin\upsmon.exe that did not meet the Enterprise signing level
                    requirements or violated code integrity policy (Policy ID:{0283ac0f-fff1-49ae-ada1-8a933130cad6}).
Message          : Code Integrity determined that a process (\Device\HarddiskVolume3\Windows\System32\cmd.exe) attempte
                   d to load \Device\HarddiskVolume3\NUT\sbin\upsmon.exe that did not meet the Enterprise signing level
                    requirements.
Message          : Code Integrity determined that a process (\Device\HarddiskVolume3\Windows\System32\cmd.exe) attempte
                   d to load \Device\HarddiskVolume3\NUT\sbin\upssched.exe that did not meet the Enterprise signing lev
                   el requirements or violated code integrity policy (Policy ID:{0283ac0f-fff1-49ae-ada1-8a933130cad6})

I don't have time at all right now to figure out how to disable this signature verification on the test machine, so I'll return to the tests and logs next week.

[jimklimov]

Thanks for the update. FWIW, they were never signed, so this bit is not a regression in the CI-built preview archives.

The involvement of "Enterprise guard" however suggests that the system may be set up in some more complicated fashion than the permissive runners in the CI cloud, which might impact visibility of inter-process communication pipes or whatever.

[jimklimov]

Status for now: merging this PR as it should fix situations for which the original concern in #3479 applied. Maybe the situation in #3525 just differs from that.

In any case, if that problem remains in place, we will follow up on the master branch or its subsequent spin-offs for #3525 discussion.

@alexdruqn-cpu : if you would apply these newer post-merge builds to your system, note that now #3499 was also merged, so NOTIFYCMD and CMDSCRIPT must use a separate token (quoted or not) for each program name and argument, e.g.

# obsolete:
NOTIFYCMD "/path/to/notifier -DDDD"

# newly needed:
NOTIFYCMD /path/to/notifier -DDDD
# or quoted if needed for single tokens with white space, e.g.:
NOTIFYCMD "C:/Program Files/NUT/notifier.exe" -DDDD