Logging in Marsyas

In this post I discuss the use of logging in Marsyas as an alternative to temporary print statements and/or debugging. Most developers are marginally aware of the existing facilities and I want to make a push to make them more widely used. It is my hope that after reading this post code in MarSystems like : 

•    cout << type_ <<  "/" << name_ << "/mrs_real/gain = " << gainValue << endl;

 will be replaced with: 

•     MRSDIAG(type_ << "/" << name_ << "/mrs_real/gain = " << gainValue);

Notice that the logging macros fully support the C++ stream syntax and therefore can include much richer information than just simply a text message (for example you could output a realvec or a counter variable). 

Marsyas is frequently used as a library/framework linked to external applications such as GUIs and command line tools as well as a back end to web servers. In addition it is also designed to support real-time interactive music generation and analysis as well as batch processing of collections with thousands of audio files. These different usage scenarios result into sometimes contradictory design requirements. For example in real-time scenarios it is desirable that unexpected behavior does not stop the data flowing through the system. As an example the SoundFileSource MarSystem outputs audio buffers with zeroes if the provided file-name can not be opened rather than doing something more drastic like exiting which could be a desired behavior in batch processing of files.

 

Even though a lot can be accomplished by using and combining the existing MarSystems sooner or later most developers have to write their own MarSystems to extend the provided functionality.  A frequent process used by the current developers (including me) is to write the new MarSystem, add various cout statements to help understand whether it is working or not and when everything looks good remove or comment out the cout statements from the source code. That way the resulting MarSystem does not produce any output that would clutter the screen as well as possibly confuse things like web-servers. Later if something goes wrong the cout statements are re-introduced and the cycle continues. Because of the heavy computational requirements of audio processing such print statements can have a significant slow down effect.

An alternative for understanding the run time behavior of a program is the use of a debugger. There are two main issues that potentially limit the use of a debugger when used with Marsyas. The first is that in multi-threaded applications (such as GUIs) debugging can not be used reliably. The second is that compiling in Debug mode can significantly slow down the computational time.

Logging is an important technique for better understanding the behavior of a program during run time.

It consists of recording information about the program while it is running at different levels of detail and controlling where that information is stored. The Marsyas logging system was designed with the considerations discussed above in mind. It is mostly configured at compile time so that there is no performance penalty when it is not used (even a small run-time check would result in performance effects given the heavy computation requirements for audio).  It supports three different output streams (standard output, standard error and a marsyas log file). When logging to file is enabled log messages are appended to the log file allowing a single log to be used for multiple invocations of the code something useful in parallel batch processing jobs.

There are several different types of log messages supported. They are: 

1. MRSMSG: Messages are high level information about the running of the system. They should only be used in MarSystem and applications that need to display output. For example the ClassificationReport.cpp MarSystem should be using instead of the current cout statements (excellent homework for any of the readers).
2. MRSWARN: Warnings provide information about things that might be a cause of concern but ignoring them will not affect the operation of the system. For example if a sound file can not be opened then a warning message is logged.
3. MRSERR: Errors are more severe than warnings and indicate that something serious is going wrong. In certain cases they are followed by exiting the program.
4. MRSDIAG: Diagnostics provide detailed information about the operation of the system. They can be turned on and off arbitrarily at run-time (when enabled) allowing fine control of the information displayed. For example ideally each MarSystem should have diagnostic messages for the myProcess and myUpdate methods and the values of the controls (more homework for all of us)
5. MRSDEBUG: Debug messages are specific and detailed and trying to help with debugging the code. They are similar to diagnostic messages but more about what went wrong rather than what is going right. 

Typically Marsyas is configured to display only the first 3 messages types (messages, warnings and errors) in Release and all of them in Debug. By appropriately configuring CMake it is possible to have logging to any combination of standard output, standard input and log file.