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

[Andrei Vagin]

On Thu, Dec 20, 2018 at 05:27:17PM +0100, Adrian Reber wrote:
> 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.

It is just my opinion. Lets see what other people think about this. My
opinion is that the earlylog should not be full-functional, we don't
want that it is used for something else except errors.

Another options is that we can support log level for these messages and
print an error message if earlylog isn't empty.

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