New logging mechanism

[artur-twardowski]

Implementation of the log messages' mechanism for LMMS. Implements #5159, now in scope of #5468.

The new API is intended to be used universally in the application, including the performance-critical sections.

Basics:

• The central class is LogManager, which needs to be accessible from any place in the code. To achieve this, it was implemented as a singleton.
• The LogManager stores a list of LogSinks. Each LogSink represents a different kind of output for the log lines. Examples are: standard output, a log file, a debug messages' window inside an application, a remote endpoint...
• Each LogSink is assigned independently the highest level of verbosity of the messages. Currently there are six levels: Fatal, Error, Warning, Info, Debug Low, Debug High.
• Whenever the LogManager accepts a log line, it is broadcast to all the sinks, unless the verbosity level of the line is greater than the sink's verbosity level. For example, if we set the log file's verbosity level to Debug Low and console's verbosity to Warning, all Errors will appear in both places. On the other hand, Infos will be present only in the log file, Debug Highs will not appear anywhere.
• In order to shorten the code, the programmer is supposed to use a set of dedicated macros rather than calling LogManager's API directly. There are two sets of macros. Log_xxx macros accept the same syntax as printf function, while Log_Str_xxx macros are supposed to be used as C++ streams (or Qt's mechanism). Replace "xxx" by the verbosity level designator: Fatal, Err, Wrn, Inf, Dbg_Lo, Dbg_Hi.
• Each log line, besides the actual message, is accompanied by some metadata: verbosity information, sequential number of the log message, a timestamp and the location of the log (source file name and line number). The timestamps are relative to the execution of LMMS (more precisely: the "Logging activated" message is at t=0) and have a resolution of 1 µs.

Extra stuff:

• To reduce the overhead of logging in terms of thread's execution time, the log messages are cached inside LogManager and are distributed to LogSinks in the flushing process. Flushing is done periodically in a separate thread (LoggingThread). Thanks to this solution, the thread that generated a log line will not be paused by writing to a console and/or a file - it will continue running while the log line is processed in the background.
• LoggingThread can be disabled (in case it is really needed), under such condition the log messages will be flushed immediately after they are generated. This may however have negative impact on the performance.
• Flushing process can be temporarily paused. This allows to use the logging mechanism inside performance-critical code, ensuring that no console/file writes will compete for the CPU time. Until flushing is resumed, all the log lines remain cached inside LogManager. This remains valid even if the LoggingThread is disabled - in such situation the flush is invoked immediately at the resume.
• All the logs generated through Qt's mechanism are forwarded to the new mechanism, since Qt provides a way to define a custom logs' handler. The final goal, however, is to replace all these qDebugs, qWarnings, etc. with the new unified API, alongside with all the printfs.
• Access to the log messages cache is synchronized with a mutex. The flush pause flag is synchronized either with a separate mutex.

The pull request currently contains a preliminary implementation, being more a kind of proposal or PoC. A few things are yet to be done:

• implementation of sinks for log file and log window
• adding appropriate configuration options, accessible via GUI
• enhancing log messages with the information about the name of a thread that generated each line
• usage of smart pointers instead of C-style pointers to store the sinks

[LmmsBot]

🤖 Hey, I'm @LmmsBot from github.com/lmms/bot and I made downloads for this pull request, click me to make them magically appear! 🎩

Linux

• Linux (AppImage): lmms-1.2.1.691-linux-x86_64.AppImage (build link)

Windows

• Windows 32-bit: lmms-1.2.1.691-mingw-win32.exe (build link)
• Windows 64-bit: lmms-1.2.1.691-mingw-win64.exe (build link)
• Windows 32-bit: lmms-1.2.1-msvc2017-win32.exe (build link)
• Windows 64-bit: lmms-1.2.1-msvc2017-win64.exe (build link)

macOS

• macOS : lmms-1.2.1.691-mac10.13.dmg (build link)

🤖

