Skip to content

Conversation

jimklimov
Copy link
Member

@jimklimov jimklimov commented May 15, 2025

Follows up from #2955 to consistently log instant command and variable setting, so drivers differ less for end-user experience.

Previously all drivers tended to do this differently, which made troubleshooting harder. Now they would all follow the same logic and message structure, at least in broad strokes, and specifically would try to upslog*() => syslog any operations that can impact power delivery to the useful load. So if a system crashes with a self-inflicted power outage, there's a chance it would have already recorded why.

While here, also identified some cases where upslog*() methods' first argument was a number, not a syslog macro name. Probably some time ago someone could not choose between upslogx() and upsdebugx()?..

NOTE: Code of these methods is peppered with TODO/FIXME comments regarding cleaner use of return codes (INVALID/UNKNOWN/FAILED/...) where apparently some reply types in headers and dstate (and data server side) appeared later than these methods. This was largely ignored and may be a focus of another PR eventually; some more such comments were added where the current responses seemed imperfect, however this was on a best-effort basis when something caught my eye, so probably some similar cases were missed.

jimklimov added 10 commits May 15, 2025 09:59
…evel instead of a syslog macro

Signed-off-by: Jim Klimov <[email protected]>
…evel definitions and message wording for beginning and failing instcmd() or setvar() consistently in different drivers

Signed-off-by: Jim Klimov <[email protected]>
…ing macros

Testing:

    :; NUT_STATEPATH=/tmp ./drivers/dummy-ups -DDDDDD -s test -x port= &
    :; (echo NOBROADCAST ; echo "INSTCMD qqq" ; sleep 3 ; echo "INSTCMD qqq arg" ; sleep 3 ; echo "SET qqq" ; sleep 3 ; echo "SET qqq 123" ; sleep 10; ) | ./server/sockdebug /tmp/dummy-ups-test

Outputs:

   8.003940     [D6] sock_arg: Driver on /tmp/dummy-ups-test is now handling INSTCMD with 2 args
   8.003974     [D2] entering main_instcmd(qqq, (null)) for [test] on socket 5
   8.003982     [D2] shared main_instcmd() does not handle command qqq, proceeding to driver-specific handler
   8.004017     [D1] Starting dummy-ups.c::instcmd('qqq', '(null)')
   8.004049     instcmd: unknown command [qqq] [(null)]

   8.004059     [D6] sock_arg: Driver on /tmp/dummy-ups-test is now handling INSTCMD with 3 args
   8.004068     [D2] entering main_instcmd(qqq, arg) for [test] on socket 5
   8.004075     [D2] shared main_instcmd() does not handle command qqq, proceeding to driver-specific handler
   8.004080     [D1] Starting dummy-ups.c::instcmd('qqq', 'arg')
   8.004086     instcmd: unknown command [qqq] [arg]

(apparently the two got coalesced by delay between main.c loops)

   11.504627    [D6] sock_arg: Driver on /tmp/dummy-ups-test is now handling SET with 2 args
   11.504669    Unknown command on socket:
   11.504675    arg 0: SET
   11.504678    arg 1: qqq

(SET must have an argument)

   14.004807    [D6] sock_arg: Driver on /tmp/dummy-ups-test is now handling SET with 3 args
   14.004856    [D2] entering main_setvar(qqq, 123) for [test] on socket 5
   14.004867    [D2] shared main_setvar() does not handle variable qqq, proceeding to driver-specific handler
   14.004874    [D1] Starting dummy-ups.c::setvar('qqq', '123')
   14.004930    [D2] find_info: unknown variable: qqq
   14.004979    [D1] Unknown data. Committing anyway...
   14.004992    [D2] find_info: unknown variable: qqq
   14.004997    [D1] Unknown data. Committing value anyway...
   14.005062    [D5] send_to_all: SETINFO qqq "123"
   14.005113    [D2] find_info: unknown variable: qqq
   14.005125    [D2] setvar: unknown variable (qqq), using default flags
   14.005133    [D5] send_to_all: SETFLAGS qqq RW STRING
   14.005144    [D5] send_to_all: SETAUX qqq 32

Signed-off-by: Jim Klimov <[email protected]>
…lents to be consistent across all drivers [WIP]

Signed-off-by: Jim Klimov <[email protected]>
…nd LOG_INSTCMD_POWERSTATE level

Signed-off-by: Jim Klimov <[email protected]>
…CMD_POWERSTATE*() macros shine

Signed-off-by: Jim Klimov <[email protected]>
@jimklimov jimklimov added this to the 2.8.4 milestone May 15, 2025
@jimklimov jimklimov added enhancement Shutdowns and overrides and battery level triggers Issues and PRs about system shutdown, especially if battery charge/runtime remaining is involved labels May 15, 2025
@desertwitch
Copy link
Contributor

Maybe also worth adding to the developer documents in docs/ to have a common ground on this written down somewhere.

@jimklimov
Copy link
Member Author

I gave this a bit of thought, and maybe better hand off the docs part (perhaps to you, if volunteering) so it would also serve as a review with separate eyeballs :)

IIRC the sddefault approach added for 2.8.3 could be also un(der)-documented...

@desertwitch
Copy link
Contributor

Sure, I hope I'll have time at the weekend to look through it and come up with something.

@jimklimov
Copy link
Member Author

Superb, thanks!

jimklimov added 6 commits May 16, 2025 12:16
…SB loops, do not go for NUT_UNMAPPED_VARIANT either

Signed-off-by: Jim Klimov <[email protected]>
… would refuse printf("%s",NULL) if warnings are enabled (so NUT_STRARG must be enabled if auto)

Signed-off-by: Jim Klimov <[email protected]>
… deliver its doc either"

This reverts commit 7a2e5d7:
the doc is part of qa-guide. Makes more sense to also dist the script instead.
@jimklimov jimklimov merged commit 8f4340a into networkupstools:master May 18, 2025
20 of 23 checks passed
@jimklimov jimklimov deleted the instcmd-setvar-brushup branch May 18, 2025 13:21
@desertwitch
Copy link
Contributor

I'm afraid I'm a bit lost here still, so from my understanding this standardises the debug and error levels to use common severities within instcmd and setvar? So developers should use these instead of randomly picking a debug severity of say 6 when it should better be 3? The _STARTING functions in turn emit a standardised log that handling was started within the driver, so it is visible straight away that the command made it to the driver handling part?

@jimklimov
Copy link
Member Author

I guess one could say that. Being macros, these values can be re-defined during a build (perhaps passed in CFLAGS), but even then they would be consistent so when troubleshooting different drivers, we would see these entries at same verbosity levels everywhere.

jimklimov added a commit to jimklimov/nut that referenced this pull request Jul 14, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement Shutdowns and overrides and battery level triggers Issues and PRs about system shutdown, especially if battery charge/runtime remaining is involved

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants