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

• Philipps talk about structured logging
• GLib logging documentation
• Systemd journal documentation