Skip to content

Logging

Jump to bottom Edit New page
James Edmondson edited this page Sep 25, 2018 · 43 revisions

C++ Guide Series
Architecture | Knowledge Base | Networking | Containers | Threads | Optimizations | KaRL | Encryption | Checkpointing | Knowledge Performance | Logging

Overview

Logging is the process of saving or printing useful information to a console, file, or knowledge base that can be used for later analysis or forensics. Logging is especially useful for debugging problems that occurred during an execution of a MADARA-enabled program. In this wiki, we'll describe how to use madara::logger::Logger, the global logger, custom loggers, thread local logging, and also the performance potential of using the KnowledgeBase class itself.

The types of logging in MADARA

Table of Contents

The Basics of Print-based Logging

Print-based logging is the process of printing useful text-based messages to a console, system logger, or file. In MADARA logging, there is no STDOUT or std::cout target because MADARA is primarily focused on multi-threaded, multi-agent systems, and STDOUT is a buffered output. Consequently, MADARA text-based logging focuses on STDERR, system loggers, and files through the madara::logger::Logger class. The built-in MADARA Logger class works in exactly the same way that the C-style printf works.

The Functions Available to the Logger

void 	add_file (const std::string &filename)
 	Adds a file to the logging output
 
void 	add_syslog (void)
 	Adds the system logger to the logging output (Android, stderr)
 
void 	add_term (void)
 	Adds terminal to logger outputs (On Android, also means syslog)
 
void 	clear (void)
 	Clears all log targets. Useful for removing the default add_term
 
int 	get_level (void)
 	Gets the maximum logging detail level
 
std::string 	get_tag (void)
 	Gets the tag used for syslogs (e.g. Android)
 
void 	log (int level, const char * message,...)
 	Logs a message to all added loggers
 
void 	set_level (int level)
 	Sets the maximum logging detail level
 
void 	set_tag (const std::string &tag)
 	Sets the tag used for syslogs
 
void 	set_timestamp_format (const std::string &format="%x %X: ")
        Sets a prefix to all log messages that can include time information, threading, etc.

Logging Levels

When you use a custom logger (an instantiation of madara::logger::Logger in your program), you can set any levels you want from 0 to INT_MAX. It is recommended that you make your own logger level enumeration and then use this when you are using the Logger class. However, you can also use the logging levels provided in the madara/logger/Logger.h file.

The important thing to understand about logging levels is that logging events consists of two levels: 1) the level of the event and 2) the maximum event level that your logger is logging at the moment.

The MADARA Log Levels

