[network-manager-openvpn/th/vpn-plugin-debug-bgo766816: 4/4] service: improve logging for nm-openvpn-service-openvpn-helper



commit ecc36342c074b24dc66580f891c7de047e202e7d
Author: Thomas Haller <thaller redhat com>
Date:   Mon May 23 14:20:49 2016 +0200

    service: improve logging for nm-openvpn-service-openvpn-helper
    
    - pass the syslog level to the helper via --debug. This way, the helper
      has more information about the logging verbosity.
    
    - like for nm-openvpn-service, don't use g_log() and related functions
      for logging. They generate by default a prefix that we don't want,
      and they don't work with levels G_LOG_LEVEL_INFO and lower, unless
      G_MESSAGES_DEBUG is defined.
    
    - print a different prefix to the logging line. The first part of the
      prefix is equal to what is printed by the nm-openvpn-service. The
      second part, indicates that it's the helper and its PID.
    
    Note that now with multiple VPN support, there might be helpers invoked
    for different connections. We need to be able to distinguis their
    log-messages.

 src/Makefile.am                         |   16 ++++-
 src/nm-openvpn-service-openvpn-helper.c |  109 ++++++++++++++++++++-----------
 src/nm-openvpn-service.c                |    7 ++-
 3 files changed, 90 insertions(+), 42 deletions(-)
---
diff --git a/src/Makefile.am b/src/Makefile.am
index 1014392..5f8ed86 100644
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -12,7 +12,11 @@ AM_CPPFLAGS = \
        -DNM_OPENVPN_LOCALEDIR=\"$(datadir)/locale\" \
        -DG_LOG_DOMAIN=\"nm-openvpn\"
 
-libexec_PROGRAMS = nm-openvpn-service nm-openvpn-service-openvpn-helper
+libexec_PROGRAMS = \
+       nm-openvpn-service \
+       nm-openvpn-service-openvpn-helper
+
+###############################################################################
 
 nm_openvpn_service_SOURCES = \
        nm-openvpn-service.c \
@@ -23,10 +27,16 @@ nm_openvpn_service_LDADD = \
        $(LIBNM_LIBS) \
        $(top_builddir)/shared/libnm-vpn-plugin-openvpn-shared.la
 
+###############################################################################
+
 nm_openvpn_service_openvpn_helper_SOURCES = \
-       nm-openvpn-service-openvpn-helper.c
+       nm-openvpn-service-openvpn-helper.c \
+       $(top_srcdir)/shared/nm-service-defines.h
 
 nm_openvpn_service_openvpn_helper_LDADD = \
-       $(LIBNM_LIBS)
+       $(LIBNM_LIBS) \
+       $(top_builddir)/shared/libnm-vpn-plugin-openvpn-shared.la
+
+###############################################################################
 
 CLEANFILES = *~
diff --git a/src/nm-openvpn-service-openvpn-helper.c b/src/nm-openvpn-service-openvpn-helper.c
index 6deead7..c6ee039 100644
--- a/src/nm-openvpn-service-openvpn-helper.c
+++ b/src/nm-openvpn-service-openvpn-helper.c
@@ -38,26 +38,57 @@
 #include <arpa/inet.h>
 #include <ctype.h>
 #include <netdb.h>
+#include <syslog.h>
 
-#include "nm-openvpn-service.h"
+#include "utils.h"
+#include "nm-utils/nm-shared-utils.h"
 
 extern char **environ;
 
