Home > Articles > Programming

  • Print
  • + Share This
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.

  • + Share This
  • 🔖 Save To Your Account