<html><head><meta http-equiv="Content-Type" content="text/html charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class=""><br class=""><div><blockquote type="cite" class=""><div class="">On 12 Jun 2017, at 23:32, Marc-André Lureau <<a href="mailto:marcandre.lureau@gmail.com" class="">marcandre.lureau@gmail.com</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><div dir="ltr" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class="">Hi<br class=""><div class=""><br class=""><div class="gmail_quote"><div dir="ltr" class="">On Mon, Jun 12, 2017 at 9:11 PM Christophe de Dinechin <<a href="mailto:dinechin@redhat.com" class="">dinechin@redhat.com</a>> wrote:<br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">> On 12 Jun 2017, at 10:19,<span class="Apple-converted-space"> </span><a href="mailto:marcandre.lureau@redhat.com" target="_blank" class="">marcandre.lureau@redhat.com</a><span class="Apple-converted-space"> </span>wrote:<br class="">><br class="">> From: Marc-André Lureau <<a href="mailto:marcandre.lureau@redhat.com" target="_blank" class="">marcandre.lureau@redhat.com</a>><br class="">><br class="">> Hi,<br class="">><br class="">> This is a RFC series to clean-up Spice logging infrastructure to fully<br class="">> rely on glib g_log & g_log_structured if available, and add logging<br class="">> categories. It is thus a counter-proposal to Christophe D. "RFC:<br class="">> Lightweight tracing mechanism", with which it shares the category<br class="">> selection/listing feature.<br class=""><br class="">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.<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">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.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">Here is what I like:<br class=""><br class="">1. Can be implemented in glib, and in my opinion, would be a nice addition there (replacing the spice prefix, obviously).<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">+1<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">2. Also has some self-documentation provisions (although, quite frankly, expecting someone to set SPICE_DEBUG=help seems a bit contrived to me ;-)<br class=""><br class=""></blockquote><div class="">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.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">3. Removes overhead associated with spice_log, replacing it with direct calls to glib logging functions<br class=""><br class="">4. Migrates to structured logging if available, so you get the benefits of that too.<br class=""><br class="">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.<br class=""><br class=""><br class="">Here is what I feel is debatable:<br class=""><br class="">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.<br class=""></blockquote><div class=""><br class=""></div><div class="">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. <span class="Apple-converted-space"> </span><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">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?<br class=""><br class=""></blockquote><div class="">glib uses deprecation macros & tricks for doing min & max version checking, and spice has 2.28 as max version currently (see<span class="Apple-converted-space"> </span><a href="https://git.gnome.org/browse/glib/tree/glib/gversionmacros.h" class="">https://git.gnome.org/browse/glib/tree/glib/gversionmacros.h</a><span class="Apple-converted-space"> </span>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<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">3. What is the comment /* because spice_debug(NULL) exists.. */ ? It does not explain anything to me, frightens me even ;-)<br class=""> </blockquote><div class=""><br class=""></div><div class="">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.<br class=""><br class=""></div><div class="">This should go away quickly, along with _spice_debug as soon as we switch codebase to g_log usage and spice_log().<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""></blockquote><div class=""><br class=""></div><div class="">Well, it's bit easier to write and to read too :)<br class=""> <span class="Apple-converted-space"> </span><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">5. Do we still need the ugly setenv of G_MESSAGES_DEBUG? Is there really no better way to deal with this?<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">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.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">Here is what I don’t like:<br class=""><br class="">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).<br class=""></blockquote><br class=""></div><div class="gmail_quote">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.<br class=""><br class=""></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""></blockquote><br class=""></div><div class="gmail_quote">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?).<br class=""><br class=""></div><div class="gmail_quote">I don't think it make sense to associate a category to a g_return* for ex.<br class=""><br class=""></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">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?<br class=""><br class=""></blockquote><div class=""> </div><div class="">spice_log() takes a format string and its argument for the message.<br class=""><br class=""></div><div class="">If you need more custom fields, you'll have to use g_log_strucutred(), I don't see an easy way around that.<br class=""></div></div></div></div></div></blockquote><div><br class=""></div><div>That was based on a misunderstanding of the interface based on the documentation (where the only hint that “MESSAGE” must be last and takes printf-formatted varargs after that is the example). I looked at the code, and indeed, the parameter loop exists with “MESSAGE” and then deals with the rest with vsnprintf or similar. Very odd interface, but why not.</div><div><br class=""></div><br class=""><blockquote type="cite" class=""><div class=""><div dir="ltr" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><div class=""><div class="gmail_quote"><div class=""><br class=""></div><div class=""> </div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">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.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""><br class=""></blockquote><div class=""><br class="">Whoo, client sending debug options to the server? That is quite strange.<br class=""></div></div></div></div></div></blockquote><div><br class=""></div><div>What I would like is to be able to enable collection of debug information (ideally on a per-session basis) without having to restart the server. Is that strange?</div><br class=""><blockquote type="cite" class=""><div class=""><div dir="ltr" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><div class=""><div class="gmail_quote"><div class=""><br class=""></div><div class="">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 .<br class=""> <br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">Here is what I feel is the important stuff missing relative to my own proposal:<br class=""><br class="">1. No command-line option to select debug categories. Can be fixed with a script wrapper, but command-line options are a good thing.<br class=""></blockquote><div class=""> </div><div class="">Command line options are user visible, thus must be stable and friendly. I disagree to put anything more complicated that --spice-debug.<br class=""> <br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">2. Using space as a separator, forcing you to quote the SPICE_DEBUG value. Same as 1, just inconvenient for not good reason.<br class=""><br class=""></blockquote><div class=""> </div><div class="">I'd like to follow G_MESSAGES_DEBUG here. I think we could accept : as seperator too though (and glib should too imho).<br class=""></div><div class=""> </div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""></blockquote><div class=""><br class=""></div><div class="">We may want SPICE_DEBUG=1 to be only some default categories (SPICE_DEBUG=all for all)<br class=""><br class=""></div><div class="">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.<br class=""></div><div class=""> </div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">4. Timing information not recorded in spice_debug. I think that information is useful and missing from the current implementation.<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">Shouldn't be too difficult to add. G_DEBUG_HERE shows an example.<br class=""></div><div class=""> </div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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.<br class=""></blockquote><div class=""><br class=""></div><div class="">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.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;"><br class="">6. No provision for anything similar to my tweaks, and unnecessary domain restriction with a name like “log_enabled”.<br class=""><br class=""></blockquote><div class=""><br class=""></div><div class="">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.<br class=""></div><div class=""><br class=""></div><div class="">Yes, it could accept arbitrary category name, by making the declaration slightly less pleasant, but we are used to this with C.<br class=""><br class=""></div><blockquote class="gmail_quote" style="margin: 0px 0px 0px 0.8ex; border-left-width: 1px; border-left-style: solid; border-left-color: rgb(204, 204, 204); padding-left: 1ex;">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 ;-)<br class=""><br class=""><br class="">><br class="">> It is useful to be able to filter the logging by domains, but GLib<br class="">> only provides domain selection with G_MESSAGES_DEBUG, and it's<br class="">> recommended to have few domains per application/library. Also, domain<br class="">> filtering code in glib isn't very efficient, and can't be listed<br class="">> easily.<br class=""><br class="">I think your approach solves that to some extent, and could solve it correctly in glib too.<br class=""><br class="">><br class="">> A common solution to this problem is to add some form of "sub-domain"<br class="">> or "categories" on top of glib (see for ex gtkdebug.h). I propose a<br class="">> simple way to register such log categories, to list and selectively<br class="">> enable them with the SPICE_DEBUG= environment variable, as well as<br class="">> related convenience macros.<br class="">><br class="">> Comments welcome,<br class="">><br class="">> Marc-André Lureau (4):<br class="">> log: replace spice log with glib<br class="">> Replace spice_* logging with g_*<br class="">> RFC: Add spice log categories<br class="">> Add 'common_ssl' Spice log<br class="">><br class="">> common/canvas_base.c | 148 ++++++++++-----------<br class="">> common/canvas_utils.c | 18 +--<br class="">> common/gdi_canvas.c | 82 ++++++------<br class="">> common/log.c | 208 +++++++----------------------<br class="">> common/log.h | 175 ++++++++++++++----------<br class="">> common/lz.c | 22 +--<br class="">> common/lz_decompress_tmpl.c | 18 +--<br class="">> common/marshaller.c | 2 +-<br class="">> common/mem.c | 2 +-<br class="">> common/pixman_utils.c | 156 +++++++++++-----------<br class="">> common/quic.c | 88 ++++++------<br class="">> common/quic_family_tmpl.c | 6 +-<br class="">> common/quic_rgb_tmpl.c | 32 ++---<br class="">> common/quic_tmpl.c | 32 ++---<br class="">> common/rect.h | 2 +-<br class="">> common/region.c | 2 +-<br class="">> common/ring.h | 26 ++--<br class="">> common/rop3.c | 10 +-<br class="">> common/snd_codec.c | 18 +--<br class="">> common/ssl_verify.c | 74 ++++++-----<br class="">> common/sw_canvas.c | 20 +--<br class="">> tests/test-logging.c | 317 +-------------------------------------------<br class="">> 22 files changed, 544 insertions(+), 914 deletions(-)<br class="">><br class="">> --<br class="">> 2.13.0.91.g00982b8dd<br class="">><br class=""><br class="">_______________________________________________<br class="">Spice-devel mailing list<br class=""><a href="mailto:Spice-devel@lists.freedesktop.org" target="_blank" class="">Spice-devel@lists.freedesktop.org</a><br class=""><a href="https://lists.freedesktop.org/mailman/listinfo/spice-devel" rel="noreferrer" target="_blank" class="">https://lists.freedesktop.org/mailman/listinfo/spice-devel</a><br class=""></blockquote></div></div></div><div dir="ltr" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class="">--<span class="Apple-converted-space"> </span><br class=""></div><div data-smartmail="gmail_signature" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><div dir="ltr" class="">Marc-André Lureau<br class=""></div></div><span style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; float: none; display: inline !important;" class="">_______________________________________________</span><br style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><span style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; float: none; display: inline !important;" class="">Spice-devel mailing list</span><br style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><a href="mailto:Spice-devel@lists.freedesktop.org" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px;" class="">Spice-devel@lists.freedesktop.org</a><br style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px;" class=""><a href="https://lists.freedesktop.org/mailman/listinfo/spice-devel" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px;" class="">https://lists.freedesktop.org/mailman/listinfo/spice-devel</a></div></blockquote></div><br class=""></body></html>