<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<p>Hi Jim<br>
<br>
and thank's a lot for this "fun exploration".<br>
<br>
i have change all stars by UPS1@localhost in my
/etc/nut/upssched.conf<br>
<br>
But nothing better for wrong NOTIFYTYPE.<br>
<br>
TIMER intiated by ONLINE process continue to receive "ONBATT" env
value by NOTIFYTYPE var.<br>
<br>
<span style="font-family:monospace"><span
style="color:#000000;background-color:#ffffff;">Apr 22
08:22:00 brisefer upsmon[1613670]: Onduleur UPS1@localhost en
mode Secours sur batterie
</span><br>
Apr 22 08:22:00 brisefer upssched[1854124]: Executing command:
ONBATT
<br>
Apr 22 08:22:00 brisefer upssched-cmd-received-NOTIFYTYPE:
ONBATT
<br>
Apr 22 08:22:00 brisefer upssched-cmd-read-Upsc_ups_status: OB
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: Timer daemon started
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-5 (300 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-10 (600 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-15 (900 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-20 (1200 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-25 (1500 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-30 (1800 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-60 (3600 seconds)
<br>
Apr 22 08:22:00 brisefer upssched[1854156]: New timer:
BATT-STATUS-120 (7200 seconds)
<br>
Apr 22 08:22:55 brisefer upsmon[1613670]: Onduleur
UPS1@localhost en mode Secteur : recharge batterie en cours
<br>
Apr 22 08:22:55 brisefer upssched[1854183]: Executing command:
ONLINE
<br>
Apr 22 08:22:55 brisefer upssched-cmd-received-NOTIFYTYPE:
ONLINE
<br>
Apr 22 08:22:55 brisefer upssched-cmd-read-Upsc_ups_status: OL
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-5
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-10
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-15
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-20
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-25
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-30
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-60
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: Cancelling timer:
BATT-STATUS-120
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: New timer:
LINE-STATUS-5 (300 seconds)
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: New timer:
LINE-STATUS-60 (3600 seconds)
<br>
Apr 22 08:22:55 brisefer upssched[1854156]: New timer:
LINE-STATUS-120 (7200 seconds)
<br>
Apr 22 08:27:55 brisefer upssched[1854156]: Event: LINE-STATUS-5
<br>
Apr 22 08:27:55 brisefer upssched-cmd-received-NOTIFYTYPE:
ONBATT
<br>
Apr 22 08:27:55 brisefer upssched-cmd-read-Upsc_ups_status: OL
<br>
Apr 22 09:22:55 brisefer upssched[1854156]: Event:
LINE-STATUS-60 <br>
Apr 22 09:22:55 brisefer upssched-cmd-received-NOTIFYTYPE:
ONBATT
<br>
Apr 22 09:22:55 brisefer upssched-cmd-read-Upsc_ups_status: OL
<br>
Apr 22 10:22:55 brisefer upssched[1854156]: Event:
LINE-STATUS-120 <br>
Apr 22 10:22:55 brisefer upssched-cmd-received-NOTIFYTYPE:
ONBATT
<br>
Apr 22 10:22:55 brisefer upssched-cmd-read-Upsc_ups_status: OL
<br>
Apr 22 10:23:10 brisefer upssched[1854156]: Timer queue empty,
exiting<br>
<br>
My script upssched-cmd script now don't use NOTIFYTYPE as good
information. It's working and all messages are OK<br>
<br>
thank's</span></p>
<p><span style="font-family:monospace">Rémi</span></p>
<p><span style="font-family:monospace"><br>
</span></p>
<div class="moz-cite-prefix">Le 11/04/2025 à 16:09, Jim Klimov a
écrit :<br>
</div>
<blockquote type="cite"
cite="mid:CAJYg8vJ+eCOgOMj6XzTxbP4KKfTFeTSa14a0s5HjqvOpr2RAQQ@mail.gmail.com">
<meta http-equiv="content-type" content="text/html; charset=UTF-8">
<div dir="ltr">
<div>So, I've done some experiments, also integrating upssched
into NIT (NUT Integration Testing) suite, to help automate the
setup and debugging - that aspect can be seen in <a
href="https://github.com/jimklimov/nut/tree/issue-2890"
moz-do-not-send="true" class="moz-txt-link-freetext">https://github.com/jimklimov/nut/tree/issue-2890</a>
(also investigating for <a
href="https://github.com/networkupstools/nut/issues/2890"
moz-do-not-send="true" class="moz-txt-link-freetext">https://github.com/networkupstools/nut/issues/2890</a>
that also touches on upssched).</div>
<div><br>
</div>
<div>My current conclusion is that `setenv("NOTIFYTYPE")` only
happens when `upsmon` calls whatever it has as the `NOTIFYCMD`
handler. It is a new process every time it is called, and when
the handler is a script or other short-lived program, it
indeed sees the current unique value of NOTIFYTYPE (and
UPSNAME, and "other CLI args" that convey the message for
notification).</div>
<div><br>
</div>
<div>However in case of upssched, the first call to
create/cancel timers launches a daemon (to track timer states
and execute `CMDSCRIPT` when timers elapse). Subsequent calls
to `upssched` as a CLI program talk to this daemon via pipe,
to inform it of state changes for `START-TIMER` and
`CANCEL-TIMER` matches, e.g.:</div>
<div><br>
</div>
<div>UPS dummy@localhost:12345 on battery<br>
Fri Apr 11 13:40:09 UTC 2025:
/home/jim/nut/scripts/misc/notifyme-debug ONBATT
[dummy@localhost:12345]: args: UPS
dummy@localhost:12345 on battery (1 arg tokens)<br>
Defaulting debug verbosity to NUT_DEBUG_LEVEL=3 since none was
requested by command-line options<br>
0.000081 [D2:7688] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.000129 [D1:7688] parse_at: this AT command is for a
wildcard: matched<br>
0.000171 [D1:7688] parse_at: SKIP: 'ONLINE' in AT
command did not match the 'ONBATT' NOTIFYTYPE we were launched
to process<br>
...</div>
<div> 0.001165 [D1:7688] parse_at: this AT command is for
a wildcard: matched<br>
0.001172 [D1:7688] parse_at: processing EXECUTE<br>
0.001193 Executing command: ONBATT<br>
Fri Apr 11 13:40:09 UTC 2025:
/home/jim/nut/clients/upssched-cmd: THIS IS A SAMPLE SCRIPT,
PLEASE TAILOR IT FOR YOUR DEPLOYMENT OF NUT!<br>
Fri Apr 11 13:40:09 UTC 2025: UPSNAME='dummy@localhost:12345'
NOTIFYTYPE='ONBATT' args=ONBATT<br>
0.009687 [D2:7688] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.009719 [D1:7688] parse_at: this AT command is for a
wildcard: matched<br>
0.009751 [D1:7688] parse_at: processing CANCEL-TIMER<br>
25.037157 [D3:7373] new connection on fd 16<br>
25.037214 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
25.037238 [D3:7373] arg 0: CANCEL<br>
25.037243 [D3:7373] arg 1: LINE-STATUS-1s</div>
<div>...</div>
<div> 0.019160 [D2:7688] parse_at: is '*' in AT command
the 'dummy@localhost:12345' we were launched to process?<br>
0.019190 [D1:7688] parse_at: this AT command is for a
wildcard: matched<br>
0.019196 [D1:7688] parse_at: processing START-TIMER<br>
25.046606 [D3:7373] closing connection on fd 16<br>
25.046647 [D3:7373] new connection on fd 16<br>
25.046706 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
25.046729 [D3:7373] arg 0: START<br>
25.046734 [D3:7373] arg 1: BATT-STATUS-60<br>
25.046757 [D3:7373] arg 2: 3600<br>
25.046780 New timer: BATT-STATUS-60 (3600 seconds)<br>
0.019597 [D2:7688] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.019622 [D1:7688] parse_at: this AT command is for a
wildcard: matched<br>
0.019627 [D1:7688] parse_at: SKIP: 'REPLBATT' in AT
command did not match the 'ONBATT' NOTIFYTYPE we were launched
to process</div>
<div><br>
</div>
<div>Note the 25-sec timestamps of the daemon, and 0.x sec
timestamps of the client that reacts to a new ONBATT event.</div>
<div><br>
</div>
<div>The `upssched` code, its infinite-looping daemon included,
never calls `setenv()`. So all runs of a `CMDSCRIPT` inherit
the environment exported for the first run of `upssched` when
it created the daemon, including the original and static value
of `NOTIFYTYPE`.</div>
<div><br>
</div>
<div>The `upssched` CLI program directly runs the `CMDSCRIPT`
when an `AT ... EXECUTE ...` line is matched, however --
including the `NOTIFYTYPE` relevant at this moment, as seen in
the third report from `
upssched-cmd`
script below:</div>
<div><br>
</div>
<div> 25.047059 [D3:7373] closing connection on fd 16<br>
0.019795 [D2:7688] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.019818 [D1:7688] parse_at: this AT command is for a
wildcard: matched<br>
0.019842 [D1:7688] parse_at: SKIP: 'COMMBAD' in AT
command did not match the 'ONBATT' NOTIFYTYPE we were launched
to process<br>
0.019858 [D1:7688] Exiting upssched (CLI process)<br>
26.048227 Event: BATT-STATUS-1s<br>
Fri Apr 11 13:40:10 UTC 2025:
/home/jim/nut/clients/upssched-cmd: THIS IS A SAMPLE SCRIPT,
PLEASE TAILOR IT FOR YOUR DEPLOYMENT OF NUT!<br>
Fri Apr 11 13:40:10 UTC 2025: UPSNAME='dummy@localhost:12345'
NOTIFYTYPE='ONBATT' args=BATT-STATUS-1s<br>
27.061667 Event: BATT-STATUS-2s<br>
Fri Apr 11 13:40:11 UTC 2025:
/home/jim/nut/clients/upssched-cmd: THIS IS A SAMPLE SCRIPT,
PLEASE TAILOR IT FOR YOUR DEPLOYMENT OF NUT!<br>
Fri Apr 11 13:40:11 UTC 2025: UPSNAME='dummy@localhost:12345'
NOTIFYTYPE='ONBATT' args=BATT-STATUS-2s<br>
UPS dummy@localhost:12345 on line power<br>
Fri Apr 11 13:40:14 UTC 2025:
/home/jim/nut/scripts/misc/notifyme-debug ONLINE
[dummy@localhost:12345]: args: UPS
dummy@localhost:12345 on line power (1 arg tokens)<br>
Defaulting debug verbosity to NUT_DEBUG_LEVEL=3 since none was
requested by command-line options<br>
0.000068 [D2:7720] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.000109 [D1:7720] parse_at: this AT command is for a
wildcard: matched<br>
0.000138 [D1:7720] parse_at: processing EXECUTE<br>
0.000143 Executing command: ONLINE<br>
Fri Apr 11 13:40:14 UTC 2025:
/home/jim/nut/clients/upssched-cmd: THIS IS A SAMPLE SCRIPT,
PLEASE TAILOR IT FOR YOUR DEPLOYMENT OF NUT!<br>
Fri Apr 11 13:40:14 UTC 2025: UPSNAME='dummy@localhost:12345'
NOTIFYTYPE='ONLINE' args=ONLINE<br>
0.011340 [D2:7720] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.011389 [D1:7720] parse_at: this AT command is for a
wildcard: matched<br>
0.011398 [D1:7720] parse_at: processing CANCEL-TIMER<br>
30.042455 [D3:7373] new connection on fd 16<br>
30.042490 Event: BATT-STATUS-5s<br>
Fri Apr 11 13:40:14 UTC 2025:
/home/jim/nut/clients/upssched-cmd: THIS IS A SAMPLE SCRIPT,
PLEASE TAILOR IT FOR YOUR DEPLOYMENT OF NUT!<br>
Fri Apr 11 13:40:14 UTC 2025: UPSNAME='dummy@localhost:12345'
NOTIFYTYPE='ONBATT' args=BATT-STATUS-5s<br>
30.051445 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
30.051489 [D3:7373] arg 0: CANCEL<br>
30.051496 [D3:7373] arg 1: BATT-STATUS-1s</div>
<div><br>
</div>
<div>It seems that sometimes timer calls can happen before they
get the cancel signal (processing the list and calling the
commands can take a while), note the jump from 27.x to 30.x
seconds and call to handle BATT-STATUS-5s
even though we are already processing cancellation of
BATT-STATUS-1s and would likely get to cancel 5s in a moment.</div>
<div><br>
</div>
<div>...</div>
<div> 0.020701 [D2:7720] parse_at: is '*' in AT command
the 'dummy@localhost:12345' we were launched to process?<br>
0.020727 [D1:7720] parse_at: this AT command is for a
wildcard: matched<br>
0.020733 [D1:7720] parse_at: processing CANCEL-TIMER<br>
30.051843 [D3:7373] closing connection on fd 16<br>
30.051897 [D3:7373] new connection on fd 16<br>
30.051963 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
30.051992 [D3:7373] arg 0: CANCEL<br>
30.052021 [D3:7373] arg 1: BATT-STATUS-2s<br>
0.021220 [D2:7720] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.021250 [D1:7720] parse_at: this AT command is for a
wildcard: matched<br>
0.021290 [D1:7720] parse_at: processing CANCEL-TIMER<br>
30.052299 [D3:7373] closing connection on fd 16<br>
30.052340 [D3:7373] new connection on fd 16<br>
30.052392 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
30.052415 [D3:7373] arg 0: CANCEL<br>
30.052420 [D3:7373] arg 1: BATT-STATUS-5s<br>
0.021601 [D2:7720] parse_at: is '*' in AT command the
'dummy@localhost:12345' we were launched to process?<br>
0.021626 [D1:7720] parse_at: this AT command is for a
wildcard: matched<br>
0.021631 [D1:7720] parse_at: processing CANCEL-TIMER<br>
30.052685 [D3:7373] closing connection on fd 16<br>
30.052727 [D3:7373] new connection on fd 16<br>
30.052781 [D3:7373] Ending sock_read() on a good note:
try to use command:<br>
30.052804 [D3:7373] arg 0: CANCEL<br>
30.052810 [D3:7373] arg 1: BATT-STATUS-15s<br>
30.052831 Cancelling timer: BATT-STATUS-15s</div>
<div>...</div>
<div><br>
</div>
<div>Ultimately, what should matter for the `CMDSCRIPT` are its
command-line arguments (technically, the first and only one).
That alone dictates the operation it should run, regardless of
the UPSNAME or NOTIFYTYPE values. It would probably be correct
to unset those variables in the loop at least, or in the tool
overall (to not imply any guarantees of anything related to
those strings).</div>
<div><br>
</div>
<div>If timers or executions relate to a particular UPS, name it
in the `AT` line spec (instead of the asterisk) and track as
an uniquely named timer to start or cancel.</div>
<div><br>
</div>
<div>That was a fun exploration, thanks for the nudge!</div>
<div><br>
</div>
<div>Jim Klimov</div>
<div><br>
</div>
<div><br>
</div>
</div>
<br>
<div class="gmail_quote gmail_quote_container">
<div dir="ltr" class="gmail_attr">On Tue, Apr 8, 2025 at
10:59 AM RemiG <<a
href="mailto:mailing-nut@dbmtechnologies.com"
moz-do-not-send="true" class="moz-txt-link-freetext">mailing-nut@dbmtechnologies.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote" style="margin:0px 0px 0px
0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<div>
<p><font face="monospace">Hi for all<br>
<br>
an other one with same wrong NOTIFYTYPE (my supposition)
(</font><font face="monospace"><span
style="font-family:monospace"><span
style="color:rgb(0,0,0);background-color:rgb(255,255,255)">ups.mfr:
EATON, </span>ups.model: Ellipse PRO 1600)<br>
</span><br>
upsmon says NOTIFYTYPE = ONBATT</font></p>
<p><font face="monospace">upssched create a time associated
to this Event => BATT-STATUS-5 (but Power return
before 5 minutes ;-) so ... )<br>
upsmon says NOTIFYTYPE = ONLINE</font></p>
<p> </p>
<p><font face="monospace">upssched.conf delete this Event
=> BATT-STATUS-5, </font><font face="monospace"><font
face="monospace">BATT-STATUS-10</font></font></p>
<p><font face="monospace">upssched create a TIMER associated
to this Event => LINE-STATUS-5 and so on<br>
<br>
</font></p>
<p><font face="monospace">and after all other timers created
by ONLINE => LINE-STATUS-5, LINE-STATUS-10</font></p>
<p><font face="monospace">sent ENV var NOTIFYTYPE to
/bin/upssched-cmd bash script => ONBATT (but upsc
UPS@localhost read ups.status : OL CHRG )</font></p>
<p><font face="monospace"><br>
</font></p>
<p><font face="monospace">Isn't it strange ONBATT / OL CHGR<br>
</font></p>
<p><font face="monospace"><span
style="color:rgb(0,0,0);background-color:rgb(255,255,255)">root@greg:~#
grep " ups" /var/log/syslog </span><br>
Apr 8 10:07:33 greg upsmon[32507]: Onduleur
UPS1@localhost en mode Secours sur batterie <br>
Apr 8 10:07:33 greg upssched[17464]: Executing command:
ONBATT <br>
Apr 8 10:07:34 greg upssched-cmd-received-NOTIFYTYPE:
ONBATT <br>
Apr 8 10:07:34 greg upssched-cmd-read-Upsc_ups_status:
OB DISCHRG <br>
Apr 8 10:07:34 greg upssched[17497]: Timer daemon
started <br>
Apr 8 10:07:34 greg upssched[17497]: New timer:
BATT-STATUS-5 (300 seconds) <br>
Apr 8 10:07:34 greg upssched[17497]: New timer:
BATT-STATUS-10 (600 seconds) <br>
Apr 8 10:08:03 greg upsmon[32507]: Onduleur
UPS1@localhost en mode Secteur : recharge batterie en
cours <br>
Apr 8 10:08:03 greg upssched[17516]: Executing command:
ONLINE <br>
Apr 8 10:08:03 greg upssched-cmd-received-NOTIFYTYPE:
ONLINE <br>
Apr 8 10:08:03 greg upssched-cmd-read-Upsc_ups_status:
OL CHRG <br>
Apr 8 10:08:04 greg upssched[17497]: Cancelling timer:
BATT-STATUS-5 <br>
Apr 8 10:08:04 greg upssched[17497]: Cancelling timer:
BATT-STATUS-10 <br>
Apr 8 10:08:04 greg upssched[17497]: New timer:
LINE-STATUS-5 (300 seconds) <br>
Apr 8 10:08:04 greg upssched[17497]: New timer:
LINE-STATUS-10 (600 seconds) <br>
</font><span style="font-family:monospace"><span
style="font-family:monospace"><span
style="color:rgb(0,0,0);background-color:rgb(255,255,255)">Apr
8 10:13:04 greg upssched[17497]: Event:
LINE-STATUS-5 </span><br>
Apr 8 10:13:04 greg upssched-cmd-received-NOTIFYTYPE:
ONBATT <br>
Apr 8 10:13:04 greg
upssched-cmd-read-Upsc_ups_status: OL CHRG <br>
Apr 8 10:18:04 greg upssched[17497]: Event:
LINE-STATUS-10 <br>
Apr 8 10:18:05 greg upssched-cmd-received-NOTIFYTYPE:
ONBATT <br>
Apr 8 10:18:05 greg
upssched-cmd-read-Upsc_ups_status: OL CHRG<br>
</span></span>-- </p>
<blockquote type="cite">
<div class="gmail_quote">
<blockquote class="gmail_quote" style="margin:0px 0px
0px 0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div>
<pre cols="72"># admin linux only ;-)</pre>
</div>
_______________________________________________<br>
Nut-upsuser mailing list<br>
<a href="mailto:Nut-upsuser@alioth-lists.debian.net"
target="_blank" moz-do-not-send="true"
class="moz-txt-link-freetext">Nut-upsuser@alioth-lists.debian.net</a><br>
<a
href="https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser"
rel="noreferrer" target="_blank"
moz-do-not-send="true" class="moz-txt-link-freetext">https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser</a><br>
</blockquote>
</div>
</blockquote>
<pre cols="72">--
# admin linux only ;-)</pre>
</div>
</blockquote>
</div>
</blockquote>
<pre class="moz-signature" cols="72">--
# admin linux only ;-)</pre>
</body>
</html>