Logging and more

A while ago, GLib gained a new facility for ‘structured logging’. At the same time, it also gained support for writing logs to the systemd journal. Clearly, logging in GLib got a bit more complicated, and it can be a bit confusing.

This article is an attempt to clarify things.

Structured or not

The traditional GLib logging facilities are the g_message(), g_debug(), etc macros, which eventually call the g_log() function, which then uses the log handler that has been set with g_log_set_handler() to do the actual writing. You can put any information you like into your logs, but it has to all be formatted as a single string, the message.

g_debug ("You have %d eggs", 12 + 2);

g_log (G_LOG_DOMAIN,
       G_LOG_LEVEL_DEBUG,
       "You have %d eggs", 12 + 2);

With the new structured logging facilities, you call g_log_structured(), which then uses a log writer function to do the writing. So far, this is very similar to the older logging facility. The advantage of structured logs is that you can put multiple fields into the log without resorting to formatting it all into a string. Instead, you pass an array of log fields, which are key-value pairs.

g_log_structured (G_LOG_DOMAIN,
                  G_LOG_LEVEL_DEBUG,
                  "CODE_FILE", "mysource.c",
                  "CODE_LINE", 312,
                  "MESSSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e",
                  "MESSAGE", "You have %d eggs", 12 + 2);

CODE_FILE, CODE_LINE and MESSAGE_ID here are just examples for “standard” fields. You can also invent your own fields. Note that you can still use printf-style formatting for the MESSAGE field.

So GLib has two separate logging facilities now. To make matters a bit more interesting, we allow you to redirect the g_message(), g_debug(), etc wrapper macros to use g_log_structured() instead of g_log() under the covers. To do so, define the G_LOG_USE_STRUCTURED macro before including glib.h.

Why is this useful? For one thing, it saves you the trouble of replacing all your g_debug() and still lets you take some advantage of the structured logging – when used in this fashion, the traditional macros use separate fields for the log domain, the code file and line and some other fields, which can be helpful for filtering and searching in the resulting logs, in particular with the systemd journal.

Another advantage is that you can use a single backend, the log writer function, to control where both old and new logging calls end up.

Where have all my logs gone ?

Structured logging is frequently associated with the systemd journal. So, it is not surprising that people expect the g_log_structured() output to go the journal. And that is a really useful thing for services, or when you are launching an application e.g. from a desktop icon. But if you run it from the terminal, you probably expect to see its output right there.

To satisfy these competing demands, the GLib default log writer function tries to be smart. If it detects that stderr is redirected to the journald socket, then it writes its structured output to the journal. Otherwise, it formats a message and writes it to stderr.

Both GNOME Shell and DBus arrange for stderr to be redirected to the journal when they start apps or services. A way to explicitly redirect stderr to the journal is to run your application under systemd-cat:

systemd-cat my-app-that-logs

If you are sure that you want your logs to always go to the journal, you can tell GLib to use a log writer that does that:

g_log_set_writer_func (g_log_writer_journald, NULL, NULL)

Beyond the default

Even though the log writer functions that GLib provides by default should serve many needs, you might need to write your own. In that case, GLib has a number of useful functions that can help you, such as g_log_writer_format_fields(), g_log_writer_is_journald() or g_log_writer_supports_color().

Happy logging!

References

GLib 2.19.6 unstable release

This is the sixth development release leading up to GLib 2.20.
7 bugs fixed in this release!

  • General
    • New format macro to print goffset data: G_OFFSET_FORMAT
  • GIO:
    • Add a GFilter{Input,Output}Stream::close-base-stream properties which determine whether the base stream will be closed when the filter stream is finalized.
    • g_data_input_stream_read_line and …_read_until have asynchronous variants now.

Read the original announcement for more info and downloads.

GLib 2.19.1 unstable release

This is the second development release leading up to GLib 2.20.

Overview of Changes from GLib 2.19.0 to GLib 2.19.1

  • g_icon_to_string, g_icon_new_for_string: GIcon serialization support
  • G_FILE_ATTRIBUTE_PREVIEW_ICON: new file attribute for preview images
  • g_app_info_get_commandline: new function to get the full commandline
  • g_mount_shadow, g_mount_unshadow, g_mount_is_shadowed: New
  • functions to ‘shadow’ mounts (i.e. hide them from the UI when they already have a different representation, like a bookmark)

42 bugs fixed in this release.

Read the original announcement for more info and downloads.

GLib 2.19.0 unstable release

This is the first development release leading up to GLib 2.20.

Overview of Changes from GLib 2.18.1 to GLib 2.19.0

  • Rewrite GHashTable to use open addressing with quadratic probing instead of chaining. This has the potential to reduce memory fragmentation significantly, while being slightly faster due to better locality and no need to call alloc/free functions for nodes. Benchmarks suggest it also uses less memory overall.
  • Make g_poll available as public api
  • New macros g_assert_error and g_assert_no_error to assert that a GError is set or unset
  • g_cancellable_make_pollfd: New method to make a GPollFD for a cancellable
  • g_app_info_can_delete, g_app_info_delete, g_app_info_reset_type_associations: New functions to clean up app infos and content types
  • When launching applications, always pass fuse file:// uris when possible, and let gio convert such uris back to gio uris.

33 bugs fixed in this release!

Read the original announcement for more info and downloads.