[Swan-dev] better log content

[Antony Antony]

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.

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.

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.  

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!
> 
> - 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