Re: [Qemu-devel] [PATCH v5] log: Make glib logging go through QEMU

[Christophe Fergeau]

On Thu, Jan 24, 2019 at 05:10:28PM +0100, Markus Armbruster wrote:
> Christophe Fergeau <address@hidden> writes:
> 
> > This commit adds a qemu_init_logging() helper which calls
> > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...)
> > are handled similarly to other QEMU logs. This means they will get a
> > timestamp if timestamps are enabled, and they will go through the
> > monitor if one is configured.
> 
> s/monitor/HMP monitor/
> 
> I see why one would like to extend the timestamp feature to GLib log
> messages.  Routing them through the HMP monitor is perhaps debatable.
> Cc: Dave in case he has an opinion.

Yep, I don't mind whether this goes through HMP or not, this definitely
was not one of my goals when writing this patch. I mention it in the
commit log because this is what the current code is going to do.

> > [snip]
> > diff --git a/util/qemu-error.c b/util/qemu-error.c
> > index fcbe8a1f74..1118ed4695 100644
> > --- a/util/qemu-error.c
> > +++ b/util/qemu-error.c
> > @@ -345,3 +345,50 @@ bool warn_report_once_cond(bool *printed, const char 
> > *fmt, ...)
> >      va_end(ap);
> >      return true;
> >  }
> > +
> > +static char *qemu_glog_domains;
> > +
> > +static void qemu_log_func(const gchar *log_domain,
> > +                          GLogLevelFlags log_level,
> > +                          const gchar *message,
> > +                          gpointer user_data)
> > +{
> > +    switch (log_level & G_LOG_LEVEL_MASK) {
> > +    case G_LOG_LEVEL_DEBUG:
> > +        /* Use same G_MESSAGES_DEBUG logic as glib to enable/disable debug
> > +         * messages
> > +         */
> 
> Wing both ends of the comment, please.

Fixed.

> 
> > +        if (qemu_glog_domains == NULL) {
> > +            break;
> > +        }
> > +        if (strcmp(qemu_glog_domains, "all") != 0 &&
> > +          (log_domain == NULL || !strstr(qemu_glog_domains, log_domain))) {
> > +            break;
> > +        }
> > +        /* Fall through */
> > +    case G_LOG_LEVEL_INFO:
> > +        /* Fall through */
> 
> g_log_default_handler() applies G_MESSAGES_DEBUG suppression logic to
> G_LOG_LEVEL_INFO messages, too.  Do you deviate intentionally?

Nope, I thought INFO and MESSAGE were equivalent. Fixed now.

> 
> > +    case G_LOG_LEVEL_MESSAGE:
> > +        info_report("%s: %s", log_domain, message);
> 
> @log_domain can be null.  You even check for that above.

Fixed.

> 
> > +        break;
> > +    case G_LOG_LEVEL_WARNING:
> > +        warn_report("%s: %s", log_domain, message);
> > +        break;
> > +    case G_LOG_LEVEL_CRITICAL:
> > +        /* Fall through */
> > +    case G_LOG_LEVEL_ERROR:
> > +        error_report("%s: %s", log_domain, message);
> > +        break;
> 
> Sure we don't need to check for G_LOG_FLAG_RECURSION?
> g_log_default_handler() has a conditional for that...
> 
> Not sure it has anything for G_LOG_FLAG_FATAL; it's code is surprisingly
> complex.

Both are filtered out from the switch() through G_LOG_LEVEL_MASK:
   switch (log_level & G_LOG_LEVEL_MASK) {
and
https://developer.gnome.org/glib/2.58/glib-Message-Logging.html#G-LOG-FLAG-RECURSION:CAPS
documents G_LOG_FLAG_FATAL and G_LOG_FLAG_RECURSION as fatal.

However, g_log_set_handler() then mentions handling them anyways:
https://developer.gnome.org/glib/2.58/glib-Message-Logging.html#g-log-set-handler
"Sets the log handler for a domain and a set of log levels. To handle
fatal and recursive messages the log_levels parameter must be combined
with the G_LOG_FLAG_FATAL and G_LOG_FLAG_RECURSION bit flags."

My understanding of glib's code is if any of these 2 flags is set, glib
is going to abort anyways, so handling or not handling these flags is
not going to make a big difference.

> 
> > +    }
> > +}
> > +
> > +/*
> > + * Init QEMU logging subsystem. This sets up glib logging so libraries 
> > using it
> > + * also print their logs through {info,warn,error}_report.
> > + */
> 
> Format like the other function comments:
> 
>    /*
>     * Init QEMU logging subsystem.
>     * This sets up glib logging so libraries using it also print their logs
>     * through error_report(), warn_report(), info_report().
>     */
> 
> Braces expanded for better grepability.
> 
> > +void qemu_init_logging(void)
> 
> Naming is hard...  Yes, this "initializes logging" in a sense: it
> installs a GLib default log handler that routes GLib log messages
> through this module.  But that's detail; the callers don't care what
> this function does, all they care for is "must call early".  If this
> module ever grows a need to initialize something else before it gets
> used, we'll regret naming its initialization function
> qemu_init_logging().
> 
> Hmm, it has already grown such a need: initializing @progname.
> error_set_progname() does it.  Asking a module's users to call *two*
> initializtion functions is not nice.
> 
> Fuse the two into error_init(const char *argv0)?

Ok, I've done that now, I'll send a v6.

Thanks for the review,

Christophe

signature.asc
Description: PGP signature