[v3,1/3] Printout early log messages

Submitted by Adrian Reber on Dec. 12, 2018, 7:44 a.m.

Details

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

Commit Message

Adrian Reber Dec. 12, 2018, 7:44 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 | 84 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 83 insertions(+), 1 deletion(-)

Patch hide | download patch | download mbox

diff --git a/criu/log.c b/criu/log.c
index a268ab8..bb2b14b 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;
@@ -262,18 +274,87 @@  void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
 {
 	int fd, size, ret, off = 0;
 	int __errno = errno;
+	int tmp_log_level;
+	unsigned int log_size;
+	unsigned int pos;
 
 	if (unlikely(loglevel == LOG_MSG)) {
 		fd = STDOUT_FILENO;
 		off = buf_off; /* skip dangling timestamp */
 	} else {
-		if (loglevel > current_loglevel)
+		/*
+		 * If logging has not yet been initialized (init_done == 0)
+		 * make sure all messages are written to the early_log_buffer.
+		 */
+		if ((loglevel > current_loglevel) && init_done)
 			return;
 		fd = log_get_fd();
 		if (current_loglevel >= LOG_TIMESTAMP)
 			print_ts();
 	}
 
+	if (!init_done && !(loglevel == LOG_MSG)) {
+		if (early_log_buf_off >= EARLY_LOG_BUF_LEN)
+			return;
+		log_size = 0;
+		/* 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;
+
+		return;
+	}
+
+	/*
+	 * 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) {
+		pos = 0;
+		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;
+	}
+
 	size  = vsnprintf(buffer + buf_off, sizeof buffer - buf_off, format, params);
 	size += buf_off;
 
@@ -284,6 +365,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

Radostin Stoyanov Dec. 12, 2018, 8:39 a.m.
On 12/12/2018 07:44, 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>
>
Acked-by: Radostin Stoyanov <rstoyanov1@gmail.com>
Mike Rapoport Dec. 12, 2018, 12:31 p.m.
Hi Adrian,

Sorry that I'm jumping this late, I've been a bit behind the CRIU list
these days.

On Wed, Dec 12, 2018 at 07:44:50AM +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 | 84 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 83 insertions(+), 1 deletion(-)
> 
> diff --git a/criu/log.c b/criu/log.c
> index a268ab8..bb2b14b 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;
> @@ -262,18 +274,87 @@ void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  {
>  	int fd, size, ret, off = 0;
>  	int __errno = errno;
> +	int tmp_log_level;
> +	unsigned int log_size;
> +	unsigned int pos;
>  
>  	if (unlikely(loglevel == LOG_MSG)) {
>  		fd = STDOUT_FILENO;
>  		off = buf_off; /* skip dangling timestamp */
>  	} else {
> -		if (loglevel > current_loglevel)
> +		/*
> +		 * If logging has not yet been initialized (init_done == 0)
> +		 * make sure all messages are written to the early_log_buffer.
> +		 */
> +		if ((loglevel > current_loglevel) && init_done)

I think a nicer way would be to have

		if (!init_done) {
			early_vprint(format, params);
			return;
		}
		if (loglevel > current_loglevel)
			return;


>  			return;
>  		fd = log_get_fd();
>  		if (current_loglevel >= LOG_TIMESTAMP)
>  			print_ts();
>  	}
>  
> +	if (!init_done && !(loglevel == LOG_MSG)) {

and have the whole block below as

void early_vprint(const char *format, va_list params)

> +		if (early_log_buf_off >= EARLY_LOG_BUF_LEN)
> +			return;
> +		log_size = 0;
> +		/* 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;
> +
> +		return;
> +	}
> +
> +	/*
> +	 * 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) {
> +		pos = 0;
> +		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;
> +	}

This block also seems like a good candidate for a helper function.

> +
>  	size  = vsnprintf(buffer + buf_off, sizeof buffer - buf_off, format, params);
>  	size += buf_off;
>  
> @@ -284,6 +365,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
> 
> _______________________________________________
> CRIU mailing list
> CRIU@openvz.org
> https://lists.openvz.org/mailman/listinfo/criu
>
Dmitry Safonov Dec. 12, 2018, 2:37 p.m.
Hi Adrian, Mike,

On 12/12/18 12:31 PM, Mike Rapoport wrote:
> Hi Adrian,
> 
> Sorry that I'm jumping this late, I've been a bit behind the CRIU list
> these days.
> 
> On Wed, Dec 12, 2018 at 07:44:50AM +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

I very much like the idea :)

>> Signed-off-by: Adrian Reber <areber@redhat.com>
>> ---
>>  criu/log.c | 84 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>>  1 file changed, 83 insertions(+), 1 deletion(-)

[..]

>>  
>>  	if (unlikely(loglevel == LOG_MSG)) {
>>  		fd = STDOUT_FILENO;
>>  		off = buf_off; /* skip dangling timestamp */
>>  	} else {
>> -		if (loglevel > current_loglevel)
>> +		/*
>> +		 * If logging has not yet been initialized (init_done == 0)
>> +		 * make sure all messages are written to the early_log_buffer.
>> +		 */
>> +		if ((loglevel > current_loglevel) && init_done)
> 
> I think a nicer way would be to have
> 
> 		if (!init_done) {
> 			early_vprint(format, params);
> 			return;
> 		}
> 		if (loglevel > current_loglevel)
> 			return;

Probably loglevel check should be before early print?

>>  			return;
>>  		fd = log_get_fd();
>>  		if (current_loglevel >= LOG_TIMESTAMP)
>>  			print_ts();
>>  	}
>>  
>> +	if (!init_done && !(loglevel == LOG_MSG)) {
> 
> and have the whole block below as
> 
> void early_vprint(const char *format, va_list params)
> 

Yes, please, it asks for a helper.


Thanks,
          Dima
Dmitry Safonov Dec. 12, 2018, 2:38 p.m.
On 12/12/18 2:37 PM, Dmitry Safonov wrote:
> Probably loglevel check should be before early print?

Nevermind, I've forgot that we set current loglevel in during log init.
Adrian Reber Dec. 13, 2018, 8:06 a.m.
On Wed, Dec 12, 2018 at 02:37:16PM +0000, Dmitry Safonov wrote:
> Hi Adrian, Mike,
> 
> On 12/12/18 12:31 PM, Mike Rapoport wrote:
> > Hi Adrian,
> > 
> > Sorry that I'm jumping this late, I've been a bit behind the CRIU list
> > these days.
> > 
> > On Wed, Dec 12, 2018 at 07:44:50AM +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
> 
> I very much like the idea :)

Thanks everyone for the feedback. Reworked patch series is on its way.

		Adrian
Dmitry Safonov Dec. 13, 2018, 3:36 p.m.
On 12/12/18 2:38 PM, Dmitry Safonov wrote:
> 
> On 12/12/18 2:37 PM, Dmitry Safonov wrote:
>> Probably loglevel check should be before early print?
> 
> Nevermind, I've forgot that we set current loglevel in during log init.
> 

For correctness sake of filtering loglevel messages, we could have wrote
them to the buffer starting with level number.. and parse it when
logging is inited..
But it doesn't seems worth a fuzz for just a couple of printed messages
regardless lower loglevel.
Andrey Vagin Dec. 17, 2018, 6:16 a.m.
On Wed, Dec 12, 2018 at 07:44:50AM +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 | 84 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 83 insertions(+), 1 deletion(-)
> 
> diff --git a/criu/log.c b/criu/log.c
> index a268ab8..bb2b14b 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];

