libnm: add logging NML_DBUS_LOG*() for debugging D-Bus for NMClient

Commonly, a library (like libnm) is not supposed to log anything.
Logging is not a suitable way to notify the calling application
about anything. When something of importance happens, then the
application must be notified via the library's API.

However, logging can be very useful for debugging to see what is going
on. Add a logging macro that by default does nothing, but can be turned
on via an environment variable "LIBNM_CLIENT_DEBUG=debug".

Another point is that libnm relies on the server side NetworkManager
D-Bus interface to be in an expected manner. For example, we require a
D-Bus object "org.freedesktop.NetworkManager" to be present and certain
D-Bus interfaces implemented.

However libnm should treat NetworkManager as external and untrusted component.
That means, we cannot assert against the expectations we have. There are two
reasons for this:

  - a bug in NetworkManager, dbus-daemon or else may cause such errors.
    This must not trigger an assertion failure in the client
    application, at least not unless requested.

  - libnm must be forward and backward compatible against a different
    NetworkManager server version. That is only possibly by ignoring
    anything that is unexpected. Asserting by default might prevent
    to implement API changes, both on libnm and server side.

Note that we also don't notify the calling application via dedicated
API. On the one hand, these things *can* happen. On the other hand, what
would the calling appication do about it anyway? libnm by default must
just behave gracefully and pretend all is good.

For testing, development and debugging that is however not useful. We
want the user to opt in to strict API validation. The user will be able
to do that by setting "LIBNM_CLIENT_DEBUG=warning", which causes API
violations being logged with g_warning(). These are assertions when
running with G_DEBUG=fatal-warnings.

This is inspired by GDBus' G_DBUS_DEBUG variable.

Note that LIBNM_CLIENT_DEBUG environment variables is undocumented, unstable
API. It's used for debugging and testing of the current libnm version at hand.
There is no guaranteed stable behavior how a different libnm version
might behave.
This commit is contained in:
Thomas Haller 2019-10-14 08:06:33 +02:00
parent 27fa6bad0c
commit a5b2ba02ea
2 changed files with 171 additions and 0 deletions

View file

