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

[Adrian Reber]

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.

> > +	/* Skip the log entry size */
> > +	early_log_buf_off += sizeof(unsigned int);
> > +	if (loglevel >= LOG_TIMESTAMP) {
> > +		/*
> > +		 * If logging is not yet setup we just write zeros
> > +		 * instead of a real timestamp. This way we can
> > +		 * keep the same format as the other messages on
> > +		 * log levels with timestamps (>=LOG_TIMESTAMP).
> > +		 */
> > +		log_size  = snprintf(early_log_buffer + early_log_buf_off, sizeof early_log_buffer - early_log_buf_off, "(00.000000) ");
> 
> This line is too long

I agree, but do we have that documented anywhere. I think there are many
places in CRIU where there are long lines, so I thought it was not
really important. What is our line length limit?

		Adrian