Merge pull request #155 from kgaillot/splitlogging

Implement extended information logging (aka split logging)

.gitignore

@@ -6,6 +6,7 @@
 *.so.*
 *.3
 *.rpm
+*.swp
 *.pc
 *.log
 Makefile
@@ -27,3 +28,4 @@ abi_dumps
 TAGS
 *~
 test-driver
+tests/*.trs

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

tests/check_log.c

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2011 Red Hat, Inc.
+ * Copyright (c) 2011-2015 Red Hat, Inc.
  *
  * All rights reserved.
  *
@@ -708,6 +708,63 @@ START_TEST(test_threaded_logging)
 }
 END_TEST
 
+START_TEST(test_extended_information)
+{
+	int32_t t;
+	int32_t rc;
+	int extended;
+
+	qb_log_init("test", LOG_USER, LOG_DEBUG);
+	qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
+
+	t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
+	_ck_assert_int(t, >, QB_LOG_STDOUT);
+	qb_log_format_set(t, "%b");
+	rc = qb_log_filter_fn_set(NULL);
+	ck_assert_int_eq(rc, 0);
+	rc = qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_FILTER_FILE,
+			       "*", LOG_TRACE);
+	ck_assert_int_eq(rc, 0);
+	rc = qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_FILTER_FORMAT,
+			       "*", LOG_TRACE);
+	ck_assert_int_eq(rc, 0);
+	rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FORMAT,
+			       "*", LOG_TRACE);
+	ck_assert_int_eq(rc, 0);
+	rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
+	ck_assert_int_eq(rc, 0);
+
+	for (extended = QB_FALSE; extended <= QB_TRUE; ++extended) {
+		rc = qb_log_ctl(t, QB_LOG_CONF_EXTENDED, extended);
+		ck_assert_int_eq(rc, 0);
+
+		num_msgs = 0;
+
+		memset(test_buf, 0, sizeof(test_buf));
+		qb_log(LOG_ERR, "message with no extended information");
+		ck_assert_str_eq(test_buf, "message with no extended information");
+
+		memset(test_buf, 0, sizeof(test_buf));
+		qb_log(LOG_ERR, "message with empty extended information "QB_XS);
+		ck_assert_str_eq(test_buf, "message with empty extended information ");
+
+		memset(test_buf, 0, sizeof(test_buf));
+		qb_log(LOG_ERR, QB_XS" message with only extended information");
+		ck_assert_str_eq(test_buf, extended?
+				 "| message with only extended information" : "");
+
+		memset(test_buf, 0, sizeof(test_buf));
+		qb_log(LOG_ERR, "message with extended information "QB_XS" (namely this)");
+		ck_assert_str_eq(test_buf, extended?
+				 "message with extended information | (namely this)"
+				 : "message with extended information ");
+
+		ck_assert_int_eq(num_msgs, (extended? 4 : 3));
+	}
+	qb_log_fini();
+}
+END_TEST
+
 static Suite *
 log_suite(void)
 {
@@ -751,6 +808,10 @@ log_suite(void)
 	tcase_add_test(tc, test_threaded_logging);
 	suite_add_tcase(s, tc);
 
+	tc = tcase_create("extended_information");
+	tcase_add_test(tc, test_extended_information);
+	suite_add_tcase(s, tc);
+
 	return s;
 }