From: David Lamparter <equinox@diac24.net>
Date: Fri, 6 Dec 2019 12:48:06 +0000 (+0100)
Subject: vtysh: show live log messages
X-Git-Tag: pim6-testing-20220430~286^2
X-Git-Url: https://git.puffer.fish/?a=commitdiff_plain;h=refs%2Fpull%2F10353%2Fhead;p=mirror%2Ffrr.git

vtysh: show live log messages

https://www.youtube.com/watch?v=8psFQCEgA18

Signed-off-by: David Lamparter <equinox@opensourcerouting.org>
---

diff --git a/configure.ac b/configure.ac
index ddd883e54f..170d16ca6a 100644
--- a/configure.ac
+++ b/configure.ac
@@ -1371,6 +1371,8 @@ case "${enable_vtysh}" in
       AC_MSG_ERROR([libreadline (needed for vtysh) not found and/or missing dependencies])
     ], [$LIBREADLINE])
   ], [])
+  LIBS="$LIBS -lreadline"
+  AC_CHECK_FUNCS([rl_clear_visible_line])
   LIBS="$prev_libs"
 
   AC_CHECK_HEADER([readline/history.h])
diff --git a/doc/user/vtysh.rst b/doc/user/vtysh.rst
index ec674e377c..97b3863ef5 100644
--- a/doc/user/vtysh.rst
+++ b/doc/user/vtysh.rst
@@ -29,6 +29,30 @@ administrator with an external editor.
    vtysh.
 
 
+Live logs
+=========
+
+.. clicmd:: terminal monitor [DAEMON]
+
+   Receive and display log messages.
+
+   It is not currently possible to change the minimum message priority (fixed
+   to debug) or output formatting.  These will likely be made configurable in
+   the future.
+
+   Log messages are received asynchronously and may be printed both during
+   command execution as well as while on the prompt.  They are printed to
+   stderr, unlike regular CLI output which is printed to stdout.  The intent is
+   that stdin/stdout might be driven by some script while log messages are
+   visible on stderr.  If stdout and stderr are the same file, the prompt and
+   pending input will be cleared and reprinted appropriately.
+
+   .. note::
+
+      If ``vtysh`` cannot keep up, some log messages may be lost.  The daemons
+      do **not** wait for, get blocked by, or buffer messages for ``vtysh``.
+
+
 Pager usage
 ===========
 
diff --git a/vtysh/subdir.am b/vtysh/subdir.am
index 5f7d854948..624361645e 100644
--- a/vtysh/subdir.am
+++ b/vtysh/subdir.am
@@ -7,6 +7,10 @@ bin_PROGRAMS += vtysh/vtysh
 man1 += $(MANBUILD)/vtysh.1
 endif
 
+clippy_scan += \
+	vtysh/vtysh.c \
+	# end
+
 vtysh_vtysh_SOURCES = \
 	vtysh/vtysh_main.c \
 	vtysh/vtysh.c \
diff --git a/vtysh/vtysh.c b/vtysh/vtysh.c
index 2b9b2b4cca..e209cea690 100644
--- a/vtysh/vtysh.c
+++ b/vtysh/vtysh.c
@@ -40,6 +40,7 @@
 #include "linklist.h"
 #include "command.h"
 #include "memory.h"
+#include "network.h"
 #include "filter.h"
 #include "vtysh/vtysh.h"
 #include "vtysh/vtysh_daemons.h"
@@ -69,8 +70,14 @@ struct vtysh_client {
 	int flag;
 	char path[MAXPATHLEN];
 	struct vtysh_client *next;
+
+	struct thread *log_reader;
+	int log_fd;
 };
 
+static bool stderr_tty;
+static bool stderr_stdout_same;
+
 /* Some utility functions for working on vtysh-specific vty tasks */
 
 static FILE *vty_open_pager(struct vty *vty)
