GNOME Bugzilla – Bug 661926
Improve the default logging setup in GLib
Last modified: 2017-06-16 10:10:42 UTC
The default logging setup in GLib is a bit too simple to work out of the box. This forces many projects to implement their own log handler. Two things that have been mentioned frequently are - message timestamps - debug messages being emitted by default These patches introduce a few more environment variables to influence the behavior of the default log handler: G_MESSAGES_TIMESTAMP and G_MESSAGES_LEVELS. Some open questions: - Do we need a separate variable for timestamps, or could this just be subsumed with G_MESSAGES_PREFIXED ? - Should G_MESSAGES_LEVELS by just G_MESSAGES ?
Created attachment 199139 [details] [review] Add timestamp support to the default log handler This adds support for a G_MESSAGES_TIMESTAMP environment variable which specifies log levels for which to prepend a timestamp to each log message. The format of the timestamps is hh:mm:ss:mmm.
Created attachment 199140 [details] [review] Make log levels configurable for the default log handler Introduce a G_MESSAGES_LEVELS environment variable that lets you specify which log levels to let through in the default log handler. We always let errors, warnings and criticals through, but messages, infos and debugs are not emitted by default. This is an attempt to make the default log handler good enough for most situations.
Created attachment 199141 [details] [review] Improve log handler documentation
*** Bug 430334 has been marked as a duplicate of this bug. ***
(In reply to comment #2) > Introduce a G_MESSAGES_LEVELS environment variable that lets > you specify which log levels to let through in the default > log handler. We always let errors, warnings and criticals > through, but messages, infos and debugs are not emitted > by default. 1) I always assumed g_message()s would be emitted by default... sort of a more annoying version of g_printf(). 2) Since some libraries include egregious amounts of g_debug() spew, it might be nice to be able to enable it on a per-module basis. "G_DEBUG_MESSAGES='Gtk Shell' ./blah" or something 3) It would be awesome if there was some method that you could set a breakpoint on that would only be hit for messages that were actually being printed. (I hate it when I set a breakpoint on g_log and it stops on suppressed g_debug messages.)
The following fix has been pushed: d2d62ec Make the default log handler more useful
Created attachment 200569 [details] [review] Make the default log handler more useful We make the default log handler only print default and informational messages if the log domain is explicitly requested.
Hi Matthias, Why is G_MESSAGES_DEBUG space-separated? Now that I read the code, domain is actually simply matched with strstr, so actually, :, etc works too :) What about G_MESSAGES_LEVELS & G_MESSAGES_TIMESTAMP ? you dropped the idea for what reason? thanks
(In reply to Marc-Andre Lureau from comment #8) > Hi Matthias, > > Why is G_MESSAGES_DEBUG space-separated? Now that I read the code, domain is > actually simply matched with strstr, so actually, :, etc works too :) Because it’s always been space-separated, and space-separation is more common than :-separation. > What about G_MESSAGES_LEVELS & G_MESSAGES_TIMESTAMP ? you dropped the idea > for what reason? I don’t know what Matthias’ thinking is about these (6 years on), but with the structured logging support, you can just implement your own writer function to add them if you want. See g_log_set_writer_func().
(In reply to Philip Withnall from comment #9) > (In reply to Marc-Andre Lureau from comment #8) > > Hi Matthias, > > > > Why is G_MESSAGES_DEBUG space-separated? Now that I read the code, domain is > > actually simply matched with strstr, so actually, :, etc works too :) > > Because it’s always been space-separated, and space-separation is more > common than :-separation. What has always been space-separated? G_MESSAGES_DEBUG? sure since it was added this way. The question is still why? g_parse_debug_string() used for many other _DEBUG environmnet variables accept much more seperators. > > > What about G_MESSAGES_LEVELS & G_MESSAGES_TIMESTAMP ? you dropped the idea > > for what reason? > > I don’t know what Matthias’ thinking is about these (6 years on), but with > the structured logging support, you can just implement your own writer > function to add them if you want. See g_log_set_writer_func(). Yeah, you could also just implement G_MESSAGES_DEBUG in your own handler. But when something is generally useful, it is nice to have it in glib... Another annoyance, g_log_set_writer_func() is not per domain any more, so you can't have debug level filtering provided for a specificy library domain for ex. Btw, I fail to see what the log writer return value is for. It seems to be ignored, it could be void. At least, the documentation could tell the default behaviour in case of unhandled return. thanks
(In reply to Marc-Andre Lureau from comment #10) > (In reply to Philip Withnall from comment #9) > > (In reply to Marc-Andre Lureau from comment #8) > > > Hi Matthias, > > > > > > Why is G_MESSAGES_DEBUG space-separated? Now that I read the code, domain is > > > actually simply matched with strstr, so actually, :, etc works too :) > > > > Because it’s always been space-separated, and space-separation is more > > common than :-separation. > > What has always been space-separated? G_MESSAGES_DEBUG? sure since it was > added this way. Yes. > The question is still why? g_parse_debug_string() used for > many other _DEBUG environmnet variables accept much more seperators. I’m not sure I see the point of the question. Is the fact that it’s space-separated causing problems for you? > Another annoyance, g_log_set_writer_func() is not per domain any more, so > you can't have debug level filtering provided for a specificy library domain > for ex. That’s part of the point of having a single writer function — all message output is now in control of the application, rather than libraries all installing conflicting log handler functions and all using separate environment variables for enabling debug messages, which made things a pain for users to debug. Have you read the introduction to the new logging functionality? https://developer.gnome.org/glib/stable/glib-Message-Logging.html#glib-Message-Logging.description If you’re an application developer, your writer function can match messages on their `GLIB_DOMAIN` key and filter them as appropriate. If you’re a library developer, you should not care about where your debug output goes or how it’s handled. Your library outputs messages; the application which is using the library works out whether it cares about them. > Btw, I fail to see what the log writer return value is for. It seems to be > ignored, it could be void. At least, the documentation could tell the > default behaviour in case of unhandled return. It’s useful when your application’s log writer function is chaining up to another log writer function. If the chained call returns G_LOG_WRITER_UNHANDLED, the application can choose to use a different log writer instead. The default top-level behaviour in case of G_LOG_WRITER_UNHANDLED is to drop the log message (what else can we do?). The documentation was a bit lacking in this area, so I’ve expanded it a bit: commit ac0b0c84f7d310012d6960d96bb5daa62b8d2d48 Author: Philip Withnall <withnall@endlessm.com> Date: Wed Jun 14 09:56:13 2017 +0100 gmessages: Expand documentation on GLogWriterFunc chaining As prompted by Marc-Andre Lureau. Signed-off-by: Philip Withnall <withnall@endlessm.com> https://bugzilla.gnome.org/show_bug.cgi?id=661926 glib/gmessages.c | 5 ++++- glib/gmessages.h | 7 +++++++ 2 files changed, 11 insertions(+), 1 deletion(-) --- If you have other problems with the new logging functionality, please open a new bug report with specific concerns. I don’t want this old one to get appropriated for unrelated problems. Thanks.
(In reply to Philip Withnall from comment #11) > > The question is still why? g_parse_debug_string() used for > > many other _DEBUG environmnet variables accept much more seperators. > > I’m not sure I see the point of the question. Is the fact that it’s > space-separated causing problems for you? It's usually considered more convenient not to have to quote strings. And for consistency with other _DEBUG variables, I would have the other separators. > If you’re a library developer, you should not care about where your debug > output goes or how it’s handled. Your library outputs messages; the > application which is using the library works out whether it cares about them. I mostly agree with you. But it's not that simple, there are historical practices, and you know, people don't like changes.. I'll try to catch on irc for some other questions. Thanks
(In reply to Marc-Andre Lureau from comment #12) > (In reply to Philip Withnall from comment #11) > > > The question is still why? g_parse_debug_string() used for > > > many other _DEBUG environmnet variables accept much more seperators. > > > > I’m not sure I see the point of the question. Is the fact that it’s > > space-separated causing problems for you? > > It's usually considered more convenient not to have to quote strings. And > for consistency with other _DEBUG variables, I would have the other > separators. As you said, the matching is done with strstr() so there’s nothing stopping you from using `:` when you use G_MESSAGES_DEBUG. I don’t want to change the documentation or the default practice, though, since I’ve seen domain names containing colons. > > If you’re a library developer, you should not care about where your debug > > output goes or how it’s handled. Your library outputs messages; the > > application which is using the library works out whether it cares about them. > > I mostly agree with you. But it's not that simple, there are historical > practices, and you know, people don't like changes.. The new API was accepted into GLib because the maintainers saw it as an improvement over the old one. You are welcome to continue using the old log-handler-based API if you want (it’s not marked as deprecated at the moment), and it should continue to work the same as before.