[network-manager-libreswan/th/vpn-plugin-debug-bgo766872: 14/20] service: replace g_log() by new logging macros



commit 4907815ba205e8eec74a4bd64087d91d387c9a9a
Author: Thomas Haller <thaller redhat com>
Date:   Thu May 26 13:20:43 2016 +0200

    service: replace g_log() by new logging macros
    
    Introduce new logging macros _LOGD(), _LOGI(), _LOGW() similar
    like we have them in NetworkManager core and nm-openvpn.
    
    They no longer use g_log() but g_print(). The reason is that
    - g_log() adds a prefix that we don't want
    - g_info() and g_debug() levels are disabled by g_log() unless
      G_DEBUG_MESSAGES is set.
    - g_warning() dumps core when run with G_DEBUG=fatal-warnings.
      It seems more suited for assertion failures than regular logging.
    - by default, g_warning() and higher prints to stderr, while g_info()
      and lower uses stdout.
    
    Also, these new logging macros honor a log_level setting.

 src/nm-libreswan-service.c |  151 ++++++++++++++++++++++++--------------------
 1 files changed, 82 insertions(+), 69 deletions(-)
---
diff --git a/src/nm-libreswan-service.c b/src/nm-libreswan-service.c
index e0dd03c..100d5c8 100644
--- a/src/nm-libreswan-service.c
+++ b/src/nm-libreswan-service.c
@@ -53,6 +53,7 @@
 
 #include "nm-libreswan-helper-service-dbus.h"
 #include "utils.h"
+#include "nm-vpn/nm-vpn-plugin-macros.h"
 
 #if !defined(DIST_VERSION)
 # define DIST_VERSION VERSION
@@ -72,6 +73,7 @@ G_DEFINE_TYPE (NMLibreswanPlugin, nm_libreswan_plugin, NM_TYPE_VPN_SERVICE_PLUGI
 
 static struct {
        gboolean debug;
+       int log_level;
        GMainLoop *loop;
 } gl/*obal*/;
 
@@ -126,19 +128,33 @@ typedef struct {
 
 #define NM_LIBRESWAN_PLUGIN_GET_PRIVATE(o) (G_TYPE_INSTANCE_GET_PRIVATE ((o), NM_TYPE_LIBRESWAN_PLUGIN, 
NMLibreswanPluginPrivate))
 
-#define DEBUG(...) \
+/****************************************************************/
+
+#define _NMLOG(level, ...) \
     G_STMT_START { \
-        if (gl.debug) { \
-            g_message (__VA_ARGS__); \
-        } \
+         if (gl.log_level >= (level)) { \
+              g_print ("nm-libreswan[%ld] %-7s " _NM_UTILS_MACRO_FIRST (__VA_ARGS__) "\n", \
+                       (long) getpid (), \
+                       nm_utils_syslog_to_str (level) \
+                       _NM_UTILS_MACRO_REST (__VA_ARGS__)); \
+         } \
     } G_STMT_END
 
-/****************************************************************/
+static gboolean
+_LOGD_enabled (void)
+{
+    return gl.log_level >= LOG_INFO;
+}
+
+#define _LOGD(...) _NMLOG(LOG_INFO,    __VA_ARGS__)
+#define _LOGI(...) _NMLOG(LOG_NOTICE,  __VA_ARGS__)
+#define _LOGW(...) _NMLOG(LOG_WARNING, __VA_ARGS__)
+#define _LOGE(...) _NMLOG(LOG_EMERG, __VA_ARGS__)
 
 static void
 _debug_write_option (const char *setting)
 {
-       g_print ("Config %s\n", setting);
+       _LOGD ("Config %s", setting);
 }
 
 /****************************************************************/
