restorer: Use the simple logging engine

Remove the restorer-log and link log-simple into restorer
blob. Now we can use the normal pr_foo API.
Signed-off-by: Pavel Emelyanov <xemul@parallels.com>

Makefile.pie

@@ -12,7 +12,7 @@ PBLOB-BIN	:= parasite.bin
 PBLOB-BIN-O	:= $(PBLOB-BIN).o
 
 ROBJS		+= restorer.o
-ROBJS		+= restorer-log.o
+ROBJS		+= log-simple.o
 RSRCS		+= $(patsubst %.o,%.c,$(ROBJS))
 
 RBLOB-NAME	:= restorer

include/restorer-log.h

-#ifndef RESTORER_LOG_H__
-#define RESTORER_LOG_H__
-
-#include "log-levels.h"
-
-extern long vprint_num(char *buf, long num);
-
-extern void write_hex_n_on_level(unsigned int loglevel, unsigned long num);
-extern void write_num_n_on_level(unsigned int loglevel, long num);
-extern void write_num_on_level(unsigned int loglevel, long num);
-extern void write_str_n_on_level(unsigned int loglevel, char *str);
-
-extern void restorer_set_logfd(int fd);
-extern void restorer_set_loglevel(unsigned int loglevel);
-
-#define write_str_err(str)	print_on_level(LOG_ERROR, str)
-#define write_str_n_err(str)	write_str_n_on_level(LOG_ERROR, str)
-
-#define	write_num_err(num)	write_num_on_level(LOG_ERROR, num)
-#define write_num_n_err(num)	write_num_n_on_level(LOG_ERROR, num)
-
-#define write_str_info(str)	print_on_level(LOG_INFO, str)
-#define write_str_n_info(str)	write_str_n_on_level(LOG_INFO, str)
-
-#define write_num_info(num)	write_num_on_level(LOG_INFO, num)
-#define write_num_n_info(num)	write_num_n_on_level(LOG_INFO, num)
-
-#define write_hex_n_err(num)	write_hex_n_on_level(LOG_ERROR, num)
-
-#endif /* RESTORER_LOG_H__ */

include/util.h

@@ -38,9 +38,7 @@
 #define BUG_ON_HANDLER(condition)					\
 	do {								\
 		if ((condition)) {					\
-			write_str_err("BUG at " __FILE__ ": ");		\
-			write_num_err(__LINE__);			\
-			write_str_err("\n");				\
+			pr_err("BUG at %s:%d\n", __FILE__, __LINE__);	\
 			*(volatile unsigned long *)NULL = 0xdead0000 + __LINE__;	\
 		}							\
 	} while (0)

restorer-log.c

