> all: set G_LOG_DOMAIN appropriately, for better g_log() messages

Looking at:

-DG_LOG_DOMAIN=\""NetworkManager-ifupdown"\" \

this means, that every line will be prefixed with such a long word. Maybe shorten it to 

-DG_LOG_DOMAIN=\""NM-ifupdown"\" \

and 
-    -DG_LOG_DOMAIN=\""NetworkManager"\" \
+    -DG_LOG_DOMAIN=\""NM"\" \




> settings: use g_message() / g_warning() in settings plugins

I would keep the define PLUGIN_*,
- but move them src/settings/nm-system-config-interface.h
- rename them to NM_PLUGIN_* (or similar)
- remove the first parameter of the define. Maybe they do need some specifier with some special data per plugin, but I would solve that via:



src/settings/nm-system-config-interface.h:

#define NM_PLUGIN_DEBUG(format, ...) \
    g_message("%s: " format, _nm_setting_plugin_info->name, __VA_ARGS__)

typedef struct {
    const char *name;
} NMSettingPluginInfo;
extern NMSettingPluginInfo _nm_setting_plugin_info;



src/settings/plugins/keyfile/plugin.c

#include "nm-system-config-interface.h"

NMSettingPluginInfo _nm_setting_plugin_info = { .name = G_LOG_DOMAIN; };

...
   NM_PLUGIN_DEBUG ("log some message %s", "hello");
   



In step 2, the NM_PLUGIN_* defines should call nm_log_* instead of g_message.





Overall, a great change. Really like it!!

