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

[Thomas Wood]

On 17 December 2014 at 17:19, Chris Wilson <chris at chris-wilson.co.uk> wrote:
> 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;

Yes, this check is done at the start of the function.

>
> 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");

The for loop above was to avoid using strlen (which is not listed as
signal safe), but strlen is being used in write_log_msg, so this would
need further work to make it safe too.

>
> 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;

Yes, this is added in patch 4 of this series.

>
>> +     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:

Yes, this is problematic. It will probably be worth adding some
library test cases to try and ensure the default signal handlers are
as safe as possible.

>
> 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
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/intel-gfx