@@ -126,27 +133,27 @@ static void vtysh_pager_envdef(bool fallback)
 /* --- */
 
 struct vtysh_client vtysh_client[] = {
-	{.fd = -1, .name = "zebra", .flag = VTYSH_ZEBRA, .next = NULL},
-	{.fd = -1, .name = "ripd", .flag = VTYSH_RIPD, .next = NULL},
-	{.fd = -1, .name = "ripngd", .flag = VTYSH_RIPNGD, .next = NULL},
-	{.fd = -1, .name = "ospfd", .flag = VTYSH_OSPFD, .next = NULL},
-	{.fd = -1, .name = "ospf6d", .flag = VTYSH_OSPF6D, .next = NULL},
-	{.fd = -1, .name = "ldpd", .flag = VTYSH_LDPD, .next = NULL},
-	{.fd = -1, .name = "bgpd", .flag = VTYSH_BGPD, .next = NULL},
-	{.fd = -1, .name = "isisd", .flag = VTYSH_ISISD, .next = NULL},
-	{.fd = -1, .name = "pimd", .flag = VTYSH_PIMD, .next = NULL},
-	{.fd = -1, .name = "nhrpd", .flag = VTYSH_NHRPD, .next = NULL},
-	{.fd = -1, .name = "eigrpd", .flag = VTYSH_EIGRPD, .next = NULL},
-	{.fd = -1, .name = "babeld", .flag = VTYSH_BABELD, .next = NULL},
-	{.fd = -1, .name = "sharpd", .flag = VTYSH_SHARPD, .next = NULL},
-	{.fd = -1, .name = "fabricd", .flag = VTYSH_FABRICD, .next = NULL},
-	{.fd = -1, .name = "watchfrr", .flag = VTYSH_WATCHFRR, .next = NULL},
-	{.fd = -1, .name = "pbrd", .flag = VTYSH_PBRD, .next = NULL},
-	{.fd = -1, .name = "staticd", .flag = VTYSH_STATICD, .next = NULL},
-	{.fd = -1, .name = "bfdd", .flag = VTYSH_BFDD, .next = NULL},
-	{.fd = -1, .name = "vrrpd", .flag = VTYSH_VRRPD, .next = NULL},
-	{.fd = -1, .name = "pathd", .flag = VTYSH_PATHD, .next = NULL},
-	{.fd = -1, .name = "pim6d", .flag = VTYSH_PIM6D, .next = NULL},
+	{.name = "zebra", .flag = VTYSH_ZEBRA},
+	{.name = "ripd", .flag = VTYSH_RIPD},
+	{.name = "ripngd", .flag = VTYSH_RIPNGD},
+	{.name = "ospfd", .flag = VTYSH_OSPFD},
+	{.name = "ospf6d", .flag = VTYSH_OSPF6D},
+	{.name = "ldpd", .flag = VTYSH_LDPD},
+	{.name = "bgpd", .flag = VTYSH_BGPD},
+	{.name = "isisd", .flag = VTYSH_ISISD},
+	{.name = "pimd", .flag = VTYSH_PIMD},
+	{.name = "nhrpd", .flag = VTYSH_NHRPD},
+	{.name = "eigrpd", .flag = VTYSH_EIGRPD},
+	{.name = "babeld", .flag = VTYSH_BABELD},
+	{.name = "sharpd", .flag = VTYSH_SHARPD},
+	{.name = "fabricd", .flag = VTYSH_FABRICD},
+	{.name = "watchfrr", .flag = VTYSH_WATCHFRR},
+	{.name = "pbrd", .flag = VTYSH_PBRD},
+	{.name = "staticd", .flag = VTYSH_STATICD},
+	{.name = "bfdd", .flag = VTYSH_BFDD},
+	{.name = "vrrpd", .flag = VTYSH_VRRPD},
+	{.name = "pathd", .flag = VTYSH_PATHD},
+	{.name = "pim6d", .flag = VTYSH_PIM6D},
 };
 
 /* Searches for client by name, returns index */
@@ -182,8 +189,8 @@ static void vclient_close(struct vtysh_client *vclient)
 	}
 }
 