-static gboolean helper_debug = FALSE;
+static struct {
+       int log_level;
+       const char *log_prefix_token;
+} gl;
+
+/*****************************************************************************/
+
+#define _NMLOG(level, log_always, ...) \
+       G_STMT_START { \
+               if ((log_always) || gl.log_level >= (level)) { \
+                       g_print ("nm-openvpn[%s]: %-7s [helper-%ld] " _NM_UTILS_MACRO_FIRST (__VA_ARGS__) 
"\n", \
+                                gl.log_prefix_token ?: "???", \
+                                nm_utils_syslog_to_str (level), \
+                                (long) getpid () \
+                                _NM_UTILS_MACRO_REST (__VA_ARGS__)); \
+               } \
+       } G_STMT_END
+
+static inline gboolean
+_LOGd_enabled (void)
+{
+       return gl.log_level >= LOG_INFO;
+}
+
+#define _LOGd(...) _NMLOG(LOG_DEBUG,   FALSE, __VA_ARGS__)
+#define _LOGD(...) _NMLOG(LOG_DEBUG,   TRUE,  __VA_ARGS__)
+#define _LOGI(...) _NMLOG(LOG_INFO,    TRUE,  __VA_ARGS__)
+#define _LOGW(...) _NMLOG(LOG_WARNING, TRUE,  __VA_ARGS__)
+
+/*****************************************************************************/
 
 static void
 helper_failed (GDBusProxy *proxy, const char *reason)
 {
        GError *err = NULL;
 
-       g_warning ("nm-openvpn-service-openvpn-helper did not receive a valid %s from openvpn", reason);
+       _LOGW ("nm-openvpn-service-openvpn-helper did not receive a valid %s from openvpn", reason);
 
        if (!g_dbus_proxy_call_sync (proxy, "SetFailure",
                                     g_variant_new ("(s)", reason),
                                     G_DBUS_CALL_FLAGS_NONE, -1,
                                     NULL,
                                     &err)) {
-               g_warning ("Could not send failure information: %s", err->message);
+               _LOGW ("Could not send failure information: %s", err->message);
                g_error_free (err);
        }
 
@@ -75,7 +106,7 @@ send_config (GDBusProxy *proxy, GVariant *config,
                                     G_DBUS_CALL_FLAGS_NONE, -1,
                                     NULL,
                                     &err)) {
-               g_warning ("Could not send configuration information: %s", err->message);
+               _LOGW ("Could not send configuration information: %s", err->message);
                g_error_free (err);
                err = NULL;
        }
@@ -86,7 +117,7 @@ send_config (GDBusProxy *proxy, GVariant *config,
                                             G_DBUS_CALL_FLAGS_NONE, -1,
                                             NULL,
                                             &err)) {
-                       g_warning ("Could not send IPv4 configuration information: %s", err->message);
+                       _LOGW ("Could not send IPv4 configuration information: %s", err->message);
                        g_error_free (err);
                        err = NULL;
                }
@@ -98,7 +129,7 @@ send_config (GDBusProxy *proxy, GVariant *config,
                                             G_DBUS_CALL_FLAGS_NONE, -1,
                                             NULL,
                                             &err)) {
-                       g_warning ("Could not send IPv6 configuration information: %s", err->message);
+                       _LOGW ("Could not send IPv6 configuration information: %s", err->message);
                        g_error_free (err);
                        err = NULL;
                }
@@ -213,14 +244,14 @@ get_ip4_routes (void)
                        break;
 
                if (inet_pton (AF_INET, tmp, &network) <= 0) {
-                       g_warning ("Ignoring invalid static route address '%s'", tmp ? tmp : "NULL");
+                       _LOGW ("Ignoring invalid static route address '%s'", tmp ? tmp : "NULL");
                        continue;
                }
 
                snprintf (buf, BUFLEN, "route_netmask_%d", i);
                tmp = getenv (buf);
                if (!tmp || inet_pton (AF_INET, tmp, &netmask) <= 0) {
-                       g_warning ("Ignoring invalid static route netmask '%s'", tmp ? tmp : "NULL");
+                       _LOGW ("Ignoring invalid static route netmask '%s'", tmp ? tmp : "NULL");
                        continue;
                }
 
@@ -228,7 +259,7 @@ get_ip4_routes (void)
                tmp = getenv (buf);
                /* gateway can be missing */
                if (tmp && (inet_pton (AF_INET, tmp, &gateway) <= 0)) {
-                       g_warning ("Ignoring invalid static route gateway '%s'", tmp ? tmp : "NULL");
+                       _LOGW ("Ignoring invalid static route gateway '%s'", tmp ? tmp : "NULL");
                        continue;
                }
 
@@ -241,7 +272,7 @@ get_ip4_routes (void)
                        errno = 0;
                        tmp_metric = strtol (tmp, NULL, 10);
                        if (errno || tmp_metric < 0 || tmp_metric > G_MAXUINT32) {
-                               g_warning ("Ignoring invalid static route metric '%s'", tmp);
+                               _LOGW ("Ignoring invalid static route metric '%s'", tmp);
                                continue;
                        }
                        metric = (guint32) tmp_metric;
