rewrite logging system with spdlog

include/villas/graph/directed.hpp

@@ -52,7 +52,7 @@ public:
 	DirectedGraph(const std::string& name = "DirectedGraph") :
 	    lastVertexId(0), lastEdgeId(0)
 	{
-		logger = loggerGetOrCreate(name);
+		logger = logging.get(name);
 	}
 
 	std::shared_ptr<VertexType> getVertex(VertexIdentifier vertexId) const
@@ -290,7 +290,7 @@ protected:
 	std::map<VertexIdentifier, std::shared_ptr<VertexType>> vertices;
 	std::map<EdgeIdentifier, std::shared_ptr<EdgeType>> edges;
 
-	SpdLogger logger;
+	Logger logger;
 };
 
 } // namespacae graph

include/villas/log.h

@@ -23,18 +23,14 @@
 
 #pragma once
 
+#include <stdarg.h>
+
+#include <jansson.h>
+
 #ifdef __cplusplus
 extern "C" {
 #endif
 
-#include <stdarg.h>
-#include <stdbool.h>
-#include <time.h>
-#include <sys/ioctl.h>
-
-#include <villas/common.h>
-#include <villas/log_config.h>
-
 /* The log level which is passed as first argument to print() */
 enum log_level {
 	LOG_LVL_DEBUG,
@@ -44,8 +40,6 @@ enum log_level {
 	LOG_LVL_STATS,
 };
 
-typedef void (*log_cb_t)(struct log *l, enum log_level lvl, const char *fmt, va_list va);
-
 /** Debug facilities.
  *
  * To be or-ed with the debug level
@@ -77,7 +71,7 @@ enum log_facilities {
 	LOG_WEBSOCKET =		(1L << 29),
 	LOG_OPAL =		(1L << 30),
 	LOG_COMEDI =		(1L << 31),
-	LOG_IB =		(1L << 32),
+	LOG_IB =		(1LL << 32),
 
 	/* Classes */
 	LOG_NODES = LOG_NODE | LOG_SOCKET | LOG_FILE | LOG_FPGA | LOG_NGSI | LOG_WEBSOCKET | LOG_OPAL | LOG_COMEDI | LOG_IB,
@@ -85,78 +79,10 @@ enum log_facilities {
 	LOG_ALL = ~0xFF
 };
 
-struct log {
-	enum state state;
-
-	const char *name;
-
-	struct timespec epoch;	/**< A global clock used to prefix the log messages. */
-
-	struct winsize window;	/**< Size of the terminal window. */
-	int width;		/**< The real usable log output width which fits into one line. */
-
-	/** Debug level used by the debug() macro.
-	 * It defaults to V (defined by the Makefile) and can be
-	 * overwritten by the 'debug' setting in the configuration file. */
-	int level;
-	long facilities;	/**< Debug facilities used by the debug() macro. */
-	const char *path;	/**< Path of the log file. */
-	char *prefix;		/**< Prefix each line with this string. */
-	int syslog;		/**< Whether or not to log to syslogd. */
-	bool tty;		/**< Is the log file a tty? */
-
-	log_cb_t callback;
-
-	FILE *file;		/**< Send all log output to this file / stdout / stderr. */
-};
-
-/** The global log instance. */
-extern struct log *global_log;
-
-/** Initialize log object */
-int log_init(struct log *l, const char *name, int level, long faciltities);
-
-void log_set_callback(struct log *l, log_cb_t cb);
-
-int log_open(struct log *l);
-
-int log_close(struct log *l);
-
-/** Destroy log object */
-int log_destroy(struct log *l);
-
-/** Set logging facilities based on expression.
- *
- * Currently we support two types of expressions:
- *  1. A comma seperated list of logging facilities
- *  2. A comma seperated list of logging facilities which is prefixes with an exclamation mark '!'
- *
- * The first case enables only faciltities which are in the list.
- * The second case enables all faciltities with exception of those which are in the list.
- *
- * @param expression The expression
- * @return The new facilties mask (see enum log_faciltities)
- */
-int log_set_facility_expression(struct log *l, const char *expression);
-
-/** Logs variadic messages to stdout.
- *
- * @param lvl The log level
- * @param fmt The format string (printf alike)
- */
-void log_print(struct log *l, enum log_level lvl, const char *fmt, ...)
-	__attribute__ ((format(printf, 3, 4)));
-
-/** Logs variadic messages to stdout.
- *
- * @param lvl The log level
- * @param fmt The format string (printf alike)
- * @param va The variadic argument list (see stdarg.h)
- */
-void log_vprint(struct log *l, enum log_level lvl, const char *fmt, va_list va);
+int log_get_width();
 
 /** Printf alike debug message with level. */
-void debug(long lvl, const char *fmt, ...)
+void debug(long long lvl, const char *fmt, ...)
 	__attribute__ ((format(printf, 2, 3)));
 
 /** Printf alike info message. */
@@ -179,6 +105,10 @@ void error(const char *fmt, ...)
 void serror(const char *fmt, ...)
 	__attribute__ ((format(printf, 1, 2)));
 
+/** Print configuration error and exit. */
+void jerror(json_error_t *err, const char *fmt, ...)
+	__attribute__ ((format(printf, 2, 3)));
+
 #ifdef __cplusplus
 }
 #endif

include/villas/log.hpp

@@ -25,33 +25,51 @@
 
 #include <string>
 
-#define SPDLOG_LEVEL_NAMES { "trace", "debug", "info ",  "warn ", "error", "crit ", "off   " }
-#define SPDLOG_NAME_WIDTH 17
 #define SPDLOG_FMT_EXTERNAL
 
 #include <spdlog/spdlog.h>
-#include <spdlog/sinks/stdout_color_sinks.h>
+#include <spdlog/sinks/dist_sink.h>
 #include <spdlog/fmt/ostr.h>
 
-#define _ESCAPE	"\x1b"
-#define TXT_RESET_ALL	_ESCAPE "[0m"
+#include <jansson.h>
 
-#define TXT_RESET_BOLD	_ESCAPE "[21m"
-#define TXT_BOLD(s)		_ESCAPE "[1m" + std::string(s)  + TXT_RESET_BOLD
+#include <villas/terminal.hpp>
 
-#define TXT_RESET_COLOR	_ESCAPE "[39m"
-#define TXT_RED(s)		_ESCAPE "[31m" + std::string(s) + TXT_RESET_COLOR
-#define TXT_GREEN(s)	_ESCAPE "[32m" + std::string(s) + TXT_RESET_COLOR
-#define TXT_YELLOW(s)	_ESCAPE "[33m" + std::string(s) + TXT_RESET_COLOR
-#define TXT_BLUE(s)		_ESCAPE "[34m" + std::string(s) + TXT_RESET_COLOR
+namespace villas {
 
-using SpdLogger = std::shared_ptr<spdlog::logger>;
+/* Forward declarations */
+class Log;
 
-inline SpdLogger loggerGetOrCreate(const std::string& logger_name)
-{
-    auto logger = spdlog::get(logger_name);
-    if(not logger) {
-        logger = spdlog::stdout_color_mt(logger_name);
-    }
-    return logger;
-}
+using Logger = std::shared_ptr<spdlog::logger>;
+
+extern Log logging;
+
+class Log {
+
+public:
+	using DistSink = std::shared_ptr<spdlog::sinks::dist_sink_mt>;
+	using Level = spdlog::level::level_enum;
+
+protected:
+	Logger logger = logging.get("log");
+	DistSink sinks;
+
+	std::string pattern;		/**< Logging format. */
+	std::string prefix;		/**< Prefix each line with this string. */
+
+public:
+
+	Log(Level level = Level::info);
+
+	/**< Get the real usable log output width which fits into one line. */
+	int getWidth();
+
+	void parse(json_t *cfg);
+
+	Logger get(const std::string &name);
+
+	void setLevel(Level lvl);
+	void setLevel(const std::string &lvl);
+};
+
+} // namespace villas

include/villas/log_config.h

-/** Logging routines that depend on jansson.
- *
- * @file
- * @author Steffen Vogel <stvogel@eonerc.rwth-aachen.de>
- * @copyright 2017-2018, Institute for Automation of Complex Power Systems, EONERC
- * @license GNU General Public License (version 3)
- *
- * VILLAScommon
- *
- * This program is free software: you can redistribute it and/or modify
- * it under the terms of the GNU General Public License as published by
- * the Free Software Foundation, either version 3 of the License, or
- * any later version.
- *
- * This program is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- * GNU General Public License for more details.
- *
- * You should have received a copy of the GNU General Public License
- * along with this program.  If not, see <http://www.gnu.org/licenses/>.
- *********************************************************************************/
-
-#pragma once
-
-struct log;
-
-#include <jansson.h>
-
-#include <villas/log.h>
-
-/** Parse logging configuration. */
-int log_parse(struct log *l, json_t *cfg);
-
-/** Print configuration error and exit. */
-void jerror(json_error_t *err, const char *fmt, ...)
-	__attribute__ ((format(printf, 2, 3)));

tests/main.cpp → include/villas/log_opal_sink.hpp

-/** Main Unit Test entry point.
+/** Log sink for OPAL-RTs OpalPrint().
  *
+ * @file
  * @author Steffen Vogel <stvogel@eonerc.rwth-aachen.de>
- * @copyright 2017-2018, Steffen Vogel
+ * @copyright 2018, Institute for Automation of Complex Power Systems, EONERC
  * @license GNU General Public License (version 3)
  *
  * VILLAScommon
@@ -20,29 +21,45 @@
  * along with this program.  If not, see <http://www.gnu.org/licenses/>.
  *********************************************************************************/
 
-#include <criterion/criterion.h>
-#include <criterion/options.h>
+#pragma once
+
+#include <mutex>
 
 #include <villas/log.hpp>
 
-#include <spdlog/spdlog.h>
+#include <spdlog/sinks/base_sink.h>
+#include <spdlog/details/null_mutex.h>
 
-void init_logging();
+namespace villas {
+namespace node {
 
-int main(int argc, char *argv[])
+template<typename Mutex>
+class OpalSink : public spdlog::sinks::base_sink<Mutex>
 {
-	int ret;
 
-	init_logging();
+protected:
+	void sink_it_(const spdlog::details::log_msg& msg) override
+	{
+#ifdef ENABLE_OPAL_ASYNC
+		fmt::memory_buffer formatted;
+
+		sink::formatter_->format(msg, formatted);
+
+		auto str = fmt::to_string(formatted).c_str();
+
+		OpalPrint(PROJECT_NAME ": %s\n", str);
+#endif
+	}
 
-	/* Run criterion tests */
-	auto tests = criterion_initialize();
+	void flush_() override
+	{
+		/* nothing to do */
+	}
+};
 
-	ret = criterion_handle_args(argc, argv, true);
-	if (ret)
-		ret = !criterion_run_all_tests(tests);
+using OpalSink_mt = OpalSink<std::mutex>;
+using OpalSink_st = OpalSink<spdlog::details::null_mutex>;
 
-	criterion_finalize(tests);
 
-	return ret;
-}
+} // namespace node
+} // namespace villas

