public inbox for igt-dev@lists.freedesktop.org
 help / color / mirror / Atom feed
* [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
@ 2019-09-13  9:17 Chris Wilson
  2019-09-13  9:19 ` Chris Wilson
                   ` (3 more replies)
  0 siblings, 4 replies; 7+ messages in thread
From: Chris Wilson @ 2019-09-13  9:17 UTC (permalink / raw)
  To: igt-dev; +Cc: Petri Latvala

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

^ permalink raw reply related	[flat|nested] 7+ messages in thread
end of thread, other threads:[~2019-09-14  4:23 UTC | newest]

Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2019-09-13  9:17 [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message Chris Wilson
2019-09-13  9:19 ` Chris Wilson
2019-09-13  9:38   ` Petri Latvala
2019-09-13 11:16     ` Chris Wilson
2019-09-13  9:35 ` [igt-dev] [PATCH i-g-t v2] " Chris Wilson
2019-09-13 10:04 ` [igt-dev] ✓ Fi.CI.BAT: success for runner: Add a timestamp to each log message (rev3) Patchwork
2019-09-14  4:23 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox