[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category

Mon Jun 12 17:11:14 UTC 2017

> 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.

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).

2. Also has some self-documentation provisions (although, quite frankly, expecting someone to set SPICE_DEBUG=help seems a bit contrived to me ;-)

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.

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?

3. What is the comment /* because spice_debug(NULL) exists.. */ ? It does not explain anything to me, frightens me even ;-)

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.

5. Do we still need the ugly setenv of G_MESSAGES_DEBUG? Is there really no better way to deal with this?

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).

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.

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?

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.

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.

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.

2. Using space as a separator, forcing you to quote the SPICE_DEBUG value. Same as 1, just inconvenient for not good reason.

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.

4. Timing information not recorded in spice_debug. I think that information is useful and missing from the current implementation.

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.

6. No provision for anything similar to my tweaks, and unnecessary domain restriction with a name like “log_enabled”.

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
> 