logging: merge branch 'th/logging-rh1593519'

https://github.com/NetworkManager/NetworkManager/pull/145
https://bugzilla.redhat.com/show_bug.cgi?id=1593519

configure.ac

@@ -391,10 +391,8 @@ AC_ARG_WITH(config-logging-backend-default,
             nm_config_logging_backend_default="$withval",
             nm_config_logging_backend_default="")
 
-if test "$nm_config_logging_backend_default" != 'debug' \
-     -a "$nm_config_logging_backend_default" != 'syslog' \
-     -a "$nm_config_logging_backend_default" != 'journal' \
-     -a "$nm_config_logging_backend_default" != 'journal-syslog-style'; then
+if test "$nm_config_logging_backend_default" != 'syslog' \
+     -a "$nm_config_logging_backend_default" != 'journal'; then
 	# unknown backend. Reset to default. Silently accept the invalid value to
 	# be future proof.
 	nm_config_logging_backend_default=''

man/NetworkManager.conf.xml

@@ -603,12 +603,10 @@ unmanaged-devices=mac:00:22:68:1c:59:b1;mac:00:1E:65:30:D1:C4;interface-name:eth
         <varlistentry>
           <term><varname>backend</varname></term>
           <listitem><para>The logging backend. Supported values
-          are "<literal>debug</literal>", "<literal>syslog</literal>",
-          "<literal>journal</literal>".
-          "<literal>debug</literal>" uses syslog and logs to standard error.
-          If NetworkManager is started in debug mode (<literal>--debug</literal>)
-          this option is ignored and "<literal>debug</literal>" is always used.
-          Otherwise, the default is "<literal>&NM_CONFIG_DEFAULT_LOGGING_BACKEND_TEXT;</literal>".
+          are "<literal>syslog</literal>" and "<literal>journal</literal>".
+          When NetworkManager is started with "<literal>--debug</literal>"
+          in addition all messages will be printed to stderr.
+          If unspecified, the default is "<literal>&NM_CONFIG_DEFAULT_LOGGING_BACKEND_TEXT;</literal>".
           </para></listitem>
         </varlistentry>
         <varlistentry>

meson_options.txt

@@ -21,7 +21,7 @@ option('modify_system', type: 'boolean', value: false, description: 'Allow users
 option('polkit_agent', type: 'boolean', value: false, description: 'enable polkit agent for clients')
 option('selinux', type: 'boolean', value: true, description: 'Build with SELinux')
 option('systemd_journal', type: 'boolean', value: true, description: 'Use systemd journal for logging')
-option('config_logging_backend_default', type: 'combo', choices: ['default', 'debug', 'syslog', 'journal', 'journal-syslog-style'], value: 'default', description: 'Default value for logging.backend')
+option('config_logging_backend_default', type: 'combo', choices: ['default', 'syslog', 'journal'], value: 'default', description: 'Default value for logging.backend')
 option('hostname_persist', type: 'combo', choices: ['default', 'suse', 'gentoo', 'slackware'], value: 'default', description: 'Hostname persist method')
 option('libaudit', type: 'combo', choices: ['yes', 'yes-disabled-by-default', 'no'], value: 'yes', description: 'Build with audit daemon support. yes-disabled-by-default enables support, but disables it unless explicitly configured via NetworkManager.conf')
 

src/devices/nm-device.c

@@ -13790,12 +13790,10 @@ nm_device_spawn_iface_helper (NMDevice *self)
 		g_ptr_array_add (argv, g_strdup_printf ("%d %s", (int) stable_type, stable_id));
 	}
 
