Part of the FARGOS Development, LLC Utility Library

FARGOS Development Logging API Reference

Overview of the FARGOS Development Logging Facility

The FARGOS Development Logging API (henceforth refered to as "the Logging API") has been designed to be easy to use, but extremely efficient and able to handle a variety of use cases with several novel capabilities. It can be overwhelming at first glance due to the rich amount of function, so it is easier to start by examining the high-level functionality before investigating the lower-level internals. There is some influence from the trace facility in IBM's RSCT product; that particular feature was oriented towards deployments in supercomputer clusters where administrators wanted to be guaranteed that log files would never exceed a certain size. Those trace files were also binary files, which used message catalogs to provide the templates needed to decode each recorded log line. While this does yield a significant reduction in the size of the log files, it is also fair to remember the "I" in IBM stands for International and they were well-aware that not everyone used English as the universal language. The main downside of such an approach is that an external utility is needed to render the traces readable.

Not to belabor the point, but the Logging API can truly be used in several different ways, some of which are not obvious. Because an IO_Processor can be used to separate the preparation of log messages from their actual storage or transmission, an application thread can be prevented from blocking on I/O (this can be enabled using the +logthread command line option). The use of memory-mapped files to back auxillary data structures allows log messages that had not yet been written to be recovered (the extremely useful invokeAndRestart cover script will automatically use log_util to do such recovery). There are a plethora of convenience functions built upon very sophisticated, thread-aware facilities that do their best to minimize data movement and CPU cycles. It has been used to even to perform inter-application communication between processes to announce trade activity, for example, without requiring data to be moved between address spaces.

In the presentation below, the phrase "by default" will appear frequently. In general, this means that the default will be what most people want, but there exists a mechanism that can be overridden for an exotic special case. The Logging API provides functionality first-and-foremost, but there is a good deal of convenient policy layered on top of it. If required, one can usually bypass the conventions and access the very lowest layers and implement alternate behavior.

Components and Log Levels

The Logging API presented here uses the concept of components to implement one form of granularity of control over logging output. The other form of control is logging levels, discussed later. Two components are always defined: one is named "app" and the other is named "io". The "app" component name is intended to be used in files associated with the application and "io" is normally associated with I/O streams or used by lazy authors of library components.

Note: best practice is to always create an appropriate component name for a library element rather than fallback on the catch-all "io". One should normally never use "app" in a library component as it would be taking away the intended ability for the application writer to use it as they saw fit, but it can be done.

For convenience, interfaces are provided to many routines that assume a source file is associated with a given component, which eliminates the burden of having to specify the component of interest on every logging-related call. The THIS_COMPONENT macro is used to set the name of the desired default component for a given source file.

Note: "never" set the THIS_COMPONENT macro in a header file; unfortunately, if you think that was needed, you are probably using it wrong.

Declaring and Defining a Custom Component

Note: for the purposes of this discussion, the name customComponent will be used. Without loss of generality, it would be replaced with whatever name the developer desires. The name chosen must be suitable for use as a variable name—it is not a text string.

A new component must both be declared and defined—these are two distinct items. The declaration of a component is normally performed in a header file, which might be subsequently be included by many other source files. The definition of a component is only performed once and thus should appear within a single source file.

Declaring a Component

The simplest way to declare a component is to use the DECLARE_STANDARD_COMPONENT_VARS() macro in the relevant header file:

#include <utils/logging/logging_api.hpp>

DECLARE_STANDARD_COMPONENT_VARS(customComponent);

and use DEFINE_STANDARD_COMPONENT_VARS(customComponent) and AUTO_REGISTER_COMPONENT(customComponent) in the single source file chosen to implement it:

#include <utils/logging/logging_api.hpp>

DEFINE_STANDARD_COMPONENT_VARS(customComponent);
AUTO_REGISTER_COMPONENT(customComponent);

The AUTO_REGISTER_COMPONENT(customComponent) registers the name of the component and the corresponding log mask variable with the command line option parser, enabling the +logmask and ‑logmask options to be handled.

Rather than have customComponent duplicated in serveral places, it can be preferrable to define THIS_COMPONENT first and then use DEFINE_STANDARD_VARS_FOR_THIS_COMPONENT() and AUTO_REGISTER_THIS_COMPONENT(). This approach makes it easy to change the component name simply by altering the value of THIS_COMPONENT.

