Using the ACE Logging Facility
This chapter is from the book
This chapter is from the book
This chapter is from the book
Every program needs to display diagnostics: error messages, debugging output, and so on. Traditionally, we might use a number of printf() calls or cerr statements in our application in order to help trace execution paths or display helpful runtime information. ACE's logging facility provides us with ways to do these things while at the same time giving us great control over how much of the information is printed and where it is directed.
It is important to have a convenient way to create debug statements. In this modern age of graphical source-level debuggers, it might seem strange to pepper your application with the equivalent of a bunch of print statements. However, diagnostic statements are useful both during development and long after an application is considered to be bug free.
-
They can record information while the program is running and a debugger isn't available or practical, such as with a server.
-
They can record output during testing for regression analysis, as the ACE test suite does.
The ACE mechanisms allow us to enable and disable these statements at compile time. When compiled in, they can also be enabled and disabled at will at runtime. Thus, you don't have to pay for the overhead—in either CPU cycles or disk space—under normal conditions. But if a problem arises, you can easily cause copious amounts of debugging information to be recorded to assist you in finding and fixing it. It is an unfortunate fact that many bugs will never appear until the program is in the hands of the end user.
In this chapter, we cover how to
-
Use basic logging and tracing techniques
-
Enable and disable display of various logging message severities
-
Customize the logging mechanics
-
Direct the output messages to various logging sinks
-
Capture log messages before they're output
-
Use the distributed ACE logging service
-
Combine various logging facility features
-
Dynamically configure logging sinks and severity levels
3.1 Basic Logging and Tracing
Three macros are commonly used to display diagnostic output from your code: ACE_DEBUG, ACE_ERROR, and ACE_TRACE. The arguments to the first two are the same; their operation is nearly identical, so for our purposes now, we'll treat them the same. They both take a severity indicator as one of the arguments, so you can display any message using either; however, the convention is to use ACE_DEBUG for your own debugging statements and ACE_ERROR for warnings and errors. The use of these macros is the same:
ACE_DEBUG ((severity, formatting-args)); ACE_ERROR ((severity, formatting-args));
The severity parameter specifies the severity level of your message. The most common levels are LM_DEBUG and LM_ERROR. All the valid severity values are listed in Table 3.1.
The formatting-args parameter is a printf()-like set of format conversion operators and formatting arguments for insertion into the output. The complete set of formatting directives is described in Table 3.2. One might wonder why printf()-like formatting was chosen instead of the more natural—to C++ coders—C++ iostream-style formatting. In some cases, it would have been easier to correctly log certain types of information with type-safe insertion operators. However, an important factor in the logging facility's design is the ability to effectively "no-op" the logging statements at compile time. Note that the ACE_DEBUG and ACE_ERROR invocations require two sets of parentheses. The outer set delimits the single macro argument. This single argument comprises all the arguments, and their enclosing parentheses, needed for a method call. If the preprocessor macro ACE_NDEBUG is defined, the ACE_DEBUG macro will expand to a blank line, ignoring the content of the inner set of parentheses. Achieving this same optimization with insertion operators would have resulted in a rather odd usage:
ACE_DEBUG ((debug_info << "Hi Mom" << endl));
Table 3.1. ACE_Log_Msg Logging Severity Levels
|
Severity Level |
Meaning |
|---|---|
|
LM_TRACE |
Messages indicating function-calling sequence |
|
LM_DEBUG |
Debugging information |
|
LM_INFO |
Messages that contain information normally of use only when debugging a program |
|
LM_NOTICE |
Conditions that are not error conditions but that may require special handling |
|
LM_WARNING |
Warning messages |
|
LM_ERROR |
Error messages |
|
LM_CRITICAL |
Critical conditions, such as hard device errors |
|
LM_ALERT |
A condition that should be corrected immediately, such as a corrupted system database |
|
LM_EMERGENCY |
A panic condition, normally broadcast to all users |
Similarly, many of the formatting tokens, such as %I, would have been awkward to implement and overly verbose to use:
ACE_DEBUG((debug_info<<ACE_Log_Msg::nested_indent<<"Hi Mom"<<endl));
One could argue away the compile-time optimization by causing ACE_NDEBUG to put the debug output stream object into a no-op mode. That may be sufficient for some platforms, but for others, such as embedded real-time systems, you really do want the code to simply not exist.
Unlike ACE_DEBUG and ACE_ERROR, which cause output where the macro is placed, ACE_TRACE causes one line of debug information to be printed at the point of the ACE_TRACE statement and another when its enclosing scope is exited. Therefore, placing an ACE_TRACE statement at the beginning of a function or method provides a trace of when that function or method is entered and exited. The ACE_TRACE macro accepts a single character string rather than a set of formatting directives. Because C++ doesn't have a handy way to dump a stack trace, this can be very useful indeed.
Let's take a look at a simple application:
#include "ace/Log_Msg.h"
void foo (void);
int ACE_TMAIN (int, ACE_TCHAR *[])
{
ACE_TRACE(ACE_TEXT ("main"));
ACE_DEBUG ((LM_INFO, ACE_TEXT ("%IHi Mom\n")));
foo();
ACE_DEBUG ((LM_INFO, ACE_TEXT ("%IGoodnight\n")));
return 0;
}
void foo (void)
{
ACE_TRACE (ACE_TEXT ("foo"));
ACE_DEBUG ((LM_INFO, ACE_TEXT ("%IHowdy Pardner\n")));
}
Our first step is always to include the Log_Msg.h header file. It defines many helpful macros, including ACE_DEBUG and ACE_ERROR, to make your life easier. The full set of output-producing macros is listed in Table 3.3.
You can use ACE_DEBUG to print just about any arbitrary string you want, and the many format directives listed in Table 3.2 can also be modified with printf()-style modifiers for length, precision, and fill adjustments. (See a printf() reference for details on the modifiers.) In the preceding example, we've used %I so that the ACE_DEBUG messages are nicely indented along with the ACE_TRACE messages.
If you compile and execute the preceding code, you should get something like this:
(1024) calling main in file `Simple1.cpp' on line 7
Hi Mom
(1024) calling foo in file `Simple1.cpp' on line 18
Howdy Pardner
(1024) leaving foo
Goodnight
(1024) leaving main
Table 3.2. ACE Logging Format Directives
|
Code |
Argument Type |
Displays |
|---|---|---|
|
A |
ACE_timer_t |
Floating-point number; long decimal number if platform doesn't support floating point |
|
a |
— |
Aborts the program after displaying output |
|
c |
char |
Single character |
|
C |
char* |
Character string (narrow characters) |
|
i,d |
int |
Decimal number |
|
I |
— |
Indents output according to the nesting depth, obtained from ACE_Trace::get_nesting_indent() |
|
e,E,f,F,g,G |
double |
Double-precision floating-point number |
|
l |
— |
Line number where logging macro appears |
|
M |
— |
Text form of the message severity level |
|
m |
— |
Message corresponding to errno value, as done by strerror(), for example |
|
N |
— |
File name where logging macro appears |
|
n |
— |
Program name given to ACE_Log_Msg::open() |
|
o |
int |
Octal number |
|
P |
— |
Current process ID |
|
p |
ACE_TCHAR* |
Specified character string, followed by the appropriate errno message, that is, as done by perror() |
|
Q |
ACE_UINT64 |
Decimal number |
|
r |
void (*)() |
Nothing; calls the specified function |
|
R |
int |
Decimal number |
|
S |
int |
Signal name of the numbered signal |
|
s |
ACE_TCHAR* |
Character string: narrow or wide, according to ACE_TCHAR type |
|
T |
— |
Current time as hour:minute:sec.usec |
|
D |
— |
Timestamp as month/day/year hour:minute:sec.usec |
|
t |
— |
Calling thread's ID (1 if single threaded) |
|
u |
int |
Unsigned decimal number |
|
w |
wchar_t |
Single wide character |
|
W |
wchar_t* |
Wide-character string |
|
x,X |
int |
Hexadecimal number |
|
@ |
void* |
Pointer value in hexadecimal |
|
% |
N/A |
Single percent sign: "%" |
The compile-time values of three configuration settings control whether the logging macros produce logging method calls: ACE_NTRACE, ACE_NDEBUG, and ACE_NLOGGING. These macros are all interpreted as "not." For example, ACE_NTRACE is "not tracing" when its value is 1. To enable the configuration area, set the macro to 0. ACE_NTRACE usually defaults to 1 (disabled), and the others default to 0 (enabled). Table 3.3 shows which configuration setting controls each logging macro. This allows you to sprinkle your code with as little or as much debug information as you want and then turn it on or off when compiling.
When deciding which features to enable, be aware that ACE_TRACE output is conditional on both the ACE_NTRACE and ACE_NDEBUG configuration settings. The reason is that the ACE_TRACE macro, when enabled, expands to instantiate an ACE_Trace object. The ACE_Trace class's constructor and destructor use ACE_DEBUG to log the entry and exit messages. They're logged at the LM_TRACE severity level, so that level also must be enabled at runtime to show any tracing output; it is enabled by default.