-	logging_backend = nm_config_get_is_debug (nm_config_get ())
-	                  ? g_strdup ("debug")
-	                  : nm_config_data_get_value (NM_CONFIG_GET_DATA_ORIG,
-	                                              NM_CONFIG_KEYFILE_GROUP_LOGGING,
-	                                              NM_CONFIG_KEYFILE_KEY_LOGGING_BACKEND,
-	                                              NM_CONFIG_GET_VALUE_STRIP | NM_CONFIG_GET_VALUE_NO_EMPTY);
+	logging_backend = nm_config_data_get_value (NM_CONFIG_GET_DATA_ORIG,
+	                                            NM_CONFIG_KEYFILE_GROUP_LOGGING,
+	                                            NM_CONFIG_KEYFILE_KEY_LOGGING_BACKEND,
+	                                            NM_CONFIG_GET_VALUE_STRIP | NM_CONFIG_GET_VALUE_NO_EMPTY);
 	if (logging_backend) {
 		g_ptr_array_add (argv, g_strdup ("--logging-backend"));
 		g_ptr_array_add (argv, logging_backend);

src/main.c

@@ -227,11 +227,12 @@ main (int argc, char *argv[])
 	gboolean success = FALSE;
 	NMManager *manager = NULL;
 	NMConfig *config;
-	GError *error = NULL;
+	gs_free_error GError *error = NULL;
 	gboolean wrote_pidfile = FALSE;
 	char *bad_domains = NULL;
 	NMConfigCmdLineOptions *config_cli;
 	guint sd_id = 0;
+	GError *error_invalid_logging_config = NULL;
 
 	/* Known to cause a possible deadlock upon GDBus initialization:
 	 * https://bugzilla.gnome.org/show_bug.cgi?id=674885 */
@@ -304,11 +305,6 @@ main (int argc, char *argv[])
 		         _("%s.  Please use --help to see a list of valid options.\n"),
 		         error->message);
 		exit (1);
-	} else if (bad_domains) {
-		fprintf (stderr,
-		         _("Ignoring unrecognized log domain(s) '%s' passed on command line.\n"),
-		         bad_domains);
-		g_clear_pointer (&bad_domains, g_free);
 	}
 
 	/* Read the config file and CLI overrides */
@@ -330,15 +326,9 @@ main (int argc, char *argv[])
 		if (!nm_logging_setup (nm_config_get_log_level (config),
 		                       nm_config_get_log_domains (config),
 		                       &bad_domains,
-		                       &error)) {
-			fprintf (stderr, _("Error in configuration file: %s.\n"),
-			         error->message);
-			exit (1);
-		} else if (bad_domains) {
-			fprintf (stderr,
-			         _("Ignoring unrecognized log domain(s) '%s' from config files.\n"),
-			         bad_domains);
-			g_clear_pointer (&bad_domains, g_free);
+		                       &error_invalid_logging_config)) {
+			/* ignore error, and print the failure reason below.
+			 * Likewise, print about bad_domains below. */
 		}
 	}
 
@@ -374,6 +364,19 @@ main (int argc, char *argv[])
 	nm_log_info (LOGD_CORE, "Read config: %s", nm_config_data_get_config_description (nm_config_get_data (config)));
 	nm_config_data_log (nm_config_get_data (config), "CONFIG: ", "  ", NULL);
 
+	if (error_invalid_logging_config) {
+		nm_log_warn (LOGD_CORE, "config: invalid logging configuration: %s", error_invalid_logging_config->message);
+		g_clear_error (&error_invalid_logging_config);
+	}
+	if (bad_domains) {
+		nm_log_warn (LOGD_CORE, "config: invalid logging domains '%s' from %s",
+		             bad_domains,
+		             (global_opt.opt_log_level == NULL && global_opt.opt_log_domains == NULL)
+		               ? "config file"
+		               : "command line");
+		nm_clear_g_free (&bad_domains);
+	}
+
 	/* the first access to State causes the file to be read (and possibly print a warning) */
 	nm_config_state_get (config);
 

src/nm-logging.c

