[Spice-devel] [PATCH spice-common 3/4] RFC: Add spice log categories
Victor Toso
victortoso at redhat.com
Tue Jun 13 14:35:02 UTC 2017
Hi,
On Tue, Jun 13, 2017 at 09:49:25AM -0400, Marc-André Lureau wrote:
> 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?
I'm just thinking on the fact that setting SPICE_DEBUG nowadays _should_
enable all debug but now that will not be true...
> Is there something you don't agree with from the proposal about
> SPICE_DEBUG variable handling above?
Not really. I like it. In the past I did the same but the outcome was
that SPICE_DEBUG should keep its behavior, etc.
Well, at least we should check if it has a valid value.
> > > > > 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"
Ah right, its default in glib itself.
>
> >
> > > > >
> > > > > 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).
Hm, I have yet to play with the API to say for sure but I thought we
could use G_LOG_USE_STRUCTURED and set a g_log_set_writer_func() on our
spice_log_init() and if it doesn't not belong to our domain, we could
have the _writer_func_handler() to return G_LOG_WRITER_UNHANDLED.
But now I see that g_log_set_writer_func() manual says "Libraries **must
not** call this function — only programs are allowed to install a writer
function, as there must be a single, central point where log messages
are formatted and outputted." so you are probably right that
G_LOG_USE_STRUCTURED is not useful to us.
>
> >
> > >
> > > > > +
> > > > > + 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?
Something like your reply to Jonathon:
"override future deprecation warning from symbols introduced after
GLIB_VERSION_MAX_ALLOWED"
>
> > >
> > > >
> > > > > +
> > > > > +#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.
Right.
> Does that make sense? Do you see another easy path forward?
Easy? No :) I think it is straight forward as is but it'll depend if we
want to keep some of those environments for longer time and what
considerations we have on spice logging functions as API between
spice-gtk and spice-server (Frediano had a comment about it IIRC)
IMHO removing the deprecated environment variables should be fine and
finishing up your series with spice_{debug,warning,...} using glog and
categories in the end would be great as, for what I see, we should move
all g_{debug,warning,...} in spice-gtk, spice-server and spice-common to
use spice_{debug,warning,...} (correct me if I'm mistaken here, plz)
Cheers,
-------------- 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/4842fe39/attachment-0001.sig>
More information about the Spice-devel
mailing list