lib: rewrite zlog lock-free & TLS-buffered

This is a full rewrite of the "back end" logging code.  It now uses a
lock-free list to iterate over logging targets, and the targets
themselves are as lock-free as possible.  (syslog() may have a hidden
internal mutex in the C library;  the file/fd targets use a single
write() call which should ensure atomicity kernel-side.)

Note that some functionality is lost in this patch:
- Solaris printstack() backtraces are ditched (unlikely to come back)
- the `log-filter` machinery is gone (re-added in followup commit)
- `terminal monitor` is temporarily stubbed out.  The old code had a
  race condition with VTYs going away.  It'll likely come back rewritten
  and with vtysh support.
- The `zebra_ext_log` hook is gone.  Instead, it's now much easier to
  add a "proper" logging target.

v2: TLS buffer to get some actual performance

Signed-off-by: David Lamparter <equinox@diac24.net>

1 files changed, 10 insertions, 477 deletions

diff --git a/lib/command.c b/lib/command.c
index 8811b3a791..be8f1e72a3 100644
--- a/lib/command.c
+++ b/lib/command.c
@@ -31,7 +31,7 @@
 #include "frrstr.h"
 #include "memory.h"
 #include "log.h"
-#include "log_int.h"
+#include "log_vty.h"
 #include "thread.h"
 #include "vector.h"
 #include "linklist.h"