#define THIS_COMPONENT customComponent
DEFINE_STANDARD_VARS_FOR_THIS_COMPONENT();
AUTO_REGISTER_THIS_COMPONENT();

Remember that the component is only defined in one-and-only-one source file. The remaining source files in a typical library would include the header that declared the component, and simply define THIS_COMPONENT as customComponent. Thus a complete example using the LOG_CERR() macro to output on standard error would be:

#include <utils/logging/logging_api.hpp>

#define THIS_COMPONENT customComponent
DEFINE_STANDARD_VARS_FOR_THIS_COMPONENT;
AUTO_REGISTER_THIS_COMPONENT;

void aLibraryRoutine()
{
   LOG_CERR(error) << "Something went wrong!" << LOG_ENDLINE;
}

Logging Levels

The other unit of granularity provided by the Logging API is that of a logging level. By default, log levels are treated as being orthogonal rather than representing a strict hierarchy. Enabling or disabling a distinct logging level does not have any affect on the others. By default, the following level names are automatically declared:

trace
Intended for low-level tracing activity, such as function entry/exit. Normally inhibited.
debug
More detailed log information that would normally be inhibited
info
Regular information, normally always output. One very notable exception is that of the io component; it is normally configured to have information messages inhibited.
warn
Warning messages, unexpected states that appear to be tolerable. Normally always output.
error
Error messages, states that indicate an serious problem. Normally always output.
fatal
Unrecoverable error or condition. Normally always output.
user
User-defined messages. This can get very complicated with the ability to define new level names, introduce a strict hierarchy.of levels, etc.

Note: It is possible to make use of a conventional logging hierarchy and there are a range of userInfo1-userInfo6 and userDebug1-userDebug6 levels that are also defined for this purpose. Discussion on their usage is deferred until later.

Normally, output for the process is saved into a particular log file. Some sites like to make use of syslog to pick up and forward exceptional conditions, so there are a couple of logging levels that trigger special case treatment: the content can be simultaneously be logged to the log file, written to standard error or submitted to the syslog daemon.

warningAndSyslog, errorAndSyslog, fatalAndSyslog
Send the text to both the log file and the syslog daemon.
warningAndStderr, errorAndStderr, fatalAndStderr
Send the text to both the log file and the standard error stream.
warningAndBroadcast, errorAndBroadcast, fatalAndBroadcast
Send the text to both the log file, the syslog daemon and the standard error stream.

Initializing the Logging System and Creating a Log File

Command Line Arguments

Many of the logging facilties options can be manipulated via arguments passed in on the command line. If a program has options of its own to process, it can be convenient to first strip all of the logging-related options out argv and adjust the count in argc using a call to LogMessageRecord::process_commandline_log_flags().

int main(int argc, const char *argv[])
{
    // parse and strip log-related arguments
    LogMessageRecord::process_commandline_log_flags(&default_LogSubsystemInfo,
        argc, argv, &argc, argv);

If the call to LogMessageRecord::process_commandline_log_flags() is not made, the log-related arguments will still be processed by an eventual call to LogManager::initializeLogSubsystem(). The PROCESS_COMMAND_LINE_FLAGS() convenience macro performs the call to LogMessageRecord::process_command_line().

Initializing the Logging System

While not mandatory, the DEFAULT_SharedMemoryVariableManager is normally initialized so that external control of the logging facility can be performed using commands like setLogMask. The logging system is itself is initialized by a called to LogManager::initializeLogSubsystem(). This is done only once.

Logging Output Streams

A logging output stream is owned by a LogManager object. There are two LogManager objects created automatically: LogManager::STDOUT_LogManager is associated with standard output and LogManager::STDCERR_LogManager is associated with standard errror. The simplest way to access the two are via LOG_COUT(logLevel) and LOG_CERR(logLevel), respectively. For some applications, these may be all that are required, but many will want to have at least one log file of their own. There is provision for one log file to be considered the default log; this is maintained by the LogManager::DEFAULT_LogManager variable. It is possible to have many active log files, but that requires using APIs that do not assume the use of the default log file. Such usage is not particularly burdensome. For example, the implementation of LOG_CERR() is merely:

#define LOG_CERR(lvl) LOG_INTO(LogManager::STDERR_LogManager, lvl)

As had been previously noted, the THIS_COMPONENT macro is not intended to be defined within a header file, which poses an issue for inlined functions realized in header files. In those scenarios, the developer should fall back on specifying the appropriate component, often with one of the LOG_COMPONENT_ variants. This is illustrated in the fragment below that uses the app component:

  LOG_COMPONENT_CERR(app,error) << "Segment is only " << segmentLen <<
      " but at least " << minSize <<
      " bytes would be required for file to hold " << totalRecords <<
      " of length " << metaRecordLength << LOG_ENDLINE;
  

A new log file is normally opened using LogManager::newStandardLogFile(), but a LogManager can be associated with already an open file descriptor.

Putting it all together leads to code similar to the following:

  LOG_COUT(info) << argv[0] << " begins execution [stdout]" << LOG_ENDLINE;
  LOG_CERR(info) << argv[0] << " begins execution [stderr]" << LOG_ENDLINE;
  {
      size_t segLen = 4096 * 4096; // pages to allocate for all variables...
      // Initialize default manager
      DEFAULT_sharedMemoryVariableManager.createAndAttachStandardSegment("myAppName", &segLen);
      LogManager::initializeLogSubsystem(&argc, argv, argc, argv); // parse and strip log-related arguments
      LogManager::newStandardLogFile("myAppName", FILENAME_WITH_EVERYTHING);
      LOG_WHEN(info) << argv[0] << " begins execution" << LOG_ENDLINE;
  }
  

Note: the usage of LOG_COUT(info), LOG_CERR(info) and LOG_WHEN(info) to announce the startup of the process is recommended best practice for production services. These help enable the content of the log files to be programatically synchronized and merged if one needs to correlate activity that was unfortunately logged across different output streams; the mergeLogs utility is one example of an application that can be used for that purpose.

Using the Default Log Stream

As shown in the initialization example, LOG_WHEN() can be used to log output to the default LogManager; however, authors of library routines should not assume this will be initialized—the application author may have concluded they did not want a separate log file. Instead, IFLOG_WHEN() provides the additional check that the default log manager was created.

Often a particular log message will always be wanted, so having the ability to be able to disable it provides no benefit or may actually be detrimental. As an example of the latter, an application that is creating an audit trail would be well-advised to not permit the disabling of such log messages. For those scenarios, LOG_ALWAYS() and IFLOG_ALWAYS() will provide the desired functionality. In general LOG_WHEN()/IFLOG_WHEN()are preferred to LOG_ALWAYS()/IFLOG_ALWAYS()based on the principle that the LOG_ALWAYS() variants take away functionality (i.e., the ability to inhibit the output of a message); however, developers should always be guided by the needs of the application.

Log Masks

Usually log output can be inhibited, although there are intentional exceptions such as the use of LOG_ALWAYS() mentioned above. Using the previously presented examples, our program will have produced initial output similar to:

$ myApp
2020/07/15 00:32:08.942220 139950130459840 t.cpp:20 INFO myApp begins execution [stdout]
2020/07/15 00:32:08.942259 139950130459840 t.cpp:21 INFO myApp begins execution [stderr]

It can be seen from the output above that the default output format prefixes each line of output with the date, time, thread id, source file name and line number and message level. Each of these fields can be disabled by setting the logPrefixMask associated with the respective LogManager, such as via LogManager::setLogPrefixMask() or at initialization time via LogManager::initializeLogSubsystem(). Inhibiting the output of such information has its place, but best practice is to retain all of these fields, as the loss of information can never be recovered. The mergeLogs utility has the ability to strip out any of those fields, so it is usually a better idea to filter a log file through mergeLogs rather than never generate the information in the first place.

Note: the filename that will be visible is influenced by the build system in use. In most projects, it is far better to provide a complete path name to the source file so that a file can be conveniently located afterwards. As a concrete example, using vim's gF sequence while the cursor is positioned within the filename:lineNumber block can open up the relevant source file at the point where the log message was generated. If the build system in use only feeds the compiler the name of the source file berefit of any directories in the path name, the information will not be available for output. The Logging API is sandbox-aware and will automatically strip the prefixes to the src directories of the current sandbox and associated backing trees. The GCOV_PREFIX_STRIP environment variable is also honored.

The prototype application under discussion creates a log file and shared memory variable segment with names that indicate the application, time of invocation and host upon which it executed and process identifier. The default naming convention is designed to permit all log files to be collected in a single location without fear of name collisions. Examination of the shared memory variable segment shows:

$ smvq -z
smv_query -f ./myAppName-20200715_003327-development-67246.smv -z
/stdout/io_stats/bytesRead = uint64 159
/stdout/io_stats/bytesProcessed = uint64 159
/stdout/io_stats/packetsRead = uint32 2
/stdout/io_stats/packetsProcessed = uint32 2
/stderr/io_stats/bytesRead = uint64 89
/stderr/io_stats/bytesProcessed = uint64 89
/stderr/io_stats/packetsRead = uint32 1
/stderr/io_stats/packetsProcessed = uint32 1
/customComponent/customComponent_logMask = uint64 960
app_logMask = uint64 960
io_logMask = uint64 896
coalesceIOVEC = uint32 4
/LOG/myAppName/io_stats/bytesRead = uint64 80
/LOG/myAppName/io_stats/bytesProcessed = uint64 80
/LOG/myAppName/io_stats/packetsRead = uint32 1
/LOG/myAppName/io_stats/packetsProcessed = uint32 1

The customComponent_logMask, app_logMask and io_logMask variables expose the current mask for their respective components. These can be easily interpreted by the setLogMask command:

$ setLogMask
current customComponent logMask enables info warn error fatal
current app logMask enables info warn error fatal
current io logMask enables warn error fatal

One could disable informative message for the customComponent by doing:

$ setLogMask customComponent -info
now customComponent logMask enables warn error fatal

Log masks can be enabled or disabled on an application's command line using the +logmask or ‑logmask options, respectively. A log mask is named using the convention of [componentName.]levelName, where the initial componentName and period separator are optional if the intent is to not name a single component but instead affect all components. Given the previous example, this invocation would generate no output because the information messages were disabled:

$ myApp -logmask customComponent.info

Note: anything associated with a conditional message is not performed if the message is inhibited. These lines result in a different value for intVal depending on whether or not +logmask customComponent.debug was specified on the command line:

 int intVal = 0;
 LOG_COUT(debug) << "val debug=" << ++intVal << LOG_ENDLINE;
 LOG_COUT(info) << "val info=" << intVal << LOG_ENDLINE;

Without, one sees:

2020/07/15 14:47:01.608056 139623495235392 t.cpp:41 INFO val info=0

With +logmask customComponent.debug, one sees:

2020/07/15 14:47:32.520996 140024273564864 t.cpp:40 DEBUG val debug=1
2020/07/15 14:47:32.521005 140024273564864 t.cpp:41 INFO val info=1

In general, one should not take advantage of side-effects with condtional messages.

Using mergeLogs

The mergeLogs utility has the ability to follow files (somewhat similar to tail ‑f), watch directories for the appearance of new files that match patterns, and can efficiently merge the content of multiple files so that their lines are appropriately ordered by time. It can also skew the time in a file, which can be helpful if files from different hosts are to be merged and their clocks were not synchronized closely enough. As a trivial example, the three output streams generated by the prototype application will correctly be merged:

$ mergeLogs myAppName-20200715_003*67426.log stderr stdout
2020/07/15 00:33:27.772206 140374653130560 t.cpp:20 INFO a.out begins execution [stdout]
2020/07/15 00:33:27.772249 140374653130560 t.cpp:21 INFO a.out begins execution [stderr]
2020/07/15 00:33:27.788870 140374653130560 t.cpp:15 INFO Hello, world

Hint: skewing the clock can be used for more than just minor adjustments. For example, shifting the time of one file 24 hours can allow comparison of behavior on different days.

$ mergeLogs --help
usage: mergeLogs [-deftTSF] [--interval seconds] { [--date {YYYYMMDD|YYYY/MM/DD}] [--dir dirName] [--skew nanoseconds] [--reorder N] {{--watch pattern}| {[--seek offset] fileName}} } ...
  -d = strip date
  -e = strip error level
  -f = strip filename
  -t = strip thread Id
  -T = strip timestamp
  -S = generate symbolic thread Ids (table dumped at end)
  -F or --follow = follow files
 NOTE: -deft strips all but time
  --stdin recognized as filename
  --date specifies default date for subsequent files
  --dir specifies directory for subsequent relative file names
  --watch = specifies pattern for files that may appear (used with --follow)
  --skew shifts logical record times in next file
  --seek skips indicated number of bytes in next file
  -i or --interval = specifies interval used to check for new content when -F flag was specified
  --reorder specifies the maximum distance between out-of-order lines in a log file

Logging Threads

One of the problems with traditional log output is corruption in the face of multiple threads attempting to generate output simultaneously. The Logging API addresses this issue by protecting each line of output from interference from another thread; however, this is done in such as way as to not cause a thread to block waiting for another to finish generating its output line. The default output format also includes the thread identifier.

Under some circumstances, it may be viewed as important to not permit a thread to be delayed waiting for its output to be commited to stable storage. Because the Logging API uses the IO_Processor class, the actual processing of the log messages can be performed by a background thread. This feature can be enabled via the +logthread command line option. Having a background output thread increases the possibility for there to be uncommitted log messages if the application crashes unexpectedly. The +logmap command line option exposes the internal state via an auxillary memory-mapped file that will survive a crash. The unprocessed content, if any, can be retrieved using the log_util program and this is something done automatically by the super-useful invokeAndRestart cover script.

Logging Message Style

In small organizations, one often finds that no formal structure on messages has been imposed. That flexibility usually disappears in organizations that are producing products for an international customer base. For example, a minimal convention would be to enforce the output of a unique message identifier for every line of output. A classic convention was to use a 3-or-4-character prefix corresponding to a particular product or component and a 3-or-4-digit number allocated within that particular product offering (e.g., "XGM028"). One benefit is that the message would be readily identifiable regardless of the locale of the end user.

Small organizations doing bespoke work for themselves will typically forgo such formal structure. There is still a great benefit to be obtained from structuring the message content in a way so that it can be parsed programmatically. It is strongly suggested that one adopt a style of outputting attribute=value elements because this convention goes a long way towards making log output machine-readable. A program such as parseAttrVal can take such content and format and display it in a variety of ways or even convert it into a CSV file.

$ parseAttrVal --help
usage: parseAttrVal [{‑‑csv | ‑‑flat | ‑‑perrow | ‑‑tree}] [‑‑path [n]] [‑‑separator C] [‑‑equals C] [{{‑‑quote C} | ‑‑noquote}] [{‑‑all | ‑‑struct | ‑‑ignore C}] [{‑‑findfirstvar C | ‑‑nofindfirstvar}] [‑‑noheader] [‑‑date] [‑‑time] {[‑f] fileName} ...]
   If no file specified, reads from stdin
  --csv = output as CSV file
  --flat = output as attribute/value pairs
  --perrow = flat, field separator is newline
  --tree = output as tree
  --json = output as JSON
  --jsonin = input is JSON (see json2line filter)
  --path = output variable name as full absolute path
  --path N = output variable with at most N elements
  --separator C = use C as field separator
  --lastseparator C = use C as field separator after last element
  --groupseparator C = use C as field separator after end of group
  --equals C = use C as name / value separator
  --quote C = use C as quote character around text values
  --noquote = do not quote text fields
  --ignore C = skip leading characters until first 'C'
  --all = skip no leading characters
  --structs = skip leading characters until first '['
  --findfirstvar C = start with first apparent attribute name found using assignment character C
  --nofindfirstvar = disable search for first attribute name
  --skip N = skip N characters before beginning parse
  --noheader = do not include CSV header line or variable names
  --date = also output date from log file line
  --time = also output time from log file line
  Default is: --csv --structs --findfirstvar = --path

More Efficient Logging

The examples presented to this point have all made use of some form of operator<<() with LOG_COUT(), LOG_CERR(), and LOG_WHEN(). This usage gives the appearance that items are being formatted and appended to a buffer, which will subsequently be written to a file descriptor. That is not really what is occurring. One of the paramount requirements for performance is to minimize data movement. The default output mechanism (and, yes, this means it can be overridden when there is a special case need) uses writev() or the equivalent to copy relevant data directly from the source without the need for an intermediate copy. This is illustrated by the strace output below:

753546 writev(1, [{iov_base="2020/07/15 13:43:39.268352 14040"..., iov_len=43},
 {iov_base="t.cpp", iov_len=5},
 {iov_base=":", iov_len=1},
 {iov_base="17", iov_len=2},
 {iov_base=" ", iov_len=1},
 {iov_base="INFO", iov_len=4},
 {iov_base=" ", iov_len=1},
 {iov_base="Hello, world\n", iov_len=13}], 8) = 70

This also has a positive effect on the data caches: frequently consistent data, such as the filename, will be present and the avoidance of unneccesary writes helps inhibit the invalidation of cache lines and the corresponding interference it causes with other processors. There are a few convenience macros that allow one to pass blocks of memory that are to be given special treatment. These include: AS_TEXT_BUFFER(), AS_ESCAPED_TEXT_BUFFER(), AS_BINARY_BUFFER(), AS_HEXADECIMAL_BUFFFER(). Thus a line like:

LOG_COUT(info) << "hex=" << AS_HEXADECIMAL_BUFFER("0123", 4) << LOG_ENDLINE;

yields output like:

hex=30313233

Developers required to handle internationalization will be well-aware that the convenience mechanisms shown so far are not a great match: there is no concept of a message template nor positional arguments. One would have to render the message first, then output it.

The Logging API's lower-level interfaces allow one to specify a message template and provide the corresponding arguments. The most commonly used are EMIT_CONDITIONAL_MESSAGE() and its unconditional equivalent ALWAYS_EMIT_MESSAGE(). For example:

    EMIT_CONDITIONAL_MESSAGE(info);
        LOG_MESSAGE_FORMAT("arg1=%d arg2=%d hex=%s\n");
        LOG_ARG(11);
        LOG_ARG(22);
        LOG_ARG(AS_HEXADECIMAL_BUFFER("0123", 4));
    AS_TIMESTAMPED_TEXT;

yields output into the log file similar to the line below:

2020/07/15 14:33:57.347014 140050054018880 t.cpp:39 INFO arg1=11 arg2=22 hex=30113233

The AS_TIMESTAMPED_TEXT clause above triggers the actual rendering of the content, while minimizing any data movement. Best-of-breed routines, such as uint_to_ascii() and float_to_ascii() are used internally to convert native numeric types into ASCII characters. Time information is represented as a NanosecondTimePoint and converted with the aid of one or more TimePointCache objects, which, among other things, avoids repeated kernel calls to stat() /etc/localtime.

There is a AS_BINARY_RECORD clause that can be used in scenarios where the data should not be rendered into ASCII. There are two common reasons for choosing to do this:

  1. Maximizing performance by eliminating computation and data movement: the minimal raw data is simply saved into the log file and no computation to render it into ASCII is performed.
  2. As a machine-readable interchange format.

Note that space savings is not one of the listed items. While there are scenarios where a binary log record is smaller than the corresponding textual output, this is definitely not something to be guaranteed. There are some opportunities for savings, such as the binary timestamp only requiring 8 bytes while the formatted date and time typically use up 27 characters and thread identifiers tend to be fairly long as well. But when a log line is finally rendered into ASCII, a lot of additional semantic information can be discarded, such as whether a data element was to be viewed as an integer, floating-point number, string, converted to hexadecimal, etc. Those attributes are retained in the binary log so that the data can be properly rendered later and thus do consume space.

The previous example could be reworked to become:

    EMIT_CONDITIONAL_MESSAGE(info);
        LOG_MESSAGE_FORMAT("arg1=%d arg2=%d hex=%s\n");
        LOG_ARG(11);
        LOG_ARG(22);
        LOG_ARG(AS_HEXADECIMAL_BUFFER("0123", 4));
    AS_BINARY_RECORD;

and the resulting log file would look similar to this hexadecimal output:

