Merge pull request #8656 from opensourcerouting/xref-5424-prep-2

lib: preparations for RFC5424 syslog support

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
+      This setting is not saved to ``frr.conf`` and not shown in
-   daemon independent.
+      :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

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...)

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
+		if (zlog_msg_prio(msgs[i]) >= LOG_DEBUG) {
-		    && search_buf(zlog_msg_text(msgs[i], NULL)) < 0)
+			text = zlog_msg_text(msgs[i], &text_len);
+			if (search_buf(text, text_len) < 0)
 				continue;
-
+		}
 		msgfilt[o++] = msgs[i];
 	}
 

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)] = "";

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

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,
+size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags)
-		   uint32_t flags)
 {
+	size_t outsz = out ? (out->buf + out->len - out->pos) : 0;
 	size_t len1;
 
 	if (!(flags & ZLOG_TS_FORMAT))
@@ -672,34 +739,76 @@ 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)
+		if (!out)
-			return 0;
+			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)
+		if (!out)
-			return 0;
+			return len1 + len2;
-		memcpy(out, msg->ts_str, len1);
+
-		memcpy(out + len1, msg->ts_zonetail, len2);
+		if (len1 + len2 > outsz) {
-		out[len1 + len2] = '\0';
+			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)
@@ -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),

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

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)
+			zlog_msg_ts(msg, &fbuf,
-				*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);
+			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",
+		text = zlog_msg_text(msgs[i], &text_len);
-		       zlog_msg_text(msgs[i], NULL));
+		syslog(zlog_msg_prio(msgs[i]) | zte->syslog_facility, "%.*s",
+		       (int)text_len, text);
 	}
 }