I would suggest to create a pipe and set it as a temporary log file
descritor.  Then when a real log will be set up, we will be able to read
everything from a pipe and write into the log file.


> +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;
> @@ -262,18 +274,87 @@ void vprint_on_level(unsigned int loglevel, const char *format, va_list params)
>  {
>  	int fd, size, ret, off = 0;
>  	int __errno = errno;
> +	int tmp_log_level;
> +	unsigned int log_size;
> +	unsigned int pos;
>  
>  	if (unlikely(loglevel == LOG_MSG)) {
>  		fd = STDOUT_FILENO;
>  		off = buf_off; /* skip dangling timestamp */
>  	} else {
> -		if (loglevel > current_loglevel)
> +		/*
> +		 * If logging has not yet been initialized (init_done == 0)
> +		 * make sure all messages are written to the early_log_buffer.
> +		 */
> +		if ((loglevel > current_loglevel) && init_done)
>  			return;
>  		fd = log_get_fd();
>  		if (current_loglevel >= LOG_TIMESTAMP)
>  			print_ts();
>  	}
>  
> +	if (!init_done && !(loglevel == LOG_MSG)) {
> +		if (early_log_buf_off >= EARLY_LOG_BUF_LEN)
> +			return;
> +		log_size = 0;
> +		/* 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);

This line is two times longer than allowed by coding style...

> +		/* Save log entry size */
> +		memcpy(early_log_buffer + (early_log_buf_off - sizeof(unsigned int)), &log_size, sizeof(unsigned int));

what for? Why is it not enough to have early_log_buf_off?

> +		early_log_buf_off += log_size;
> +

Pls, create a helper for this code

> +		return;

> +	}
> +
> +	/*
> +	 * 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) {

Why does this code here? should it be in log_init?

> +		pos = 0;
> +		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;
> +	}
> +
>  	size  = vsnprintf(buffer + buf_off, sizeof buffer - buf_off, format, params);
>  	size += buf_off;
>  
> @@ -284,6 +365,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
>