@@ -98,6 +98,12 @@ static struct Global {
 	const char *prefix;
 	const char *syslog_identifier;
 	enum {
+		/* before we setup syslog (during start), the backend defaults to GLIB, meaning:
+		 * we use g_log() for all logging. At that point, the application is not yet supposed
+		 * to do any logging and doing so indicates a bug.
+		 *
+		 * Afterwards, the backend is either SYSLOG or JOURNAL. From that point, also
+		 * g_log() is redirected to this backend via a logging handler. */
 		LOG_BACKEND_GLIB,
 		LOG_BACKEND_SYSLOG,
 		LOG_BACKEND_JOURNAL,
@@ -832,21 +838,36 @@ nm_logging_set_prefix (const char *format, ...)
 void
 nm_logging_syslog_openlog (const char *logging_backend, gboolean debug)
 {
+	gboolean fetch_monotonic_timestamp = FALSE;
+	gboolean obsolete_debug_backend = FALSE;
+
+	nm_assert (NM_IN_STRSET (""NM_CONFIG_DEFAULT_LOGGING_BACKEND,
+	                         NM_LOG_CONFIG_BACKEND_JOURNAL,
+	                         NM_LOG_CONFIG_BACKEND_SYSLOG));
+
 	if (global.log_backend != LOG_BACKEND_GLIB)
 		g_return_if_reached ();
 
 	if (!logging_backend)
 		logging_backend = ""NM_CONFIG_DEFAULT_LOGGING_BACKEND;
 
+	if (nm_streq (logging_backend, NM_LOG_CONFIG_BACKEND_DEBUG)) {
+		/* "debug" was wrongly documented as a valid logging backend. It makes no sense however,
+		 * because printing to stderr only makes sense when not demonizing. Whether to daemonize
+		 * is only controlled via command line arguments (--no-daemon, --debug) and not via the
+		 * logging backend from configuration.
+		 *
+		 * Fall back to the default. */
+		logging_backend = ""NM_CONFIG_DEFAULT_LOGGING_BACKEND;
+		obsolete_debug_backend = TRUE;
+	}
+
 #if SYSTEMD_JOURNAL
-	if (strcmp (logging_backend, "syslog") != 0) {
+	if (!nm_streq (logging_backend, NM_LOG_CONFIG_BACKEND_SYSLOG)) {
 		global.log_backend = LOG_BACKEND_JOURNAL;
 		global.uses_syslog = TRUE;
 		global.debug_stderr = debug;
-
-		/* ensure we read a monotonic timestamp. Reading the timestamp the first
-		 * time causes a logging message. We don't want to do that during _nm_log_impl. */
-		nm_utils_get_monotonic_timestamp_ns ();
+		fetch_monotonic_timestamp = TRUE;
 	} else
 #endif
 	{
@@ -860,5 +881,30 @@ nm_logging_syslog_openlog (const char *logging_backend, gboolean debug)
 	                   G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
 	                   nm_log_handler,
 	                   NULL);
-}
 
+	if (fetch_monotonic_timestamp) {
+		/* ensure we read a monotonic timestamp. Reading the timestamp the first
+		 * time causes a logging message. We don't want to do that during _nm_log_impl. */
+		nm_utils_get_monotonic_timestamp_ns ();
+	}
+
+	if (obsolete_debug_backend)
+		nm_log_dbg (LOGD_CORE, "config: ignore deprecated logging backend 'debug', fallback to '%s'", logging_backend);
+
+	if (nm_streq (logging_backend, NM_LOG_CONFIG_BACKEND_SYSLOG)) {
+		/* good */
+	} else if (nm_streq (logging_backend, NM_LOG_CONFIG_BACKEND_JOURNAL)) {
+#if !SYSTEMD_JOURNAL
+		nm_log_warn (LOGD_CORE, "config: logging backend 'journal' is not available, fallback to 'syslog'");
+#endif
+	} else {
+		nm_log_warn (LOGD_CORE, "config: invalid logging backend '%s', fallback to '%s'",
+		             logging_backend,
+#if SYSTEMD_JOURNAL
+		             NM_LOG_CONFIG_BACKEND_JOURNAL
+#else
+		             NM_LOG_CONFIG_BACKEND_SYSLOG
+#endif
+		             );
+	}
+}

src/nm-logging.h

@@ -28,6 +28,10 @@
 #error nm-test-utils.h must be included as last header
 #endif
 
+#define NM_LOG_CONFIG_BACKEND_DEBUG   "debug"
+#define NM_LOG_CONFIG_BACKEND_SYSLOG  "syslog"
+#define NM_LOG_CONFIG_BACKEND_JOURNAL "journal"
+
 /* Log domains */
 typedef enum  { /*< skip >*/
 	LOGD_NONE       = 0LL,