diff --git a/doc/user/basic.rst b/doc/user/basic.rst index 452794e3a8..6a0249f316 100644 --- a/doc/user/basic.rst +++ b/doc/user/basic.rst @@ -180,11 +180,17 @@ Basic Config Commands is used to start the daemon then this command is turned on by default and cannot be turned off and the [no] form of the command is dissallowed. -.. clicmd:: log-filter WORD [DAEMON] +.. clicmd:: log filtered-file [FILENAME [LEVEL]] + + Configure a destination file for filtered logs with the + :clicmd:`log filter-text WORD` command. + +.. clicmd:: log filter-text WORD This command forces logs to be filtered on a specific string. A log message will only be printed if it matches on one of the filters in the log-filter - table. Can be daemon independent. + table. The filter only applies to file logging targets configured with + :clicmd:`log filtered-file [FILENAME [LEVEL]]`. .. note:: @@ -193,10 +199,15 @@ Basic Config Commands Log filters prevent this but you should still expect a small performance hit due to filtering each of all those logs. -.. clicmd:: log-filter clear [DAEMON] + .. note:: - This command clears all current filters in the log-filter table. Can be - daemon independent. + This setting is not saved to ``frr.conf`` and not shown in + :clicmd:`show running-config`. It is intended for ephemeral debugging + purposes only. + +.. clicmd:: clear log filter-text + + This command clears all current filters in the log-filter table. .. clicmd:: log immediate-mode diff --git a/lib/compiler.h b/lib/compiler.h index e805eb8be4..970ed297fc 100644 --- a/lib/compiler.h +++ b/lib/compiler.h @@ -347,7 +347,11 @@ extern "C" { #define PRIx64 "Lx" #else /* !_FRR_ATTRIBUTE_PRINTFRR */ +#ifdef __NetBSD__ +#define PRINTFRR(a, b) __attribute__((format(gnu_syslog, a, b))) +#else #define PRINTFRR(a, b) __attribute__((format(printf, a, b))) +#endif /* frr-format plugin is C-only for now, so no point in doing these shenanigans * for C++... (also they can break some C++ stuff...) diff --git a/lib/log_filter.c b/lib/log_filter.c index 721e57a628..f01497dead 100644 --- a/lib/log_filter.c +++ b/lib/log_filter.c @@ -111,13 +111,14 @@ int zlog_filter_dump(char *buf, size_t max_size) return len; } -static int search_buf(const char *buf) +static int search_buf(const char *buf, size_t len) { char *found = NULL; frr_with_mutex(&logfilterlock) { for (int i = 0; i < zlog_filter_count; i++) { - found = strstr(buf, zlog_filters[i]); + found = memmem(buf, len, zlog_filters[i], + strlen(zlog_filters[i])); if (found != NULL) return 0; } @@ -131,12 +132,15 @@ static void zlog_filterfile_fd(struct zlog_target *zt, struct zlog_msg *msgs[], { struct zlog_msg *msgfilt[nmsgs]; size_t i, o = 0; + const char *text; + size_t text_len; for (i = 0; i < nmsgs; i++) { - if (zlog_msg_prio(msgs[i]) >= LOG_DEBUG - && search_buf(zlog_msg_text(msgs[i], NULL)) < 0) - continue; - + if (zlog_msg_prio(msgs[i]) >= LOG_DEBUG) { + text = zlog_msg_text(msgs[i], &text_len); + if (search_buf(text, text_len) < 0) + continue; + } msgfilt[o++] = msgs[i]; } diff --git a/lib/log_vty.c b/lib/log_vty.c index 9dbf216d31..cbb8de8976 100644 --- a/lib/log_vty.c +++ b/lib/log_vty.c @@ -34,6 +34,7 @@ #define ZLOG_MAXLVL(a, b) MAX(a, b) DEFINE_HOOK(zlog_rotate, (), ()); +DEFINE_HOOK(zlog_cli_show, (struct vty * vty), (vty)); static const int log_default_lvl = LOG_DEBUG; @@ -57,7 +58,7 @@ static struct zlog_cfg_filterfile zt_filterfile = { }, }; -static const char *zlog_progname; +const char *zlog_progname; static const char *zlog_protoname; static const struct facility_map { @@ -94,7 +95,14 @@ static const char * const zlog_priority[] = { "notifications", "informational", "debugging", NULL, }; -static const char *facility_name(int facility) +const char *zlog_priority_str(int priority) +{ + if (priority > LOG_DEBUG) + return "???"; + return zlog_priority[priority]; +} + +const char *facility_name(int facility) { const struct facility_map *fm; @@ -104,7 +112,7 @@ static const char *facility_name(int facility) return ""; } -static int facility_match(const char *str) +int facility_match(const char *str) { const struct facility_map *fm; @@ -194,6 +202,8 @@ DEFUN_NOSH (show_logging, vty_out(vty, "Record priority: %s\n", (zt_file.record_priority ? "enabled" : "disabled")); vty_out(vty, "Timestamp precision: %d\n", zt_file.ts_subsec); + + hook_call(zlog_cli_show, vty); return CMD_SUCCESS; } @@ -588,8 +598,9 @@ DEFUN (no_config_log_filterfile, DEFPY (log_filter, log_filter_cmd, - "[no] log-filter WORD$filter", + "[no] log filter-text WORD$filter", NO_STR + "Logging control\n" FILTER_LOG_STR "String to filter by\n") { @@ -616,8 +627,9 @@ DEFPY (log_filter, /* Clear all log filters */ DEFPY (log_filter_clear, log_filter_clear_cmd, - "clear log-filter", + "clear log filter-text", CLEAR_STR + "Logging control\n" FILTER_LOG_STR) { zlog_filter_clear(); @@ -627,8 +639,9 @@ DEFPY (log_filter_clear, /* Show log filter */ DEFPY (show_log_filter, show_log_filter_cmd, - "show log-filter", + "show logging filter-text", SHOW_STR + "Show current logging configuration\n" FILTER_LOG_STR) { char log_filters[ZLOG_FILTERS_MAX * (ZLOG_FILTER_LENGTH_MAX + 3)] = ""; diff --git a/lib/log_vty.h b/lib/log_vty.h index f0fb7d3dba..db46b3cb5b 100644 --- a/lib/log_vty.h +++ b/lib/log_vty.h @@ -34,9 +34,14 @@ extern void log_config_write(struct vty *vty); extern int log_level_match(const char *s); extern void log_show_syslog(struct vty *vty); +extern int facility_match(const char *str); +extern const char *facility_name(int facility); + DECLARE_HOOK(zlog_rotate, (), ()); extern void zlog_rotate(void); +DECLARE_HOOK(zlog_cli_show, (struct vty * vty), (vty)); + #ifdef __cplusplus } #endif diff --git a/lib/zlog.c b/lib/zlog.c index 89ab9265d1..6fd52cae62 100644 --- a/lib/zlog.c +++ b/lib/zlog.c @@ -67,6 +67,7 @@ DEFINE_HOOK(zlog_aux_init, (const char *prefix, int prio_min), char zlog_prefix[128]; size_t zlog_prefixsz; int zlog_tmpdirfd = -1; +int zlog_instance = -1; static atomic_bool zlog_ec = true, zlog_xid = true; @@ -107,6 +108,7 @@ struct zlog_msg { size_t stackbufsz; char *text; size_t textlen; + size_t hdrlen; /* This is always ISO8601 with sub-second precision 9 here, it's * converted for callers as needed. ts_dot points to the "." @@ -116,8 +118,23 @@ struct zlog_msg { * Valid if ZLOG_TS_ISO8601 is set. * (0 if timestamp has not been formatted yet) */ - uint32_t ts_flags; char ts_str[32], *ts_dot, ts_zonetail[8]; + uint32_t ts_flags; + + /* "mmm dd hh:mm:ss" for 3164 legacy syslog - too dissimilar from + * the above, so just kept separately here. + */ + uint32_t ts_3164_flags; + char ts_3164_str[16]; + + /* at the time of writing, 16 args was the actual maximum of arguments + * to a single zlog call. Particularly printing flag bitmasks seems + * to drive this. That said, the overhead of dynamically sizing this + * probably outweighs the value. If anything, a printfrr extension + * for printing flag bitmasks might be a good idea. + */ + struct fmt_outpos argpos[24]; + size_t n_argpos; }; /* thread-local log message buffering @@ -204,8 +221,15 @@ static inline void zlog_tls_set(struct zlog_tls *val) #endif #ifdef CAN_DO_TLS -static long zlog_gettid(void) +static intmax_t zlog_gettid(void) { +#ifndef __OpenBSD__ + /* accessing a TLS variable is much faster than a syscall */ + static thread_local intmax_t cached_tid = -1; + if (cached_tid != -1) + return cached_tid; +#endif + long rv = -1; #ifdef HAVE_PTHREAD_GETTHREADID_NP rv = pthread_getthreadid_np(); @@ -225,6 +249,10 @@ static long zlog_gettid(void) rv = mach_thread_self(); mach_port_deallocate(mach_task_self(), rv); #endif + +#ifndef __OpenBSD__ + cached_tid = rv; +#endif return rv; } @@ -244,7 +272,7 @@ void zlog_tls_buffer_init(void) for (i = 0; i < array_size(zlog_tls->msgp); i++) zlog_tls->msgp[i] = &zlog_tls->msgs[i]; - snprintfrr(mmpath, sizeof(mmpath), "logbuf.%ld", zlog_gettid()); + snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid()); mmfd = openat(zlog_tmpdirfd, mmpath, O_RDWR | O_CREAT | O_EXCL | O_CLOEXEC, 0600); @@ -311,7 +339,7 @@ void zlog_tls_buffer_fini(void) zlog_tls_free(zlog_tls); zlog_tls_set(NULL); - snprintfrr(mmpath, sizeof(mmpath), "logbuf.%ld", zlog_gettid()); + snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid()); if (do_unlink && unlinkat(zlog_tmpdirfd, mmpath, 0)) zlog_err("unlink logbuf: %s (%d)", strerror(errno), errno); } @@ -326,6 +354,24 @@ void zlog_tls_buffer_fini(void) } #endif +void zlog_msg_pid(struct zlog_msg *msg, intmax_t *pid, intmax_t *tid) +{ +#ifndef __OpenBSD__ + static thread_local intmax_t cached_pid = -1; + if (cached_pid != -1) + *pid = cached_pid; + else + cached_pid = *pid = (intmax_t)getpid(); +#else + *pid = (intmax_t)getpid(); +#endif +#ifdef CAN_DO_TLS + *tid = zlog_gettid(); +#else + *tid = *pid; +#endif +} + static inline void zlog_tls_free(void *arg) { struct zlog_tls *zlog_tls = arg; @@ -592,15 +638,19 @@ const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen) if (need) need += bputch(&fb, ' '); - hdrlen = need; + msg->hdrlen = hdrlen = need; assert(hdrlen < msg->stackbufsz); + fb.outpos = msg->argpos; + fb.outpos_n = array_size(msg->argpos); + fb.outpos_i = 0; + va_copy(args, msg->args); need += vbprintfrr(&fb, msg->fmt, args); va_end(args); msg->textlen = need; - need += bputch(&fb, '\0'); + need += bputch(&fb, '\n'); if (need <= msg->stackbufsz) msg->text = msg->stackbuf; @@ -612,25 +662,42 @@ const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen) fb.buf = msg->text; fb.len = need; fb.pos = msg->text + hdrlen; + fb.outpos_i = 0; va_copy(args, msg->args); vbprintfrr(&fb, msg->fmt, args); va_end(args); - bputch(&fb, '\0'); + bputch(&fb, '\n'); } + + msg->n_argpos = fb.outpos_i; } if (textlen) *textlen = msg->textlen; return msg->text; } +void zlog_msg_args(struct zlog_msg *msg, size_t *hdrlen, size_t *n_argpos, + const struct fmt_outpos **argpos) +{ + if (!msg->text) + zlog_msg_text(msg, NULL); + + if (hdrlen) + *hdrlen = msg->hdrlen; + if (n_argpos) + *n_argpos = msg->n_argpos; + if (argpos) + *argpos = msg->argpos; +} + #define ZLOG_TS_FORMAT (ZLOG_TS_ISO8601 | ZLOG_TS_LEGACY) #define ZLOG_TS_FLAGS ~ZLOG_TS_PREC -size_t zlog_msg_ts(struct zlog_msg *msg, char *out, size_t outsz, - uint32_t flags) +size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags) { + size_t outsz = out ? (out->buf + out->len - out->pos) : 0; size_t len1; if (!(flags & ZLOG_TS_FORMAT)) @@ -672,36 +739,78 @@ size_t zlog_msg_ts(struct zlog_msg *msg, char *out, size_t outsz, len1 = strlen(msg->ts_str); if (flags & ZLOG_TS_LEGACY) { - if (len1 + 1 > outsz) - return 0; + if (!out) + return len1; + + if (len1 > outsz) { + memset(out->pos, 0, outsz); + out->pos += outsz; + return len1; + } /* just swap out the formatting, faster than redoing it */ for (char *p = msg->ts_str; p < msg->ts_str + len1; p++) { switch (*p) { case '-': - *out++ = '/'; + *out->pos++ = '/'; break; case 'T': - *out++ = ' '; + *out->pos++ = ' '; break; default: - *out++ = *p; + *out->pos++ = *p; } } - *out = '\0'; return len1; } else { size_t len2 = strlen(msg->ts_zonetail); - if (len1 + len2 + 1 > outsz) - return 0; - memcpy(out, msg->ts_str, len1); - memcpy(out + len1, msg->ts_zonetail, len2); - out[len1 + len2] = '\0'; + if (!out) + return len1 + len2; + + if (len1 + len2 > outsz) { + memset(out->pos, 0, outsz); + out->pos += outsz; + return len1 + len2; + } + + memcpy(out->pos, msg->ts_str, len1); + out->pos += len1; + memcpy(out->pos, msg->ts_zonetail, len2); + out->pos += len2; return len1 + len2; } } +size_t zlog_msg_ts_3164(struct zlog_msg *msg, struct fbuf *out, uint32_t flags) +{ + flags &= ZLOG_TS_UTC; + + if (!msg->ts_3164_str[0] || flags != msg->ts_3164_flags) { + /* these are "hardcoded" in RFC3164, so they're here too... */ + static const char *const months[12] = { + "Jan", "Feb", "Mar", "Apr", "May", "Jun", + "Jul", "Aug", "Sep", "Oct", "Nov", "Dec", + }; + struct tm tm; + + /* RFC3164 explicitly asks for local time, but common usage + * also includes UTC. + */ + if (flags & ZLOG_TS_UTC) + gmtime_r(&msg->ts.tv_sec, &tm); + else + localtime_r(&msg->ts.tv_sec, &tm); + + snprintfrr(msg->ts_3164_str, sizeof(msg->ts_3164_str), + "%3s %2d %02d:%02d:%02d", months[tm.tm_mon], + tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec); + + msg->ts_3164_flags = flags; + } + return bputs(out, msg->ts_3164_str); +} + void zlog_set_prefix_ec(bool enable) { atomic_store_explicit(&zlog_ec, enable, memory_order_relaxed); @@ -777,6 +886,7 @@ void zlog_init(const char *progname, const char *protoname, { zlog_uid = uid; zlog_gid = gid; + zlog_instance = instance; if (instance) { snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), diff --git a/lib/zlog.h b/lib/zlog.h index c421c16f38..d9c8952ac5 100644 --- a/lib/zlog.h +++ b/lib/zlog.h @@ -31,14 +31,19 @@ #include "frrcu.h" #include "memory.h" #include "hook.h" +#include "printfrr.h" #ifdef __cplusplus extern "C" { #endif +DECLARE_MGROUP(LOG); + extern char zlog_prefix[]; extern size_t zlog_prefixsz; extern int zlog_tmpdirfd; +extern int zlog_instance; +extern const char *zlog_progname; struct xref_logmsg { struct xref xref; @@ -143,9 +148,18 @@ struct zlog_msg; extern int zlog_msg_prio(struct zlog_msg *msg); extern const struct xref_logmsg *zlog_msg_xref(struct zlog_msg *msg); -/* pass NULL as textlen if you don't need it. */ +/* text is NOT \0 terminated; instead there is a \n after textlen since the + * logging targets would jump extra hoops otherwise for a single byte. (the + * \n is not included in textlen) + * + * calling this with NULL textlen is likely wrong. + * use "%.*s", (int)textlen, text when passing to printf-like functions + */ extern const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen); +extern void zlog_msg_args(struct zlog_msg *msg, size_t *hdrlen, + size_t *n_argpos, const struct fmt_outpos **argpos); + /* timestamp formatting control flags */ /* sub-second digit count */ @@ -161,9 +175,18 @@ extern const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen); /* default is local time zone */ #define ZLOG_TS_UTC (1 << 10) -extern size_t zlog_msg_ts(struct zlog_msg *msg, char *out, size_t outsz, +extern size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags); +/* "mmm dd hh:mm:ss" for RFC3164 syslog. Only ZLOG_TS_UTC for flags. */ +extern size_t zlog_msg_ts_3164(struct zlog_msg *msg, struct fbuf *out, + uint32_t flags); + +/* currently just returns the current PID/TID since we never write another + * thread's messages + */ +extern void zlog_msg_pid(struct zlog_msg *msg, intmax_t *pid, intmax_t *tid); + /* This list & struct implements the actual logging targets. It is accessed * lock-free from all threads, and thus MUST only be changed atomically, i.e. * RCU. @@ -254,6 +277,8 @@ extern void zlog_tls_buffer_fini(void); /* Enable or disable 'immediate' output - default is to buffer messages. */ extern void zlog_set_immediate(bool set_p); +extern const char *zlog_priority_str(int priority); + #ifdef __cplusplus } #endif diff --git a/lib/zlog_targets.c b/lib/zlog_targets.c index 7799fbfda7..48785ad298 100644 --- a/lib/zlog_targets.c +++ b/lib/zlog_targets.c @@ -31,7 +31,6 @@ * absolute end. */ -DECLARE_MGROUP(LOG); DEFINE_MGROUP_ACTIVEATEXIT(LOG, "logging subsystem"); DEFINE_MTYPE_STATIC(LOG, LOG_FD, "log file target"); @@ -79,13 +78,17 @@ void zlog_fd(struct zlog_target *zt, struct zlog_msg *msgs[], size_t nmsgs) int prio = zlog_msg_prio(msg); if (prio <= zt->prio_min) { + struct fbuf fbuf = { + .buf = ts_buf, + .pos = ts_pos, + .len = sizeof(ts_buf), + }; + iov[iovpos].iov_base = ts_pos; - if (iovpos > 0) - *ts_pos++ = '\n'; - ts_pos += zlog_msg_ts(msg, ts_pos, - sizeof(ts_buf) - 1 - - (ts_pos - ts_buf), - ZLOG_TS_LEGACY | zte->ts_subsec); + zlog_msg_ts(msg, &fbuf, + ZLOG_TS_LEGACY | zte->ts_subsec); + ts_pos = fbuf.pos; + *ts_pos++ = ' '; iov[iovpos].iov_len = ts_pos - (char *)iov[iovpos].iov_base; @@ -107,7 +110,7 @@ void zlog_fd(struct zlog_target *zt, struct zlog_msg *msgs[], size_t nmsgs) iov[iovpos].iov_base = (char *)zlog_msg_text(msg, &textlen); - iov[iovpos].iov_len = textlen; + iov[iovpos].iov_len = textlen + 1; iovpos++; } @@ -120,11 +123,6 @@ void zlog_fd(struct zlog_target *zt, struct zlog_msg *msgs[], size_t nmsgs) if (iovpos > 0 && (ts_buf + sizeof(ts_buf) - ts_pos < TS_LEN || i + 1 == nmsgs || array_size(iov) - iovpos < 5)) { - iov[iovpos].iov_base = (char *)"\n"; - iov[iovpos].iov_len = 1; - - iovpos++; - writev(fd, iov, iovpos); iovpos = 0; @@ -439,13 +437,16 @@ static void zlog_syslog(struct zlog_target *zt, struct zlog_msg *msgs[], { size_t i; struct zlt_syslog *zte = container_of(zt, struct zlt_syslog, zt); + const char *text; + size_t text_len; for (i = 0; i < nmsgs; i++) { if (zlog_msg_prio(msgs[i]) > zt->prio_min) continue; - syslog(zlog_msg_prio(msgs[i]) | zte->syslog_facility, "%s", - zlog_msg_text(msgs[i], NULL)); + text = zlog_msg_text(msgs[i], &text_len); + syslog(zlog_msg_prio(msgs[i]) | zte->syslog_facility, "%.*s", + (int)text_len, text); } }