[Swan-dev] logging final pass

[Andrew Cagney]

On Fri, 27 Nov 2020 at 12:44, Paul Wouters <paul at nohats.ca> wrote:
>
> On Wed, 25 Nov 2020, Andrew Cagney wrote:
>
> > Here's the current status.
> >
> > The standard log primitive is:
> >
> >   log_message(RC_FLAGS, logger, FMT, ...)
>
> > but this is all very tedious, so there are wrappers for common cases:
> >
> >  log_state(RC_LOG, &ike->sa, "hi!");
>
> Still a bit tedious :)

we could have:
   log_sa(RC_LOG, ike, "huh!");
(especially if we assume 'st' is dying - I suspect all kernel code
shoudl expect a child_sa).

>
> > - can log_message() be shortened?
> > It can't be log() as that is taken by the math library, but llog() or
> > (with irony) plog(), loglog() are now all free (or will be tomorrow)
>
> I would prefer llog() of those.

sure.

I would also change log_sa() to llog_sa() et.al.

> > - do we want wrappers, such as log_state(), or not?
> > I ask as I found, when updating code, that it was easier to just use
> > log_message() everywhere, even though it was longer
>
> I'm not sure...
>
> > - can/should the convention where a struct logger field is always
> > called .logger be adopted?
> > So that log_message(RC_LOG, foo->logger, "logging foo") works; it
> > would violate .st_*.

It could be reduced to:
    llog(RC_LOG, st->logger, "state");

(technical nit, the choice of "st_" as the prefix was really
unfortunate - it clashes with struct stat wiich #defines st_...
fields)

> I think there is value in using .st_logger, especially for people new
> to the code to help them realise that is something of the struct state.
> But ideally, I would like to see more that behind wrappers :)

Right, reading:
   llog(RC_LOG, c->logger, ...)
   llog(RC_LOG, md->logger, ...)
is a big hint as to what is being used when logging.

otoh it is longer ...  hence me wondering about:
  lloglog(md, "....", ...)
which implies RC_LOG, and ->logger.


> > - speaking of wrappers, what about loglog(O, MSG, ...) =>
> > log_message(RC_LOG, O->logger, MSG, ...) ....
> >
> > The gaps:
> >
> > -> what is with log_connection(rc_flags, logger, WHACKFD, c, ...); or
> > how come states have a logger but not the connection
> > Because it wasn't clear, at the time, if adding a logger to a
> > connection was useful.  Turns out that most logging is against either
> > message digest or a state.  For a connection it was typically
> > triggered by whack - hence whackfd - or via pending.  Of course this
> > ignores:
> > - revival (yet again revival and pending appear in the same sentence)
> > - other exceptions
> > - just being consistent
> > So I'll likely end up adding a connection logger; mainly for consistency.
> Seems fine to me.
>
> > -> what is with code picking up the global logger such as
> > log_global(30), pexpect(450), passert(850), ...
> > Move along, nothing to see, ... too painful to replace ...
>
> :)
>
> > - but I want per-connection/per-state debugging to work again ...
> > The current theory is to add <<lset_t debug>> to <<struct logger>> and
> > then have dbg_message(logger, ....) test it
>
> This was basically never used, and I wouldn't do it. The issue is that
> almost always in these complicated scenarios, there is connection
> switching and so enabling logging for one connection (even if that
> includes all its instances) is often not good enough. And if you add
> it without it picking up its connection instances, it's basically
> useless. No one has real issues needing debugging for 1 permanent
> static connection. And it is very common for the fist packet to hit
> the wrong connection and only switching after IDs are transmitted.
> So my vote here is don't re-add this.

Works for me ...

> > - is there 'something better'?
> >                /* XXX: something better */
> >                close_any(&st->st_logger->object_whackfd);
> >                st->st_logger->object_whackfd = dup_any(logger->global_whackfd);
> > yes.  Think about one whack adding a connection while a second is
> > trying to delete it.
>
> Wouldn't these be guaranteed to happen sequentially and not interleaves?
> (as long as we don't switch to a helper-per-packet-processing scenario.

It can interleave.  I forget the details but it first came up in the
pending tests.
The above hack means that the second whack boots the first whack off
the state.  It isn't pretty but it works.

> > - what about 'struct show'?
> > It's job is to suppress or add blank lines in show* output.  I do
> > wonder about renaming it to 'struct whack', I'll keep wondering.
>
> I don't care much about this, whatever works for you is fine with me.
>
> Paul