enum LogLevels
{
  LOG_EMERGENCY = 0,    // emergencies (usually errors that are absolutely necessary) 
  LOG_ALWAYS = 0,       // events that are always logged, no matter the set level
  LOG_ERROR = 1,        // error events (DEFAULT LOG LEVEL)
  LOG_WARNING = 2,      // warning events
  LOG_MAJOR = 3,        // major events such as results of functions/features
  LOG_MINOR = 4,        // minor events within functions/features
  LOG_TRACE = 5,        // trace through functions
  LOG_DETAILED = 6      // extreme detail

Efficient Logging Macros

In general, you should never use the log method directly on an instance of madara::logger::Logger unless the level is LOG_EMERGENCY or LOG_ALWAYS. The reason why is because logging is one of the most expensive operations possible in the MADARA toolset, and when you use log, you also use all of its arguments--which almost always includes more expensive function calls that create arguments.

Consider one of the more common printable information: strings. Building a string is expensive, and you may want to do something like this: logger.log (LOG_MINOR, "My name is %s\n", (first_name + middle_name + last_name).c_str ()).

If you call log like this, what your compiler will do is evaluate each argument in the log method and then call the log function. The problem is that adding 3 std::string variables together can take microseconds, depending on your CPU, and the log level here is only LOG_MINOR. If the log level is set to the default of 1 (LOG_ERROR), then this operation and the message itself should not be compiled and evaluated. There's no way to really make this happen with madara::logger::Logger::log, but there are special macros provided in MADARA that only allow log to be evaluated if the log level is appropriate. These logger macros are discussed below:

madara_logger_log(logger, level, message, args):
  // Expand args and log to a logger instance if the level is appropriate

madara_logger_ptr_log(logger_ptr, level, message, args):
  // Expand args and log to a logger pointer if the level is appropriate

madara_logger_cond_log_ptrs(conditional, logger_ptr, alt_logger_ptr, level, message, args):
  // Expand args and log to a logger pointer if the condition is true and the level is appropriate.
  // If the condition is false and the level is appropriate, log to the alternate logger pointer

madara_logger_cond_log(conditional, logger, alt_logger_ptr, level, message, args):
  // Expand args and log to a logger instance if the condition is true and the level is appropriate.
  // If the condition is false and the level is appropriate, log to the alternate logger pointer

Examples of Print-Based Logging

Example of Logging to STDERR

With a custom MADARA logger:

Code

#include "madara/logger/Logger.h"

int my_variable = 10;
std::string my_string = "this string";

// by default, loggers print to stderr
madara::logger::Logger logger;
logger.log (madara::logger::LOG_ALWAYS, "My variable is %d. My string is %s\n",
  my_variable, my_string.c_str ());

Console Output

My variable is 10. My string is this string

Example of Logging to Files

Code

#include "madara/logger/Logger.h"

int my_variable = 10;
std::string my_string = "this string";
std::string my_file_name = "logger_output.txt";

// by adding file, we print to both stderr and the file. To only print to file,
// we would need to call clear() before calling add_file(my_file_name)
madara::logger::Logger logger;
logger.add_file (my_file_name);

logger.log (madara::logger::LOG_ALWAYS, "My variable is %d. My string is %s\n",
  my_variable, my_string.c_str ());

Console Output

My variable is 10. My string is this string

Contents of logger_output.txt

My variable is 10. My string is this string

Example of Logging with a Prefix

Code

#include "madara/logger/Logger.h"

int my_variable = 10;
std::string my_string = "this string";
std::string my_file_name = "logger_output.txt";

// set_timestamp_format supports anything in strftime and also a few custom symbols:
// %MGT: get current time in seconds.nanoseconds
// %MTN: get thread name (discussed more later in thread local)
// %MTZ: get thread hertz (discussed more later in thread local)
madara::logger::Logger logger;
logger.set_timestamp_format ("%x %X: MyProgram: ");

logger.log (madara::logger::LOG_ALWAYS, "My variable is %d. My string is %s",
  my_variable, my_string.c_str ());

Console Output

09/24/18 12:00:05: MyProgram: My variable is 10. My string is this string

Example of Logging Levels

Code

#include "madara/logger/Logger.h"

madara::logger::Logger logger;
logger.set_level (madara::logger::LOG_MAJOR);

logger.log (madara::logger::LOG_ALWAYS, "This message is LOG_ALWAYS (0)\n");
logger.log (madara::logger::LOG_ERROR, "This message is an error at LOG_ERROR (1)\n");
logger.log (madara::logger::LOG_WARNING, "This message is LOG_WARNING (2)\n");
logger.log (madara::logger::LOG_MAJOR, "This message is LOG_MAJOR (3)\n");
logger.log (madara::logger::LOG_MINOR, "This message is LOG_MINOR (4)\n");
logger.log (madara::logger::LOG_TRACE, "This message is LOG_TRACE (5)\n");
logger.log (madara::logger::LOG_DETAILED, "This message is LOG_DETAILED (6)\n");

Console Output

This message is LOG_ALWAYS (0)
This message is an error at LOG_ERROR (1)
This message is LOG_WARNING (2)
This message is LOG_MAJOR (3)

Example of Efficient Logging Macros

Code

#include "madara/logger/Logger.h"

madara::logger::Logger logger;
logger.set_level (madara::logger::LOG_MAJOR);

madara_logger_log (logger, madara::logger::LOG_ALWAYS, "This message is LOG_ALWAYS (0)\n");
madara_logger_log (logger, madara::logger::LOG_ERROR, "This message is an error at LOG_ERROR (1)\n");
madara_logger_log (logger, madara::logger::LOG_WARNING, "This message is LOG_WARNING (2)\n");
madara_logger_log (logger, (madara::logger::LOG_MAJOR, "This message is LOG_MAJOR (3)\n");
madara_logger_log (logger, madara::logger::LOG_MINOR, "This message is LOG_MINOR (4)\n");
madara_logger_log (logger, madara::logger::LOG_TRACE, "This message is LOG_TRACE (5)\n");
madara_logger_log (logger, madara::logger::LOG_DETAILED, "This message is LOG_DETAILED (6)\n");

Console Output

This message is LOG_ALWAYS (0)
This message is an error at LOG_ERROR (1)
This message is LOG_WARNING (2)
This message is LOG_MAJOR (3)

Global Loggers

MADARA provides a global logger at madara::logger::global_logger that is used for all MADARA-related logging events to all configured targets. The global_logger is not encouraged for usage in your MADARA applications due to the fact that thousands of events are being logged within the MADARA middleware. However, if all of your logging events are at LOG_ALWAYS, then it is reasonable to use the global_logger to mix your own log events into the mix. The global_logger is a singleton instance of madara::logger::Logger with static scope (you can use it anywhere).

Code

#include "madara/logger/GlobalLogger.h"

madara::logger::Logger logger;
logger.set_level (madara::logger::LOG_ERROR);

madara_logger_ptr_log (madara::logger::global_logger.get (), madara::logger::LOG_ALWAYS, "This message is LOG_ALWAYS (0)\n");

Console Output

This message is LOG_ALWAYS (0)

Thread Local Loggers

While debugging multi-threaded code, you will likely want thread-specific logging to isolate the events within single threads that you are focusing on debugging. To aid in achieving this, madara::logger::Logger has a special log level that overrides the levels of the global_logger and any custom instances of madara::logger::Logger. What this effectively means is that if you use the thread local logger level, it will allow you to have two different log levels: 1) what the thread local logging level specifies in that thread and 2) what every other thread logs at.

