[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category
Marc-André Lureau
marcandre.lureau at gmail.com
Mon Jun 12 21:32:38 UTC 2017
Hi
On Mon, Jun 12, 2017 at 9:11 PM Christophe de Dinechin <dinechin at redhat.com>
wrote:
>
> > On 12 Jun 2017, at 10:19, marcandre.lureau at redhat.com wrote:
> >
> > From: Marc-André Lureau <marcandre.lureau at redhat.com>
> >
> > Hi,
> >
> > This is a RFC series to clean-up Spice logging infrastructure to fully
> > rely on glib g_log & g_log_structured if available, and add logging
> > categories. It is thus a counter-proposal to Christophe D. "RFC:
> > Lightweight tracing mechanism", with which it shares the category
> > selection/listing feature.
>
> I do not see it as a counter proposal, but rather as an improvement to a
> part I had not really dealt with, the logging itself. I also see this as
> something that, as implemented, truly belongs to glib. I would happily
> trade the slight extra costs for the benefits of having that be a shared
> mechanism between glib applications.
>
>
I'll propose it, but don't think glib will be interested, as they have the
domain selection and strctured logging. You can do filtering of the log you
send on top.
Here is what I like:
>
> 1. Can be implemented in glib, and in my opinion, would be a nice addition
> there (replacing the spice prefix, obviously).
>
>
+1
2. Also has some self-documentation provisions (although, quite frankly,
> expecting someone to set SPICE_DEBUG=help seems a bit contrived to me ;-)
>
> A DEBUG environment variable is often parsed with g_parse_debug_string()
(G_DEBUG=help, see also glib/clutter/gtk etc), which uses 'help' to list
all keys. Here I wanted to follow more closely G_MESSAGES_DEBUG, use glob
matching, and list a category description too, although we may consider
that last part quite unnecessary and may switch to g_parse eventually.
3. Removes overhead associated with spice_log, replacing it with direct
> calls to glib logging functions
>
> 4. Migrates to structured logging if available, so you get the benefits of
> that too.
>
> 5. Uses “true” pattern matching as opposed to my ad-hoc syntax. Its
> clearly more expensive, but then it’s only once at startup, so it’s better.
>
>
> Here is what I feel is debatable:
>
> 1. Replacing spice_foo with g_foo in the code (i.e. your patch 2/4). It
> makes sense to be able to do something special about, say,
> spice_return_if_fail, if only make it easy to breakpoint (e.g. by adding a
> call to some foo() function) to debug a spice CRITICAL message.
>
I don't really get the problem here, you can put a breakpoint anywhere
where there is a g_return* or you may use G_DEBUG=fatal-criticals to break
on criticals and/or errors.
>
> 2. What is the story regarding deprecation of g_log_structured? Are you
> switching to an interface that you know is going to be deprecated soon?
>
> glib uses deprecation macros & tricks for doing min & max version
checking, and spice has 2.28 as max version currently (see
https://git.gnome.org/browse/glib/tree/glib/gversionmacros.h and other
macros). To enable G_LOG_USER_STRUCTURED on Fedora for instance, we need to
override the warning. This is also done in a couple of places in spice-gtk
btw
3. What is the comment /* because spice_debug(NULL) exists.. */ ? It does
> not explain anything to me, frightens me even ;-)
>
spice_debug(x) should be g_debug(SPICE_LOG_DOMAIN ": " x, ## __VA_ARGS__),
but you can't do that if you have callers with NULL.
This should go away quickly, along with _spice_debug as soon as we switch
codebase to g_log usage and spice_log().
4. Using macros for things that are standard C preprocessor features, like
> G_PASTE or G_STRINGIFY. Mostly a matter of style. I would do that to my own
> code if the consensus is that it is better.
>
Well, it's bit easier to write and to read too :)
> 5. Do we still need the ugly setenv of G_MESSAGES_DEBUG? Is there really
> no better way to deal with this?
>
>
If we want SPICE_DEBUG=foo to enable log, then yes, we need to tweak it.
Otherwise, we would have to tell the user to set both environment variables.
> Here is what I don’t like:
>
> 1. If we go with structured, I think we should go all the way and avoid
> mixing multiple things in a single field, e.g. [G_STRINGIFY(Name)": “ Msg]
> or definitions of spice_printerr, spice_info, etc. (where the log domain is
> added to the message rather than being its own thing).
>
We can do that, but we won't have the control on the default
writer/formater, since spice is a library. The SPICE_LOG_CATEGORY will not
appear in the default log which uses only fields it knows about,
G_LOG_DOMAIN, level & MESSAGE etc. It will be stored in the journal though.
Imho, it's fine if MESSAGE contains the category prefixed too.
2. Different approach for error and warnings (straight to
> g_error/g_warning), logs (macro version 1) an debug (macro version 2). I
> would prefer a single spice_log and route everything through there.
>
I would rather simply say, use g* for anything logging related. If you have
a debug category, use spice_log, which may have a log level ,or a
reintroduce spice_debug/spice_warning if necessary (I believe it's not,
someone uses SPICE_DEBUG_LEVEL with interesting results?).
I don't think it make sense to associate a category to a g_return* for ex.
> 3. It seems that the structured spice_log takes key/value pairs in its
> __VA_ARGS__, whereas the non-structured would take a printf-like format. Am
> I reading that wrong?
>
>
spice_log() takes a format string and its argument for the message.
If you need more custom fields, you'll have to use g_log_strucutred(), I
don't see an easy way around that.
> 4. Making _spice_debug inline will cause unnecessary code bloat. There is
> no optimisation opportunity that inlining exposes in that case. I would
> just make that a regular function.
>
>
Agree, I am not a big fan of 'inline' myself (and other
pseudo-optimizations), but this code should go away quickly. I don't mind
make it a regular function in the meantime.
5. The spice_log_init deals with hard-coded variables in a hard-coded way.
> I purposely had a function taking a string, and called either with env vars
> or command line options. I was thinking long-term about other inputs,
> notably the client being able to send debug options to the server.
>
>
Whoo, client sending debug options to the server? That is quite strange.
I want to avoid creating new variables or options. I think it would be way
easier if we only had SPICE_DEBUG. But yeah, eventually we could have a
function with a string to parse instead .
>
> Here is what I feel is the important stuff missing relative to my own
> proposal:
>
> 1. No command-line option to select debug categories. Can be fixed with a
> script wrapper, but command-line options are a good thing.
>
Command line options are user visible, thus must be stable and friendly. I
disagree to put anything more complicated that --spice-debug.
> 2. Using space as a separator, forcing you to quote the SPICE_DEBUG value.
> Same as 1, just inconvenient for not good reason.
>
>
I'd like to follow G_MESSAGES_DEBUG here. I think we could accept : as
seperator too though (and glib should too imho).
> 3. “SPICE_DEBUG=1” means “all categories”. Seems simple, but my experience
> tells me that makes it simplistic. In practice, this will prevent people
> from putting some useful information under debug categories because they
> would be too high volume. Mouse coordinates is the example I gave before. I
> want to be able to show mouse coordinates when I need them, but not have
> them in a customer debug report, which I assume would just set
> SPICE_DEBUG=1.
>
We may want SPICE_DEBUG=1 to be only some default categories
(SPICE_DEBUG=all for all)
Although I don't think cursor movement is a very high traffic. In fact, I
think none of spice_log & g_log should be very high, or you should use a
tracer library instead.
> 4. Timing information not recorded in spice_debug. I think that
> information is useful and missing from the current implementation.
>
>
Shouldn't be too difficult to add. G_DEBUG_HERE shows an example.
> 5. No convenient way to just log minimal stuff to stdout e.g. for grep,
> and customize what is shown. As if convenience for sysadmins meant we can’t
> also be convenient for developers.
>
This can be done at application level with a custom log/writer handler. I
don't think Spice should provide this facility. In any case, this isn't
incompatible with this proposal.
> 6. No provision for anything similar to my tweaks, and unnecessary domain
> restriction with a name like “log_enabled”.
>
>
As already discussed, what you call "tweaks", which I simply call option,
should be considered case by case. For now, this is only about adding
categories.
Yes, it could accept arbitrary category name, by making the declaration
slightly less pleasant, but we are used to this with C.
That last one is really bad. The “output” is definitely an improvement over
> what exists, which I was just reusing practically as-is. The whole “input"
> half of my proposal, on the other hand, is just gone. To stick with my
> stupid punchcard analogy, an auto-sorting printer with color and bold
> capabilities is a vast improvement for output, but sill does not help me if
> what I care about is writing vi or emacs. Which, in case it was unclear so
> far, it is ;-)
>
>
> >
> > It is useful to be able to filter the logging by domains, but GLib
> > only provides domain selection with G_MESSAGES_DEBUG, and it's
> > recommended to have few domains per application/library. Also, domain
> > filtering code in glib isn't very efficient, and can't be listed
> > easily.
>
> I think your approach solves that to some extent, and could solve it
> correctly in glib too.
>
> >
> > A common solution to this problem is to add some form of "sub-domain"
> > or "categories" on top of glib (see for ex gtkdebug.h). I propose a
> > simple way to register such log categories, to list and selectively
> > enable them with the SPICE_DEBUG= environment variable, as well as
> > related convenience macros.
> >
> > Comments welcome,
> >
> > Marc-André Lureau (4):
> > log: replace spice log with glib
> > Replace spice_* logging with g_*
> > RFC: Add spice log categories
> > Add 'common_ssl' Spice log
> >
> > common/canvas_base.c | 148 ++++++++++-----------
> > common/canvas_utils.c | 18 +--
> > common/gdi_canvas.c | 82 ++++++------
> > common/log.c | 208 +++++++----------------------
> > common/log.h | 175 ++++++++++++++----------
> > common/lz.c | 22 +--
> > common/lz_decompress_tmpl.c | 18 +--
> > common/marshaller.c | 2 +-
> > common/mem.c | 2 +-
> > common/pixman_utils.c | 156 +++++++++++-----------
> > common/quic.c | 88 ++++++------
> > common/quic_family_tmpl.c | 6 +-
> > common/quic_rgb_tmpl.c | 32 ++---
> > common/quic_tmpl.c | 32 ++---
> > common/rect.h | 2 +-
> > common/region.c | 2 +-
> > common/ring.h | 26 ++--
> > common/rop3.c | 10 +-
> > common/snd_codec.c | 18 +--
> > common/ssl_verify.c | 74 ++++++-----
> > common/sw_canvas.c | 20 +--
> > tests/test-logging.c | 317
> +-------------------------------------------
> > 22 files changed, 544 insertions(+), 914 deletions(-)
> >
> > --
> > 2.13.0.91.g00982b8dd
> >
>
> _______________________________________________
> Spice-devel mailing list
> Spice-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel
>
--
Marc-André Lureau
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/spice-devel/attachments/20170612/420086a3/attachment-0001.html>
More information about the Spice-devel
mailing list