-#include "restorer-log.h"
-#include "syscall.h"
-
-static int current_logfd;
-static unsigned int current_loglevel;
-
-#define __add_ord(c)			\
-	do {				\
-		if (c < 10)		\
-			c += '0';	\
-		else			\
-			c += 'a' - 10;	\
-	} while (0)
-
-void restorer_set_logfd(int fd)
-{
-	current_logfd = fd;
-}
-
-void restorer_set_loglevel(unsigned int loglevel)
-{
-	current_loglevel = loglevel;
-}
-
-static void write_str(const char *str)
-{
-	int len = 0;
-
-	while (str[len])
-		len++;
-
-	sys_write(current_logfd, str, len);
-}
-
-void print_on_level(unsigned int loglevel, const char *str, ...)
-{
-	if (loglevel > current_loglevel)
-		return;
-	write_str(str);
-}
-
-void write_str_n_on_level(unsigned int loglevel, char *str)
-{
-	char new_line = '\n';
-
-	if (loglevel > current_loglevel)
-		return;
-
-	write_str(str);
-	sys_write(current_logfd, &new_line, 1);
-}
-
-static void write_num(long num)
-{
-	unsigned long d = 1000000000000000000;
-	unsigned int started = 0;
-	unsigned int c;
-
-	if (num < 0) {
-		num = -num;
-		c = '-';
-		sys_write(current_logfd, &c, 1);
-	}
-
-	while (d) {
-		c = num / d;
-		num -= d * c;
-		d /= 10;
-		if (!c && !started)
-			continue;
-		if (!started)
-			started = 1;
-		__add_ord(c);
-		sys_write(current_logfd, &c, 1);
-
-	}
-}
-
-void write_num_on_level(unsigned int loglevel, long num)
-{
-	if (loglevel > current_loglevel)
-		return;
-	write_num(num);
-}
-
-void write_num_n_on_level(unsigned int loglevel, long num)
-{
-	unsigned char c = '\n';
-
-	if (loglevel > current_loglevel)
-		return;
-
-	write_num(num);
-	sys_write(current_logfd, &c, sizeof(c));
-}
-
-void write_hex_n_on_level(unsigned int loglevel, unsigned long num)
-{
-	unsigned char *s = (unsigned char *)&num;
-	unsigned char c;
-	int i;
-
-	if (loglevel > current_loglevel)
-		return;
-
-	c = 'x';
-	sys_write(current_logfd, &c, 1);
-	for (i = sizeof(long)/sizeof(char) - 1; i >= 0; i--) {
-		c = (s[i] & 0xf0) >> 4;
-		__add_ord(c);
-		sys_write(current_logfd, &c, 1);
-
-		c = (s[i] & 0x0f);
-		__add_ord(c);
-		sys_write(current_logfd, &c, 1);
-	}
-
-	c = '\n';
-	sys_write(current_logfd, &c, 1);
-}
-
-long vprint_num(char *buf, long num)
-{
-	unsigned long d = 1000000000000000000;
-	unsigned int started = 0;
-	unsigned int i = 0;
-	unsigned int c;
-
-	if (num < 0) {
-		num = -num;
-		buf[i++] = '-';
-	}
-
-	while (d) {
-		c = num / d;
-		num -= d * c;
-		d /= 10;
-		if (!c && !started)
-			continue;
-		if (!started)
-			started = 1;
-		__add_ord(c);
-		buf[i++] = c;
-
-	}
-
-	buf[i++] = 0;
-
-	return i;
-}

restorer.c

@@ -15,7 +15,7 @@
 #include "compiler.h"
 #include "types.h"
 #include "syscall.h"
-#include "restorer-log.h"
+#include "log.h"
 #include "util.h"
 #include "image.h"
 #include "sk-inet.h"
@@ -29,10 +29,8 @@
 #define sys_prctl_safe(opcode, val1, val2, val3)			\
 	({								\
 		long __ret = sys_prctl(opcode, val1, val2, val3, 0);	\
-		if (__ret) {						\
-			write_num_n_err(__LINE__);			\
-			write_num_n_err(__ret);				\
-		}							\
+		if (__ret) 						\
+			 pr_err("prctl failed @%d with %ld\n", __LINE__, __ret);\
 		__ret;							\
 	})
 
@@ -40,12 +38,16 @@ static struct task_entries *task_entries;
 
 static void sigchld_handler(int signal, siginfo_t *siginfo, void *data)
 {
-	write_num_info(siginfo->si_pid);
+	char *r;
+
 	if (siginfo->si_code & CLD_EXITED)
-		write_str_info(" exited, status=");
+		r = " exited, status=";
 	else if (siginfo->si_code & CLD_KILLED)
-		write_str_info(" killed by signal ");
-	write_num_n_info(siginfo->si_status);
+		r = " killed by signal ";
+	else
+		r = "disappeared with ";
+
+	pr_info("Task %d %s %d\n", siginfo->si_pid, r, siginfo->si_status);
 
 	futex_abort_and_wake(&task_entries->nr_in_progress);
 	/* sa_restorer may be unmaped, so we can't go back to userspace*/
@@ -137,9 +139,7 @@ long __export_restore_thread(struct thread_restore_args *args)
 	int my_pid = sys_gettid();
 
 	if (my_pid != args->pid) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(my_pid);
-		write_num_n_err(args->pid);
+		pr_err("Thread pid mismatch %d/%d\n", my_pid, args->pid);
 		goto core_restore_end;
 	}
 
@@ -147,9 +147,7 @@ long __export_restore_thread(struct thread_restore_args *args)
 
 	if (args->has_futex) {
 		if (sys_set_robust_list((void *)args->futex_rla, args->futex_rla_len)) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(my_pid);
-			write_num_n_err(args->pid);
+			pr_err("Robust list err %d\n", my_pid);
 			goto core_restore_end;
 		}
 	}
