[igt-dev] [PATCH i-g-t] runner: Add a timestamp to each log message
Petri Latvala
petri.latvala at intel.com
Fri Sep 13 09:38:34 UTC 2019
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 at chris-wilson.co.uk>
> Cc: Petri Latvala <petri.latvala at intel.com>
Reviewed-by: 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