From 6da5fc59d860913a278f488f0873ce68f038de2b Mon Sep 17 00:00:00 2001 From: Thomas Haller Date: Mon, 15 Feb 2021 08:47:16 +0100 Subject: [PATCH 1/3] libnm: log PID in LIBNM_CLIENT_DEBUG debug logging --- libnm/nm-libnm-utils.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/libnm/nm-libnm-utils.c b/libnm/nm-libnm-utils.c index 1fb6a47c3..1000e04d1 100644 --- a/libnm/nm-libnm-utils.c +++ b/libnm/nm-libnm-utils.c @@ -46,6 +46,7 @@ _nml_dbus_log(NMLDBusLogLevel level, gboolean use_stdout, const char *fmt, ...) va_list args; const char * prefix = ""; gint64 ts; + pid_t pid; /* 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 @@ -89,14 +90,18 @@ _nml_dbus_log(NMLDBusLogLevel level, gboolean use_stdout, const char *fmt, ...) ts = nm_utils_clock_gettime_nsec(CLOCK_BOOTTIME); + pid = getpid(); + if (use_stdout) { - g_print("libnm-dbus: %s[%" G_GINT64_FORMAT ".%05" G_GINT64_FORMAT "] %s\n", + g_print("libnm-dbus[%lld]: %s[%" G_GINT64_FORMAT ".%05" G_GINT64_FORMAT "] %s\n", + (long long) pid, prefix, ts / NM_UTILS_NSEC_PER_SEC, (ts / (NM_UTILS_NSEC_PER_SEC / 10000)) % 10000, msg); } else { - g_printerr("libnm-dbus: %s[%" G_GINT64_FORMAT ".%05" G_GINT64_FORMAT "] %s\n", + g_printerr("libnm-dbus[%lld]: %s[%" G_GINT64_FORMAT ".%05" G_GINT64_FORMAT "] %s\n", + (long long) pid, prefix, ts / NM_UTILS_NSEC_PER_SEC, (ts / (NM_UTILS_NSEC_PER_SEC / 10000)) % 10000, From 1f9622358a691aa97b72b3df118feac7970769c4 Mon Sep 17 00:00:00 2001 From: Thomas Haller Date: Mon, 15 Feb 2021 09:11:42 +0100 Subject: [PATCH 2/3] libnm: avoid assertion failure in _dbus_handle_properties_changed() for logging no properties --- libnm/nm-client.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/libnm/nm-client.c b/libnm/nm-client.c index 2c7751965..ec79b40ef 100644 --- a/libnm/nm-client.c +++ b/libnm/nm-client.c @@ -2930,11 +2930,15 @@ _dbus_handle_properties_changed(NMClient * self, gs_free char *ss = NULL; NML_NMCLIENT_LOG_T(self, - "[%s]: %s: properties changed for interface %s { %s }", + "[%s]: %s: properties changed for interface %s %s%s%s", object_path, log_context, interface_name, - (ss = g_variant_print(changed_properties, TRUE))); + NM_PRINT_FMT_QUOTED(changed_properties, + "{ ", + (ss = g_variant_print(changed_properties, TRUE)), + " }", + "(no changed properties)")); } if (inout_dbobj) { From e1e9abdf041b4cc95fb1936b75ced7669f3d7867 Mon Sep 17 00:00:00 2001 From: Thomas Haller Date: Mon, 15 Feb 2021 09:17:07 +0100 Subject: [PATCH 3/3] libnm: fix tracking object state in NMClient cache NMClient has a NMLDBusObject instance for each D-Bus object that it sees. This object can be in different states, like that we already saw it on D-Bus or that it is only referred to by another property. Due to a bug, we would wrongly not update the state and trigger an assertion. Reproduce with python-dbusmock (commit e89e28bf1bc0254a1eb71b71cf68ef7a97d11e5b) by running `pytest -v -s tests/test_networkmanager.py -k test_one_wifi_with_accesspoints`. With LIBNM_CLIENT_DEBUG we get: >>> libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: properties changed for interface org.freedesktop.NetworkManager.Device { {'ActiveConnection': } } libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: set property org.freedesktop.NetworkManager.Device.ActiveConnection libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 linked libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 consumed >>> libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: set D-Bus object state watched-only libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 consumed >>> libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: property ActiveConnection references /org/freedesktop/NetworkManager/ActiveConnection/0 but object is not present on D-Bus libnm-dbus[96085]: [6464.06459] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 consumed libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: properties changed for interface org.freedesktop.NetworkManager.Device { {'State': } } libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: set property org.freedesktop.NetworkManager.Device.State libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 linked libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 consumed libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06460] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06461] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 consumed libnm-dbus[96085]: [6464.06461] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 consumed libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: properties changed for interface org.freedesktop.NetworkManager.Device { {'StateReason': <(uint32 100, uint32 0)>} } libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: properties-changed: set property org.freedesktop.NetworkManager.Device.StateReason libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 linked libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x01 consumed libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 linked libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/Devices/mock_WiFi2]: changed-type 0x02 consumed libnm-dbus[96085]: [6464.06462] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager]: changed-type 0x02 consumed >>> libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: properties changed for interface org.freedesktop.NetworkManager.Connection.Active { {'Devices': <[objectpath '/org/freedesktop/NetworkManager/Devices/mock_WiFi2']>, 'Default6': , 'Default': , 'Type': <'802-11-wireless'>, 'Vpn': , 'Connection': , 'Master': , 'SpecificObject': , 'Uuid': <'72757a57-8cb6-4052-a18f-4e2be4ba27d9'>, 'State': , 'Id': <'AP_3'>} } >>> here we lack "set D-Bus object state on-dbus" libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Devices libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Default6 libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Default libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Type libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Vpn libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Connection libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Master libnm-dbus[96085]: [6464.06465] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.SpecificObject libnm-dbus[96085]: [6464.06466] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Uuid libnm-dbus[96085]: [6464.06466] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.State libnm-dbus[96085]: [6464.06466] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: interfaces-added: set property org.freedesktop.NetworkManager.Connection.Active.Id libnm-dbus[96085]: [6464.06466] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: changed-type 0x01 linked libnm-dbus[96085]: [6464.06466] nmclient[c9bf1eaa1f4b6c99]: [/org/freedesktop/NetworkManager/ActiveConnection/0]: changed-type 0x01 consumed Bail out! libnm:ERROR:libnm/nm-client.c:2863:_dbus_handle_obj_changed_dbus: assertion failed: (dbobj->obj_state >= NML_DBUS_OBJ_STATE_ON_DBUS) Backtrace: #3 0x00007f0bd11173bf in g_assertion_message_expr (domain=domain@entry=0x7f0bd1576018 "libnm", file=file@entry=0x7f0bd1576006 "libnm/nm-client.c", line=line@entry=2863, func=func@entry=0x7f0bd157f1b0 <__func__.170> "_dbus_handle_obj_changed_dbus", expr=expr@entry=0x7f0bd157cba0 "dbobj->obj_state >= NML_DBUS_OBJ_STATE_ON_DBUS") at ../glib/gtestutils.c:2963 #4 0x00007f0bd14959dd in _dbus_handle_obj_changed_dbus (self=self@entry=0x5612d4f5a130, log_context=) at libnm/nm-client.c:2863 #5 0x00007f0bd1495c29 in _dbus_handle_changes (self=self@entry=0x5612d4f5a130, log_context=, allow_init_start_check_complete=allow_init_start_check_complete@entry=1) at libnm/nm-client.c:2909 #6 0x00007f0bd1497e56 in _dbus_managed_objects_changed_cb (connection=, sender_name=, arg_object_path=, interface_name=, signal_name=, parameters=0x7f0bb800d720, user_data=0x5612d4f5a130) at libnm/nm-client.c:3172 #7 0x00007f0bd132a8df in emit_signal_instance_in_idle_cb (data=data@entry=0x7f0bb8003700) at ../gio/gdbusconnection.c:3789 #8 0x00007f0bd10f1b5b in g_idle_dispatch (source=source@entry=0x7f0bb8012260, callback=0x7f0bd132a860 , user_data=0x7f0bb8003700) at ../glib/gmain.c:5836 #9 0x00007f0bd10f2a9f in g_main_dispatch (context=0x5612d4f4b630) at ../glib/gmain.c:3325 #10 g_main_context_dispatch (context=0x5612d4f4b630) at ../glib/gmain.c:4043 #11 0x00007f0bd1144a98 in g_main_context_iterate.constprop.0 (context=0x5612d4f4b630, block=block@entry=1, dispatch=dispatch@entry=1, self=) at ../glib/gmain.c:4119 #12 0x00007f0bd10f2163 in g_main_loop_run (loop=0x5612d4f4b720) at ../glib/gmain.c:4317 #13 0x00005612d44b6543 in main (argc=7, argv=0x7fff4414f1d8) at clients/cli/nmcli.c:1036 https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=982613 https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/662 Fixes: ce0e898fb476 ('libnm: refactor caching of D-Bus objects in NMClient') --- libnm/nm-client.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/libnm/nm-client.c b/libnm/nm-client.c index ec79b40ef..92ad5ef2b 100644 --- a/libnm/nm-client.c +++ b/libnm/nm-client.c @@ -2950,9 +2950,12 @@ _dbus_handle_properties_changed(NMClient * self, dbobj = _dbobjs_dbobj_get_r(self, dbus_path); } - if (dbobj) + if (dbobj) { + nm_assert(dbobj->obj_state >= NML_DBUS_OBJ_STATE_WATCHED_ONLY); db_iface_data = nml_dbus_object_iface_data_get(dbobj, interface_name, allow_add_iface); - else if (allow_add_iface) { + if (db_iface_data && dbobj->obj_state == NML_DBUS_OBJ_STATE_WATCHED_ONLY) + nml_dbus_object_set_obj_state(dbobj, NML_DBUS_OBJ_STATE_ON_DBUS, self); + } else if (allow_add_iface) { dbobj = _dbobjs_dbobj_create(self, g_steal_pointer(&dbus_path)); nml_dbus_object_set_obj_state(dbobj, NML_DBUS_OBJ_STATE_ON_DBUS, self); db_iface_data = nml_dbus_object_iface_data_get(dbobj, interface_name, TRUE);