@@ -184,16 +182,14 @@ long __export_restore_thread(struct thread_restore_args *args)
 	fsgs_base = args->gpregs.fs_base;
 	ret = sys_arch_prctl(ARCH_SET_FS, fsgs_base);
 	if (ret) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(ret);
+		pr_err("SET_FS fail %ld\n", ret);
 		goto core_restore_end;
 	}
 
 	fsgs_base = args->gpregs.gs_base;
 	ret = sys_arch_prctl(ARCH_SET_GS, fsgs_base);
 	if (ret) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(ret);
+		pr_err("SET_GS fail %ld\n", ret);
 		goto core_restore_end;
 	}
 
@@ -208,8 +204,7 @@ long __export_restore_thread(struct thread_restore_args *args)
 	restore_creds(NULL);
 	futex_dec_and_wake(&task_entries->nr_in_progress);
 
-	write_num_info(sys_gettid());
-	write_str_n_info(": Restored");
+	pr_info("%ld: Restored\n", sys_gettid());
 
 	futex_wait_while(&task_entries->start, CR_STATE_RESTORE);
 	futex_dec_and_wake(&task_entries->nr_in_progress);
@@ -224,8 +219,7 @@ long __export_restore_thread(struct thread_restore_args *args)
 		: "r"(new_sp)
 		: "rax","rsp","memory");
 core_restore_end:
-	write_num_n_err(__LINE__);
-	write_num_n_err(sys_getpid());
+	pr_err("Restorer abnormal termination for %ld\n", sys_getpid());
 	sys_exit_group(1);
 	return -1;
 }
@@ -234,7 +228,7 @@ static long restore_self_exe_late(struct task_restore_core_args *args)
 {
 	int fd = args->fd_exe_link;
 
-	write_str_info("Restoring EXE\n");
+	pr_info("Restoring EXE link\n");
 	sys_prctl_safe(PR_SET_MM, PR_SET_MM_EXE_FILE, fd, 0);
 	sys_close(fd);
 
@@ -318,15 +312,17 @@ long __export_restore_task(struct task_restore_core_args *args)
 	act.rt_sa_handler = sigchld_handler;
 	sys_sigaction(SIGCHLD, &act, NULL, sizeof(rt_sigset_t));
 
-	restorer_set_logfd(args->logfd);
-	restorer_set_loglevel(args->loglevel);
+	log_set_fd(args->logfd);
+	log_set_loglevel(args->loglevel);
+
+	pr_info("Switched to the restorer %d\n", my_pid);
 
 	for (vma_entry = args->self_vmas; vma_entry->start != 0; vma_entry++) {
 		if (!vma_entry_is(vma_entry, VMA_AREA_REGULAR))
 			continue;
 
 		if (sys_munmap((void *)vma_entry->start, vma_entry_len(vma_entry))) {
-			write_num_n_err(__LINE__);
+			pr_err("Munmap fail for %lx\n", vma_entry->start);
 			goto core_restore_end;
 		}
 	}
@@ -344,14 +340,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 		va = restore_mapping(vma_entry);
 
 		if (va != vma_entry->start) {
-			write_num_n_err(__LINE__);
-			write_hex_n_err(vma_entry->start);
-			write_hex_n_err(vma_entry->end);
-			write_hex_n_err(vma_entry->prot);
-			write_hex_n_err(vma_entry->flags);
-			write_hex_n_err(vma_entry->fd);
-			write_hex_n_err(vma_entry->pgoff);
-			write_hex_n_err(va);
+			pr_err("Can't restore %lx mapping with %lx\n", vma_entry->start, va);
 			goto core_restore_end;
 		}
 	}
@@ -365,15 +354,13 @@ long __export_restore_task(struct task_restore_core_args *args)
 			break;
 
 		if (ret != sizeof(va)) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(ret);
+			pr_err("Bad mapping page size %ld\n", ret);
 			goto core_restore_end;
 		}
 
 		ret = sys_read(args->fd_pages, (void *)va, PAGE_SIZE);
 		if (ret != PAGE_SIZE) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(ret);
+			pr_err("Can'r read mapping page %ld\n", ret);
 			goto core_restore_end;
 		}
 	}
