// SPDX-License-Identifier: ISC /* * Copyright (c) 2015-21 David Lamparter, for NetDEF, Inc. */ /* when you work on this code, please install a fuzzer (e.g. AFL) and run * tests/lib/fuzz_zlog.c * * The most likely type of bug in this code is an off-by-one error in the * buffer management pieces, and this isn't easily covered by an unit test * or topotests. Fuzzing is the best tool here, but the CI can't do that * since it's quite resource intensive. */ #include "zebra.h" #include #include "frrsendmmsg.h" #include "zlog_5424.h" #include #include #include "memory.h" #include "frrcu.h" #include "printfrr.h" #include "typerb.h" #include "frr_pthread.h" #include "command.h" #include "monotime.h" #include "frrevent.h" #include "lib/version.h" #include "lib/lib_errors.h" DEFINE_MTYPE_STATIC(LOG, LOG_5424, "extended log target"); DEFINE_MTYPE_STATIC(LOG, LOG_5424_ROTATE, "extended log rotate helper"); /* the actual log target data structure * * remember this is RCU'd by the core zlog functions. Changing anything * works by allocating a new struct, filling it, adding it, and removing the * old one. */ struct zlt_5424 { struct zlog_target zt; atomic_uint_fast32_t fd; enum zlog_5424_format fmt; uint32_t ts_flags; int facility; /* the various extra pieces to add... */ bool kw_version : 1; bool kw_location : 1; bool kw_uid : 1; bool kw_ec : 1; bool kw_args : 1; /* some formats may or may not include the trailing \n */ bool use_nl : 1; /* for DGRAM & SEQPACKET sockets, send 1 log message per packet, since * the socket preserves packet boundaries. On Linux, this uses * sendmmsg() for efficiency, on other systems we need a syscall each. */ bool packets : 1; /* for DGRAM, in order to not have to reconnect, we need to use * sendto()/sendmsg() with the destination given; otherwise we'll get * ENOTCONN. (We do a connect(), which serves to verify the type of * socket, but if the receiver goes away, the kernel disconnects the * socket so writev() no longer works since the destination is now * unspecified.) */ struct sockaddr_storage sa; socklen_t sa_len; /* these are both getting set, but current_err is cleared on success, * so we know whether the error is current or past. */ int last_err, current_err; atomic_size_t lost_msgs; struct timeval last_err_ts; struct rcu_head_close head_close; }; static int zlog_5424_open(struct zlog_cfg_5424 *zcf, int sock_type); /* rough header length estimate * ============================ * * ^ = might grow * * 49^ longest filename (pceplib/test/pcep_utils_double_linked_list_test.h) * 5^ highest line number (48530, bgpd/bgp_nb_config.c) * 65^ longest function name * (lib_prefix_list_entry_ipv6_prefix_length_greater_or_equal_destroy) * 11 unique id ("XXXXX-XXXXX") * 10 EC ("4294967295" or "0xffffffff") * 35 ISO8601 TS at full length ("YYYY-MM-DD HH:MM:SS.NNNNNNNNN+ZZ:ZZ") * --- * 175 * * rarely used (hopefully...): * 26^ FRR_VERSION ("10.10.10-dev-gffffffffffff") * --- * 201 * * x16 highest number of format parameters currently * 40 estimate for hostname + 2*daemon + pid * * specific format overhead: * * RFC3164 - shorter than the others * RFC5424 - 175 + "<999>1 "=7 + 52 (location@50145) + 40 (host/...) * rarely: + 65 + 26 (for [origin]) * args: 16 * (8 + per-arg (20?)) = ~448 * * so without "args@", origin or (future) keywords, around 256 seems OK * with args@ and/or origin and/or keywords, 512 seems more reasonable * * but - note the code allocates this amount multiplied by the number of * messages in the incoming batch (minimum 3), this means short messages and * long messages smooth each other out. * * Since the code handles space-exceeded by grabbing a bunch of stack memory, * a reasonable middle ground estimate is desirable here, so ... * *drumroll* * let's go with 128 + args?128. (remember the minimum 3 multiplier) * * low_space is the point where we don't try to fit another message in & just * submit what we have to the kernel. * * The zlog code only buffers debug & informational messages, so in production * usage most of the calls will be writing out only 1 message. This makes * the min *3 multiplier quite useful. */ static inline size_t zlog_5424_bufsz(struct zlt_5424 *zte, size_t nmsgs, size_t *low_space) { size_t ret = 128; if (zte->kw_args) ret += 128; *low_space = ret; return ret * MAX(nmsgs, 3); } struct state { struct fbuf *fbuf; struct iovec *iov; }; /* stack-based keyword support is likely to bump this to 3 or 4 */ #define IOV_PER_MSG 2 _Static_assert(IOV_MAX >= IOV_PER_MSG, "this code won't work with IOV_MAX < IOV_PER_MSG"); /* the following functions are quite similar, but trying to merge them just * makes a big mess. check the others when touching one. * * timestamp keywords hostname * RFC5424 ISO8601 yes yes * RFC3164 RFC3164 no yes * local RFC3164 no no * journald ISO8601(unused) yes (unused) */ static size_t zlog_5424_one(struct zlt_5424 *zte, struct zlog_msg *msg, struct state *state) { size_t textlen; struct fbuf *fbuf = state->fbuf; char *orig_pos = fbuf->pos; size_t need = 0; int prio = zlog_msg_prio(msg); intmax_t pid, tid; zlog_msg_pid(msg, &pid, &tid); need += bprintfrr(fbuf, "<%d>1 ", prio | zte->facility); need += zlog_msg_ts(msg, fbuf, zte->ts_flags); need += bprintfrr(fbuf, " %s %s %jd %.*s ", cmd_hostname_get() ?: "-", zlog_progname, pid, (int)(zlog_prefixsz - 2), zlog_prefix); if (zte->kw_version) need += bprintfrr( fbuf, "[origin enterpriseId=\"50145\" software=\"FRRouting\" swVersion=\"%s\"]", FRR_VERSION); const struct xref_logmsg *xref; struct xrefdata *xrefdata; need += bprintfrr(fbuf, "[location@50145 tid=\"%jd\"", tid); if (zlog_instance > 0) need += bprintfrr(fbuf, " instance=\"%d\"", zlog_instance); xref = zlog_msg_xref(msg); xrefdata = xref ? xref->xref.xrefdata : NULL; if (xrefdata) { if (zte->kw_uid) need += bprintfrr(fbuf, " id=\"%s\"", xrefdata->uid); if (zte->kw_ec && prio <= LOG_WARNING) need += bprintfrr(fbuf, " ec=\"%u\"", xref->ec); if (zte->kw_location) need += bprintfrr( fbuf, " file=\"%s\" line=\"%d\" func=\"%s\"", xref->xref.file, xref->xref.line, xref->xref.func); } need += bputch(fbuf, ']'); size_t hdrlen, n_argpos; const struct fmt_outpos *argpos; const char *text; text = zlog_msg_text(msg, &textlen); zlog_msg_args(msg, &hdrlen, &n_argpos, &argpos); if (zte->kw_args && n_argpos) { need += bputs(fbuf, "[args@50145"); for (size_t i = 0; i < n_argpos; i++) { int len = argpos[i].off_end - argpos[i].off_start; need += bprintfrr(fbuf, " arg%zu=%*pSQsq", i + 1, len, text + argpos[i].off_start); } need += bputch(fbuf, ']'); } need += bputch(fbuf, ' '); if (orig_pos + need > fbuf->buf + fbuf->len) { /* not enough space in the buffer for headers. the loop in * zlog_5424() will flush other messages that are already in * the buffer, grab a bigger buffer if needed, and try again. */ fbuf->pos = orig_pos; return need; } /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */ state->iov->iov_base = orig_pos; state->iov->iov_len = fbuf->pos - orig_pos; state->iov++; state->iov->iov_base = (char *)text + hdrlen; state->iov->iov_len = textlen - hdrlen + zte->use_nl; state->iov++; return 0; } static size_t zlog_3164_one(struct zlt_5424 *zte, struct zlog_msg *msg, struct state *state) { size_t textlen; struct fbuf *fbuf = state->fbuf; char *orig_pos = fbuf->pos; size_t need = 0; int prio = zlog_msg_prio(msg); intmax_t pid, tid; zlog_msg_pid(msg, &pid, &tid); need += bprintfrr(fbuf, "<%d>", prio | zte->facility); need += zlog_msg_ts_3164(msg, fbuf, zte->ts_flags); if (zte->fmt != ZLOG_FMT_LOCAL) { need += bputch(fbuf, ' '); need += bputs(fbuf, cmd_hostname_get() ?: "-"); } need += bprintfrr(fbuf, " %s[%jd]: ", zlog_progname, pid); if (orig_pos + need > fbuf->buf + fbuf->len) { /* not enough space in the buffer for headers. loop in * zlog_5424() will flush other messages that are already in * the buffer, grab a bigger buffer if needed, and try again. */ fbuf->pos = orig_pos; return need; } /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */ state->iov->iov_base = orig_pos; state->iov->iov_len = fbuf->pos - orig_pos; state->iov++; state->iov->iov_base = (char *)zlog_msg_text(msg, &textlen); state->iov->iov_len = textlen + zte->use_nl; state->iov++; return 0; } static size_t zlog_journald_one(struct zlt_5424 *zte, struct zlog_msg *msg, struct state *state) { size_t textlen; struct fbuf *fbuf = state->fbuf; char *orig_pos = fbuf->pos; size_t need = 0; int prio = zlog_msg_prio(msg); intmax_t pid, tid; zlog_msg_pid(msg, &pid, &tid); need += bprintfrr(fbuf, "PRIORITY=%d\n" "SYSLOG_FACILITY=%d\n" "TID=%jd\n" "FRR_DAEMON=%s\n" "SYSLOG_TIMESTAMP=", prio, zte->facility, tid, zlog_progname); need += zlog_msg_ts(msg, fbuf, zte->ts_flags); need += bputch(fbuf, '\n'); if (zlog_instance > 0) need += bprintfrr(fbuf, "FRR_INSTANCE=%d\n", zlog_instance); const struct xref_logmsg *xref; struct xrefdata *xrefdata; xref = zlog_msg_xref(msg); xrefdata = xref ? xref->xref.xrefdata : NULL; if (xrefdata) { if (zte->kw_uid && xrefdata->uid[0]) need += bprintfrr(fbuf, "FRR_ID=%s\n", xrefdata->uid); if (zte->kw_ec && prio <= LOG_WARNING) need += bprintfrr(fbuf, "FRR_EC=%d\n", xref->ec); if (zte->kw_location) need += bprintfrr(fbuf, "CODE_FILE=%s\n" "CODE_LINE=%d\n" "CODE_FUNC=%s\n", xref->xref.file, xref->xref.line, xref->xref.func); } size_t hdrlen, n_argpos; const struct fmt_outpos *argpos; const char *text; text = zlog_msg_text(msg, &textlen); zlog_msg_args(msg, &hdrlen, &n_argpos, &argpos); if (zte->kw_args && n_argpos) { for (size_t i = 0; i < n_argpos; i++) { int len = argpos[i].off_end - argpos[i].off_start; /* rather than escape the value, we could use * journald's binary encoding, but that seems a bit * excessive/unnecessary. 99% of things we print here * will just output 1:1 with %pSE. */ need += bprintfrr(fbuf, "FRR_ARG%zu=%*pSE\n", i + 1, len, text + argpos[i].off_start); } } need += bputs(fbuf, "MESSAGE="); if (orig_pos + need > fbuf->buf + fbuf->len) { /* not enough space in the buffer for headers. loop in * zlog_5424() will flush other messages that are already in * the buffer, grab a bigger buffer if needed, and try again. */ fbuf->pos = orig_pos; return need; } /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */ state->iov->iov_base = orig_pos; state->iov->iov_len = fbuf->pos - orig_pos; state->iov++; state->iov->iov_base = (char *)text + hdrlen; state->iov->iov_len = textlen - hdrlen + 1; state->iov++; return 0; } static size_t zlog_one(struct zlt_5424 *zte, struct zlog_msg *msg, struct state *state) { switch (zte->fmt) { case ZLOG_FMT_5424: return zlog_5424_one(zte, msg, state); case ZLOG_FMT_3164: case ZLOG_FMT_LOCAL: return zlog_3164_one(zte, msg, state); case ZLOG_FMT_JOURNALD: return zlog_journald_one(zte, msg, state); } return 0; } static void zlog_5424_err(struct zlt_5424 *zte, size_t count) { if (!count) { zte->current_err = 0; return; } /* only the counter is atomic because otherwise it'd be meaningless */ atomic_fetch_add_explicit(&zte->lost_msgs, count, memory_order_relaxed); /* these are non-atomic and can provide wrong results when read, but * since they're only for debugging / display, that's OK. */ zte->current_err = zte->last_err = errno; monotime(&zte->last_err_ts); } static void zlog_5424(struct zlog_target *zt, struct zlog_msg *msgs[], size_t nmsgs) { size_t i; struct zlt_5424 *zte = container_of(zt, struct zlt_5424, zt); int fd, ret; size_t niov = MIN(IOV_PER_MSG * nmsgs, IOV_MAX); struct iovec iov[niov], *iov_last = iov + niov; struct mmsghdr mmsg[zte->packets ? nmsgs : 1], *mpos = mmsg; size_t count = 0; /* refer to size estimate at top of file */ size_t low_space; char hdr_buf[zlog_5424_bufsz(zte, nmsgs, &low_space)]; struct fbuf hdr_pos = { .buf = hdr_buf, .pos = hdr_buf, .len = sizeof(hdr_buf), }; struct state state = { .fbuf = &hdr_pos, .iov = iov, }; fd = atomic_load_explicit(&zte->fd, memory_order_relaxed); memset(mmsg, 0, sizeof(mmsg)); if (zte->sa_len) { for (i = 0; i < array_size(mmsg); i++) { mmsg[i].msg_hdr.msg_name = (struct sockaddr *)&zte->sa; mmsg[i].msg_hdr.msg_namelen = zte->sa_len; } } mmsg[0].msg_hdr.msg_iov = iov; for (i = 0; i < nmsgs; i++) { int prio = zlog_msg_prio(msgs[i]); size_t need = 0; if (prio <= zte->zt.prio_min) { if (zte->packets) mpos->msg_hdr.msg_iov = state.iov; need = zlog_one(zte, msgs[i], &state); if (zte->packets) { mpos->msg_hdr.msg_iovlen = state.iov - mpos->msg_hdr.msg_iov; mpos++; } count++; } /* clang-format off */ if ((need || (size_t)(hdr_pos.buf + hdr_pos.len - hdr_pos.pos) < low_space || i + 1 == nmsgs || state.iov + IOV_PER_MSG > iov_last) && state.iov > iov) { /* clang-format on */ if (zte->packets) { struct mmsghdr *sendpos; for (sendpos = mmsg; sendpos < mpos;) { ret = sendmmsg(fd, sendpos, mpos - sendpos, 0); if (ret <= 0) break; sendpos += ret; } zlog_5424_err(zte, mpos - sendpos); mpos = mmsg; } else { if (!zte->sa_len) ret = writev(fd, iov, state.iov - iov); else { mpos->msg_hdr.msg_iovlen = state.iov - iov; ret = sendmsg(fd, &mpos->msg_hdr, 0); } if (ret < 0) zlog_5424_err(zte, count); else zlog_5424_err(zte, 0); } count = 0; hdr_pos.pos = hdr_buf; state.iov = iov; } /* if need == 0, we just put a message (or nothing) in the * buffer and are continuing for more to batch in a single * writev() */ if (need == 0) continue; if (need && need <= sizeof(hdr_buf)) { /* don't need to allocate, just try this msg * again without other msgs already using up * buffer space */ i--; continue; } /* need > sizeof(hdr_buf), need to grab some memory. Taking * it off the stack is fine here. */ char buf2[need]; struct fbuf fbuf2 = { .buf = buf2, .pos = buf2, .len = sizeof(buf2), }; state.fbuf = &fbuf2; need = zlog_one(zte, msgs[i], &state); assert(need == 0); if (!zte->sa_len) ret = writev(fd, iov, state.iov - iov); else { mpos->msg_hdr.msg_iovlen = state.iov - iov; ret = sendmsg(fd, &mpos->msg_hdr, 0); } if (ret < 0) zlog_5424_err(zte, 1); else zlog_5424_err(zte, 0); count = 0; state.fbuf = &hdr_pos; state.iov = iov; mpos = mmsg; } assert(state.iov == iov); } /* strftime(), gmtime_r() and localtime_r() aren't AS-Safe (they access locale * data), but we need an AS-Safe timestamp below :( */ static void gmtime_assafe(time_t ts, struct tm *res) { res->tm_sec = ts % 60; ts /= 60; res->tm_min = ts % 60; ts /= 60; res->tm_hour = ts % 24; ts /= 24; ts -= 11017; /* start on 2020-03-01, 11017 days since 1970-01-01 */ /* 1461 days = 3 regular years + 1 leap year * this works until 2100, which isn't a leap year * * struct tm.tm_year starts at 1900. */ res->tm_year = 2000 - 1900 + 4 * (ts / 1461); ts = ts % 1461; if (ts == 1460) { res->tm_year += 4; res->tm_mon = 1; res->tm_mday = 29; return; } res->tm_year += ts / 365; ts %= 365; /* note we're starting in march like the romans did... */ if (ts >= 306) /* Jan 1 of next year */ res->tm_year++; static time_t months[13] = { 0, 31, 61, 92, 122, 153, 184, 214, 245, 275, 306, 337, 365, }; const size_t month_max = array_size(months) - 1; for (size_t i = 0; i < month_max; i++) { if (ts < months[i + 1]) { res->tm_mon = ((i + 2) % 12); res->tm_mday = 1 + ts - months[i]; break; } } } /* one of the greatest advantages of this logging target: unlike syslog(), * which is not AS-Safe, we can send crashlogs to syslog here. */ static void zlog_5424_sigsafe(struct zlog_target *zt, const char *text, size_t len) { static const char *const months_3164[12] = { "Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec", }; struct zlt_5424 *zte = container_of(zt, struct zlt_5424, zt); struct iovec iov[3], *iovp = iov; char buf[256]; struct fbuf fbuf = { .buf = buf, .pos = buf, .len = sizeof(buf), }; int fd; intmax_t pid = (intmax_t)getpid(); struct tm tm; switch (zte->fmt) { case ZLOG_FMT_5424: gmtime_assafe(time(NULL), &tm); bprintfrr( &fbuf, "<%d>1 %04u-%02u-%02uT%02u:%02u:%02uZ - %s %jd %.*s ", zte->facility | LOG_CRIT, tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, zlog_progname, pid, (int)(zlog_prefixsz - 2), zlog_prefix); break; case ZLOG_FMT_3164: case ZLOG_FMT_LOCAL: /* this will unfortuantely be wrong by the timezone offset * if the user selected non-UTC. But not much we can do * about that... */ gmtime_assafe(time(NULL), &tm); bprintfrr(&fbuf, "<%d>%3s %2u %02u:%02u:%02u %s%s[%jd]: ", zte->facility | LOG_CRIT, months_3164[tm.tm_mon], tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, (zte->fmt == ZLOG_FMT_LOCAL) ? "" : "- ", zlog_progname, pid); break; case ZLOG_FMT_JOURNALD: bprintfrr(&fbuf, "PRIORITY=%d\n" "SYSLOG_FACILITY=%d\n" "FRR_DAEMON=%s\n" "MESSAGE=", LOG_CRIT, zte->facility, zlog_progname); break; } iovp->iov_base = fbuf.buf; iovp->iov_len = fbuf.pos - fbuf.buf; iovp++; iovp->iov_base = (char *)text; iovp->iov_len = len; iovp++; if (zte->use_nl) { iovp->iov_base = (char *)"\n"; iovp->iov_len = 1; iovp++; } fd = atomic_load_explicit(&zte->fd, memory_order_relaxed); if (!zte->sa_len) writev(fd, iov, iovp - iov); else { struct msghdr mh = {}; mh.msg_name = (struct sockaddr *)&zte->sa; mh.msg_namelen = zte->sa_len; mh.msg_iov = iov; mh.msg_iovlen = iovp - iov; sendmsg(fd, &mh, 0); } } /* housekeeping & configuration */ void zlog_5424_init(struct zlog_cfg_5424 *zcf) { pthread_mutex_init(&zcf->cfg_mtx, NULL); } static void zlog_5424_target_free(struct zlt_5424 *zlt) { if (!zlt) return; rcu_close(&zlt->head_close, zlt->fd); rcu_free(MTYPE_LOG_5424, zlt, zt.rcu_head); } void zlog_5424_fini(struct zlog_cfg_5424 *zcf, bool keepopen) { if (keepopen) zcf->active = NULL; if (zcf->active) { struct zlt_5424 *ztf; struct zlog_target *zt; zt = zlog_target_replace(&zcf->active->zt, NULL); ztf = container_of(zt, struct zlt_5424, zt); zlog_5424_target_free(ztf); } pthread_mutex_destroy(&zcf->cfg_mtx); } static void zlog_5424_cycle(struct zlog_cfg_5424 *zcf, int fd) { struct zlog_target *old; struct zlt_5424 *zlt = NULL, *oldt; if (fd >= 0) { struct zlog_target *zt; /* all of this is swapped in by zlog_target_replace() below, * the old target is RCU-freed afterwards. */ zt = zlog_target_clone(MTYPE_LOG_5424, &zcf->active->zt, sizeof(*zlt)); zlt = container_of(zt, struct zlt_5424, zt); zlt->fd = fd; zlt->kw_version = zcf->kw_version; zlt->kw_location = zcf->kw_location; zlt->kw_uid = zcf->kw_uid; zlt->kw_ec = zcf->kw_ec; zlt->kw_args = zcf->kw_args; zlt->use_nl = true; zlt->facility = zcf->facility; /* DGRAM & SEQPACKET = 1 log message per packet */ zlt->packets = (zcf->sock_type == SOCK_DGRAM) || (zcf->sock_type == SOCK_SEQPACKET); zlt->sa = zcf->sa; zlt->sa_len = zcf->sa_len; zlt->fmt = zcf->fmt; zlt->zt.prio_min = zcf->prio_min; zlt->zt.logfn = zlog_5424; zlt->zt.logfn_sigsafe = zlog_5424_sigsafe; switch (zcf->fmt) { case ZLOG_FMT_5424: case ZLOG_FMT_JOURNALD: zlt->ts_flags = zcf->ts_flags; zlt->ts_flags &= ZLOG_TS_PREC | ZLOG_TS_UTC; zlt->ts_flags |= ZLOG_TS_ISO8601; break; case ZLOG_FMT_3164: case ZLOG_FMT_LOCAL: zlt->ts_flags = zcf->ts_flags & ZLOG_TS_UTC; if (zlt->packets) zlt->use_nl = false; break; } } old = zcf->active ? &zcf->active->zt : NULL; old = zlog_target_replace(old, &zlt->zt); zcf->active = zlt; /* oldt->fd == fd happens for zlog_5424_apply_meta() */ oldt = container_of(old, struct zlt_5424, zt); if (oldt && oldt->fd != (unsigned int)fd) rcu_close(&oldt->head_close, oldt->fd); rcu_free(MTYPE_LOG_5424, oldt, zt.rcu_head); } static void zlog_5424_reconnect(struct event *t) { struct zlog_cfg_5424 *zcf = EVENT_ARG(t); int fd = EVENT_FD(t); char dummy[256]; ssize_t ret; if (zcf->active) { ret = read(fd, dummy, sizeof(dummy)); if (ret > 0) { /* logger is sending us something?!?! */ event_add_read(t->master, zlog_5424_reconnect, zcf, fd, &zcf->t_reconnect); return; } if (ret == 0) zlog_warn("logging socket %pSE closed by peer", zcf->filename); else zlog_warn("logging socket %pSE error: %m", zcf->filename); } /* do NOT close() anything here; other threads may still be writing * and their messages need to be lost rather than end up on a random * other fd that got reassigned the same number, like a BGP session! */ fd = zlog_5424_open(zcf, -1); frr_with_mutex (&zcf->cfg_mtx) { zlog_5424_cycle(zcf, fd); } } static int zlog_5424_unix(struct sockaddr_un *suna, int sock_type) { int fd; int size = 1 * 1024 * 1024, prev_size; socklen_t opt_size; int save_errno; fd = socket(AF_UNIX, sock_type, 0); if (fd < 0) return -1; if (connect(fd, (struct sockaddr *)suna, sizeof(*suna))) { /* zlog_5424_open() will print the error for connect() */ save_errno = errno; close(fd); errno = save_errno; return -1; } opt_size = sizeof(prev_size); if (getsockopt(fd, SOL_SOCKET, SO_SNDBUF, &prev_size, &opt_size)) return fd; /* setsockopt_so_sendbuf() logs on error; we don't really care that * much here. Also, never shrink the buffer below the initial size. */ while (size > prev_size && setsockopt(fd, SOL_SOCKET, SO_SNDBUF, &size, sizeof(size)) == -1) size /= 2; return fd; } static int zlog_5424_open(struct zlog_cfg_5424 *zcf, int sock_type) { int fd = -1; int flags = 0; int err; socklen_t optlen; bool do_chown = false; bool need_reconnect = false; static const int unix_types[] = { SOCK_STREAM, SOCK_SEQPACKET, SOCK_DGRAM, }; struct sockaddr_un sa; zcf->sock_type = -1; zcf->sa_len = 0; switch (zcf->dst) { case ZLOG_5424_DST_NONE: return -1; case ZLOG_5424_DST_FD: fd = dup(zcf->fd); if (fd < 0) { flog_err_sys(EC_LIB_SYSTEM_CALL, "failed to dup() log file descriptor: %m (FD limit too low?)"); return -1; } optlen = sizeof(sock_type); if (!getsockopt(fd, SOL_SOCKET, SO_TYPE, &sock_type, &optlen)) { zcf->sock_type = sock_type; need_reconnect = (zcf->sock_type != SOCK_DGRAM); } break; case ZLOG_5424_DST_FIFO: if (!zcf->filename) return -1; if (!zcf->file_nocreate) { frr_with_privs (lib_privs) { mode_t prevmask; prevmask = umask(0777 ^ zcf->file_mode); err = mkfifo(zcf->filename, 0666); umask(prevmask); } if (err == 0) do_chown = true; else if (errno != EEXIST) return -1; } flags = O_NONBLOCK; fallthrough; case ZLOG_5424_DST_FILE: if (!zcf->filename) return -1; frr_with_privs (lib_privs) { fd = open(zcf->filename, flags | O_WRONLY | O_APPEND | O_CLOEXEC | O_NOCTTY); } if (fd >= 0) break; if (zcf->file_nocreate || flags) { flog_err_sys(EC_LIB_SYSTEM_CALL, "could not open log file %pSE: %m", zcf->filename); return -1; } frr_with_privs (lib_privs) { mode_t prevmask; prevmask = umask(0777 ^ zcf->file_mode); fd = open(zcf->filename, O_WRONLY | O_APPEND | O_CLOEXEC | O_NOCTTY | O_CREAT | O_EXCL, zcf->file_mode); umask(prevmask); } if (fd >= 0) { do_chown = true; break; } frr_with_privs (lib_privs) { fd = open(zcf->filename, O_WRONLY | O_APPEND | O_CLOEXEC | O_NOCTTY); } if (fd >= 0) break; flog_err_sys(EC_LIB_SYSTEM_CALL, "could not open or create log file %pSE: %m", zcf->filename); return -1; case ZLOG_5424_DST_UNIX: if (!zcf->filename) return -1; memset(&sa, 0, sizeof(sa)); sa.sun_family = AF_UNIX; strlcpy(sa.sun_path, zcf->filename, sizeof(sa.sun_path)); /* check if ZLOG_5424_DST_FD needs a touch when changing * something here. the user can pass in a pre-opened unix * socket through a fd at startup. */ frr_with_privs (lib_privs) { if (sock_type != -1) fd = zlog_5424_unix(&sa, sock_type); else { for (size_t i = 0; i < array_size(unix_types); i++) { fd = zlog_5424_unix(&sa, unix_types[i]); if (fd != -1) { zcf->sock_type = unix_types[i]; break; } } } } if (fd == -1) { zcf->sock_type = -1; flog_err_sys( EC_LIB_SYSTEM_CALL, "could not connect to log unix path %pSE: %m", zcf->filename); need_reconnect = true; /* no return -1 here, trigger retry code below */ } else { /* datagram sockets are connectionless, restarting * the receiver may lose some packets but will resume * working afterwards without any action from us. */ need_reconnect = (zcf->sock_type != SOCK_DGRAM); } break; } /* viable on both DST_FD and DST_UNIX path */ if (zcf->sock_type == SOCK_DGRAM) { zcf->sa_len = sizeof(zcf->sa); if (getpeername(fd, (struct sockaddr *)&zcf->sa, &zcf->sa_len)) { flog_err_sys( EC_LIB_SYSTEM_CALL, "could not get remote address for log socket. logging may break if log receiver restarts."); zcf->sa_len = 0; } } if (do_chown) { uid_t uid = zcf->file_uid; gid_t gid = zcf->file_gid; if (uid != (uid_t)-1 || gid != (gid_t)-1) { frr_with_privs (lib_privs) { err = fchown(fd, uid, gid); } if (err) flog_err_sys( EC_LIB_SYSTEM_CALL, "failed to chown() log file %pSE: %m", zcf->filename); } } if (need_reconnect) { assert(zcf->master); if (fd != -1) { event_add_read(zcf->master, zlog_5424_reconnect, zcf, fd, &zcf->t_reconnect); zcf->reconn_backoff_cur = zcf->reconn_backoff; } else { event_add_timer_msec(zcf->master, zlog_5424_reconnect, zcf, zcf->reconn_backoff_cur, &zcf->t_reconnect); zcf->reconn_backoff_cur += zcf->reconn_backoff_cur / 2; if (zcf->reconn_backoff_cur > zcf->reconn_backoff_max) zcf->reconn_backoff_cur = zcf->reconn_backoff_max; } } return fd; } bool zlog_5424_apply_dst(struct zlog_cfg_5424 *zcf) { int fd = -1; event_cancel(&zcf->t_reconnect); if (zcf->prio_min != ZLOG_DISABLED) fd = zlog_5424_open(zcf, -1); frr_with_mutex (&zcf->cfg_mtx) { zlog_5424_cycle(zcf, fd); } return fd != -1; } bool zlog_5424_apply_meta(struct zlog_cfg_5424 *zcf) { frr_with_mutex (&zcf->cfg_mtx) { if (zcf->active) zlog_5424_cycle(zcf, zcf->active->fd); } return true; } void zlog_5424_state(struct zlog_cfg_5424 *zcf, size_t *lost_msgs, int *last_errno, bool *stale_errno, struct timeval *err_ts) { if (lost_msgs) *lost_msgs = zcf->active ? atomic_load_explicit(&zcf->active->lost_msgs, memory_order_relaxed) : 0; if (last_errno) *last_errno = zcf->active ? zcf->active->last_err : 0; if (stale_errno) *stale_errno = zcf->active ? !zcf->active->current_err : 0; if (err_ts && zcf->active) *err_ts = zcf->active->last_err_ts; } struct rcu_close_rotate { struct rcu_head_close head_close; struct rcu_head head_self; }; bool zlog_5424_rotate(struct zlog_cfg_5424 *zcf) { struct rcu_close_rotate *rcr; int fd; frr_with_mutex (&zcf->cfg_mtx) { if (!zcf->active) return true; event_cancel(&zcf->t_reconnect); /* need to retain the socket type because it also influences * other fields (packets) and we can't atomically swap these * out. But we really want the atomic swap so we neither lose * nor duplicate log messages, particularly for file targets. * * (zlog_5424_apply_dst / zlog_target_replace will cause * duplicate log messages if another thread logs something * while we're right in the middle of swapping out the log * target) */ fd = zlog_5424_open(zcf, zcf->sock_type); if (fd < 0) return false; fd = atomic_exchange_explicit(&zcf->active->fd, (uint_fast32_t)fd, memory_order_relaxed); } rcr = XCALLOC(MTYPE_LOG_5424_ROTATE, sizeof(*rcr)); rcu_close(&rcr->head_close, fd); rcu_free(MTYPE_LOG_5424_ROTATE, rcr, head_self); return true; }