Initial implementation of the new logging mechanism. Implements the c…

…hange proposed in LMMS#5468/LMMS#5159

include/ConsoleLogSink.h

@@ -0,0 +1,14 @@
+#ifndef CONSOLE_LOG_SINK_H
+#define CONSOLE_LOG_SINK_H
+
+#include "Logging.h"
+
+class ConsoleLogSink: public LogSink
+{
+public:
+	ConsoleLogSink(LogVerbosity maxVerbosity, LogManager& logManager);
+	void onLogLine(const LogLine& line) override;
+	~ConsoleLogSink() = default;
+};
+
+#endif // CONSOLE_LOG_SINK_H

include/Logging.h

@@ -0,0 +1,93 @@
+#ifndef DEBUG_TRACE_H
+#define DEBUG_TRACE_H
+
+#include <string>
+#include <vector>
+
+class LogManager;
+
+enum class LogVerbosity
+{
+	Fatal = 0,
+	Error,
+	Warning,
+	Info,
+	Debug_Lo,
+	Debug_Hi,
+
+	Last
+};
+
+struct LogLine
+{
+	LogVerbosity verbosity;
+	unsigned int logLineNo;
+	unsigned long int timestamp;
+	std::string fileName;
+	unsigned int fileLineNo;
+	std::string content;
+
+	LogLine(LogVerbosity verbosity,
+		const char* fileName,
+		unsigned int fileLineNo,
+		const char* content);
+
+	std::string toString() const;
+};
+
+class LogSink
+{
+public:
+	LogSink(LogVerbosity maxVerbosity, LogManager& logManager);
+	virtual ~LogSink();
+
+	virtual void onLogLine(const LogLine& line) = 0;
+
+	LogVerbosity getMaxVerbosity()
+	{
+		return m_maxVerbosity;
+	}
+
+private:
+	LogVerbosity m_maxVerbosity;
+	LogManager& m_logManager;
+};
+
+class LogManager
+{
+public:
+	static LogManager& inst();
+	~LogManager();
+	void addSink(LogSink* sink);
+
+	void pauseFlush();
+	void resumeFlush();
+
+	void push(const LogLine& logLine);
+	void flush();
+
+private:
+	LogManager();
+
+	bool m_flushPaused;
+	LogVerbosity m_maxVerbosity;
+	std::vector<LogSink*> m_sinks;
+	std::vector<LogLine> m_pendingLogLines;
+};
+
+#define Log_Gen(verb,format,...)                                               \
+	do {                                                                   \
+		char _content[1024];                                           \
+		snprintf(_content, sizeof(_content), format, ##__VA_ARGS__);   \
+		LogLine _logLine(verb, __FILE__, __LINE__, _content);          \
+		LogManager::inst().push(std::move(_logLine));                  \
+	} while(0)
+
+#define Log_Fatal(format,...) Log_Gen(LogVerbosity::Fatal, format, ##__VA_ARGS__);
+#define Log_Err(format,...) Log_Gen(LogVerbosity::Error, format, ##__VA_ARGS__);
+#define Log_Wrn(format,...) Log_Gen(LogVerbosity::Warning, format, ##__VA_ARGS__);
+#define Log_Inf(format,...) Log_Gen(LogVerbosity::Info, format, ##__VA_ARGS__);
+#define Log_Dbg_Lo(format, ...) Log_Gen(LogVerbosity::Debug_Lo, format, ##__VA_ARGS__);
+#define Log_Dbg_Hi(format, ...) Log_Gen(LogVerbosity::Debug_Hi, format, ##__VA_ARGS__);
+
+#endif // DEBUG_TRACE_H

src/core/CMakeLists.txt

@@ -9,6 +9,7 @@ set(LMMS_SRCS
 	core/BufferManager.cpp
 	core/Clipboard.cpp
 	core/ComboBoxModel.cpp
+	core/ConsoleLogSink.cpp
 	core/ConfigManager.cpp
 	core/Controller.cpp
 	core/ControllerConnection.cpp
@@ -33,6 +34,7 @@ set(LMMS_SRCS
 	core/LfoController.cpp
 	core/LinkedModelGroups.cpp
 	core/LocklessAllocator.cpp
+	core/Logging.cpp
 	core/MemoryHelper.cpp
 	core/MemoryManager.cpp
 	core/MeterModel.cpp

src/core/ConsoleLogSink.cpp

@@ -0,0 +1,12 @@
+#include <iostream>
+#include "ConsoleLogSink.h"
+
+ConsoleLogSink::ConsoleLogSink(LogVerbosity maxVerbosity, LogManager& logManager)
+	: LogSink(maxVerbosity, logManager)
+{
+}
+
+void ConsoleLogSink::onLogLine(const LogLine& line)
+{
+	std::cout << line.toString() << std::endl;
+}

src/core/Logging.cpp

@@ -0,0 +1,154 @@
+#include "Logging.h"
+#include <sstream>
+#include <iomanip>
+#include <sys/time.h>
+
+const int LOG_QUEUE_SIZE = 256;
+const unsigned int USEC_PER_SEC = 1000000;
+
+#if defined(WIN32) || defined(_WIN32)
+	#define PATH_SEPARATOR "\\"
+#else
+	#define PATH_SEPARATOR "/"
+#endif
+
+
+LogLine::LogLine(LogVerbosity verbosity,
+		const char* fileName,
+		unsigned int fileLineNo,
+		const char* content)
+{
+	static unsigned int logLineNo = 0;
+	static unsigned long int initialTimestamp = 0;
+	struct timeval tv;
+
+	this->verbosity = verbosity;
+	this->fileLineNo = fileLineNo;
+	this->fileName = fileName;
+	this->content = content;
+	this->logLineNo = logLineNo++;
+
+	/* Fill the timestamp information */
+	gettimeofday(&tv, nullptr);
+	this->timestamp = tv.tv_sec * USEC_PER_SEC + tv.tv_usec;
+
+	/* If the timestamp was not set yet, initialize it with the value
+	 * we have just obtained - this way the very first log line will
+	 * always have the timestamp of 0 */
+	if (initialTimestamp == 0)
+	{
+		initialTimestamp = this->timestamp;
+	}
+
+	this->timestamp -= initialTimestamp;
+
+	/* Check if the file name is a basename. If not, drop the directory
+	 * information */
+	if (this->fileName.find(PATH_SEPARATOR) != std::string::npos)
+	{
+		this->fileName = this->fileName.substr(
+					this->fileName.rfind(PATH_SEPARATOR)+1);
+	}
+
+}
+
+std::string LogLine::toString() const
+{
+	const char VERBOSITY_LETTERS[] = {'F', 'E', 'W', 'I', 'L', 'H'};
+	static_assert(sizeof(VERBOSITY_LETTERS) == (int)LogVerbosity::Last);
+
+	std::ostringstream os;
+	if (verbosity < LogVerbosity::Last)
+	{
+		os << VERBOSITY_LETTERS[(int)verbosity];
+	}
+	else
+	{
+		os << "X";
+	}
+
+	os << "-" << logLineNo;
+	os << "-" << (timestamp / USEC_PER_SEC);
+	os << "." << std::setw(6) << std::setfill('0') << (timestamp % USEC_PER_SEC);
+	os << "-" << fileName << ":" << fileLineNo;
+	os << ": " << content;
+
+	return os.str();
+}
+
+LogSink::LogSink(LogVerbosity maxVerbosity, LogManager& logManager)
+	: m_maxVerbosity(maxVerbosity), m_logManager(logManager)
+{
+}
+
+LogSink::~LogSink()
+{
+}
+
+
+LogManager& LogManager::inst()
+{
+	static LogManager instance;
+	return instance;
+}
+
+LogManager::LogManager()
+{
+	m_pendingLogLines.reserve(LOG_QUEUE_SIZE);
+	m_flushPaused = false;
+}
+
+LogManager::~LogManager()
+{
+	for (LogSink* pSink: m_sinks)
+	{
+		delete pSink;
+	}
+}
+
+void LogManager::addSink(LogSink* sink)
+{
+	m_sinks.push_back(sink);
+}
+
+void LogManager::pauseFlush()
+{
+	m_flushPaused = true;
+}
+
+void LogManager::resumeFlush()
+{
+	m_flushPaused = false;
+}
+
+void LogManager::push(const LogLine& logLine)
+{
+	if (m_maxVerbosity > logLine.verbosity) return;
+
+	if (m_pendingLogLines.size() < LOG_QUEUE_SIZE -1)
+	{
+		m_pendingLogLines.push_back(logLine);
+	}
+	else if (m_pendingLogLines.size() == LOG_QUEUE_SIZE - 1)
+	{
+		Log_Wrn("Log queue overflow, some lines might be dropped");
+	}
+
+	if (!m_flushPaused) flush();
+}
+
+void LogManager::flush()
+{
+	for (LogSink* pSink: m_sinks)
+	{
+		for (LogLine& logLine: m_pendingLogLines)
+		{
+			if (logLine.verbosity <= pSink->getMaxVerbosity())
+			{
+				pSink->onLogLine(logLine);
+			}
+		}
+	}
+	m_pendingLogLines.clear();
+}
+

src/core/audio/AudioPulseAudio.cpp

@@ -26,6 +26,7 @@
 #include <QLabel>
 
 #include "AudioPulseAudio.h"
+#include "Logging.h"
 
 #ifdef LMMS_HAVE_PULSEAUDIO
 
@@ -134,12 +135,12 @@ static void stream_state_callback( pa_stream *s, void * userdata )
 			break;
 
 		case PA_STREAM_READY:
-			qDebug( "Stream successfully created\n" );
+			Log_Inf( "Stream successfully created" );
 			break;
 
 		case PA_STREAM_FAILED:
 		default:
-			qCritical( "Stream error: %s\n",
+			Log_Err( "Stream error: %s\n",
 					pa_strerror(pa_context_errno(
 						pa_stream_get_context( s ) ) ) );
 	}
@@ -160,7 +161,7 @@ static void context_state_callback(pa_context *c, void *userdata)
 
 		case PA_CONTEXT_READY:
 		{
-			qDebug( "Connection established.\n" );
+			Log_Inf("Connection established");
 			_this->m_s = pa_stream_new( c, "lmms", &_this->m_sampleSpec,  NULL);
 			pa_stream_set_state_callback( _this->m_s, stream_state_callback, _this );
 			pa_stream_set_write_callback( _this->m_s, stream_write_callback, _this );
@@ -195,7 +196,8 @@ static void context_state_callback(pa_context *c, void *userdata)
 
 		case PA_CONTEXT_FAILED:
 		default:
-			qCritical( "Connection failure: %s\n", pa_strerror( pa_context_errno( c ) ) );
+			Log_Err( "Connection failure: %s",
+				 pa_strerror( pa_context_errno( c ) ) );
 			_this->signalConnected( false );
 	}
 }

src/core/main.cpp

@@ -39,6 +39,9 @@
 #include <QPushButton>
 #include <QTextStream>
 
+#include "Logging.h"
+#include "ConsoleLogSink.h"
+
 #ifdef LMMS_BUILD_WIN32
 #include <windows.h>
 #endif
@@ -693,6 +696,12 @@ int main( int argc, char * * argv )
 		fileCheck( fileToImport );
 	}
 
+	LogManager::inst().addSink(new ConsoleLogSink(
+					LogVerbosity::Debug_Lo,
+					LogManager::inst()));
+
+	Log_Inf("Logging activated");
+
 	ConfigManager::inst()->loadConfigFile(configFile);
 
 	// Hidden settings
@@ -729,7 +738,7 @@ int main( int argc, char * * argv )
 				sched_get_priority_min( SCHED_FIFO ) ) / 2;
 	if( sched_setscheduler( 0, SCHED_FIFO, &sparam ) == -1 )
 	{
-		printf( "Notice: could not set realtime priority.\n" );
+		Log_Wrn("Could not set realtime priority.");
 	}
 #endif
 #endif
@@ -738,7 +747,7 @@ int main( int argc, char * * argv )
 #ifdef LMMS_BUILD_WIN32
 	if( !SetPriorityClass( GetCurrentProcess(), HIGH_PRIORITY_CLASS ) )
 	{
-		printf( "Notice: could not set high priority.\n" );
+		Log_Wrn("Could not set realtime priority.");
 	}
 #endif
 
@@ -765,14 +774,15 @@ int main( int argc, char * * argv )
 		Engine::init( true );
 		destroyEngine = true;
 
-		printf( "Loading project...\n" );
+		Log_Inf("Loading project...");
 		Engine::getSong()->loadProject( fileToLoad );
 		if( Engine::getSong()->isEmpty() )
 		{
-			printf("The project %s is empty, aborting!\n", fileToLoad.toUtf8().constData() );
+			Log_Wrn("The project %s is empty, aborting!",
+				fileToLoad.toUtf8().constData() );
 			exit( EXIT_FAILURE );
 		}
-		printf( "Done\n" );
+		Log_Inf("Done");
 
 		Engine::getSong()->setExportLoop( renderLoop );