Merge pull request #15515 from opensourcerouting/zlog-recirculate-ldpd

ldpd, lib: integrate lde/ldpe into standard logging infrastructure

ldpd/lde.c

@@ -28,6 +28,7 @@
 #include "stream.h"
 #include "network.h"
 #include "libfrr.h"
+#include "zlog_live.h"
 
 static void		 lde_shutdown(void);
 static void lde_dispatch_imsg(struct event *thread);
@@ -116,6 +117,8 @@ static struct frr_signal_t lde_signals[] =
 void
 lde(void)
 {
+	static struct zlog_live_cfg child_log;
+
 #ifdef HAVE_SETPROCTITLE
 	setproctitle("label decision engine");
 #endif
@@ -123,6 +126,8 @@ lde(void)
 	log_procname = log_procnames[PROC_LDE_ENGINE];
 
 	master = frr_init();
+	zlog_live_open_fd(&child_log, LOG_DEBUG, LDPD_FD_LOG);
+
 	/* no frr_config_fork() here, allow frr_pthread to create threads */
 	frr_is_after_fork = true;
 

ldpd/ldpd.c

@@ -35,9 +35,10 @@
 #include "qobj.h"
 #include "libfrr.h"
 #include "lib_errors.h"
+#include "zlog_recirculate.h"
 
 static void		 ldpd_shutdown(void);
-static pid_t		 start_child(enum ldpd_process, char *, int, int);
+static pid_t		 start_child(enum ldpd_process, char *, int, int, int);
 static void main_dispatch_ldpe(struct event *thread);
 static void main_dispatch_lde(struct event *thread);
 static int		 main_imsg_send_ipc_sockets(struct imsgbuf *,
@@ -69,6 +70,8 @@ DEFINE_QOBJ_TYPE(l2vpn_pw);
 DEFINE_QOBJ_TYPE(l2vpn);
 DEFINE_QOBJ_TYPE(ldpd_conf);
 
+const char		*log_procname;
+
 struct ldpd_global	 global;
 struct ldpd_init	 init;
 struct ldpd_conf	*ldpd_conf, *vty_conf;
@@ -231,8 +234,12 @@ main(int argc, char *argv[])
 {
 	char			*saved_argv0;
 	int			 lflag = 0, eflag = 0;
-	int			 pipe_parent2ldpe[2], pipe_parent2ldpe_sync[2];
-	int			 pipe_parent2lde[2], pipe_parent2lde_sync[2];
+	int			 pipe_parent2ldpe[2];
+	int			 pipe_parent2ldpe_sync[2];
+	int			 pipe_ldpe_log[2];
+	int			 pipe_parent2lde[2];
+	int			 pipe_parent2lde_sync[2];
+	int			 pipe_lde_log[2];
 	bool                    ctl_sock_used = false;
 
 	ldpd_process = PROC_MAIN;
@@ -300,15 +307,6 @@ main(int argc, char *argv[])
 		exit(1);
 	}
 
-	if (lflag || eflag) {
-		struct zprivs_ids_t ids;
-
-		zprivs_preinit(&ldpd_privs);
-		zprivs_get_ids(&ids);
-
-		zlog_init(ldpd_di.progname, "LDP", 0,
-			  ids.uid_normal, ids.gid_normal);
-	}
 	if (lflag)
 		lde();
 	else if (eflag)
@@ -321,6 +319,9 @@ main(int argc, char *argv[])
 	    pipe_parent2ldpe_sync) == -1)
 		fatal("socketpair");
 
+	if (socketpair(AF_UNIX, SOCK_DGRAM, PF_UNSPEC, pipe_ldpe_log) == -1)
+		fatal("socketpair");
+
 	if (socketpair(AF_UNIX, SOCK_STREAM, PF_UNSPEC, pipe_parent2lde) == -1)
 		fatal("socketpair");
 
@@ -328,6 +329,9 @@ main(int argc, char *argv[])
 	    pipe_parent2lde_sync) == -1)
 		fatal("socketpair");
 
+	if (socketpair(AF_UNIX, SOCK_DGRAM, PF_UNSPEC, pipe_lde_log) == -1)
+		fatal("socketpair");
+
 	sock_set_nonblock(pipe_parent2ldpe[0]);
 	sock_set_cloexec(pipe_parent2ldpe[0]);
 	sock_set_nonblock(pipe_parent2ldpe[1]);
