[Spice-devel] [PATCH spice-common 3/4] RFC: Add spice log categories
Jonathon Jongsma
jjongsma at redhat.com
Tue Jun 13 19:40:22 UTC 2017
On Tue, 2017-06-13 at 05:35 -0400, Marc-André Lureau wrote:
> Hi
>
> ----- Original Message -----
> > This code assumes that there is only a single G_LOG_DOMAIN used
> > within
> > a particular project, but it's not stated explicity (as far as I
> > can
> > tell)
>
> Kind of, you mean for the G_MESSAGES_DEBUG manipulation?
Yes, essentially.
>
> >
> > On Mon, 2017-06-12 at 12:19 +0400, marcandre.lureau at redhat.com
> > wrote:
> > > From: Marc-André Lureau <marcandre.lureau at redhat.com>
> > >
> > > A log category is defined with SPICE_LOG_CATEGORY(). The macro
> > > will
> > > register a structure with a constructor (and unregister it on
> > > unloading with a destructor).
> > >
> > > spice_log_init() must be called at initialization time, to set
> > > enabled
> > > categories and add the 'Spice' glib domain to G_MESSAGES_DEBUG
> > > (NB:
> > > if
> > > useful, we could have other log domains automatically associated
> > > with
> > > categories and enable them too).
> > >
> > > 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.
> > >
> > > 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.
> > >
> > > If deemed necessary, you can also avoid expensive log computation
> > > with
> > > SPICE_LOG_ENABLED() macro help.
> > >
> > > 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.
Hmm, I hadn't realized that you can use per-domain logging functions
with structured logging. That's unfortunate.
>
> > > +
> > > + 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_categor
> > > y_,
> > > 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.
Yes I understand now. Victor's suggestion in another email is good, I
think.
>
> >
> > > +
> > > +#define spice_log(Name, Msg, ...) G_STMT_START
> > > { \
> > > + if (SPICE_LOG_ENABLED(Name))
> > > { \
> > > + g_log_structured(G_LOG_DOMAIN,
> > > G_LOG_LEVEL_DEBUG, \
> > > + "CODE_FILE",
> > > __FILE__, \
> > > + "CODE_LINE",
> > > G_STRINGIFY(__LINE__), \
> > > + "CODE_FUNC",
> > > G_STRFUNC, \
> > > + "SPICE_LOG_CATEGORY",
> > > G_STRINGIFY(Name), \
> > > + "MESSAGE", G_STRINGIFY(Name)": " Msg,
> > > ##
> > > __VA_ARGS__); \
> > > + }
> > > \
> > > +} G_STMT_END
> > > +#else /* !G_LOG_USE_STRUCTURED */
> > > +#define spice_log(Name, Msg, ...) G_STMT_START
> > > { \
> > > + if (SPICE_LOG_ENABLED(Name))
> > > { \
> > > + g_debug(G_STRINGIFY(Name)": " Msg, ##
> > > __VA_ARGS__); \
> > > + }
> > > \
> > > +} G_STMT_END
> > > +#endif
> > > +
> > > +void spice_log_category_register(SpiceLogCategory *cat);
> > > +void spice_log_category_unregister(SpiceLogCategory *cat);
> > > +void spice_log_init(void);
> > > +
> > > /* deprecated, please use glib directly */
> > > #define spice_return_if_fail(x) g_return_if_fail(x)
> > > #define spice_return_val_if_fail(x, val) g_return_val_if_fail(x,
> > > val)
> > > @@ -36,7 +93,7 @@ G_BEGIN_DECLS
> > > #define spice_assert(x) g_assert(x)
> > > #define spice_static_assert(x) G_STATIC_ASSERT(x)
> > >
> > > -/* deprecated */
> > > +/* deprecated, use spice_log() instead */
> > > #ifndef SPICE_LOG_DOMAIN
> > > #define SPICE_LOG_DOMAIN __FILE__
> > > #endif
> > > @@ -61,7 +118,20 @@ static inline void _spice_debug(const char
> > > *domain, const char *file,
> > > if (msg) {
> > > g_string_append_vprintf(s, msg, args);
> > > }
> > > +#if G_LOG_USE_STRUCTURED
> > > + G_GNUC_BEGIN_IGNORE_DEPRECATIONS
> > > + const GLogField fields[] = {
> > > + { "GLIB_DOMAIN", G_LOG_DOMAIN, -1 },
> > > + { "MESSAGE", s->str, -1 },
> > > + { "CODE_FILE", file, -1 },
> > > + { "CODE_LINE", line, -1 },
> > > + { "CODE_FUNC", func, -1 },
> > > + };
> >
> > No SPICE_LOG_CATEGORY here?
>
> This is compatibility code, it doesn't have categories.
>
> All of the code marked as *deprecated* should in fact go away pretty
> quickly, once we replace existing spice_debug() with the new category
> API or straight g_debug().
hmm. this seems odd to me. I'm not crazy abuot the idea that some of
the debug output may be categorized and some may not.
So if I'm debugging a mouse problem and I want to see only inputs-
related debug output, I might run virt-viewer like so:
SPICE_DEBUG=inputs virt-viewer
This will then print out everything in the "inputs" category as well as
everything that was logged with g_debug() (or spice_debug()). So to
truly limit the output to only the "inputs" category I'd have to use
something like:
SPICE_DEBUG=inputs virt-viewer |grep inputs
While that doesn't totally defeat the purpose of categorized logging,
it sure makes it less useful. In my opinion, if we're going to
introduce categorization of logging, we should require a category for
all logged messages (which probably means never using g_debug()
directly). This _spice_debug() function already has a "domain" argument
which is prepended to the message, so why not use that to set
SPICE_LOG_CATEGORY?
>
> >
> > > + g_log_structured_array(G_LOG_LEVEL_DEBUG, fields,
> > > G_N_ELEMENTS(fields));
> > > + G_GNUC_END_IGNORE_DEPRECATIONS
> > > +#else
> > > g_debug("%s", s->str);
> > > +#endif
> > > va_end(args);
> > > g_string_free(s, true);
> > > }
> >
> > Up above, spice_log() checks to see whether the category is enabled
> > before logging the message. But spice_debug() does not contain any
> > categories so it doesn't check anything. So as far as I can tell,
> > any
> > message logged with spice_debug() will get printed if any other
> > spice
> > category is enabled. For instance, if I use the following
> > configuration:
> >
> > SPICE_DEBUG=cat1 virt-viewer
> >
> > I will end up with a lot output that includes all messages printed
> > via
> > "spice_log(cat1, ...)" in addition to all messages printed with
> > "spice_debug(...)". Is that correct?
> >
> >
>
> True, a direct glog will be printed by default. That's why we
> introduce categories in the first place, to do the filtering.
>
> > > diff --git a/tests/test-logging.c b/tests/test-logging.c
> > > index 03f367a..cfe63e4 100644
> > > --- a/tests/test-logging.c
> > > +++ b/tests/test-logging.c
> > > @@ -87,6 +87,7 @@ int main(int argc, char **argv)
> > > fatal_mask =
> > > (GLogLevelFlags)g_log_set_always_fatal((GLogLevelFlags)
> > > G_LOG_FATAL_MASK);
> > >
> > > g_test_init(&argc, &argv, NULL);
> > > + spice_log_init();
> > >
> > > /* Reset fatal mask set by g_test_init() as we don't want
> > > * warnings/criticals to be fatal by default since this is
> > > what
> > > some of the
More information about the Spice-devel
mailing list