include/villas/memory.hpp

@@ -135,7 +135,7 @@ public:
 	{
 		// CRTP
 		derivedAlloc = static_cast<DerivedAllocator*>(this);
-		logger = loggerGetOrCreate(derivedAlloc->getName());
+		logger = logging.get(derivedAlloc->getName());
 
 		// default deallocation callback
 		free = [&](MemoryBlock* mem) {
@@ -207,7 +207,7 @@ protected:
 
 protected:
 	MemoryBlock::deallocator_fn free;
-	SpdLogger logger;
+	Logger logger;
 
 	// optional, if allocator should own the memory block
 	std::unique_ptr<MemoryBlock, MemoryBlock::deallocator_fn> memoryBlock;

include/villas/memory_manager.hpp

@@ -97,7 +97,7 @@ private:
 	// This is a singleton, so private constructor ...
 	MemoryManager() :
 	    memoryGraph("MemoryGraph"),
-	    logger(loggerGetOrCreate("MemoryManager"))
+	    logger(logging.get("MemoryManager"))
 	{
 		pathCheckFunc = [&](const MemoryGraph::Path& path) {
 			return this->pathCheck(path);
@@ -262,7 +262,7 @@ private:
 	std::map<std::string, AddressSpaceId> addrSpaceLookup;
 
 	/// Logger for universal access in this class
-	SpdLogger logger;
+	Logger logger;
 
 	MemoryGraph::check_path_fn pathCheckFunc;
 

include/villas/plugin.hpp

@@ -47,9 +47,11 @@ protected:
 
 public:
 
-	static SpdLogger
+	static Logger
 	getLogger()
-	{ return loggerGetOrCreate("plugin:registry"); }
+	{
+		return logging.get("plugin:registry");
+	}
 
 	static void add(Plugin *p)
 	{
@@ -126,9 +128,11 @@ protected:
 	std::string description;
 	std::string path;
 
-	SpdLogger
+	Logger
 	getLogger()
-	{ return loggerGetOrCreate("plugin:" + name); }
+	{
+		return logging.get("plugin:" + name);
+	}
 };
 
 } // namespace plugin

lib/CMakeLists.txt

@@ -32,9 +32,8 @@ add_library(villas-common SHARED
 	kernel/kernel.c
 	kernel/rt.c
 	list.c
-	log.c
-	log_config.c
-	log_helper.c
+	log.cpp
+	log_legacy.cpp
 	memory.cpp
 	memory_manager.cpp
 	plugin.cpp

lib/kernel/vfio.cpp

@@ -44,7 +44,9 @@
 #include <villas/kernel/kernel.h>
 #include <villas/kernel/vfio.hpp>
 
-static auto logger = loggerGetOrCreate("Vfio");
+using namespace villas;
+
+static auto logger = logging.get("kernel:vfio");
 
 static const char *vfio_pci_region_names[] = {
     "PCI_BAR0",		// VFIO_PCI_BAR0_REGION_INDEX,

lib/log.c

-/** Logging and debugging routines
- *
- * @author Steffen Vogel <stvogel@eonerc.rwth-aachen.de>
- * @copyright 2017-2018, Institute for Automation of Complex Power Systems, EONERC
- * @license GNU General Public License (version 3)
- *
- * VILLAScommon
- *
- * This program is free software: you can redistribute it and/or modify
- * it under the terms of the GNU General Public License as published by
- * the Free Software Foundation, either version 3 of the License, or
- * any later version.
- *
- * This program is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- * GNU General Public License for more details.
- *
- * You should have received a copy of the GNU General Public License
- * along with this program.  If not, see <http://www.gnu.org/licenses/>.
- *********************************************************************************/
-
-#include <stdio.h>
-#include <stdbool.h>
-#include <stdarg.h>
-#include <string.h>
-#include <time.h>
-#include <unistd.h>
-#include <syslog.h>
-#include <signal.h>
-
-#include <villas/config.h>
-#include <villas/log.h>
-#include <villas/utils.h>
-#include <villas/timing.h>
-#include <villas/config.h>
-
-#ifdef ENABLE_OPAL_ASYNC
-/* Define RTLAB before including OpalPrint.h for messages to be sent
- * to the OpalDisplay. Otherwise stdout will be used. */
-  #define RTLAB
-  #include "OpalPrint.h"
-#endif
-
-struct log *global_log;
-struct log default_log;
-
-/* We register a default log instance */
-__attribute__((constructor))
-void register_default_log()
-{
-	int ret;
-
-	ret = log_init(&default_log, "default", V, LOG_ALL);
-	if (ret)
-		error("Failed to initalize log");
-
-	ret = log_open(&default_log);
-	if (ret)
-		error("Failed to start log");
-
-	global_log = &default_log;
-}
-
-static const char *level_strs[] = {
-	CLR_GRY("Debug"),	/* LOG_LVL_DEBUG */
-	CLR_WHT("Info "),	/* LOG_LVL_INFO */
-	CLR_YEL("Warn "),	/* LOG_LVL_WARN */
-	CLR_RED("Error"),	/* LOG_LVL_ERROR */
-	CLR_MAG("Stats")	/* LOG_LVL_STATS */
-};
-
-/** List of debug facilities as strings */
-static const char *facilities_strs[] = {
-	"pool",		/* LOG_POOL */
-	"queue",	/* LOG_QUEUE */
-	"config",	/* LOG_CONFIG */
-	"hook",		/* LOG_HOOK */
-	"path",		/* LOG_PATH */
-	"node",		/* LOG_NODE */
-	"mem",		/* LOG_MEM */
-	"web",		/* LOG_WEB */
-	"api",		/* LOG_API */
-	"log",		/* LOG_LOG */
-	"vfio",		/* LOG_VFIO */
-	"pci",		/* LOG_PCI */
-	"xil",		/* LOG_XIL */
-	"tc",		/* LOG_TC */
-	"if",		/* LOG_IF */
-	"advio",	/* LOG_ADVIO */
-	"io",		/* LOG_IO */
-
-	/* Node-types */
-	"socket",	/* LOG_SOCKET */
-	"file",		/* LOG_FILE */
-	"fpga",		/* LOG_FPGA */
-	"ngsi",		/* LOG_NGSI */
-	"websocket",	/* LOG_WEBSOCKET */
-	"opal",		/* LOG_OPAL */
-	"comedi",	/* LOG_COMEDI */
-	"ib",		/* LOG_IB */
-};
-
-static void log_resize(int signal, siginfo_t *sinfo, void *ctx)
-{
-	int ret;
-
-	ret = ioctl(STDOUT_FILENO, TIOCGWINSZ, &global_log->window);
-	if (ret)
-		return;
-
-	global_log->width = global_log->window.ws_col - 25;
-	if (global_log->prefix)
-		global_log->width -= strlenp(global_log->prefix);
-
-	debug(LOG_LOG | 15, "New terminal size: %dx%x", global_log->window.ws_row, global_log->window.ws_col);
-}
-
-int log_init(struct log *l, const char *name, int level, long facilitites)
-{
-	int ret;
-
-	/* Register this log instance globally */
-	global_log = l;
-
-	l->name = name;
-	l->level = level;
-	l->syslog = 0;
-	l->facilities = facilitites;
-	l->file = stderr;
-	l->path = NULL;
-	l->callback = NULL;
-
-	l->epoch = time_now();
-	l->prefix = getenv("VILLAS_LOG_PREFIX");
-
-	/* Register signal handler which is called whenever the
-	 * terminal size changes. */
-	if (l->file == stderr) {
-		struct sigaction sa_resize = {
-			.sa_flags = SA_SIGINFO,
-			.sa_sigaction = log_resize
-		};
-
-		sigemptyset(&sa_resize.sa_mask);
-
-		ret = sigaction(SIGWINCH, &sa_resize, NULL);
-		if (ret)
-			return ret;
-
-		/* Try to get initial window size */
-		ioctl(STDERR_FILENO, TIOCGWINSZ, &l->window);
-
-		/* Fallback if for some reason we can not determine a prober window size */
-		if (l->window.ws_col == 0)
-			l->window.ws_col = 150;
-		if (l->window.ws_row == 0)
-			l->window.ws_row = 50;
-	}
-	else {
-		l->window.ws_col = LOG_WIDTH;
-		l->window.ws_row = LOG_HEIGHT;
-	}
-
-	l->width = l->window.ws_col - 25;
-	if (l->prefix)
-		l->width -= strlenp(l->prefix);
-
-	l->state = STATE_INITIALIZED;
-
-	return 0;
-}
-
-void log_set_callback(struct log *l, log_cb_t cb)
-{
-	l->callback = cb;
-}
-
-int log_open(struct log *l)
-{
-	if (l->path) {
-		l->file = fopen(l->path, "a+");;
-		if (!l->file) {
-			l->file = stderr;
-			error("Failed to open log file '%s'", l->path);
-		}
-	}
-	else
-		l->file = stderr;
-
-	l->tty = isatty(fileno(l->file));
-
-	if (l->syslog) {
-		openlog(NULL, LOG_PID, LOG_DAEMON);
-	}
-
-	l->state = STATE_OPENED;
-
-	debug(LOG_LOG | 5, "Log sub-system started: level=%d, faciltities=%#lx, path=%s", l->level, l->facilities, l->path);
-
-	return 0;
-}
-
-int log_close(struct log *l)
-{
-	if (l->state != STATE_OPENED)
-		return 0;
-