{"platform_name_to_artifacts": {"Linux": [{"artifact": {"title": {"title": "(AppImage)", "platform_name": "Linux"}, "link": {"link": "https://6626-15778896-gh.circle-artifacts.com/0/lmms-1.2.1.691-linux-x86_64.AppImage"}}, "build_link": "https://circleci.com/gh/LMMS/lmms/6626?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-build-link"}], "Windows": [{"artifact": {"title": {"title": "32-bit", "platform_name": "Windows"}, "link": {"link": "https://6624-15778896-gh.circle-artifacts.com/0/lmms-1.2.1.691-mingw-win32.exe"}}, "build_link": "https://circleci.com/gh/LMMS/lmms/6624?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-build-link"}, {"artifact": {"title": {"title": "64-bit", "platform_name": "Windows"}, "link": {"link": "https://6623-15778896-gh.circle-artifacts.com/0/lmms-1.2.1.691-mingw-win64.exe"}}, "build_link": "https://circleci.com/gh/LMMS/lmms/6623?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-build-link"}, {"artifact": {"title": {"title": "32-bit", "platform_name": "Windows"}, "link": {"link": "https://ci.appveyor.com/api/buildjobs/h8cyk0fx2dh1n6o3/artifacts/build/lmms-1.2.1-msvc2017-win32.exe"}}, "build_link": "https://ci.appveyor.com/project/Lukas-W/lmms/builds/33048691"}, {"artifact": {"title": {"title": "64-bit", "platform_name": "Windows"}, "link": {"link": "https://ci.appveyor.com/api/buildjobs/897f5178qbw6ani9/artifacts/build/lmms-1.2.1-msvc2017-win64.exe"}}, "build_link": "https://ci.appveyor.com/project/Lukas-W/lmms/builds/33048691"}], "macOS": [{"artifact": {"title": {"title": "", "platform_name": "macOS"}, "link": {"link": "https://6625-15778896-gh.circle-artifacts.com/0/lmms-1.2.1.691-mac10.13.dmg"}}, "build_link": "https://circleci.com/gh/LMMS/lmms/6625?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-build-link"}]}, "commit_sha": "6d9311438db11ca32ed50ca4b2f0800ef52307ac"}

[JohannesLorenz]

Some basic points/questions:

• Some of our threads, the so-called "real-time" or "audio" threads will not be allowed to run printf/qDebug()/mutex etc. The only way I can think of that lets them use the logger are ringbuffers (the mutex here will make them too slow to process audio). src/3rdparty/ringbuffer can do this. Can you consider using those ringbuffers instead of the mutexes?
• Does it make sense to add topics to debug messages? E.g. if you only want to see any kind of lv2 plugins, but from the rest only warnings/errors? Though, this may be hard to specify as command line parameters.
• The interface of Log_Gen only seems to support print() like stuff. With overloading operator<< (the std::cout way), you could enable printing almost anything.
• Did you consider using "real" functions for Log_Gen? I.e. using C++11's variadic functions?

[artur-twardowski]

• Some of our threads, the so-called "real-time" or "audio" threads will not be allowed to run printf/qDebug()/mutex etc. The only way I can think of that lets them use the logger are ringbuffers (the mutex here will make them too slow to process audio). src/3rdparty/ringbuffer can do this. Can you consider using those ringbuffers instead of the mutexes?

This is a good idea. I need to take a look at this library. A ring buffer seems to be much better idea than a vector.

• Does it make sense to add topics to debug messages? E.g. if you only want to see any kind of lv2 plugins, but from the rest only warnings/errors? Though, this may be hard to specify as command line parameters.

Actually I thought about such feature. In the tracing system I took most of the inspiration from there was a mechanism of "channels" which served for the same purpose. I thought that such a feature in LMMS' tracing may be a bit excessive and overwhelming, but maybe it is due to the fact that I am used more to filter the logs by keywords. This is however not difficult to implement.

• The interface of Log_Gen only seems to support print() like stuff. With overloading operator<< (the std::cout way), you could enable printing almost anything.

Right, that's why I provided the other set of macros utilizing Log_Str_Gen (which uses LogIostreamWrapper), so that everyone can choose the most suitable API. Personally I prefer the printf syntax since I frequently dump raw bytes in hex - "%02x" is much quicker and more readable than a parade of iomanips.

• Did you consider using "real" functions for Log_Gen? I.e. using C++11's variadic functions?

This is a good idea, but still some helper macros will be necessary if we want to include the information about source file name and line. Otherwise the developers will have to pass FILE and LINE explicitly. Maybe there is a better mechanism to do it, but I don't know about one.

[JohannesLorenz]

a mechanism of "channels" ... is however not difficult to implement.

OK. I think it's not urgent now, just an idea for later.

• Did you consider using "real" functions for Log_Gen? I.e. using C++11's variadic functions?

This is a good idea, but still some helper macros will be necessary if we want to include the information about source file name and line. Otherwise the developers will have to pass FILE and LINE explicitly. Maybe there is a better mechanism to do it, but I don't know about one.

Oh I did not see those two macros. For those it seems perfectly reasonable.

[DomClark]

It's not safe to allocate memory on a real-time thread either, so the heap allocation of LogLines unfortunately isn't always an option, and things like initialising std::strings or inserting into std::maps are also out.

[lukas-w]

Considering that this is not safe to use in a real-time context, what are the advantages of this PR's solution compared to using Qt's built-in logging capabilities?

[JohannesLorenz]

Considering that this is not safe to use in a real-time context, what are the advantages of this PR's solution compared to using Qt's built-in logging capabilities?

I think that it can be re-worked to be RT-safe. Qt's logging stuff... I don't know, but looking at the other Qt classes I'd guess that it is not RT-safe.

