[v4,1/3] Printout early log messages

Submitted by Adrian Reber on Dec. 13, 2018, 8:08 a.m.

Details

Message ID 1544688498-8852-1-git-send-email-adrian@lisas.de
State New
Series "Series without cover letter"
Headers show

Commit Message

Adrian Reber Dec. 13, 2018, 8:08 a.m.
From: Adrian Reber <areber@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@redhat.com>
---
 criu/log.c | 94 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 94 insertions(+)

Patch hide | download patch | download mbox

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;
+	/* 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) ");
+	}
+
+	log_size += vsnprintf(early_log_buffer + early_log_buf_off + log_size, sizeof early_log_buffer - early_log_buf_off - log_size, format, params);
+	/* Save log entry size */
+	memcpy(early_log_buffer + (early_log_buf_off - sizeof(unsigned int)), &log_size, sizeof(unsigned int));
+	early_log_buf_off += log_size;
+}
+
+void flush_early_log_buffer(int fd)
+{
+	unsigned int log_size;
+	unsigned int pos = 0;
+	int tmp_log_level;
+	int size;
+	int ret;
+
+	while (pos < early_log_buf_off) {
+		/*
+		 * The early_log_buffer contains all messages written
+		 * before logging was set up. We only want to print
+		 * out messages which correspond to the requested
+		 * log_level. Therefore the early_log_buffer also contains
+		 * the log_level and the size. This writes one messages,
+		 * depending on the log_level, to the logging fd. Start
+		 * with reading the log_level.
+		 */
+		tmp_log_level = early_log_buffer[pos++];
+		/* Read out log message size */
+		memcpy(&log_size, early_log_buffer + pos, sizeof(unsigned int));
+		pos += sizeof(unsigned int);
+		size = 0;
+		if (tmp_log_level <= current_loglevel) {
+			while (size < log_size) {
+				ret = write(fd, early_log_buffer + pos + size, log_size - size);
+				if (ret <= 0)
+					break;
+				size += ret;
+			}
+		} else {
+			size += log_size;
+		}
+		pos += size;
+	}
+	early_log_buf_off = 0;
+
+}
+
 void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
 {
 	int fd, size, ret, off = 0;
@@ -267,6 +345,14 @@  void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
 		fd = STDOUT_FILENO;
 		off = buf_off; /* skip dangling timestamp */
 	} else {
+		/*
+		 * If logging has not yet been initialized (init_done == 0)
+		 * make sure all messages are written to the early_log_buffer.
+		 */
+		if (!init_done) {
+			early_vprint(format, loglevel, params);
+			return;
+		}
 		if (loglevel > current_loglevel)
 			return;
 		fd = log_get_fd();
@@ -274,6 +360,13 @@  void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
 			print_ts();
 	}
 
+	/*
+	 * Once logging is setup this write out all early log messages.
+	 * Only those messages which have to correct log level are printed.
+	 */
+	if (early_log_buf_off && init_done)
+		flush_early_log_buffer(fd);
+
 	size  = vsnprintf(buffer + buf_off, sizeof buffer - buf_off, format, params);
 	size += buf_off;
 
@@ -284,6 +377,7 @@  void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
 		off += ret;
 	}
 
+	/* This is missing for messages in the early_log_buffer. */
 	if (loglevel == LOG_ERROR)
 		log_note_err(buffer + buf_off);
 

Comments

Andrey Vagin Dec. 17, 2018, 7:26 a.m.
On Thu, Dec 13, 2018 at 08:08:16AM +0000, Adrian Reber wrote:
> From: Adrian Reber <areber@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@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

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


		early_log_buf_off += log_size;

> +	}
> +
> +	log_size += vsnprintf(early_log_buffer + early_log_buf_off + log_size, sizeof early_log_buffer - early_log_buf_off - log_size, format, params);

This line is too long

sizeof(early_log_buffer), otherwise it is hard to read

> +	/* Save log entry size */
> +	memcpy(early_log_buffer + (early_log_buf_off - sizeof(unsigned int)), &log_size, sizeof(unsigned int));
> +	early_log_buf_off += log_size;
> +}
> +
> +void flush_early_log_buffer(int fd)
> +{
> +	unsigned int log_size;
> +	unsigned int pos = 0;
> +	int tmp_log_level;
> +	int size;
> +	int ret;
> +
> +	while (pos < early_log_buf_off) {
> +		/*
> +		 * The early_log_buffer contains all messages written
> +		 * before logging was set up. We only want to print
> +		 * out messages which correspond to the requested
> +		 * log_level. Therefore the early_log_buffer also contains
> +		 * the log_level and the size. This writes one messages,
> +		 * depending on the log_level, to the logging fd. Start
> +		 * with reading the log_level.
> +		 */
> +		tmp_log_level = early_log_buffer[pos++];
> +		/* Read out log message size */
> +		memcpy(&log_size, early_log_buffer + pos, sizeof(unsigned int));
> +		pos += sizeof(unsigned int);
> +		size = 0;
> +		if (tmp_log_level <= current_loglevel) {
> +			while (size < log_size) {
> +				ret = write(fd, early_log_buffer + pos + size, log_size - size);
> +				if (ret <= 0)
> +					break;
> +				size += ret;
> +			}
> +		} else {
> +			size += log_size;
> +		}
> +		pos += size;
> +	}
> +	early_log_buf_off = 0;
> +
> +}
> +
>  void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  {
>  	int fd, size, ret, off = 0;
> @@ -267,6 +345,14 @@ void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  		fd = STDOUT_FILENO;
>  		off = buf_off; /* skip dangling timestamp */
>  	} else {
> +		/*
> +		 * If logging has not yet been initialized (init_done == 0)
> +		 * make sure all messages are written to the early_log_buffer.
> +		 */
> +		if (!init_done) {
> +			early_vprint(format, loglevel, params);
> +			return;
> +		}
>  		if (loglevel > current_loglevel)
>  			return;
>  		fd = log_get_fd();
> @@ -274,6 +360,13 @@ void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  			print_ts();
>  	}
>  
> +	/*
> +	 * Once logging is setup this write out all early log messages.
> +	 * Only those messages which have to correct log level are printed.
> +	 */
> +	if (early_log_buf_off && init_done)
> +		flush_early_log_buffer(fd);

I don't understand why it is here. Why is it not in log_init()?

> +
>  	size  = vsnprintf(buffer + buf_off, sizeof buffer - buf_off, format, params);
>  	size += buf_off;
>  
> @@ -284,6 +377,7 @@ void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  		off += ret;
>  	}
>  
> +	/* This is missing for messages in the early_log_buffer. */
>  	if (loglevel == LOG_ERROR)
>  		log_note_err(buffer + buf_off);
>  
> -- 
> 1.8.3.1
>
Adrian Reber Dec. 19, 2018, 9:27 p.m.
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@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@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
Andrey Vagin Dec. 20, 2018, 6:55 a.m.
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@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@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
Adrian Reber Dec. 20, 2018, 4:27 p.m.
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@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@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
Andrey Vagin Dec. 20, 2018, 5:57 p.m.
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@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@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