Logging with GLib #474

bebehei · 2018-01-07T22:08:07Z

Move logging capabilities from plain printfs to log levels via native GLib.

This will enable the testsuite to later also catch errors/warnings.

Fixes: #368

As far as I can see, I won't implement the structured logging. This does sometimes bogus stuff.

tsipinakis

You also forgot to add verbosity to the man page.

tsipinakis · 2018-01-20T19:41:32Z

src/settings.c

+        log_set_level_from_string(option_get_string(
+                "global",
+                "verbosity", "-verbosity", NULL,
+                "The desired verbosity to merge on master"


The desired verbosity to merge on master

What?!

This should probably mention the possible values as a quick reference when needed.

What?!

mhmm.

tsipinakis · 2018-01-20T19:43:18Z

src/settings.c

@@ -106,6 +106,12 @@ void load_settings(char *cmdline_config_path)
              "Using STATIC_CONFIG is deprecated behavior.");
 #endif

+        log_set_level_from_string(option_get_string(
+                "global",
+                "verbosity", "-verbosity", NULL,


Maybe also add the shorter version -v since it's a common flag.

And I think if -v is specified or no flag it could fallback to something like info or message since the user obviously wants some more info on what's going on but that may be asking too much.

-v is already linked to the version information. And this is good the way it is.

tsipinakis · 2018-01-20T19:45:39Z

src/log.c

+                log_level = G_LOG_LEVEL_DEBUG;
+        else if (g_ascii_strcasecmp(level, "deb") == 0)
+                log_level = G_LOG_LEVEL_DEBUG;
+        else {


everything else doesn't have a bracket but this case does? Why?

tsipinakis · 2018-01-20T20:02:36Z

src/log.c

+/* if you want to have a debug build, you want to log anything,
+ * unconditionally, without specifying debug log level again */
+#ifndef DEBUG_BUILD
+        if(log_level > message_level)


This needs to be less than, not greater than. It currently accomplishes the exact opposite thing of what it's supposed to do.

(gdb) p (int)G_LOG_LEVEL_CRITICAL $20 = 8 (gdb) p (int)G_LOG_LEVEL_WARNING $21 = 16

tsipinakis · 2018-01-20T20:03:46Z

src/log.h

@@ -12,7 +12,12 @@
 #define LOG_W g_warning
 #define LOG_M g_message
 #define LOG_I g_info
-#define LOG_D g_debug
+
+#ifdef DEBUG_BUILD


I'm not sure about disabling this on production builds, if anything, the ability to set dunst to debug mode and instantly have a log of everything that's going on inside the program can be very useful to debug issues.

This is a single commit. I'll drop this.

tsipinakis · 2018-01-20T20:08:56Z

src/settings.c

@@ -106,6 +106,12 @@ void load_settings(char *cmdline_config_path)
              "Using STATIC_CONFIG is deprecated behavior.");
 #endif

+        log_set_level_from_string(option_get_string(


Also there's probably a memory leak here, the return of option_get_string is never freed.

This is a definitive memory leak. It's just that I actually want to change change the settings parser in #475 to return const values. This makes in such a case much more sense.

I had in mind, that this will be a memory leak, but only temporary. I've actually thought this will get fixed up in a follow up commit in this PR. But obviously this commit is on #475.

I guess, I'll fix it up to later refix it.

tsipinakis

You know we're close to a merge when the review is mostly about codestyle.
While nitpicky consistent codestyle is important IMO.

tsipinakis · 2018-01-22T18:29:38Z

src/log.h

+#define LOG_I g_info
+#define LOG_D g_debug
+
+#define die(...) {LOG_C(__VA_ARGS__); exit(EXIT_FAILURE);}


It's usual to use a do { } while(0) clause in macros instead of simple brackets. See here for an explanation.

Since this is a macro that can be used pretty much anywhere in the code I think it's worth making sure it's working as expected.

Also, since we're converting die to a macro shouldn't it be capitalized?

@tsipinakis I've seen this quite often. But I don't get what the actual advantage over a simple scope is. I know, you have to scope macros, that they won't change the programming context, but I'm missing the point, why this has to be done with do .. while.

Could you please explain this to me? The answers in the stackoverflow don't really enlighten me.

I've created a program and tested the actual difference. Is it really the case, that you want to have do ... while just to assert that the macro will have a trailing semicolon?

Consider this code

#define foo(x) {a(x); b();} ... if (some_bool) foo(some_bool); else ...

It looks like it works and it's similar to our die() macro which is pretty likely to be used under an if statement.

But it doesn't, after expansion we get this:

if (some_bool) {a(some_bool); b();}; <---- SYNTAX ERROR, trailing semicolon else ...

The correct form would've been to not use a semicolon since it's a macro but IMO it's better to make it look like actual code and not have corner cases like that.

if (some_bool) do { a(some_bool); b();} while(0); <-- Semicolon is supposed to be there else ...

tsipinakis · 2018-01-22T18:33:54Z

src/settings.c

-                "The verbosity to log (one of 'info', 'mesg', 'warn', 'crit')"
-        ));
+        {
+                char * loglevel = option_get_string(


There shouldn't be a space after the asterisk in pointer declaration.

tsipinakis · 2018-01-22T18:45:06Z

src/log.c

+
+static GLogLevelFlags log_level = G_LOG_LEVEL_WARNING;
+
+static const char *log_level_to_string (GLogLevelFlags level)


There shouldn't be a space after the function name, we only use space before parenthesis after keywords.

Similarly with the other functions in this file.

tsipinakis · 2018-01-22T18:45:34Z

src/log.c

+                const gchar    *message,
+                gpointer        testing)
+{
+        if(testing)


Use a space after the if keyword.

tsipinakis · 2018-01-22T18:46:38Z

src/log.c

+/* if you want to have a debug build, you want to log anything,
+ * unconditionally, without specifying debug log level again */
+#ifndef DEBUG_BUILD
+        if(log_level < message_level)


Similarly here, add a space please.

bebehei · 2018-01-23T00:16:56Z

You know we're close to a merge when the review is mostly about codestyle.
While nitpicky consistent codestyle is important IMO.

Well, I've understood the indications of your comments and interpreted these as a positive sign 😁. The worse part is that, I found much more types of these issues while rebasing interactively.

I guess, pasting code from the GLib docs and modifying it, is not a genius move.

tsipinakis · 2018-01-24T14:30:24Z

HACKING.md

+    - Mostly unneccessary info, but important to debug (as the user) some use cases.
+    - e.g.: print the notification contents after arriving
+- `LOG_D` (DEBUG):
+    - Only important during development or tracing some bugs (as the developer). Will be disabled by compile time on normal builds.


Forgot to update this after enabling debug logs on production builds.

tsipinakis · 2018-01-24T14:32:49Z

src/dbus.c

                reason = REASON_UNDEF;
        }

        if (!dbus_conn) {
-                fprintf(stderr, "ERROR: Tried to close notification but dbus connection not set!\n");
-                return;
+                LOG_E("Unable to close notification: No DBus connection.");


Where did the return statement go?

A bit out of scope but this usage of LOG_E doesn't immediately abort as the documentation suggests. I'm not sure about the correct way to go on this, either leave it to just return but dbus_conn being NULL is a pretty big issue so maybe just use DIE() instead?

Random thought: Since we're almost always going to abort when logging an error is there a reason to map LOG_E and not just DIE()?

The g_error aborts the program with SIGTRAP, so it won't return anyways.

DIE exits with critical, but does not abort the program. It should be correctable by the user. The user may just have specified a wrong param.

But if the condition dbus_conn == NULL is true, I consider this a programming error, as the on_name_lost handler should have handled this already.

tsipinakis · 2018-01-24T14:48:48Z

src/x11/x.c

@@ -832,7 +832,7 @@ gboolean x_mainloop_fd_prepare(GSource *source, gint *timeout)
        if (timeout)
                *timeout = -1;
        else
-                g_print("BUG: x_mainloop_fd_prepare: timeout == NULL\n");
+                LOG_E("x_mainloop_fd_prepare: timeout == NULL");


Glibs docs indicate that the timeout can be NULL but not when or why but I don't think this should be fatal, but should we use LOG_E anyways? Not sure about this one.

I've never looked at the GSource function stuff. For me, this part is a dark chamber, which waits to get lightened up. I'll have a try to explain it to myself.

IIUC, the function should return on the one hand side, a timeout (which will get fed to poll() as the timeout) and also should return TRUE if the source is already ready.

The docs say:

Since 2.36 this [timeout_] may be NULL, in which case the effect is as if the function always returns FALSE with a timeout of -1.

The 'effect' is exactly the same like our default. I also don't know, why this may be NULL, but we can ignore it, because it's the same like we would have done, if it's not NULL.

About the LOG_E thing here: Regardless if this is only printed to STDOUT, just by reading the code (without knowing the actual impact), this smells heavily like a null pointer assertion, which had been gone wrong.

tsipinakis · 2018-01-24T14:49:19Z

docs/dunst.pod

@@ -444,6 +444,12 @@ WM_CLASS). There should be no need to modify this setting for regular use.
 Display a notification on startup. This is usually used for debugging and there
 shouldn't be any need to use this option.

+=item B<verbosity> (values: 'info', 'mesg', 'warn', 'crit', default 'mesg')


Forgot to add debug here.

No, this was intentional. IMO debug shouldn't contain any information, which are usable in user contexts, so I guess this is better to hide this from the manpage.

I disagree here, even if it's not usable in a user context doesn't mean that someone can't get some insight on what's wrong by setting this value to debug as an experiment. Additionally, the manpage isn't just for users, potential contributors might be trying to find out how to enable debug logging to figure out an issue they've been tracing I don't think it's reasonable or expected to have to look to some other piece of documentation or dig the code to find out there's an even higher level of verbosity.

I still think we've got enough log levels for users. I think the debug level should only contain information, which is useful in combination with the source code. And, if you're going to develop on dunst's code, I hope you've read more than just the manpage. Also, if your only piece of information is the manpage, you won't have the source of dunst and therefore won't understand the log.

I'll quote HACKING.md:

LOG_I (INFO):

Mostly unneccessary info, but important to debug (as the user) some use cases.

e.g.: print the notification contents after arriving

LOG_D (DEBUG):

Only important during development or tracing some bugs (as the developer).

I have to decline your argument about potential contributors reading the manpage. I think it's more powerful, to assemble a short document, which describes the project's internals, which is bundled with the code. And I think polishing HACKING.md fits perfect for this.

I still think we've got enough log levels for users.

This is where I lose your line of reasoning. I don't think it's sensible to divide settings into "for users" and "for developers" especially if we're already including the verbosity setting in the docs. I believe it's even worse to purposefully hide a possible value of it because we assume it'll be useless to users.

While only someone who knows the codebase of dunst well will use it routinely, if someone is experiencing an issue and wants to do a quick trace to look what's up the most detailed debugging option is usually the first thing to look for in such cases. And even better it can prompt users to actually post a debug log on relevant issues if they know it shows more details into an issue they've been hunting. And even if not, it's a debug mode, the worse that can come from misusing it is slightly increased disk space usage!

Additionally as I've said above it might also confuse potential contributors since the man-page is the usual quick-reference to settings to look at what values it can take and even with the current HACKING.md file there is no specific mention that verbosity can be set to debug, only that the debug log level exists and is enabled on debug builds.

My intention was (and still is) to prevent, that the debug log becomes a daily driver for users.

To not list it in the manpage/help/etc was my solution. But you convinced me. It's actually an antipattern. And also an analogous form of "security by obscurity".

I think we still should look forward to prevent this, but there's a much cleaner way: Simply putting the right log messages into the right log level.

I've pushed a fixup commit for these docs now.

tsipinakis · 2018-01-24T14:49:27Z

dunstrc

@@ -198,6 +198,14 @@
    # automatically after a crash.
    startup_notification = false

+    # Manage dunst's desire for talking
+    # Can be one of the following values:
+    #  info: all unimportant stuff


Similarly here, debug is missing

tsipinakis · 2018-01-24T14:53:24Z

src/settings.c

+                char *loglevel = option_get_string(
+                                "global",
+                                "verbosity", "-verbosity", NULL,
+                                "The verbosity to log (one of 'info', 'mesg', 'warn', 'crit')"


Similarly here, debug is missing

tsipinakis · 2018-01-31T08:20:47Z

Didn't find anything else this is probably ready for a merge.

Can you squash the fixup before I do the final review/approve? (It's set so that any pushes dismiss earlier reviews)

bebehei · 2018-01-31T10:12:28Z

@tsipinakis Squashed.

According to the docs in the GSourceFuncs, the timeout_ parameter can be NULL. But when it's NULL, it would be equivalent to an invocation to return -1 as timeout_ and FALSE as return value. This is exactly the same, what we're doing if timeout_ is not NULL.

Logging with GLib

bebehei added the refactor label Jan 7, 2018

bebehei added this to the v1.4.0 milestone Jan 7, 2018

bebehei requested a review from tsipinakis January 7, 2018 22:08

bebehei force-pushed the logging branch 2 times, most recently from 016a727 to 139d811 Compare January 11, 2018 02:01

tsipinakis requested changes Jan 20, 2018

View reviewed changes

tsipinakis reviewed Jan 20, 2018

View reviewed changes

bebehei force-pushed the logging branch from 2f95e89 to f3d68e5 Compare January 21, 2018 14:51

tsipinakis requested changes Jan 22, 2018

View reviewed changes

bebehei force-pushed the logging branch from f3d68e5 to fb2140d Compare January 22, 2018 23:55

tsipinakis requested changes Jan 24, 2018

View reviewed changes

bebehei force-pushed the logging branch 2 times, most recently from b09454a to 839258c Compare January 30, 2018 22:58

bebehei force-pushed the logging branch from 839258c to 08b8ead Compare January 31, 2018 10:09

bebehei force-pushed the logging branch from 08b8ead to 03059c1 Compare February 2, 2018 16:17

bebehei added 10 commits February 2, 2018 17:29

Add GLib logging capabilities

cad2ac3

Add option to suppress log output when testing

2c503c2

Replace die method with appropriate critical log

020a90e

Add guidelines for logging messages

b5516be

Translate fprintf statements into log messages

19b364d

Replace PERR macro with appropriate logging macro

58dc09b

Translate last unusual logging calls

38dced7

Allow to set the log level via options

280ec45

Fix memleak

1e6a15d

bebehei force-pushed the logging branch from 03059c1 to 6402218 Compare February 2, 2018 16:29

tsipinakis approved these changes Feb 12, 2018

View reviewed changes

bebehei merged commit c3e8bed into dunst-project:master Feb 12, 2018

bebehei deleted the logging branch March 15, 2018 13:30

karlicoss pushed a commit to karlicoss/dunst that referenced this pull request Mar 21, 2019

Merge pull request dunst-project#474 from bebehei/logging

edc8be0

Logging with GLib


		static GLogLevelFlags log_level = G_LOG_LEVEL_WARNING;

		static const char *log_level_to_string (GLogLevelFlags level)

Logging with GLib #474

Logging with GLib #474

Conversation

bebehei commented Jan 7, 2018

tsipinakis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tsipinakis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bebehei commented Jan 23, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tsipinakis Jan 30, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tsipinakis commented Jan 31, 2018

bebehei commented Jan 31, 2018

tsipinakis Jan 30, 2018 •

edited

Loading