[Intel-gfx] [PATCH i-g-t 1/5] lib: print recent log output if a test fails

[Chris Wilson]

On Wed, Dec 17, 2014 at 04:45:43PM +0000, Thomas Wood wrote:
> Print recent log entries if a test or subtest fails and the current log
> level is set to info.
> 
> v2: Write log to stderr after test or subtest failure and make log
>     buffering thread safe.
> 
> Signed-off-by: Thomas Wood <thomas.wood at intel.com>
> ---
>  lib/igt_core.c | 103 +++++++++++++++++++++++++++++++++++++++++++++++++++++----
>  1 file changed, 96 insertions(+), 7 deletions(-)
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 08e0c47..457b3b1 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -50,6 +50,8 @@
>  #include <termios.h>
>  #include <errno.h>
>  #include <time.h>
> +#include <limits.h>
> +#include <pthread.h>
>  
>  #include "drmtest.h"
>  #include "intel_chipset.h"
> @@ -228,8 +230,18 @@ enum {
>   OPT_HELP = 'h'
>  };
>  
> +static const char *command_str;
> +static int igt_exitcode = IGT_EXIT_SUCCESS;
> +
>  static char* igt_log_domain_filter;
>  
> +static struct {
> +	char *entries[256];
> +	uint8_t start, end;
> +} log_buffer;
> +static pthread_mutex_t log_buffer_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
> +
>  __attribute__((format(printf, 1, 2)))
>  static void kmsg(const char *format, ...)
>  #define KERN_EMER	"<0>"
> @@ -353,6 +365,52 @@ static void low_mem_killer_disable(bool disable)
>  	chmod(adj_fname, buf.st_mode);
>  }
>  
> +#define write_log_msg(x) write(STDERR_FILENO, x, strlen(x))
> +
> +/* this function must be safe to be called inside a signal handler */
> +static void write_log(void)
> +{
> +	uint8_t i;
> +	char *last_line;
> +
> +	pthread_mutex_lock(&log_buffer_mutex);
> +
> +	/* don't write an empty log */
> +	if (log_buffer.start == log_buffer.end) {
> +		pthread_mutex_unlock(&log_buffer_mutex);
> +		return;
> +	}
> +
> +	if (in_subtest) {
> +		write_log_msg("--- Subtest ");
> +		write_log_msg(in_subtest);
> +	} else {
> +		write_log_msg("--- Test ");
> +		write_log_msg(command_str);
> +	}
> +	write_log_msg(" failed.\n");
> +	write_log_msg("--- Log Start\n");
> +
> +	i = log_buffer.start;
> +	do {
> +		last_line = log_buffer.entries[i];
> +		write_log_msg(last_line);

What happens if nothing is in the log:
log_buffer.start == log_buffer.end == 0

last_line[pos] is a *NULL, as may strlen(NULL).

When something is in the log, start != end, so this can just be a simple

if (log_buffer.start == log_buffer.end)
	return;

i = log_buffer.start;
do {
> +
> +		/* ensure each line ends in a newline */
> +		for (int pos = 0; last_line[pos] != '\0'; pos++) {
> +			if (last_line[pos] != '\n'
> +			    && last_line[pos + 1] == '\0')
> +				write_log_msg("\n");
> +		}

pos = strlen(last_line);
if (pos > 0 && last_line[pos-1] != '\n')
	write_log_msg("\n");

if (i == log_buffer.end)
	break;

i++;
} while (1);

It's not the neatest of loops, but it should be effective.

> +		i++;
> +	} while (i != log_buffer.start && i != log_buffer.end);
> +
> +	write_log_msg("--- Log End\n");

After it has dumped the log, do you want to reset the log_buffer?
i.e. log_buffer.start = log_buffer.end;

> +	pthread_mutex_unlock(&log_buffer_mutex);

I was worried by taking locks inside a signal handler, but this looks
like it could be made safe, and with a bit more work, you can make the
other half robust as well:

char *new, *old;

asprintf(&new,
	 "(%s:%d) %s%s%s: %s",
	 program_name, getpid(),
	 (domain) ? domain : "",
	 (domain) ? "-" : "",
	 igt_log_level_str[level],
	 line);

pthread_mutex_lock(&log_buffer_mutex);
old = log_buffer.entries[log_buffer.end];
log_bufffer.entries[log_buffer.end] = new;
if (++log_buffer.end == log_buffer.start)
	log_buffer.start++;
pthread_mutex_unlock(&log_buffer_mutex);

free(old);

i.e. only do the pointer head/tail assignment inside the lock to
minimise exposure.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre