* [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
* [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
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 9:35 ` [igt-dev] [PATCH i-g-t v2] " Chris Wilson
` (2 subsequent siblings)
3 siblings, 1 reply; 7+ messages in thread
From: Chris Wilson @ 2019-09-13 9:19 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..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
^ permalink raw reply related [flat|nested] 7+ messages in thread
* [igt-dev] [PATCH i-g-t v2] runner: Add a timestamp to each log message
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:35 ` 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
3 siblings, 0 replies; 7+ messages in thread
From: Chris Wilson @ 2019-09-13 9:35 UTC (permalink / raw)
To: igt-dev; +Cc: Petri Latvala
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
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
2019-09-13 9:19 ` Chris Wilson
@ 2019-09-13 9:38 ` Petri Latvala
2019-09-13 11:16 ` Chris Wilson
0 siblings, 1 reply; 7+ messages in thread
From: Petri Latvala @ 2019-09-13 9:38 UTC (permalink / raw)
To: Chris Wilson; +Cc: igt-dev
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* [igt-dev] ✓ Fi.CI.BAT: success for runner: Add a timestamp to each log message (rev3)
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:35 ` [igt-dev] [PATCH i-g-t v2] " Chris Wilson
@ 2019-09-13 10:04 ` Patchwork
2019-09-14 4:23 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork
3 siblings, 0 replies; 7+ messages in thread
From: Patchwork @ 2019-09-13 10:04 UTC (permalink / raw)
To: Chris Wilson; +Cc: igt-dev
== 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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
2019-09-13 9:38 ` Petri Latvala
@ 2019-09-13 11:16 ` Chris Wilson
0 siblings, 0 replies; 7+ messages in thread
From: Chris Wilson @ 2019-09-13 11:16 UTC (permalink / raw)
To: Petri Latvala; +Cc: igt-dev
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* [igt-dev] ✓ Fi.CI.IGT: success for runner: Add a timestamp to each log message (rev3)
2019-09-13 9:17 [igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message Chris Wilson
` (2 preceding siblings ...)
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 ` Patchwork
3 siblings, 0 replies; 7+ messages in thread
From: Patchwork @ 2019-09-14 4:23 UTC (permalink / raw)
To: Chris Wilson; +Cc: igt-dev
== 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
^ permalink raw reply [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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.