Skip to content

Logging

Jump to bottom Edit New page
James Edmondson edited this page Sep 25, 2018 · 44 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 with the KB

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.

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