[Spice-devel] [PATCH spice-common 3/4] RFC: Add spice log categories

Marc-André Lureau marcandre.lureau at redhat.com
Tue Jun 13 13:49:25 UTC 2017


Hi

----- Original Message -----
> > > > A category can be enabled with SPICE_DEBUG="cat_name foo*" (*? are
> > > > accepted glob-like wildcards). All categories are enabled with
> > > > SPICE_DEBUG=1 or 'all'. To list available categories, you can run the
> > > > program with SPICE_DEBUG=help.
> 
> IMO, SPICE_DEBUG should be kept as a flag.

What do you mean? Is there something you don't agree with from the proposal about SPICE_DEBUG variable handling above?
  
> 
> > > > 
> > > > spice_log() will log the debug message using structured logging if
> > > > available (or fallback on regular glog). The associated Spice log in
> > > > the journal will have the SPICE_LOG_CATEGORY field set accordingly.
> 
> Are we defaulting to jornal? Sorry if this is explicit somewhere else or
> if the question was already made.

glib will default to journal if stderr is connected to it.

If you run from an interactive shell, you will get the output on stderr.

You can force journal logging from the shell by prefixing the program "systemd-cat"

> 
> > > >
> > > > If deemed necessary, you can also avoid expensive log computation
> > > > with
> > > > SPICE_LOG_ENABLED() macro help.
> 
> Do you have some WIP in spice-gtk?

Not yet, I just added a call to spice_log_init() in spice_get_option_group().

