Glib logging issue

Platform
1

I have some glib / gtk programs that use logging (g_log_structured()).

I have recently noticed that the debug messages from gtk functions in these programs are showing up in the log. I am running Fedora 43 beta that is using glib 2.86 / gtk 4.20.

When I run the same program on Fedora 42, that uses glib 2.84 / gtk 4.18, I don’t see these debugging messages from the gtk4 functions.

I tried setting the environment variable G_MESSAGES_DEBUG but this made no difference.

export G_MESSAGES_DEBUG=info

I can change the maximum logging level in journald so that debug messages are not stored but then I’m not able to use this capability to add debugging messages to my applications.

What sets the level of messages that the glib2 and gtk4 libraries send to the log?

Has there been some change to the logging functionality between gtk 4.18 and 4.20 that would account for this ?

Michael

Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface cursor-blink-time: 1200
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface toolbar-icons-size
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface font-antialiasing: 'grayscale'
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface toolbar-style
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface enable-hot-corners
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface monospace-font-name
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface gtk-timeout-repeat
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface overlay-scrolling: true
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface cursor-blink-timeout: 10
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface gtk-key-theme
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface toolbar-detachable
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface font-rendering: 'automatic'
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface cursor-theme: 'Adwaita'
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface avatar-directories
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface gtk-im-status-style
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Ignoring portal setting for org.gnome.desktop.interface menubar-detachable
Oct 25 18:22:21 industrynumbers.com HPGLplotter[539687]: Using portal setting for org.gnome.desktop.interface text-scaling-factor: 1.0
...skipping...
Oct 26 11:05:21 industrynumbers.com HPGLplotter[137791]: snapshot symbolic icon as recolored node
Oct 26 11:05:21 industrynumbers.com HPGLplotter[137791]: snapshot symbolic icon as recolored node
Oct 26 11:05:21 industrynumbers.com HPGLplotter[137791]: snapshot symbolic icon as recolored node
Oct 26 11:05:21 industrynumbers.com HPGLplotter[137791]: snapshot symbolic icon as recolored node
2

So I think it has to do with the default logging level used by … g_log_writer_journald

I have the line

g_log_set_writer_func (g_log_writer_journald, NULL, NULL);

to direct my logging to the systemd journal …

#define LOG( level, message, ...) \
g_log_structured (G_LOG_DOMAIN, level, \
"SYSLOG_IDENTIFIER", "HPGLplotter", \
"CODE_FUNC", __FUNCTION__, \
"CODE_LINE", G_STRINGIFY(__LINE__), \
"MESSAGE", message,## __VA_ARGS__)

LOG( G_LOG_LEVEL_WARNING, "Cannot get system dbus bus" );

In previous Fedora releases, g_log_writer_journald did not show debug messages from the libraries (gnome and gtk). Now those messages appear.

I’d like to show debug messages that I create in the program but not debug messages from the libraries (which are just noise to me). How can I do that?

3

As a work around I can have my program filter out the glib/gtk messages before they are sent to the journal with a filter routine …

g_log_set_writer_func (filtered_log_writer_journald, NULL, NULL);

static GLogWriterOutput 
filtered_log_writer_journald (GLogLevelFlags log_level, 
                             const GLogField *fields, gsize n_fields, gpointer user_data)

{
    // Messages generated by HPGLplotter do not have the GLIB_DOMAIN field
    // glib / gtk+ messages do
    for( gint i=0; i < n_fields; i++ ) {
        if( !g_strcmp0( fields[i].key, "GLIB_DOMAIN"  ) )
            return G_LOG_WRITER_UNHANDLED;
    } 
    
    return g_log_writer_journald (log_level, fields, n_fields, NULL );

}
4

Have you read GLib – 2.0: Message Logging ?

5

yes indeed, but it gave me no clues as to why the glib library debugging suddenly appeared in the logs!

6

If I were in your situation, I would step through the log writer function (the one which was installed before your workaround of filtered_log_writer_journald()) in gdb and work out what’s causing it to consider debug messages for output.

7

That was also my thought. I looked at the code history for g_log_writer_journald but there was nothing recently that would have caused this (AFAICT). I guess the folks who package the glib / gtk4 libraries for Fedora could have changed a compile switch; however, my filter works for now.

I saw a GUDAC lecture on YouTube from one of the developers of the logging code where he says something like “we wanted to give the ability to control the logging to the program developer”. Maybe it was supposed to have worked like this all along.

8

If you are using g_log_writer_journald() directly (as opposed to using g_log_writer_default(), which is the default) then it’s expected that it will output all debug messages without filtering. The filtering is done by g_log_writer_default() (see the code for should_drop_message()).

If you’d like to use g_log_writer_journald() as your writer function, and hence not print any log messages to stdout/stderr, then you will need to wrap it in your own writer function to implement log filtering. So in that sense, your filtered_log_writer_journald() function is the right approach, although I would suggest using g_log_writer_default_would_drop() to work out whether to drop messages, as it pays attention to the G_MESSAGES_DEBUG environment variable (amongst others).

However, I would recommend against only logging messages to the journal unless you have a very specific use case, as that will mean that debugging your program by running it from a terminal is not as useful as it could be.

That talk was probably by me :slight_smile: The intent is indeed for the log writer function to give you complete control over what messages are logged and how. Without knowing the bigger picture about what you’re trying to achieve I can’t give any more specific guidance other than that if g_log_writer_default() doesn’t do what you want, then you need to provide your own log writer function which does do what you want. And that many of the pieces of code in g_log_writer_default() (like g_log_writer_default_would_drop()) can be called as separate functions from your implementation if you need.

9

Yes, I tried the recommended g_log_writer_default() but none of my logging messages showed up in the journal or in stdout/stderr (at WARNING or INFO level).

I used g_log_writer_journald() because it passed my messages on to the journal.

At the time I wrote the code (a few years ago), this method did not cause the glib debug messages to show up in the journal. Something changed with the configuration or libraries with Fedora 43 because using now g_log_writer_journald() does cause these glib debug messages to go to the journal.

Thanks for the tip on g_log_writer_default_would_drop(), that works well.

thanks .. it was helpful.

I guess my problem is that I need to separate my debugging and info messages from that of glib.

When I am debugging my program, the glib debugging messages are just noise (since I assume glib is doing what it is supposed to (and I don’t know how to interpret the messages anyway)) .

G_MESSAGES_DEBUG would instruct the logging library to do the same thing to my messages as they do to the glib messages.

10

Are you defining a value for G_LOG_DOMAIN? That’s how your messages are meant to be separated from GLib’s messages (and messages from other libraries your project depends on).

11

I don’t, but yes I can do that, although I thought I read it was discouraged in the end-user program (meant for libraries).