In the worst case, we could simply forbid logging in the RT safe (zyn does that), but being able to log in the audio thread sounds really nice.

[lukas-w]

I think that it can be re-worked to be RT-safe. Qt's logging stuff... I don't know, but looking at the other Qt classes I'd guess that it is not RT-safe.

I think making this RT-safe will be at least as complex as making a RT-safe wrapper around Qt's API. In both cases it will most likely be done using some sort of lock-free message queue, that is processed in another thread and passed on to the actual logging backend used. I'm just not entirely sure about the benefits of adding 900 lines of code to the project when Qt already implements the same functionality.

[JohannesLorenz]

@lukas-w Please explain why you think Qt's logging mechanisms would be realtime safe. This seems like an invalid claim to me.

[lukas-w]

I didn't say that.

[JohannesLorenz]

I'm just not entirely sure about the benefits of adding 900 lines of code to the project when Qt already implements the same functionality.

What does this mean then? You mean we should not add the logger, and instead just use Qt's classes?

[lukas-w]

That comment was referring to both this PR and Qt not being real-time safe. Qt provides its own logging system, so I think an addition as large as this needs to be justified, hence my asking for advantages of this PR over Qt in my first comment. At least at first glance though, it looks like this PR doesn't implement anything that Qt doesn't already offer. So yes, if that's the case, I think we should just use Qt's classes.

[JohannesLorenz]

@lukas-w So with "just use Qt's classes" you're proposing to do qDebug() << "test" in the realtime thread and tell Qt to not print that, but instead send this to a non-realtime thread? Or do you propose to do non-realtime printing inside the realtime thread (unmodified qDebug)?

[lukas-w]

I don't propose anything related to logging from real-time threads. That's a different problem on its own that neither this PR nor Qt solves which is the point I'm trying to make.

[JohannesLorenz]

If we want to be able to log in the RT thread, any proposal must have a solution for that. This PR could solve it, but I wonder if Qt's classes can solve that (without this PR).

Or we do not allow any logging in the RT thread (or only with a macro being activated).

[lukas-w]

If we want to be able to log in the RT thread

Do we? I don't get why we're even talking about this; this PR was never meant to solve RT thread logging.

any proposal must have a solution for that

Then feel free to close this PR… Frankly I don't understand the point of this discussion. If you think this solution is better than Qt, please explain why. Otherwise I vote we close this now.

[JohannesLorenz]

If we want to be able to log in the RT thread

Do we? I don't get why we're even talking about this; this PR was never meant to solve RT thread logging.

Please see #5825 to why we do need to be able to log in RT thread. Unless you have a good idea how an RT thread can dump critical messages.

any proposal must have a solution for that

Then feel free to close this PR… Frankly I don't understand the point of this discussion. If you think this solution is better than Qt, please explain why. Otherwise I vote we close this now.

If this PR does not have a solution for the RT thread, but has other good points, I rather propose extending this PR instead of writing a new one. After all, I see nothing in this PR which prevents adding this.

[lukas-w]

Unless you have a good idea how an RT thread can dump critical messages.

If this PR does not have a solution for the RT thread, but has other good points

@JohannesLorenz I've explained how logging from a RT thread could work and I've repeatedly asked for pointing out what you call "other good points" of this PR. So far I haven't seen a single argument for this PR that doesn't apply to Qt as well.

Don't take this personally, but I'm tired of repeating myself. So unless you decide to actually respond to the points I'm making, I have nothing more to add to this discussion. Believe me that I'd be sorry to see all this work go to waste, but we can't add 900 lines of largely unneeded code just so we don't insult the author.

[JohannesLorenz]

No, I don't take this personally, and I know this is not about insulting the author.

I think the whole LogSink system, LogTopic, LogVerbosity, and partially LogManager (except for thread handling) can be re-used, and they are conforming to #5468 . The first two are not RT safe at construction, but they are initialized outside of the RT thread.

LogLine and parts of LogManager must be changed to work in RT context, but it looks like this is the minority of lines?

It might be easier to see how many lines we must change when we change them...

[lukas-w]

No, I don't take this personally, and I know this is not about insulting the author.

I'd still like to apologize for my past comments' tone. I've been very stressed out the past ~half year which is bringing my patience to an unfairly low level. I realize I may have failed to offer a sufficient explanation for my argument myself. ❤️

I believe we should generally prefer Qt & 3rd party components over custom implementations wherever feasible, but I'd like to take another look at this PR's code before continuing this discussion so I can address your points properly. However I just don't have the time or energy for that right now. Maybe this PR will still be around when I do :) Until then, don't let me stop you from proceeding with this as you see fit.

[JohannesLorenz]

No problem. My tone was probably also not the best 😄

Maybe we will continue with this PR, or write a new one. We'll see.

[TechnoPorg]

@artur-twardowski Are you still interested in maintaining this PR? I am happy to take it over if not!