@@ -297,13 +328,13 @@ get_ip6_routes (void)
                        errno = 0;
                        tmp_prefix = strtol (tmp, NULL, 10);
                        if (errno || tmp_prefix <= 0 || tmp_prefix > 128) {
-                               g_warning ("Ignoring invalid static route prefix '%s'", tmp ? tmp : "NULL");
+                               _LOGW ("Ignoring invalid static route prefix '%s'", tmp ? tmp : "NULL");
                                g_strfreev (dest_prefix);
                                continue;
                        }
                        prefix = (guint32) tmp_prefix;
                } else {
-                       g_warning ("Ignoring static route %d with no prefix length", i);
+                       _LOGW ("Ignoring static route %d with no prefix length", i);
                        g_strfreev (dest_prefix);
                        continue;
                }
@@ -314,7 +345,7 @@ get_ip6_routes (void)
                route = nm_ip_route_new (AF_INET6, dest_prefix[0], prefix, tmp, -1, &error);
                g_strfreev (dest_prefix);
                if (!route) {
-                       g_warning ("Ignoring a route: %s", error->message);
+                       _LOGW ("Ignoring a route: %s", error->message);
                        g_error_free (error);
                        continue;
                }
@@ -340,8 +371,8 @@ trusted_remote_to_gvariant (void)
        if (tmp) {
                val = addr6_to_gvariant (tmp);
                if (val == NULL) {
-                       g_warning ("%s: failed to convert VPN gateway address '%s' (%d)",
-                                  __func__, tmp, errno);
+                       _LOGW ("failed to convert VPN gateway address '%s' (%d)",
+                              tmp, errno);
                        return NULL;
                }
                return val;
@@ -351,7 +382,7 @@ trusted_remote_to_gvariant (void)
        if (!tmp)
                tmp = getenv ("remote_1");
        if (!tmp) {
-               g_warning ("%s: did not receive remote gateway address", __func__);
+               _LOGW ("did not receive remote gateway address");
                return NULL;
        }
 
@@ -379,8 +410,8 @@ trusted_remote_to_gvariant (void)
                hints.ai_flags = AI_ADDRCONFIG;
                err = getaddrinfo (tmp, NULL, &hints, &result);
                if (err != 0) {
-                       g_warning ("%s: failed to look up VPN gateway address '%s' (%d)",
-                                  __func__, tmp, err);
+                       _LOGW ("failed to look up VPN gateway address '%s' (%d)",
+                              tmp, err);
                        return NULL;
                }
 
@@ -402,15 +433,15 @@ trusted_remote_to_gvariant (void)
                if (addr.s_addr != 0)
                        return g_variant_new_uint32 (addr.s_addr);
                else {
-                       g_warning ("%s: failed to convert or look up VPN gateway address '%s'",
-                                  __func__, tmp);
+                       _LOGW ("failed to convert or look up VPN gateway address '%s'",
+                              tmp);
                        return NULL;
                }
        } else {
                val = addr4_to_gvariant (tmp);
                if (val == NULL) {
-                       g_warning ("%s: failed to convert VPN gateway address '%s' (%d)",
-                                  __func__, tmp, errno);
+                       _LOGW ("failed to convert VPN gateway address '%s' (%d)",
+                              tmp, errno);
                        return NULL;
                }
        }
@@ -449,19 +480,24 @@ main (int argc, char *argv[])
                        i++;
                        break;
                }
-               if (!strcmp (argv[i], "--helper-debug"))
-                       helper_debug = TRUE;
-               else if (!strcmp (argv[i], "--tun"))
+               if (nm_streq (argv[i], "--debug")) {
+                       if (i + 2 >= argc) {
+                               g_printerr ("Missing debug arguments (requires <LEVEL> <PREFIX_TOKEN>)\n");
+                               exit (1);
+                       }
+                       gl.log_level = _nm_utils_ascii_str_to_int64 (argv[++i], 10, 0, LOG_DEBUG, 0);
+                       gl.log_prefix_token = argv[++i];
+               } else if (!strcmp (argv[i], "--tun"))
                        tapdev = 0;
                else if (!strcmp (argv[i], "--tap"))
                        tapdev = 1;
                else if (!strcmp (argv[i], "--bus-name")) {
                        if (++i == argc) {
-                               g_warning ("Missing bus name argument");
+                               g_printerr ("Missing bus name argument\n");
                                exit (1);
                        }
                        if (!g_dbus_is_name (argv[i])) {
-                               g_warning ("Invalid bus name");
+                               g_printerr ("Invalid bus name\n");
                                exit (1);
                        }
                        bus_name = argv[i];
@@ -470,7 +506,7 @@ main (int argc, char *argv[])
        }
        shift = i - 1;
 