@@ -411,8 +398,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 	ret = sys_munmap(args->shmems, SHMEMS_SIZE);
 	if (ret < 0) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(ret);
+		pr_err("Can't unmap shmem %ld\n", ret);
 		goto core_restore_end;
 	}
 
@@ -451,9 +437,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 	if (args->has_futex) {
 		if (sys_set_robust_list((void *)args->futex_rla, args->futex_rla_len)) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(my_pid);
-			write_num_n_err(args->pid);
+			pr_err("Robust list set fail %d\n", my_pid);
 			goto core_restore_end;
 		}
 	}
@@ -494,16 +478,14 @@ long __export_restore_task(struct task_restore_core_args *args)
 	fsgs_base = args->gpregs.fs_base;
 	ret = sys_arch_prctl(ARCH_SET_FS, fsgs_base);
 	if (ret) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(ret);
+		pr_info("SET_FS fail %ld\n", ret);
 		goto core_restore_end;
 	}
 
 	fsgs_base = args->gpregs.gs_base;
 	ret = sys_arch_prctl(ARCH_SET_GS, fsgs_base);
 	if (ret) {
-		write_num_n_err(__LINE__);
-		write_num_n_err(ret);
+		pr_info("SET_GS fail %ld\n", ret);
 		goto core_restore_end;
 	}
 
@@ -540,20 +522,18 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 		fd = sys_open(LAST_PID_PATH, O_RDWR, LAST_PID_PERM);
 		if (fd < 0) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(fd);
+			pr_err("Can't open last_pid %d\n", fd);
 			goto core_restore_end;
 		}
 
 		ret = sys_flock(fd, LOCK_EX);
 		if (ret) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(ret);
+			pr_err("Can't lock last_pid %d\n", fd);
 			goto core_restore_end;
 		}
 
 		for (i = 0; i < args->nr_threads; i++) {
-			char last_pid_buf[16];
+			char last_pid_buf[16], *s;
 
 			/* skip self */
 			if (thread_args[i].pid == args->pid)
@@ -565,12 +545,10 @@ long __export_restore_task(struct task_restore_core_args *args)
 				RESTORE_ALIGN_STACK((long)thread_args[i].mem_zone.stack,
 						    sizeof(thread_args[i].mem_zone.stack));
 
-			last_pid_len = vprint_num(last_pid_buf, thread_args[i].pid - 1);
-			ret = sys_write(fd, last_pid_buf, last_pid_len - 1);
+			last_pid_len = vprint_num(last_pid_buf, sizeof(last_pid_buf), thread_args[i].pid - 1, &s);
+			ret = sys_write(fd, s, last_pid_len);
 			if (ret < 0) {
-				write_num_n_err(__LINE__);
-				write_num_n_err(ret);
-				write_str_n_err(last_pid_buf);
+				pr_err("Can't set last_pid %ld/%s\n", ret, last_pid_buf);
 				goto core_restore_end;
 			}
 
@@ -619,8 +597,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 		ret = sys_flock(fd, LOCK_UN);
 		if (ret) {
-			write_num_n_err(__LINE__);
-			write_num_n_err(ret);
+			pr_err("Can't unlock last_pid %ld\n", ret);
 			goto core_restore_end;
 		}
 
@@ -636,8 +613,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 	futex_dec_and_wake(&args->task_entries->nr_in_progress);
 
-	write_num_info(sys_getpid());
-	write_str_n_info(": Restored");
+	pr_info("%ld: Restored\n", sys_getpid());
 
 	futex_wait_while(&args->task_entries->start, CR_STATE_RESTORE);
 
@@ -649,7 +625,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 
 	rst_tcp_socks_all(args->rst_tcp_socks, args->rst_tcp_socks_size);
 
-	sys_close(args->logfd);
+	log_set_fd(-1);
 
 	/*
 	 * The code that prepared the itimers makes shure the
@@ -693,8 +669,7 @@ long __export_restore_task(struct task_restore_core_args *args)
 		: "rax","rsp","memory");
 
 core_restore_end:
-	write_num_n_err(__LINE__);
-	write_num_n_err(sys_getpid());
+	pr_err("Restorer fail %ld\n", sys_getpid());
 	sys_exit_group(1);
 	return -1;