zdtm: rework logging

* Delete internal buffer, all data are written immediately in a log file
* Add timestamp and pid in a message
* All processes write log messages in one file
Signed-off-by: Andrey Vagin <avagin@openvz.org>
Signed-off-by: Pavel Emelyanov <xemul@parallels.com>

test/zdtm/lib/msg.c

@@ -3,59 +3,58 @@
 #include <unistd.h>
 #include <fcntl.h>
 #include <sys/stat.h>
+#include <sys/user.h>
 #include <string.h>
+#include <linux/limits.h>
+#include <sys/time.h>
+#include <time.h>
 
 #include "zdtmtst.h"
 
-static struct {
-	char buffer[LOG_BUF_SIZE];
-	char *ptr;
-	int left;
-} msg_buf = {
-	.buffer = {},
-	.ptr = msg_buf.buffer,
-	.left = sizeof(msg_buf.buffer),
-};
-
-void test_msg(const char *format, ...)
+int test_log_init(const char *fname, const char *suffix)
 {
-	va_list arg;
-	int len;
+	char path[PATH_MAX];
+	int logfd;
+
+	snprintf(path, sizeof(path), "%s%s", fname, suffix);
+	logfd = open(path, O_WRONLY | O_EXCL | O_CREAT | O_APPEND, 0644);
+	if (logfd < 0) {
+		err("Can't open file %s", fname);
+		return -1;
+	}
 
-	va_start(arg, format);
-	len = vsnprintf(msg_buf.ptr, msg_buf.left, format, arg);
-	va_end(arg);
+	dup2(logfd, STDERR_FILENO);
+	dup2(logfd, STDOUT_FILENO);
 
-	if (len >= msg_buf.left) {	/* indicate message buffer overflow */
-		const char overflow_mark[] = "\n.@.\n";
-		msg_buf.left = 0;
-		msg_buf.ptr = msg_buf.buffer + sizeof(msg_buf.buffer);
-		strcpy(msg_buf.ptr - sizeof(overflow_mark), overflow_mark);
-		msg_buf.ptr--;		/* correct for terminating '\0' */
-		return;
-	}
+	close(logfd);
 
-	msg_buf.ptr += len;
-	msg_buf.left -= len;
-}
+	setbuf(stdout, NULL);
+	setbuf(stderr, NULL);
 
-extern int proc_id;
+	return 0;
+}
 
-void dump_msg(const char *fname)
+void test_msg(const char *format, ...)
 {
-	if (msg_buf.ptr != msg_buf.buffer) {
-		int fd;
-		if (proc_id == 0) {
-			fd = open(fname, O_WRONLY | O_CREAT | O_EXCL | O_APPEND, 0644);
-		} else {
-			char fname_child[1000];
-			snprintf(fname_child,1000,"%s.%d",fname,proc_id);
-			fd = open(fname_child, O_WRONLY | O_CREAT | O_APPEND, 0644);
-		}
-		if (fd < 0)
-			return;
-		/* ignore errors as there's no way to report them */
-		write(fd, msg_buf.buffer, msg_buf.ptr - msg_buf.buffer);
-		close(fd);
+	va_list arg;
+	int len, off = 0;
+	char buf[PAGE_SIZE];
+	struct timeval tv;
+	struct tm *tm;
+
+	gettimeofday(&tv, NULL);
+	tm = localtime(&tv.tv_sec);
+	if (tm == NULL) {
+		err("localtime() failed");
+	} else {
+		off += strftime(buf, sizeof(buf), "%H:%M:%S", tm);
 	}
+
+	off += sprintf(buf + off, ".%.3ld: ", tv.tv_usec / 1000);
+	off += sprintf(buf + off, "%5d: ", getpid());
+	va_start(arg, format);
+	len = vsnprintf(buf + off, sizeof(buf) - off, format, arg);
+	va_end(arg);
+
+	dprintf(STDERR_FILENO, buf);
 }

test/zdtm/lib/test.c

@@ -44,15 +44,21 @@ int test_fork_id(int id)
 	return pid;
 }
 
+#define INPROGRESS ".inprogress"
 static void test_fini(void)
 {
-	extern void dump_msg(const char *);
-	dump_msg(outfile);
-	if (getpid() == master_pid)
-		unlink(pidfile);
+	char path[PATH_MAX];
+
+	if (getpid() != master_pid)
+		return;
+
+	snprintf(path, sizeof(path), "%s%s", outfile, INPROGRESS);
+	rename(path, outfile);
+
+	unlink(pidfile);
 }
 
-static void setup_outfile()
+void setup_outfile()
 {
 	if (!access(outfile, F_OK) || errno != ENOENT) {
 		fprintf(stderr, "Output file %s appears to exist, aborting\n",
@@ -64,6 +70,8 @@ static void setup_outfile()
 		fprintf(stderr, "Can't register exit function\n");
 		exit(1);
 	}
+	if (test_log_init(outfile, INPROGRESS))
+		exit(1);
 }
 
 static void redir_stdfds()
@@ -76,9 +84,7 @@ static void redir_stdfds()
 		exit(1);
 	}
 
-	dup2(nullfd, 0);
-	dup2(nullfd, 1);
-	dup2(nullfd, 2);
+	dup2(nullfd, STDIN_FILENO);
 	if (nullfd > 2)
 		close(nullfd);
 }
@@ -246,7 +252,9 @@ void test_init_ns(int argc, char **argv, unsigned long clone_flags,
 
 	parseargs(argc, argv);
 
-	setup_outfile();
+	/* setup_outfile() should be called in a target mount namespace */
+	if (!(clone_flags & CLONE_NEWNS))
+		setup_outfile();
 	redir_stdfds();
 
 	pidf = fopen(pidfile, "wx");

test/zdtm/lib/zdtmtst.h

@@ -82,7 +82,8 @@ extern int parse_opt_string(char *param, void *arg);
 #define __stringify(x)          __stringify_1(x)
 
 /* message helpers */
-#define LOG_BUF_SIZE 0x1000
+extern void setup_outfile(void);
+extern int test_log_init(const char *outfile, const char *suffix);
 #define err(format, arg...)	\
 	test_msg("ERR: %s:%d: " format " (errno = %d)\n", \
 		__FILE__, __LINE__, ## arg, errno)

test/zdtm/live/static/mountpoints.c

@@ -60,9 +60,6 @@ again:
 	return -1;
 
 done:
-	close(0);
-	close(1);
-	close(2);
 	rmdir(MPTS_ROOT);
 	if (mkdir(MPTS_ROOT, 0600) < 0) {
 		fail("Can't make zdtm_sys");
@@ -94,6 +91,10 @@ done:
 		return 1;
 	}
 
+	mknod("/dev/null", 0777 | S_IFCHR, makedev(1, 3));
+
+	setup_outfile();
+
 	fd = open(MPTS_ROOT"/kernel/meminfo", O_RDONLY);
 	if (fd == -1)
 		return 1;