main+logging: Allow early logging before config files

The new setup phase goes like this:

- main()
- parse command line options
- logging is configured, targeting stdout/stderr
- ...other stuff...
- do or do not daemonize, depending on commandline option and config files
- Call openlog() - further log messages go to syslog (and potentially
  stderr as well, if the -d option was specified so we use LOG_PERROR).

Basically, this allows us to log messages about config file parsing
and such, which *greatly* helps with debugging.

src/config/nm-config.c

@@ -254,8 +254,6 @@ static char *cli_config_path;
 static char *cli_config_dir;
 static char *cli_no_auto_default_file;
 static char *cli_plugins;
-static char *cli_log_level;
-static char *cli_log_domains;
 static char *cli_connectivity_uri;
 static int cli_connectivity_interval = -1;
 static char *cli_connectivity_response;
@@ -265,10 +263,6 @@ static GOptionEntry config_options[] = {
 	{ "config-dir", 0, 0, G_OPTION_ARG_FILENAME, &cli_config_dir, N_("Config directory location"), N_("/path/to/config/dir") },
 	{ "no-auto-default", 0, G_OPTION_FLAG_HIDDEN, G_OPTION_ARG_FILENAME, &cli_no_auto_default_file, "no-auto-default.state location", NULL },
 	{ "plugins", 0, 0, G_OPTION_ARG_STRING, &cli_plugins, N_("List of plugins separated by ','"), N_("plugin1,plugin2") },
-	{ "log-level", 0, 0, G_OPTION_ARG_STRING, &cli_log_level, N_("Log level: one of [%s]"), "INFO" },
-	{ "log-domains", 0, 0, G_OPTION_ARG_STRING, &cli_log_domains,
-	  N_("Log domains separated by ',': any combination of [%s]"),
-	  "PLATFORM,RFKILL,WIFI" },
 
 	/* These three are hidden for now, and should eventually just go away. */
 	{ "connectivity-uri", 0, G_OPTION_FLAG_HIDDEN, G_OPTION_ARG_STRING, &cli_connectivity_uri, N_("An http(s) address for checking internet connectivity"), "http://example.com" },
@@ -276,26 +270,9 @@ static GOptionEntry config_options[] = {
 	{ "connectivity-response", 0, G_OPTION_FLAG_HIDDEN, G_OPTION_ARG_STRING, &cli_connectivity_response, N_("The expected start of the response"), N_("Bingo!") },
 	{NULL}
 };
-static gboolean config_options_inited;
-
 GOptionEntry *
 nm_config_get_options (void)
 {
-	if (!config_options_inited) {
-		int i;
-
-		for (i = 0; config_options[i].long_name; i++) {
-			if (!strcmp (config_options[i].long_name, "log-level")) {
-				config_options[i].description = g_strdup_printf (config_options[i].description,
-				                                                 nm_logging_all_levels_to_string ());
-			} else if (!strcmp (config_options[i].long_name, "log-domains")) {
-				config_options[i].description = g_strdup_printf (config_options[i].description,
-				                                                 nm_logging_all_domains_to_string ());
-			}
-		}
-		config_options_inited = TRUE;
-	}
-
 	return config_options;
 }
 
@@ -519,12 +496,7 @@ nm_config_new (GError **error)
 	priv->dhcp_client = g_key_file_get_value (priv->keyfile, "main", "dhcp", NULL);
 	priv->dns_mode = g_key_file_get_value (priv->keyfile, "main", "dns", NULL);
 
-	if (cli_log_level && cli_log_level[0])
-		g_key_file_set_value (priv->keyfile, "logging", "level", cli_log_level);
 	priv->log_level = g_key_file_get_value (priv->keyfile, "logging", "level", NULL);
-
-	if (cli_log_domains && cli_log_domains[0])
-		g_key_file_set_value (priv->keyfile, "logging", "domains", cli_log_domains);
 	priv->log_domains = g_key_file_get_value (priv->keyfile, "logging", "domains", NULL);
 
 	if (cli_connectivity_uri && cli_connectivity_uri[0])
@@ -580,8 +552,6 @@ finalize (GObject *gobject)
 	g_clear_pointer (&cli_config_dir, g_free);
 	g_clear_pointer (&cli_no_auto_default_file, g_free);
 	g_clear_pointer (&cli_plugins, g_free);
-	g_clear_pointer (&cli_log_level, g_free);
-	g_clear_pointer (&cli_log_domains, g_free);
 	g_clear_pointer (&cli_connectivity_uri, g_free);
 	g_clear_pointer (&cli_connectivity_response, g_free);
 

src/logging/nm-logging.c

@@ -36,6 +36,12 @@
 
 #include "nm-logging.h"
 
+static void
+nm_log_handler (const gchar *log_domain,
+                GLogLevelFlags level,
+                const gchar *message,
+                gpointer ignored);
+
 #define LOGD_ALL \
 	(LOGD_PLATFORM | LOGD_RFKILL | LOGD_ETHER | LOGD_WIFI | LOGD_BT | LOGD_MB | \
 	 LOGD_DHCP4 | LOGD_DHCP6 | LOGD_PPP | LOGD_WIFI_SCAN | LOGD_IP4 | \
@@ -49,6 +55,7 @@
 
 static guint32 log_level = LOGL_INFO | LOGL_WARN | LOGL_ERR;
 static guint32 log_domains = LOGD_DEFAULT;
+static gboolean syslog_opened;
 
 typedef struct {
 	guint32 num;
@@ -290,7 +297,9 @@ _nm_log (const char *loc,
 {
 	va_list args;
 	char *msg;
+	char *fullmsg = NULL;
 	GTimeVal tv;
+	int syslog_level = LOG_INFO;
 
 	if (!(log_level & level) || !(log_domains & domain))
 		return;
@@ -301,16 +310,34 @@ _nm_log (const char *loc,
 
 	if ((log_level & LOGL_DEBUG) && (level == LOGL_DEBUG)) {
 		g_get_current_time (&tv);
-		syslog (LOG_INFO, "<debug> [%ld.%ld] [%s] %s(): %s", tv.tv_sec, tv.tv_usec, loc, func, msg);
+		syslog_level = LOG_INFO;
-	} else if ((log_level & LOGL_INFO) && (level == LOGL_INFO))
+		fullmsg = g_strdup_printf ("<debug> [%ld.%ld] [%s] %s(): %s", tv.tv_sec, tv.tv_usec, loc, func, msg);
-		syslog (LOG_INFO, "<info> %s", msg);
+	} else if ((log_level & LOGL_INFO) && (level == LOGL_INFO)) {
-	else if ((log_level & LOGL_WARN) && (level == LOGL_WARN))
+		syslog_level = LOG_INFO;
-		syslog (LOG_WARNING, "<warn> %s", msg);
+		fullmsg = g_strconcat ("<info> ", msg, NULL);
-	else if ((log_level & LOGL_ERR) && (level == LOGL_ERR)) {
+	} else if ((log_level & LOGL_WARN) && (level == LOGL_WARN)) {
+		syslog_level = LOG_WARNING;
+		fullmsg = g_strconcat ("<warn> ", msg, NULL);
+	} else if ((log_level & LOGL_ERR) && (level == LOGL_ERR)) {
+		syslog_level = LOG_ERR;
 		g_get_current_time (&tv);
-		syslog (LOG_ERR, "<error> [%ld.%ld] [%s] %s(): %s", tv.tv_sec, tv.tv_usec, loc, func, msg);
+		fullmsg = g_strdup_printf ("<error> [%ld.%ld] [%s] %s(): %s", tv.tv_sec, tv.tv_usec, loc, func, msg);
+	} else
+		g_assert_not_reached ();
+
+	if (syslog_opened)
+		syslog (syslog_level, "%s", fullmsg);
+	else {
+		FILE *log_target;
+		if (level == LOGL_WARN || level == LOGL_ERR)
+			log_target = stderr;
+		else
+			log_target = stdout;
+		fprintf (log_target, "%s\n", fullmsg);
 	}
+
 	g_free (msg);
+	g_free (fullmsg);
 }
 
 /************************************************************************/
@@ -349,21 +376,28 @@ nm_log_handler (const gchar *log_domain,
 }
 
 void
-nm_logging_start (gboolean debug)
+nm_logging_syslog_openlog (gboolean debug)
 {
+	static gsize log_handler_initialized = 0;
+
 	if (debug)
 		openlog (G_LOG_DOMAIN, LOG_CONS | LOG_PERROR | LOG_PID, LOG_USER);
 	else
 		openlog (G_LOG_DOMAIN, LOG_PID, LOG_DAEMON);
+	syslog_opened = TRUE;
 
+	if (g_once_init_enter (&log_handler_initialized)) {
 		g_log_set_handler (G_LOG_DOMAIN,
 		                   G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
 		                   nm_log_handler,
 		                   NULL);
+		g_once_init_leave (&log_handler_initialized, 1);
+	}
 }
 
 void
-nm_logging_shutdown (void)
+nm_logging_syslog_closelog (void)
 {
+	if (syslog_opened)
 		closelog ();
 }

src/logging/nm-logging.h

@@ -123,7 +123,7 @@ const char *nm_logging_all_domains_to_string (void);
 #undef nm_error_str
 
 gboolean nm_logging_setup     (const char *level, const char *domains, GError **error);
-void     nm_logging_start     (gboolean debug);
+void     nm_logging_syslog_openlog   (gboolean debug);
-void     nm_logging_shutdown  (void);
+void     nm_logging_syslog_closelog  (void);
 
 #endif /* NM_LOGGING_H */

src/main.c

@@ -303,6 +303,8 @@ int
 main (int argc, char *argv[])
 {
 	GOptionContext *opt_ctx = NULL;
+	char *opt_log_level = NULL;
+	char *opt_log_domains = NULL;
 	gboolean become_daemon = TRUE, run_from_build_dir = FALSE;
 	gboolean debug = FALSE;
 	gboolean g_fatal_warnings = FALSE;
@@ -311,6 +313,7 @@ main (int argc, char *argv[])
 	gboolean wifi_enabled = TRUE, net_enabled = TRUE, wwan_enabled = TRUE, wimax_enabled = TRUE;
 	gboolean success, show_version = FALSE;
 	NMPolicy *policy = NULL;
+	int i;
 	gs_unref_object NMVPNManager *vpn_manager = NULL;
 	gs_unref_object NMDnsManager *dns_mgr = NULL;
 	gs_unref_object NMDBusManager *dbus_mgr = NULL;
@@ -326,6 +329,10 @@ main (int argc, char *argv[])
 		{ "version", 'V', 0, G_OPTION_ARG_NONE, &show_version, N_("Print NetworkManager version and exit"), NULL },
 		{ "no-daemon", 'n', G_OPTION_FLAG_REVERSE, G_OPTION_ARG_NONE, &become_daemon, N_("Don't become a daemon"), NULL },
 		{ "debug", 'd', 0, G_OPTION_ARG_NONE, &debug, N_("Don't become a daemon, and log to stderr"), NULL },
+		{ "log-level", 0, 0, G_OPTION_ARG_STRING, &opt_log_level, N_("Log level: one of [%s]"), "INFO" },
+		{ "log-domains", 0, 0, G_OPTION_ARG_STRING, &opt_log_domains,
+		  N_("Log domains separated by ',': any combination of [%s]"),
+		  "PLATFORM,RFKILL,WIFI" },
 		{ "g-fatal-warnings", 0, 0, G_OPTION_ARG_NONE, &g_fatal_warnings, N_("Make all warnings fatal"), NULL },
 		{ "pid-file", 'p', 0, G_OPTION_ARG_FILENAME, &pidfile, N_("Specify the location of a PID file"), N_("filename") },
 		{ "state-file", 0, 0, G_OPTION_ARG_FILENAME, &state_file, N_("State file location"), N_("/path/to/state.file") },
@@ -363,6 +370,16 @@ main (int argc, char *argv[])
 		exit (1);
 	}
 
+	for (i = 0; options[i].long_name; i++) {
+		if (!strcmp (options[i].long_name, "log-level")) {
+			options[i].description = g_strdup_printf (options[i].description,
+			                                          nm_logging_all_levels_to_string ());
+		} else if (!strcmp (options[i].long_name, "log-domains")) {
+			options[i].description = g_strdup_printf (options[i].description,
+			                                          nm_logging_all_domains_to_string ());
+		}
+	}
+
 	/* Parse options */
 	opt_ctx = g_option_context_new (NULL);
 	g_option_context_set_translation_domain (opt_ctx, GETTEXT_PACKAGE);
@@ -387,17 +404,26 @@ main (int argc, char *argv[])
 		exit (0);
 	}
 
+	if (!nm_logging_setup (opt_log_level,
+	                       opt_log_domains,
+	                       &error)) {
+		fprintf (stderr,
+		         _("%s.  Please use --help to see a list of valid options.\n"),
+		         error->message);
+		exit (1);
+	}
+
 	/* When running from the build directory, determine our build directory
 	 * base and set helper paths in the build tree */
 	if (run_from_build_dir) {
 		char *path, *slash;
-		int i;
+		int g;
 
 		/* exe is <basedir>/src/.libs/lt-NetworkManager, so chop off
 		 * the last three components */
 		path = realpath ("/proc/self/exe", NULL);
 		g_assert (path != NULL);
-		for (i = 0; i < 3; ++i) {
+		for (g = 0; g < 3; ++g) {
 			slash = strrchr (path, '/');
 			g_assert (slash != NULL);
 			*slash = '\0';
@@ -439,15 +465,18 @@ main (int argc, char *argv[])
 		exit (1);
 	}
 
-	/* Logging setup */
+	/* Initialize logging from config file *only* if not explicitly
+	 * specified by commandline.
+	 */
+	if (opt_log_level == NULL && opt_log_domains == NULL) {
 		if (!nm_logging_setup (nm_config_get_log_level (config),
 		                       nm_config_get_log_domains (config),
 		                       &error)) {
-		fprintf (stderr,
+			fprintf (stderr, _("%s.  Please use --help to see a list of valid options.\n"),
-		         _("%s.  Please use --help to see a list of valid options.\n"),
 			         error->message);
 			exit (1);
 		}
+	}
 
 	/* Parse the state file */
 	if (!parse_state_file (state_file, &net_enabled, &wifi_enabled, &wwan_enabled, &wimax_enabled, &error)) {
@@ -485,6 +514,8 @@ main (int argc, char *argv[])
 		g_log_set_always_fatal (fatal_mask);
 	}
 
+	nm_logging_syslog_openlog (debug);
+
 	g_type_init ();
 	dbus_threads_init_default ();
 
@@ -493,8 +524,6 @@ main (int argc, char *argv[])
 	 */
 	dbus_glib_global_set_disable_legacy_property_access ();
 
-	nm_logging_start (debug);
-
 	nm_log_info (LOGD_CORE, "NetworkManager (version " NM_DIST_VERSION ") is starting...");
 	success = FALSE;
 
@@ -605,7 +634,7 @@ done:
 
 	g_clear_object (&manager);
 
-	nm_logging_shutdown ();
+	nm_logging_syslog_closelog ();
 
 	if (pidfile && wrote_pidfile)
 		unlink (pidfile);