[igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message

[igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message

[Chris Wilson]

Very handy for correlating events between different logs.

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Petri Latvala <petri.latvala@intel.com>
---
 runner/executor.c | 141 +++++++++++++++++++++++++---------------------
 1 file changed, 77 insertions(+), 64 deletions(-)

diff --git a/runner/executor.c b/runner/executor.c
index 52fee7d13..d46aa6972 100644
--- a/runner/executor.c
+++ b/runner/executor.c
@@ -2,6 +2,7 @@
 #include <fcntl.h>
 #include <linux/watchdog.h>
 #include <signal.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -26,13 +27,29 @@ static struct {
 	size_t num_dogs;
 } watchdogs;
 
+__attribute__((format(printf, 2, 3)))
+static void outf(FILE *stream, const char *fmt, ...)
+{
+	int saved_errno = errno;
+	struct timespec tv;
+	va_list ap;
+
+	if (clock_gettime(CLOCK_BOOTTIME, &tv))
+		clock_gettime(CLOCK_REALTIME, &tv);
+	outf(stream, "[%ld.%06ld] ", tv.tv_sec, tv.tv_nsec / 1000);
+
+	va_start(ap, fmt);
+	errno = saved_errno;
+	vfprintf(stream, fmt, ap);
+	va_end(ap);
+}
+
 static void __close_watchdog(int fd)
 {
 	ssize_t ret = write(fd, "V", 1);
 
 	if (ret == -1)
-		fprintf(stderr, "Failed to stop a watchdog: %s\n",
-			strerror(errno));
+		outf(stderr, "Failed to stop a watchdog: %m\n");
 
 	close(fd);
 }
@@ -42,10 +59,10 @@ static void close_watchdogs(struct settings *settings)
 	size_t i;
 
 	if (settings && settings->log_level >= LOG_LEVEL_VERBOSE)
-		printf("Closing watchdogs\n");
+		outf(stdout, "Closing watchdogs\n");
 
 	if (settings == NULL && watchdogs.num_dogs != 0)
-		fprintf(stderr, "Closing watchdogs from exit handler!\n");
+		outf(stderr, "Closing watchdogs from exit handler!\n");
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		__close_watchdog(watchdogs.fds[i]);
@@ -73,7 +90,7 @@ static void init_watchdogs(struct settings *settings)
 		return;
 
 	if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-		printf("Initializing watchdogs\n");
+		outf(stdout, "Initializing watchdogs\n");
 	}
 
 	atexit(close_watchdogs_atexit);
@@ -88,7 +105,7 @@ static void init_watchdogs(struct settings *settings)
 		watchdogs.fds[i] = fd;
 
 		if (settings->log_level >= LOG_LEVEL_VERBOSE)
-			printf(" %s\n", name);
+			outf(stdout, " %s\n", name);
 	}
 }
 
@@ -123,10 +140,8 @@ static void ping_watchdogs(void)
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		ret = ioctl(watchdogs.fds[i], WDIOC_KEEPALIVE, NULL);
-
 		if (ret == -1)
-			fprintf(stderr, "Failed to ping a watchdog: %s\n",
-				strerror(errno));
+			outf(stderr, "Failed to ping a watchdog: %m\n");
 	}
 }
 
@@ -237,7 +252,7 @@ static char *need_to_abort(const struct settings* settings)
 			continue;
 
 		if (settings->log_level >= LOG_LEVEL_NORMAL)
-			fprintf(stderr, "Aborting: %s\n", abort);
+			outf(stderr, "Aborting: %s\n", abort);
 
 		return abort;
 	}
@@ -456,7 +471,7 @@ static bool kill_child(int sig, pid_t child)
 	 */
 	kill(-child, sig);
 	if (kill(child, sig) && errno == ESRCH) {
-		fprintf(stderr, "Child process does not exist. This shouldn't happen.\n");
+		outf(stderr, "Child process does not exist. This shouldn't happen.\n");
 		return false;
 	}
 
@@ -518,9 +533,10 @@ static int monitor_output(pid_t child,
 			timeout /= timeout_intervals;
 
 			if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-				printf("Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
-				       "Using %d intervals of %d seconds.\n",
-				       wd_timeout, timeout_intervals, timeout);
+				outf(stdout,
+				     "Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
+				     "Using %d intervals of %d seconds.\n",
+				     wd_timeout, timeout_intervals, timeout);
 			}
 		}
 	}
@@ -555,7 +571,8 @@ static int monitor_output(pid_t child,
 			switch (killed) {
 			case 0:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGQUIT.\n");
+					outf(stdout,
+					     "Timeout. Killing the current test with SIGQUIT.\n");
 					fflush(stdout);
 				}
 
@@ -573,7 +590,8 @@ static int monitor_output(pid_t child,
 				break;
 			case SIGQUIT:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGKILL.\n");
+					outf(stdout,
+					     "Timeout. Killing the current test with SIGKILL.\n");
 					fflush(stdout);
 				}
 
@@ -597,8 +615,8 @@ static int monitor_output(pid_t child,
 
 				/* Nothing that can be done, really. Let's tell the caller we want to abort. */
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					fprintf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
-						taints);
+					outf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
+					     taints);
 				}
 				close_watchdogs(settings);
 				free(outbuf);
