Feature: Implement "extended" logging using a marker character

If a log message contains a magic character, everything after that marker
will be considered "extended" information. Log targets default to showing
this extended information but qb_log_ctl() may be used to indicate that
the extended information should be stripped instead.

The use case is a log message that has some information of value to administrators
and other information that is only of value for debugging. Two targets can be
configured such that the administrator log is not cluttered with debug information,
but a separate debug log is still available with complete information.

The magic character is the bell (\a). If someone wants to log an actual bell
character, they can do so in the extended information or via a %c format
(only the first bell is magic and only in the format string).

include/qb/qblog.h

@@ -363,18 +363,30 @@ void qb_log_from_external_source_va(const char *function,
  */
 #define qb_log(priority, fmt, args...) qb_logt(priority, 0, fmt, ##args)
 
+/* Define the character used to mark the beginning of "extended" information;
+ * a string equivalent is also defined so clients can use it like:
+ *    qb_log(level, "blah blah "QB_XS" yada yada", __func__);
+ */
+#define QB_XC '\a'
+#define QB_XS "\a"
+
 /**
  * This is similar to perror except it goes into the logging system.
  *
  * @param priority this takes syslog priorities.
  * @param fmt usual printf style format specifiers
  * @param args usual printf style args
+ *
+ * @note Because qb_perror() adds the system error message and error number onto
+ *       the end of the given fmt, that information will become extended
+ *       information if QB_XS is used inside fmt and will not show up in any
+ *       logs that strip extended information.
  */
 #ifndef S_SPLINT_S
 #define qb_perror(priority, fmt, args...) do {				\
 	char _perr_buf_[QB_LOG_STRERROR_MAX_LEN];			\
 	const char *_perr_str_ = qb_strerror_r(errno, _perr_buf_, sizeof(_perr_buf_));	\
-	qb_logt(priority, 0, fmt ": %s (%d)", ##args, _perr_str_, errno);		\
+	qb_logt(priority, 0, fmt ": %s (%d)", ##args, _perr_str_, errno); \
     } while(0)
 #else
 #define qb_perror
@@ -405,6 +417,7 @@ enum qb_log_conf {
 	QB_LOG_CONF_PRIORITY_BUMP,
 	QB_LOG_CONF_STATE_GET,
 	QB_LOG_CONF_FILE_SYNC,
+	QB_LOG_CONF_EXTENDED,
 };
 
 enum qb_log_filter_type {

lib/log.c

@@ -29,6 +29,7 @@
 #include <dlfcn.h>
 #endif /* HAVE_DLFCN_H */
 #include <stdarg.h>
+#include <string.h>
 
 #include <qb/qbdefs.h>
 #include <qb/qblist.h>
@@ -157,14 +158,38 @@ _cs_matches_filter_(struct qb_log_callsite *cs,
 	return match;
 }
 
+/**
+ * @internal
+ * @brief Format a log message into a string buffer
+ *
+ * @param[out] str  Destination buffer to contain formatted string
+ * @param[in]  cs   Callsite containing format to use
+ * @param[in]  ap   Variable arguments for format
+ */
+static inline void
+cs_format(char *str, struct qb_log_callsite *cs, va_list ap)
+{
+	va_list ap_copy;
+	int len;
+
+	va_copy(ap_copy, ap);
+	len = vsnprintf(str, QB_LOG_MAX_LEN, cs->format, ap_copy);
+	va_end(ap_copy);
+	if (len > QB_LOG_MAX_LEN) {
+		len = QB_LOG_MAX_LEN;
+	}
+	if (str[len - 1] == '\n') {
+		str[len - 1] = '\0';
+	}
+}
+
 void
 qb_log_real_va_(struct qb_log_callsite *cs, va_list ap)
 {
-	int32_t found_threaded;
+	int32_t found_threaded = QB_FALSE;
 	struct qb_log_target *t;
 	struct timespec tv;
 	int32_t pos;
-	int len;
 	int32_t formatted = QB_FALSE;
 	char buf[QB_LOG_MAX_LEN];
 	char *str = buf;
@@ -175,20 +200,15 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap)
 	}
 	in_logger = QB_TRUE;
 
-	if (old_internal_log_fn) {
-		if (qb_bit_is_set(cs->tags, QB_LOG_TAG_LIBQB_MSG_BIT)) {
-			if (!formatted) {
-				va_copy(ap_copy, ap);
-				len = vsnprintf(str, QB_LOG_MAX_LEN, cs->format, ap_copy);
-				va_end(ap_copy);
-				if (len > QB_LOG_MAX_LEN)
-					len = QB_LOG_MAX_LEN;
-				if (str[len - 1] == '\n') str[len - 1] = '\0';
-				formatted = QB_TRUE;
-			}
-			old_internal_log_fn(cs->filename, cs->lineno,
-					    cs->priority, str);
+	if (old_internal_log_fn &&
+	    qb_bit_is_set(cs->tags, QB_LOG_TAG_LIBQB_MSG_BIT)) {
+		if (formatted == QB_FALSE) {
+			cs_format(str, cs, ap);
+			formatted = QB_TRUE;
 		}
+		qb_do_extended(str, QB_TRUE,
+			old_internal_log_fn(cs->filename, cs->lineno,
+					    cs->priority, str));
 	}
 
 	qb_util_timespec_from_epoch_get(&tv);
@@ -197,45 +217,31 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap)
 	 * 1 if we can find a threaded target that needs this log then post it
 	 * 2 foreach non-threaded target call it's logger function
 	 */
-	found_threaded = QB_FALSE;
-
 	for (pos = 0; pos <= conf_active_max; pos++) {
 		t = &conf[pos];
-		if (t->state != QB_LOG_STATE_ENABLED) {
-			continue;
-		}
-		if (t->threaded) {
-			if (!found_threaded
-			    && qb_bit_is_set(cs->targets, t->pos)) {
-				found_threaded = QB_TRUE;
-				if (!formatted) {
-					va_copy(ap_copy, ap);
-					len = vsnprintf(str, QB_LOG_MAX_LEN, cs->format, ap_copy);
-					va_end(ap_copy);
-					if (len > QB_LOG_MAX_LEN)
-						len = QB_LOG_MAX_LEN;
-					if (str[len - 1] == '\n') str[len - 1] = '\0';
-					formatted = QB_TRUE;
-				}
-			}
-		} else {
-			if (qb_bit_is_set(cs->targets, t->pos)) {
-				if (t->vlogger) {
-					va_copy(ap_copy, ap);
-					t->vlogger(t->pos, cs, tv.tv_sec, ap_copy);
-					va_end(ap_copy);
-				} else if (t->logger) {
-					if (!formatted) {
-						va_copy(ap_copy, ap);
-						len = vsnprintf(str, QB_LOG_MAX_LEN, cs->format, ap_copy);
-						va_end(ap_copy);
-						if (len > QB_LOG_MAX_LEN)
-							len = QB_LOG_MAX_LEN;
-						if (str[len - 1] == '\n') str[len - 1] = '\0';
+		if ((t->state == QB_LOG_STATE_ENABLED)
+		    && qb_bit_is_set(cs->targets, pos)) {
+			if (t->threaded) {
+				if (!found_threaded) {
+					found_threaded = QB_TRUE;
+					if (formatted == QB_FALSE) {
+						cs_format(str, cs, ap);
 						formatted = QB_TRUE;
 					}
-					t->logger(t->pos, cs, tv.tv_sec, str);
 				}
+
+			} else if (t->vlogger) {
+				va_copy(ap_copy, ap);
+				t->vlogger(t->pos, cs, tv.tv_sec, ap_copy);
+				va_end(ap_copy);
+
+			} else if (t->logger) {
+				if (formatted == QB_FALSE) {
+					cs_format(str, cs, ap);
+					formatted = QB_TRUE;
+				}
+				qb_do_extended(str, t->extended,
+					       t->logger(t->pos, cs, tv.tv_sec, str));
 			}
 		}
 	}
@@ -265,14 +271,10 @@ qb_log_thread_log_write(struct qb_log_callsite *cs,
 
 	for (pos = 0; pos <= conf_active_max; pos++) {
 		t = &conf[pos];
-		if (t->state != QB_LOG_STATE_ENABLED) {
-			continue;
-		}
-		if (!t->threaded) {
-			continue;
-		}
-		if (qb_bit_is_set(cs->targets, t->pos)) {
-			t->logger(t->pos, cs, timestamp, buffer);
+		if ((t->state == QB_LOG_STATE_ENABLED) && t->threaded
+		    && qb_bit_is_set(cs->targets, t->pos)) {
+			qb_do_extended(buffer, t->extended,
+				t->logger(t->pos, cs, timestamp, buffer));
 		}
 	}
 }
@@ -810,6 +812,7 @@ qb_log_init(const char *name, int32_t facility, uint8_t priority)
 		conf[i].pos = i;
 		conf[i].debug = QB_FALSE;
 		conf[i].file_sync = QB_FALSE;
+		conf[i].extended = QB_TRUE;
 		conf[i].state = QB_LOG_STATE_UNUSED;
 		(void)strlcpy(conf[i].name, name, PATH_MAX);
 		conf[i].facility = facility;
@@ -1064,6 +1067,9 @@ qb_log_ctl(int32_t t, enum qb_log_conf c, int32_t arg)
 	case QB_LOG_CONF_THREADED:
 		conf[t].threaded = arg;
 		break;
+	case QB_LOG_CONF_EXTENDED:
+		conf[t].extended = arg;
+		break;
 
 	default:
 		rc = -EINVAL;

lib/log_format.c

@@ -460,12 +460,22 @@ qb_vsnprintf_serialize(char *serialize, size_t max_len,
 {
 	char *format;
 	char *p;
+	char *qb_xc;
 	int type_long = QB_FALSE;
 	int type_longlong = QB_FALSE;
         int sformat_length = 0;
         int sformat_precision = QB_FALSE;
 	uint32_t location = my_strlcpy(serialize, fmt, max_len) + 1;
 
+	/* Assume serialized output always wants extended information
+	 * (@todo: add variant of this function that takes argument for whether
+	 * to print extended information, and make this a macro with that
+	 * argument set to QB_TRUE, so callers can honor extended setting)
+	 */
+	if ((qb_xc = strchr(serialize, QB_XC)) != NULL) {
+		*qb_xc = *(qb_xc + 1)? '|' : '\0';
+	}
+
 	format = (char *)fmt;
 	for (;;) {
 		type_long = QB_FALSE;

lib/log_int.h

@@ -38,6 +38,7 @@ struct qb_log_target {
 	int32_t priority_bump;
 	int32_t file_sync;
 	int32_t debug;
+	int32_t extended;
 	size_t size;
 	char *format;
 	int32_t threaded;
@@ -70,6 +71,36 @@ struct qb_log_record {
 
 #define TIME_STRING_SIZE 64
 
+/**
+ * @internal
+ * @brief Call a log function, handling any extended information marker
+ *
+ * If the string to be passed to the log function contains an extended
+ * information marker, temporarily modify the string to strip the extended
+ * information if appropriate. Special cases: if a marker occurs with nothing
+ * after it, it will always be stripped; if only extended information is
+ * present, stmt will be called only if extended is true.
+ *
+ * @param[in]  str       Null-terminated log message
+ * @param[in]  extended  QB_TRUE if extended information should be printed
+ * @param[in]  stmt      Code block to call log function
+ *
+ * @note Because this is a macro, none of the arguments other than stmt should
+ *       have side effects.
+ */
+#define qb_do_extended(str, extended, stmt) do { \
+	char *qb_xc = strchr((str), QB_XC); \
+	if (qb_xc) { \
+		if ((qb_xc != (str)) || (extended)) { \
+			*qb_xc = ((extended) && *(qb_xc + 1))? '|' : '\0'; \
+			stmt; \
+			*qb_xc = QB_XC; \
+		} \
+	} else { \
+		stmt; \
+	} \
+} while (0)
+
 struct qb_log_target * qb_log_target_alloc(void);
 void qb_log_target_free(struct qb_log_target *t);
 struct qb_log_target * qb_log_target_get(int32_t pos);