-       if (helper_debug) {
+       if (_LOGd_enabled ()) {
                GString *args;
 
                args = g_string_new (NULL);
@@ -484,13 +520,12 @@ main (int argc, char *argv[])
                        g_free (tmp);
                }
 
-               g_message ("command line: %s", args->str);
+               _LOGd ("command line: %s", args->str);
                g_string_free (args, TRUE);
-               g_message ("openvpn script environment ---------------------------");
+
                iter = environ;
                while (iter && *iter)
-                       g_message ("%s", *iter++);
-               g_message ("------------------------------------------------------");
+                       _LOGd ("environment: %s", *iter++);
        }
 
        /* shift the arguments to the right leaving only those provided by openvpn */
@@ -508,7 +543,7 @@ main (int argc, char *argv[])
                                               NM_VPN_DBUS_PLUGIN_INTERFACE,
                                               NULL, &err);
        if (!proxy) {
-               g_warning ("Could not create a D-Bus proxy: %s", err->message);
+               _LOGW ("Could not create a D-Bus proxy: %s", err->message);
                g_error_free (err);
                exit (1);
        }
@@ -599,7 +634,7 @@ main (int argc, char *argv[])
                        g_variant_builder_add (&ip4builder, "{sv}", NM_VPN_PLUGIN_IP4_CONFIG_PREFIX, val);
                }
        } else
-               g_warning ("No IP4 netmask/prefix (missing or invalid 'ifconfig_netmask')");
+               _LOGW ("No IP4 netmask/prefix (missing or invalid 'ifconfig_netmask')");
 
        val = get_ip4_routes ();
        if (val)
@@ -633,7 +668,7 @@ main (int argc, char *argv[])
                errno = 0;
                netbits = strtol (tmp, NULL, 10);
                if (errno || netbits < 0 || netbits > 128) {
-                       g_warning ("Ignoring invalid prefix '%s'", tmp);
+                       _LOGW ("Ignoring invalid prefix '%s'", tmp);
                } else {
                        val = g_variant_new_uint32 ((guint32) netbits);
                        g_variant_builder_add (&ip6builder, "{sv}", NM_VPN_PLUGIN_IP6_CONFIG_PREFIX, val);
@@ -699,7 +734,7 @@ main (int argc, char *argv[])
                errno = 0;
                mtu = strtol (tmp, NULL, 10);
                if (errno || mtu < 0 || mtu > 20000) {
-                       g_warning ("Ignoring invalid tunnel MTU '%s'", tmp);
+                       _LOGW ("Ignoring invalid tunnel MTU '%s'", tmp);
                } else {
                        val = g_variant_new_uint32 ((guint32) mtu);
                        g_variant_builder_add (&builder, "{sv}", NM_VPN_PLUGIN_CONFIG_MTU, val);
diff --git a/src/nm-openvpn-service.c b/src/nm-openvpn-service.c
index 812dfbb..37d3f41 100644
--- a/src/nm-openvpn-service.c
+++ b/src/nm-openvpn-service.c
@@ -1487,8 +1487,11 @@ nm_openvpn_start_openvpn_binary (NMOpenvpnPlugin *plugin,
        /* Up script, called when connection has been established or has been restarted */
        add_openvpn_arg (args, "--up");
        g_object_get (plugin, NM_VPN_SERVICE_PLUGIN_DBUS_SERVICE_NAME, &bus_name, NULL);
-       stmp = g_strdup_printf ("%s%s --bus-name %s %s --", NM_OPENVPN_HELPER_PATH, _LOGd_enabled () ? " 
--helper-debug" : "",
-                               bus_name, dev_type_is_tap ? "--tap" : "--tun");
+       stmp = g_strdup_printf ("%s --debug %d %ld --bus-name %s %s --",
+                               NM_OPENVPN_HELPER_PATH,
+                               gl.log_level, (long) getpid(),
+                               bus_name,
+                               dev_type_is_tap ? "--tap" : "--tun");
        add_openvpn_arg (args, stmp);
        g_free (stmp);
        add_openvpn_arg (args, "--up-restart");


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