@@ -198,65 +198,6 @@ static struct cmd_node enable_node = {
 
 static struct cmd_node config_node = {CONFIG_NODE, "%s(config)# ", 1};
 
-static const struct facility_map {
-	int facility;
-	const char *name;
-	size_t match;
-} syslog_facilities[] = {
-	{LOG_KERN, "kern", 1},
-	{LOG_USER, "user", 2},
-	{LOG_MAIL, "mail", 1},
-	{LOG_DAEMON, "daemon", 1},
-	{LOG_AUTH, "auth", 1},
-	{LOG_SYSLOG, "syslog", 1},
-	{LOG_LPR, "lpr", 2},
-	{LOG_NEWS, "news", 1},
-	{LOG_UUCP, "uucp", 2},
-	{LOG_CRON, "cron", 1},
-#ifdef LOG_FTP
-	{LOG_FTP, "ftp", 1},
-#endif
-	{LOG_LOCAL0, "local0", 6},
-	{LOG_LOCAL1, "local1", 6},
-	{LOG_LOCAL2, "local2", 6},
-	{LOG_LOCAL3, "local3", 6},
-	{LOG_LOCAL4, "local4", 6},
-	{LOG_LOCAL5, "local5", 6},
-	{LOG_LOCAL6, "local6", 6},
-	{LOG_LOCAL7, "local7", 6},
-	{0, NULL, 0},
-};
-
-static const char *facility_name(int facility)
-{
-	const struct facility_map *fm;
-
-	for (fm = syslog_facilities; fm->name; fm++)
-		if (fm->facility == facility)
-			return fm->name;
-	return "";
-}
-
-static int facility_match(const char *str)
-{
-	const struct facility_map *fm;
-
-	for (fm = syslog_facilities; fm->name; fm++)
-		if (!strncmp(str, fm->name, fm->match))
-			return fm->facility;
-	return -1;
-}
-
-static int level_match(const char *s)
-{
-	int level;
-
-	for (level = 0; zlog_priority[level] != NULL; level++)
-		if (!strncmp(s, zlog_priority[level], 2))
-			return level;
-	return ZLOG_DISABLED;
-}
-
 /* This is called from main when a daemon is invoked with -v or --version. */
 void print_version(const char *progname)
 {
@@ -493,6 +434,8 @@ static char *zencrypt(const char *passwd)
 	return crypt(passwd, salt);
 }
 
+static bool full_cli;
+
 /* This function write configuration of this host. */
 static int config_write_host(struct vty *vty)
 {
@@ -508,7 +451,7 @@ static int config_write_host(struct vty *vty)
 	 * which would cause other daemons to then switch to syslog when they
 	 * parse frr.conf.
 	 */
-	if (strcmp(zlog_default->protoname, "WATCHFRR")) {
+	if (full_cli) {
 		if (host.encrypt) {
 			if (host.password_encrypt)
 				vty_out(vty, "password 8 %s\n",
@@ -523,59 +466,7 @@ static int config_write_host(struct vty *vty)
 				vty_out(vty, "enable password %s\n",
 					host.enable);
 		}
-
-		if (host.logfile
-		    && (zlog_default->maxlvl[ZLOG_DEST_FILE]
-			!= ZLOG_DISABLED)) {
-			vty_out(vty, "log file %s", host.logfile);
-			if (zlog_default->maxlvl[ZLOG_DEST_FILE]
-			    != zlog_default->default_lvl)
-				vty_out(vty, " %s",
-					zlog_priority
-						[zlog_default->maxlvl
-							 [ZLOG_DEST_FILE]]);
-			vty_out(vty, "\n");
-		}
-
-		if (zlog_default->maxlvl[ZLOG_DEST_STDOUT] != ZLOG_DISABLED) {
-			vty_out(vty, "log stdout");
-			if (zlog_default->maxlvl[ZLOG_DEST_STDOUT]
-			    != zlog_default->default_lvl)
-				vty_out(vty, " %s",
-					zlog_priority
-						[zlog_default->maxlvl
-							 [ZLOG_DEST_STDOUT]]);
-			vty_out(vty, "\n");
-		}
-
-		if (zlog_default->maxlvl[ZLOG_DEST_MONITOR] == ZLOG_DISABLED)
-			vty_out(vty, "no log monitor\n");
-		else if (zlog_default->maxlvl[ZLOG_DEST_MONITOR]
-			 != zlog_default->default_lvl)
-			vty_out(vty, "log monitor %s\n",
-				zlog_priority[zlog_default->maxlvl
-						      [ZLOG_DEST_MONITOR]]);
-
-		if (zlog_default->maxlvl[ZLOG_DEST_SYSLOG] != ZLOG_DISABLED) {
-			vty_out(vty, "log syslog");
-			if (zlog_default->maxlvl[ZLOG_DEST_SYSLOG]
-			    != zlog_default->default_lvl)
-				vty_out(vty, " %s",
-					zlog_priority[zlog_default->maxlvl
-							      [ZLOG_DEST_SYSLOG]]);
-			vty_out(vty, "\n");
-		}
-
-		if (zlog_default->facility != LOG_DAEMON)
-			vty_out(vty, "log facility %s\n",
-				facility_name(zlog_default->facility));
-
-		if (zlog_default->record_priority == 1)
-			vty_out(vty, "log record-priority\n");
-
-		if (zlog_default->timestamp_precision > 0)
-			vty_out(vty, "log timestamp precision %d\n",
-				zlog_default->timestamp_precision);
+		log_config_write(vty);
 
 		if (host.advanced)
 			vty_out(vty, "service advanced-vty\n");
@@ -2273,7 +2164,8 @@ DEFUN (config_logmsg,
 	int level;
 	char *message;
 
-	if ((level = level_match(argv[idx_log_level]->arg)) == ZLOG_DISABLED)
+	level = log_level_match(argv[idx_log_level]->arg);
+	if (level == ZLOG_DISABLED)
 		return CMD_ERR_NO_MATCH;
 
 	zlog(level, "%s",
@@ -2284,348 +2176,6 @@ DEFUN (config_logmsg,
 	return CMD_SUCCESS;
 }
 
-DEFUN (show_logging,
-       show_logging_cmd,
-       "show logging",
-       SHOW_STR
-       "Show current logging configuration\n")
-{
-	struct zlog *zl = zlog_default;
-
-	vty_out(vty, "Syslog logging: ");
-	if (zl->maxlvl[ZLOG_DEST_SYSLOG] == ZLOG_DISABLED)
-		vty_out(vty, "disabled");
-	else
-		vty_out(vty, "level %s, facility %s, ident %s",
-			zlog_priority[zl->maxlvl[ZLOG_DEST_SYSLOG]],
-			facility_name(zl->facility), zl->ident);
-	vty_out(vty, "\n");
-
-	vty_out(vty, "Stdout logging: ");
-	if (zl->maxlvl[ZLOG_DEST_STDOUT] == ZLOG_DISABLED)
-		vty_out(vty, "disabled");
-	else
-		vty_out(vty, "level %s",
-			zlog_priority[zl->maxlvl[ZLOG_DEST_STDOUT]]);
-	vty_out(vty, "\n");
-
-	vty_out(vty, "Monitor logging: ");
-	if (zl->maxlvl[ZLOG_DEST_MONITOR] == ZLOG_DISABLED)
-		vty_out(vty, "disabled");
-	else
-		vty_out(vty, "level %s",
-			zlog_priority[zl->maxlvl[ZLOG_DEST_MONITOR]]);
-	vty_out(vty, "\n");
-
-	vty_out(vty, "File logging: ");
-	if ((zl->maxlvl[ZLOG_DEST_FILE] == ZLOG_DISABLED) || !zl->fp)
-		vty_out(vty, "disabled");
-	else
-		vty_out(vty, "level %s, filename %s",
-			zlog_priority[zl->maxlvl[ZLOG_DEST_FILE]],
-			zl->filename);
-	vty_out(vty, "\n");
-
-	vty_out(vty, "Protocol name: %s\n", zl->protoname);
-	vty_out(vty, "Record priority: %s\n",
-		(zl->record_priority ? "enabled" : "disabled"));
-	vty_out(vty, "Timestamp precision: %d\n", zl->timestamp_precision);
-
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_stdout,
-       config_log_stdout_cmd,
-       "log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       "Logging control\n"
-       "Set stdout logging level\n"
-       LOG_LEVEL_DESC)
-{
-	int idx_log_level = 2;
-
-	if (argc == idx_log_level) {
-		zlog_set_level(ZLOG_DEST_STDOUT, zlog_default->default_lvl);
-		return CMD_SUCCESS;
-	}
-	int level;
-
-	if ((level = level_match(argv[idx_log_level]->arg)) == ZLOG_DISABLED)
-		return CMD_ERR_NO_MATCH;
-	zlog_set_level(ZLOG_DEST_STDOUT, level);
-	return CMD_SUCCESS;
-}
-
-DEFUN (no_config_log_stdout,
-       no_config_log_stdout_cmd,
-       "no log stdout [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       NO_STR
-       "Logging control\n"
-       "Cancel logging to stdout\n"
-       LOG_LEVEL_DESC)
-{
-	zlog_set_level(ZLOG_DEST_STDOUT, ZLOG_DISABLED);
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_monitor,
-       config_log_monitor_cmd,
-       "log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       "Logging control\n"
-       "Set terminal line (monitor) logging level\n"
-       LOG_LEVEL_DESC)
-{
-	int idx_log_level = 2;
-
-	if (argc == idx_log_level) {
-		zlog_set_level(ZLOG_DEST_MONITOR, zlog_default->default_lvl);
-		return CMD_SUCCESS;
-	}
-	int level;
-
-	if ((level = level_match(argv[idx_log_level]->arg)) == ZLOG_DISABLED)
-		return CMD_ERR_NO_MATCH;
-	zlog_set_level(ZLOG_DEST_MONITOR, level);
-	return CMD_SUCCESS;
-}
-
-DEFUN (no_config_log_monitor,
-       no_config_log_monitor_cmd,
-       "no log monitor [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       NO_STR
-       "Logging control\n"
-       "Disable terminal line (monitor) logging\n"
-       LOG_LEVEL_DESC)
-{
-	zlog_set_level(ZLOG_DEST_MONITOR, ZLOG_DISABLED);
-	return CMD_SUCCESS;
-}
-
-static int set_log_file(struct vty *vty, const char *fname, int loglevel)
-{
-	int ret;
-	char *p = NULL;
-	const char *fullpath;
-
-	/* Path detection. */
-	if (!IS_DIRECTORY_SEP(*fname)) {
-		char cwd[MAXPATHLEN + 1];
-		cwd[MAXPATHLEN] = '\0';
-
-		if (getcwd(cwd, MAXPATHLEN) == NULL) {
-			flog_err_sys(EC_LIB_SYSTEM_CALL,
-				     "config_log_file: Unable to alloc mem!");
-			return CMD_WARNING_CONFIG_FAILED;
-		}
-
-		p = XMALLOC(MTYPE_TMP, strlen(cwd) + strlen(fname) + 2);
-		sprintf(p, "%s/%s", cwd, fname);
-		fullpath = p;
-	} else
-		fullpath = fname;
-
-	ret = zlog_set_file(fullpath, loglevel);
-
-	XFREE(MTYPE_TMP, p);
-
-	if (!ret) {
-		if (vty)
-			vty_out(vty, "can't open logfile %s\n", fname);
-		return CMD_WARNING_CONFIG_FAILED;
-	}
-
-	XFREE(MTYPE_HOST, host.logfile);
-
-	host.logfile = XSTRDUP(MTYPE_HOST, fname);
-
-#if defined(HAVE_CUMULUS)
-	if (zlog_default->maxlvl[ZLOG_DEST_SYSLOG] != ZLOG_DISABLED)
-		zlog_set_level(ZLOG_DEST_SYSLOG, ZLOG_DISABLED);
-#endif
-	return CMD_SUCCESS;
-}
-
-void command_setup_early_logging(const char *dest, const char *level)
-{
-	char *token;
-
-	if (level) {
-		int nlevel = level_match(level);
-
-		if (nlevel != ZLOG_DISABLED)
-			zlog_default->default_lvl = nlevel;
-	}
-
-	if (!dest)
-		return;
-
-	if (strcmp(dest, "stdout") == 0) {
-		zlog_set_level(ZLOG_DEST_STDOUT, zlog_default->default_lvl);
-		return;
-	}
-
-	if (strcmp(dest, "syslog") == 0) {
-		zlog_set_level(ZLOG_DEST_SYSLOG, zlog_default->default_lvl);
-		return;
-	}
-
-	token = strstr(dest, ":");
-	if (token == NULL)
-		return;
-
-	token++;
-
-	set_log_file(NULL, token, zlog_default->default_lvl);
-}
-
-DEFUN (config_log_file,
-       config_log_file_cmd,
-       "log file FILENAME [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       "Logging control\n"
-       "Logging to file\n"
-       "Logging filename\n"
-       LOG_LEVEL_DESC)
-{
-	int idx_filename = 2;
-	int idx_log_levels = 3;
-	if (argc == 4) {
-		int level;
-		if ((level = level_match(argv[idx_log_levels]->arg))
-		    == ZLOG_DISABLED)
-			return CMD_ERR_NO_MATCH;
-		return set_log_file(vty, argv[idx_filename]->arg, level);
-	} else
-		return set_log_file(vty, argv[idx_filename]->arg,
-				    zlog_default->default_lvl);
-}
-
-static void disable_log_file(void)
-{
-	zlog_reset_file();
-
-	XFREE(MTYPE_HOST, host.logfile);
-}
-
-DEFUN (no_config_log_file,
-       no_config_log_file_cmd,
-       "no log file [FILENAME [LEVEL]]",
-       NO_STR
-       "Logging control\n"
-       "Cancel logging to file\n"
-       "Logging file name\n"
-       "Logging level\n")
-{
-	disable_log_file();
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_syslog,
-       config_log_syslog_cmd,
-       "log syslog [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       "Logging control\n"
-       "Set syslog logging level\n"
-       LOG_LEVEL_DESC)
-{
-	int idx_log_levels = 2;
-
-	if (argc == 3) {
-		int level;
-		if ((level = level_match(argv[idx_log_levels]->arg))
-		    == ZLOG_DISABLED)
-			return CMD_ERR_NO_MATCH;
-		zlog_set_level(ZLOG_DEST_SYSLOG, level);
-		return CMD_SUCCESS;
-	} else {
-		zlog_set_level(ZLOG_DEST_SYSLOG, zlog_default->default_lvl);
-		return CMD_SUCCESS;
-	}
-}
-
-DEFUN (no_config_log_syslog,
-       no_config_log_syslog_cmd,
-       "no log syslog [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>] [<emergencies|alerts|critical|errors|warnings|notifications|informational|debugging>]",
-       NO_STR
-       "Logging control\n"
-       "Cancel logging to syslog\n"
-       LOG_FACILITY_DESC
-       LOG_LEVEL_DESC)
-{
-	zlog_set_level(ZLOG_DEST_SYSLOG, ZLOG_DISABLED);
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_facility,
-       config_log_facility_cmd,
-       "log facility <kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>",
-       "Logging control\n"
-       "Facility parameter for syslog messages\n"
-       LOG_FACILITY_DESC)
-{
-	int idx_target = 2;
-	int facility = facility_match(argv[idx_target]->arg);
-
-	zlog_default->facility = facility;
-	return CMD_SUCCESS;
-}
-
-DEFUN (no_config_log_facility,
-       no_config_log_facility_cmd,
-       "no log facility [<kern|user|mail|daemon|auth|syslog|lpr|news|uucp|cron|local0|local1|local2|local3|local4|local5|local6|local7>]",
-       NO_STR
-       "Logging control\n"
-       "Reset syslog facility to default (daemon)\n"
-       LOG_FACILITY_DESC)
-{
-	zlog_default->facility = LOG_DAEMON;
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_record_priority,
-       config_log_record_priority_cmd,
-       "log record-priority",
-       "Logging control\n"
-       "Log the priority of the message within the message\n")
-{
-	zlog_default->record_priority = 1;
-	return CMD_SUCCESS;
-}
-
-DEFUN (no_config_log_record_priority,
-       no_config_log_record_priority_cmd,
-       "no log record-priority",
-       NO_STR
-       "Logging control\n"
-       "Do not log the priority of the message within the message\n")
-{
-	zlog_default->record_priority = 0;
-	return CMD_SUCCESS;
-}
-
-DEFUN (config_log_timestamp_precision,
-       config_log_timestamp_precision_cmd,
-       "log timestamp precision (0-6)",
-       "Logging control\n"
-       "Timestamp configuration\n"
-       "Set the timestamp precision\n"
-       "Number of subsecond digits\n")
-{
-	int idx_number = 3;
-	zlog_default->timestamp_precision =
-		strtoul(argv[idx_number]->arg, NULL, 10);
-	return CMD_SUCCESS;
-}
-
-DEFUN (no_config_log_timestamp_precision,
-       no_config_log_timestamp_precision_cmd,
-       "no log timestamp precision",
-       NO_STR
-       "Logging control\n"
-       "Timestamp configuration\n"
-       "Reset the timestamp precision to the default value of 0\n")
-{
-	zlog_default->timestamp_precision = 0;
-	return CMD_SUCCESS;
-}
-
 DEFUN (debug_memstats,
        debug_memstats_cmd,
        "[no] debug memstats-at-exit",
@@ -2875,7 +2425,6 @@ void cmd_init(int terminal)
 #endif
 	host.password = NULL;
 	host.enable = NULL;
-	host.logfile = NULL;
 	host.config = NULL;
 	host.noconfig = (terminal < 0);
 	host.lines = -1;
@@ -2903,7 +2452,6 @@ void cmd_init(int terminal)
 		install_element(VIEW_NODE, &config_enable_cmd);
 		install_element(VIEW_NODE, &config_terminal_length_cmd);
 		install_element(VIEW_NODE, &config_terminal_no_length_cmd);
-		install_element(VIEW_NODE, &show_logging_cmd);
 		install_element(VIEW_NODE, &show_commandtree_cmd);
 		install_element(VIEW_NODE, &echo_cmd);
 		install_element(VIEW_NODE, &autocomplete_cmd);
@@ -2930,6 +2478,8 @@ void cmd_init(int terminal)
 	install_element(CONFIG_NODE, &no_domainname_cmd);
 
 	if (terminal > 0) {
+		full_cli = true;
+
 		install_element(CONFIG_NODE, &debug_memstats_cmd);
 
 		install_element(CONFIG_NODE, &password_cmd);
@@ -2937,23 +2487,6 @@ void cmd_init(int terminal)
 		install_element(CONFIG_NODE, &enable_password_cmd);
 		install_element(CONFIG_NODE, &no_enable_password_cmd);
 
-		install_element(CONFIG_NODE, &config_log_stdout_cmd);
-		install_element(CONFIG_NODE, &no_config_log_stdout_cmd);
-		install_element(CONFIG_NODE, &config_log_monitor_cmd);
-		install_element(CONFIG_NODE, &no_config_log_monitor_cmd);
-		install_element(CONFIG_NODE, &config_log_file_cmd);
-		install_element(CONFIG_NODE, &no_config_log_file_cmd);
-		install_element(CONFIG_NODE, &config_log_syslog_cmd);
-		install_element(CONFIG_NODE, &no_config_log_syslog_cmd);
-		install_element(CONFIG_NODE, &config_log_facility_cmd);
-		install_element(CONFIG_NODE, &no_config_log_facility_cmd);
-		install_element(CONFIG_NODE, &config_log_record_priority_cmd);
-		install_element(CONFIG_NODE,
-				&no_config_log_record_priority_cmd);
-		install_element(CONFIG_NODE,
-				&config_log_timestamp_precision_cmd);
-		install_element(CONFIG_NODE,
-				&no_config_log_timestamp_precision_cmd);
 		install_element(CONFIG_NODE, &service_password_encrypt_cmd);
 		install_element(CONFIG_NODE, &no_service_password_encrypt_cmd);
 		install_element(CONFIG_NODE, &banner_motd_default_cmd);
@@ -2963,6 +2496,7 @@ void cmd_init(int terminal)
 		install_element(CONFIG_NODE, &service_terminal_length_cmd);
 		install_element(CONFIG_NODE, &no_service_terminal_length_cmd);
 
+		log_cmd_init();
 		vrf_install_commands();
 	}
 
@@ -3000,7 +2534,6 @@ void cmd_terminate(void)
 	XFREE(MTYPE_HOST, host.password_encrypt);
 	XFREE(MTYPE_HOST, host.enable);
 	XFREE(MTYPE_HOST, host.enable_encrypt);
-	XFREE(MTYPE_HOST, host.logfile);
 	XFREE(MTYPE_HOST, host.motdfile);
 	XFREE(MTYPE_HOST, host.config);
 	XFREE(MTYPE_HOST, host.motd);