diff --git a/ldpd/lde.c b/ldpd/lde.c index ef4aecadadec..876dd4163099 100644 --- a/ldpd/lde.c +++ b/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; diff --git a/ldpd/ldpd.c b/ldpd/ldpd.c index da29a4f20ddf..492a36b3d6a1 100644 --- a/ldpd/ldpd.c +++ b/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)) diff --git a/ldpd/ldpd.h b/ldpd/ldpd.h index 81c6ba3ccd57..ad831a6ea358 100644 --- a/ldpd/ldpd.h +++ b/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, diff --git a/ldpd/ldpe.c b/ldpd/ldpe.c index e66b9e92dd43..6e844c0aa18d 100644 --- a/ldpd/ldpe.c +++ b/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; diff --git a/ldpd/log.c b/ldpd/log.c deleted file mode 100644 index 7c4d782dcfaa..000000000000 --- a/ldpd/log.c +++ /dev/null @@ -1,138 +0,0 @@ -// SPDX-License-Identifier: ISC -/* $OpenBSD$ */ - -/* - * Copyright (c) 2003, 2004 Henning Brauer - */ - -#include - -#include "ldpd.h" -#include "ldpe.h" -#include "lde.h" -#include "log.h" -#include "printfrr.h" - -#include - -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); -} diff --git a/ldpd/log.h b/ldpd/log.h index 641ad8ac5edb..aa6f700608a7 100644 --- a/ldpd/log.h +++ b/ldpd/log.h @@ -8,29 +8,30 @@ #ifndef LOG_H #define LOG_H -#include +#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 */ diff --git a/ldpd/subdir.am b/ldpd/subdir.am index 0b948adb6fc2..ad5933fec363 100644 --- a/ldpd/subdir.am +++ b/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 \ diff --git a/lib/subdir.am b/lib/subdir.am index db11def74197..c621ad06584e 100644 --- a/lib/subdir.am +++ b/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 \ diff --git a/lib/zlog.c b/lib/zlog.c index 8734fd55af3e..ffca5726095b 100644 --- a/lib/zlog.c +++ b/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); diff --git a/lib/zlog.h b/lib/zlog.h index 27401d51fb13..9d9397995778 100644 --- a/lib/zlog.h +++ b/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) diff --git a/lib/zlog_recirculate.c b/lib/zlog_recirculate.c new file mode 100644 index 000000000000..abc73eeed007 --- /dev/null +++ b/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); +} diff --git a/lib/zlog_recirculate.h b/lib/zlog_recirculate.h new file mode 100644 index 000000000000..a2ddb4e172d0 --- /dev/null +++ b/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