Code

#include "madara/logger/Logger.h"

madara::logger::Logger logger;

// set a log level for the main thread to logging level ERROR (1)
logger.set_level (madara::logger::LOG_ERROR);

// inside of your new thread "thread0", set the thread local logging level to MAJOR (3)
madara::logger::set_thread_level (madara::logger::LOG_MAJOR);

// within the main program and your new thread, issue the following log events
madara_logger_ptr_log (madara::logger::global_logger.get (),
  madara::logger::LOG_ALWAYS, "This message is LOG_ALWAYS (0)\n");
madara_logger_ptr_log (madara::logger::global_logger.get (),
  madara::logger::LOG_MAJOR, "This message is LOG_MAJOR (3)\n");
madara_logger_ptr_log (madara::logger::global_logger.get (),
  madara::logger::LOG_MINOR, "This message is LOG_MINOR (4)\n");

Console Output (main)

This message is LOG_ALWAYS (0)

Console Output (thread0)

This message is LOG_ALWAYS (0)
This message is LOG_MAJOR (3)

Note that neither thread will print the LOG_MINOR event because neither had a log level at that high of a level.

Logging to the KnowledgeBase

Printing log events to STDERR or files is always expensive. Such log events tend to take between microseconds and milliseconds on any given operating system, and certain types of hardware can make the latency of logging even worse. For instance, on magnetic hard disks, the mechanical heads will cause excessive seek and write times in comparison to SSD hard disks.

So are there other options for logging that are faster? Yes. You can use a KnowledgeBase.

Serialized Temporal Knowledge

The basis of logging to a KnowledgeBase is with checkpoints and serialization of KB states to a binary format. We call a layered series of KnowledgeBase checkpoints Serialized Temporal Knowledge (STK). STKs are built from an initial set of knowledge and then as modifications are made to the KnowledgeBase, these modifications (merged into a Layer) are added to the saved KnowledgeBase in temporal order. Consequently, a STK is a sequence of Layers with each Layer containing one ore more modifications to knowledge.

There are multiple ways to create a STK, but the recommended way to create a STK is with the CheckpointStreamer, as it is the most intuitive, least prone to human error, and requires the least setup and code to keep the stream of updates going to the STK file. The following shows a simple example of saving a STK.

Saving Serialized Temporal Knowledge

In essence, to log to the KB, you need to modify variables normally and the resulting STK file will be your log of interactions and knowledge changes. The following example shows how to enable streaming of knowledge to a file called stream.stk.

