[CRIU] [PATCH v4 1/3] Printout early log messages

[Adrian Reber]

On Wed, Dec 19, 2018 at 10:55:52PM -0800, Andrei Vagin wrote:
> On Wed, Dec 19, 2018 at 10:27:34PM +0100, Adrian Reber wrote:
> > On Sun, Dec 16, 2018 at 11:26:59PM -0800, Andrei Vagin wrote:
> > > On Thu, Dec 13, 2018 at 08:08:16AM +0000, Adrian Reber wrote:
> > > > From: Adrian Reber <areber at redhat.com>
> > > > 
> > > > Up until now any pr_* logging command (except pr_msg) was lost if
> > > > logging has not been set up (log_init()).
> > > > 
> > > > To make sure not logging messages are lost, vprint_on_level() now writes
> > > > all messages (except LOG_MSG) to a temporary buffer which is written
> > > > to the logging FD once that is set up.
> > > > 
> > > > Related: https://github.com/checkpoint-restore/criu/issues/578
> > > > 
> > > > Signed-off-by: Adrian Reber <areber at redhat.com>
> > > > ---
> > > >  criu/log.c | 94 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> > > >  1 file changed, 94 insertions(+)
> > > > 
> > > > diff --git a/criu/log.c b/criu/log.c
> > > > index a268ab8..398c443 100644
> > > > --- a/criu/log.c
> > > > +++ b/criu/log.c
> > > > @@ -31,11 +31,21 @@
> > > >  /* Enable timestamps if verbosity is increased from default */
> > > >  #define LOG_TIMESTAMP		(DEFAULT_LOGLEVEL + 1)
> > > >  #define LOG_BUF_LEN		(8*1024)
> > > > +#define EARLY_LOG_BUF_LEN	1024
> > > >  
> > > >  static unsigned int current_loglevel = DEFAULT_LOGLEVEL;
> > > >  
> > > >  static char buffer[LOG_BUF_LEN];
> > > >  static char buf_off = 0;
> > > > +/*
> > > > + * The early_log_buffer is used to store log messages before
> > > > + * logging is set up to make sure no logs are lost.
> > > > + */
> > > > +static char early_log_buffer[EARLY_LOG_BUF_LEN];
> > > > +static unsigned int early_log_buf_off = 0;
> > > > +
> > > > +/* If this is 0 the logging has not been set up yet. */
> > > > +static int init_done = 0;
> > > >  
> > > >  static struct timeval start;
> > > >  /*
> > > > @@ -186,6 +196,8 @@ int log_init(const char *output)
> > > >  	if (fd < 0)
> > > >  		goto err;
> > > >  
> > > > +	init_done = 1;
> > > > +
> > > >  	print_versions();
> > > >  
> > > >  	return 0;
> > > > @@ -258,6 +270,72 @@ unsigned int log_get_loglevel(void)
> > > >  	return current_loglevel;
> > > >  }
> > > >  
> > > > +void early_vprint(const char *format, unsigned int loglevel, va_list params)
> > > > +{
> > > > +	unsigned int log_size = 0;
> > > > +
> > > > +	if (early_log_buf_off >= EARLY_LOG_BUF_LEN)
> > > > +		return;
> > > > +
> > > > +	/* Save loglevel */
> > > > +	early_log_buffer[early_log_buf_off++] = loglevel;
> > > 
> > > I would say that early_log has to contain only errors
> > 
> > The main problem this is trying to solve, is to not loose any messages.
> > 
> > If we would only care about errors, we would still loose messages from
> > pr_info(), pr_warn(), pr_debug() if used before the logging is
> > initialized. You could argue that users just should not use pr_*()
> > before logging is initialized but this happens sometimes, so why not
> > collect all messages and print them out depending on the log level.
> 
> When I wrote this comment, I meant that we don't need to save loglevel
> for these messages and they all have to have the error level be default.
> In this cases, the code will be simpler.

Hmm, yes the code will be simpler, but... Not sure. I do not really
care. For me it makes more sense to have the messages at the correct log
level.

> I have another idea. We can exit with a non-zero
> code, if pr_{info, warn, debug} is called before log_init(). Probably,
> it is too radical for reguar users, but it will be useful for tests...

This really sounds too radical. Especially in combination with RPC, log
output before log_init make debugging runc easier.

		Adrian