@@ -621,8 +639,7 @@ static int monitor_output(pid_t child,
 			s = read(outfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stdout: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading test's stdout: %m\n");
 				}
 
 				close(outfd);
@@ -689,8 +706,7 @@ static int monitor_output(pid_t child,
 			s = read(errfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stderr: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading test's stderr: %m\n");
 				}
 				close(errfd);
 				errfd = -1;
@@ -706,12 +722,11 @@ static int monitor_output(pid_t child,
 			s = read(kmsgfd, buf, sizeof(buf));
 			if (s < 0) {
 				if (errno != EPIPE && errno != EINVAL) {
-					fprintf(stderr, "Error reading from kmsg, stopping monitoring: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading from kmsg, stopping monitoring: %m\n");
 					close(kmsgfd);
 					kmsgfd = -1;
 				} else if (errno == EINVAL) {
-					fprintf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
+					outf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
 				}
 			} else {
 				write(outputs[_F_DMESG], buf, s);
@@ -726,12 +741,11 @@ static int monitor_output(pid_t child,
 
 			s = read(sigfd, &siginfo, sizeof(siginfo));
 			if (s < 0) {
-				fprintf(stderr, "Error reading from signalfd: %s\n",
-					strerror(errno));
+				outf(stderr, "Error reading from signalfd: %m\n");
 				continue;
 			} else if (siginfo.ssi_signo == SIGCHLD) {
 				if (child != waitpid(child, &status, WNOHANG)) {
-					fprintf(stderr, "Failed to reap child\n");
+					outf(stderr, "Failed to reap child\n");
 					status = 9999;
 				} else if (WIFEXITED(status)) {
 					status = WEXITSTATUS(status);
@@ -746,8 +760,9 @@ static int monitor_output(pid_t child,
 			} else {
 				/* We're dying, so we're taking them with us */
 				if (settings->log_level >= LOG_LEVEL_NORMAL)
-					printf("Abort requested via %s, terminating children\n",
-					       strsignal(siginfo.ssi_signo));
+					outf(stdout,
+					     "Abort requested via %s, terminating children\n",
+					     strsignal(siginfo.ssi_signo));
 
 				aborting = true;
 				timeout = 2;
@@ -836,7 +851,7 @@ execute_test_process(int outfd, int errfd,
 	}
 
 	execv(argv[0], argv);
-	fprintf(stderr, "Cannot execute %s\n", argv[0]);
+	outf(stderr, "Cannot execute %s\n", argv[0]);
 	exit(IGT_EXIT_INVALID);
 }
 
@@ -861,7 +876,7 @@ static void print_time_left(struct execute_state *state,
 		return;
 
 	width = digits(settings->overall_timeout);
-	printf("(%*.0fs left) ", width, state->time_left);
+	outf(stdout, "(%*.0fs left) ", width, state->time_left);
 }
 
 static char *entry_display_name(struct job_list_entry *entry)
@@ -923,12 +938,12 @@ static int execute_next_entry(struct execute_state *state,
 	snprintf(name, sizeof(name), "%zd", idx);
 	mkdirat(resdirfd, name, 0777);
 	if ((dirfd = openat(resdirfd, name, O_DIRECTORY | O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Error accessing individual test result directory\n");
+		outf(stderr, "Error accessing individual test result directory\n");
 		return -1;
 	}
 
 	if (!open_output_files(dirfd, outputs, true)) {
-		fprintf(stderr, "Error opening output files\n");
+		outf(stderr, "Error opening output files\n");
 		result = -1;
 		goto out_dirfd;
 	}
@@ -939,13 +954,13 @@ static int execute_next_entry(struct execute_state *state,
 	}
 
 	if (pipe(outpipe) || pipe(errpipe)) {
-		fprintf(stderr, "Error creating pipes: %s\n", strerror(errno));
+		outf(stderr, "Error creating pipes: %m\n");
 		result = -1;
 		goto out_pipe;
 	}
 
 	if ((kmsgfd = open("/dev/kmsg", O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Warning: Cannot open /dev/kmsg\n");
+		outf(stderr, "Warning: Cannot open /dev/kmsg\n");
 	} else {
 		/* TODO: Checking of abort conditions in pre-execute dmesg */
 		lseek(kmsgfd, 0, SEEK_END);
@@ -955,15 +970,15 @@ static int execute_next_entry(struct execute_state *state,
 	if (settings->log_level >= LOG_LEVEL_NORMAL) {
 		char *displayname;
 		int width = digits(total);
-		printf("[%0*zd/%0*zd] ", width, idx + 1, width, total);
+		outf(stdout, "[%0*zd/%0*zd] ", width, idx + 1, width, total);
 
 		print_time_left(state, settings);
 
 		displayname = entry_display_name(entry);
-		printf("%s", displayname);
+		outf(stdout, "%s", displayname);
 		free(displayname);
 
-		printf("\n");
+		outf(stdout, "\n");
 	}
 
 	/*
@@ -975,7 +990,7 @@ static int execute_next_entry(struct execute_state *state,
 
 	child = fork();
 	if (child < 0) {
-		fprintf(stderr, "Failed to fork: %s\n", strerror(errno));
+		outf(stderr, "Failed to fork: %m\n");
 		result = -1;
 		goto out_kmsgfd;
 	} else if (child == 0) {
@@ -1027,9 +1042,8 @@ static bool clear_test_result_directory(int dirfd)
 
 	for (i = 0; i < _F_LAST; i++) {
 		if (remove_file(dirfd, filenames[i])) {
-			fprintf(stderr, "Error deleting %s from test result directory: %s\n",
-				filenames[i],
-				strerror(errno));
+			outf(stderr, "Error deleting %s from test result directory: %m\n",
+			     filenames[i]);
 			return false;
 		}
 	}
@@ -1048,7 +1062,7 @@ static bool clear_old_results(char *path)
 			return true;
 		}
 
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		outf(stderr, "Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1057,7 +1071,7 @@ static bool clear_old_results(char *path)
 	    remove_file(dirfd, "endtime.txt") ||
 	    remove_file(dirfd, "aborted.txt")) {
 		close(dirfd);
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		outf(stderr, "Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1076,9 +1090,9 @@ static bool clear_old_results(char *path)
 		}
 		close(resdirfd);
 		if (unlinkat(dirfd, name, AT_REMOVEDIR)) {
-			fprintf(stderr,
-				"Warning: Result directory %s contains extra files\n",
-				name);
+			outf(stderr,
+			     "Warning: Result directory %s contains extra files\n",
+			     name);
 		}
 	}
 
@@ -1234,11 +1248,11 @@ static void oom_immortal(void)
 
 	fd = open("/proc/self/oom_score_adj", O_WRONLY);
 	if (fd < 0) {
-		fprintf(stderr, "Warning: Cannot adjust oom score.\n");
+		outf(stderr, "Warning: Cannot adjust oom score.\n");
 		return;
 	}
 	if (write(fd, never_kill, sizeof(never_kill)) != sizeof(never_kill))
-		fprintf(stderr, "Warning: Adjusting oom score failed.\n");
+		outf(stderr, "Warning: Adjusting oom score failed.\n");
 
 	close(fd);
 }
@@ -1253,22 +1267,22 @@ static bool should_die_because_signal(int sigfd)
 
 	if (ret != 0) {
 		if (ret == -1) {
-			fprintf(stderr, "Poll on signalfd failed with %s\n", strerror(errno));
+			outf(stderr, "Poll on signalfd failed with %m\n");
 			return true; /* something is wrong, let's die */
 		}
 
 		ret = read(sigfd, &siginfo, sizeof(siginfo));
 
 		if (ret == -1) {
-			fprintf(stderr, "Error reading from signalfd: %s\n", strerror(errno));
+			outf(stderr, "Error reading from signalfd: %m\n");
 			return false; /* we may want to retry later */
 		}
 
 		if (siginfo.ssi_signo == SIGCHLD) {
-			fprintf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
+			outf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
 		} else {
-			fprintf(stderr, "Runner is being killed by %s\n",
-				strsignal(siginfo.ssi_signo));
+			outf(stderr, "Runner is being killed by %s\n",
+			     strsignal(siginfo.ssi_signo));
 			return true;
 		}
 
@@ -1289,28 +1303,27 @@ bool execute(struct execute_state *state,
 	bool status = true;
 
 	if (state->dry) {
-		printf("Dry run, not executing. Invoke igt_resume if you want to execute.\n");
+		outf(stdout, "Dry run, not executing. Invoke igt_resume if you want to execute.\n");
 		return true;
 	}
 
 	if ((resdirfd = open(settings->results_path, O_DIRECTORY | O_RDONLY)) < 0) {
 		/* Initialize state should have done this */
-		fprintf(stderr, "Error: Failure opening results path %s\n",
-			settings->results_path);
+		outf(stderr, "Error: Failure opening results path %s\n",
+		     settings->results_path);
 		return false;
 	}
 
 	if ((testdirfd = open(settings->test_root, O_DIRECTORY | O_RDONLY)) < 0) {
-		fprintf(stderr, "Error: Failure opening test root %s\n",
-			settings->test_root);
+		outf(stderr, "Error: Failure opening test root %s\n",
+		     settings->test_root);
 		close(resdirfd);
 		return false;
 	}
 
 	/* TODO: On resume, don't rewrite, verify that content matches current instead */
 	if ((unamefd = openat(resdirfd, "uname.txt", O_CREAT | O_WRONLY | O_TRUNC, 0666)) < 0) {
-		fprintf(stderr, "Error: Failure opening uname.txt: %s\n",
-			strerror(errno));
+		outf(stderr, "Error: Failure opening uname.txt: %m\n");
 		close(testdirfd);
 		close(resdirfd);
 		return false;
@@ -1339,7 +1352,7 @@ bool execute(struct execute_state *state,
 
 	if (sigfd < 0) {
 		/* TODO: Handle better */
-		fprintf(stderr, "Cannot mask signals\n");
+		outf(stderr, "Cannot mask signals\n");
 		status = false;
 		goto end;
 	}
@@ -1401,7 +1414,7 @@ bool execute(struct execute_state *state,
 
 		if (overall_timeout_exceeded(state)) {
 			if (settings->log_level >= LOG_LEVEL_NORMAL) {
-				printf("Overall timeout time exceeded, stopping.\n");
+				outf(stdout, "Overall timeout time exceeded, stopping.\n");
 			}
 
 			break;
-- 
2.23.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message

[Chris Wilson]

Very handy for correlating events between different logs.

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Petri Latvala <petri.latvala@intel.com>
---
 runner/executor.c | 141 +++++++++++++++++++++++++---------------------
 1 file changed, 77 insertions(+), 64 deletions(-)

diff --git a/runner/executor.c b/runner/executor.c
index 52fee7d13..d8b64a3fb 100644
--- a/runner/executor.c
+++ b/runner/executor.c
@@ -2,6 +2,7 @@
 #include <fcntl.h>
 #include <linux/watchdog.h>
 #include <signal.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -26,13 +27,29 @@ static struct {
 	size_t num_dogs;
 } watchdogs;
 
+__attribute__((format(printf, 2, 3)))
+static void outf(FILE *stream, const char *fmt, ...)
+{
+	int saved_errno = errno;
+	struct timespec tv;
+	va_list ap;
+
+	if (clock_gettime(CLOCK_BOOTTIME, &tv))
+		clock_gettime(CLOCK_REALTIME, &tv);
+	fprintf(stream, "[%ld.%06ld] ", tv.tv_sec, tv.tv_nsec / 1000);
+
+	va_start(ap, fmt);
+	errno = saved_errno;
+	vfprintf(stream, fmt, ap);
+	va_end(ap);
+}
+
 static void __close_watchdog(int fd)
 {
 	ssize_t ret = write(fd, "V", 1);
 
 	if (ret == -1)
-		fprintf(stderr, "Failed to stop a watchdog: %s\n",
-			strerror(errno));
+		outf(stderr, "Failed to stop a watchdog: %m\n");
 
 	close(fd);
 }
@@ -42,10 +59,10 @@ static void close_watchdogs(struct settings *settings)
 	size_t i;
 
 	if (settings && settings->log_level >= LOG_LEVEL_VERBOSE)
-		printf("Closing watchdogs\n");
+		outf(stdout, "Closing watchdogs\n");
 
 	if (settings == NULL && watchdogs.num_dogs != 0)
-		fprintf(stderr, "Closing watchdogs from exit handler!\n");
+		outf(stderr, "Closing watchdogs from exit handler!\n");
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		__close_watchdog(watchdogs.fds[i]);
@@ -73,7 +90,7 @@ static void init_watchdogs(struct settings *settings)
 		return;
 
 	if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-		printf("Initializing watchdogs\n");
+		outf(stdout, "Initializing watchdogs\n");
 	}
 
 	atexit(close_watchdogs_atexit);
@@ -88,7 +105,7 @@ static void init_watchdogs(struct settings *settings)
 		watchdogs.fds[i] = fd;
 
 		if (settings->log_level >= LOG_LEVEL_VERBOSE)
-			printf(" %s\n", name);
+			outf(stdout, " %s\n", name);
 	}
 }
 
@@ -123,10 +140,8 @@ static void ping_watchdogs(void)
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		ret = ioctl(watchdogs.fds[i], WDIOC_KEEPALIVE, NULL);
-
 		if (ret == -1)
-			fprintf(stderr, "Failed to ping a watchdog: %s\n",
-				strerror(errno));
+			outf(stderr, "Failed to ping a watchdog: %m\n");
 	}
 }
 
@@ -237,7 +252,7 @@ static char *need_to_abort(const struct settings* settings)
 			continue;
 
 		if (settings->log_level >= LOG_LEVEL_NORMAL)
-			fprintf(stderr, "Aborting: %s\n", abort);
+			outf(stderr, "Aborting: %s\n", abort);
 
 		return abort;
 	}
@@ -456,7 +471,7 @@ static bool kill_child(int sig, pid_t child)
 	 */
 	kill(-child, sig);
 	if (kill(child, sig) && errno == ESRCH) {
-		fprintf(stderr, "Child process does not exist. This shouldn't happen.\n");
+		outf(stderr, "Child process does not exist. This shouldn't happen.\n");
 		return false;
 	}
 
@@ -518,9 +533,10 @@ static int monitor_output(pid_t child,
 			timeout /= timeout_intervals;
 
 			if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-				printf("Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
-				       "Using %d intervals of %d seconds.\n",
-				       wd_timeout, timeout_intervals, timeout);
+				outf(stdout,
+				     "Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
+				     "Using %d intervals of %d seconds.\n",
+				     wd_timeout, timeout_intervals, timeout);
 			}
 		}
 	}
@@ -555,7 +571,8 @@ static int monitor_output(pid_t child,
 			switch (killed) {
 			case 0:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGQUIT.\n");
+					outf(stdout,
+					     "Timeout. Killing the current test with SIGQUIT.\n");
 					fflush(stdout);
 				}
 
@@ -573,7 +590,8 @@ static int monitor_output(pid_t child,
 				break;
 			case SIGQUIT:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGKILL.\n");
+					outf(stdout,
+					     "Timeout. Killing the current test with SIGKILL.\n");
 					fflush(stdout);
 				}
 
@@ -597,8 +615,8 @@ static int monitor_output(pid_t child,
 
 				/* Nothing that can be done, really. Let's tell the caller we want to abort. */
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					fprintf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
-						taints);
+					outf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
+					     taints);
 				}
 				close_watchdogs(settings);
 				free(outbuf);
@@ -621,8 +639,7 @@ static int monitor_output(pid_t child,
 			s = read(outfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stdout: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading test's stdout: %m\n");
 				}
 
 				close(outfd);
@@ -689,8 +706,7 @@ static int monitor_output(pid_t child,
 			s = read(errfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stderr: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading test's stderr: %m\n");
 				}
 				close(errfd);
 				errfd = -1;
@@ -706,12 +722,11 @@ static int monitor_output(pid_t child,
 			s = read(kmsgfd, buf, sizeof(buf));
 			if (s < 0) {
 				if (errno != EPIPE && errno != EINVAL) {
-					fprintf(stderr, "Error reading from kmsg, stopping monitoring: %s\n",
-						strerror(errno));
+					outf(stderr, "Error reading from kmsg, stopping monitoring: %m\n");
 					close(kmsgfd);
 					kmsgfd = -1;
 				} else if (errno == EINVAL) {
-					fprintf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
+					outf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
 				}
 			} else {
 				write(outputs[_F_DMESG], buf, s);
@@ -726,12 +741,11 @@ static int monitor_output(pid_t child,
 
 			s = read(sigfd, &siginfo, sizeof(siginfo));
 			if (s < 0) {
-				fprintf(stderr, "Error reading from signalfd: %s\n",
-					strerror(errno));
+				outf(stderr, "Error reading from signalfd: %m\n");
 				continue;
 			} else if (siginfo.ssi_signo == SIGCHLD) {
 				if (child != waitpid(child, &status, WNOHANG)) {
-					fprintf(stderr, "Failed to reap child\n");
+					outf(stderr, "Failed to reap child\n");
 					status = 9999;
 				} else if (WIFEXITED(status)) {
 					status = WEXITSTATUS(status);
@@ -746,8 +760,9 @@ static int monitor_output(pid_t child,
 			} else {
 				/* We're dying, so we're taking them with us */
 				if (settings->log_level >= LOG_LEVEL_NORMAL)
-					printf("Abort requested via %s, terminating children\n",
-					       strsignal(siginfo.ssi_signo));
+					outf(stdout,
+					     "Abort requested via %s, terminating children\n",
+					     strsignal(siginfo.ssi_signo));
 
 				aborting = true;
 				timeout = 2;
@@ -836,7 +851,7 @@ execute_test_process(int outfd, int errfd,
 	}
 
 	execv(argv[0], argv);
-	fprintf(stderr, "Cannot execute %s\n", argv[0]);
+	outf(stderr, "Cannot execute %s\n", argv[0]);
 	exit(IGT_EXIT_INVALID);
 }
 
@@ -861,7 +876,7 @@ static void print_time_left(struct execute_state *state,
 		return;
 
 	width = digits(settings->overall_timeout);
-	printf("(%*.0fs left) ", width, state->time_left);
+	outf(stdout, "(%*.0fs left) ", width, state->time_left);
 }
 
 static char *entry_display_name(struct job_list_entry *entry)
@@ -923,12 +938,12 @@ static int execute_next_entry(struct execute_state *state,
 	snprintf(name, sizeof(name), "%zd", idx);
 	mkdirat(resdirfd, name, 0777);
 	if ((dirfd = openat(resdirfd, name, O_DIRECTORY | O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Error accessing individual test result directory\n");
+		outf(stderr, "Error accessing individual test result directory\n");
 		return -1;
 	}
 
 	if (!open_output_files(dirfd, outputs, true)) {
-		fprintf(stderr, "Error opening output files\n");
+		outf(stderr, "Error opening output files\n");
 		result = -1;
 		goto out_dirfd;
 	}
@@ -939,13 +954,13 @@ static int execute_next_entry(struct execute_state *state,
 	}
 
 	if (pipe(outpipe) || pipe(errpipe)) {
-		fprintf(stderr, "Error creating pipes: %s\n", strerror(errno));
+		outf(stderr, "Error creating pipes: %m\n");
 		result = -1;
 		goto out_pipe;
 	}
 
 	if ((kmsgfd = open("/dev/kmsg", O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Warning: Cannot open /dev/kmsg\n");
+		outf(stderr, "Warning: Cannot open /dev/kmsg\n");
 	} else {
 		/* TODO: Checking of abort conditions in pre-execute dmesg */
 		lseek(kmsgfd, 0, SEEK_END);
@@ -955,15 +970,15 @@ static int execute_next_entry(struct execute_state *state,
 	if (settings->log_level >= LOG_LEVEL_NORMAL) {
 		char *displayname;
 		int width = digits(total);
-		printf("[%0*zd/%0*zd] ", width, idx + 1, width, total);
+		outf(stdout, "[%0*zd/%0*zd] ", width, idx + 1, width, total);
 
 		print_time_left(state, settings);
 
 		displayname = entry_display_name(entry);
-		printf("%s", displayname);
+		outf(stdout, "%s", displayname);
 		free(displayname);
 
-		printf("\n");
+		outf(stdout, "\n");
 	}
 
 	/*
@@ -975,7 +990,7 @@ static int execute_next_entry(struct execute_state *state,
 
 	child = fork();
 	if (child < 0) {
-		fprintf(stderr, "Failed to fork: %s\n", strerror(errno));
+		outf(stderr, "Failed to fork: %m\n");
 		result = -1;
 		goto out_kmsgfd;
 	} else if (child == 0) {
@@ -1027,9 +1042,8 @@ static bool clear_test_result_directory(int dirfd)
 
 	for (i = 0; i < _F_LAST; i++) {
 		if (remove_file(dirfd, filenames[i])) {
-			fprintf(stderr, "Error deleting %s from test result directory: %s\n",
-				filenames[i],
-				strerror(errno));
+			outf(stderr, "Error deleting %s from test result directory: %m\n",
+			     filenames[i]);
 			return false;
 		}
 	}
@@ -1048,7 +1062,7 @@ static bool clear_old_results(char *path)
 			return true;
 		}
 
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		outf(stderr, "Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1057,7 +1071,7 @@ static bool clear_old_results(char *path)
 	    remove_file(dirfd, "endtime.txt") ||
 	    remove_file(dirfd, "aborted.txt")) {
 		close(dirfd);
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		outf(stderr, "Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1076,9 +1090,9 @@ static bool clear_old_results(char *path)
 		}
 		close(resdirfd);
 		if (unlinkat(dirfd, name, AT_REMOVEDIR)) {
-			fprintf(stderr,
-				"Warning: Result directory %s contains extra files\n",
-				name);
+			outf(stderr,
+			     "Warning: Result directory %s contains extra files\n",
+			     name);
 		}
 	}
 
@@ -1234,11 +1248,11 @@ static void oom_immortal(void)
 
 	fd = open("/proc/self/oom_score_adj", O_WRONLY);
 	if (fd < 0) {
-		fprintf(stderr, "Warning: Cannot adjust oom score.\n");
+		outf(stderr, "Warning: Cannot adjust oom score.\n");
 		return;
 	}
 	if (write(fd, never_kill, sizeof(never_kill)) != sizeof(never_kill))
-		fprintf(stderr, "Warning: Adjusting oom score failed.\n");
+		outf(stderr, "Warning: Adjusting oom score failed.\n");
 
 	close(fd);
 }
@@ -1253,22 +1267,22 @@ static bool should_die_because_signal(int sigfd)
 
 	if (ret != 0) {
 		if (ret == -1) {
-			fprintf(stderr, "Poll on signalfd failed with %s\n", strerror(errno));
+			outf(stderr, "Poll on signalfd failed with %m\n");
 			return true; /* something is wrong, let's die */
 		}
 
 		ret = read(sigfd, &siginfo, sizeof(siginfo));
 
 		if (ret == -1) {
-			fprintf(stderr, "Error reading from signalfd: %s\n", strerror(errno));
+			outf(stderr, "Error reading from signalfd: %m\n");
 			return false; /* we may want to retry later */
 		}
 
 		if (siginfo.ssi_signo == SIGCHLD) {
-			fprintf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
+			outf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
 		} else {
-			fprintf(stderr, "Runner is being killed by %s\n",
-				strsignal(siginfo.ssi_signo));
+			outf(stderr, "Runner is being killed by %s\n",
+			     strsignal(siginfo.ssi_signo));
 			return true;
 		}
 
@@ -1289,28 +1303,27 @@ bool execute(struct execute_state *state,
 	bool status = true;
 
 	if (state->dry) {
-		printf("Dry run, not executing. Invoke igt_resume if you want to execute.\n");
+		outf(stdout, "Dry run, not executing. Invoke igt_resume if you want to execute.\n");
 		return true;
 	}
 
 	if ((resdirfd = open(settings->results_path, O_DIRECTORY | O_RDONLY)) < 0) {
 		/* Initialize state should have done this */
-		fprintf(stderr, "Error: Failure opening results path %s\n",
-			settings->results_path);
+		outf(stderr, "Error: Failure opening results path %s\n",
+		     settings->results_path);
 		return false;
 	}
 
 	if ((testdirfd = open(settings->test_root, O_DIRECTORY | O_RDONLY)) < 0) {
-		fprintf(stderr, "Error: Failure opening test root %s\n",
-			settings->test_root);
+		outf(stderr, "Error: Failure opening test root %s\n",
+		     settings->test_root);
 		close(resdirfd);
 		return false;
 	}
 
 	/* TODO: On resume, don't rewrite, verify that content matches current instead */
 	if ((unamefd = openat(resdirfd, "uname.txt", O_CREAT | O_WRONLY | O_TRUNC, 0666)) < 0) {
-		fprintf(stderr, "Error: Failure opening uname.txt: %s\n",
-			strerror(errno));
+		outf(stderr, "Error: Failure opening uname.txt: %m\n");
 		close(testdirfd);
 		close(resdirfd);
 		return false;
@@ -1339,7 +1352,7 @@ bool execute(struct execute_state *state,
 
 	if (sigfd < 0) {
 		/* TODO: Handle better */
-		fprintf(stderr, "Cannot mask signals\n");
+		outf(stderr, "Cannot mask signals\n");
 		status = false;
 		goto end;
 	}
@@ -1401,7 +1414,7 @@ bool execute(struct execute_state *state,
 
 		if (overall_timeout_exceeded(state)) {
 			if (settings->log_level >= LOG_LEVEL_NORMAL) {
-				printf("Overall timeout time exceeded, stopping.\n");
+				outf(stdout, "Overall timeout time exceeded, stopping.\n");
 			}
 
 			break;
-- 
2.23.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] [PATCH i-g-t v2] runner: Add a timestamp to each log message

[Chris Wilson]

Very handy for correlating events between different logs.

v2: Concatenate split messages into a single call (so that the timestamp
is only added once!)

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Petri Latvala <petri.latvala@intel.com>
---
 runner/executor.c | 151 +++++++++++++++++++++++++---------------------
 1 file changed, 83 insertions(+), 68 deletions(-)

diff --git a/runner/executor.c b/runner/executor.c
index 52fee7d13..4846684e4 100644
--- a/runner/executor.c
+++ b/runner/executor.c
@@ -2,6 +2,7 @@
 #include <fcntl.h>
 #include <linux/watchdog.h>
 #include <signal.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -26,13 +27,31 @@ static struct {
 	size_t num_dogs;
 } watchdogs;
 
+__attribute__((format(printf, 2, 3)))
+static void __logf__(FILE *stream, const char *fmt, ...)
+{
+	int saved_errno = errno;
+	struct timespec tv;
+	va_list ap;
+
+	if (clock_gettime(CLOCK_BOOTTIME, &tv))
+		clock_gettime(CLOCK_REALTIME, &tv);
+	fprintf(stream, "[%ld.%06ld] ", tv.tv_sec, tv.tv_nsec / 1000);
+
+	va_start(ap, fmt);
+	errno = saved_errno;
+	vfprintf(stream, fmt, ap);
+	va_end(ap);
+}
+#define outf(fmt...) __logf__(stdout, fmt)
+#define errf(fmt...) __logf__(stderr, fmt)
+
 static void __close_watchdog(int fd)
 {
 	ssize_t ret = write(fd, "V", 1);
 
 	if (ret == -1)
-		fprintf(stderr, "Failed to stop a watchdog: %s\n",
-			strerror(errno));
+		errf("Failed to stop a watchdog: %m\n");
 
 	close(fd);
 }
@@ -42,10 +61,10 @@ static void close_watchdogs(struct settings *settings)
 	size_t i;
 
 	if (settings && settings->log_level >= LOG_LEVEL_VERBOSE)
-		printf("Closing watchdogs\n");
+		outf("Closing watchdogs\n");
 
 	if (settings == NULL && watchdogs.num_dogs != 0)
-		fprintf(stderr, "Closing watchdogs from exit handler!\n");
+		errf("Closing watchdogs from exit handler!\n");
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		__close_watchdog(watchdogs.fds[i]);
@@ -73,7 +92,7 @@ static void init_watchdogs(struct settings *settings)
 		return;
 
 	if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-		printf("Initializing watchdogs\n");
+		outf("Initializing watchdogs\n");
 	}
 
 	atexit(close_watchdogs_atexit);
@@ -88,7 +107,7 @@ static void init_watchdogs(struct settings *settings)
 		watchdogs.fds[i] = fd;
 
 		if (settings->log_level >= LOG_LEVEL_VERBOSE)
-			printf(" %s\n", name);
+			outf("  %s\n", name);
 	}
 }
 
@@ -123,10 +142,8 @@ static void ping_watchdogs(void)
 
 	for (i = 0; i < watchdogs.num_dogs; i++) {
 		ret = ioctl(watchdogs.fds[i], WDIOC_KEEPALIVE, NULL);
-
 		if (ret == -1)
-			fprintf(stderr, "Failed to ping a watchdog: %s\n",
-				strerror(errno));
+			errf("Failed to ping a watchdog: %m\n");
 	}
 }
 
@@ -237,7 +254,7 @@ static char *need_to_abort(const struct settings* settings)
 			continue;
 
 		if (settings->log_level >= LOG_LEVEL_NORMAL)
-			fprintf(stderr, "Aborting: %s\n", abort);
+			errf("Aborting: %s\n", abort);
 
 		return abort;
 	}
@@ -456,7 +473,7 @@ static bool kill_child(int sig, pid_t child)
 	 */
 	kill(-child, sig);
 	if (kill(child, sig) && errno == ESRCH) {
-		fprintf(stderr, "Child process does not exist. This shouldn't happen.\n");
+		errf("Child process does not exist. This shouldn't happen.\n");
 		return false;
 	}
 
@@ -518,9 +535,8 @@ static int monitor_output(pid_t child,
 			timeout /= timeout_intervals;
 
 			if (settings->log_level >= LOG_LEVEL_VERBOSE) {
-				printf("Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
-				       "Using %d intervals of %d seconds.\n",
-				       wd_timeout, timeout_intervals, timeout);
+				outf("Watchdog doesn't support the timeout we requested (shortened to %d seconds). Using %d intervals of %d seconds.\n",
+				     wd_timeout, timeout_intervals, timeout);
 			}
 		}
 	}
@@ -555,7 +571,7 @@ static int monitor_output(pid_t child,
 			switch (killed) {
 			case 0:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGQUIT.\n");
+					outf("Timeout. Killing the current test with SIGQUIT.\n");
 					fflush(stdout);
 				}
 
@@ -573,7 +589,7 @@ static int monitor_output(pid_t child,
 				break;
 			case SIGQUIT:
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					printf("Timeout. Killing the current test with SIGKILL.\n");
+					outf("Timeout. Killing the current test with SIGKILL.\n");
 					fflush(stdout);
 				}
 
@@ -597,8 +613,8 @@ static int monitor_output(pid_t child,
 
 				/* Nothing that can be done, really. Let's tell the caller we want to abort. */
 				if (settings->log_level >= LOG_LEVEL_NORMAL) {
-					fprintf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
-						taints);
+					errf("Child refuses to die, tainted %lx. Aborting.\n",
+					     taints);
 				}
 				close_watchdogs(settings);
 				free(outbuf);
@@ -621,8 +637,7 @@ static int monitor_output(pid_t child,
 			s = read(outfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stdout: %s\n",
-						strerror(errno));
+					errf("Error reading test's stdout: %m\n");
 				}
 
 				close(outfd);
@@ -689,8 +704,7 @@ static int monitor_output(pid_t child,
 			s = read(errfd, buf, sizeof(buf));
 			if (s <= 0) {
 				if (s < 0) {
-					fprintf(stderr, "Error reading test's stderr: %s\n",
-						strerror(errno));
+					errf("Error reading test's stderr: %m\n");
 				}
 				close(errfd);
 				errfd = -1;
@@ -706,12 +720,11 @@ static int monitor_output(pid_t child,
 			s = read(kmsgfd, buf, sizeof(buf));
 			if (s < 0) {
 				if (errno != EPIPE && errno != EINVAL) {
-					fprintf(stderr, "Error reading from kmsg, stopping monitoring: %s\n",
-						strerror(errno));
+					errf("Error reading from kmsg, stopping monitoring: %m\n");
 					close(kmsgfd);
 					kmsgfd = -1;
 				} else if (errno == EINVAL) {
-					fprintf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
+					errf("Warning: Buffer too small for kernel log record, record lost.\n");
 				}
 			} else {
 				write(outputs[_F_DMESG], buf, s);
@@ -726,12 +739,11 @@ static int monitor_output(pid_t child,
 
 			s = read(sigfd, &siginfo, sizeof(siginfo));
 			if (s < 0) {
-				fprintf(stderr, "Error reading from signalfd: %s\n",
-					strerror(errno));
+				errf("Error reading from signalfd: %m\n");
 				continue;
 			} else if (siginfo.ssi_signo == SIGCHLD) {
 				if (child != waitpid(child, &status, WNOHANG)) {
-					fprintf(stderr, "Failed to reap child\n");
+					errf("Failed to reap child\n");
 					status = 9999;
 				} else if (WIFEXITED(status)) {
 					status = WEXITSTATUS(status);
@@ -746,8 +758,8 @@ static int monitor_output(pid_t child,
 			} else {
 				/* We're dying, so we're taking them with us */
 				if (settings->log_level >= LOG_LEVEL_NORMAL)
-					printf("Abort requested via %s, terminating children\n",
-					       strsignal(siginfo.ssi_signo));
+					outf("Abort requested via %s, terminating children\n",
+					     strsignal(siginfo.ssi_signo));
 
 				aborting = true;
 				timeout = 2;
@@ -836,7 +848,7 @@ execute_test_process(int outfd, int errfd,
 	}
 
 	execv(argv[0], argv);
-	fprintf(stderr, "Cannot execute %s\n", argv[0]);
+	errf("Cannot execute %s\n", argv[0]);
 	exit(IGT_EXIT_INVALID);
 }
 
@@ -852,16 +864,17 @@ static int digits(size_t num)
 	return ret;
 }
 
-static void print_time_left(struct execute_state *state,
-			    struct settings *settings)
+static int print_time_left(struct execute_state *state,
+			   struct settings *settings,
+			   char *buf, int rem)
 {
 	int width;
 
 	if (settings->overall_timeout <= 0)
-		return;
+		return 0;
 
 	width = digits(settings->overall_timeout);
-	printf("(%*.0fs left) ", width, state->time_left);
+	return snprintf(buf, rem, "(%*.0fs left) ", width, state->time_left);
 }
 
 static char *entry_display_name(struct job_list_entry *entry)
@@ -923,12 +936,12 @@ static int execute_next_entry(struct execute_state *state,
 	snprintf(name, sizeof(name), "%zd", idx);
 	mkdirat(resdirfd, name, 0777);
 	if ((dirfd = openat(resdirfd, name, O_DIRECTORY | O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Error accessing individual test result directory\n");
+		errf("Error accessing individual test result directory\n");
 		return -1;
 	}
 
 	if (!open_output_files(dirfd, outputs, true)) {
-		fprintf(stderr, "Error opening output files\n");
+		errf("Error opening output files\n");
 		result = -1;
 		goto out_dirfd;
 	}
@@ -939,13 +952,13 @@ static int execute_next_entry(struct execute_state *state,
 	}
 
 	if (pipe(outpipe) || pipe(errpipe)) {
-		fprintf(stderr, "Error creating pipes: %s\n", strerror(errno));
+		errf("Error creating pipes: %m\n");
 		result = -1;
 		goto out_pipe;
 	}
 
 	if ((kmsgfd = open("/dev/kmsg", O_RDONLY | O_CLOEXEC)) < 0) {
-		fprintf(stderr, "Warning: Cannot open /dev/kmsg\n");
+		errf("Warning: Cannot open /dev/kmsg\n");
 	} else {
 		/* TODO: Checking of abort conditions in pre-execute dmesg */
 		lseek(kmsgfd, 0, SEEK_END);
@@ -953,17 +966,22 @@ static int execute_next_entry(struct execute_state *state,
 
 
 	if (settings->log_level >= LOG_LEVEL_NORMAL) {
+		char buf[100];
 		char *displayname;
 		int width = digits(total);
-		printf("[%0*zd/%0*zd] ", width, idx + 1, width, total);
+		int len;
+
+		len = snprintf(buf, sizeof(buf),
+			       "[%0*zd/%0*zd] ", width, idx + 1, width, total);
 
-		print_time_left(state, settings);
+		len += print_time_left(state, settings,
+				       buf + len, sizeof(buf) - len);
 
 		displayname = entry_display_name(entry);
-		printf("%s", displayname);
+		len += snprintf(buf + len, sizeof(buf) - len, "%s", displayname);
 		free(displayname);
 
-		printf("\n");
+		outf("%s\n", buf);
 	}
 
 	/*
@@ -975,7 +993,7 @@ static int execute_next_entry(struct execute_state *state,
 
 	child = fork();
 	if (child < 0) {
-		fprintf(stderr, "Failed to fork: %s\n", strerror(errno));
+		errf("Failed to fork: %m\n");
 		result = -1;
 		goto out_kmsgfd;
 	} else if (child == 0) {
@@ -1027,9 +1045,8 @@ static bool clear_test_result_directory(int dirfd)
 
 	for (i = 0; i < _F_LAST; i++) {
 		if (remove_file(dirfd, filenames[i])) {
-			fprintf(stderr, "Error deleting %s from test result directory: %s\n",
-				filenames[i],
-				strerror(errno));
+			errf("Error deleting %s from test result directory: %m\n",
+			     filenames[i]);
 			return false;
 		}
 	}
@@ -1048,7 +1065,7 @@ static bool clear_old_results(char *path)
 			return true;
 		}
 
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		errf("Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1057,7 +1074,7 @@ static bool clear_old_results(char *path)
 	    remove_file(dirfd, "endtime.txt") ||
 	    remove_file(dirfd, "aborted.txt")) {
 		close(dirfd);
-		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
+		errf("Error clearing old results: %m\n");
 		return false;
 	}
 
@@ -1076,9 +1093,8 @@ static bool clear_old_results(char *path)
 		}
 		close(resdirfd);
 		if (unlinkat(dirfd, name, AT_REMOVEDIR)) {
-			fprintf(stderr,
-				"Warning: Result directory %s contains extra files\n",
-				name);
+			errf("Warning: Result directory %s contains extra files\n",
+			     name);
 		}
 	}
 
@@ -1234,11 +1250,11 @@ static void oom_immortal(void)
 
 	fd = open("/proc/self/oom_score_adj", O_WRONLY);
 	if (fd < 0) {
-		fprintf(stderr, "Warning: Cannot adjust oom score.\n");
+		errf("Warning: Cannot adjust oom score.\n");
 		return;
 	}
 	if (write(fd, never_kill, sizeof(never_kill)) != sizeof(never_kill))
-		fprintf(stderr, "Warning: Adjusting oom score failed.\n");
+		errf("Warning: Adjusting oom score failed.\n");
 
 	close(fd);
 }
@@ -1253,22 +1269,22 @@ static bool should_die_because_signal(int sigfd)
 
 	if (ret != 0) {
 		if (ret == -1) {
-			fprintf(stderr, "Poll on signalfd failed with %s\n", strerror(errno));
+			errf("Poll on signalfd failed with %m\n");
 			return true; /* something is wrong, let's die */
 		}
 
 		ret = read(sigfd, &siginfo, sizeof(siginfo));
 
 		if (ret == -1) {
-			fprintf(stderr, "Error reading from signalfd: %s\n", strerror(errno));
+			errf("Error reading from signalfd: %m\n");
 			return false; /* we may want to retry later */
 		}
 
 		if (siginfo.ssi_signo == SIGCHLD) {
-			fprintf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
+			errf("Runner got stray SIGCHLD while not executing any tests.\n");
 		} else {
-			fprintf(stderr, "Runner is being killed by %s\n",
-				strsignal(siginfo.ssi_signo));
+			errf("Runner is being killed by %s\n",
+			     strsignal(siginfo.ssi_signo));
 			return true;
 		}
 
@@ -1289,28 +1305,27 @@ bool execute(struct execute_state *state,
 	bool status = true;
 
 	if (state->dry) {
-		printf("Dry run, not executing. Invoke igt_resume if you want to execute.\n");
+		outf("Dry run, not executing. Invoke igt_resume if you want to execute.\n");
 		return true;
 	}
 
 	if ((resdirfd = open(settings->results_path, O_DIRECTORY | O_RDONLY)) < 0) {
 		/* Initialize state should have done this */
-		fprintf(stderr, "Error: Failure opening results path %s\n",
-			settings->results_path);
+		errf("Error: Failure opening results path %s\n",
+		     settings->results_path);
 		return false;
 	}
 
 	if ((testdirfd = open(settings->test_root, O_DIRECTORY | O_RDONLY)) < 0) {
-		fprintf(stderr, "Error: Failure opening test root %s\n",
-			settings->test_root);
+		errf("Error: Failure opening test root %s\n",
+		     settings->test_root);
 		close(resdirfd);
 		return false;
 	}
 
 	/* TODO: On resume, don't rewrite, verify that content matches current instead */
 	if ((unamefd = openat(resdirfd, "uname.txt", O_CREAT | O_WRONLY | O_TRUNC, 0666)) < 0) {
-		fprintf(stderr, "Error: Failure opening uname.txt: %s\n",
-			strerror(errno));
+		errf("Error: Failure opening uname.txt: %m\n");
 		close(testdirfd);
 		close(resdirfd);
 		return false;
@@ -1339,7 +1354,7 @@ bool execute(struct execute_state *state,
 
 	if (sigfd < 0) {
 		/* TODO: Handle better */
-		fprintf(stderr, "Cannot mask signals\n");
+		errf("Cannot mask signals\n");
 		status = false;
 		goto end;
 	}
@@ -1401,7 +1416,7 @@ bool execute(struct execute_state *state,
 
 		if (overall_timeout_exceeded(state)) {
 			if (settings->log_level >= LOG_LEVEL_NORMAL) {
-				printf("Overall timeout time exceeded, stopping.\n");
+				outf("Overall timeout time exceeded, stopping.\n");
 			}
 
 			break;
-- 
2.23.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message

[Petri Latvala]

On Fri, Sep 13, 2019 at 10:19:17AM +0100, Chris Wilson wrote:
> Very handy for correlating events between different logs.
> 
> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Petri Latvala <petri.latvala@intel.com>

Reviewed-by: Petri Latvala <petri.latvala@intel.com>


> ---
>  runner/executor.c | 141 +++++++++++++++++++++++++---------------------
>  1 file changed, 77 insertions(+), 64 deletions(-)
> 
> diff --git a/runner/executor.c b/runner/executor.c
> index 52fee7d13..d8b64a3fb 100644
> --- a/runner/executor.c
> +++ b/runner/executor.c
> @@ -2,6 +2,7 @@
>  #include <fcntl.h>
>  #include <linux/watchdog.h>
>  #include <signal.h>
> +#include <stdarg.h>
>  #include <stdio.h>
>  #include <stdlib.h>
>  #include <string.h>
> @@ -26,13 +27,29 @@ static struct {
>  	size_t num_dogs;
>  } watchdogs;
>  
> +__attribute__((format(printf, 2, 3)))
> +static void outf(FILE *stream, const char *fmt, ...)
> +{
> +	int saved_errno = errno;
> +	struct timespec tv;
> +	va_list ap;
> +
> +	if (clock_gettime(CLOCK_BOOTTIME, &tv))
> +		clock_gettime(CLOCK_REALTIME, &tv);
> +	fprintf(stream, "[%ld.%06ld] ", tv.tv_sec, tv.tv_nsec / 1000);
> +
> +	va_start(ap, fmt);
> +	errno = saved_errno;
> +	vfprintf(stream, fmt, ap);
> +	va_end(ap);
> +}
> +
>  static void __close_watchdog(int fd)
>  {
>  	ssize_t ret = write(fd, "V", 1);
>  
>  	if (ret == -1)
> -		fprintf(stderr, "Failed to stop a watchdog: %s\n",
> -			strerror(errno));
> +		outf(stderr, "Failed to stop a watchdog: %m\n");
>  
>  	close(fd);
>  }
> @@ -42,10 +59,10 @@ static void close_watchdogs(struct settings *settings)
>  	size_t i;
>  
>  	if (settings && settings->log_level >= LOG_LEVEL_VERBOSE)
> -		printf("Closing watchdogs\n");
> +		outf(stdout, "Closing watchdogs\n");
>  
>  	if (settings == NULL && watchdogs.num_dogs != 0)
> -		fprintf(stderr, "Closing watchdogs from exit handler!\n");
> +		outf(stderr, "Closing watchdogs from exit handler!\n");
>  
>  	for (i = 0; i < watchdogs.num_dogs; i++) {
>  		__close_watchdog(watchdogs.fds[i]);
> @@ -73,7 +90,7 @@ static void init_watchdogs(struct settings *settings)
>  		return;
>  
>  	if (settings->log_level >= LOG_LEVEL_VERBOSE) {
> -		printf("Initializing watchdogs\n");
> +		outf(stdout, "Initializing watchdogs\n");
>  	}
>  
>  	atexit(close_watchdogs_atexit);
> @@ -88,7 +105,7 @@ static void init_watchdogs(struct settings *settings)
>  		watchdogs.fds[i] = fd;
>  
>  		if (settings->log_level >= LOG_LEVEL_VERBOSE)
> -			printf(" %s\n", name);
> +			outf(stdout, " %s\n", name);
>  	}
>  }
>  
> @@ -123,10 +140,8 @@ static void ping_watchdogs(void)
>  
>  	for (i = 0; i < watchdogs.num_dogs; i++) {
>  		ret = ioctl(watchdogs.fds[i], WDIOC_KEEPALIVE, NULL);
> -
>  		if (ret == -1)
> -			fprintf(stderr, "Failed to ping a watchdog: %s\n",
> -				strerror(errno));
> +			outf(stderr, "Failed to ping a watchdog: %m\n");
>  	}
>  }
>  
> @@ -237,7 +252,7 @@ static char *need_to_abort(const struct settings* settings)
>  			continue;
>  
>  		if (settings->log_level >= LOG_LEVEL_NORMAL)
> -			fprintf(stderr, "Aborting: %s\n", abort);
> +			outf(stderr, "Aborting: %s\n", abort);
>  
>  		return abort;
>  	}
> @@ -456,7 +471,7 @@ static bool kill_child(int sig, pid_t child)
>  	 */
>  	kill(-child, sig);
>  	if (kill(child, sig) && errno == ESRCH) {
> -		fprintf(stderr, "Child process does not exist. This shouldn't happen.\n");
> +		outf(stderr, "Child process does not exist. This shouldn't happen.\n");
>  		return false;
>  	}
>  
> @@ -518,9 +533,10 @@ static int monitor_output(pid_t child,
>  			timeout /= timeout_intervals;
>  
>  			if (settings->log_level >= LOG_LEVEL_VERBOSE) {
> -				printf("Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
> -				       "Using %d intervals of %d seconds.\n",
> -				       wd_timeout, timeout_intervals, timeout);
> +				outf(stdout,
> +				     "Watchdog doesn't support the timeout we requested (shortened to %d seconds).\n"
> +				     "Using %d intervals of %d seconds.\n",
> +				     wd_timeout, timeout_intervals, timeout);
>  			}
>  		}
>  	}
> @@ -555,7 +571,8 @@ static int monitor_output(pid_t child,
>  			switch (killed) {
>  			case 0:
>  				if (settings->log_level >= LOG_LEVEL_NORMAL) {
> -					printf("Timeout. Killing the current test with SIGQUIT.\n");
> +					outf(stdout,
> +					     "Timeout. Killing the current test with SIGQUIT.\n");
>  					fflush(stdout);
>  				}
>  
> @@ -573,7 +590,8 @@ static int monitor_output(pid_t child,
>  				break;
>  			case SIGQUIT:
>  				if (settings->log_level >= LOG_LEVEL_NORMAL) {
> -					printf("Timeout. Killing the current test with SIGKILL.\n");
> +					outf(stdout,
> +					     "Timeout. Killing the current test with SIGKILL.\n");
>  					fflush(stdout);
>  				}
>  
> @@ -597,8 +615,8 @@ static int monitor_output(pid_t child,
>  
>  				/* Nothing that can be done, really. Let's tell the caller we want to abort. */
>  				if (settings->log_level >= LOG_LEVEL_NORMAL) {
> -					fprintf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
> -						taints);
> +					outf(stderr, "Child refuses to die, tainted %lx. Aborting.\n",
> +					     taints);
>  				}
>  				close_watchdogs(settings);
>  				free(outbuf);
> @@ -621,8 +639,7 @@ static int monitor_output(pid_t child,
>  			s = read(outfd, buf, sizeof(buf));
>  			if (s <= 0) {
>  				if (s < 0) {
> -					fprintf(stderr, "Error reading test's stdout: %s\n",
> -						strerror(errno));
> +					outf(stderr, "Error reading test's stdout: %m\n");
>  				}
>  
>  				close(outfd);
> @@ -689,8 +706,7 @@ static int monitor_output(pid_t child,
>  			s = read(errfd, buf, sizeof(buf));
>  			if (s <= 0) {
>  				if (s < 0) {
> -					fprintf(stderr, "Error reading test's stderr: %s\n",
> -						strerror(errno));
> +					outf(stderr, "Error reading test's stderr: %m\n");
>  				}
>  				close(errfd);
>  				errfd = -1;
> @@ -706,12 +722,11 @@ static int monitor_output(pid_t child,
>  			s = read(kmsgfd, buf, sizeof(buf));
>  			if (s < 0) {
>  				if (errno != EPIPE && errno != EINVAL) {
> -					fprintf(stderr, "Error reading from kmsg, stopping monitoring: %s\n",
> -						strerror(errno));
> +					outf(stderr, "Error reading from kmsg, stopping monitoring: %m\n");
>  					close(kmsgfd);
>  					kmsgfd = -1;
>  				} else if (errno == EINVAL) {
> -					fprintf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
> +					outf(stderr, "Warning: Buffer too small for kernel log record, record lost.\n");
>  				}
>  			} else {
>  				write(outputs[_F_DMESG], buf, s);
> @@ -726,12 +741,11 @@ static int monitor_output(pid_t child,
>  
>  			s = read(sigfd, &siginfo, sizeof(siginfo));
>  			if (s < 0) {
> -				fprintf(stderr, "Error reading from signalfd: %s\n",
> -					strerror(errno));
> +				outf(stderr, "Error reading from signalfd: %m\n");
>  				continue;
>  			} else if (siginfo.ssi_signo == SIGCHLD) {
>  				if (child != waitpid(child, &status, WNOHANG)) {
> -					fprintf(stderr, "Failed to reap child\n");
> +					outf(stderr, "Failed to reap child\n");
>  					status = 9999;
>  				} else if (WIFEXITED(status)) {
>  					status = WEXITSTATUS(status);
> @@ -746,8 +760,9 @@ static int monitor_output(pid_t child,
>  			} else {
>  				/* We're dying, so we're taking them with us */
>  				if (settings->log_level >= LOG_LEVEL_NORMAL)
> -					printf("Abort requested via %s, terminating children\n",
> -					       strsignal(siginfo.ssi_signo));
> +					outf(stdout,
> +					     "Abort requested via %s, terminating children\n",
> +					     strsignal(siginfo.ssi_signo));
>  
>  				aborting = true;
>  				timeout = 2;
> @@ -836,7 +851,7 @@ execute_test_process(int outfd, int errfd,
>  	}
>  
>  	execv(argv[0], argv);
> -	fprintf(stderr, "Cannot execute %s\n", argv[0]);
> +	outf(stderr, "Cannot execute %s\n", argv[0]);
>  	exit(IGT_EXIT_INVALID);
>  }
>  
> @@ -861,7 +876,7 @@ static void print_time_left(struct execute_state *state,
>  		return;
>  
>  	width = digits(settings->overall_timeout);
> -	printf("(%*.0fs left) ", width, state->time_left);
> +	outf(stdout, "(%*.0fs left) ", width, state->time_left);
>  }
>  
>  static char *entry_display_name(struct job_list_entry *entry)
> @@ -923,12 +938,12 @@ static int execute_next_entry(struct execute_state *state,
>  	snprintf(name, sizeof(name), "%zd", idx);
>  	mkdirat(resdirfd, name, 0777);
>  	if ((dirfd = openat(resdirfd, name, O_DIRECTORY | O_RDONLY | O_CLOEXEC)) < 0) {
> -		fprintf(stderr, "Error accessing individual test result directory\n");
> +		outf(stderr, "Error accessing individual test result directory\n");
>  		return -1;
>  	}
>  
>  	if (!open_output_files(dirfd, outputs, true)) {
> -		fprintf(stderr, "Error opening output files\n");
> +		outf(stderr, "Error opening output files\n");
>  		result = -1;
>  		goto out_dirfd;
>  	}
> @@ -939,13 +954,13 @@ static int execute_next_entry(struct execute_state *state,
>  	}
>  
>  	if (pipe(outpipe) || pipe(errpipe)) {
> -		fprintf(stderr, "Error creating pipes: %s\n", strerror(errno));
> +		outf(stderr, "Error creating pipes: %m\n");
>  		result = -1;
>  		goto out_pipe;
>  	}
>  
>  	if ((kmsgfd = open("/dev/kmsg", O_RDONLY | O_CLOEXEC)) < 0) {
> -		fprintf(stderr, "Warning: Cannot open /dev/kmsg\n");
> +		outf(stderr, "Warning: Cannot open /dev/kmsg\n");
>  	} else {
>  		/* TODO: Checking of abort conditions in pre-execute dmesg */
>  		lseek(kmsgfd, 0, SEEK_END);
> @@ -955,15 +970,15 @@ static int execute_next_entry(struct execute_state *state,
>  	if (settings->log_level >= LOG_LEVEL_NORMAL) {
>  		char *displayname;
>  		int width = digits(total);
> -		printf("[%0*zd/%0*zd] ", width, idx + 1, width, total);
> +		outf(stdout, "[%0*zd/%0*zd] ", width, idx + 1, width, total);
>  
>  		print_time_left(state, settings);
>  
>  		displayname = entry_display_name(entry);
> -		printf("%s", displayname);
> +		outf(stdout, "%s", displayname);
>  		free(displayname);
>  
> -		printf("\n");
> +		outf(stdout, "\n");
>  	}
>  
>  	/*
> @@ -975,7 +990,7 @@ static int execute_next_entry(struct execute_state *state,
>  
>  	child = fork();
>  	if (child < 0) {
> -		fprintf(stderr, "Failed to fork: %s\n", strerror(errno));
> +		outf(stderr, "Failed to fork: %m\n");
>  		result = -1;
>  		goto out_kmsgfd;
>  	} else if (child == 0) {
> @@ -1027,9 +1042,8 @@ static bool clear_test_result_directory(int dirfd)
>  
>  	for (i = 0; i < _F_LAST; i++) {
>  		if (remove_file(dirfd, filenames[i])) {
> -			fprintf(stderr, "Error deleting %s from test result directory: %s\n",
> -				filenames[i],
> -				strerror(errno));
> +			outf(stderr, "Error deleting %s from test result directory: %m\n",
> +			     filenames[i]);
>  			return false;
>  		}
>  	}
> @@ -1048,7 +1062,7 @@ static bool clear_old_results(char *path)
>  			return true;
>  		}
>  
> -		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
> +		outf(stderr, "Error clearing old results: %m\n");
>  		return false;
>  	}
>  
> @@ -1057,7 +1071,7 @@ static bool clear_old_results(char *path)
>  	    remove_file(dirfd, "endtime.txt") ||
>  	    remove_file(dirfd, "aborted.txt")) {
>  		close(dirfd);
> -		fprintf(stderr, "Error clearing old results: %s\n", strerror(errno));
> +		outf(stderr, "Error clearing old results: %m\n");
>  		return false;
>  	}
>  
> @@ -1076,9 +1090,9 @@ static bool clear_old_results(char *path)
>  		}
>  		close(resdirfd);
>  		if (unlinkat(dirfd, name, AT_REMOVEDIR)) {
> -			fprintf(stderr,
> -				"Warning: Result directory %s contains extra files\n",
> -				name);
> +			outf(stderr,
> +			     "Warning: Result directory %s contains extra files\n",
> +			     name);
>  		}
>  	}
>  
> @@ -1234,11 +1248,11 @@ static void oom_immortal(void)
>  
>  	fd = open("/proc/self/oom_score_adj", O_WRONLY);
>  	if (fd < 0) {
> -		fprintf(stderr, "Warning: Cannot adjust oom score.\n");
> +		outf(stderr, "Warning: Cannot adjust oom score.\n");
>  		return;
>  	}
>  	if (write(fd, never_kill, sizeof(never_kill)) != sizeof(never_kill))
> -		fprintf(stderr, "Warning: Adjusting oom score failed.\n");
> +		outf(stderr, "Warning: Adjusting oom score failed.\n");
>  
>  	close(fd);
>  }
> @@ -1253,22 +1267,22 @@ static bool should_die_because_signal(int sigfd)
>  
>  	if (ret != 0) {
>  		if (ret == -1) {
> -			fprintf(stderr, "Poll on signalfd failed with %s\n", strerror(errno));
> +			outf(stderr, "Poll on signalfd failed with %m\n");
>  			return true; /* something is wrong, let's die */
>  		}
>  
>  		ret = read(sigfd, &siginfo, sizeof(siginfo));
>  
>  		if (ret == -1) {
> -			fprintf(stderr, "Error reading from signalfd: %s\n", strerror(errno));
> +			outf(stderr, "Error reading from signalfd: %m\n");
>  			return false; /* we may want to retry later */
>  		}
>  
>  		if (siginfo.ssi_signo == SIGCHLD) {
> -			fprintf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
> +			outf(stderr, "Runner got stray SIGCHLD while not executing any tests.\n");
>  		} else {
> -			fprintf(stderr, "Runner is being killed by %s\n",
> -				strsignal(siginfo.ssi_signo));
> +			outf(stderr, "Runner is being killed by %s\n",
> +			     strsignal(siginfo.ssi_signo));
>  			return true;
>  		}
>  
> @@ -1289,28 +1303,27 @@ bool execute(struct execute_state *state,
>  	bool status = true;
>  
>  	if (state->dry) {
> -		printf("Dry run, not executing. Invoke igt_resume if you want to execute.\n");
> +		outf(stdout, "Dry run, not executing. Invoke igt_resume if you want to execute.\n");
>  		return true;
>  	}
>  
>  	if ((resdirfd = open(settings->results_path, O_DIRECTORY | O_RDONLY)) < 0) {
>  		/* Initialize state should have done this */
> -		fprintf(stderr, "Error: Failure opening results path %s\n",
> -			settings->results_path);
> +		outf(stderr, "Error: Failure opening results path %s\n",
> +		     settings->results_path);
>  		return false;
>  	}
>  
>  	if ((testdirfd = open(settings->test_root, O_DIRECTORY | O_RDONLY)) < 0) {
> -		fprintf(stderr, "Error: Failure opening test root %s\n",
> -			settings->test_root);
> +		outf(stderr, "Error: Failure opening test root %s\n",
> +		     settings->test_root);
>  		close(resdirfd);
>  		return false;
>  	}
>  
>  	/* TODO: On resume, don't rewrite, verify that content matches current instead */
>  	if ((unamefd = openat(resdirfd, "uname.txt", O_CREAT | O_WRONLY | O_TRUNC, 0666)) < 0) {
> -		fprintf(stderr, "Error: Failure opening uname.txt: %s\n",
> -			strerror(errno));
> +		outf(stderr, "Error: Failure opening uname.txt: %m\n");
>  		close(testdirfd);
>  		close(resdirfd);
>  		return false;
> @@ -1339,7 +1352,7 @@ bool execute(struct execute_state *state,
>  
>  	if (sigfd < 0) {
>  		/* TODO: Handle better */
> -		fprintf(stderr, "Cannot mask signals\n");
> +		outf(stderr, "Cannot mask signals\n");
>  		status = false;
>  		goto end;
>  	}
> @@ -1401,7 +1414,7 @@ bool execute(struct execute_state *state,
>  
>  		if (overall_timeout_exceeded(state)) {
>  			if (settings->log_level >= LOG_LEVEL_NORMAL) {
> -				printf("Overall timeout time exceeded, stopping.\n");
> +				outf(stdout, "Overall timeout time exceeded, stopping.\n");
>  			}
>  
>  			break;
> -- 
> 2.23.0
> 
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✓ Fi.CI.BAT: success for runner: Add a timestamp to each log message (rev3)

[Patchwork]

== Series Details ==

Series: runner: Add a timestamp to each log message (rev3)
URL   : https://patchwork.freedesktop.org/series/66644/
State : success

== Summary ==

CI Bug Log - changes from CI_DRM_6888 -> IGTPW_3452
====================================================

Summary
-------

  **SUCCESS**

  No regressions found.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/66644/revisions/3/mbox/

Possible new issues
-------------------

  Here are the unknown changes that may have been introduced in IGTPW_3452:

### IGT changes ###

#### Suppressed ####

  The following results come from untrusted machines, tests, or statuses.
  They do not affect the overall result.

  * igt@i915_pm_rpm@basic-pci-d3-state:
    - {fi-tgl-u}:         NOTRUN -> [SKIP][1]
   [1]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-tgl-u/igt@i915_pm_rpm@basic-pci-d3-state.html

  * igt@i915_pm_rpm@basic-rte:
    - {fi-tgl-u}:         NOTRUN -> [FAIL][2]
   [2]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-tgl-u/igt@i915_pm_rpm@basic-rte.html

  
Known issues
------------

  Here are the changes found in IGTPW_3452 that come from known issues:

### IGT changes ###

#### Issues hit ####

  * igt@gem_exec_suspend@basic-s3:
    - fi-blb-e6850:       [PASS][3] -> [INCOMPLETE][4] ([fdo#107718])
   [3]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-blb-e6850/igt@gem_exec_suspend@basic-s3.html
   [4]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-blb-e6850/igt@gem_exec_suspend@basic-s3.html

  * igt@prime_vgem@basic-read:
    - fi-icl-u3:          [PASS][5] -> [DMESG-WARN][6] ([fdo#107724])
   [5]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-icl-u3/igt@prime_vgem@basic-read.html
   [6]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-icl-u3/igt@prime_vgem@basic-read.html

  
#### Possible fixes ####

  * igt@gem_ctx_create@basic:
    - fi-bxt-dsi:         [INCOMPLETE][7] ([fdo#103927]) -> [PASS][8]
   [7]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-bxt-dsi/igt@gem_ctx_create@basic.html
   [8]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-bxt-dsi/igt@gem_ctx_create@basic.html

  * igt@gem_ctx_create@basic-files:
    - {fi-tgl-u2}:        [INCOMPLETE][9] -> [PASS][10]
   [9]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-tgl-u2/igt@gem_ctx_create@basic-files.html
   [10]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-tgl-u2/igt@gem_ctx_create@basic-files.html

  * igt@gem_exec_gttfill@basic:
    - {fi-tgl-u}:         [INCOMPLETE][11] ([fdo#111593]) -> [PASS][12]
   [11]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-tgl-u/igt@gem_exec_gttfill@basic.html
   [12]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-tgl-u/igt@gem_exec_gttfill@basic.html

  * igt@gem_exec_suspend@basic-s4-devices:
    - fi-icl-u3:          [DMESG-WARN][13] ([fdo#107724]) -> [PASS][14] +2 similar issues
   [13]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-icl-u3/igt@gem_exec_suspend@basic-s4-devices.html
   [14]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-icl-u3/igt@gem_exec_suspend@basic-s4-devices.html

  * igt@kms_frontbuffer_tracking@basic:
    - fi-hsw-peppy:       [DMESG-WARN][15] ([fdo#102614]) -> [PASS][16]
   [15]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/fi-hsw-peppy/igt@kms_frontbuffer_tracking@basic.html
   [16]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/fi-hsw-peppy/igt@kms_frontbuffer_tracking@basic.html

  
  {name}: This element is suppressed. This means it is ignored when computing
          the status of the difference (SUCCESS, WARNING, or FAILURE).

  [fdo#102614]: https://bugs.freedesktop.org/show_bug.cgi?id=102614
  [fdo#103927]: https://bugs.freedesktop.org/show_bug.cgi?id=103927
  [fdo#106107]: https://bugs.freedesktop.org/show_bug.cgi?id=106107
  [fdo#106350]: https://bugs.freedesktop.org/show_bug.cgi?id=106350
  [fdo#107718]: https://bugs.freedesktop.org/show_bug.cgi?id=107718
  [fdo#107724]: https://bugs.freedesktop.org/show_bug.cgi?id=107724
  [fdo#111593]: https://bugs.freedesktop.org/show_bug.cgi?id=111593
  [fdo#111600]: https://bugs.freedesktop.org/show_bug.cgi?id=111600


Participating hosts (54 -> 44)
------------------------------

  Missing    (10): fi-ilk-m540 fi-cml-s fi-hsw-4200u fi-byt-squawks fi-bsw-cyan fi-ivb-3770 fi-pnv-d510 fi-icl-y fi-byt-clapper fi-bdw-samus 


Build changes
-------------

  * CI: CI-20190529 -> None
  * IGT: IGT_5179 -> IGTPW_3452

  CI-20190529: 20190529
  CI_DRM_6888: 52e9cd0877ee673ba1bb80c7c7be2e53c0821084 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_3452: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/
  IGT_5179: 3374cd0b048f9c277b2815bf80502f9f89680176 @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message

[Chris Wilson]

Quoting Petri Latvala (2019-09-13 10:38:34)
> On Fri, Sep 13, 2019 at 10:19:17AM +0100, Chris Wilson wrote:
> > Very handy for correlating events between different logs.
> > 
> > Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Petri Latvala <petri.latvala@intel.com>
> 
> Reviewed-by: Petri Latvala <petri.latvala@intel.com>

Put an example of the igt_runner0.txt output (with the mixed message
formats) and pushed. Let's see if this helps solve some of the
mysteries.
-Chris
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✓ Fi.CI.IGT: success for runner: Add a timestamp to each log message (rev3)

[Patchwork]

== Series Details ==

Series: runner: Add a timestamp to each log message (rev3)
URL   : https://patchwork.freedesktop.org/series/66644/
State : success

== Summary ==

CI Bug Log - changes from CI_DRM_6888_full -> IGTPW_3452_full
====================================================

Summary
-------

  **SUCCESS**

  No regressions found.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/66644/revisions/3/mbox/

Known issues
------------

  Here are the changes found in IGTPW_3452_full that come from known issues:

### IGT changes ###

#### Issues hit ####

  * igt@gem_eio@reset-stress:
    - shard-glk:          [PASS][1] -> [FAIL][2] ([fdo#109661])
   [1]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-glk6/igt@gem_eio@reset-stress.html
   [2]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-glk3/igt@gem_eio@reset-stress.html

  * igt@gem_exec_schedule@deep-bsd:
    - shard-iclb:         [PASS][3] -> [SKIP][4] ([fdo#111325]) +4 similar issues
   [3]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb6/igt@gem_exec_schedule@deep-bsd.html
   [4]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb4/igt@gem_exec_schedule@deep-bsd.html

  * igt@gem_exec_schedule@reorder-wide-bsd1:
    - shard-iclb:         [PASS][5] -> [SKIP][6] ([fdo#109276]) +13 similar issues
   [5]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb2/igt@gem_exec_schedule@reorder-wide-bsd1.html
   [6]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb5/igt@gem_exec_schedule@reorder-wide-bsd1.html

  * igt@i915_pm_rpm@modeset-stress-extra-wait:
    - shard-glk:          [PASS][7] -> [DMESG-WARN][8] ([fdo#105763] / [fdo#106538])
   [7]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-glk2/igt@i915_pm_rpm@modeset-stress-extra-wait.html
   [8]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-glk8/igt@i915_pm_rpm@modeset-stress-extra-wait.html

  * igt@i915_suspend@fence-restore-untiled:
    - shard-apl:          [PASS][9] -> [DMESG-WARN][10] ([fdo#108566]) +5 similar issues
   [9]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-apl5/igt@i915_suspend@fence-restore-untiled.html
   [10]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-apl1/igt@i915_suspend@fence-restore-untiled.html

  * igt@kms_cursor_legacy@2x-long-cursor-vs-flip-atomic:
    - shard-hsw:          [PASS][11] -> [FAIL][12] ([fdo#105767])
   [11]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-hsw5/igt@kms_cursor_legacy@2x-long-cursor-vs-flip-atomic.html
   [12]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-hsw8/igt@kms_cursor_legacy@2x-long-cursor-vs-flip-atomic.html

  * igt@kms_flip@2x-flip-vs-suspend-interruptible:
    - shard-hsw:          [PASS][13] -> [INCOMPLETE][14] ([fdo#103540]) +1 similar issue
   [13]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-hsw4/igt@kms_flip@2x-flip-vs-suspend-interruptible.html
   [14]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-hsw4/igt@kms_flip@2x-flip-vs-suspend-interruptible.html

  * igt@kms_flip@busy-flip:
    - shard-iclb:         [PASS][15] -> [INCOMPLETE][16] ([fdo#107713])
   [15]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb1/igt@kms_flip@busy-flip.html
   [16]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb7/igt@kms_flip@busy-flip.html

  * igt@kms_frontbuffer_tracking@fbc-1p-primscrn-shrfb-plflip-blt:
    - shard-iclb:         [PASS][17] -> [FAIL][18] ([fdo#103167]) +4 similar issues
   [17]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb5/igt@kms_frontbuffer_tracking@fbc-1p-primscrn-shrfb-plflip-blt.html
   [18]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb5/igt@kms_frontbuffer_tracking@fbc-1p-primscrn-shrfb-plflip-blt.html

  * igt@kms_frontbuffer_tracking@fbc-2p-scndscrn-spr-indfb-draw-render:
    - shard-glk:          [PASS][19] -> [FAIL][20] ([fdo#103167])
   [19]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-glk2/igt@kms_frontbuffer_tracking@fbc-2p-scndscrn-spr-indfb-draw-render.html
   [20]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-glk3/igt@kms_frontbuffer_tracking@fbc-2p-scndscrn-spr-indfb-draw-render.html

  * igt@kms_frontbuffer_tracking@psr-1p-primscrn-cur-indfb-draw-mmap-wc:
    - shard-iclb:         [PASS][21] -> [FAIL][22] ([fdo#109247]) +4 similar issues
   [21]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb1/igt@kms_frontbuffer_tracking@psr-1p-primscrn-cur-indfb-draw-mmap-wc.html
   [22]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb2/igt@kms_frontbuffer_tracking@psr-1p-primscrn-cur-indfb-draw-mmap-wc.html

  * igt@kms_setmode@basic:
    - shard-apl:          [PASS][23] -> [FAIL][24] ([fdo#99912])
   [23]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-apl1/igt@kms_setmode@basic.html
   [24]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-apl7/igt@kms_setmode@basic.html

  
#### Possible fixes ####

  * igt@gem_eio@reset-stress:
    - shard-iclb:         [FAIL][25] ([fdo#109661]) -> [PASS][26]
   [25]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb8/igt@gem_eio@reset-stress.html
   [26]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb4/igt@gem_eio@reset-stress.html

  * igt@gem_exec_schedule@preemptive-hang-bsd:
    - shard-iclb:         [SKIP][27] ([fdo#111325]) -> [PASS][28] +6 similar issues
   [27]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb1/igt@gem_exec_schedule@preemptive-hang-bsd.html
   [28]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb6/igt@gem_exec_schedule@preemptive-hang-bsd.html

  * igt@gem_softpin@softpin:
    - shard-apl:          [INCOMPLETE][29] ([fdo#103927]) -> [PASS][30]
   [29]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-apl5/igt@gem_softpin@softpin.html
   [30]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-apl6/igt@gem_softpin@softpin.html

  * igt@gem_tiled_swapping@non-threaded:
    - shard-kbl:          [DMESG-WARN][31] ([fdo#108686]) -> [PASS][32]
   [31]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-kbl2/igt@gem_tiled_swapping@non-threaded.html
   [32]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-kbl1/igt@gem_tiled_swapping@non-threaded.html

  * igt@i915_suspend@fence-restore-tiled2untiled:
    - shard-apl:          [DMESG-WARN][33] ([fdo#108566]) -> [PASS][34] +5 similar issues
   [33]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-apl1/igt@i915_suspend@fence-restore-tiled2untiled.html
   [34]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-apl6/igt@i915_suspend@fence-restore-tiled2untiled.html

  * igt@kms_cursor_crc@pipe-c-cursor-64x21-sliding:
    - shard-apl:          [FAIL][35] ([fdo#103232]) -> [PASS][36]
   [35]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-apl2/igt@kms_cursor_crc@pipe-c-cursor-64x21-sliding.html
   [36]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-apl3/igt@kms_cursor_crc@pipe-c-cursor-64x21-sliding.html
    - shard-kbl:          [FAIL][37] ([fdo#103232]) -> [PASS][38]
   [37]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-kbl4/igt@kms_cursor_crc@pipe-c-cursor-64x21-sliding.html
   [38]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-kbl6/igt@kms_cursor_crc@pipe-c-cursor-64x21-sliding.html

  * igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions:
    - shard-hsw:          [FAIL][39] ([fdo#103355]) -> [PASS][40]
   [39]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-hsw6/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions.html
   [40]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-hsw4/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions.html

  * igt@kms_flip@2x-flip-vs-fences-interruptible:
    - shard-hsw:          [INCOMPLETE][41] ([fdo#103540]) -> [PASS][42]
   [41]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-hsw4/igt@kms_flip@2x-flip-vs-fences-interruptible.html
   [42]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-hsw1/igt@kms_flip@2x-flip-vs-fences-interruptible.html

  * igt@kms_frontbuffer_tracking@fbc-1p-primscrn-spr-indfb-draw-pwrite:
    - shard-iclb:         [FAIL][43] ([fdo#103167]) -> [PASS][44] +7 similar issues
   [43]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb6/igt@kms_frontbuffer_tracking@fbc-1p-primscrn-spr-indfb-draw-pwrite.html
   [44]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb7/igt@kms_frontbuffer_tracking@fbc-1p-primscrn-spr-indfb-draw-pwrite.html

  * igt@kms_psr@psr2_dpms:
    - shard-iclb:         [SKIP][45] ([fdo#109441]) -> [PASS][46] +1 similar issue
   [45]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb4/igt@kms_psr@psr2_dpms.html
   [46]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb2/igt@kms_psr@psr2_dpms.html

  * igt@kms_setmode@basic:
    - shard-kbl:          [FAIL][47] ([fdo#99912]) -> [PASS][48]
   [47]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-kbl6/igt@kms_setmode@basic.html
   [48]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-kbl2/igt@kms_setmode@basic.html

  * igt@kms_vblank@pipe-b-query-forked-hang:
    - shard-iclb:         [INCOMPLETE][49] ([fdo#107713]) -> [PASS][50]
   [49]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb7/igt@kms_vblank@pipe-b-query-forked-hang.html
   [50]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb6/igt@kms_vblank@pipe-b-query-forked-hang.html

  * igt@prime_busy@hang-bsd2:
    - shard-iclb:         [SKIP][51] ([fdo#109276]) -> [PASS][52] +13 similar issues
   [51]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb5/igt@prime_busy@hang-bsd2.html
   [52]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb2/igt@prime_busy@hang-bsd2.html

  
#### Warnings ####

  * igt@gem_mocs_settings@mocs-rc6-bsd2:
    - shard-iclb:         [SKIP][53] ([fdo#109276]) -> [FAIL][54] ([fdo#111330])
   [53]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb5/igt@gem_mocs_settings@mocs-rc6-bsd2.html
   [54]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb4/igt@gem_mocs_settings@mocs-rc6-bsd2.html

  * igt@gem_mocs_settings@mocs-reset-bsd2:
    - shard-iclb:         [FAIL][55] ([fdo#111330]) -> [SKIP][56] ([fdo#109276]) +1 similar issue
   [55]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6888/shard-iclb1/igt@gem_mocs_settings@mocs-reset-bsd2.html
   [56]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/shard-iclb6/igt@gem_mocs_settings@mocs-reset-bsd2.html

  
  [fdo#103167]: https://bugs.freedesktop.org/show_bug.cgi?id=103167
  [fdo#103232]: https://bugs.freedesktop.org/show_bug.cgi?id=103232
  [fdo#103355]: https://bugs.freedesktop.org/show_bug.cgi?id=103355
  [fdo#103540]: https://bugs.freedesktop.org/show_bug.cgi?id=103540
  [fdo#103927]: https://bugs.freedesktop.org/show_bug.cgi?id=103927
  [fdo#105763]: https://bugs.freedesktop.org/show_bug.cgi?id=105763
  [fdo#105767]: https://bugs.freedesktop.org/show_bug.cgi?id=105767
  [fdo#106538]: https://bugs.freedesktop.org/show_bug.cgi?id=106538
  [fdo#107713]: https://bugs.freedesktop.org/show_bug.cgi?id=107713
  [fdo#108566]: https://bugs.freedesktop.org/show_bug.cgi?id=108566
  [fdo#108686]: https://bugs.freedesktop.org/show_bug.cgi?id=108686
  [fdo#109247]: https://bugs.freedesktop.org/show_bug.cgi?id=109247
  [fdo#109276]: https://bugs.freedesktop.org/show_bug.cgi?id=109276
  [fdo#109441]: https://bugs.freedesktop.org/show_bug.cgi?id=109441
  [fdo#109661]: https://bugs.freedesktop.org/show_bug.cgi?id=109661
  [fdo#111325]: https://bugs.freedesktop.org/show_bug.cgi?id=111325
  [fdo#111330]: https://bugs.freedesktop.org/show_bug.cgi?id=111330
  [fdo#99912]: https://bugs.freedesktop.org/show_bug.cgi?id=99912


Participating hosts (10 -> 6)
------------------------------

  Missing    (4): pig-skl-6260u shard-skl pig-hsw-4770r pig-glk-j5005 


Build changes
-------------

  * CI: CI-20190529 -> None
  * IGT: IGT_5179 -> IGTPW_3452
  * Piglit: piglit_4509 -> None

  CI-20190529: 20190529
  CI_DRM_6888: 52e9cd0877ee673ba1bb80c7c7be2e53c0821084 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_3452: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/
  IGT_5179: 3374cd0b048f9c277b2815bf80502f9f89680176 @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  piglit_4509: fdc5a4ca11124ab8413c7988896eec4c97336694 @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_3452/
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev