Logging in Mace: Mace provides a very sophisticated logging infrastructure which are work at improving regularly. It is intended to be simple, usable, flexible, and efficient. It is strongly recommended to use the Mace logging facility in all Mace code, whether it be in the library, application, or Mace services. You could of course use traditional I/O facilities for outputting statements, but we hope after reading this chapter, you will be convinced to make use of the Mace logging facility. If you wish to use a logging facility Mace doesn't currently provide, it is not hard to add new logging backends. Outline: - Anatomy of a Mace log entry - Configuring what gets printed where, also, the logging backend - Formatting options / backends - Parameter configuration - Programmatic configuration - Logging within Mace services - Automatic selector generation - Automated logging - Logging macros - Logging in non-services - Note about logging at the model checker Anatomy of a Mace log entry ====================== Mace logs have a variety of formatting options, but the following pieces of data can be collected for each log entry: - A timestamp, in OS granularity (microseconds on Linux and OSX). - A thread identifier - A log level (unsigned integer) - A selector / selector id - The developer-provided log content Under the "standard" log formatting options, a log message might appear as: 1266934333.394853 04 [TRACE::MasterStore::updateEntry::(demux)] updateEntry([r=AddressBookRecord(email=foobar@macesystems.org, firstname=foo, lastname=bar, commonname=Foo Bar, commonname_lc=)][force=false][rid=1]) In this log, the first element is the timestamp. This is in seconds (and fractional seconds) since the "epoch". The second column (04) is a thread identifier. This is thread number 4 in this execution. Then, between the brackets is a selector string, which usually describes the nature of the function doing the logging. In this case, the selector string is "TRACE::MasterStore::updateEntry::(demux)". This implies that the log was auto-generated by the Mace compiler (TRACE) for a service called "MasterStore" which is receiving an event called "updateEntry". The log is being printed by the generated "demux" function, which has the responsibility of determining which of the matching transitions to execute. Selector strings are designed to be more flexible than the traditional log levels. It allows you to ask the logging infrastructure to only print messages from the MasterStore service, or the updateEntry transition. Possible prefixes on the selector include TRACE (compiler generated), DEBUG, WARNING, and ERROR. No prefix is prepended to normal user logging, but DEBUG, WARNING, and ERROR may appear if the user uses appropriate logging macros. The log level does not get printed with log messages. Finally, the last part of the message is the data being logged. In this case, it is an automatically generated message about the method being called. It is logging a call to updateEntry, and telling you the values of the r, force, and rid parameters. Configuring what gets printed where ============================ By default, the only logging which is emitted by the application are those logs which contain WARNING or ERROR in their selector strings. These warning and error messages are by default printed to standard error. So, to tell the logging subsystem to emit logs, you have to tell it what kinds of logs to print, and how to print them. Logs can be emitted either in a textual form, or in some kind of structured or binary format. In textual form, different parts of the log have different formatting options. Timestamps, for example, can be omitted, logged as a date string, or logged as seconds and microseconds since the epoch. Thread IDs and selector strings can either be printed or not. Finally, text format logs can be directed at a variety of output file descriptors, including stdout, stderr, or another separate file. There are two main ways to do setup the logging configuration. First, it can be done programmatically in the application, or it can be done by processing configuration parameters. In either case, the configuration of selectors to print should occur before logging takes place, since it will cache the decision of whether to log any particular log. For a log to be printed, the selector string must be "selected" for emitting, it's log level must be at or below the system log level, and logging must not be compiled out or disabled. Logging backends ------------------------- The primary logging backend is the text-log backend (LOG_FPRINTF). However, other backends exist which are under development. These include binary and sql logging, which allow the log data to be emitted in a structured format which will be easier for tools to process later. Additionally, the logging infrastructure has the option to log to a memory buffer, and only dump the logs when asked or when the system catches a signal. Programmatic logging configuration ------------------------------------------------- Logging configuration occurs with calls to Log::add(), Log::autoAdd(), and/or Log::autoAddAll(). These calls are documented in-line in the code and would appear in a doxygen generated set of logs for the Mace library. Log::add() adds a specific selector string, specifying the selector string, output file, timestamp format, log selector format, thread id format, and output method. Log::autoAdd() takes similar parameters, but takes a regular expression to match against selector strings. Finally, Log::autoAddAll() takes no selector string parameter, because it tells the logging infrastructure to print everything. Additionally, applications can do a few things to limit or disable logging. First, they can set a log level. Second, the can call Log::disableLogging() and Log::enableLogging() which turns logging on and off at runtime. Finally, they can set a compile-time log-level, which causes the logging macros to compile to no-ops. (For details of the last, see lib/mace-macros.h). Configuration parameter configuration ---------------------------------------------------- Most of Mace-developed applications include a call to load the command line parameters and parameter file to the params class using params::loadparams(). They then generally ask the logging subsystem to configure itself based on these parameters by calling Log::configure(). The logging subsystem looks at a number of parameters mentioned in lib/params.h, which cause it to call the Log::*add functions on itself. Example parameters include MACE_LOG_AUTO_ALL, which, when set to 1 calls Log::autoAddAll(). MACE_LOG_AUTO_SELECTORS, which could be set to a set of space-separated regular expressions to call Log::autoAdd() on. See lib/params.h for further logging parameters and their descriptions (look for MACE_LOG). Logging within Mace services ======================= First, all Mace services have an optional trace level statement which tells the compiler how much automated logging to insert in the code. Setting trace to off disables compiler-generated logging. 'low' tells the compiler to log a statement each time a transition is called, and to print some of the parameters. 'med' tells the compiler to log a statement at the beginning and ending of each transition and routine, and print the values of the functional parameters and return values. 'high' tells the compiler to log the state of the node once the event ends, if a non-constant transition executes on the node. As a result of all the automated logging options, I find that I seldom write manual logging statements anymore. However, for doing so, there are two options: text logging and structured logging. Text logging is like traditional logging in that you can use either printf-style or output-operator style logging. In structured logging, you can declare functions in a structured logging block. The Mace compiler then defines a structured log object which can be used for either text logging or logging to binary/sql formats. The structured log object type is taken from the name of the function, and the data fields and types are the parameters from the function. The structured log is emitted by simply calling the declared function in the code. Selectors are auto-generated within Mace services and transitions. The selector strings are generated as given above: (::)::::(::). To use output operator logging, you can simply use maceout, macewarn, maceerr, or macedbg(#) in the same fashion you would cout or cerr. macedbg takes a log level -- the other mechanisms emit logs with log level 0. Instead of using std::endl at the end of a log statement, use Log::endl, which causes the log to be emitted. Until Log::endl is placed in the stream, the log will only be buffered. To use printf-style logging, call maceLog(...), maceDebug(#, ...), maceWarn(...), and maceError(...), with parameters similar to printf. Newlines are not needed in the format strings. maceDebug takes a log level. For full details see lib/mace-macros.h. Logging outside Mace services ======================== Programmatically, you can perform logging directly to the logging subsystem by calling one of the Log::log or Log::binaryLog functions (see lib/Log.h). However, we find it much simpler to use the same macros we use in Mace services. In particular, this will require you to #include "mace-macros.h" in your service. Then, at the beginning of the function, you can put ADD_SELECTORS("XXX"), where XXX is replaced with the selector string you would like to you use. ADD_FUNC_SELECTORS maps to ADD_SELECTORS(__PRETTY_FUNCTION__), which generates selector strings based on the function declaration. Logging and the Mace Modelchecker ============================= The Mace Modelchecker supports logging configuration by parameters described above, and also supports a few options for parameterized programmatic configuration. In particular, passing TRACE_ALL as 1 to the model checker causes it to call Log::autoAddAll(). Additionally, you can use -TRACE_SIMULATOR as 1, which logs some detail about what's happening in a service. TRACE_SUBST is also supported, and behaves like MACE_LOG_AUTO_SELECTORS. It's important to follow two basic guidelines with the model checker. (1) Don't use other logging/IO infrastructures, because they will not properly be turned off during the search, and on during replay. (2) Services should have trace set to med or high to fully work with all the tools accompanying the model checker. At lower trace levels, not enough information is included to support the full range of functionality. In general, when the modelchecker is searching paths for bugs, logging is disabled, to support fast execution. Then, when the model checker finds an error, it is re-run with logging turned on fully to generate the complete execution trace. One other comment on modelchecker logs---they contain an extra field at their beginning, which is the IP address of the node generating the log message.