> > > >
> > > > TODO: add tests
> > > >
> > > > Signed-off-by: Marc-André Lureau <marcandre.lureau at redhat.com>
> > > > ---
> > > >  common/log.c         | 67
> > > > ++++++++++++++++++++++++++++++++++++++++++++++++
> > > >  common/log.h         | 72
> > > > +++++++++++++++++++++++++++++++++++++++++++++++++++-
> > > >  tests/test-logging.c |  1 +
> > > >  3 files changed, 139 insertions(+), 1 deletion(-)
> > > >
> > > > diff --git a/common/log.c b/common/log.c
> > > > index 6a15a30..029e279 100644
> > > > --- a/common/log.c
> > > > +++ b/common/log.c
> > > > @@ -18,3 +18,70 @@
> > > >  #ifdef HAVE_CONFIG_H
> > > >  #include <config.h>
> > > >  #endif
> > > > +
> > > > +#include "log.h"
> > > > +
> > > > +static GSList *log_categories = NULL; /* all registered log
> > > > categories */
> > > > +
> > > > +void spice_log_category_register(SpiceLogCategory *cat)
> > > > +{
> > > > +    if (!g_slist_find(log_categories, cat)) {
> > > > +        log_categories = g_slist_prepend(log_categories, cat);
> > > > +    }
> > > > +}
> > > > +
> > > > +void spice_log_category_unregister(SpiceLogCategory *cat)
> > > > +{
> > > > +    log_categories = g_slist_remove(log_categories, cat);
> > > > +}
> > > > +
> > > > +void spice_log_init(void)
> > > > +{
> > > > +    bool all = false;
> > > > +    const char *env = g_getenv("SPICE_DEBUG");
> > > > +    const char *genv = g_getenv("G_MESSAGES_DEBUG");
> > > > +
> > > > +    if (g_strcmp0(env, "help") == 0) {
> > > > +        g_printerr("SPICE_DEBUG=1 or 'all' to enable all debug\n");
> > > > +        g_printerr("SPICE_DEBUG=\"cat1* cat2\" to enable specific
> > > > categories\n");
> > > > +        g_printerr("Available Spice debug categories:\n");
> > > > +        for (GSList *l = log_categories; l != NULL; l =
> > > > g_slist_next(l)) {
> > > > +            SpiceLogCategory *cat = l->data;
> > > > +            g_printerr("%-20s - %s\n", cat->name, cat->desc);
> > > > +        }
> > > > +        return;
> > > > +    }
> > > > +
> > > > +    /* Make sure GLib default log handler will show the debug
> > > > +     * messages. Messing with environment variables like this is
> > > > +     * rather ugly, but done for historical reasons.
> > > > +     */
> > > > +    if (env && *env != '\0') {
> > > > +        if (genv == NULL) {
> > > > +            g_setenv("G_MESSAGES_DEBUG", G_LOG_DOMAIN, TRUE);
> > > > +        } else if (!g_str_equal(genv, "all")) {
> > > > +            char *new_env = g_strconcat(genv, " ", G_LOG_DOMAIN,
> > > > NULL);
> > > > +            g_setenv("G_MESSAGES_DEBUG", new_env, TRUE);
> > > > +            g_free(new_env);
> > > > +        }
> > > > +    }
> > >
> > > One alternative to doing this env variable mangling may be to set our
> > > own log handler for this domain.
> >
> > That can't be done with structured logging. I think the argument is
> > that it's easier to let the application decide how and where to log,
> > or have a single log handler to configure.
> 
> It should work if G_LOG_USE_STRUCTURED is defined before including
> glib.h, no?

If you set G_LOG_USE_STRUCTURED, glib will use structured log API. But there is a single structured log handler (contrary to traditional glog that can have per-domain).

> 
> >
> > > > +
> > > > +    all = g_strcmp0(env, "1") == 0 || g_strcmp0(env, "all") == 0;
> > > > +    if (all) {
> > > > +        for (GSList *l = log_categories; l != NULL; l =
> > > > g_slist_next(l)) {
> > > > +            SpiceLogCategory *cat = l->data;
> > > > +            cat->enabled = true;
> > > > +        }
> > > > +    } else if (env) {
> > > > +        char **cat_sel = g_strsplit(env, " ", -1);
> > > > +        for (char **strv = cat_sel; *strv != NULL; strv++) {
> > > > +            GPatternSpec *pat = g_pattern_spec_new(*strv);
> > > > +            for (GSList *l = log_categories; l != NULL; l =
> > > > g_slist_next(l)) {
> > > > +                SpiceLogCategory *cat = l->data;
> > > > +                cat->enabled = g_pattern_match_string(pat, cat-
> > > > >name);
> > > > +            }
> > > > +            g_pattern_spec_free(pat);
> > > > +        }
> > > > +        g_strfreev(cat_sel);
> > > > +    }
> > > > +}
> > > > diff --git a/common/log.h b/common/log.h
> > > > index b86fd08..e202563 100644
> > > > --- a/common/log.h
> > > > +++ b/common/log.h
> > > > @@ -28,6 +28,63 @@
> > > >  
> > > >  G_BEGIN_DECLS
> > > >  
> > > > +typedef struct SpiceLogCategory {
> > > > +    const char *name;
> > > > +    const char *desc;
> > > > +    bool enabled;
> > > > +} SpiceLogCategory;
> > > > +
> > > > +/* This is only useful if the category is shared in several units.
> > > > */
> > > > +/* The code could probably be better organized instead. */
> > > > +#define SPICE_LOG_CATEGORY_DECLARE(Name)                        \
> > > > +    extern SpiceLogCategory G_PASTE(spice_log_category_, Name);
> > > > +
> > > > +#define SPICE_LOG_CATEGORY(Name,
> > > > Desc)                                  \
> > > > +    SpiceLogCategory G_PASTE(spice_log_category_, Name) =
> > > > {             \
> > > > +        .name =
> > > > G_STRINGIFY(Name),                                      \
> > > > +        .desc =
> > > > Desc,                                                   \
> > > > +        .enabled =
> > > > false,                                               \
> > > > +    };
> > > >     \
> > > > +    SPICE_CONSTRUCTOR_FUNC(G_PASTE(spice_log_category_ctor_, Name))
> > > > {   \
> > > > +        spice_log_category_register(&G_PASTE(spice_log_category_,
> > > > Name)); \
> > > > +    }
> > > >     \
> > > > +    SPICE_DESTRUCTOR_FUNC(G_PASTE(spice_log_category_dtor_, Name))
> > > > {    \
> > > > +        spice_log_category_unregister(&G_PASTE(spice_log_category_,
> > > > Name)); \
> > > > +    }
> > > > +
> > > > +#define SPICE_LOG_ENABLED(Name)                                 \
> > > > +    G_UNLIKELY(G_PASTE(spice_log_category_, Name).enabled)
> > > > +
> > > > +#if G_LOG_USE_STRUCTURED
> > > > +/* override future deprecation warning */
> > > > +#define g_log_structured(Domain, Level, ...) G_STMT_START {     \
> > > > +    G_GNUC_BEGIN_IGNORE_DEPRECATIONS                            \
> > > > +        g_log_structured(Domain, Level, ## __VA_ARGS__);        \
> > > > +    G_GNUC_END_IGNORE_DEPRECATIONS                              \
> > > > +} G_STMT_END
> > >
> > > explain the deprecation bit?
> >
> > I explained in the cover letter discussion, this is about glib
> > versioning macros, it warns if we use symbols >2.28. We have similar
> > tricks in spice-gtk.
> 
> Maybe including this in the code comment would help
> 

How would you improve "override future deprecation warning" ? add the version it was introduced?

> >
> > >
> > > > +
> > > > +#define spice_log(Name, Msg, ...) G_STMT_START
> > > > {                        \
> > > > +    if (SPICE_LOG_ENABLED(Name))
> > > > {                                      \
> > > > +        g_log_structured(G_LOG_DOMAIN,
> > > > G_LOG_LEVEL_DEBUG,               \
> 
> The bit I don't get is why we will do this only for _LEVEL_DEBUG. For
> instance, we have DISPLAY_DEBUG(), CHANNEL_DEBUG() and so on. But
> g_warning() will not have the nice fields below by default, right?
> 
> Why not spice_log(Name, log_level, Msg, ...) and on SPICE_LOG_ENABLED we
> consider the log_level as well?

As I said in other comments, we should consider this. But we would first need to transition the code to the new API. That is easier if we switch all spice_{debug,warning,...} to glog (since it's 1-1), then reintroduce new spice_{debug,warning..} with categories.

Does that make sense? Do you see another easy path forward?


More information about the Spice-devel mailing list