[CRIU] [PATCH v5 1/3] Printout early log messages
Andrei Vagin
avagin at gmail.com
Thu Dec 27 00:43:26 MSK 2018
On Thu, Dec 20, 2018 at 04:18:11PM +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
Pls, take a look at the attached patch
>
> Signed-off-by: Adrian Reber <areber at redhat.com>
> ---
> criu/log.c | 99 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
> 1 file changed, 99 insertions(+)
>
> diff --git a/criu/log.c b/criu/log.c
> index a268ab8a4..246b44155 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;
> /*
> @@ -155,6 +165,45 @@ static void print_versions(void)
> buf.release, buf.version, buf.machine);
> }
>
> +static 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;
> +}
> +
> int log_init(const char *output)
> {
> int new_logfd, fd;
> @@ -186,6 +235,14 @@ int log_init(const char *output)
> if (fd < 0)
> goto err;
>
> + init_done = 1;
> +
> + /*
> + * Once logging is setup this write out all early log messages.
> + * Only those messages which have to correct log level are printed.
> + */
> + flush_early_log_buffer(fd);
> +
> print_versions();
>
> return 0;
> @@ -258,6 +315,39 @@ unsigned int log_get_loglevel(void)
> return current_loglevel;
> }
>
> +static 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 vprint_on_level(unsigned int loglevel, const char *format, va_list params)
> {
> int fd, size, ret, off = 0;
> @@ -267,6 +357,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();
> @@ -284,6 +382,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);
>
> --
> 2.18.0
>
-------------- next part --------------
diff --git a/criu/log.c b/criu/log.c
index 246b44155..060d1ee6e 100644
--- a/criu/log.c
+++ b/criu/log.c
@@ -165,12 +165,14 @@ static void print_versions(void)
buf.release, buf.version, buf.machine);
}
+struct early_log_hdr {
+ uint16_t level;
+ uint16_t len;
+};
+
static 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) {
@@ -183,24 +185,22 @@ static void flush_early_log_buffer(int fd)
* 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) {
+ struct early_log_hdr *hdr = (void *)early_log_buffer + pos;
+ pos += sizeof(hdr);
+ if (hdr->level <= current_loglevel) {
+ size_t size = 0;
+ while (size < hdr->len) {
ret = write(fd, early_log_buffer + pos + size,
- log_size - size);
+ hdr->len - size);
if (ret <= 0)
break;
size += ret;
}
- } else {
- size += log_size;
}
- pos += size;
+ pos += hdr->len;
}
+ if (early_log_buf_off)
+ pr_warn("The early log isn't empty\n");
early_log_buf_off = 0;
}
@@ -318,14 +318,17 @@ unsigned int log_get_loglevel(void)
static void early_vprint(const char *format, unsigned int loglevel, va_list params)
{
unsigned int log_size = 0;
+ struct early_log_hdr *hdr;
if (early_log_buf_off >= EARLY_LOG_BUF_LEN)
return;
/* Save loglevel */
- early_log_buffer[early_log_buf_off++] = loglevel;
+
+ hdr = (void *)early_log_buffer + early_log_buf_off;
+ hdr->level = loglevel;
/* Skip the log entry size */
- early_log_buf_off += sizeof(unsigned int);
+ early_log_buf_off += sizeof(hdr);
if (loglevel >= LOG_TIMESTAMP) {
/*
* If logging is not yet setup we just write zeros
@@ -343,8 +346,7 @@ static void early_vprint(const char *format, unsigned int loglevel, va_list para
format, params);
/* Save log entry size */
- memcpy(early_log_buffer + (early_log_buf_off - sizeof(unsigned int)),
- &log_size, sizeof(unsigned int));
+ hdr->len = log_size;
early_log_buf_off += log_size;
}
More information about the CRIU
mailing list