[v2,39/39] util/log: Support per-thread log files

Add a new log flag, tid, to turn this feature on.
Require the log filename to be set, and to contain %d.

Do not allow tid to be turned off once it is on, nor let
the filename be change thereafter.  This avoids the need
for signalling each thread to re-open on a name change.

Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
---
v2: Make use of CONFIG_GETTID, and fallback to SYS_gettid.
---
 include/qemu/log.h |   1 +
 util/log.c         | 149 ++++++++++++++++++++++++++++++++++-----------
 2 files changed, 115 insertions(+), 35 deletions(-)

Richard Henderson <richard.henderson@linaro.org> writes:

> Add a new log flag, tid, to turn this feature on.
> Require the log filename to be set, and to contain %d.
>
> Do not allow tid to be turned off once it is on, nor let
> the filename be change thereafter.  This avoids the need
> for signalling each thread to re-open on a name change.
>
> Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
> ---
> v2: Make use of CONFIG_GETTID, and fallback to SYS_gettid.
> ---
>  include/qemu/log.h |   1 +
>  util/log.c         | 149 ++++++++++++++++++++++++++++++++++-----------
>  2 files changed, 115 insertions(+), 35 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index a325bca661..c5643d8dd5 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -34,6 +34,7 @@ bool qemu_log_separate(void);
>  #define CPU_LOG_PLUGIN     (1 << 18)
>  /* LOG_STRACE is used for user-mode strace logging. */
>  #define LOG_STRACE         (1 << 19)
> +#define LOG_PER_THREAD     (1 << 20)
>  
>  /* Lock/unlock output. */
>  
> diff --git a/util/log.c b/util/log.c
> index df0710720f..0bb2233788 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -27,6 +27,9 @@
>  #include "qemu/thread.h"
>  #include "qemu/lockable.h"
>  #include "qemu/rcu.h"
> +#ifdef CONFIG_LINUX
> +#include <sys/syscall.h>
> +#endif
>  
>  
>  typedef struct RCUCloseFILE {
> @@ -38,22 +41,36 @@ typedef struct RCUCloseFILE {
>  static QemuMutex global_mutex;
>  static char *global_filename;
>  static FILE *global_file;
> +static __thread FILE *thread_file;
>  
>  int qemu_loglevel;
> -static int log_append = 0;
> +static bool log_append;
> +static bool log_per_thread;
>  static GArray *debug_regions;
>  
>  /* Returns true if qemu_log() will really write somewhere. */
>  bool qemu_log_enabled(void)
>  {
> -    return qatomic_read(&global_file) != NULL;
> +    return log_per_thread || qatomic_read(&global_file) != NULL;
>  }
>  
>  /* Returns true if qemu_log() will write somewhere other than stderr. */
>  bool qemu_log_separate(void)
>  {
>      FILE *logfile = qatomic_read(&global_file);
> -    return logfile && logfile != stderr;
> +    return log_per_thread || (logfile && logfile != stderr);
> +}
> +
> +static int log_thread_id(void)
> +{
> +#ifdef CONFIG_GETTID
> +    return gettid();
> +#elif defined(SYS_gettid)
> +    return syscall(SYS_gettid);
> +#else
> +    static int counter;
> +    return qatomic_fetch_inc(&counter);
> +#endif
>  }
>  
>  /* Lock/unlock output. */
> @@ -62,20 +79,34 @@ FILE *qemu_log_trylock(void)
>  {
>      FILE *logfile;
>  
> -    rcu_read_lock();
> -    /*
> -     * FIXME: typeof_strip_qual, as used by qatomic_rcu_read,
> -     * does not work with pointers to undefined structures,
> -     * such as we have with struct _IO_FILE and musl libc.
> -     * Since all we want is a read of a pointer, cast to void**,
> -     * which does work with typeof_strip_qual.
> -     */
> -    logfile = qatomic_rcu_read((void **)&global_file);
> -    if (logfile) {
> -        qemu_flockfile(logfile);
> -    } else {
> -        rcu_read_unlock();
> +    logfile = thread_file;
> +    if (!logfile) {
> +        if (log_per_thread) {
> +            g_autofree char *filename
> +                = g_strdup_printf(global_filename, log_thread_id());
> +            logfile = fopen(filename, "w");
> +            if (!logfile) {
> +                return NULL;
> +            }
> +            thread_file = logfile;
> +        } else {
> +            rcu_read_lock();
> +            /*
> +             * FIXME: typeof_strip_qual, as used by qatomic_rcu_read,
> +             * does not work with pointers to undefined structures,
> +             * such as we have with struct _IO_FILE and musl libc.
> +             * Since all we want is a read of a pointer, cast to void**,
> +             * which does work with typeof_strip_qual.
> +             */
> +            logfile = qatomic_rcu_read((void **)&global_file);
> +            if (!logfile) {
> +                rcu_read_unlock();
> +                return NULL;
> +            }
> +        }
>      }
> +
> +    qemu_flockfile(logfile);
>      return logfile;
>  }
>  
> @@ -84,7 +115,9 @@ void qemu_log_unlock(FILE *logfile)
>      if (logfile) {
>          fflush(logfile);
>          qemu_funlockfile(logfile);
> -        rcu_read_unlock();
> +        if (!log_per_thread) {
> +            rcu_read_unlock();
> +        }
>      }
>  }
>  
> @@ -112,40 +145,74 @@ static void rcu_close_file(RCUCloseFILE *r)
>      g_free(r);
>  }
>  
> +/**
> + * valid_filename_template:
> + *
> + * Validate the filename template.  Require %d if per_thread, allow it
> + * otherwise; require no other % within the template.
> + * Return 0 if invalid, 1 if stderr, 2 if strdup, 3 if pid printf.

From a neatness point of view having an enum would make it easier to
read in the switch down bellow...

> + */
> +static int valid_filename_template(const char *filename,
> +                                   bool per_thread, Error **errp)
> +{
> +    if (filename) {
> +        char *pidstr = strstr(filename, "%");
> +
> +        if (pidstr) {
> +            /* We only accept one %d, no other format strings */
> +            if (pidstr[1] != 'd' || strchr(pidstr + 2, '%')) {
> +                error_setg(errp, "Bad logfile template: %s", filename);
> +                return 0;
> +            }
> +            return per_thread ? 2 : 3;
> +        }
> +    }
> +    if (per_thread) {
> +        error_setg(errp, "Filename template with '%%d' required for 'tid'");
> +        return 0;
> +    }
> +    return filename ? 2 : 1;
> +}
> +
>  /* enable or disable low levels log */
>  static bool qemu_set_log_internal(const char *filename, bool changed_name,
>                                    int log_flags, Error **errp)
>  {
>      bool need_to_open_file;
>      bool daemonized;
> +    bool per_thread;
>      FILE *logfile;
>  
>      QEMU_LOCK_GUARD(&global_mutex);
>      logfile = global_file;
>  
> +    per_thread = log_flags & LOG_PER_THREAD;
> +
>      if (changed_name) {
>          char *newname = NULL;
>  
>          /*
> -         * Allow the user to include %d in their logfile which will be
> -         * substituted with the current PID. This is useful for debugging many
> -         * nested linux-user tasks but will result in lots of logs.
> -         *
> -         * filename may be NULL. In that case, log output is sent to stderr
> +         * Once threads start opening their own log files, we have no
> +         * easy mechanism to tell them all to close and re-open.
> +         * There seems little cause to do so either -- this option
> +         * will most often be used at user-only startup.
>           */
> -        if (filename) {
> -            char *pidstr = strstr(filename, "%");
> +        if (log_per_thread) {
> +            error_setg(errp, "Cannot change log filename after setting 'tid'");
> +            return false;
> +        }
>  
> -            if (pidstr) {
> -                /* We only accept one %d, no other format strings */
> -                if (pidstr[1] != 'd' || strchr(pidstr + 2, '%')) {
> -                    error_setg(errp, "Bad logfile format: %s", filename);
> -                    return false;
> -                }
> -                newname = g_strdup_printf(filename, getpid());
> -            } else {
> -                newname = g_strdup(filename);
> -            }
> +        switch (valid_filename_template(filename, per_thread, errp)) {
> +        case 0:
> +            return false; /* error */
> +        case 1:
> +            break;  /* stderr */
> +        case 2:
> +            newname = g_strdup(filename);
> +            break;
> +        case 3:
> +            newname = g_strdup_printf(filename, getpid());
> +            break;

default: g_assert_not_reached?

>          }
>  
>          g_free(global_filename);
> @@ -153,8 +220,17 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
>          filename = newname;
>      } else {
>          filename = global_filename;
> +        if (per_thread && !valid_filename_template(filename, true, errp)) {
> +            return false; /* error */
> +        }
>      }
>  
> +    /* Once the per-thread flag is set, it cannot be unset. */
> +    if (per_thread) {
> +        log_per_thread = true;
> +    }
> +    /* The flag itself is not relevant for need_to_open_file. */
> +    log_flags &= ~LOG_PER_THREAD;
>  #ifdef CONFIG_TRACE_LOG
>      log_flags |= LOG_TRACE;
>  #endif
> @@ -163,12 +239,13 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
>      /*
>       * In all cases we only log if qemu_loglevel is set.
>       * Also:
> +     *   If per-thread, open the file for each thread in qemu_log_lock.
>       *   If not daemonized we will always log either to stderr
>       *     or to a file (if there is a filename).
>       *   If we are daemonized, we will only log if there is a filename.
>       */
>      daemonized = is_daemonized();
> -    need_to_open_file = log_flags && (!daemonized || filename);
> +    need_to_open_file = log_flags && !per_thread && (!daemonized || filename);
>  
>      if (logfile && (!need_to_open_file || changed_name)) {
>          qatomic_rcu_set(&global_file, NULL);
> @@ -354,6 +431,8 @@ const QEMULogItem qemu_log_items[] = {
>  #endif
>      { LOG_STRACE, "strace",
>        "log every user-mode syscall, its input, and its result" },
> +    { LOG_PER_THREAD, "tid",
> +      "open a separate log file per thread; filename must contain '%d'" },
>      { 0, NULL, NULL },
>  };

Otherwise:

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

On 4/14/22 08:35, Alex Bennée wrote:
>> +/**
>> + * valid_filename_template:
>> + *
>> + * Validate the filename template.  Require %d if per_thread, allow it
>> + * otherwise; require no other % within the template.
>> + * Return 0 if invalid, 1 if stderr, 2 if strdup, 3 if pid printf.
> 
>  From a neatness point of view having an enum would make it easier to
> read in the switch down bellow...

Fair, and...

>> +        switch (valid_filename_template(filename, per_thread, errp)) {
>> +        case 0:
>> +            return false; /* error */
>> +        case 1:
>> +            break;  /* stderr */
>> +        case 2:
>> +            newname = g_strdup(filename);
>> +            break;
>> +        case 3:
>> +            newname = g_strdup_printf(filename, getpid());
>> +            break;
> 
> default: g_assert_not_reached?

... using an enum with an extra enumerator for testing gives us

../src/util/log.c: In function ‘qemu_set_log_internal’:
../src/util/log.c:213:9: error: enumeration value ‘vft_new_case’ not handled in switch 
[-Werror=switch]
   213 |         switch (valid_filename_template(filename, per_thread, errp)) {
       |         ^~~~~~
cc1: all warnings being treated as errors

though that does require *not* having a default case.


r~