GNOME Bugzilla – Bug 744456
Structured logging API
Last modified: 2016-08-02 14:55:50 UTC
See: https://mail.gnome.org/archives/desktop-devel-list/2015-February/msg00121.html The libgsystem implementation is here: https://git.gnome.org/browse/libgsystem/tree/src/gsystem-log.c Note it does not require glib to link to libsystemd; the code to write to the journal socket directly is quite small.
Er, sorry it *does* link to libsystemd, but the core sd_journal_sendv() API is ~600 lines now.
> void gs_log_structured (const char *message, const char *const *keys) I think it would be nice to have three things (basically ‘give me convenience wrappers!’): 1. A varargs version which takes (key1, value1, key2, value2, …, NULL) to avoid the calling code having to build ‘KEY=VALUE’ strings manually. 2. A printf-varargs version which basically looks the same as the current g_log(). This would have to omit @keys. If the developer wants to use a printf-style string and @keys, they will have to use g_strdup_printf() first, I guess. 3. Some kind of wrapper which takes the typical level and domain keys, since they’re quite useful. e.g. g_log_new (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, /* pre-formatted, not printf-style */ key1, value1, key2, value2, …);
Should this be implemented in the existing g_warning(), g_critical() and so on? Is it possible to switch to writing to the journal socket directly, rather than depending on libsystemd (or is there some way to keep the API, but make the dependency optional)? Does this make sense on non-Linux platforms, such as the logging system on Windows, or traditional syslog?
Created attachment 324004 [details] [review] gmessages: Simplify _g_log_abort() in gmessages.c a little
Created attachment 324005 [details] [review] gmessages: Add a structured logging API In parallel with g_log(), add a new structured logging API, based around g_log_structured() and various helper functions which are exposed publicly to allow programs to build their own logging policies easily, without having to rewrite a lot of gmessages.c because it’s all internal. See the expanded documentation at the top of gmessages.c for some rationale. See the g_log_structured() documentation for some example code.
Created attachment 324006 [details] [review] gmessages: Add colour output support to structured log messages If outputting to a terminal which supports coloured output (rather than, for example, redirecting to a file). This is only enabled for structured log messages, where colour output support can be tested. It is not enabled for non-structured log messages.
Here’s a first approach at implementing this in GLib. It adds a g_log_structured() API, and exposes various bits of code which were previously private to gmessages.c, with the intention that programs can write their own log writer functions which use the GLib implementations of things (like writing to journald or stdout) but apply their own policy on top, determining which logging domains to ignore/output/whatever, what to do with various log levels, and whether to additionally output to other sinks. This patch series is not yet ready to be pushed. In particular, more tests need to be added, and something needs to be done about g_test_expect_message(). I think g_test_expect_message() should be deprecated, and replaced by something which allows the user more flexibility over how the lists of outputted and expected messages are matched. This would allow tests to easily ignore messages which appear on one code path but not another; or messages which are repeated an unknown number of times. I’m not sure either about how to integrate g_log() and g_log_structured(). I am inclined to leave them separate for the moment, as they have slightly different semantics regarding log domains and fatal behaviour which would be hard to reconcile between them. Anyway, all feedback welcome. :-)
NAK to having both g_message/g_warning/g_critical and G_MESSAGE/G_WARNING/G_CRITICAL and having them do different things.
(In reply to Matthias Clasen from comment #8) > NAK to having both g_message/g_warning/g_critical and > G_MESSAGE/G_WARNING/G_CRITICAL and having them do different things. OK. What about g_message_structured() or G_MESSAGE_STRUCTURED(). Bit more typing though.
Review of attachment 324005 [details] [review]: I only gave this a very superficial look so far. ::: glib/gmessages.c @@ +65,3 @@ + * get additional log data. Code which uses logging in performance-critical + * sections should compile out the g_log_structured() calls in + * non-development builds. I'd say "debugging" builds. A hybrid approach some organizations do is to deploy e.g. 5% of their machines with debugging builds, and see what assertions/log messages output. (This is all a lot nicer with a log framework that can be turned on at runtime too, but that's a whole other story) @@ +1976,3 @@ + strcmp (field->key, "SYSLOG_IDENTIFIER") != 0 && + strcmp (field->key, "SYSLOG_PID") != 0 && + strcmp (field->key, "GLIB_DOMAIN") != 0) This is a candidate for a gperf lookup.
(In reply to Colin Walters from comment #10) > Review of attachment 324005 [details] [review] [review]: > > I only gave this a very superficial look so far. Thanks; do you have any other comments about the general approach, or about the naming question in comment #9? > ::: glib/gmessages.c > @@ +65,3 @@ > + * get additional log data. Code which uses logging in > performance-critical > + * sections should compile out the g_log_structured() calls in > + * non-development builds. > > I'd say "debugging" builds. A hybrid approach some organizations do is to > deploy e.g. 5% of their machines with debugging builds, and see what > assertions/log messages output. Fair. I’ll change that in the next iteration. > @@ +1976,3 @@ > + strcmp (field->key, "SYSLOG_IDENTIFIER") != 0 && > + strcmp (field->key, "SYSLOG_PID") != 0 && > + strcmp (field->key, "GLIB_DOMAIN") != 0) > > This is a candidate for a gperf lookup. Sure, if you’re happy with me adding a gperf dependency to GLib (or committing the generated files).
(In reply to Philip Withnall from comment #9) > (In reply to Matthias Clasen from comment #8) > > NAK to having both g_message/g_warning/g_critical and > > G_MESSAGE/G_WARNING/G_CRITICAL and having them do different things. > > OK. What about g_message_structured() or G_MESSAGE_STRUCTURED(). Bit more > typing though. Certainly better than what you had before; although I still don't like the all caps. My more fundamental issue with this approach is that we end up with two parallel logging infrastructures in GLib. I'd much rather see us put structured logging underneath the existing apis, and then add new apis to expose the new functionality.
(In reply to Philip Withnall from comment #11) > (In reply to Colin Walters from comment #10) > > Review of attachment 324005 [details] [review] [review] [review]: > > > > I only gave this a very superficial look so far. > > Thanks; do you have any other comments about the general approach, or about > the naming question in comment #9? > > > ::: glib/gmessages.c > > @@ +65,3 @@ > > + * get additional log data. Code which uses logging in > > performance-critical > > + * sections should compile out the g_log_structured() calls in > > + * non-development builds. > > > > I'd say "debugging" builds. A hybrid approach some organizations do is to > > deploy e.g. 5% of their machines with debugging builds, and see what > > assertions/log messages output. > > Fair. I’ll change that in the next iteration. > > > @@ +1976,3 @@ > > + strcmp (field->key, "SYSLOG_IDENTIFIER") != 0 && > > + strcmp (field->key, "SYSLOG_PID") != 0 && > > + strcmp (field->key, "GLIB_DOMAIN") != 0) > > > > This is a candidate for a gperf lookup. > > Sure, if you’re happy with me adding a gperf dependency to GLib (or > committing the generated files). Sounds to me like optimization without profiling... there are many other places in the GTK+ stack that do this sort of string key lookup and would be much more likely candidates for performance wins. Measure first.
(In reply to Matthias Clasen from comment #13) > Sounds to me like optimization without profiling... > > there are many other places in the GTK+ stack that do this sort of string > key lookup and would be much more likely candidates for performance wins. > Measure first. True. I’ll leave that for now and we can always optimise it later. (In reply to Matthias Clasen from comment #12) > (In reply to Philip Withnall from comment #9) > > (In reply to Matthias Clasen from comment #8) > > > NAK to having both g_message/g_warning/g_critical and > > > G_MESSAGE/G_WARNING/G_CRITICAL and having them do different things. > > > > OK. What about g_message_structured() or G_MESSAGE_STRUCTURED(). Bit more > > typing though. > > Certainly better than what you had before; although I still don't like the > all caps. I’ve gone with g_message_structured(), g_debug_structured(), etc. G_DEBUG_NOW() remains capitalised because it’s intended for debug use, and I think it helps for it to stand out in that case. > My more fundamental issue with this approach is that we end up with two > parallel logging infrastructures in GLib. I'd much rather see us put > structured logging underneath the existing apis, and then add new apis to > expose the new functionality. Indeed, I had some questions about that in comment #7: > This patch series is not yet ready to be pushed. In particular, more tests need to be added, and something needs to be done about g_test_expect_message(). I think g_test_expect_message() should be deprecated, and replaced by something which allows the user more flexibility over how the lists of outputted and expected messages are matched. This would allow tests to easily ignore messages which appear on one code path but not another; or messages which are repeated an unknown number of times. > > I’m not sure either about how to integrate g_log() and g_log_structured(). I am inclined to leave them separate for the moment, as they have slightly different semantics regarding log domains and fatal behaviour which would be hard to reconcile between them. I think it might be possible to put structured logging beneath the current logging API, but I suspect it would have to be a ground-up rewrite, which scares me a little. It’s the kind of API which applications have been using in obscure ways for a long time, and I fear that changing any part of it will break those applications. What I was thinking about doing would be to keep the two systems separate, but deprecate various parts of the old logging API which don’t map well to the new one (fatal masks, g_log_set_always_fatal(), log handlers and default handlers, user-defined log levels). After a few releases, the remaining parts of the logging API (g_log(), g_debug(), g_message(), etc.) could be ported to use structured logging underneath, and lose support for the deprecated functions. However, that would be an API break. The non-API-breaking alternative would be to keep the two systems separate forever (and remove the functions listed as to be deprecated, above, when we hit GLib 3.0, hah). This is the simplest approach, and shouldn’t confuse users as long as the documentation is fairly explicit about the fact that the two systems can’t be mixed (in which case, I should move the structured logging APIs to a new documentation section). It shouldn’t affect application behaviour. The only downside I can think of is that we keep carrying the old code around.
There will never be a glib3. Any plans predicated on that are doomed
(In reply to Matthias Clasen from comment #15) > There will never be a glib3. Any plans predicated on that are doomed I thought that was the case, hence the ‘hah’. Got any thoughts about the rest of comment #14?
I think things like fatal masks, aborts, etc should remain g_log features. I would expect us to offer a simple connect-glog-to-the-journal api that installs a message handler doing the right thing. For me, that would be the main win here - there's all those g_log calls out there, and if we can make them end up in the journal with what little bits of strucured metadata we can scoop up behind the scenes, thats great. Waiting for the world to switch to g_structured_log, not so much.
(In reply to Matthias Clasen from comment #17) > I think things like fatal masks, aborts, etc should remain g_log features. > > I would expect us to offer a simple connect-glog-to-the-journal api that > installs a message handler doing the right thing. For me, that would be the > main win here - there's all those g_log calls out there, and if we can make > them end up in the journal with what little bits of strucured metadata we > can scoop up behind the scenes, thats great. That seems reasonable, yeah. Where the most important structured values are going to be info vs critical/error. > Waiting for the world to switch to g_structured_log, not so much. I guess for the projects I maintain now I'd mostly be fine just taking a hard dependency on libsystemd. But for some like gnome-shell it does seem valuable to have a structured API that falls back to printf if not on systemd.
(In reply to Matthias Clasen from comment #17) > I think things like fatal masks, aborts, etc should remain g_log features. > > I would expect us to offer a simple connect-glog-to-the-journal api that > installs a message handler doing the right thing. For me, that would be the > main win here - there's all those g_log calls out there, and if we can make > them end up in the journal with what little bits of strucured metadata we > can scoop up behind the scenes, thats great. > > Waiting for the world to switch to g_structured_log, not so much. Reasonable. Do you mean for there to be some: g_log_enable_journald_output(); which would switch g_log() from printing to stdout to calling g_log_structured() instead? Or do you mean for that to be implicit, and with GLib 2.50 have all g_log() calls actually call through to g_log_structured() instead of fprintf(stdout)? I would suggest the latter, otherwise people are going to have to change their code to call g_log_enable_journald_output(), which I doubt they would just to get structured log level data in the journal. In either case, the least invasive way of doing it would be to replace the fprintf() calls with g_log_structured(). That would preserve the fatal masks, aborts, etc. in the g_log() layer, and would mean that messages from g_log() are only passed through to g_log_structured() if they would have been printed on the terminal. If an application has installed a custom g_log() handler, the messages would not reach g_log_structured() unless that handler called g_log_default_handler(). Messages would then be passed through the g_log_structured() writer callback, which could also choose to drop them, or send them somewhere other than the journal or stdout. I think that all fits together OK.
Created attachment 329726 [details] [review] fixup! gmessages: Add a structured logging API
Created attachment 329727 [details] [review] gmessages: Rebase g_log() on g_log_structured() Replace the underlying write_string() call which is the ultimate result of calling g_log() with a call to g_log_structured(). This means that all g_log() calls will pass through the structured log handling code path, as long as they are not already modified or dropped by the g_log() code (fatal masks, aborts, etc.). In the case that the default structured log writer is in use, this will result in the same format of log output to stdout or stderr, as previously happened. If a non-default writer is in use, it handles the message as it sees fit.
Created attachment 329728 [details] [review] fixup! gmessages: Add a structured logging API
Created attachment 329729 [details] [review] fixup! gmessages: Add a structured logging API
Created attachment 329730 [details] [review] fixup! gmessages: Rebase g_log() on g_log_structured()
Created attachment 329731 [details] [review] fixup! gmessages: Add a structured logging API
Created attachment 329732 [details] [review] fixup! gmessages: Add a structured logging API
Various fixups to the original set of commits; I can provide a squashed patchset if wanted. This is ready for more detailed review. All the unit tests pass now; the journald API (https://github.com/systemd/systemd/issues/2473fa) is not needed since we currently check the link in /proc/$pid/fd/1 to see if it's a socket (which journald uses and, for example, stdout does not). This is probably good enough to use for now, while waiting for the journald API.
Review of attachment 324006 [details] [review]: ::: glib/gmessages.c @@ +1253,3 @@ + gboolean use_colour) +{ + /* we may not call _any_ GLib functions here */ We may not call any GLib functions... @@ +1271,3 @@ + return "\033[1;32m"; + + return "\033[1;31m"; ... And yet we call g_assert_not_reached(). So: 1. the comment is wrong, and should be removed 2. g_assert_not_reached() is safe, and should be noted 3. g_assert_not_reached() is not safe, and this function needs to be fixed to call abort(). Also, if G_DISABLE_ASSERT is set, this function will generate a compile error as it does not return, and nothing has told the compiler that.
Created attachment 329817 [details] [review] gmessages: Simplify _g_log_abort() in gmessages.c a little
Created attachment 329818 [details] [review] gmessages: Add a structured logging API In parallel with g_log(), add a new structured logging API, based around g_log_structured() and various helper functions which are exposed publicly to allow programs to build their own logging policies easily, without having to rewrite a lot of gmessages.c because it’s all internal. See the expanded documentation at the top of gmessages.c for some rationale. See the g_log_structured() documentation for some example code.
Created attachment 329819 [details] [review] gmessages: Add colour output support to structured log messages If outputting to a terminal which supports coloured output (rather than, for example, redirecting to a file). This is only enabled for structured log messages, where colour output support can be tested. It is not enabled for non-structured log messages.
Created attachment 329820 [details] [review] gmessages: Rebase g_log() on g_log_structured() Replace the underlying write_string() call which is the ultimate result of calling g_log() with a call to g_log_structured(). This means that all g_log() calls will pass through the structured log handling code path, as long as they are not already modified or dropped by the g_log() code (fatal masks, aborts, etc.). In the case that the default structured log writer is in use, this will result in the same format of log output to stdout or stderr, as previously happened. If a non-default writer is in use, it handles the message as it sees fit.
Updated patch set which squashes in all the above fixups, fixes comment #28, and fixes the MY_APPLICATION_STATE example to actually do what the documentation and code expect. - Remove gtest_log_writer() because it's handled through g_log() now - Fix dereferencing of array elements in g_log_writer_default() - Disable fatal handling when passing through from g_log() to g_log_structured() as the former already handles it - Remove g_assert_not_reached() from a few places - Separate recursion handling in g_log() and g_log_structured() so that it doesn't abort when g_log() passes through to g_log_structured()
Created attachment 329821 [details] [review] gmessages: detect logging to the journal more reliably Systemd has a pull request open which adds the $JOURNAL_STREAM environment variable [1]. That can be used to more reliably find out if a process is connected to the journal. I've attached a patch to g_log_writer_is_journal_fd() that uses that instead. https://github.com/systemd/systemd/pull/3537
Review of attachment 329821 [details] [review]: Thanks! Looks good to apply if/when the other patches are reviewed/fixed/accepted.
Review of attachment 329818 [details] [review]: ::: glib/gmessages.c @@ +1573,3 @@ + g_return_val_if_fail (output != NULL, FALSE); + + return isatty (fileno (output)); I don't think we need api for this, tbh - if a writer func implementation wants to check this, it can just use isatty itself @@ +1650,3 @@ + const GLogField *fields, + gsize n_fields, + gboolean use_colour) use_color is not used at all, afaics. @@ +1688,3 @@ + else + g_string_append_printf (gstring, "(%s:%lu): ", prg_name, pid); + } Isn't the pid part of journald logs anyway ? @@ +1772,3 @@ + * locale’s character set — so we assume the incoming @fields are correctly + * encoded. If this isn’t true for you, please file a bug. */ + g_warn_if_fail (g_get_charset (NULL)); I don't think this g_warn adds value. If you want to do something about !utf8, use strdup_convert as we do in other places. @@ +1852,3 @@ + g_print ("%s\n", out); + else + g_printerr ("%s\n", out); There's some risk here: both g_print and g_printerr have their own replaceable writer functions. I would suggest to use fprintf here. @@ +1914,3 @@ + + /* Mark messages as fatal if they have a level set in + * g_log_set_always_fatal(). */ Pet peeve of mine: line the */ up with the *s, on a line by itself. ::: glib/gmessages.h @@ +195,3 @@ + G_GNUC_NULL_TERMINATED + G_GNUC_NO_INSTRUMENT; + We dont use G_GNUC_NO_INSTRUMENT in our headers elsewhere, and I don't think we should start here. Its a pretty useless annotation, and having a macro for it was a bad idea... @@ +206,3 @@ + gpointer user_data, + GDestroyNotify user_data_free) + G_GNUC_NO_INSTRUMENT; This repeats the mistake we made with these setters for the g_log api: You need to be able to save the old func, including its user data. @@ +210,3 @@ +GLIB_AVAILABLE_IN_2_50 +gchar *g_log_level_flags_to_string (GLogLevelFlags flags) + G_GNUC_NO_INSTRUMENT; Not a fan of manual string conversion utilities like this in the public api @@ +214,3 @@ +GLIB_AVAILABLE_IN_2_50 +gboolean g_log_writer_supports_colour (FILE *output) + G_GNUC_NO_INSTRUMENT; Eek. A FILE* in our api ?! @@ +217,3 @@ +GLIB_AVAILABLE_IN_2_50 +gboolean g_log_writer_is_journald (FILE *output) + G_GNUC_NO_INSTRUMENT; Eek again @@ +246,3 @@ + +/** + * G_DEBUG_NOW: The NOW doesn't sit right with me. Maybe G_DEBUG_TIMESTAMP ? But aren't timestamps part of journald logs anyway ? @@ +267,3 @@ + * `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. + * + * The provided structured fields may change in future. I think the documentation should be explicit about not being able to wrap these macros in helper functions, since they use __FILE__, __LINE__, etc.
Review of attachment 329817 [details] [review]: Looks ok to me
Review of attachment 329819 [details] [review]: The vestigial color support in the previous patch would be better off in this one, just to keep it all together.
Review of attachment 329820 [details] [review]: ::: glib/gmessages.c @@ +1919,3 @@ + { + if (g_strcmp0 (fields[i].key, "GLIB_OLD_LOG_API") == 0 && + g_strcmp0 (fields[i].value, "1") == 0) This looks a bit awkward and inefficient. If we really have to do this, then just checking the first field might be enough, since we're only passing a single field from the old log api to the new ? But I am not really convinced that we need this check anyway: per-domain fatalness is really a fringe feature of g_logv.
Comment on attachment 329817 [details] [review] gmessages: Simplify _g_log_abort() in gmessages.c a little Attachment 329817 [details] pushed as ae9e72e - gmessages: Simplify _g_log_abort() in gmessages.c a little
(In reply to Matthias Clasen from comment #36) > Review of attachment 329818 [details] [review] [review]: > > ::: glib/gmessages.c > @@ +1573,3 @@ > + g_return_val_if_fail (output != NULL, FALSE); > + > + return isatty (fileno (output)); > > I don't think we need api for this, tbh - if a writer func implementation > wants to check this, it can just use isatty itself I added this as API because it needs to grow cross-platform support. I’ll add a FIXME comment to that effect. isatty() is the simplest possible check for whether colour codes are supported. To do the check properly on UNIX, we should actually use terminfo to look up the colour support for $TERM. On Windows, we need to work out whether the terminal is cmd.exe (doesn’t support colours) or something like bash (does). I’ll move this to the following patch too, and expand its comment message to explain. > @@ +1650,3 @@ > + const GLogField *fields, > + gsize n_fields, > + gboolean use_colour) > > use_color is not used at all, afaics. Will be moved to the following patch. > @@ +1688,3 @@ > + else > + g_string_append_printf (gstring, "(%s:%lu): ", prg_name, pid); > + } > > Isn't the pid part of journald logs anyway ? This is in g_log_writer_format_fields(), which is called by g_log_writer_standard_streams() to format the message for printing to stdout if we’re not using the journal. If we are using the journal, there is no need to format the message fields. > @@ +1772,3 @@ > + * locale’s character set — so we assume the incoming @fields are > correctly > + * encoded. If this isn’t true for you, please file a bug. */ > + g_warn_if_fail (g_get_charset (NULL)); > > I don't think this g_warn adds value. If you want to do something about > !utf8, use strdup_convert as we do in other places. As the comment above the g_warn_if_fail() explains, I don’t think we can arbitrarily use strdup_convert() to convert fields to UTF-8 if the process’ charset is not UTF-8, since we don’t know which fields are text and which are arbitrary binary. I guess we do know a few well-known fields (those listed in _g_log_writer_fallback()) but converting them and not the others seems a bit inconsistent. I suppose it would simplify the most common use case of not providing any custom fields, though. We could then document that it’s the application’s responsibility to convert all other fields to UTF-8. What do you think? > @@ +1852,3 @@ > + g_print ("%s\n", out); > + else > + g_printerr ("%s\n", out); > > There's some risk here: both g_print and g_printerr have their own > replaceable writer functions. I would suggest to use fprintf here. OK. > @@ +1914,3 @@ > + > + /* Mark messages as fatal if they have a level set in > + * g_log_set_always_fatal(). */ > > Pet peeve of mine: line the */ up with the *s, on a line by itself. Done. > ::: glib/gmessages.h > @@ +195,3 @@ > + G_GNUC_NULL_TERMINATED > + G_GNUC_NO_INSTRUMENT; > + > > We dont use G_GNUC_NO_INSTRUMENT in our headers elsewhere, and I don't think > we should start here. Its a pretty useless annotation, and having a macro > for it was a bad idea... Fair. Dropped. > @@ +206,3 @@ > + gpointer user_data, > + GDestroyNotify > user_data_free) > + G_GNUC_NO_INSTRUMENT; > > This repeats the mistake we made with these setters for the g_log api: You > need to be able to save the old func, including its user data. No, the entire point of this is that the application sets its writer function once, at startup, and that’s used for the remainder of the process’ lifetime. There should be no need to set a new one. Do you have a particular use case in mind which this API doesn’t fit? > @@ +210,3 @@ > +GLIB_AVAILABLE_IN_2_50 > +gchar *g_log_level_flags_to_string (GLogLevelFlags flags) > + G_GNUC_NO_INSTRUMENT; > > Not a fan of manual string conversion utilities like this in the public api I think such functions are useful for debugging; though I think in this case I made it public because it was used in one of the formatting functions, and one of the motivations for all this API is to allow applications to be able to reuse components of GLib’s implementation, especially for formatting. However, I don’t think it’s used in any of the patches any more, so it can be dropped. > @@ +214,3 @@ > +GLIB_AVAILABLE_IN_2_50 > +gboolean g_log_writer_supports_colour (FILE *output) > + G_GNUC_NO_INSTRUMENT; > > Eek. A FILE* in our api ?! Changed to an FD. > @@ +217,3 @@ > +GLIB_AVAILABLE_IN_2_50 > +gboolean g_log_writer_is_journald (FILE *output) > + G_GNUC_NO_INSTRUMENT; > > Eek again Changed to an FD. > @@ +246,3 @@ > + > +/** > + * G_DEBUG_NOW: > > The NOW doesn't sit right with me. Maybe G_DEBUG_TIMESTAMP ? But aren't > timestamps part of journald logs anyway ? Or G_DEBUG_HERE, which is a bit shorter? Timestamps are part of journald logs, but not part of the stdout formatting given by g_log_writer_standard_streams(), which is what’s probably going to be used here, as the developer is likely to be running their code from a terminal. > @@ +267,3 @@ > + * `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. > + * > + * The provided structured fields may change in future. > > I think the documentation should be explicit about not being able to wrap > these macros in helper functions, since they use __FILE__, __LINE__, etc. OK.
(In reply to Matthias Clasen from comment #39) > Review of attachment 329820 [details] [review] [review]: > > ::: glib/gmessages.c > @@ +1919,3 @@ > + { > + if (g_strcmp0 (fields[i].key, "GLIB_OLD_LOG_API") == 0 && > + g_strcmp0 (fields[i].value, "1") == 0) > > This looks a bit awkward and inefficient. If we really have to do this, then > just checking the first field might be enough, since we're only passing a > single field from the old log api to the new ? Good idea; done. > But I am not really convinced that we need this check anyway: per-domain > fatalness is really a fringe feature of g_logv. ABI stability! One example of this: the unit tests fail without the GLIB_OLD_LOG_API stuff. We either discard ABI stability entirely and don’t provide support for g_log() using g_log_structured(); or we do it properly. Otherwise people will just get annoyed that g_log() used to work with per-domain fatalness and now apparently doesn’t.
(In reply to Philip Withnall from comment #41) > (In reply to Matthias Clasen from comment #36) > > Review of attachment 329818 [details] [review] [review] [review]: > > > > ::: glib/gmessages.c > > @@ +1573,3 @@ > > + g_return_val_if_fail (output != NULL, FALSE); > > + > > + return isatty (fileno (output)); > > > > I don't think we need api for this, tbh - if a writer func implementation > > wants to check this, it can just use isatty itself > > I added this as API because it needs to grow cross-platform support. I’ll > add a FIXME comment to that effect. > > isatty() is the simplest possible check for whether colour codes are > supported. To do the check properly on UNIX, we should actually use terminfo > to look up the colour support for $TERM. On Windows, we need to work out > whether the terminal is cmd.exe (doesn’t support colours) or something like > bash (does). > > I’ll move this to the following patch too, and expand its comment message to > explain. Still not a fan. Lets mull this some more. > > This is in g_log_writer_format_fields(), which is called by > g_log_writer_standard_streams() to format the message for printing to stdout > if we’re not using the journal. > > If we are using the journal, there is no need to format the message fields. Yeah, makes sense. > > I guess we do know a few well-known fields (those listed in > _g_log_writer_fallback()) but converting them and not the others seems a bit > inconsistent. I suppose it would simplify the most common use case of not > providing any custom fields, though. We could then document that it’s the > application’s responsibility to convert all other fields to UTF-8. > > What do you think? That sounds better to me. But the docs for GLogField sound to me like we do know which fields are binary and which are text. If not, maybe GLogField should gain some clear indicator for that ? > > @@ +206,3 @@ > > + gpointer user_data, > > + GDestroyNotify > > user_data_free) > > + G_GNUC_NO_INSTRUMENT; > > > > This repeats the mistake we made with these setters for the g_log api: You > > need to be able to save the old func, including its user data. > > No, the entire point of this is that the application sets its writer > function once, at startup, and that’s used for the remainder of the process’ > lifetime. There should be no need to set a new one. > > Do you have a particular use case in mind which this API doesn’t fit? I retract that comment actually. I was thinking of g_log_set_default_handler which returns the previous handler but forgets the data. As things stand with your patch, there's simply no way to get the previous log writer (except for the default one). And thats fine, I think. > > + > > +/** > > + * G_DEBUG_NOW: > > > > The NOW doesn't sit right with me. Maybe G_DEBUG_TIMESTAMP ? But aren't > > timestamps part of journald logs anyway ? > > Or G_DEBUG_HERE, which is a bit shorter? thats better
(In reply to Philip Withnall from comment #42) > (In reply to Matthias Clasen from comment #39) > > Review of attachment 329820 [details] [review] [review] [review]: > > > > ::: glib/gmessages.c > > @@ +1919,3 @@ > > + { > > + if (g_strcmp0 (fields[i].key, "GLIB_OLD_LOG_API") == 0 && > > + g_strcmp0 (fields[i].value, "1") == 0) > > > > This looks a bit awkward and inefficient. If we really have to do this, then > > just checking the first field might be enough, since we're only passing a > > single field from the old log api to the new ? > > Good idea; done. > > > But I am not really convinced that we need this check anyway: per-domain > > fatalness is really a fringe feature of g_logv. > > ABI stability! One example of this: the unit tests fail without the > GLIB_OLD_LOG_API stuff. We either discard ABI stability entirely and don’t > provide support for g_log() using g_log_structured(); or we do it properly. > Otherwise people will just get annoyed that g_log() used to work with > per-domain fatalness and now apparently doesn’t. If the loop is gone, lets keep it.
(In reply to Matthias Clasen from comment #43) > (In reply to Philip Withnall from comment #41) > > (In reply to Matthias Clasen from comment #36) > > > Review of attachment 329818 [details] [review] [review] [review] [review]: > > > > > > ::: glib/gmessages.c > > > @@ +1573,3 @@ > > > + g_return_val_if_fail (output != NULL, FALSE); > > > + > > > + return isatty (fileno (output)); > > > > > > I don't think we need api for this, tbh - if a writer func implementation > > > wants to check this, it can just use isatty itself > > > > I added this as API because it needs to grow cross-platform support. I’ll > > add a FIXME comment to that effect. > > > > isatty() is the simplest possible check for whether colour codes are > > supported. To do the check properly on UNIX, we should actually use terminfo > > to look up the colour support for $TERM. On Windows, we need to work out > > whether the terminal is cmd.exe (doesn’t support colours) or something like > > bash (does). > > > > I’ll move this to the following patch too, and expand its comment message to > > explain. > > Still not a fan. Lets mull this some more. Colin, Allison, thoughts? > > I guess we do know a few well-known fields (those listed in > > _g_log_writer_fallback()) but converting them and not the others seems a bit > > inconsistent. I suppose it would simplify the most common use case of not > > providing any custom fields, though. We could then document that it’s the > > application’s responsibility to convert all other fields to UTF-8. > > > > What do you think? > > That sounds better to me. But the docs for GLogField sound to me like we do > know which fields are binary and which are text. If not, maybe GLogField > should gain some clear indicator for that ? We know which GLogFields are nul-terminated and which have a specified length in bytes. The value of all GLogFields is an arbitrary byte array. We could have nul-terminated non-UTF-8 strings; or UTF-8 strings where the length has been provided (and it is nul-terminated, but that’s not represented in GLogField). I’ve been getting things wrong though. We //know// that any strings being passed to g_log_structured() (etc.) are UTF-8 encoded, since that’s a requirement of using GLib — any strings are internally handled as UTF-8. We only need to care about re-encoding on input or output. Input doesn’t matter here, and output doesn’t matter either since journald wants UTF-8. So I’ll just drop the g_warn_if_fail(). It was wrong to be there in the first place. This has also highlighted some inaccuracies in the documentation for g_log_writer_format_fields(), which I’ll fix. > > > @@ +206,3 @@ > > > + gpointer user_data, > > > + GDestroyNotify > > > user_data_free) > > > + G_GNUC_NO_INSTRUMENT; > > > > > > This repeats the mistake we made with these setters for the g_log api: You > > > need to be able to save the old func, including its user data. > > > > No, the entire point of this is that the application sets its writer > > function once, at startup, and that’s used for the remainder of the process’ > > lifetime. There should be no need to set a new one. > > > > Do you have a particular use case in mind which this API doesn’t fit? > > I retract that comment actually. I was thinking of g_log_set_default_handler > which returns the previous handler but forgets the data. > As things stand with your patch, there's simply no way to get the previous > log writer (except for the default one). And thats fine, I think. Great. > > > + > > > +/** > > > + * G_DEBUG_NOW: > > > > > > The NOW doesn't sit right with me. Maybe G_DEBUG_TIMESTAMP ? But aren't > > > timestamps part of journald logs anyway ? > > > > Or G_DEBUG_HERE, which is a bit shorter? > > thats better Also great. (In reply to Matthias Clasen from comment #44) > (In reply to Philip Withnall from comment #42) > > (In reply to Matthias Clasen from comment #39) > > > Review of attachment 329820 [details] [review] [review] [review] [review]: > > > > > > ::: glib/gmessages.c > > > @@ +1919,3 @@ > > > + { > > > + if (g_strcmp0 (fields[i].key, "GLIB_OLD_LOG_API") == 0 && > > > + g_strcmp0 (fields[i].value, "1") == 0) > > > > > > This looks a bit awkward and inefficient. If we really have to do this, then > > > just checking the first field might be enough, since we're only passing a > > > single field from the old log api to the new ? > > > > Good idea; done. > > > > > But I am not really convinced that we need this check anyway: per-domain > > > fatalness is really a fringe feature of g_logv. > > > > ABI stability! One example of this: the unit tests fail without the > > GLIB_OLD_LOG_API stuff. We either discard ABI stability entirely and don’t > > provide support for g_log() using g_log_structured(); or we do it properly. > > Otherwise people will just get annoyed that g_log() used to work with > > per-domain fatalness and now apparently doesn’t. > > If the loop is gone, lets keep it. It is. Thanks for the suggestion.
Created attachment 330715 [details] [review] gmessages: Add a structured logging API In parallel with g_log(), add a new structured logging API, based around g_log_structured() and various helper functions which are exposed publicly to allow programs to build their own logging policies easily, without having to rewrite a lot of gmessages.c because it’s all internal. See the expanded documentation at the top of gmessages.c for some rationale. See the g_log_structured() documentation for some example code.
Created attachment 330716 [details] [review] gmessages: Add colour output support to structured log messages If outputting to a terminal which supports coloured output (rather than, for example, redirecting to a file). This is only enabled for structured log messages, where colour output support can be tested. It is not enabled for non-structured log messages.
Created attachment 330717 [details] [review] gmessages: Rebase g_log() on g_log_structured() Replace the underlying write_string() call which is the ultimate result of calling g_log() with a call to g_log_structured(). This means that all g_log() calls will pass through the structured log handling code path, as long as they are not already modified or dropped by the g_log() code (fatal masks, aborts, etc.). In the case that the default structured log writer is in use, this will result in the same format of log output to stdout or stderr, as previously happened. If a non-default writer is in use, it handles the message as it sees fit.
Created attachment 330718 [details] [review] gmessages: Detect logging to the journal more reliably Using systemd’s new JOURNAL_STREAM environment variable.
Review of attachment 330715 [details] [review]: Is anyone signed up to port applications to use this? I think I probably could for ostree, though we'd end up with some #ifdefs, and dropping support for the "is a socket" in favor of the environment variable means it wouldn't work for me on older systemds.
Review of attachment 330716 [details] [review]: ::: glib/gmessages.c @@ +1272,3 @@ + return "\033[1;32m"; + else if (log_level & G_LOG_LEVEL_DEBUG) + return "\033[1;32m"; Where do these colors come from ? Do we need dark theme support in glib now ? ::: glib/gmessages.h @@ +207,2 @@ GLIB_AVAILABLE_IN_2_50 +gboolean g_log_writer_supports_colour (gint output_fd); I don't think we have any 'colour' in our apis in the gtk stack. I don't think we should start now...
Review of attachment 330718 [details] [review]: ::: glib/gmessages.c @@ +1631,1 @@ } Will this work in a flatpak sandbox where we just make the journal sockets available ?
(In reply to Colin Walters from comment #50) > Review of attachment 330715 [details] [review] [review]: > > Is anyone signed up to port applications to use this? I think I probably > could for ostree, though we'd end up with some #ifdefs, and dropping support > for the "is a socket" in favor of the environment variable means it wouldn't > work for me on older systemds. I hope to have a go at porting polkit, but am on holiday for the next week, so will have to pick it up when I return. If you really want support for older systems, you can always write your own writer function, based on g_log_writer_default() but which calls a custom version of g_log_writer_is_journald(). (In reply to Matthias Clasen from comment #51) > Review of attachment 330716 [details] [review] [review]: > > ::: glib/gmessages.c > @@ +1272,3 @@ > + return "\033[1;32m"; > + else if (log_level & G_LOG_LEVEL_DEBUG) > + return "\033[1;32m"; > > Where do these colors come from ? Do we need dark theme support in glib now ? I think the terminal can remap the colours to suit its theme; gnome-terminal certainly does (try Edit → Profile Preferences → Colours). > ::: glib/gmessages.h > @@ +207,2 @@ > GLIB_AVAILABLE_IN_2_50 > +gboolean g_log_writer_supports_colour (gint output_fd); > > I don't think we have any 'colour' in our apis in the gtk stack. I don't > think we should start now... Bah. I’ll brexit the API. (Well spotted.)
(In reply to Matthias Clasen from comment #52) > Review of attachment 330718 [details] [review] [review]: > > ::: glib/gmessages.c > @@ +1631,1 @@ > } > > Will this work in a flatpak sandbox where we just make the journal sockets > available ? If you redirect the stdout/stderr of the sandboxed process to the journal sockets, then you should set JOURNAL_STREAM. If you don’t redirect the output then there’s no need to do anything.
Created attachment 330742 [details] [review] gmessages: Add a structured logging API In parallel with g_log(), add a new structured logging API, based around g_log_structured() and various helper functions which are exposed publicly to allow programs to build their own logging policies easily, without having to rewrite a lot of gmessages.c because it’s all internal. See the expanded documentation at the top of gmessages.c for some rationale. See the g_log_structured() documentation for some example code.
Created attachment 330743 [details] [review] gmessages: Add colour output support to structured log messages If outputting to a terminal which supports coloured output (rather than, for example, redirecting to a file). This is only enabled for structured log messages, where colour output support can be tested. It is not enabled for non-structured log messages.
Created attachment 330744 [details] [review] gmessages: Rebase g_log() on g_log_structured() Replace the underlying write_string() call which is the ultimate result of calling g_log() with a call to g_log_structured(). This means that all g_log() calls will pass through the structured log handling code path, as long as they are not already modified or dropped by the g_log() code (fatal masks, aborts, etc.). In the case that the default structured log writer is in use, this will result in the same format of log output to stdout or stderr, as previously happened. If a non-default writer is in use, it handles the message as it sees fit.
Created attachment 330745 [details] [review] gmessages: Detect logging to the journal more reliably Using systemd’s new JOURNAL_STREAM environment variable.
I was discussing this with Nacho which in turn asked Philip on irc, and he asked to add a few comments here. I admit I did not read the whole 58 comments, and instead just looked at the header file. The first comment is "THANK YOU!", we have logging based on g_log internally and today we have a bunch of hacks in place including super ugly things like a macro for redefining G_LOG_DOMAIN at the top of each file in order to namespace it with the component name and then parsing such domain in the handler to decide what to do with the specific message. From the top of my head the features we would like are: * having __FILE__, __FUNCTION__, etc available in the handler, since today g_log macros do not have that * have a way to have "components" and then have a way to attach different logging policy to each (e.g. log component A at debug level, while all the rest at warn level) * have a way to send logs to multiple destinations, ideally on a per component basis (e.g. log everything to file, log messages higher than warn to console, log messages from component A to A.audit.log) At a glance the structured api seems either to support these things or good enough to them on top of it. One thing that may be missing is a central way to configure such policy, eg, have a way to load some configuration that describes which destinations to enable for each level and for each matching field. However I guess for now it is ok to leave this up to the application and tomorrow that could be a higher level "log4g" library that provides this kind of thing (as the similarly named, insanely bloated logging libs for other languages :) One thing that I wonder when looking at the API is why do we still need to treat the log domain as a special case: it seems to me that it could be treated in the same way as other fields, just documenting it as a "reserved" field name. In the bikeshedding department, CODE_LINE etc are a bit ugly as field names... I know they come from the systemd spec, but still... I would have expeced a naming scheme where the fields used by glib itself are namespaced in some way.
I've pushed the first 3 patches, plus a fixup of mine. I've left out the JOURNAL_STREAM patch because a) there is no systemd release with that feature yet and b) I couldn't make it work with systemd-cat, even setting JOURNAL_STREAM manually. Attachment 330742 [details] pushed as 052eaf2 - gmessages: Add a structured logging API Attachment 330743 [details] pushed as 37ef301 - gmessages: Add colour output support to structured log messages Attachment 330744 [details] pushed as fce7cfa - gmessages: Rebase g_log() on g_log_structured()
I started to replace g_warning in gtk with g_warning_structured, and then I realized how stupid that is... I literally changed nothing else. Have we considered doing this in gmessages.h ? Just replace #define g_warning(...) g_log (G_LOG_DOMAIN, \ G_LOG_LEVEL_WARNING, \ __VA_ARGS__) with #define g_warning(format, ...) \ g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING, \ format, __VA_ARGS__, \ "CODE_FILE", G_STRINGIFY (__FILE__), \ "CODE_LINE", G_STRINGIFY (__LINE__), \ "CODE_FUNC", G_STRINGIFY (__FUNC__), \ NULL) If there is concern about subtle differences in fatality handling, we can protect this by an opt-in #define, like #define G_LOG_USE_STRUCTURED 1
(In reply to Matthias Clasen from comment #61) > If there is concern about subtle differences in fatality handling, we can > protect this by an opt-in #define, like > > #define G_LOG_USE_STRUCTURED 1 That works for me. We would need to be careful that G_LOG_USE_STRUCTURED doesn’t leak into public headers from anybody who uses it though. Note that commit 42725fb17d532a8c5903a6c849f7ca3ae01faee7 is slightly wrong. The correct fix for g_warning_structured("Hey!) is to re-add the ‘##’ to __VA_ARGS__, rather than removing the format argument. See the stuff about ‘##’ here: https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html. I don’t want to just push a fix for it though, since I haven’t got GTK+ set up for testing with atm. --- I still need to take a look at Paolo’s and Olivier’s comments (provided privately) before we can consider this done. And I guess we need to take another look at the fourth patch.
(In reply to Paolo Borelli from comment #59) > The first comment is "THANK YOU!", we have logging based on g_log internally > and today we have a bunch of hacks in place including super ugly things like > a macro for redefining G_LOG_DOMAIN at the top of each file in order to > namespace it with the component name and then parsing such domain in the > handler to decide what to do with the specific message. > > > From the top of my head the features we would like are: > * having __FILE__, __FUNCTION__, etc available in the handler, since today > g_log macros do not have that This is the case: find the `CODE_FILE`, `CODE_LINE`, etc. fields in the array of fields passed to your writer function. The field naming follows the standard set by journald: https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html > * have a way to have "components" and then have a way to attach different > logging policy to each (e.g. log component A at debug level, while all the > rest at warn level) You can add your own custom field for the component name, then use that as an input to your logging policy in your writer function. The writer function is where you set your logging policy, and it can be as simple or as complex as you like. > * have a way to send logs to multiple destinations, ideally on a per > component basis (e.g. log everything to file, log messages higher than warn > to console, log messages from component A to A.audit.log) Yup, again, this is a matter of implementing that policy in your writer function. > At a glance the structured api seems either to support these things or good > enough to them on top of it. The idea is that GLib provides the mechanism to do whatever policy you want. > One thing that may be missing is a central way to configure such policy, eg, > have a way to load some configuration that describes which destinations to > enable for each level and for each matching field. However I guess for now > it is ok to leave this up to the application and tomorrow that could be a > higher level "log4g" library that provides this kind of thing (as the > similarly named, insanely bloated logging libs for other languages :) At the moment, I think that’s too specific to a single use case to include in GLib. It’s something which most applications wouldn’t need. As you say, though, it could be implemented in a higher-level library and parts of it could eventually filter down to GLib if they turn out to be useful for most programs. > One thing that I wonder when looking at the API is why do we still need to > treat the log domain as a special case: it seems to me that it could be > treated in the same way as other fields, just documenting it as a "reserved" > field name. It’s a bit of a trade off. Internally, the log domain is handled the same as any other field — the only thing that g_log_structured() does with its log_domain parameter is turn it into a GLIB_DOMAIN field. It is used by g_log_writer_format_fields() to be put in normal formatted output. It is used by g_log_writer_default() to check against G_MESSAGES_DEBUG. The idea for including it as a parameter to g_log_structured() was because it’s a fairly commonly used field — most code which uses GLib logging also uses logging domains appropriately. So it’s there as a convenience, to save having to add a GLIB_DOMAIN field manually, which would be a bit more faff. Do you think that’s an acceptable tradeoff? I’m open to being persuaded. > In the bikeshedding department, CODE_LINE etc are a bit ugly as field > names... I know they come from the systemd spec, but still... I would have > expeced a naming scheme where the fields used by glib itself are namespaced > in some way. I think consistency with the systemd spec is important, and the lack of namespacing isn’ŧ a problem since they’re defined in the spec. The custom fields which GLib uses are all prefixed with ‘GLIB_’. Do you think it would make sense to include some advice in the documentation about what namespacing applications should do? I guess it would. Commit 12acd90d8a9c728aac621a3103c3d84e6c98c81c pushed to cover that one.
(In reply to Philip Withnall from comment #62) > (In reply to Matthias Clasen from comment #61) > > If there is concern about subtle differences in fatality handling, we can > > protect this by an opt-in #define, like > > > > #define G_LOG_USE_STRUCTURED 1 > > That works for me. We would need to be careful that G_LOG_USE_STRUCTURED > doesn’t leak into public headers from anybody who uses it though. > > Note that commit 42725fb17d532a8c5903a6c849f7ca3ae01faee7 is slightly wrong. > The correct fix for g_warning_structured("Hey!) is to re-add the ‘##’ to > __VA_ARGS__, rather than removing the format argument. See the stuff about > ‘##’ here: https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html. I don’t > want to just push a fix for it though, since I haven’t got GTK+ set up for > testing with atm. Ah, I hadn't noticed that. We should probably take this occasion to reevaluate our current complex support for various forms of variadic macros: G_HAVE_ISO_VARARGS G_HAVE_GNUC_VARARGS if we still need to support both of these, we should support them for the g_log_structured macros in the same way we do for g_log. If we can just assume C99 variadic macros, then we should document that in https://wiki.gnome.org/Projects/GLib/CompilerRequirements and simpify the g_log macros accordingly.
btw, philip: I noticed that we end up sending the GLIB_OLD_LOG_API key into the journal. Probably not a problem, but I wondered if it was intentional on your part.
(In reply to Matthias Clasen from comment #64) > (In reply to Philip Withnall from comment #62) > > (In reply to Matthias Clasen from comment #61) > > > If there is concern about subtle differences in fatality handling, we can > > > protect this by an opt-in #define, like > > > > > > #define G_LOG_USE_STRUCTURED 1 > > > > That works for me. We would need to be careful that G_LOG_USE_STRUCTURED > > doesn’t leak into public headers from anybody who uses it though. > > > > Note that commit 42725fb17d532a8c5903a6c849f7ca3ae01faee7 is slightly wrong. > > The correct fix for g_warning_structured("Hey!) is to re-add the ‘##’ to > > __VA_ARGS__, rather than removing the format argument. See the stuff about > > ‘##’ here: https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html. I don’t > > want to just push a fix for it though, since I haven’t got GTK+ set up for > > testing with atm. > > Ah, I hadn't noticed that. We should probably take this occasion to > reevaluate our current complex support for various forms of variadic macros: In any case, the ## trick you describe is a gcc extension; and we are not using it in the iso varargs case for g_warning and friends.
Created attachment 331675 [details] [review] Allow using g_log_structured instead of g_log Look for a macro G_LOG_USE_STRUCTURED, and if it is defined, use g_log_structured instead of g_log when defining g_warning and friends. This avoids the extra complication of going through g_logv _and_ g_log_structured go get a essage logged; it also lets us pass the code-related fields. We don't do this unconditionally (yet), since some users might rely on the more fine-grained fatality support in g_logv.
(In reply to Philip Withnall from comment #55) > Created attachment 330742 [details] [review] [review] > gmessages: Add a structured logging API > > In parallel with g_log(), add a new structured logging API, based around > g_log_structured() and various helper functions which are exposed > publicly to allow programs to build their own logging policies easily, > without having to rewrite a lot of gmessages.c because it’s all > internal. > > See the expanded documentation at the top of gmessages.c for some > rationale. See the g_log_structured() documentation for some example > code. from the attachment: 303 g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, 304 "This is a debug message about pointer %p and integer %u.", 305 some_pointer, some_integer, What about adding a test that checks the behavior when the format string has an odd number of insertions?
Created attachment 331698 [details] Console output on cmd.exe on Windows 10. Hi, Apparently I found that this causes some issues on Windows, that causes glib to crash on Windows/32-bit gtk3-demo upon launch when a g_warning() is triggered, but the program works okay on 64-bit builds, so probably something about sizes on pointers or so is behind this? If I revert commit fce7cfaf, then things go alright, but it does seem to me that the problem is in the g_log_structured() that was added in this patch series, as fce7cfaf makes g_log() call g_log_structured(). (In reply to Philip Withnall from comment #41) > isatty() is the simplest possible check for whether colour codes are > supported. To do the check properly on UNIX, we should actually use terminfo > to look up the colour support for $TERM. On Windows, we need to work out > whether the terminal is cmd.exe (doesn’t support colours) or something like > bash (does). Does this attach picture fit the color support that is being looked for on cmd.exe? This is from Windows 10--I need to check Windows 7 and 8.1 though. With blessings, thank you!
The number of formatting fields is not the problem. My problem is that if I run a locally built gimp-2.9(gtk2) or evince(gtk3) without setting GTK_PATH, both warn failing to load "canberra-gtk-module" Gtk-Message: Failed to load module "canberra-gtk-module" Since glib-2.49.3 gimp-2.9 crashes while evince doesn't and prints the Gtk-Message on the console. I rebuilt (adding a #warning to glib headers) gtk-2 and gtk-3 and both use as g_message macro the G_HAVE_ISO_VARARGS version this is gdb stacktrace after gimp-2.9 crash >0x00007ffff22bb2aa in __strcmp_sse2_unaligned () from /lib64/libc.so.6 >#0 0x00007ffff22bb2aa in __strcmp_sse2_unaligned () from /lib64/libc.so.6 >#1 0x00007ffff2dc230b in g_log_structured (log_domain=log_domain@entry=0x7ffff77f66bb "Gtk", log_level=log_level@entry=G_LOG_LEVEL_MESSAGE, > format=format@entry=0x7ffff2e0da36 "%s") at gmessages.c:1445 >#2 0x00007ffff2dc2520 in g_log_default_handler (log_domain=log_domain@entry=0x7ffff77f66bb "Gtk", log_level=log_level@entry=G_LOG_LEVEL_MESSAGE, > message=message@entry=0xc7f210 "Failed to load module \"canberra-gtk-module\"", unused_data=unused_data@entry=0x0) at gmessages.c:2383 >#3 0x00007ffff2dc27a7 in g_logv (log_domain=0x7ffff77f66bb "Gtk", log_level=G_LOG_LEVEL_MESSAGE, format=<optimized out>, args=args@entry=0x7fffffffd428) > at gmessages.c:1160 >#4 0x00007ffff2dc299d in g_log (log_domain=log_domain@entry=0x7ffff77f66bb "Gtk", log_level=log_level@entry=G_LOG_LEVEL_MESSAGE, > format=format@entry=0x7ffff788b2c8 "Failed to load module \"%s\"%s%s") at gmessages.c:1219 >#5 0x00007ffff7678021 in load_module (name=0xcad600 "canberra-gtk-module", module_list=0x0) at gtkmodules.c:373 >#6 load_modules (module_str=module_str@entry=0xc72bd0 "canberra-gtk-module") at gtkmodules.c:413 >#7 0x00007ffff76783a4 in _gtk_modules_settings_changed (settings=settings@entry=0xc61d80, modules=0xc72bd0 "canberra-gtk-module") at gtkmodules.c:571 >#8 0x00007ffff76784b5 in display_opened_cb (display_manager=<optimized out>, display=display@entry=0xc67010) at gtkmodules.c:499 >#9 0x00007ffff309266f in g_cclosure_marshal_VOID__OBJECTv (closure=0xc24220, return_value=<optimized out>, instance=0xc5fb40, args=<optimized out>, > marshal_data=<optimized out>, n_params=<optimized out>, param_types=0xc61af0) at gmarshal.c:2102 >#10 0x00007ffff308f935 in _g_closure_invoke_va (closure=closure@entry=0xc24220, return_value=return_value@entry=0x0, instance=instance@entry=0xc5fb40, > args=args@entry=0x7fffffffd890, n_params=<optimized out>, param_types=0xc61af0) at gclosure.c:867 >#11 0x00007ffff30aa801 in g_signal_emit_valist (instance=instance@entry=0xc5fb40, signal_id=signal_id@entry=15, detail=detail@entry=0, > var_args=var_args@entry=0x7fffffffd890) at gsignal.c:3294 >#12 0x00007ffff30ab2fc in g_signal_emit_by_name (instance=0xc5fb40, detailed_signal=detailed_signal@entry=0x7ffff730ccbf "display_opened") at gsignal.c:348 >#13 0x00007ffff72c6d5f in IA__gdk_display_open (display_name=<optimized out>) at gdkdisplay-x11.c:413 >#14 0x00007ffff7296552 in IA__gdk_display_open_default_libgtk_only () at gdk.c:324 >#15 0x00007ffff765daf8 in post_parse_hook (context=<optimized out>, group=<optimized out>, data=0xbbe1c0, error=0x7fffffffdbf8) at gtkmain.c:814 >#16 0x00007ffff2dc72a8 in g_option_context_parse (context=context@entry=0xbb8900, argc=argc@entry=0x7fffffffdbac, argv=argv@entry=0x7fffffffdbe8, > error=error@entry=0x7fffffffdbf8) at goption.c:2159 >#17 0x00007ffff2dc8177 in g_option_context_parse_strv (context=context@entry=0xbb8900, arguments=arguments@entry=0x7fffffffdbe8, > error=error@entry=0x7fffffffdbf8) at goption.c:2689 >#18 0x000000000048e24c in main (argc=<optimized out>, argv=<optimized out>) at main.c:499
(In reply to Massimo from comment #70) > The number of formatting fields is not the problem. > > My problem is that if I run a locally built gimp-2.9(gtk2) or evince(gtk3) > without setting GTK_PATH, both warn failing to load "canberra-gtk-module" > > Gtk-Message: Failed to load module "canberra-gtk-module" > > > Since glib-2.49.3 gimp-2.9 crashes while evince doesn't > and prints the Gtk-Message on the console. > > I rebuilt (adding a #warning to glib headers) gtk-2 and gtk-3 > and both use as g_message macro the G_HAVE_ISO_VARARGS version > touching glib/gmessages.c and running make -C glib install CFLAGS="-g3 -O0" fixes gimp-2.9 crash, so it could be a gcc optimization issue. gcc version 6.1.1 20160621 (Red Hat 6.1.1-3) (GCC)
(In reply to Massimo from comment #71) > (In reply to Massimo from comment #70) > > The number of formatting fields is not the problem. > > > > My problem is that if I run a locally built gimp-2.9(gtk2) or evince(gtk3) > > without setting GTK_PATH, both warn failing to load "canberra-gtk-module" > > > > Gtk-Message: Failed to load module "canberra-gtk-module" > > > > > > Since glib-2.49.3 gimp-2.9 crashes while evince doesn't > > and prints the Gtk-Message on the console. > > > > I rebuilt (adding a #warning to glib headers) gtk-2 and gtk-3 > > and both use as g_message macro the G_HAVE_ISO_VARARGS version > > > > touching glib/gmessages.c and running > > make -C glib install CFLAGS="-g3 -O0" > > fixes gimp-2.9 crash, so it could be a gcc optimization > issue. > > > gcc version 6.1.1 20160621 (Red Hat 6.1.1-3) (GCC) Building with clang fails with: clang version 3.8.0 (tags/RELEASE_380/final) CC libglib_2_0_la-gmessages.lo gmessages.c:1399:50: error: format string is not a string literal [-Werror,-Wformat-nonliteral] size = vsnprintf (buffer, sizeof (buffer), format, args); ^~~~~~ gmessages.c:1404:55: error: format string is not a string literal [-Werror,-Wformat-nonliteral] message = message_allocated = g_strdup_vprintf (format, args); ^~~~~~
Created attachment 331738 [details] [review] gmessages: Add G_GNUC_PRINTF mark for g_log_structured It is required to avoid non-literal format string warning when using clang.
Review of attachment 331738 [details] [review]: Looks good. I’m away for the next week and a bit, which is unfortunate timing; but I’ll pick this up again when I get back. (I realise that’s not very helpful given that it’s just been pushed, sorry.)
Comment on attachment 331738 [details] [review] gmessages: Add G_GNUC_PRINTF mark for g_log_structured Attachment 331738 [details] pushed as 0793299 - gmessages: Add G_GNUC_PRINTF mark for g_log_structured
Sorry, the patch doesn't seem to work with GCC ... glib/gmessages.c: In function ‘test_structured_logging_no_state’: glib/gmessages.c:2383:64: error: too many arguments for format [-Werror=format-extra-args] glib/tests/logging.c: In function ‘test_structured_logging_no_state’: glib/tests/logging.c:304:21: error: too many arguments for format [-Werror=format-extra-args]
IIUC a problem is that here the code assumes g_strdup_vprintf consumes/advances as many args as are requested by format: https://git.gnome.org/browse/glib/tree/glib/gmessages.c#n1404 That's the only way to find the NULL/sentinel here[1]: https://git.gnome.org/browse/glib/tree/glib/gmessages.c#n1414 when called from here[2]: https://git.gnome.org/browse/glib/tree/glib/gmessages.c#n2383 But man vsnprintf states that: <quote> int vsnprintf(char *str, size_t size, const char *format, va_list ap); .... The functions vprintf(), vfprintf(), vdprintf(), vsprintf(), vsnprintf() ... Because they invoke the va_arg macro, the value of ap is undefined after the call. See stdarg(3). </quote> and g_strdup_vprintf possibly calls vsnprintf, so the assumption is not guaranteed and as I see debugging gimp-2.9 the loop[1] continues beyond the NULL/sentinel passed to g_log_structured[2].
Hi, (In reply to Fan, Chun-wei from comment #69) > Created attachment 331698 [details] > Console output on cmd.exe on Windows 10. > > Hi, > > Apparently I found that this causes some issues on Windows, that causes glib > to crash on Windows/32-bit gtk3-demo upon launch when a g_warning() is > triggered, but the program works okay on 64-bit builds, so probably > something about sizes on pointers or so is behind this? If I revert commit > fce7cfaf, then things go alright, but it does seem to me that the problem is > in the g_log_structured() that was added in this patch series, as fce7cfaf > makes g_log() call g_log_structured(). To follow up, this occurs whenever a g_message() is triggered as well. Apparently I took a stab at the code--apparently the extra va_arg() calls within the two for loops in g_log_structured () caused the 32-bit code to walk over the edge when acquiring the individual varargs, causing a bad pointer returned which will then cause the crash. If I remove these va_arg() calls, things will work alright, but then the second va_arg() call acquires the value that is needed, so I'm not sure whether removing that would be alright, or is there another means to acquire it. My take at this. With blessings, thank you!
Created attachment 331757 [details] [review] gmessages: Fix G_GNUC_PRINTF mark for g_log_structured Fixes build failure with gcc.
Review of attachment 331757 [details] [review]: ::: glib/gmessages.h @@ +192,3 @@ GLogLevelFlags log_level, const gchar *format, + ...) G_GNUC_PRINTF (3, 0) This is not what the __attribute__((format...)) says it should do. The first index is the index (starting from 1) of the format string; the second on is the first argument to check. 0 should be used for vprintf-style functions, or strftime-style functions. `G_GNUC_PRINTF (3, 4)` is the appropriate annotation.
Review of attachment 331757 [details] [review]: Looking at sd-journal.h, with prior art, it seems that __attribute__((format(printf, 3, 0))) is actually the recommended practice. The compiler will just check the format string for consistency, in that case, and leave the additional arguments alone. This also fixes the build on Continuous.
Review of attachment 331757 [details] [review]: Pushed the patch with a different commit message.
*** Bug 768908 has been marked as a duplicate of this bug. ***
With glib 2.49.4, many things are crashing: Pretty much many things crash now: gnome-shell (gdb) bt full
+ Trace 236476
Reverting to before the new api was added fixes the crashes.
And nautilus: (gdb) bt full
+ Trace 236477
(In reply to Hussam Al-Tayeb from comment #85) > And nautilus: The log domain is NULL, which is not something that the default handler handles.
Created attachment 332003 [details] [review] Allow null log domains The old logging API allows NULL log domains, so we need to code defensively against the case before calling the new structured logging API.
(In reply to Emmanuele Bassi (:ebassi) from comment #87) > Created attachment 332003 [details] [review] [review] > Allow null log domains > > The old logging API allows NULL log domains, so we need to code > defensively against the case before calling the new structured > logging API. This fixed the crashes for me and gnome-keyring works again \o/
Created attachment 332127 [details] [review] gmessages.c: Fix build on non-Linux Hi, Apparently the new code updates on gmessages.c depended on strictly-Linux items unconditionally... so here's the simple patch for this. Thanks to Matthias for reworking the g_log_structured() API so that it now runs fine on Windows. BTW, are the g_log_structured() tests in glib/tests/logging.c dependent on journald behavior? I didn't get to check further yet, but apparently they crash on Windows. With blessings, thank you!
(In reply to Fan, Chun-wei from comment #89) > Created attachment 332127 [details] [review] [review] > gmessages.c: Fix build on non-Linux > > Hi, > > Apparently the new code updates on gmessages.c depended on strictly-Linux > items unconditionally... so here's the simple patch for this. Thanks to > Matthias for reworking the g_log_structured() API so that it now runs fine > on Windows. > > BTW, are the g_log_structured() tests in glib/tests/logging.c dependent on > journald behavior? I didn't get to check further yet, but apparently they > crash on Windows. They shouldn't, I don't think. All the tests I added use log writer functions that don't even try to hit the journal.
(In reply to Fan, Chun-wei from comment #89) It would be very nice to have windows event log writer implementation, btw.
(In reply to Matthias Clasen from comment #91) > (In reply to Fan, Chun-wei from comment #89) > > > It would be very nice to have windows event log writer implementation, btw. I had a look at implementing this on wing in the past but I did not have time at the end, I guess if nobody jumps in I can try to have a look at this in glib directly.
Review of attachment 332003 [details] [review]: something equivalent was already committed
Review of attachment 332127 [details] [review]: ok
Review of attachment 332127 [details] [review]: Hi Matthias, Thanks, I have pushed the patch as 6d6b97a. With blessings, thank you!
Created attachment 332205 [details] [review] gmessages.h: Use G_STRFUNC instead of __func__ Hi, One more simple patch from me again... make use of G_STRFUNC rather than __func__ so that all supported compilers are happy when we use structured logs. With blessings, thank you!
Review of attachment 332205 [details] [review]: Yes, makes sense.
Review of attachment 332205 [details] [review]: Hi Emmanuele, Thanks, I pushed the patch as 7cf037e. With blessings, and cheers!
I think we can call this done now. Thanks Matthias, Ray, Fan Chun-wei and others for polishing it all and giving it more testing.