diff options
Diffstat (limited to '')
| -rw-r--r-- | lib/zlog_5424.c | 1145 |
1 files changed, 1145 insertions, 0 deletions
diff --git a/lib/zlog_5424.c b/lib/zlog_5424.c new file mode 100644 index 0000000..9da7c55 --- /dev/null +++ b/lib/zlog_5424.c @@ -0,0 +1,1145 @@ +/* + * Copyright (c) 2015-21 David Lamparter, for NetDEF, Inc. + * + * Permission to use, copy, modify, and distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + */ + +/* 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 "zlog_5424.h" + +#include <sys/un.h> +#include <syslog.h> + +#include "memory.h" +#include "frrcu.h" +#include "printfrr.h" +#include "typerb.h" +#include "frr_pthread.h" +#include "command.h" +#include "monotime.h" +#include "thread.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 unsigned int months[13] = { + 0, 31, 61, 92, 122, 153, 184, 214, 245, 275, 306, 337, 365, + }; + + for (size_t i = 0; i < array_size(months); i++) { + if ((unsigned int)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 thread *t) +{ + struct zlog_cfg_5424 *zcf = THREAD_ARG(t); + int fd = THREAD_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?!?! */ + thread_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: + break; + + case ZLOG_5424_DST_FD: + fd = dup(zcf->fd); + + 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) + break; + + 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) + break; + } + + flags = O_NONBLOCK; + /* fallthru */ + + case ZLOG_5424_DST_FILE: + if (!zcf->filename) + break; + + 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); + break; + } + + 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); + break; + + case ZLOG_5424_DST_UNIX: + if (!zcf->filename) + break; + + 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; + } 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) { + thread_add_read(zcf->master, zlog_5424_reconnect, zcf, + fd, &zcf->t_reconnect); + zcf->reconn_backoff_cur = zcf->reconn_backoff; + + } else { + thread_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; + + thread_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; + + thread_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; +} |