(In reply to comment #1)
> > all: set G_LOG_DOMAIN appropriately, for better g_log() messages
> 
> Looking at:
> 
> -DG_LOG_DOMAIN=\""NetworkManager-ifupdown"\" \
> 
> this means, that every line will be prefixed with such a long word.

In fact, you should never actually see any of the G_LOG_DOMAIN strings that start with "NetworkManager"...

In the NM binary itself, nm_logging_syslog_openlog() causes all g_log() output to get redirected to nm_log_handler(), and then any message with a log domain starting with "libnm-" or "NetworkManager" gets redirected to syslog() (without the domain).

In the test programs, you should never see any log messages, because we use g_test_expect_message() to suppress them all. (In fact, the whole point of setting the log domains was just so that we could end up NOT seeing them :-). Older versions of GLib don't let you pass a NULL domain to g_test_expect_message(), so we need to set it to something explicitly.)

So the only times you'll see a G_LOG_DOMAIN is in the output of clients (which may show "libnm-util" or "libnm-glib" messages), and in helper programs like nm-dhcp-helper and nm-pppd-plugin (which should only end up showing messages with their own name or with "NetworkManager").

> #define NM_PLUGIN_DEBUG(format, ...) \
>     g_message("%s: " format, _nm_setting_plugin_info->name, __VA_ARGS__)

Having the plugin name prefixed to the log messages seems to have been mostly redundant. If the message is talking about a file in /etc/NetworkManager/system-connections/ then you know it came from the keyfile plugin. If it's talking about a file in /etc/sysconfig/network-scripts, then it's ifcfg-rh, etc.

And we don't have any such auto-disambiguation anywhere else in NM. If there are plugin messages where additional disambiguation is needed, then we should just put the disambiguation directly into the log messages.

> In step 2, the NM_PLUGIN_* defines should call nm_log_* instead of g_message.

This wouldn't have much effect... In the daemon, nm_log() and g_log() both end up redirecting to syslog(), and in the test programs, they both end up redirecting to g_log_handler_default(). But I guess if we used nm_log() then (a) the code as a whole is more consistent, and (b) we can have them log specifically as LOGD_SETTINGS (or add LOGD_SETTINGS_PLUGIN), and then you can control how much logging you get. (Lots of the existing ifupdown/ifnet messages really ought to be debug-level I think...)

At any rate, I don't think there's any reason to keep the plugin-specific logging functions. The plugins can just call nm_log_*() directly just like everything else.

> settings: use g_message() / g_warning() in settings plugins

It changed the output. Now I see 
** Message:    ifcfg-rh: parsing
/etc/sysconfig/network-scripts/ifcfg-ethernet-30 ... 
** Message:    ifcfg-rh:     read connection 'ethernet'
NetworkManager[9661]: <info> new connection
/etc/NetworkManager/system-connections/aaaXXX

Before there was:
Mar 28 08:20:16 aaa NetworkManager[2704]:    ifcfg-rh: parsing
/etc/sysconfig/network-scripts/ifcfg-ethernet-30 ...
Mar 28 08:20:16 aaa NetworkManager[2704]:    ifcfg-rh:     read connection
'ethernet'
Mar 28 08:20:21 aaa NetworkManager[2704]:    keyfile: new connection
/etc/NetworkManager/system-connections/aaaXXX

E.g. bogus "** Message" for ifcfg-rh, missing "keyfile:" prefix for keyfiles.

> libnm-util: use g_test_expect_message() in tests
g_test_expect_message ("libnm-util", G_LOG_LEVEL_CRITICAL, "*key != NULL*");
Enclosing "*" in messages could be misleading (regarded as pointer
dereferencing)

(In reply to comment #3)
> E.g. bogus "** Message" for ifcfg-rh, missing "keyfile:" prefix for keyfiles.

The missing "keyfile" was intentional, as mentioned above. I think the bogus "** Message" means you need to "make clean; make" to make sure that everything gets recompiled with the new -DG_LOG_DOMAIN.

> g_test_expect_message ("libnm-util", G_LOG_LEVEL_CRITICAL, "*key != NULL*");
> Enclosing "*" in messages could be misleading (regarded as pointer
> dereferencing)

The match string is a glob pattern, and it has to match the entire message, so either you have to start and end with "*", or else you have to write out all the "assertion failed blah blah", which seems bad because then we're relying on that text in GLib not ever getting rewritten (like it already did to change the `'-style quotes to ''-style).

I think that once you're used to seeing g_test_expect_message() used, it's not that confusing...

(In reply to comment #2)
> (In reply to comment #1)
> > > all: set G_LOG_DOMAIN appropriately, for better g_log() messages
> > 
> > Looking at:
> > 
> > -DG_LOG_DOMAIN=\""NetworkManager-ifupdown"\" \
> > 
> > this means, that every line will be prefixed with such a long word.
> 
> In fact, you should never actually see any of the G_LOG_DOMAIN strings that
> start with "NetworkManager"...
> 
> In the NM binary itself, nm_logging_syslog_openlog() causes all g_log() output
> to get redirected to nm_log_handler(), and then any message with a log domain
> starting with "libnm-" or "NetworkManager" gets redirected to syslog() (without
> the domain).
> 
> In the test programs, you should never see any log messages, because we use
> g_test_expect_message() to suppress them all. (In fact, the whole point of
> setting the log domains was just so that we could end up NOT seeing them :-).
> Older versions of GLib don't let you pass a NULL domain to
> g_test_expect_message(), so we need to set it to something explicitly.)

Especially while writing the tests, it's useful to be able to print something. But anyway, I was just asking, if it makes sense to abbreviate the NetworkManager* prefix.

> So the only times you'll see a G_LOG_DOMAIN is in the output of clients (which
> may show "libnm-util" or "libnm-glib" messages), and in helper programs like
> nm-dhcp-helper and nm-pppd-plugin (which should only end up showing messages
> with their own name or with "NetworkManager").

Fine.



> > #define NM_PLUGIN_DEBUG(format, ...) \
> >     g_message("%s: " format, _nm_setting_plugin_info->name, __VA_ARGS__)
> 
> Having the plugin name prefixed to the log messages seems to have been mostly
> redundant. If the message is talking about a file in
> /etc/NetworkManager/system-connections/ then you know it came from the keyfile
> plugin. If it's talking about a file in /etc/sysconfig/network-scripts, then
> it's ifcfg-rh, etc.
> 
> And we don't have any such auto-disambiguation anywhere else in NM. If there
> are plugin messages where additional disambiguation is needed, then we should
> just put the disambiguation directly into the log messages.

In nm_log_ we have the LOGD_* domains, which is exactly this. In libnm-util/libnm-glib we avoid logging in general (but there we would use g_log, which has a G_LOG_DOMAIN prefix).

No, we don't have this auto-disambiguation. I was mainly suggesting to keep the #define for logging, instead of replacing it with plain g_message. Whether the #define uses a prefix, is then another question -- at least it could and we could add/remove it in *one* place.



> > In step 2, the NM_PLUGIN_* defines should call nm_log_* instead of g_message.
> 
> This wouldn't have much effect... In the daemon, nm_log() and g_log() both end
> up redirecting to syslog(), and in the test programs, they both end up
> redirecting to g_log_handler_default(). But I guess if we used nm_log() then
> (a) the code as a whole is more consistent, and (b) we can have them log
> specifically as LOGD_SETTINGS (or add LOGD_SETTINGS_PLUGIN), and then you can
> control how much logging you get. (Lots of the existing ifupdown/ifnet messages
> really ought to be debug-level I think...)

I think nm-logging has advantages over plain g_log. That's a good reason to use nm-logging and to have nm-logging in the first place. If you would think, g_log is an adequate replacement (what I don't think), then we should get rid of nm-logging completely.