@@ -296,7 +312,7 @@ block_quit (NMLibreswanPlugin *self)
 {
        NMLibreswanPluginPrivate *priv = NM_LIBRESWAN_PLUGIN_GET_PRIVATE (self);
        priv->quit_blockers++;
-       DEBUG ("Block quit: %d blockers", priv->quit_blockers);
+       _LOGD ("Block quit: %d blockers", priv->quit_blockers);
 }
 
 static void
@@ -305,7 +321,7 @@ unblock_quit (NMLibreswanPlugin *self)
        NMLibreswanPluginPrivate *priv = NM_LIBRESWAN_PLUGIN_GET_PRIVATE (self);
        if (--priv->quit_blockers == 0)
                g_main_loop_quit (gl.loop);
-       DEBUG ("Unblock quit: %d blockers", priv->quit_blockers);
+       _LOGD ("Unblock quit: %d blockers", priv->quit_blockers);
 }
 
 /****************************************************************/
@@ -463,10 +479,10 @@ connect_failed (NMLibreswanPlugin *self,
                 NMVpnPluginFailure reason)
 {
        if (error) {
-               g_warning ("Connect failed: (%s/%d) %s",
-                          g_quark_to_string (error->domain),
-                          error->code,
-                          error->message);
+               _LOGW ("Connect failed: (%s/%d) %s",
+                      g_quark_to_string (error->domain),
+                      error->code,
+                      error->message);
        }
 
        nm_vpn_service_plugin_failure (NM_VPN_SERVICE_PLUGIN (self), reason);
@@ -492,7 +508,7 @@ check_running_cb (GPid pid, gint status, gpointer user_data)
        if (WIFEXITED (status))
                ret = WEXITSTATUS (status);
 
-       DEBUG ("Spawn: child %d exited with status %d", pid, ret);
+       _LOGD ("Spawn: child %d exited with status %d", pid, ret);
        unblock_quit (self);
 
        /* Reap child */
@@ -535,7 +551,7 @@ child_watch_cb (GPid pid, gint status, gpointer user_data)
        GError *error = NULL;
        gboolean success;
 
-       DEBUG ("Spawn: child %d exited", pid);
+       _LOGD ("Spawn: child %d exited", pid);
        unblock_quit (self);
 
        if (priv->watch_id == 0 || priv->pid != pid) {
@@ -550,9 +566,9 @@ child_watch_cb (GPid pid, gint status, gpointer user_data)
        if (WIFEXITED (status)) {
                ret = WEXITSTATUS (status);
                if (ret)
-                       g_message ("Spawn: child %d exited with error code %d", pid, ret);
+                       _LOGI ("Spawn: child %d exited with error code %d", pid, ret);
        } else
-               g_warning ("Spawn: child %d died unexpectedly", pid);
+               _LOGW ("Spawn: child %d died unexpectedly", pid);
 
        /* Reap child */
        waitpid (pid, NULL, WNOHANG);
@@ -580,7 +596,7 @@ child_watch_cb (GPid pid, gint status, gpointer user_data)
                priv->retries = 0;
                success = connect_step (self, &error);
        } else if (priv->retries) {
-               g_message ("Spawn: %d more tries...", priv->retries);
+               _LOGI ("Spawn: %d more tries...", priv->retries);
                priv->retry_id = g_timeout_add (100, retry_cb, self);
                return;
        }
@@ -611,7 +627,8 @@ do_spawn (NMLibreswanPlugin *self,
        GError *local = NULL;
        va_list ap;
        GPtrArray *argv;
-       char *cmdline, *arg;
+       gs_free char *cmdline = NULL;
+       char *arg;
        gboolean success;
        GPid pid = 0;
 
@@ -624,11 +641,7 @@ do_spawn (NMLibreswanPlugin *self,
        va_end (ap);
        g_ptr_array_add (argv, NULL);
 
-       if (gl.debug) {
-               cmdline = g_strjoinv (" ", (char **) argv->pdata);
-               g_message ("Spawn: %s", cmdline);
-               g_free (cmdline);
-       }
+       _LOGI ("Spawn: %s", (cmdline = g_strjoinv (" ", (char **) argv->pdata)));
 
        if (out_stdin || out_stderr) {
                success = g_spawn_async_with_pipes (NULL, (char **) argv->pdata, NULL,
@@ -641,11 +654,11 @@ do_spawn (NMLibreswanPlugin *self,
                                         NULL, NULL, &pid, &local);
        }
        if (success) {
-               DEBUG ("Spawn: child process %d", pid);
+               _LOGD ("Spawn: child process %d", pid);
        } else {
-               g_warning ("Spawn failed: (%s/%d) %s",
-                          g_quark_to_string (local->domain),
-                          local->code, local->message);
+               _LOGW ("Spawn failed: (%s/%d) %s",
+                      g_quark_to_string (local->domain),
+                      local->code, local->message);
                g_propagate_error (error, local);
        }
 
@@ -747,7 +760,8 @@ spawn_pty (NMLibreswanPlugin *self,
        struct termios termios_flags;
        va_list ap;
        GPtrArray *argv;
-       char *cmdline, *arg;
+       gs_free char *cmdline = NULL;
+       char *arg;
        int ret;
 
        /* The pipes */
@@ -839,11 +853,7 @@ spawn_pty (NMLibreswanPlugin *self,
        va_end (ap);
        g_ptr_array_add (argv, NULL);
 
-       if (gl.debug) {
-               cmdline = g_strjoinv (" ", (char **) argv->pdata);
-               g_message ("PTY spawn: %s", cmdline);
-               g_free (cmdline);
-       }
+       _LOGI ("PTY spawn: %s", (cmdline = g_strjoinv (" ", (char **) argv->pdata)));
 
        /* Fork the command */
        child_pid = forkpty (&pty_master_fd, NULL, NULL, NULL);
@@ -851,11 +861,11 @@ spawn_pty (NMLibreswanPlugin *self,
                /* in the child */
 
                if (dup2 (stdout_pipe[1], 1) == -1) {
-                       g_error ("PTY spawn: cannot dup stdout (%d): %s.", errno, g_strerror (errno));
+                       _LOGE ("PTY spawn: cannot dup stdout (%d): %s.", errno, g_strerror (errno));
                        _exit (-1);
                }
                if (dup2 (stderr_pipe[1], 2) == -1) {
-                       g_error ("PTY spawn: cannot dup stderr (%d): %s.", errno, g_strerror (errno));
+                       _LOGE ("PTY spawn: cannot dup stderr (%d): %s.", errno, g_strerror (errno));
                        _exit (-1);
                }
 
@@ -871,12 +881,12 @@ spawn_pty (NMLibreswanPlugin *self,
 
                /* This is probably a rather futile attempt to produce an error message
                 * as it goes to the piped stderr. */
-               g_error ("PTY spawn: cannot exec '%s' (%d): %s", (char *) argv->pdata[0],
+               _LOGE ("PTY spawn: cannot exec '%s' (%d): %s", (char *) argv->pdata[0],
                         errno, g_strerror (errno));
                _exit (-1);
        }
 
-       DEBUG ("PTY spawn: child process %d", child_pid);
+       _LOGD ("PTY spawn: child process %d", child_pid);
 
        /* Close child side's pipes */
        close (stderr_pipe[1]);
@@ -940,10 +950,10 @@ verify_source (struct nl_msg *msg, gpointer user_data)
 
        if (!creds || creds->pid || creds->uid || creds->gid) {
                if (creds) {
-                       g_warning ("netlink: received non-kernel message (pid %d uid %d gid %d)",
-                                  creds->pid, creds->uid, creds->gid);
+                       _LOGW ("netlink: received non-kernel message (pid %d uid %d gid %d)",
+                              creds->pid, creds->uid, creds->gid);
                } else
-                       g_warning ("netlink: received message without credentials");
+                       _LOGW ("netlink: received message without credentials");
                return NL_STOP;
        }
 
@@ -985,7 +995,7 @@ parse_reply (struct nl_msg *msg, void *arg)
        }
 
        if (n->nlmsg_type != XFRM_MSG_NEWPOLICY) {
-               g_warning ("msg type %d not NEWPOLICY", n->nlmsg_type);
+               _LOGW ("msg type %d not NEWPOLICY", n->nlmsg_type);
                return NL_SKIP;
        }
 
@@ -994,7 +1004,7 @@ parse_reply (struct nl_msg *msg, void *arg)
         */
 
        if (!nlmsg_valid_hdr (n, sizeof (struct xfrm_userpolicy_info))) {
-               g_warning ("msg too short");
+               _LOGW ("msg too short");
                return -NLE_MSG_TOOSHORT;
        }
 
@@ -1003,7 +1013,7 @@ parse_reply (struct nl_msg *msg, void *arg)
                       nlmsg_attrdata (n, sizeof (struct xfrm_userpolicy_info)),
                       nlmsg_attrlen (n, sizeof (struct xfrm_userpolicy_info)),
                       NULL) < 0) {
-               g_warning ("failed to parse attributes");
+               _LOGW ("failed to parse attributes");
                return NL_SKIP;
        }
 
@@ -1048,7 +1058,7 @@ have_sad_routes (const char *gw_addr4)
 
        err = nl_send_simple (sk, XFRM_MSG_GETPOLICY, NLM_F_DUMP, NULL, 0);
        if (err < 0) {
-               g_warning ("Error sending: %d %s", err, nl_geterror (err));
+               _LOGW ("Error sending: %d %s", err, nl_geterror (err));
                goto done;
        }
 
@@ -1056,7 +1066,7 @@ have_sad_routes (const char *gw_addr4)
 
        err = nl_recvmsgs_default (sk);
        if (err < 0) {
-               g_warning ("Error parsing: %d %s", err, nl_geterror (err));
+               _LOGW ("Error parsing: %d %s", err, nl_geterror (err));
                goto done;
        }
 
@@ -1254,11 +1264,11 @@ handle_callback (NMDBusLibreswanHelper *object,
        guint i;
        const char *verb;
 
-       g_message ("Configuration from the helper received.");
+       _LOGI ("Configuration from the helper received.");
 
        verb = lookup_string (env, "PLUTO_VERB");
        if (!verb) {
-               g_warning ("PLUTO_VERB missing");
+               _LOGW ("PLUTO_VERB missing");
                goto out;
        }
 
@@ -1269,7 +1279,7 @@ handle_callback (NMDBusLibreswanHelper *object,
        if (val)
                g_variant_builder_add (&config, "{sv}", NM_VPN_PLUGIN_IP4_CONFIG_GATEWAY, val);
        else {
-               g_warning ("IPsec/Pluto Right Peer (VPN Gateway)");
+               _LOGW ("IPsec/Pluto Right Peer (VPN Gateway)");
                goto out;
        }
 
@@ -1285,7 +1295,7 @@ handle_callback (NMDBusLibreswanHelper *object,
        if (val)
                g_variant_builder_add (&config, "{sv}", NM_VPN_PLUGIN_IP4_CONFIG_ADDRESS, val);
        else {
-               g_warning ("IP4 Address");
+               _LOGW ("IP4 Address");
                goto out;
        }
 
@@ -1294,7 +1304,7 @@ handle_callback (NMDBusLibreswanHelper *object,
        if (val)
                g_variant_builder_add (&config, "{sv}", NM_VPN_PLUGIN_IP4_CONFIG_PTP, val);
        else {
-               g_warning ("IP4 PTP Address");
+               _LOGW ("IP4 PTP Address");
                goto out;
        }
 
@@ -1384,7 +1394,7 @@ handle_auth (NMLibreswanPlugin *self, const char **out_message, const char **out
                        g_io_channel_write_chars (priv->channel, p, -1, &bytes_written, &error);
                        g_io_channel_flush (priv->channel, NULL);
                        if (error) {
-                               g_warning ("Failed to write password to ipsec: '%s'", error->message);
+                               _LOGW ("Failed to write password to ipsec: '%s'", error->message);
                                g_clear_error (&error);
                                return FALSE;
                        }
@@ -1394,7 +1404,7 @@ handle_auth (NMLibreswanPlugin *self, const char **out_message, const char **out
                g_io_channel_write_chars (priv->channel, "\n", -1, NULL, NULL);
                g_io_channel_flush (priv->channel, NULL);
 
-               DEBUG ("PTY: password written");
+               _LOGD ("PTY: password written");
 
                /* Don't re-use the password */
                memset (priv->password, 0, strlen (priv->password));
@@ -1421,13 +1431,13 @@ io_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
        const char *found;
 
        if (condition & G_IO_HUP) {
-               DEBUG ("PTY disconnected");
+               _LOGD ("PTY disconnected");
                priv->io_id = 0;
                return G_SOURCE_REMOVE;
        }
 
        if (condition & G_IO_ERR) {
-               g_warning ("PTY spawn: pipe error!");
+               _LOGW ("PTY spawn: pipe error!");
                goto done;
        }
        g_assert (condition & G_IO_IN);
@@ -1444,7 +1454,7 @@ io_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
        if (priv->io_buf->len < strlen (PASSPHRASE_REQUEST))
                return G_SOURCE_CONTINUE;
 
-       DEBUG ("VPN request '%s'", priv->io_buf->str);
+       _LOGD ("VPN request '%s'", priv->io_buf->str);
 
        found = strstr (priv->io_buf->str, PASSPHRASE_REQUEST);
        if (found) {
@@ -1455,7 +1465,7 @@ io_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
                g_string_erase (priv->io_buf, 0, (found + strlen (PASSPHRASE_REQUEST)) - priv->io_buf->str);
 
                if (!handle_auth (self, &message, &hints[0])) {
-                       g_warning ("Unhandled management socket request '%s'", buf);
+                       _LOGW ("Unhandled management socket request '%s'", buf);
                        reason = NM_VPN_PLUGIN_FAILURE_CONNECT_FAILED;
                        goto done;
                }
@@ -1464,11 +1474,11 @@ io_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
                        /* Request new secrets if we need any */
                        priv->pending_auth = TRUE;
                        if (priv->interactive) {
-                               DEBUG ("Requesting new secrets: '%s' (%s)", message, hints[0]);
+                               _LOGD ("Requesting new secrets: '%s' (%s)", message, hints[0]);
                                nm_vpn_service_plugin_secrets_required (NM_VPN_SERVICE_PLUGIN (self), 
message, hints);
                        } else {
                                /* Interactive not allowed, can't ask for more secrets */
-                               g_warning ("More secrets required but cannot ask interactively");
+                               _LOGW ("More secrets required but cannot ask interactively");
                                reason = NM_VPN_PLUGIN_FAILURE_LOGIN_FAILED;
                                goto done;
                        }
@@ -1497,7 +1507,7 @@ pr_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
        char *nl;
 
        if (condition & (G_IO_ERR | G_IO_HUP)) {
-               DEBUG ("PTY(%s) pipe error!", pipe->detail);
+               _LOGD ("PTY(%s) pipe error!", pipe->detail);
                pipe->id = 0;
                return G_SOURCE_REMOVE;
        }
@@ -1519,7 +1529,7 @@ pr_cb (GIOChannel *source, GIOCondition condition, gpointer user_data)
                        break;
                *nl = 0;  /* Don't print the linebreak */
                if (pipe->str->str[0])
-                       DEBUG ("PTY(%s): %s", pipe->detail, pipe->str->str);
+                       _LOGD ("PTY(%s): %s", pipe->detail, pipe->str->str);
                g_string_erase (pipe->str, 0, (nl - pipe->str->str) + 1);
        }
 
@@ -1540,7 +1550,7 @@ connect_step (NMLibreswanPlugin *self, GError **error)
        g_warn_if_fail (priv->pid == 0);
        priv->pid = 0;
 
-       DEBUG ("Connect: step %d", priv->connect_step);
+       _LOGD ("Connect: step %d", priv->connect_step);
 
        uuid = nm_connection_get_uuid (priv->connection);
 
@@ -1636,7 +1646,7 @@ connect_step (NMLibreswanPlugin *self, GError **error)
                g_io_channel_set_buffered (priv->channel, FALSE);
                priv->io_id = g_io_add_watch (priv->channel, G_IO_IN | G_IO_ERR | G_IO_HUP, io_cb, self);
 
-               if (gl.debug) {
+               if (_LOGD_enabled ()) {
                        pipe_init (&priv->out, up_stdout, "OUT");
                        pipe_init (&priv->err, up_stderr, "ERR");
                }
@@ -1677,8 +1687,10 @@ _connect_common (NMVpnServicePlugin   *plugin,
        NMSettingVpn *s_vpn;
        const char *con_name = nm_connection_get_uuid (connection);
 
-       if (gl.debug)
+       if (_LOGD_enabled ()) {
+               _LOGD ("connection:");
                nm_connection_dump (connection);
+       }
 
        priv->ipsec_path = find_helper_bin ("ipsec", error);
        if (!priv->ipsec_path)
@@ -1807,7 +1819,7 @@ real_new_secrets (NMVpnServicePlugin *plugin,
                return FALSE;
        }
 
-       DEBUG ("VPN received new secrets; sending to ipsec");
+       _LOGD ("VPN received new secrets; sending to ipsec");
 
        g_free (priv->password);
        priv->password = g_strdup (nm_setting_vpn_get_secret (s_vpn, NM_LIBRESWAN_XAUTH_PASSWORD));
@@ -1823,7 +1835,7 @@ real_new_secrets (NMVpnServicePlugin *plugin,
 
        /* Request new secrets if we need any */
        if (message) {
-               DEBUG ("Requesting new secrets: '%s'", message);
+               _LOGD ("Requesting new secrets: '%s'", message);
                nm_vpn_service_plugin_secrets_required (plugin, message, hints);
        }
 
@@ -1992,15 +2004,16 @@ main (int argc, char *argv[])
        if (getenv ("LIBRESWAN_DEBUG") || getenv ("IPSEC_DEBUG"))
                gl.debug = TRUE;
 
-       if (gl.debug)
-               g_message ("%s (version " DIST_VERSION ") starting...", argv[0]);
+       gl.log_level = gl.debug ? LOG_INFO : LOG_NOTICE;
+
+       _LOGD ("%s (version " DIST_VERSION ") starting...", argv[0]);
 
        plugin = g_initable_new (NM_TYPE_LIBRESWAN_PLUGIN, NULL, &error,
                                 NM_VPN_SERVICE_PLUGIN_DBUS_SERVICE_NAME, bus_name,
                                 NM_VPN_SERVICE_PLUGIN_DBUS_WATCH_PEER, !gl.debug,
                                 NULL);
        if (!plugin) {
-               g_warning ("Failed to initialize a plugin instance: %s", error->message);
+               _LOGW ("Failed to initialize a plugin instance: %s", error->message);
                g_error_free (error);
                exit (1);
        }
@@ -2012,7 +2025,7 @@ main (int argc, char *argv[])
                                               connection,
                                               NM_DBUS_PATH_LIBRESWAN_HELPER,
                                               &error)) {
-               g_warning ("Failed to export helper interface: %s", error->message);
+               _LOGW ("Failed to export helper interface: %s", error->message);
                g_error_free (error);
                g_clear_object (&plugin);
                exit (1);


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]