Saving STKs

#include "madara/knowledge/KnowledgeBase.h"
#include "madara/knowledge/CheckpointStreamer.h"
#include "madara/utility/Utility.h"

using knowledge = madara::knowledge;
using utility = madara::utility;

knowledge::KnowledgeBase kb;
knowledge::CheckpointSettings settings;

settings.filename = "stream.stk";

// write up to 100 times per second
auto streamer = std::make_unique<knowledge::CheckpointStreamer>(std::move(settings), kb, 100);
kb.attach_streamer(std::move(streamer));

// write to var1 twice, separated by 1 second.
kb.set("var1", 1);
utility::sleep (1.0);
kb.set("var1", 2);
kb.set("var2", 3);

// at this point, 2 changes are saved to var1 and 1 change to var2 in the STK

// print the resulting information will only show the current value
// of var1 (2) and var2 (3)
kb.print ();

Inspecting Serialized Temporal Knowledge

To read a log of variables saved to a STK, you need to inspect the STK file. Two tools in the MADARA project are useful for inspecting STKs from the command line: $MADARA_ROOT/bin/karl and $MADARA_ROOT/bin/stk_inspect. Both are compiled as part of a base install of MADARA with $GAMS_ROOT/scripts/linux/base_install madara or any combinations with madara.

Printing final knowledge with karl

$MADARA_ROOT/bin/karl -0b stream.stk -k

Console Output

Knowledge in Knowledge Base:
  var1 = 2
  var2 = 3

Inspecting an STK with stk_inspect

To print out performance and debugging information with STK inspect, do not use the -s option to save to a file

$MADARA_ROOT/bin/stk_inspect -f stream.stk -k

Console Output

var1: 2 updates (@1hz) (@0.008KB/s) (Size: Min 8B, Max 8B)
var2: 1 updates (@0.5hz) (@0.004KB/s) (Size: Min 8B, Max 8B)

Knowledge in Knowledge Base:
  var1 = 2
  var2 = 3

For larger STKs, it's much faster to use the -s option to save the performance and debugging information to a file

$MADARA_ROOT/bin/stk_inspect -f stream.stk -k -s stream_data.txt

Console Output

Knowledge in Knowledge Base:
  var1 = 2
  var2 = 3

Contents of stream_data.txt

var1: 2 updates (@1hz) (@0.008KB/s) (Size: Min 8B, Max 8B)
var2: 1 updates (@0.5hz) (@0.004KB/s) (Size: Min 8B, Max 8B)

Logging Transport Data to KnowledgeBase

MADARA has built-in logging to KBs which you can take advantage of to help debug networking performance. To enable debugging a transport's operation into your KB, you need to use the function debug_to_kb on the TransportSettings class instance that you pass into the constructor of a KnowledgeBase or the KnowledgeBase::attach_transport function.

Transport Debug Information

The following information is logged to the KnowledgeBase when you use the debug_to_kb function.

.transport.failed_receives=receives that did not return packets
.transport.failed_sends=sends that did not succeed
.transport.received_data=amount of data in bytes that have been received
.transport.received_data_max=the maximum bytes received in a packet
.transport.received_data_min=the minimum bytes received in a packet
.transport.received_packets=the number of received packets
.transport.sent_data=the amount of data in bytes that have been sent
.transport.sent_data_max=the maximum bytes sent in a packet
.transport.sent_data_min=the minimum bytes sent in a packet
.transport.sent_packets=number of sent packets

Transport Debug Example Usage

#include "madara/transports/TransportSettings.h"
#include "madara/knowledge/KnowledgeBase.h"

madara::transport::TransportSettings settings;
settings.debug_to_kb (".transport1");

madara::knowledge::KnowledgeBase kb ("agent0", settings);

Logging Threader Data to KnowledgeBase

MADARA has built-in logging to KBs which you can take advantage of to help debug threading performance. To enable debugging a thread's operation into your KB, you need to use the function debug_to_kb on the Threader class that you use to launch MADARA threads.

Thread Debug Information

