logging: merge branch 'th/platform-sysctl-logging-mt'

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/merge_requests/772

3 files changed, 144 insertions, 32 deletions

diff --git a/src/libnm-glib-aux/nm-macros-internal.h b/src/libnm-glib-aux/nm-macros-internal.h
index 113a67a0d2..37dde0173b 100644
--- a/src/libnm-glib-aux/nm-macros-internal.h
+++ b/src/libnm-glib-aux/nm-macros-internal.h
@@ -1733,6 +1733,54 @@ nm_decode_version(guint version, guint *major, guint *minor, guint *micro)
         _buf;                                                                               \
     })
 
+#define nm_vsprintf_buf_or_alloc(format, va_last_arg, sbuf_stack, out_sbuf_heap, out_len) \
+    ({                                                                                    \
+        const char *const _format        = (format);                                      \
+        char *const       _sbuf_stack    = (sbuf_stack);                                  \
+        char **const      _out_sbuf_heap = (out_sbuf_heap);                               \
+        gsize *const      _out_len       = (out_len);                                     \
+        const char *      _msg;                                                           \
+        va_list           _va_args;                                                       \
+        int               _l;                                                             \
+                                                                                          \
+        G_STATIC_ASSERT_EXPR(G_N_ELEMENTS(sbuf_stack) > sizeof(_sbuf_stack));             \
+                                                                                          \
+        va_start(_va_args, va_last_arg);                                                  \
+        _l = g_vsnprintf(_sbuf_stack, sizeof(sbuf_stack), _format, _va_args);             \
+        va_end(_va_args);                                                                 \
+                                                                                          \
+        nm_assert(_l >= 0 && _l < G_MAXINT);                                              \
+                                                                                          \
+        if ((gsize) _l >= sizeof(sbuf_stack)) {                                           \
+            const gsize _l2 = ((gsize) _l) + 1u;                                          \
+            char *      _sbuf_heap;                                                       \
+                                                                                          \
+            /* Don't use g_strdup_vprintf() here either, because that also needs
+             * to first determine the length (which is commonly does by printing
+             * to a stack allocated buffer of size 1. We already know the required
+             * size. */          \
+                                                                                          \
+            _sbuf_heap = g_malloc(_l2);                                                   \
+                                                                                          \
+            va_start(_va_args, va_last_arg);                                              \
+            _l = g_vsnprintf(_sbuf_heap, _l2, _format, _va_args);                         \
+            va_end(_va_args);                                                             \
+                                                                                          \
+            nm_assert(_l >= 0 && ((gsize) _l) == _l2 - 1u);                               \
+                                                                                          \
+            _msg            = _sbuf_heap;                                                 \
+            *_out_sbuf_heap = _sbuf_heap;                                                 \
+        } else {                                                                          \
+            _msg            = _sbuf_stack;                                                \
+            *_out_sbuf_heap = NULL;                                                       \
+        }                                                                                 \
+                                                                                          \
+        nm_assert(strlen(_msg) == (gsize) _l);                                            \
+        NM_SET_OUT(_out_len, (gsize) _l);                                                 \
+                                                                                          \
+        _msg;                                                                             \
+    })
+
 /* it is "unsafe" because @bufsize must not be a constant expression and
  * there is no check at compiletime. Regardless of that, the buffer size
  * must not be larger than 300 bytes, as this gets stack allocated. */
@@ -1805,8 +1853,13 @@ NM_AUTO_DEFINE_FCN_VOID0(GMutex *, _nm_auto_unlock_g_mutex, g_mutex_unlock);
 
 #define nm_auto_unlock_g_mutex nm_auto(_nm_auto_unlock_g_mutex)
 
-#define _NM_G_MUTEX_LOCKED(lock, uniq) \
-    nm_auto_unlock_g_mutex GMutex *NM_UNIQ_T(nm_lock, uniq) = (lock)
+#define _NM_G_MUTEX_LOCKED(lock, uniq)                                      \
+    _nm_unused nm_auto_unlock_g_mutex GMutex *NM_UNIQ_T(nm_lock, uniq) = ({ \
+        GMutex *const _lock = (lock);                                       \
+                                                                            \
+        g_mutex_lock(_lock);                                                \
+        _lock;                                                              \
+    })
 
 #define NM_G_MUTEX_LOCKED(lock) _NM_G_MUTEX_LOCKED(lock, NM_UNIQ)
 
