Loggers specify what log messages they want to receive during registration.

This also allows us to generate the log message only once for all
loggers that need it (avoids calls to custom printf specifier callbacks).

To update the log levels loggers can simply be registered again.

src/libcharon/bus/bus.c

@@ -40,9 +40,17 @@ struct private_bus_t {
 	linked_list_t *listeners;
 
 	/**
-	 * List of registered loggers.
+	 * List of registered loggers for each log group as log_entry_t.
+	 * Loggers are ordered by descending log level.
+	 * The extra list stores all loggers so we can properly unregister them.
 	 */
-	linked_list_t *loggers;
+	linked_list_t *loggers[DBG_MAX + 1];
+
+	/**
+	 * Maximum log level of any registered logger for each log group.
+	 * This allows to check quickly if a log message has to be logged at all.
+	 */
+	level_t max_level[DBG_MAX + 1];
 
 	/**
 	 * Mutex for the list of listeners, recursively.
@@ -79,6 +87,25 @@ struct entry_t {
 
 };
 
+typedef struct log_entry_t log_entry_t;
+
+/**
+ * a logger entry
+ */
+struct log_entry_t {
+
+	/**
+	 * registered logger interface
+	 */
+	logger_t *logger;
+
+	/**
+	 * registered log levels per group
+	 */
+	level_t levels[DBG_MAX];
+
+};
+
 METHOD(bus_t, add_listener, void,
 	private_bus_t *this, listener_t *listener)
 {
@@ -114,11 +141,98 @@ METHOD(bus_t, remove_listener, void,
 	this->mutex->unlock(this->mutex);
 }
 
+/**
+ * Register a logger on the given log group according to the requested level
+ */
+static inline void register_logger(private_bus_t *this, debug_t group,
+								   log_entry_t *entry)
+{
+	enumerator_t *enumerator;
+	linked_list_t *loggers;
+	log_entry_t *current;
+	level_t level;
+
+	loggers = this->loggers[group];
+	level = entry->levels[group];
+
+	enumerator = loggers->create_enumerator(loggers);
+	while (enumerator->enumerate(enumerator, (void**)&current))
+	{
+		if (current->levels[group] <= level)
+		{
+			break;
+		}
+	}
+	loggers->insert_before(loggers, enumerator, entry);
+	enumerator->destroy(enumerator);
+
+	this->max_level[group] = max(this->max_level[group], level);
+}
+
+/**
+ * Unregister a logger from all log groups (destroys the log_entry_t)
+ */
+static inline void unregister_logger(private_bus_t *this, logger_t *logger)
+{
+	enumerator_t *enumerator;
+	linked_list_t *loggers;
+	log_entry_t *entry, *found = NULL;
+
+	loggers = this->loggers[DBG_MAX];
+	enumerator = loggers->create_enumerator(loggers);
+	while (enumerator->enumerate(enumerator, &entry))
+	{
+		if (entry->logger == logger)
+		{
+			loggers->remove_at(loggers, enumerator);
+			found = entry;
+			break;
+		}
+	}
+	enumerator->destroy(enumerator);
+
+	if (found)
+	{
+		debug_t group;
+		for (group = 0; group < DBG_MAX; group++)
+		{
+			if (found->levels[group] > LEVEL_SILENT)
+			{
+				loggers = this->loggers[group];
+				loggers->remove(loggers, found, NULL);
+
+				this->max_level[group] = LEVEL_SILENT;
+				if (loggers->get_first(loggers, (void**)&entry) == SUCCESS)
+				{
+					this->max_level[group] = entry->levels[group];
+				}
+			}
+		}
+		free(found);
+	}
+}
+
 METHOD(bus_t, add_logger, void,
 	private_bus_t *this, logger_t *logger)
 {
+	log_entry_t *entry;
+	debug_t group;
+
+	INIT(entry,
+		.logger = logger,
+	);
+
 	this->log_lock->write_lock(this->log_lock);
-	this->loggers->insert_last(this->loggers, logger);
+	unregister_logger(this, logger);
+	for (group = 0; group < DBG_MAX; group++)
+	{
+		entry->levels[group] = logger->get_level(logger, group);
+		if (entry->levels[group] > LEVEL_SILENT)
+		{
+			register_logger(this, group, entry);
+		}
+	}
+	this->loggers[DBG_MAX]->insert_last(this->loggers[DBG_MAX], entry);
 	this->log_lock->unlock(this->log_lock);
 }
 
@@ -126,7 +240,7 @@ METHOD(bus_t, remove_logger, void,
 	private_bus_t *this, logger_t *logger)
 {
 	this->log_lock->write_lock(this->log_lock);
-	this->loggers->remove(this->loggers, logger, NULL);
+	unregister_logger(this, logger);
 	this->log_lock->unlock(this->log_lock);
 }
 
@@ -154,43 +268,41 @@ typedef struct {
 	debug_t group;
 	/** debug level */
 	level_t level;
-	/** format string */
-	char *format;
-	/** argument list */
-	va_list args;
+	/** message */
+	char message[8192];
 } log_data_t;
 
 /**
  * logger->log() invocation as a invoke_function callback
  */
-static void log_cb(logger_t *logger, log_data_t *data)
+static void log_cb(log_entry_t *entry, log_data_t *data)
 {
-	va_list args;
-
-	va_copy(args, data->args);
-	logger->log(logger, data->group, data->level, data->thread, data->ike_sa,
-				data->format, args);
-	va_end(args);
+	if (entry->levels[data->group] < data->level)
+	{
+		return;
+	}
+	entry->logger->log(entry->logger, data->group, data->level,
+					   data->thread, data->ike_sa, data->message);
 }
 
 METHOD(bus_t, vlog, void,
 	private_bus_t *this, debug_t group, level_t level,
 	char* format, va_list args)
 {
-	log_data_t data;
-
-	data.ike_sa = this->thread_sa->get(this->thread_sa);
-	data.thread = thread_current_id();
-	data.group = group;
-	data.level = level;
-	data.format = format;
-	va_copy(data.args, args);
-
 	this->log_lock->read_lock(this->log_lock);
-	this->loggers->invoke_function(this->loggers, (void*)log_cb, &data);
-	this->log_lock->unlock(this->log_lock);
+	if (this->max_level[group] >= level)
+	{
+		linked_list_t *loggers = this->loggers[group];
+		log_data_t data;
 
-	va_end(data.args);
+		data.ike_sa = this->thread_sa->get(this->thread_sa);
+		data.thread = thread_current_id();
+		data.group = group;
+		data.level = level;
+		vsnprintf(data.message, sizeof(data.message), format, args);
+		loggers->invoke_function(loggers, (linked_list_invoke_t)log_cb, &data);
+	}
+	this->log_lock->unlock(this->log_lock);
 }
 
 METHOD(bus_t, log_, void,
@@ -598,8 +710,14 @@ METHOD(bus_t, narrow, void,
 METHOD(bus_t, destroy, void,
 	private_bus_t *this)
 {
+	debug_t group;
+	for (group = 0; group < DBG_MAX; group++)
+	{
+		this->loggers[group]->destroy(this->loggers[group]);
+	}
+	this->loggers[DBG_MAX]->destroy_function(this->loggers[DBG_MAX],
+											 (void*)free);
 	this->listeners->destroy_function(this->listeners, (void*)free);
-	this->loggers->destroy(this->loggers);
 	this->thread_sa->destroy(this->thread_sa);
 	this->log_lock->destroy(this->log_lock);
 	this->mutex->destroy(this->mutex);
@@ -612,6 +730,7 @@ METHOD(bus_t, destroy, void,
 bus_t *bus_create()
 {
 	private_bus_t *this;
+	debug_t group;
 
 	INIT(this,
 		.public = {
@@ -638,12 +757,17 @@ bus_t *bus_create()
 			.destroy = _destroy,
 		},
 		.listeners = linked_list_create(),
-		.loggers = linked_list_create(),
 		.mutex = mutex_create(MUTEX_TYPE_RECURSIVE),
 		.log_lock = rwlock_create(RWLOCK_TYPE_DEFAULT),
 		.thread_sa = thread_value_create(NULL),
 	);
 
+	for (group = 0; group <= DBG_MAX; group++)
+	{
+		this->loggers[group] = linked_list_create();
+		this->max_level[group] = LEVEL_SILENT;
+	}
+
 	return &this->public;
 }
 

src/libcharon/bus/bus.h

@@ -150,6 +150,14 @@ struct bus_t {
 	 * by multiple threads.  Recursive calls are not prevented, so logger that
 	 * may cause recursive calls are responsible to avoid infinite loops.
 	 *
+	 * During registration get_level() is called for all log groups and the
+	 * logger is registered to receive log messages for groups for which
+	 * the requested log level is > LEVEL_SILENT and whose level is lower
+	 * or equal than the requested level.
+	 *
+	 * To update the registered log levels call add_logger again with the
+	 * same logger and return the new levels from get_level().
+	 *
 	 * @param logger	logger to register.
 	 */
 	void (*add_logger) (bus_t *this, logger_t *logger);

src/libcharon/bus/listeners/file_logger.c

@@ -62,65 +62,65 @@ struct private_file_logger_t {
 
 METHOD(logger_t, log_, void,
 	private_file_logger_t *this, debug_t group, level_t level, int thread,
-	ike_sa_t* ike_sa, char *format, va_list args)
+	ike_sa_t* ike_sa, char *message)
 {
-	if (level <= this->levels[group])
-	{
-		char buffer[8192], timestr[128], namestr[128] = "";
-		char *current = buffer, *next;
-		struct tm tm;
-		time_t t;
+	char timestr[128], namestr[128] = "";
+	char *current = message, *next;
+	struct tm tm;
+	time_t t;
 
-		if (this->time_format)
+	if (this->time_format)
+	{
+		t = time(NULL);
+		localtime_r(&t, &tm);
+		strftime(timestr, sizeof(timestr), this->time_format, &tm);
+	}
+	if (this->ike_name && ike_sa)
+	{
+		if (ike_sa->get_peer_cfg(ike_sa))
 		{
-			t = time(NULL);
-			localtime_r(&t, &tm);
-			strftime(timestr, sizeof(timestr), this->time_format, &tm);
-		}
-		if (this->ike_name && ike_sa)
-		{
-			if (ike_sa->get_peer_cfg(ike_sa))
-			{
-				snprintf(namestr, sizeof(namestr), " <%s|%d>",
-					ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
-			}
-			else
-			{
-				snprintf(namestr, sizeof(namestr), " <%d>",
-					ike_sa->get_unique_id(ike_sa));
-			}
+			snprintf(namestr, sizeof(namestr), " <%s|%d>",
+				ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 		}
 		else
 		{
-			namestr[0] = '\0';
+			snprintf(namestr, sizeof(namestr), " <%d>",
+				ike_sa->get_unique_id(ike_sa));
 		}
-
-		/* write in memory buffer first */
-		vsnprintf(buffer, sizeof(buffer), format, args);
-
-		/* prepend a prefix in front of every line */
-		this->mutex->lock(this->mutex);
-		while (current)
-		{
-			next = strchr(current, '\n');
-			if (next)
-			{
-				*(next++) = '\0';
-			}
-			if (this->time_format)
-			{
-				fprintf(this->out, "%s %.2d[%N]%s %s\n",
-						timestr, thread, debug_names, group, namestr, current);
-			}
-			else
-			{
-				fprintf(this->out, "%.2d[%N]%s %s\n",
-						thread, debug_names, group, namestr, current);
-			}
-			current = next;
-		}
-		this->mutex->unlock(this->mutex);
 	}
+	else
+	{
+		namestr[0] = '\0';
+	}
+
+	/* prepend a prefix in front of every line */
+	this->mutex->lock(this->mutex);
+	while (current)
+	{
+		next = strchr(current, '\n');
+		if (next)
+		{
+			*(next++) = '\0';
+		}
+		if (this->time_format)
+		{
+			fprintf(this->out, "%s %.2d[%N]%s %s\n",
+					timestr, thread, debug_names, group, namestr, current);
+		}
+		else
+		{
+			fprintf(this->out, "%.2d[%N]%s %s\n",
+					thread, debug_names, group, namestr, current);
+		}
+		current = next;
+	}
+	this->mutex->unlock(this->mutex);
+}
+
+METHOD(logger_t, get_level, level_t,
+	private_file_logger_t *this, debug_t group)
+{
+	return this->levels[group];
 }
 
 METHOD(file_logger_t, set_level, void,
@@ -161,6 +161,7 @@ file_logger_t *file_logger_create(FILE *out, char *time_format, bool ike_name)
 		.public = {
 			.logger = {
 				.log = _log_,
+				.get_level = _get_level,
 			},
 			.set_level = _set_level,
 			.destroy = _destroy,

src/libcharon/bus/listeners/logger.h

@@ -33,21 +33,31 @@ struct logger_t {
 	/**
 	 * Log a debugging message.
 	 *
-	 * @note Calls to bus_t.log() are handled seperately from calls to
-	 * other functions. This callback may be called concurrently by
-	 * multiple threads.  Also recurisve calls are not prevented, logger that
-	 * may cause recursive calls are responsible to avoid infinite loops.
+	 * @note Calls to bus_t.log() are handled separately from calls to
+	 * other functions.  This callback may be called concurrently by
+	 * multiple threads.  Also recursive calls are not prevented, loggers that
+	 * may cause recursive log messages are responsible to avoid infinite loops.
 	 *
 	 * @param group		kind of the signal (up, down, rekeyed, ...)
 	 * @param level		verbosity level of the signal
 	 * @param thread	ID of the thread raised this signal
 	 * @param ike_sa	IKE_SA associated to the event
-	 * @param format	printf() style format string
-	 * @param args		vprintf() style argument list
+	 * @param message	log message
 	 */
 	void (*log)(logger_t *this, debug_t group, level_t level, int thread,
-				ike_sa_t *ike_sa, char* format, va_list args);
+				ike_sa_t *ike_sa, char* message);
 
+	/**
+	 * Get the desired log level for a debug group.  This is called during
+	 * registration.
+	 *
+	 * If the desired log levels have changed, re-register the logger with
+	 * the bus.
+	 *
+	 * @param group		debug group
+	 * @return			max level to log (0..4) or -1 for none (see debug.h)
+	 */
+	level_t (*get_level)(logger_t *this, debug_t group);
 };
 
 #endif /** LOGGER_H_ @}*/

src/libcharon/bus/listeners/sys_logger.c

@@ -57,47 +57,48 @@ struct private_sys_logger_t {
 
 METHOD(logger_t, log_, void,
 	private_sys_logger_t *this, debug_t group, level_t level, int thread,
-	ike_sa_t* ike_sa, char *format, va_list args)
+	ike_sa_t* ike_sa, char *message)
 {
-	if (level <= this->levels[group])
+	char groupstr[4], namestr[128] = "";
+	char *current = message, *next;
+
+	/* cache group name and optional name string */
+	snprintf(groupstr, sizeof(groupstr), "%N", debug_names, group);
+
+	if (this->ike_name && ike_sa)
 	{
-		char buffer[8192], groupstr[4], namestr[128] = "";
-		char *current = buffer, *next;
-
-		/* write in memory buffer first */
-		vsnprintf(buffer, sizeof(buffer), format, args);
-		/* cache group name and optional name string */
-		snprintf(groupstr, sizeof(groupstr), "%N", debug_names, group);
-
-		if (this->ike_name && ike_sa)
+		if (ike_sa->get_peer_cfg(ike_sa))
 		{
-			if (ike_sa->get_peer_cfg(ike_sa))
-			{
-				snprintf(namestr, sizeof(namestr), " <%s|%d>",
-					ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
-			}
-			else
-			{
-				snprintf(namestr, sizeof(namestr), " <%d>",
-					ike_sa->get_unique_id(ike_sa));
-			}
+			snprintf(namestr, sizeof(namestr), " <%s|%d>",
+				ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 		}
-
-		/* do a syslog for every line */
-		this->mutex->lock(this->mutex);
-		while (current)
+		else
 		{
-			next = strchr(current, '\n');
-			if (next)
-			{
-				*(next++) = '\0';
-			}
-			syslog(this->facility|LOG_INFO, "%.2d[%s]%s %s\n",
-				   thread, groupstr, namestr, current);
-			current = next;
+			snprintf(namestr, sizeof(namestr), " <%d>",
+				ike_sa->get_unique_id(ike_sa));
 		}
-		this->mutex->unlock(this->mutex);
 	}
+
+	/* do a syslog for every line */
+	this->mutex->lock(this->mutex);
+	while (current)
+	{
+		next = strchr(current, '\n');
+		if (next)
+		{
+			*(next++) = '\0';
+		}
+		syslog(this->facility|LOG_INFO, "%.2d[%s]%s %s\n",
+			   thread, groupstr, namestr, current);
+		current = next;
+	}
+	this->mutex->unlock(this->mutex);
+}
+
+METHOD(logger_t, get_level, level_t,
+	private_sys_logger_t *this, debug_t group)
+{
+	return this->levels[group];
 }
 
 METHOD(sys_logger_t, set_level, void,
@@ -135,6 +136,7 @@ sys_logger_t *sys_logger_create(int facility, bool ike_name)
 		.public = {
 			.logger = {
 				.log = _log_,
+				.get_level = _get_level,
 			},
 			.set_level = _set_level,
 			.destroy = _destroy,