@@ -335,6 +339,11 @@ main(int argc, char *argv[])
 	sock_set_nonblock(pipe_parent2ldpe_sync[0]);
 	sock_set_cloexec(pipe_parent2ldpe_sync[0]);
 	sock_set_cloexec(pipe_parent2ldpe_sync[1]);
+	sock_set_nonblock(pipe_ldpe_log[0]);
+	sock_set_cloexec(pipe_ldpe_log[0]);
+	sock_set_nonblock(pipe_ldpe_log[1]);
+	sock_set_cloexec(pipe_ldpe_log[1]);
+
 	sock_set_nonblock(pipe_parent2lde[0]);
 	sock_set_cloexec(pipe_parent2lde[0]);
 	sock_set_nonblock(pipe_parent2lde[1]);
@@ -342,14 +351,24 @@ main(int argc, char *argv[])
 	sock_set_nonblock(pipe_parent2lde_sync[0]);
 	sock_set_cloexec(pipe_parent2lde_sync[0]);
 	sock_set_cloexec(pipe_parent2lde_sync[1]);
+	sock_set_nonblock(pipe_lde_log[0]);
+	sock_set_cloexec(pipe_lde_log[0]);
+	sock_set_nonblock(pipe_lde_log[1]);
+	sock_set_cloexec(pipe_lde_log[1]);
 
 	/* start children */
 	lde_pid = start_child(PROC_LDE_ENGINE, saved_argv0,
-	    pipe_parent2lde[1], pipe_parent2lde_sync[1]);
+	    pipe_parent2lde[1], pipe_parent2lde_sync[1], pipe_lde_log[1]);
 	ldpe_pid = start_child(PROC_LDP_ENGINE, saved_argv0,
-	    pipe_parent2ldpe[1], pipe_parent2ldpe_sync[1]);
+	    pipe_parent2ldpe[1], pipe_parent2ldpe_sync[1], pipe_ldpe_log[1]);
 
 	master = frr_init();
+	/* The two child processes use the zlog_live backend to send their
+	 * messages here, where the actual logging config is then applied.
+	 * Look for zlog_live_open_fd() to find the other end of this.
+	 */
+	zlog_recirculate_subscribe(master, pipe_lde_log[0]);
+	zlog_recirculate_subscribe(master, pipe_ldpe_log[0]);
 
 	vrf_init(NULL, NULL, NULL, NULL);
 	access_list_init();
@@ -484,7 +503,8 @@ ldpd_shutdown(void)
 }
 
 static pid_t
-start_child(enum ldpd_process p, char *argv0, int fd_async, int fd_sync)
+start_child(enum ldpd_process p, char *argv0, int fd_async, int fd_sync,
+	    int fd_log)
 {
 	char	*argv[7];
 	int	 argc = 0, nullfd;
@@ -499,6 +519,7 @@ start_child(enum ldpd_process p, char *argv0, int fd_async, int fd_sync)
 	default:
 		close(fd_async);
 		close(fd_sync);
+		close(fd_log);
 		return (pid);
 	}
 
@@ -520,6 +541,9 @@ start_child(enum ldpd_process p, char *argv0, int fd_async, int fd_sync)
 	if (dup2(fd_sync, LDPD_FD_SYNC) == -1)
 		fatal("cannot setup imsg sync fd");
 