00000000: 314c ff00 9800 0000 7dbb 4006 8c0b 2216  1L......}.@...".
00000010: 4057 fa05 527f 0000 2a00 0000 4000 0000  @W..R...*...@...
00000020: 0300 0000 3000 0000 3600 0000 5000 0000  ....0...6...P...
00000030: 742e 6370 7000 6172 6731 3d25 6420 6172  t.cpp.arg1=%d ar
00000040: 6732 3d25 6420 6865 783d 2573 0a00 0000  g2=%d hex=%s....
00000050: 0400 0000 0400 0000 0800 0000 1000 0000  ................
00000060: 0b00 0000 0000 0000 0400 0000 0400 0000  ................
00000070: 0800 0000 1000 0000 1600 0000 0000 0000  ................
00000080: 9800 0000 0400 0000 0800 0000 1000 0000  ................
00000090: 3031 3233 0000 0000                      0123....

Feeding the file to mergeLogs will render it into ASCII:

$ mergeLogs *.log
2020/07/15 17:51:54.070809 139990264338240 t.cpp:42 INFO arg1=11 arg2=22 hex=30313233

Specialized Output Routines

The SPLIT_ACROSS_LINES() macro is a convenience cover to the LogMessageRecord::splitLongLogLine() routine. The AS_TEXT_BUFFER() macro can be used to denote a block of text for output that is not null-terminated. The near-identical AS_BINARY_BUFFER() macro can be used to denote a block of binary data. For situations in which the binary data should be displayed as hexadecimal characters, the AS_HEXADECIMAL_BUFFER() macro has the ability to generate hexadecimal output in either upper or lowercase characters. For binary records, only the original data is recorded and the expansion to hexadecimal occurs at the time of the final rendering. The related convenience macro AS_ESCAPED_TEXT_BUFFER works much like AS_TEXT_BUFFER() but adds the capability to replace characters on output with a sequence of 0, 1 or more alternative characters. These usually represent an escape sequence. The corresponding operator<<() for LogMessageRecord is clever enough to maximize the number of contiguous bytes that are added to the LogMessageRecord.

The LOG_STREAM_OBJECT() macro can be used to create a temporary LogManager object and associated LogMessageRecord that act as a std::ostringstream. The built-up contents of the buffer can be transferred using LOG_APPEND_BUFFER().

The FORMAT_LOG_BUFFER() macro can be used in a fashion somewhat similar to sprintf(); it formats the contents of a LogMessageRecord as text and returns a char pointer to the resulting string. The hidden scope that is introduced needs to be closed by the RELEASE_LOG_BUFFER() macro.

Custom Log Levels

A great deal of utility can be realized by the standard orthogonal log levels such as trace, debug, warn, error, etc. There are, however, scenarios in which a developer desires to create their own log levels. One reason is to declare an alternate log level name for a component, for example, assigning new component-specific labels for trace and debug log levels. A more complicated scenario involves developing a hierarchy of user-defined log levels, where enabling a high-level log level implies all of the log levels beneath it are also enabled; this in contrast to the normal orthogonal treatment of the standard log levels.

The setLogMask command recognizes user0 through user6 as denoting 7 orthogonal user-defined logging levels. It also recognizes level1 through level6 as denoting 6 hierachical logging levels.

$ setLogMask ‑‑help
usage: setLogMask [‑‑value] [‑q] [‑c logComponentName] [logMaskName[,logMask2[,..]]] {+|‑}{trace|debug|info|warn|error|fatal|user0...user6|level1...level6} ... [smvq args]
  userN identifies user-specific equivalence class
  levelN identifies a user-specific level that includes all prior levels
  --value ignores current value and sets specified value
  -q inhibits displaying final value as expanded attributes
  -c NAME allows selecting most recent instance of a particular application
    For example:  -c app-instance1
 A comma-separated list of logMask names can be specified.
 If none are specified, all found in the segment are addressed

The class AutoRegisterLogLevelName provides a mechanism to automatically call LogMessageRecord::define_commandline_flag() to register a new logging level name. The DEFINE_COMPONENT_USER_LOG_MASK() macro is the high-level interface for defining custom log levels; it trivially combines the DECLARE_COMPONENT_USER_LOG_MASK() and AUTO_REGISTER_USER_LOG_MASK() macros and would be used in a single source file. The DECLARE_COMPONENT_USER_LOG_MASK() macro can be used in header files to to permit the use of the log mask across multiple source files.


Last updated: 2024-04-12