[igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
Chris Wilson
chris at chris-wilson.co.uk
Fri Sep 13 09:19:17 UTC 2019
Very handy for correlating events between different logs.
Signed-off-by: Chris Wilson <chris at chris-wilson.co.uk>
Cc: Petri Latvala <petri.latvala at 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
More information about the igt-dev
mailing list