Use the ring buffer

Enable logging to the ring buffer through an environment variable (and
use it in the test setup). Enrich some error & fatal logs with dumping
the ring buffer.

README

@@ -50,3 +50,8 @@ respectively. The levels are:
 
 Note that what is logged is also limited by what logging is compiled in with
 the `MAX_LOG_LEVEL` make option above.
+
+Furthermore, it is possible to enable an internal logging ringbuffer. If you
+run with `PAKOND_RINGLOG=yes` environment variable, all the messages (even the
+ones that are not output) are stored for some time and they are dumped in case
+a problem happens. It is recommended to do so when trying to debug a problem.

launch

 #!/bin/bash
 
-: ${PAKOND_STDERR_LEVEL:=DBG} ${PAKOND_SYSLOG_LEVEL:=FATAL}
-export PAKOND_STDERR_LEVEL PAKOND_SYSLOG_LEVEL
+: ${PAKOND_STDERR_LEVEL:=DBG} ${PAKOND_SYSLOG_LEVEL:=FATAL} ${PAKOND_RINGLOG=yes}
+export PAKOND_STDERR_LEVEL PAKOND_SYSLOG_LEVEL PAKOND_RINGLOG
 
 iptables -A INPUT -j NFQUEUE --queue-num 0
 iptables -A OUTPUT -j NFQUEUE --queue-num 1

src/main.cpp

@@ -29,10 +29,10 @@ int main(int argc, const char *argv[]) {
 		thread.run();
 		return 0;
 	} catch (const std::exception &e) {
-		LOG(FATAL, "Unhandled exception: ", [&e] {return e.what();});
+		LOG_DUMP(FATAL, "Unhandled exception: ", [&e] {return e.what();});
 		return 1;
 	} catch (...) {
-		LOG(FATAL, "Unhandled unknown exception");
+		LOG_DUMP(FATAL, "Unhandled unknown exception");
 		return 1;
 	}
 }

src/nfq.cpp

@@ -139,7 +139,7 @@ bool NFQ::process() {
 		 */
 		int result = nfq_handle_packet(handle, data, recvHeaders[i].msg_len);
 		if (result != 0)
-			LOG(ERROR, "Failed to handle a packet: ", result, "/", Blob(data, recvHeaders[i].msg_len).toString());
+			LOG_DUMP(ERROR, "Failed to handle a packet: ", result, "/", Blob(data, recvHeaders[i].msg_len).toString());
 	}
 	// Process the packets and assign flows
 	const Flows &flows(dissector.process(packets));

src/ringlog.cpp

@@ -95,7 +95,7 @@ atomic<uint32_t> generation;
 // value that matters has an initializer
 class MsgCache {
 private:
-	Msg *cache[cacheMaxSize];
+	Msg *cache[cacheMaxSize] = {};
 	size_t cacheSize = 0;
 public:
 	// When a thread terminates, we don't want to leak the messages

src/util.cpp

@@ -51,6 +51,7 @@ LogLevel name2Level(const char *name) {
 // This is also limited by what is compiled in with MAX_LOG_LEVEL
 LogLevel maxLogLevelStderr = TRACE;
 LogLevel maxLogLevelSyslog = TRACE;
+bool ringlogEnabled = false;
 
 void doSyslog(LogLevel level, const std::string &msg) {
 	syslog(prios[level], "%s", msg.c_str());
@@ -59,6 +60,8 @@ void doSyslog(LogLevel level, const std::string &msg) {
 void loggingInitialize() {
 	maxLogLevelStderr = name2Level(getenv("PAKOND_STDERR_LEVEL"));
 	maxLogLevelSyslog = name2Level(getenv("PAKOND_SYSLOG_LEVEL"));
+	const char *ringlogEnabledEnv = getenv("PAKOND_RINGLOG");
+	ringlogEnabled = ringlogEnabledEnv && (strcasecmp(ringlogEnabledEnv, "yes") == 0);
 	openlog("pakond", LOG_PID, LOG_DAEMON);
 }
 
@@ -74,7 +77,7 @@ uint64_t timeGrab(clockid_t id) {
 
 bool inValgrind() {
 	const char *inValgrindEnv = getenv("IN_VALGRIND");
-	return inValgrindEnv && (strcmp(inValgrindEnv, "yes") == 0);
+	return inValgrindEnv && (strcasecmp(inValgrindEnv, "yes") == 0);
 }
 
 }

src/util.hpp

@@ -20,6 +20,8 @@
 #ifndef PAKOND_UTIL_H
 #define PAKOND_UTIL_H
 
+#include "ringlog.hpp"
+
 #include <sstream>
 #include <string>
 #include <cstring>
@@ -148,6 +150,7 @@ constexpr bool logEnabled(LogLevel level) { return level >= MAX_LOG_LEVEL; }
 
 extern LogLevel maxLogLevelStderr;
 extern LogLevel maxLogLevelSyslog;
+extern bool ringlogEnabled;
 
 // Is this log severity level enabled on stderr?
 static inline bool logEnabledStderr(LogLevel level) {
@@ -197,7 +200,7 @@ template<class ...Msgs> void log(LogLevel level, const char *file, size_t line,
 		loggingInitialize();
 	const bool enabledSyslog = logEnabledSyslog(level);
 	const bool enabledStderr = logEnabledStderr(level);
-	if (enabledStderr || enabledSyslog) {
+	if (enabledStderr || enabledSyslog || ringlogEnabled) {
 		// Construct the message in memory and output it at once (hopufully atomic)
 		std::stringstream output;
 		logPrint(output, msgs...);
@@ -205,10 +208,13 @@ template<class ...Msgs> void log(LogLevel level, const char *file, size_t line,
 		const std::string &str = output.str();
 		if (enabledSyslog)
 			doSyslog(level, str);
-		if (enabledStderr) {
+		if (enabledStderr || ringlogEnabled) {
 			std::stringstream output_full;
 			output_full << std::left << logName(level) << "\t" << std::setw(23) << file << std::setw(0) << "\t" << line << "\t" << std::setw(55) << function << std::setw(0) << "\t" << std::this_thread::get_id() << "\t" << str;
-			std::cerr << output_full.str();
+			const std::string full = output_full.str();
+			if (enabledStderr)
+				std::cerr << full;
+			ringlog(full);
 		}
 	}
 }
@@ -221,6 +227,9 @@ template<class ...Msgs> void log(LogLevel level, const char *file, size_t line,
 //
 #define TRC LOG(TRACE, "Passing here")
 
+// Log and dump a ringbuffer if it is enabled
+#define LOG_DUMP(LEVEL, ...) do { LOG(LEVEL, __VA_ARGS__); if (ringlogEnabled) dumpRingFile(); } while (0)
+
 // Time in seconds
 uint64_t timeGrab(clockid_t id = CLOCK_REALTIME_COARSE);
 // Time in msec

src/worker.cpp

@@ -72,9 +72,9 @@ void Worker::run() {
 		LOG(DBG, "Terminating worker");
 		return;
 	} catch (const std::exception &e) {
-		LOG(ERROR, "Lost thread due to exception: ", [&e]{ return e.what(); });
+		LOG_DUMP(ERROR, "Lost thread due to exception: ", [&e]{ return e.what(); });
 	} catch (...) {
-		LOG(ERROR, "Lost thread due to unknown exception");
+		LOG_DUMP(ERROR, "Lost thread due to unknown exception");
 	}
 	// We get here only if there was an exception (we return early on success)
 	MainThread::global().lostThread(id());