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

[Andrei Vagin]

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.

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

> 
> > > +	/* 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?

Usually we are following the linux kernel coding style 
https://www.kernel.org/doc/html/v4.10/process/coding-style.html#breaking-long-lines-and-strings


2) Breaking long lines and strings
Coding style is all about readability and maintainability using commonly
available tools.

The limit on the length of lines is 80 columns and this is a strongly
preferred limit.

Statements longer than 80 columns will be broken into sensible chunks,
unless exceeding 80 columns significantly increases readability and does
not hide information. Descendants are always substantially shorter than
the parent and are placed substantially to the right. The same applies
to function headers with a long argument list. However, never break
user-visible strings such as printk messages, because that breaks the
ability to grep for them.

> 
> 		Adrian