[Nut-upsdev] logging strategy

[Greg Troxel]

Jim Klimov <jimklimov+nut at gmail.com> writes:

>   I don't think there is any particular strategy, at least not one I'd know
> of either :) So it is mostly ad-hoc, to keep smaller verbosity numbers
> reasonably quiet, and sufficient info to see the logic progression at a
> given debug level (e.g. if major milestones of a routine are logged at
> level N, further traces like "I saw value X here" would be N+1 or more).
> De-facto verbosities fizzle out at 6, but generally it is an int value,
> so...

Sounds good - what I wrote down as a plan for bestfortress very much
matches that, 1 to 5 where 5 is if you want to see every IO byte.

>   Regarding syslog/stdout/stderr, the upsdebugx*() methods are defined here
> and near:
> https://github.com/networkupstools/nut/blob/ad70749f243527e774c3f03a08228430143396e9/common/common.c#L1205
> and end up calling vupslog() at which can report to stderr (not stdout)
> and/or syslog, based on settings - see around
> https://github.com/networkupstools/nut/blob/ad70749f243527e774c3f03a08228430143396e9/common/common.c#L1011.
> The UPSLOG_STDERR bit is set by default, but cleared in the background()
> method, along with raising the UPSLOG_SYSLOG bit. By default enabled debug
> means staying foreground, so the bits are not changed. However "recently"
> the explicit -F/-B flags were added to manipulate fore-/back-grounding
> independently of debug (default behavior remains as it was).

ack, makes sense.

>   Note that daemons started under service management frameworks like SMF or
> systemd can remain in "foreground" mode (with backgrounding handled by
> framework forking itself), so continue logging to stderr with messages
> landing into systemd journal or SMF service-instance log file.

ok - netbsd doesn't do that (expecting things to daemonize and use
syslog), but good to know.

>   A few programs are more explicit about this, e.g.:
> ````
> :; git grep -n syslogbit_set
> common/common.c:130:void syslogbit_set(void)
> include/common.h:234:void syslogbit_set(void);
>
> clients/upssched.c:1341:        syslogbit_set();
> drivers/main.c:1052:            syslogbit_set();
> server/upsd.c:1827:     syslogbit_set();
> ````

I did find that in drivers/main.c.

> So upsdebugx should therefore 1) not have the driver name and 2) should
> have a function, for things that aren't clearly locatable.  Correct?
>
> 1) I don't think it prints a driver name (at least not by itself - maybe
> some drivers or other programs pass format strings which hardcode such
> stuff).

I was confused; syslog on my system is printing the program name.

> 2) a common incantation is `upsdebugx(NUM, "%s: some text", __func__);` to
> take advantage of modern compilers providing the __func__ macro.
> Technically also __FILE__ and __LINE__ may be used. Neither is guaranteed
> across the portability board however, but that is likely to only bite very
> old systems nowadays. The `configure` script tries some fallbacks for
> __func__ but not for others.

Thanks - I may try that, but I think I'm trying to write debug
statements that are sort of human readable without code refs and also
easily findable in the code.

But ack that __func__ is acceptable.

> As for s_upsdebug_ascii() - I do not think it is a perfectly good idea to
> change it (maybe is - not much used in NUT codebase; but possibly some
> forks have more use for it).
> It sounds reasonable however to define and implement a different method for
> this purpose, when you expect that sort of content - and call it where
> suitable.
>
> Maybe makes sense to create a typical hexdump printer along the lines of
> https://gist.github.com/jimklimov/07913a3e30a7d7ec50e9c946117c994f#file-jenkins-credump-L17-L41
> (that particular code is groovy, but trivial to convert elsewhere).

I want to see mostly-ascii as mostly-ascii with escapes, because that's
what Fortress output smells like so far, rather than flipping to all
hex (if I read groovy right).

Totally fair point about not changing s_upsdebug_ascii (but I think we
shouldn't worry about forks as socially they should contribute back).  I
will just add a new s_upsdebug_escapedascii and friends -- works for me.