[Spice-devel] [PATCH spice-common 3/4] RFC: Add spice log categories
Frediano Ziglio
fziglio at redhat.com
Wed Jun 14 11:52:45 UTC 2017
>
> 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.
>
> 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.
>
> If deemed necessary, you can also avoid expensive log computation with
> SPICE_LOG_ENABLED() macro help.
>
> 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) {
I agree with other people that this "help" usage is weird.
> + 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);
> + }
> + }
> +
> + 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));
> \
> + }
> +
Usually to do these stuff I use a simple "manual" list so
I would add a "SpiceLogCategory *next" pointer to SpiceLogCategory and
just use the constructor. This have some advantages:
- don't need extra allocations. Other than reducing memory usage
and fragmentation you could have some issues with system uses multiple
allocators (well, sometimes happens on some weird systems like
Windows);
- there are no possible allocation failure (well, should be rare at
startup but if you are paranoid... you are paranoid!);
- you don't need destructor. The entire list will be freed as part of
memory unmapping.
I found weird the capital names for parameters.
I also would prefer ## instead of G_PASTE, this syntax was introduced
as standard in C preprocessors quite some time ago. In the same patch
you are using __VA_ARGS__ with is much more recent.
> +#define SPICE_LOG_ENABLED(Name) \
> + G_UNLIKELY(G_PASTE(spice_log_category_, Name).enabled)
> +
OT: wondering if this G_PASTE(spice_log_category_, Name).enabled could
be make a compile time constant in some way so to optimize out.
> +#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
> +
> +#define spice_log(Name, Msg, ...) G_STMT_START { \
> + if (SPICE_LOG_ENABLED(Name)) { \
> + g_log_structured(G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
> + "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 },
> + };
> + 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);
> }
> 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
Frediano
More information about the Spice-devel
mailing list