diff --git a/src/libnm-log-core/nm-logging.c b/src/libnm-log-core/nm-logging.c
index 06f6044e69..2ab0d92e07 100644
--- a/src/libnm-log-core/nm-logging.c
+++ b/src/libnm-log-core/nm-logging.c
@@ -24,6 +24,7 @@
 
 #include "libnm-glib-aux/nm-logging-base.h"
 #include "libnm-glib-aux/nm-time-utils.h"
+#include "libnm-glib-aux/nm-str-buf.h"
 
 /*****************************************************************************/
 
@@ -401,7 +402,10 @@ nm_logging_setup(const char *level, const char *domains, char **bad_domains, GEr
     if (had_platform_debug && !_nm_logging_enabled_lockfree(LOGL_DEBUG, LOGD_PLATFORM)) {
         /* when debug logging is enabled, platform will cache all access to
          * sysctl. When the user disables debug-logging, we want to clear that
-         * cache right away. */
+         * cache right away.
+         *
+         * It's important that we call this without having a lock on "log", because
+         * otherwise we might deadlock. */
         _nm_logging_clear_platform_logging_cache();
     }
 
@@ -457,22 +461,22 @@ _domains_to_string(gboolean          include_level_override,
                    const NMLogDomain log_state[static _LOGL_N_REAL])
 {
     const LogDesc *diter;
-    GString *      str;
+    NMStrBuf       sbuf;
     int            i;
 
     /* We don't just return g_strdup() the logging domains that were set during
      * nm_logging_setup(), because we want to expand "DEFAULT" and "ALL".
      */
 
-    str = g_string_sized_new(75);
+    nm_str_buf_init(&sbuf, NM_UTILS_GET_NEXT_REALLOC_SIZE_40, FALSE);
+
     for (diter = &domain_desc[0]; diter->name; diter++) {
         /* If it's set for any lower level, it will also be set for LOGL_ERR */
         if (!(diter->num & log_state[LOGL_ERR]))
             continue;
 
-        if (str->len)
-            g_string_append_c(str, ',');
-        g_string_append(str, diter->name);
+        nm_str_buf_append_required_delimiter(&sbuf, ',');
+        nm_str_buf_append(&sbuf, diter->name);
 
         if (!include_level_override)
             continue;
@@ -480,7 +484,8 @@ _domains_to_string(gboolean          include_level_override,
         /* Check if it's logging at a lower level than the default. */
         for (i = 0; i < log_level; i++) {
             if (diter->num & log_state[i]) {
-                g_string_append_printf(str, ":%s", nm_log_level_desc[i].name);
+                nm_str_buf_append_c(&sbuf, ':');
+                nm_str_buf_append(&sbuf, nm_log_level_desc[i].name);
                 break;
             }
         }
@@ -488,13 +493,14 @@ _domains_to_string(gboolean          include_level_override,
         if (!(diter->num & log_state[log_level])) {
             for (i = log_level + 1; i < _LOGL_N_REAL; i++) {
                 if (diter->num & log_state[i]) {
-                    g_string_append_printf(str, ":%s", nm_log_level_desc[i].name);
+                    nm_str_buf_append_c(&sbuf, ':');
+                    nm_str_buf_append(&sbuf, nm_log_level_desc[i].name);
                     break;
                 }
             }
         }
     }
-    return g_string_free(str, FALSE);
+    return nm_str_buf_finalize(&sbuf, NULL);
 }
 
 static char _all_logging_domains_to_str[273];
@@ -656,8 +662,9 @@ _nm_log_impl(const char *file,
              const char *fmt,
              ...)
 {
-    va_list            args;
-    char *             msg;
+    char               msg_stack[400];
+    gs_free char *     msg_heap = NULL;
+    const char *       msg;
     GTimeVal           tv;
     int                errsv;
     const NMLogDomain *cur_log_state;
@@ -698,9 +705,7 @@ _nm_log_impl(const char *file,
         errno = error;
     }
 
-    va_start(args, fmt);
-    msg = g_strdup_vprintf(fmt, args);
-    va_end(args);
+    msg = nm_vsprintf_buf_or_alloc(fmt, fmt, msg_stack, &msg_heap, NULL);
 
 #define MESSAGE_FMT "%s%-7s [%ld.%04ld] %s"
 #define MESSAGE_ARG(prefix, tv, msg) \
@@ -797,8 +802,6 @@ _nm_log_impl(const char *file,
         break;
     }
 
-    g_free(msg);
-
     errno = errsv;
 }
 
diff --git a/src/libnm-platform/nm-linux-platform.c b/src/libnm-platform/nm-linux-platform.c
index d689dfae63..0ee3a227ea 100644
--- a/src/libnm-platform/nm-linux-platform.c
+++ b/src/libnm-platform/nm-linux-platform.c
@@ -429,6 +429,7 @@ typedef struct {
 
     GHashTable *sysctl_get_prev_values;
     CList       sysctl_list;
+    CList       sysctl_clear_cache_lst;
 
     NMUdevClient *udev_client;
 
@@ -447,6 +448,7 @@ typedef struct {
 
         int is_handling;
     } delayed_action;
+
 } NMLinuxPlatformPrivate;
 
 struct _NMLinuxPlatform {
@@ -463,6 +465,18 @@ G_DEFINE_TYPE(NMLinuxPlatform, nm_linux_platform, NM_TYPE_PLATFORM)
 #define NM_LINUX_PLATFORM_GET_PRIVATE(self) \
     _NM_GET_PRIVATE(self, NMLinuxPlatform, NM_IS_LINUX_PLATFORM, NMPlatform)
 
+static NMPlatform *
+NM_LINUX_PLATFORM_FROM_PRIVATE(NMLinuxPlatformPrivate *priv)
+{
+    gpointer self;
+
+    nm_assert(priv);
+
+    self = (((char *) priv) - G_STRUCT_OFFSET(NMLinuxPlatform, _priv));
+    nm_assert(NM_IS_LINUX_PLATFORM(self));
+    return self;
+}
+
 /*****************************************************************************/
 
 #define _NMLOG_PREFIX_NAME             "platform-linux"
@@ -5450,19 +5464,28 @@ sysctl_set_async(NMPlatform *            platform,
     g_object_unref(task);
 }
 
-static GSList *sysctl_clear_cache_list;
+static CList  sysctl_clear_cache_lst_head = C_LIST_INIT(sysctl_clear_cache_lst_head);
+static GMutex sysctl_clear_cache_lock;
 
 void
 _nm_logging_clear_platform_logging_cache(void)
 {
-    while (sysctl_clear_cache_list) {
-        NMLinuxPlatformPrivate *priv = NM_LINUX_PLATFORM_GET_PRIVATE(sysctl_clear_cache_list->data);
+    NM_G_MUTEX_LOCKED(&sysctl_clear_cache_lock);
+
+    while (TRUE) {
+        NMLinuxPlatformPrivate *priv;
+
+        priv = c_list_first_entry(&sysctl_clear_cache_lst_head,
+                                  NMLinuxPlatformPrivate,
+                                  sysctl_clear_cache_lst);
+        if (!priv)
+            return;
+
+        nm_assert(NM_IS_LINUX_PLATFORM(NM_LINUX_PLATFORM_FROM_PRIVATE(priv)));
 
-        sysctl_clear_cache_list =
-            g_slist_delete_link(sysctl_clear_cache_list, sysctl_clear_cache_list);
+        c_list_unlink(&priv->sysctl_clear_cache_lst);
 
-        g_hash_table_destroy(priv->sysctl_get_prev_values);
-        priv->sysctl_get_prev_values = NULL;
+        nm_clear_pointer(&priv->sysctl_get_prev_values, g_hash_table_destroy);
     }
 }
 
@@ -5484,11 +5507,33 @@ sysctl_cache_entry_free(SysctlCacheEntry *entry)
 static void
 _log_dbg_sysctl_get_impl(NMPlatform *platform, const char *pathid, const char *contents)
 {
+    /* Note that we only have on global mutex for all NMPlatform instances. But in general
+     * we hardly run with concurrent threads and there are few NMPlatform instances. So
+     * this is acceptable.
+     *
+     * Note that there are only three functions that touch
+     *   - sysctl_clear_cache_lst_head
+     *   - priv->sysctl_get_prev_values
+     *   - priv->sysctl_list
+     *   - priv->sysctl_clear_cache_lst
+     * these are:
+     *   1) _nm_logging_clear_platform_logging_cache()
+     *   2) _log_dbg_sysctl_get_impl()
+     *   3) finalize()
+     *
+     * Note that 2) keeps the lock while also log! Logging itself may take a lock
+     * and it may even call back into our code again (like g_log() handlers
+     * and _nm_logging_clear_platform_logging_cache() which is called by logging).
+     *
+     * But in practice this is safe because logging code releases its lock before
+     * calling _nm_logging_clear_platform_logging_cache().
+     **/
+    NM_G_MUTEX_LOCKED(&sysctl_clear_cache_lock);
     NMLinuxPlatformPrivate *priv  = NM_LINUX_PLATFORM_GET_PRIVATE(platform);
     SysctlCacheEntry *      entry = NULL;
 
     if (!priv->sysctl_get_prev_values) {
-        sysctl_clear_cache_list = g_slist_prepend(sysctl_clear_cache_list, platform);
+        c_list_link_tail(&sysctl_clear_cache_lst_head, &priv->sysctl_clear_cache_lst);
         c_list_init(&priv->sysctl_list);
         priv->sysctl_get_prev_values =
             g_hash_table_new_full(nm_pstr_hash,
@@ -5510,6 +5555,7 @@ _log_dbg_sysctl_get_impl(NMPlatform *platform, const char *pathid, const char *c
             g_free(entry->value);
             entry->value = g_strdup(contents);
         }
+
         nm_c_list_move_front(&priv->sysctl_list, &entry->lst);
     } else {
         gs_free char *    contents_escaped = g_strescape(contents, NULL);
@@ -5523,7 +5569,7 @@ _log_dbg_sysctl_get_impl(NMPlatform *platform, const char *pathid, const char *c
         memcpy(entry->path_data, pathid, len + 1);
 
         /* Remove oldest entry when the cache becomes too big */
-        if (g_hash_table_size(priv->sysctl_get_prev_values) > 1000) {
+        if (g_hash_table_size(priv->sysctl_get_prev_values) > 1000u) {
             old = c_list_last_entry(&priv->sysctl_list, SysctlCacheEntry, lst);
             g_hash_table_remove(priv->sysctl_get_prev_values, old);
         }
@@ -9362,6 +9408,9 @@ nm_linux_platform_init(NMLinuxPlatform *self)
 {
     NMLinuxPlatformPrivate *priv = NM_LINUX_PLATFORM_GET_PRIVATE(self);
 
+    c_list_init(&priv->sysctl_clear_cache_lst);
+    c_list_init(&priv->sysctl_list);
+
     priv->delayed_action.list_master_connected = g_ptr_array_new();
     priv->delayed_action.list_refresh_link     = g_ptr_array_new();
     priv->delayed_action.list_wait_for_nl_response =
@@ -9517,8 +9566,8 @@ path_is_read_only_fs(const char *path)
         return TRUE;
 
     /* On NFS, statvfs() might not reflect whether we can actually
-	 * write to the remote share. Let's try again with
-	 * access(W_OK) which is more reliable, at least sometimes. */
+     * write to the remote share. Let's try again with
+     * access(W_OK) which is more reliable, at least sometimes. */
     if (access(path, W_OK) < 0 && errno == EROFS)
         return TRUE;
 
@@ -9576,9 +9625,16 @@ finalize(GObject *object)
 
     nl_socket_free(priv->nlh);
 
-    if (priv->sysctl_get_prev_values) {
-        sysctl_clear_cache_list = g_slist_remove(sysctl_clear_cache_list, object);
-        g_hash_table_destroy(priv->sysctl_get_prev_values);
+    {
+        NM_G_MUTEX_LOCKED(&sysctl_clear_cache_lock);
+
+        if (priv->sysctl_get_prev_values) {
+            c_list_unlink(&priv->sysctl_clear_cache_lst);
+            g_hash_table_destroy(priv->sysctl_get_prev_values);
+        }
+
+        nm_assert(c_list_is_empty(&priv->sysctl_clear_cache_lst));
+        nm_assert(c_list_is_empty(&priv->sysctl_list));
     }
 
     priv->udev_client = nm_udev_client_destroy(priv->udev_client);