@ -10,6 +10,85 @@
/*****************************************************************************/
volatile int _nml_dbus_log_level = 0;
int
_nml_dbus_log_level_init (void)
{
const GDebugKey keys[] = {
{ "trace", _NML_DBUS_LOG_LEVEL_TRACE },
{ "debug", _NML_DBUS_LOG_LEVEL_DEBUG },
{ "warning", _NML_DBUS_LOG_LEVEL_WARN },
{ "error", _NML_DBUS_LOG_LEVEL_ERROR },
};
int l;
l = _NML_DBUS_LOG_LEVEL_INITIALIZED
| nm_utils_parse_debug_string (g_getenv ("LIBNM_CLIENT_DEBUG"),
keys,
G_N_ELEMENTS (keys));
if (!g_atomic_int_compare_and_exchange (&_nml_dbus_log_level, 0, l))
l = g_atomic_int_get (&_nml_dbus_log_level);
nm_assert (l & _NML_DBUS_LOG_LEVEL_INITIALIZED);
return l;
}
void
_nml_dbus_log (NMLDBusLogLevel level,
const char *fmt,
...) {
NMLDBusLogLevel configured_log_level;
gs_free char *msg = NULL;
va_list args;
const char *prefix = "";
/* we only call _nml_dbus_log() after nml_dbus_log_enabled(), which already does
* an atomic access to the variable. Since the value is only initialized once and
* never changes, we can just access it without additional locking. */
configured_log_level = _nml_dbus_log_level;
nm_assert (level & configured_log_level);
va_start (args, fmt);
msg = g_strdup_vprintf (fmt, args);
va_end (args);
switch (level) {
case NML_DBUS_LOG_LEVEL_TRACE:
prefix = "<trace> ";
break;
case NML_DBUS_LOG_LEVEL_DEBUG:
prefix = "<debug> ";
break;
case NML_DBUS_LOG_LEVEL_WARN:
prefix = "<warn > ";
if (NM_FLAGS_HAS (configured_log_level, _NML_DBUS_LOG_LEVEL_WARN)) {
g_warning ("libnm-dbus: %s%s", prefix, msg);
return;
}
break;
case NML_DBUS_LOG_LEVEL_ERROR:
prefix = "<error> ";
if (NM_FLAGS_HAS (configured_log_level, _NML_DBUS_LOG_LEVEL_ERROR)) {
g_critical ("libnm-dbus: %s%s", prefix, msg);
return;
}
if (NM_FLAGS_HAS (configured_log_level, _NML_DBUS_LOG_LEVEL_WARN)) {
g_warning ("libnm-dbus: %s%s", prefix, msg);
return;
}
break;
default:
break;
}
g_printerr ("libnm-dbus: %s%s\n", prefix, msg);
}
/*****************************************************************************/
static char *
_fixup_string (const char *desc,
const char *const *ignored_phrases,

View file

@ -14,6 +14,98 @@
#define _NM_DEPRECATED_SYNC_METHOD_INTERNAL NM_DEPRECATED_IN_1_22
#define _NM_DEPRECATED_SYNC_WRITABLE_PROPERTY_INTERNAL NM_DEPRECATED_IN_1_22
/*****************************************************************************/
typedef enum {
_NML_DBUS_LOG_LEVEL_INITIALIZED = 0x01,
_NML_DBUS_LOG_LEVEL_TRACE = 0x02,
_NML_DBUS_LOG_LEVEL_DEBUG = 0x04,
/* the difference between a warning and a critical is that it results in
* g_warning() vs. g_critical() messages. Note that we want to use "warnings"
* for unknown D-Bus API that could just result because we run against a
* newer NetworkManager version (such warnings are more graceful, because
* we want that libnm can be forward compatible against newer servers).
* Critial warnings should be emitted when NetworkManager exposes something
* on D-Bus that breaks the current expectations. Usually NetworkManager
* should not break API, hence such issues are more severe. */
_NML_DBUS_LOG_LEVEL_WARN = 0x08,
_NML_DBUS_LOG_LEVEL_ERROR = 0x10,
/* ANY is only relevant for nml_dbus_log_enabled() to check whether any of the
* options is on. */
NML_DBUS_LOG_LEVEL_ANY = _NML_DBUS_LOG_LEVEL_INITIALIZED,
NML_DBUS_LOG_LEVEL_TRACE = _NML_DBUS_LOG_LEVEL_TRACE,
NML_DBUS_LOG_LEVEL_DEBUG = _NML_DBUS_LOG_LEVEL_DEBUG
| NML_DBUS_LOG_LEVEL_TRACE,
NML_DBUS_LOG_LEVEL_WARN = _NML_DBUS_LOG_LEVEL_WARN
| NML_DBUS_LOG_LEVEL_DEBUG,
NML_DBUS_LOG_LEVEL_ERROR = _NML_DBUS_LOG_LEVEL_ERROR
| NML_DBUS_LOG_LEVEL_WARN,
} NMLDBusLogLevel;
extern volatile int _nml_dbus_log_level;
int _nml_dbus_log_level_init (void);
static inline gboolean
nml_dbus_log_enabled (NMLDBusLogLevel level)
{
int l;
nm_assert (NM_IN_SET (level, NML_DBUS_LOG_LEVEL_ANY,
NML_DBUS_LOG_LEVEL_TRACE,
NML_DBUS_LOG_LEVEL_DEBUG,
NML_DBUS_LOG_LEVEL_WARN,
NML_DBUS_LOG_LEVEL_ERROR));
l = g_atomic_int_get (&_nml_dbus_log_level);
if (G_UNLIKELY (l == 0))
l = _nml_dbus_log_level_init ();
nm_assert (l & _NML_DBUS_LOG_LEVEL_INITIALIZED);
if (level == NML_DBUS_LOG_LEVEL_ANY)
return l != _NML_DBUS_LOG_LEVEL_INITIALIZED;
return !!(((NMLDBusLogLevel) l) & level);
}
void _nml_dbus_log (NMLDBusLogLevel level,
const char *fmt,
...) _nm_printf (2, 3);
#define NML_DBUS_LOG(level, ...) \
G_STMT_START { \
G_STATIC_ASSERT ( (level) == NML_DBUS_LOG_LEVEL_TRACE \
|| (level) == NML_DBUS_LOG_LEVEL_DEBUG \
|| (level) == NML_DBUS_LOG_LEVEL_WARN \
|| (level) == NML_DBUS_LOG_LEVEL_ERROR); \
\
if (nml_dbus_log_enabled (level)) { \
_nml_dbus_log ((level), __VA_ARGS__); \
} \
} G_STMT_END
#define NML_DBUS_LOG_T(...) NML_DBUS_LOG (NML_DBUS_LOG_LEVEL_TRACE, __VA_ARGS__)
#define NML_DBUS_LOG_D(...) NML_DBUS_LOG (NML_DBUS_LOG_LEVEL_DEBUG, __VA_ARGS__)
#define NML_DBUS_LOG_W(...) NML_DBUS_LOG (NML_DBUS_LOG_LEVEL_WARN, __VA_ARGS__)
#define NML_DBUS_LOG_E(...) NML_DBUS_LOG (NML_DBUS_LOG_LEVEL_ERROR, __VA_ARGS__)
#define NML_NMCLIENT_LOG(level, self, ...) \
NML_DBUS_LOG ((level), \
"nmclient["NM_HASH_OBFUSCATE_PTR_FMT"]: " _NM_UTILS_MACRO_FIRST (__VA_ARGS__), \
NM_HASH_OBFUSCATE_PTR (self) \
_NM_UTILS_MACRO_REST (__VA_ARGS__))
#define NML_NMCLIENT_LOG_T(self, ...) NML_NMCLIENT_LOG (NML_DBUS_LOG_LEVEL_TRACE, self, __VA_ARGS__)
#define NML_NMCLIENT_LOG_D(self, ...) NML_NMCLIENT_LOG (NML_DBUS_LOG_LEVEL_DEBUG, self, __VA_ARGS__)
#define NML_NMCLIENT_LOG_W(self, ...) NML_NMCLIENT_LOG (NML_DBUS_LOG_LEVEL_WARN, self, __VA_ARGS__)
#define NML_NMCLIENT_LOG_E(self, ...) NML_NMCLIENT_LOG (NML_DBUS_LOG_LEVEL_ERROR, self, __VA_ARGS__)
/*****************************************************************************/
char *nm_utils_fixup_vendor_string (const char *desc);
char *nm_utils_fixup_product_string (const char *desc);