+	if (dup2(fd_log, LDPD_FD_LOG) == -1)
+		fatal("cannot setup zlog fd");
+
 	argv[argc++] = argv0;
 	switch (p) {
 	case PROC_MAIN:
@@ -569,9 +593,6 @@ static void main_dispatch_ldpe(struct event *thread)
 			break;
 
 		switch (imsg.hdr.type) {
-		case IMSG_LOG:
-			logit(imsg.hdr.pid, "%s", (const char *)imsg.data);
-			break;
 		case IMSG_REQUEST_SOCKETS:
 			af = imsg.hdr.pid;
 			main_imsg_send_net_sockets(af);
@@ -637,9 +658,6 @@ static void main_dispatch_lde(struct event *thread)
 			break;
 
 		switch (imsg.hdr.type) {
-		case IMSG_LOG:
-			logit(imsg.hdr.pid, "%s", (const char *)imsg.data);
-			break;
 		case IMSG_KLABEL_CHANGE:
 			if (imsg.hdr.len - IMSG_HEADER_SIZE !=
 			    sizeof(struct kroute))

ldpd/ldpd.h

@@ -30,6 +30,7 @@
 
 #define LDPD_FD_ASYNC		3
 #define LDPD_FD_SYNC		4
+#define LDPD_FD_LOG		5
 
 #define LDPD_OPT_VERBOSE	0x00000001
 #define LDPD_OPT_VERBOSE2	0x00000002
@@ -139,7 +140,6 @@ enum imsg_type {
 	IMSG_RECONF_L2VPN_IPW,
 	IMSG_RECONF_END,
 	IMSG_DEBUG_UPDATE,
-	IMSG_LOG,
 	IMSG_ACL_CHECK,
 	IMSG_INIT,
 	IMSG_PW_UPDATE,

ldpd/ldpe.c

@@ -23,6 +23,7 @@
 #include "privs.h"
 #include "sigevent.h"
 #include "libfrr.h"
+#include "zlog_live.h"
 
 static void	 ldpe_shutdown(void);
 static void ldpe_dispatch_main(struct event *thread);
@@ -93,6 +94,8 @@ char *pkt_ptr; /* packet buffer */
 void
 ldpe(void)
 {
+	static struct zlog_live_cfg child_log;
+
 #ifdef HAVE_SETPROCTITLE
 	setproctitle("ldp engine");
 #endif
@@ -100,6 +103,8 @@ ldpe(void)
 	log_procname = log_procnames[ldpd_process];
 
 	master = frr_init();
+	zlog_live_open_fd(&child_log, LOG_DEBUG, LDPD_FD_LOG);
+
 	/* no frr_config_fork() here, allow frr_pthread to create threads */
 	frr_is_after_fork = true;
 

ldpd/log.c

@@ -1,138 +0,0 @@
-// SPDX-License-Identifier: ISC
-/*	$OpenBSD$ */
-
-/*
- * Copyright (c) 2003, 2004 Henning Brauer <henning@openbsd.org>
- */
-
-#include <zebra.h>
-
-#include "ldpd.h"
-#include "ldpe.h"
-#include "lde.h"
-#include "log.h"
-#include "printfrr.h"
-
-#include <lib/log.h>
-
-const char	*log_procname;
-
-void
-logit(int pri, const char *fmt, ...)
-{
-	va_list	ap;
-
-	va_start(ap, fmt);
-	vlog(pri, fmt, ap);
-	va_end(ap);
-}
-
-void
-vlog(int pri, const char *fmt, va_list ap)
-{
-	char	 buf[1024];
-
-	switch (ldpd_process) {
-	case PROC_LDE_ENGINE:
-		vsnprintfrr(buf, sizeof(buf), fmt, ap);
-		lde_imsg_compose_parent_sync(IMSG_LOG, pri, buf, strlen(buf) + 1);
-		break;
-	case PROC_LDP_ENGINE:
-		vsnprintfrr(buf, sizeof(buf), fmt, ap);
-		ldpe_imsg_compose_parent_sync(IMSG_LOG, pri, buf, strlen(buf) + 1);
-		break;
-	case PROC_MAIN:
-		vzlog(pri, fmt, ap);
-		break;
-	}
-}
-
-void
-log_warn(const char *emsg, ...)
-{
-	char	*nfmt;
-	va_list	 ap;
-
-	/* best effort to even work in out of memory situations */
-	if (emsg == NULL)
-		logit(LOG_ERR, "%s", strerror(errno));
-	else {
-		va_start(ap, emsg);
-
-		if (asprintf(&nfmt, "%s: %s", emsg, strerror(errno)) == -1) {
-			/* we tried it... */
-			vlog(LOG_ERR, emsg, ap);
-			logit(LOG_ERR, "%s", strerror(errno));
-		} else {
-#pragma GCC diagnostic push
-#pragma GCC diagnostic ignored "-Wformat-nonliteral"
-			/* format extended above */
-			vlog(LOG_ERR, nfmt, ap);
-#pragma GCC diagnostic pop
-			free(nfmt);
-		}
-		va_end(ap);
-	}
-}
-
-void
-log_warnx(const char *emsg, ...)
-{
-	va_list	 ap;
-
-	va_start(ap, emsg);
-	vlog(LOG_ERR, emsg, ap);
-	va_end(ap);
-}
-
-void
-log_info(const char *emsg, ...)
-{
-	va_list	 ap;
-
-	va_start(ap, emsg);
-	vlog(LOG_INFO, emsg, ap);
-	va_end(ap);
-}
-
-void
-log_notice(const char *emsg, ...)
-{
-	va_list	 ap;
-
-	va_start(ap, emsg);
-	vlog(LOG_NOTICE, emsg, ap);
-	va_end(ap);
-}
-
-void
-log_debug(const char *emsg, ...)
-{
-	va_list	 ap;
-
-	va_start(ap, emsg);
-	vlog(LOG_DEBUG, emsg, ap);
-	va_end(ap);
-}
-
-void
-fatal(const char *emsg)
-{
-	if (emsg == NULL)
-		logit(LOG_CRIT, "fatal in %s: %s", log_procname, strerror(errno));
-	else
-		if (errno)
-			logit(LOG_CRIT, "fatal in %s: %s: %s",
-			    log_procname, emsg, strerror(errno));
-		else
-			logit(LOG_CRIT, "fatal in %s: %s", log_procname, emsg);
-
-	exit(1);
-}
-
-void
-fatalx(const char *emsg)
-{
-	errno = 0;
-	fatal(emsg);
-}

ldpd/log.h

@@ -8,29 +8,30 @@
 #ifndef LOG_H
 #define LOG_H
 
-#include <stdarg.h>
+#include "log.h"
+#include "assert.h"
 
 extern const char	*log_procname;
 
-void	 logit(int, const char *, ...)
-		__attribute__((__format__ (printf, 2, 3)));
-void	 vlog(int, const char *, va_list)
-		__attribute__((__format__ (printf, 2, 0)));
-void	 log_warn(const char *, ...)
-		__attribute__((__format__ (printf, 1, 2)));
-void	 log_warnx(const char *, ...)
-		__attribute__((__format__ (printf, 1, 2)));
-void	 log_info(const char *, ...)
-		__attribute__((__format__ (printf, 1, 2)));
-void	 log_notice(const char *, ...)
-		__attribute__((__format__ (printf, 1, 2)));
-void	 log_debug(const char *, ...)
-		__attribute__((__format__ (printf, 1, 2)));
-void	 fatal(const char *)
-		__attribute__ ((noreturn))
-		__attribute__((__format__ (printf, 1, 0)));
-void	 fatalx(const char *)
-		__attribute__ ((noreturn))
-		__attribute__((__format__ (printf, 1, 0)));
+#define log_warnx	zlog_err	/* yes this is poorly named */
+#define log_warn	zlog_warn
+#define log_info	zlog_info
+#define log_notice	zlog_notice	/* not used anywhere */
+#define log_debug	zlog_debug
+
+#define fatal(msg)                                                             \
+	do {                                                                   \
+		assertf(0, "fatal in %s: %pSQq (%m)", log_procname,            \
+			(const char *)msg);                                    \
+		__builtin_unreachable();                                       \
+	} while (0)                                                            \
+	/* end */
+#define fatalx(msg)                                                            \
+	do {                                                                   \
+		assertf(0, "fatal in %s: %pSQq", log_procname,                 \
+			(const char *)msg);                                    \
+		__builtin_unreachable();                                       \
+	} while (0)                                                            \
+	/* end */
 
 #endif /* LOG_H */

ldpd/subdir.am

@@ -28,7 +28,6 @@ ldpd_libldp_a_SOURCES = \
 	ldpd/ldp_vty_exec.c \
 	ldpd/ldp_zebra.c \
 	ldpd/ldpe.c \
-	ldpd/log.c \
 	ldpd/logmsg.c \
 	ldpd/neighbor.c \
 	ldpd/notification.c \

lib/subdir.am

@@ -131,6 +131,7 @@ lib_libfrr_la_SOURCES = \
 	lib/zlog_5424.c \
 	lib/zlog_5424_cli.c \
 	lib/zlog_live.c \
+	lib/zlog_recirculate.c \
 	lib/zlog_targets.c \
 	lib/printf/printf-pos.c \
 	lib/printf/vfprintf.c \
@@ -329,6 +330,7 @@ pkginclude_HEADERS += \
 	lib/zlog.h \
 	lib/zlog_5424.h \
 	lib/zlog_live.h \
+	lib/zlog_recirculate.h \
 	lib/zlog_targets.h \
 	lib/pbr.h \
 	lib/tc.h \

lib/zlog.c

@@ -50,6 +50,7 @@
 #include "printfrr.h"
 #include "frrcu.h"
 #include "zlog.h"
+#include "zlog_live.h"
 #include "libfrr_trace.h"
 #include "frrevent.h"
 
@@ -109,6 +110,9 @@ struct zlog_msg {
 	size_t textlen;
 	size_t hdrlen;
 
+	/* for relayed log messages ONLY (cf. zlog_recirculate_live_msg) */
+	intmax_t pid, tid;
+
 	/* This is always ISO8601 with sub-second precision 9 here, it's
 	 * converted for callers as needed.  ts_dot points to the "."
 	 * separating sub-seconds.  ts_zonetail is "Z" or "+00:00" for the
@@ -357,6 +361,16 @@ void zlog_msg_pid(struct zlog_msg *msg, intmax_t *pid, intmax_t *tid)
 {
 #ifndef __OpenBSD__
 	static thread_local intmax_t cached_pid = -1;
+#endif
+
+	/* recirculated messages */
+	if (msg->pid) {
+		*pid = msg->pid;
+		*tid = msg->tid;
+		return;
+	}
+
+#ifndef __OpenBSD__
 	if (cached_pid != -1)
 		*pid = cached_pid;
 	else
@@ -507,6 +521,89 @@ static void vzlog_tls(struct zlog_tls *zlog_tls, const struct xref_logmsg *xref,
 		XFREE(MTYPE_LOG_MESSAGE, msg->text);
 }
 
+/* reinject log message received by zlog_recirculate_recv().  As of writing,
+ * only used in the ldpd parent process to proxy messages from lde/ldpe
+ * subprocesses.
+ */
+void zlog_recirculate_live_msg(uint8_t *data, size_t len)
+{
+	struct zlog_target *zt;
+	struct zlog_msg stackmsg = {}, *msg = &stackmsg;
+	struct zlog_live_hdr *hdr;
+	struct xrefdata *xrefdata, ref = {};
+
+	if (len < sizeof(*hdr))
+		return;
+
+	hdr = (struct zlog_live_hdr *)data;
+	if (hdr->hdrlen < sizeof(*hdr))
+		return;
+	data += hdr->hdrlen;
+	len -= sizeof(*hdr);
+
+	msg->ts.tv_sec = hdr->ts_sec;
+	msg->ts.tv_nsec = hdr->ts_nsec;
+	msg->pid = hdr->pid;
+	msg->tid = hdr->tid;
+	msg->prio = hdr->prio;
+
+	if (hdr->textlen > len)
+		return;
+	msg->textlen = hdr->textlen;
+	msg->hdrlen = hdr->texthdrlen;
+	msg->text = (char *)data;
+
+	/* caller needs to make sure we have a trailing \n\0, it's not
+	 * transmitted on zlog_live
+	 */
+	if (msg->text[msg->textlen] != '\n' ||
+	    msg->text[msg->textlen + 1] != '\0')
+		return;
+
+	static_assert(sizeof(msg->argpos[0]) == sizeof(hdr->argpos[0]),
+		      "in-memory struct doesn't match on-wire variant");
+	msg->n_argpos = MIN(hdr->n_argpos, array_size(msg->argpos));
+	memcpy(msg->argpos, hdr->argpos, msg->n_argpos * sizeof(msg->argpos[0]));
+
+	/* This will only work if we're in the same daemon: we received a log
+	 * message uid and are now doing a lookup in *our* known uids to find
+	 * it.  This works for ldpd because it's the same binary containing the
+	 * same log messages, and ldpd is the only use case right now.
+	 *
+	 * When the uid is not found, the log message uid is lost but the
+	 * message itself is still processed correctly.  If this is needed,
+	 * this can be made to work in two ways:
+	 * (a) synthesize a temporary xref_logmsg from the received data.
+	 *     This is a bit annoying due to lifetimes with per-thread buffers.
+	 * (b) extract and aggregate all log messages.  This already happens
+	 *     with frr.xref but that would need to be fed back in.
+	 */
+	strlcpy(ref.uid, hdr->uid, sizeof(ref.uid));
+	xrefdata = xrefdata_uid_find(&xrefdata_uid, &ref);
+
+	if (xrefdata && xrefdata->xref->type == XREFT_LOGMSG) {
+		struct xref_logmsg *xref_logmsg;
+
+		xref_logmsg = (struct xref_logmsg *)xrefdata->xref;
+		msg->xref = xref_logmsg;
+		msg->fmt = xref_logmsg->fmtstring;
+	} else {
+		/* fake out format string... */
+		msg->fmt = msg->text + hdr->texthdrlen;
+	}
+
+	rcu_read_lock();
+	frr_each_safe (zlog_targets, &zlog_targets, zt) {
+		if (msg->prio > zt->prio_min)
+			continue;
+		if (!zt->logfn)
+			continue;
+
+		zt->logfn(zt, &msg, 1);
+	}
+	rcu_read_unlock();
+}
+
 static void zlog_backtrace_msg(const struct xref_logmsg *xref, int prio)
 {
 	struct event *tc = pthread_getspecific(thread_current);

lib/zlog.h

@@ -125,6 +125,9 @@ static inline void zlog_ref(const struct xref_logmsg *xref,
 
 extern void zlog_sigsafe(const char *text, size_t len);
 
+/* recirculate a log message from zlog_live */
+extern void zlog_recirculate_live_msg(uint8_t *data, size_t len);
+
 /* extra priority value to disable a target without deleting it */
 #define ZLOG_DISABLED	(LOG_EMERG-1)
 

lib/zlog_recirculate.c

@@ -0,0 +1,56 @@
+// SPDX-License-Identifier: ISC
+/*
+ * Copyright (c) 2024  David Lamparter, for NetDEF, Inc.
+ */
+
+#include "zebra.h"
+
+#include "log.h"
+#include "frrevent.h"
+
+#include "zlog_recirculate.h"
+
+/* This is only the event loop part;  it's split off from
+ * zlog_recirculate_live_msg since there's an integration boundary;  this
+ * half deals with events, the other half with zlog interna.
+ *
+ * As of writing, this runs in ldpd in the *parent* process and receives log
+ * messages from the lde/ldpe subprocesses.  It is not used anywhere else
+ * (yet?)
+ */
+static void zlog_recirculate_recv(struct event *ev)
+{
+	uint8_t rxbuf[4096];
+	ssize_t n_rd;
+	int fd = EVENT_FD(ev);
+
+	/* see below for -2, "\n\0" are added */
+	n_rd = read(fd, rxbuf, sizeof(rxbuf) - 2);
+	if (n_rd == 0) {
+		/* EOF */
+		close(fd);
+		/* event_add_read not called yet, nothing to cancel */
+		return;
+	}
+	if (n_rd < 0 && (errno != EAGAIN) && (errno != EWOULDBLOCK)) {
+		/* error */
+		zlog_warn("error on log relay socket %d: %m", fd);
+		close(fd);
+		/* event_add_read not called yet, nothing to cancel */
+		return;
+	}
+
+	event_add_read(ev->master, zlog_recirculate_recv, NULL, fd, NULL);
+	if (n_rd < 0)
+		return;
+
+	/* log infrastructure has an implicit \n\0 at the end */
+	rxbuf[n_rd] = '\n';
+	rxbuf[n_rd + 1] = '\0';
+	zlog_recirculate_live_msg(rxbuf, n_rd);
+}
+
+void zlog_recirculate_subscribe(struct event_loop *el, int fd)
+{
+	event_add_read(el, zlog_recirculate_recv, NULL, fd, NULL);
+}

lib/zlog_recirculate.h

@@ -0,0 +1,12 @@
+// SPDX-License-Identifier: ISC
+/*
+ * Copyright (c) 2024  David Lamparter, for NetDEF, Inc.
+ */
+
+#ifndef _FRR_ZLOG_RECIRCULATE_H
+#define _FRR_ZLOG_RECIRCULATE_H
+
+/* fd should be one end of a socketpair() */
+extern void zlog_recirculate_subscribe(struct event_loop *tm, int fd);
+
+#endif