[v2,1/3] Printout early log messages

Submitted by Adrian Reber on Dec. 12, 2018, 5:18 a.m.

Details

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

Commit Message

Adrian Reber Dec. 12, 2018, 5:18 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

Adrian Reber Dec. 12, 2018, 7:48 a.m.
Series fails CI because of:

flake8 --config=scripts/flake8.cfg test/others/rpc/config_file.py
test/others/rpc/config_file.py:10:1: F401 'time' imported but unused

Resending v3.

		Adrian

On Wed, Dec 12, 2018 at 05:18:24AM +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)
>  			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);
>  
> -- 
> 1.8.3.1
> 
> _______________________________________________
> CRIU mailing list
> CRIU@openvz.org
> https://lists.openvz.org/mailman/listinfo/criu