[Spice-devel] [PATCH spice-common 3/4] RFC: Add spice log categories
Victor Toso
victortoso at redhat.com
Tue Jun 13 13:18:04 UTC 2017
Hi,
On Tue, Jun 13, 2017 at 05:35:05AM -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?
>
> >
> > 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.
IMO, SPICE_DEBUG should be kept as a flag.
> > >
> > > 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.
> > >
> > > If deemed necessary, you can also avoid expensive log computation
> > > with
> > > SPICE_LOG_ENABLED() macro help.
Do you have some WIP in spice-gtk?
> > >
> > > 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?
>
> > > +
> > > + 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
>
> >
> > > +
> > > +#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?
> > > + "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().
>
> >
> > > + 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
> >
> _______________________________________________
> Spice-devel mailing list
> Spice-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/spice-devel/attachments/20170613/c8bf225a/attachment-0001.sig>
More information about the Spice-devel
mailing list