This chapter is from the book
This chapter is from the book
This chapter is from the book
In most cases, people will use the standard ACE tracing and logging macros shown in Table 3.3. Sometimes, however, their behavior may need to be customized. Or you might want to create wrapper macros in anticipation of future customization.
Table 3.4. Commonly Used ACE_Log_Msg Methods
|
Method |
Purpose |
|---|---|
|
op_status |
The return value of the current function. By convention, –1 indicates an error condition. |
|
errnum |
The current errno value. |
|
linenum |
The line number on which the message was generated. |
|
file |
File name in which the message was generated. |
|
msg |
A message to be sent to the log output target. |
|
inc |
Increments nesting depth. Returns the previous value. |
|
dec |
Decrements the nesting depth. Returns the new value. |
|
trace_depth |
The current nesting depth. |
start_tracing stop_tracing tracing_enabled |
Enable/disable/query the tracing status for the current ACE_Log_Msg instance. The tracing status of a thread's ACE_LOG_MSG singleton determines whether an ACE_Trace object generates log messages. |
|
priority_mask |
Get/set the set of severity levels—at instance or process level—for which messages will be logged. |
|
log_priority_enabled |
Return non-zero if the requested priority is enabled. |
|
set |
Sets the line number, file name, op_status, and several other characteristics all at once. |
|
conditional_set |
Sets the line number, file name, op_status, and errnum values for the next log message; however, they take effect only if the next logging message's severity level is enabled. |
3.3.1 Wrapping ACE_DEBUG
Perhaps you want to ensure that all your LM_DEBUG messages contain a particular text string so that you can easily grep for them in your output file. Or maybe you want to ensure that every one of them is prefixed with the handy "%I" directive so they indent properly. If you lay the groundwork at the beginning of your project and encourage your coders to use your macros, it will be easy to implement these kinds of things in the future.
The following macro definitions wrap the ACE_DEBUG macro in a handy way. Note how we've guaranteed that every message will be properly indented, and we've prefixed each message to make searching for specific strings in the output easier.
#define DEBUG_PREFIX ACE_TEXT ("DEBUG%I")
#define INFO_PREFIX ACE_TEXT ("INFO%I")
#define NOTICE_PREFIX ACE_TEXT ("NOTICE%I")
#define WARNING_PREFIX ACE_TEXT ("WARNING%I")
#define ERROR_PREFIX ACE_TEXT ("ERROR%I")
#define CRITICAL_PREFIX ACE_TEXT ("CRITICAL%I")
#define ALERT_PREFIX ACE_TEXT ("ALERT%I")
#define EMERGENCY_PREFIX ACE_TEXT ("EMERGENCY%I")
#define MY_DEBUG(FMT, ...) ACE_DEBUG(( LM_DEBUG, DEBUG_PREFIX FMT __VA_ARGS__))
#define MY_INFO(FMT, ...) ACE_DEBUG(( LM_INFO, INFO_PREFIX FMT __VA_ARGS__))
#define MY_NOTICE(FMT, ...) ACE_DEBUG(( LM_NOTICE, NOTICE_PREFIX FMT __VA_ARGS__))
#define MY_WARNING(FMT, ...) ACE_DEBUG(( LM_WARNING, WARNING_PREFIX FMT __VA_ARGS__))
#define MY_ERROR(FMT, ...) ACE_DEBUG(( LM_ERROR, ERROR_PREFIX FMT __VA_ARGS__))
#define MY_CRITICAL(FMT, ...) ACE_DEBUG(( LM_CRITICAL, CRITICAL_PREFIX FMT __VA_ARGS__))
#define MY_ALERT(FMT, ...) ACE_DEBUG(( LM_ALERT, ALERT_PREFIX FMT __VA_ARGS__))
#define MY_EMERGENCY(FMT, ...) ACE_DEBUG(( LM_EMERGENCY, EMERGENCY_PREFIX FMT __VA_ARGS__))
Of course, it would be more useful if each of our prefixes were surrounded by an #ifdef to allow them to be overridden, but we leave that as an exercise to the reader.
Using these macros instead of the usual ACE_DEBUG macros is, as expected, easy to do:
#include "Trace.h"
void foo (void);
int ACE_TMAIN (int, ACE_TCHAR *[])
{
ACE_TRACE (ACE_TEXT ("main"));
MY_DEBUG (ACE_TEXT ("Hi Mom\n"));
foo ();
MY_DEBUG (ACE_TEXT ("Goodnight\n"));
return 0;
}
void foo (void)
{
ACE_TRACE (ACE_TEXT ("foo"));
MY_DEBUG (ACE_TEXT ("Howdy Pardner\n"));
}
Our output is nicely indented and prefixed as requested:
(1024) calling main in file `Wrap_Macros.cpp' on line 11 DEBUG Hi Mom (1024) calling foo in file `Wrap_Macros.cpp' on line 20 DEBUG Howdy Pardner (1024) leaving foo DEBUG Goodnight (1024) leaving main
The __VA_ARGS__ trick works fine for recent versions of the GNU C/C++ preprocessor but may not be available everywhere else, so be sure to read your compiler's documentation before committing yourself to this particular approach. If something similar isn't available to you, you can use a slightly less elegant approach:
#define MY_DEBUG LM_DEBUG, ACE_TEXT ("DEBUG%I")
#define MY_INFO LM_INFO, ACE_TEXT ("INFO%I")
#define MY_NOTICE LM_NOTICE, ACE_TEXT ("NOTICE%I")
#define MY_WARNING LM_WARNING, ACE_TEXT ("WARNING%I")
#define MY_ERROR LM_ERROR, ACE_TEXT ("ERROR%I")
#define MY_CRITICAL LM_CRITICAL, ACE_TEXT ("CRITICAL%I")
#define MY_ALERT LM_ALERT, ACE_TEXT ("ALERT%I")
#define MY_EMERGENCY LM_EMERGENCY, ACE_TEXT ("EMERGENCY%I")
This approach could be used something like this:
ACE_DEBUG ((MY_DEBUG ACE_TEXT ("Hi Mom\n")));
ACE_DEBUG ((MY_DEBUG ACE_TEXT ("Goodnight\n")));
It produces exactly the same output at the expense of slightly less attractive code.
3.3.2 ACE_Trace
We will now create an ACE_TRACE variant that will display the line number at which a function exits. The default ACE_Trace object implementation doesn't do this and doesn't provide an easy way for us to extend it, so, unfortunately, we have to create our own object from scratch. However, we can cut and paste from the ACE_Trace implementation in order to give ourselves a head start.
Consider this simple class:
class Trace
{
public:
Trace (const ACE_TCHAR *prefix,
const ACE_TCHAR *name,
int line,
const ACE_TCHAR *file)
{
this->prefix_ = prefix;
this->name_ = name;
this->line_ = line;
this->file_ = file;
ACE_Log_Msg *lm = ACE_LOG_MSG;
if (lm->tracing_enabled ()
&& lm->trace_active () == 0)
{
lm->trace_active (1);
ACE_DEBUG
((LM_TRACE,
ACE_TEXT ("%s%*s(%t) calling %s in file `%s'")
ACE_TEXT (" on line %d\n"),
this->prefix_,
Trace::nesting_indent_ * lm->inc (),
ACE_TEXT (""),
this->name_,
this->file_,
this->line_));
lm->trace_active (0);
}
}
void setLine (int line)
{
this->line_ = line;
}
~Trace (void)
{
ACE_Log_Msg *lm = ACE_LOG_MSG;
if (lm->tracing_enabled ()
&& lm->trace_active () == 0)
{
lm->trace_active (1);
ACE_DEBUG
((LM_TRACE,
ACE_TEXT ("%s%*s(%t) leaving %s in file `%s'")
ACE_TEXT (" on line %d\n"),
this->prefix_,
Trace::nesting_indent_ * lm->dec (),
ACE_TEXT (""),
this->name_,
this->file_,
this->line_));
lm->trace_active (0);
}
}
private:
enum { nesting_indent_ = 3 };
const ACE_TCHAR *prefix_;
const ACE_TCHAR *name_;
const ACE_TCHAR *file_;
int line_;
};
Trace is a simplified version of ACE_Trace. Because our focus is printing a modified function exit message, we chose to leave out some of the more esoteric ACE_Trace functionality. We did, however, include a prefix parameter to the constructor so that each entry/exit message can be prefixed (before indentation), if you want. In an ideal world, you would simply use the following method to select the messages you're interested in: ACE_Log_Msg::priority_mask(). On the other hand, if you're asked to do a postmortem analysis of a massive, all-debug-enabled log file, the prefixes can be quite handy.
With our new Trace class available to us, we can now create a set of simple macros that will use this new class to implement function tracing in our code:
#define TRACE_PREFIX ACE_TEXT ("TRACE ")
#if (ACE_NTRACE == 1)
# define TRACE(X)
# define TRACE_RETURN(V)
# define TRACE_RETURN_VOID()
#else
# define TRACE(X) Trace ____ (TRACE_PREFIX, ACE_TEXT (X), __LINE__, ACE_TEXT (__FILE__))
# define TRACE_RETURN(V) do { ____.setLine(__LINE__); return V; } while (0)
# define TRACE_RETURN_VOID() do { ____.setLine(__LINE__); } while (0)
#endif
The addition of the TRACE_RETURN and TRACE_RETURN_VOID macros is how our Trace object's destructor will know to print the line number at which the function exits. Each of these macros uses the convenient setLine() method to set the current line number before allowing the Trace instance to go out of scope, destruct, and print our message.
This is a simple example using our new object:
#include "Trace.h"
void foo (void);
int ACE_TMAIN (int, ACE_TCHAR *[])
{
TRACE (ACE_TEXT ("main"));
MY_DEBUG (ACE_TEXT ("Hi Mom\n"));
foo ();
MY_DEBUG (ACE_TEXT ("Goodnight\n"));
TRACE_RETURN (0);
}
void foo (void)
{
TRACE (ACE_TEXT ("foo"));
MY_DEBUG (ACE_TEXT ("Howdy Pardner\n"));
TRACE_RETURN_VOID ();
}
It produces the following output:
TRACE (1024) calling main in file `Trace_Return.cpp' on line 11 DEBUG Hi Mom TRACE (1024) calling foo in file `Trace_Return.cpp' on line 22 DEBUG Howdy Pardner TRACE (1024) leaving foo in file `Trace_Return.cpp' on line 24 DEBUG Goodnight TRACE (1024) leaving main in file `Trace_Return.cpp' on line 17
Although the output is a bit wordy, we succeeded in our original intent of printing the line number at which each function returns. Although that may seem like a small thing for a trivial program, consider the fact that few useful programs are trivial. If you are trying to understand the flow of a legacy application, it may well be worth your time to liberally instrument it with TRACE and TRACE_RETURN macros to get a feel for the paths taken. Of course, training yourself to use TRACE_RETURN may take some time, but in the end, you will have a much better idea of how the code flows.