.threader.hertz=intended thread hertz rate
.threader.thread0.end_time=last timestamp of the thread executions
.threader.thread0.executions=number of executions
.threader.thread0.last_duration=last run duration of a thread
.threader.thread0.last_start_time=last start timestamp
.threader.thread0.max_duration=max run duration of a thread
.threader.thread0.min_duration=min run duration of a thread
.threader.thread0.start_time=the first timestamp of thread executions

Thread Debug Example Usage

#include "madara/threads/Threader.h"

madara::knowledge::KnowledgeBase kb ("agent0", settings);
madara::threads::Threader threader (kb);
threader.debug_to_kb (".threads");

Event-Based Transport Filters

In addition to the above built-in debugging information, you can also create custom extensions of madara::transport::AggregateFilters to save information into the KnowledgeBase. To do this, simply use the madara::knowledge::Variables interface (the third argument to an AggregateFilter's filter method) and set the variables you want to save, as appropriate. See the Networking wiki for more information on AggregateFilter. For examples, see the many filters provided by MADARA in the $MADARA_ROOT/include/madara/filters directory (API docs | Repo).

Custom Event and Performance Logging

Once you start a CheckpointStream to a STK file, any variable you create or modify in the KnowledgeBase will be logged into the STK file alongside the other knowledge. This means that you can insert debug symbols, almost like your own logging debug state machine that can be read and inspected later with karl, stk_inspect, or any KnowledgeBase replay mechanism such as madara::knowledge::CheckpointReader or madara::knowledge::CheckpointPlayer.

This may appear more complicated than it is, so let's try to make this clear with an example. Consider the following function with logging information embedded into the KB rather than using print statements.

#include "madara/knowledge/KnowledgeBase.h"
#include "madara/knowledge/CheckpointStreamer.h"
#include "madara/utility/Utility.h"
#include "madara/knowledge/containers/Integer"

namespace knowledge = madara::knowledge;
namespace containers = knowledge::containers;
namespace utility = madara::utility;

// logging event Integer containers to setup later and use in my_function_call
containers::Integer function_call_begin;
containers::Integer function_call_end;

/// create a function that has logging events embedded into the KB
void my_function_call (knowledge::KnowledgeBase kb)
{
  ++function_call_begin;

  // note that we could have used a containers::Integer here
  // but this is just showing another way of doing this
  kb.set ("my_var", kb.get ("my_var") + 1, knowledge::EvalSettings::DELAY);

  ++function_call_end;
}

...

knowledge::KnowledgeBase kb;
knowledge::CheckpointSettings settings;

// setup two debug logging event integers in the KB
function_call_begin.set_name ("function_call.begin", kb);
function_call_end.set_name ("function_call.end", kb);

settings.filename = "stream.stk";

// write up to 100 times per second
auto streamer = std::make_unique<knowledge::CheckpointStreamer>(std::move(settings), kb, 100);
kb.attach_streamer(std::move(streamer));

// call the function 100 times to increment var and the begin and end logging events
for (int i = 0; i < 100; ++i)
{
  my_function_call (kb);

  // sleep for 1s, just because (we're just creating some temporal space in the STK)
  utility.sleep (1.0);
}

Now, let's run the stk_inspect on the stream.stk and see what's inside

$MADARA_ROOT/bin/stk_inspect -f stream.stk -k -s stream_data.txt

Console Output

Knowledge in Knowledge Base:
  function_call.begin = 100
  my_var = 100
  function_call.end = 100

Contents of stream_data.txt

function_call.begin: 100 updates (@1hz) (@0.008KB/s) (Size: Min 8B, Max 8B)
my_var: 100 updates (@1hz) (@0.008KB/s) (Size: Min 8B, Max 8B)
function_call.end: 100 updates (@1hz) (@0.008KB/s) (Size: Min 8B, Max 8B)

The average time to save an integer into the KB ranges between 40 and 100ns, depending on the operating system and hardware. In comparison to the time taken for printing log messages to STDERR or FILES (which can take hundreds of microseconds to even milliseconds), this is extremely fast and efficient.

C++ Guide Series
Architecture | Knowledge Base | Networking | Containers | Threads | Optimizations | KaRL | Encryption | Checkpointing | Knowledge Performance | Logging

Add a custom footer
Add a custom sidebar
Clone this wiki locally