[Swan-dev] better log content

[Andrew Cagney]

On Fri, 20 Sep 2019 at 08:27, Antony Antony <antony at phenome.org> wrote:
>
> Making log easier to track, and shorter prefixes, is great idea.  However
> removing connections prefix completely sounds a bit extreme to me! I think
> it is better to make a configurable options for shorter prefixes when you
> need it.

We need the connection [instance] - its our anchor when tracing things
(or at least should be).  It's all the guff that comes afterwards.
Most notably when OE for instance:

   "private-or-clear#192.1.2.0/24"[2] 10.0.10.1/32=== ...192.1.2.45 #3:

While I'm sure it means something, from my pov it is meaningless.

Two things about making this configurable:

- it needs a sane default (this is why the gnome dogma I had drilled
into me is that configuration options are a sign of compromise and
poor design - design the default properly and options aren't required,
and no one uses them)

- information currently embedded in the prefix will need to be logged
explicitly - just like for a shorter prefix, we can't rely on
information being available as a side effect of the prefix

Having said this, one simple configuration option would be to, when
redacting ip-addresses, suppress all that guff (since it will be
largely meaningless anyway); however, again, it will force us to log
more stuff explicitly.

> may be you saw some ugly long lines? share a few real lines you consider as
> long? and how often these prefixes appear.

>
> I think one of our issue is tracking log lines when things fail. When
> something fails we dump a lot of stuff. It is hard to make sense of it all,
> possibly no prefix would make it worse in cases such as OE, mobike.

The correct connection instance is needed as a prefix.

>
> I vaguely recollect a prefix width(real estate) argument when we introduced
> microseconds prefix. May be something like log-prefix-format=
> configurable option? Then one could configure a time format and shorter
> connection prefixes when you like.
>
> Also in light of the connections switching issues we currently have I
> suggest not to remove connection name prefixes completely. It could be also
> useful to debug OE. Why I bring up time prefixing is in most cases with
> multiple connections and multiple peers you also need time to make sense of
> it all. So connection prefix is not the only long one taking premium space.
>
> Sep 19 16:36:12.148222: "east-any"[1] 192.1.3.209 #1: STATE_MAIN_R1: sent
> MR1, expecting MI2
>
> One idea to track IKE and child would be prefix child st with IKE state?
> something like #2/1 (or #1320/1088). I can't imagine a one size fit all log
> prefix for most debugging situations. I am considering OE, access vpn
> certificate and %any, and, just net-to-net usecases.  A real world busy log
> with IKE scanners in the wild and truncated messages is very hard to track.

I've wondered about that.   More typically though, our problem is that
IKE SA messages - for instance authentication - get logged against the
child sa; and/or we log against the wrong instance.



> On Tue, Sep 17, 2019 at 05:40:45PM -0400, Andrew Cagney wrote:
> > Several things I've noticed while trying to use the log files to track
> > down problems:
> >
> > - tracking a connection instance's IKE and CHILD SAs is painful
> > I've an awk script to do this, but the mere existence of this script
> > should act as a red flag :-).  For instance, to match an IKE_SA with
> > its first CHILD_SA the script:
> >   -> matches /#[0-9]*: Authenticated using RSA/ - the line contains
> > both the "connection instance" + #IKE_SA; this is used to map
> > "connection instance"->#IKE_SA
> >   -> matches /#[0-9]*: negotiated connection/ - the line contains
> > "connection instance" + #CHILD_SA; combining this with above gets
> > #IKE_SA<->#CHILD_SA
> > yuck!

Imagine a shop where
- the sales assistant, not yet knowing your identity, puts all of your
purchases on some other random customer's card
- then when you prove identity, the charges against the random
customer hopefully all get reversed and you get the bill
/me thinks that the previous customer, with a bill full of of bogus
charges and reversals, isn't going to be happy.

To me that's what we're doing.

> > - the connection prefix seems like far too much information,
> > especially when it is constantly repeated and redacted; for instance
> > <ip-address> in:
> >     ... "my-connection"[1234] <ip-address> #100: ...
> > is just wasted real estate; would it be better to dump all the
> > connection instance details once as a line
> >
> > - as a follow-on it would be nice if the connection instance prefix
> > stopped changing between log lines
> > because the prefix is generated dynamically it evolves as the
> > connection information gets changed; again a log line once one all
> > changes are done
> >
> > Andrew
> > _______________________________________________
> > Swan-dev mailing list
> > Swan-dev at lists.libreswan.org
> > https://lists.libreswan.org/mailman/listinfo/swan-dev