Inside of NM (and it's plugins) we should not use g_log directly (except via g_return*). We have all the nm-logging how we want it, no need to use a second mechanism (g_log).

but my point here was not to switch to nm_log now, but to make/keep a #define -- so that we can switch later transparently. Or if you want to switch now, that is fine with me -- but don't replace everything by g_message() now -- which is a step in the wrong direction.


> At any rate, I don't think there's any reason to keep the plugin-specific
> logging functions. The plugins can just call nm_log_*() directly just like
> everything else.

Fully agree. I was just not sure we want to fix this now, but if you want, I very much agree.

Pushed danw/errors2 with the plugins changed to use nm_log rather than g_log. (danw/errors still contains the original code).

I also removed the commit "logging: make the g_log() logging format more like the nm_log() format", since it didn't seem to make sense any more.

"logging: use GLib's logging functions if not using syslog" got modified a bit in that nm_log() needs to call nm_logging_setup() itself if nothing else did, or otherwise all log domains are disabled. Fixing that then caused some additional warnings to show up in the output of test-ifcfg-rh that had been suppressed before, which led to the "ifcfg-rh: don't write out IP config on Team connections" fix.

If you're wondering why I added the PARSE_ERROR macro in ifcfg-rh, but not elsewhere, it's because ifcfg-rh is the only plugin that's consistent about indenting connection-parsing errors. We should fix that up at some point.

(In reply to comment #6)
> Pushed danw/errors2 with the plugins changed to use nm_log rather than g_log.
> (danw/errors still contains the original code).
> 
> I also removed the commit "logging: make the g_log() logging format more like
> the nm_log() format", since it didn't seem to make sense any more.
> 
> "logging: use GLib's logging functions if not using syslog" got modified a bit
> in that nm_log() needs to call nm_logging_setup() itself if nothing else did,
> or otherwise all log domains are disabled. Fixing that then caused some
> additional warnings to show up in the output of test-ifcfg-rh that had been
> suppressed before, which led to the "ifcfg-rh: don't write out IP config on
> Team connections" fix.
> 
> If you're wondering why I added the PARSE_ERROR macro in ifcfg-rh, but not
> elsewhere, it's because ifcfg-rh is the only plugin that's consistent about
> indenting connection-parsing errors. We should fix that up at some point.

danw/errors2 looks good to me

For PARSE_ERROR, what's wrong with just indenting the nm_log_XXX() strings?

Also, are we loosing the logging about what settings plugin is printing the message?  That was initially added so that we'd know exactly what was at fault when something got logged.  So now, instead of:

ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-roamtest-wpa_1 ...
ifcfg-rh:     read connection 'roamtest-8021x'
keyfile: new connection /etc/NetworkManager/system-connections/Sample PPTP
keyfile: ipv4.addresses1: Deprecated semicolon at the end of value.

won't it just be:

<info> parsing /etc/sysconfig/network-scripts/ifcfg-roamtest-wpa_1 ...
<info>     read connection 'roamtest-8021x'
<info> new connection /etc/NetworkManager/system-connections/Sample PPTP
<warn> ipv4.addresses1: Deprecated semicolon at the end of value.

If that's the case, I hate to ask you to go through and rework that since it's a ton of mind-numbing typing, but I think we're loosing a bit of useful information there...

As for the actual patches, they all look good to me and I *love* the fact that you took it upon yourself to do this cleanup.  It's been a long long  long time coming.

Oh, I also ran into this:

make[7]: Entering directory `/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests'
make  check-local
make[8]: Entering directory `/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests'
/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests/test-ifcfg-rh-utils
lt-test-ifcfg-rh-utils: SUCCESS
/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests/test-ifcfg-rh

(/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests/.libs/lt-test-ifcfg-rh:30777): NetworkManager-WARNING **: Did not see expected message WARNING **: *aliasem1:1*has no DEVICE*

(/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests/.libs/lt-test-ifcfg-rh:30777): NetworkManager-WARNING **: <warn>     alias file '/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests/network-scripts/ifcfg-aliasem1:2' has invalid DEVICE (aliasem0:2) for filename
make[8]: *** [check-local] Trace/breakpoint trap
make[8]: Leaving directory `/home/dcbw/Development/fdo/NetworkManager/src/settings/plugins/ifcfg-rh/tests'

Not sure what that's about but recorded for posterity.

(In reply to comment #8)
> For PARSE_ERROR, what's wrong with just indenting the nm_log_XXX() strings?

nothing, it just seemed useful. I can undo it.

> Also, are we losing the logging about what settings plugin is printing the
> message?

Yes, as above, it seemed unnecessary to me, since you can tell what plugin is printing the message based on the pathname of the connection anyway...

> I hate to ask you to go through and rework that since it's
> a ton of mind-numbing typing

No, it's pretty trivial to fix with search+replace if you want.

(In reply to comment #10)
> (In reply to comment #8)
> > For PARSE_ERROR, what's wrong with just indenting the nm_log_XXX() strings?
> 
> nothing, it just seemed useful. I can undo it.
> 
> > Also, are we losing the logging about what settings plugin is printing the
> > message?
> 
> Yes, as above, it seemed unnecessary to me, since you can tell what plugin is
> printing the message based on the pathname of the connection anyway...
> 
> > I hate to ask you to go through and rework that since it's
> > a ton of mind-numbing typing
> 
> No, it's pretty trivial to fix with search+replace if you want.

Nah, after thinking about these, I'm fine with the changes.

pushed again; I realized that there were other test programs spewing warnings too, so I added more fixes. The second-to-last commit is new:

  09f6252 dbus-manager: don't try to create private bus in test programs

and the last commit is updated to include more expect-message fixes than before:

  f487bde core: use g_test_expect_message() in test programs

(Mostly I just want the dbus-manager patch reviewed.)

(In reply to comment #12)
> pushed again; I realized that there were other test programs spewing warnings
> too, so I added more fixes. The second-to-last commit is new:
> 
>   09f6252 dbus-manager: don't try to create private bus in test programs
> 
> and the last commit is updated to include more expect-message fixes than
> before:
> 
>   f487bde core: use g_test_expect_message() in test programs
> 
> (Mostly I just want the dbus-manager patch reviewed.)

running `make check` on the current version of danw/error2 fails for me. This is already fixed in current master by commit ab0c37d042f749f6f859b3010c079e53f1739dbf, ...

After rebasing to current master, the test for ifnet still fail (due to duplicate platform_setup() which is already fixed in master by f20e9d04398030dc519f757e27d877e72e06112c).

rest looks good to me.

rebased, re-tested, and pushed