-static ssize_t vtysh_client_receive(struct vtysh_client *vclient,
-				    char *buf, size_t bufsz, int *pass_fd)
+static ssize_t vtysh_client_receive(struct vtysh_client *vclient, char *buf,
+				    size_t bufsz, int *pass_fd)
 {
 	struct iovec iov[1] = {
 		{
@@ -289,9 +296,8 @@ static int vtysh_client_run(struct vtysh_client *vclient, const char *line,
 	do {
 		ssize_t nread;
 
-		nread = vtysh_client_receive(vclient, bufvalid,
-					     buf + bufsz - bufvalid - 1,
-					     pass_fd);
+		nread = vtysh_client_receive(
+			vclient, bufvalid, buf + bufsz - bufvalid - 1, pass_fd);
 
 		if (nread < 0 && (errno == EINTR || errno == EAGAIN))
 			continue;
@@ -1630,6 +1636,8 @@ static int vtysh_end(void)
 	return CMD_SUCCESS;
 }
 
+#include "vtysh/vtysh_clippy.c"
+
 DEFUNSH(VTYSH_REALLYALL, vtysh_end_all, vtysh_end_all_cmd, "end",
 	"End current mode and change to enable mode\n")
 {
@@ -3512,6 +3520,281 @@ DEFUN (vtysh_show_daemons,
 	return CMD_SUCCESS;
 }
 
+struct visual_prio {
+	/* 4 characters for nice alignment */
+	const char *label;
+
+	int c256_background;
+	int c256_formatarg;
+};
+
+/* clang-format off */
+struct visual_prio visual_prios[] = {
+	[LOG_EMERG] = {
+		.label = "\e[31;1mEMRG",
+		.c256_background = 53,
+		.c256_formatarg = 225,
+	},
+	[LOG_ALERT] = {
+		.label = "\e[31;1mALRT",
+		.c256_background = 53,
+		.c256_formatarg = 225,
+	},
+	[LOG_CRIT] = {
+		.label = "\e[31;1mCRIT",
+		.c256_background = 53,
+		.c256_formatarg = 225,
+	},
+	[LOG_ERR] = {
+		.label = "\e[38;5;202mERR!",
+		.c256_background = 52,
+		.c256_formatarg = 224,
+	},
+	[LOG_WARNING] = {
+		.label = "\e[38;5;222mWARN",
+		.c256_background = 58,
+		.c256_formatarg = 230,
+	},
+	[LOG_NOTICE] = {
+		.label = "NTFY",
+		.c256_background = 234,
+		.c256_formatarg = 195,
+	},
+	[LOG_INFO] = {
+		.label = "\e[38;5;192mINFO",
+		.c256_background = 236,
+		.c256_formatarg = 195,
+	},
+	[LOG_DEBUG] = {
+		.label = "\e[38;5;116mDEBG",
+		.c256_background = 238,
+		.c256_formatarg = 195,
+	},
+};
+/* clang-format on */
+
+static void vtysh_log_print(struct vtysh_client *vclient,
+			    struct zlog_live_hdr *hdr, const char *text)
+{
+	size_t textlen = hdr->textlen, textpos = 0;
+	time_t ts = hdr->ts_sec;
+	struct visual_prio *vis;
+	struct tm tm;
+	char ts_buf[32];
+
+	if (hdr->prio > array_size(visual_prios))
+		vis = &visual_prios[LOG_CRIT];
+	else
+		vis = &visual_prios[hdr->prio];
+
+	localtime_r(&ts, &tm);
+	strftime(ts_buf, sizeof(ts_buf), "%Y-%m-%d %H:%M:%S", &tm);
+
+	if (!stderr_tty) {
+		const char *label = vis->label + strlen(vis->label) - 4;
+
+		fprintf(stderr, "%s.%03u [%s] %s: %.*s\n", ts_buf,
+			hdr->ts_nsec / 1000000U, label, vclient->name,
+			(int)textlen, text);
+		return;
+	}
+
+	fprintf(stderr,
+		"\e[48;5;%dm\e[38;5;247m%s.%03u [%s\e[38;5;247m] \e[38;5;255m%s\e[38;5;247m: \e[38;5;251m",
+		vis->c256_background, ts_buf, hdr->ts_nsec / 1000000U,
+		vis->label, vclient->name);
+
+	for (size_t fmtpos = 0; fmtpos < hdr->n_argpos; fmtpos++) {
+		struct fmt_outpos *fmt = &hdr->argpos[fmtpos];
+
+		if (fmt->off_start < textpos || fmt->off_end < fmt->off_start ||
+		    fmt->off_end > textlen)
+			continue;
+
+		while (fmt->off_end > fmt->off_start &&
+		       text[fmt->off_end - 1] == ' ')
+			fmt->off_end--;
+
+		fprintf(stderr, "%.*s\e[38;5;%dm%.*s\e[38;5;251m",
+			(int)(fmt->off_start - textpos), text + textpos,
+			vis->c256_formatarg,
+			(int)(fmt->off_end - fmt->off_start),
+			text + fmt->off_start);
+		textpos = fmt->off_end;
+	}
+	fprintf(stderr, "%.*s\033[K\033[m\n", (int)(textlen - textpos),
+		text + textpos);
+}
+
+static void vtysh_log_read(struct thread *thread)
+{
+	struct vtysh_client *vclient = THREAD_ARG(thread);
+	struct {
+		struct zlog_live_hdr hdr;
+		char text[4096];
+	} buf;
+	const char *text;
+	ssize_t ret;
+
+	thread_add_read(master, vtysh_log_read, vclient, vclient->log_fd,
+			&vclient->log_reader);
+
+	ret = recv(vclient->log_fd, &buf, sizeof(buf), 0);
+
+	if (ret < 0 && ERRNO_IO_RETRY(errno))
+		return;
+
+	if (ret <= 0) {
+		struct timespec ts;
+
+		if (ret != 0)
+			snprintfrr(buf.text, sizeof(buf.text),
+				   "log monitor connection error: %m");
+		else
+			snprintfrr(
+				buf.text, sizeof(buf.text),
+				"log monitor connection closed unexpectedly");
+		buf.hdr.textlen = strlen(buf.text);
+
+		THREAD_OFF(vclient->log_reader);
+		close(vclient->log_fd);
+		vclient->log_fd = -1;
+
+		clock_gettime(CLOCK_REALTIME, &ts);
+		buf.hdr.ts_sec = ts.tv_sec;
+		buf.hdr.ts_nsec = ts.tv_nsec;
+		buf.hdr.prio = LOG_ERR;
+		buf.hdr.flags = 0;
+		buf.hdr.arghdrlen = 0;
+		buf.hdr.n_argpos = 0;
+	}
+
+	if (stderr_stdout_same) {
+#ifdef HAVE_RL_CLEAR_VISIBLE_LINE
+		rl_clear_visible_line();
+#else
+		puts("\r");
+#endif
+		fflush(stdout);
+	}
+
+	text = buf.text + sizeof(buf.hdr.argpos[0]) * buf.hdr.n_argpos;
+	vtysh_log_print(vclient, &buf.hdr, text);
+
+	if (stderr_stdout_same)
+		rl_forced_update_display();
+
+	return;
+}
+
+#ifdef CLIPPY
+/* clippy/clidef can't process the DEFPY below without some value for this */
+#define DAEMONS_LIST "daemon"
+#endif
+
+DEFPY (vtysh_terminal_monitor,
+       vtysh_terminal_monitor_cmd,
+       "terminal monitor ["DAEMONS_LIST"]$daemon",
+       "Set terminal line parameters\n"
+       "Receive log messages to active VTY session\n"
+       DAEMONS_STR)
+{
+	static const char line[] = "terminal monitor\n";
+	int ret_all = CMD_SUCCESS, ret, fd;
+	size_t i, ok = 0;
+
+	for (i = 0; i < array_size(vtysh_client); i++) {
+		struct vtysh_client *vclient = &vtysh_client[i];
+
+		if (daemon && strcmp(vclient->name, daemon))
+			continue;
+
+		for (; vclient; vclient = vclient->next) {
+			if (vclient->log_fd != -1) {
+				vty_out(vty, "%% %s: already monitoring logs\n",
+					vclient->name);
+				ok++;
+				continue;
+			}
+
+			fd = -1;
+			ret = vtysh_client_run(vclient, line, NULL, NULL, &fd);
+			if (fd != -1) {
+				set_nonblocking(fd);
+				vclient->log_fd = fd;
+				thread_add_read(master, vtysh_log_read, vclient,
+						vclient->log_fd,
+						&vclient->log_reader);
+			}
+			if (ret != CMD_SUCCESS) {
+				vty_out(vty, "%% failed to enable logs on %s\n",
+					vclient->name);
+				ret_all = CMD_WARNING;
+			} else
+				ok++;
+		}
+	}
+
+	if (!ok && ret_all == CMD_SUCCESS) {
+		vty_out(vty,
+			"%% command had no effect, relevant daemons not connected?\n");
+		ret_all = CMD_WARNING;
+	}
+	return ret_all;
+}
+
+DEFPY (no_vtysh_terminal_monitor,
+       no_vtysh_terminal_monitor_cmd,
+       "no terminal monitor ["DAEMONS_LIST"]$daemon",
+       NO_STR
+       "Set terminal line parameters\n"
+       "Receive log messages to active VTY session\n"
+       DAEMONS_STR)
+{
+	static const char line[] = "no terminal monitor\n";
+	int ret_all = CMD_SUCCESS, ret;
+	size_t i, ok = 0;
+
+	for (i = 0; i < array_size(vtysh_client); i++) {
+		struct vtysh_client *vclient = &vtysh_client[i];
+
+		if (daemon && strcmp(vclient->name, daemon))
+			continue;
+
+		for (; vclient; vclient = vclient->next) {
+			/* run this even if log_fd == -1, in case something
+			 * got desync'd
+			 */
+			ret = vtysh_client_run(vclient, line, NULL, NULL, NULL);
+			if (ret != CMD_SUCCESS) {
+				vty_out(vty,
+					"%% failed to disable logs on %s\n",
+					vclient->name);
+				ret_all = CMD_WARNING;
+			} else
+				ok++;
+
+			/* with this being a datagram socket, we can't expect
+			 * a close notification...
+			 */
+			if (vclient->log_fd != -1) {
+				THREAD_OFF(vclient->log_reader);
+
+				close(vclient->log_fd);
+				vclient->log_fd = -1;
+			}
+		}
+	}
+
+	if (!ok && ret_all == CMD_SUCCESS) {
+		vty_out(vty,
+			"%% command had no effect, relevant daemons not connected?\n");
+		ret_all = CMD_WARNING;
+	}
+	return ret_all;
+}
+
+
 /* Execute command in child process. */
 static void execute_command(const char *command, int argc, const char *arg1,
 			    const char *arg2)
@@ -4019,8 +4302,21 @@ void vtysh_uninit(void)
 
 void vtysh_init_vty(void)
 {
+	struct stat st_out, st_err;
+
 	cmd_defer_tree(true);
 
+	for (size_t i = 0; i < array_size(vtysh_client); i++) {
+		vtysh_client[i].fd = -1;
+		vtysh_client[i].log_fd = -1;
+	}
+
+	stderr_tty = isatty(STDERR_FILENO);
+
+	if (fstat(STDOUT_FILENO, &st_out) || fstat(STDERR_FILENO, &st_err) ||
+	    (st_out.st_dev == st_err.st_dev && st_out.st_ino == st_err.st_ino))
+		stderr_stdout_same = true;
+
 	/* Make vty structure. */
 	vty = vty_new();
 	vty->type = VTY_SHELL;
@@ -4514,6 +4810,9 @@ void vtysh_init_vty(void)
 	install_element(VIEW_NODE, &vtysh_terminal_no_length_cmd);
 	install_element(VIEW_NODE, &vtysh_show_daemons_cmd);
 
+	install_element(VIEW_NODE, &vtysh_terminal_monitor_cmd);
+	install_element(VIEW_NODE, &no_vtysh_terminal_monitor_cmd);
+
 	install_element(VIEW_NODE, &vtysh_ping_cmd);
 	install_element(VIEW_NODE, &vtysh_ping_ip_cmd);
 	install_element(VIEW_NODE, &vtysh_traceroute_cmd);
diff --git a/vtysh/vtysh.h b/vtysh/vtysh.h
index 8fb85293e5..6053955be9 100644
--- a/vtysh/vtysh.h
+++ b/vtysh/vtysh.h
@@ -24,6 +24,10 @@
 #include "memory.h"
 DECLARE_MGROUP(MVTYSH);
 
+struct thread_master;
+
+extern struct thread_master *master;
+
 #define VTYSH_ZEBRA     0x00001
 #define VTYSH_RIPD      0x00002
 #define VTYSH_RIPNGD    0x00004