ACE TAO Programming [005] 简单介绍日志功能的实现

 

3.1 Basic Logging and Tracing

通常，用ACE_DEBUG, ACE_ERROR, and ACE_TRACE这三个宏来输出诊断信息

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;

 

然而，ACE_DEBUG通常用来输出自己的调试信息；ACE_ERROR用来输出警告和错误

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.

 

最常用的就是LM_DEBUG和LM_ERROR

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.

 

 

 

3.2 Enabling and Disabling Logging Severities

Consider this slightly modified code:

#include "ace/Log_Msg.h"void foo(void);int ACE_TMAIN (int, ACE_TCHAR *[]){  ACE_TRACE (ACE_TEXT ("main"));  ACE_LOG_MSG->priority_mask (LM_DEBUG | LM_NOTICE, ACE_Log_Msg::PROCESS); /*设定log信息的权限值，此处允许DEBUG和NOTICE消息输出，其他禁止*/  ACE_DEBUG ((LM_INFO, ACE_TEXT ("%IHi Mom/n")));  foo ();  ACE_DEBUG ((LM_DEBUG, ACE_TEXT ("%IGoodnight/n")));  return 0;}void foo(void){  ACE_TRACE (ACE_TEXT ("foo"));  ACE_DEBUG ((LM_NOTICE, ACE_TEXT ("%IHowdy Pardner/n")));}

The following output is produced:

(1024) calling main in file `Simple2.cpp' on line 7      Howdy Pardner   Goodnight

在这个例子中，我们在运行时改变了logging level，只有DEBUG和NOTICE信息得以输出，其他信息都被忽略了

In this example, we changed the logging level at runtime so that only messages logged with LM_DEBUG and LM_NOTICE priority are displayed;

all others are ignored. The LM_INFO "Hi Mom" message is not displayed,

 

也没有TRACE信息输出

and there is no ACE_TRACE output.

 

此处也稍微透露出ACE日志类是如何工作的。在ACE中，ACE_Log_Msg类实现了对消息的格式化。

对于每一个产生的线程，ACE自动维护一个线程相关的单件模式的ACE_Log_Msg实例。

例如main线程，ACE_LOG_MSG是获取单件模式实例指针的入口。

所有ACE日志宏logging macros使用ACE_LOG_MSG对ACE_Log_Msg单件模式的实例进行正确的方法调用。

很少有需求需要直接去实例化一个ACE_Log_Msg。

ACE自动的为每一个产生的线程创建一个实例，以保持每个线程有自己独立的日志输出。

We've also revealed a little more about how ACE's logging facility works. The ACE_Log_Msg class implements the log message formatting capabilities in ACE.

ACE automatically maintains a thread-specific singleton instance of the ACE_Log_Msg class for each spawned thread, as well as the main thread. ACE_LOG_MSG is a shortcut for obtaining the pointer to the thread's singleton instance.

All the ACE logging macros use ACE_LOG_MSG to make method calls on the correct ACE_Log_Msg instance.

There is seldom a reason to instantiate an ACE_Log_Msg object directly. ACE automatically creates a new instance for each thread spawned, keeping each thread's logging output separate.

Table 3.3. ACE Logging Macros

Macro

Function

Disabled by

ACE_ASSERT(test)

Much like the assert() library call. If the test fails, an assertion message including the file name and line number, along with the test itself, will be printed and the application aborted.

ACE_NDEBUG

ACE_HEX_DUMP((level, buffer, size [,text]))

Dumps the buffer as a string of hex digits. If provided, the optional text parameter will be printed prior to the hex string. The op_status^[a] is set to 0.

ACE_NLOGGING

ACE_RETURN(value)

No message is printed, the calling function returns with value; op_status is set to value.

ACE_NLOGGING

ACE_ERROR_RETURN((level, string, ...), value)

Logs the string at the requested level. The calling function then returns with value; op_status is set to value.

ACE_NLOGGING

ACE_ERROR((level, string, ...))

Sets the op_status to –1 and logs the string at the requested level.

ACE_NLOGGING

ACE_DEBUG((level, string, ...))

Sets the op_status to 0 and logs the string at the requested level.

ACE_NLOGGING

ACE_ERROR_INIT( value, flags )

Sets the op_status to value and the logger's option flags to flags. Valid flags values are defined in Table 3.5.

ACE_NLOGGING

ACE_ERROR_BREAK((level, string, ...))

Invokes ACE_ERROR() followed by a break. Use this to display an error message and exit a while or for loop, for instance.

ACE_NLOGGING

ACE_TRACE(string)

Displays the file name, line number, and string where ACE_TRACE appears. Displays "Leaving 'string'" when the ACE_TRACE-enclosing scope exits.

ACE_NTRACE

^[a] Many of the macros in this table refer to op_status. This internal variable is used to keep the logging framework aware of the program state, that is, the "operation status." By convention, a value of 0 indicates good. Anything else is considered an error or exception state. Also see Table 3.4.

我们可以通过ACE_Log_Msg::priority_mask()方法来设定日志等级以输出我们所期望的信息

We can use the ACE_Log_Msg::priority_mask() method to set the logging severity levels we desire output to be produced for: All the available logging levels are listed in Table 3.1. Each level is represented by a mask, so the levels can be combined. Let's look at the complete signature of the priority_mask() methods:

/// Get the current ACE_Log_Priority mask.u_long priority_mask (MASK_TYPE = THREAD);/// Set the ACE_Log_Priority mask, returns original mask.u_long priority_mask (u_long, MASK_TYPE = THREAD);

The first version is used to read the severity mask; the second changes it and returns the original mask so it can be restored later. The second argument must be one of two values, reflecting two different scopes of severity mask setting:

 

    1.  PROCESS标志所设定或提取的日志等级值是进程范围的，即所有此进程范围内的ACE_Log_Msg实例都受到此日志等级值的影响。

    2.  THREAD有点用词不当，其实它指的是方法调用的那个ACE_Log_Msg实例。

         你可以给已经由ACE自动创建的ACE_Log_Msg实例添加ACE_Log_Msg实例，但很少会干这种事。

         通常，我们简单的认为ACE_Log_Msg实例是线程相关的。

1. ACE_Log_Msg::PROCESS: Specifying PROCESS retrieves or sets the processwide mask affecting logging severity for all ACE_Log_Msg instances.

2. ACE_Log_Msg::THREAD: Each ACE_Log_Msg instance also has its own severity mask, and this value retrieves or sets it. THREAD is technically a misnomer, as it refers to the ACE_Log_Msg instance the method is invoked on, and you can create ACE_Log_Msg instances in addition to those that ACE creates for each thread. However, that is a relatively rare thing to do, so we usually simply refer to ACE_Log_Msg instances as thread specific.

在应用日志等级设定时，ACE_Log_Msg检查进程和线程两方面的设定值，无论那个（进程、线程）使得日志等级有效，日志都会被记录。

默认情况下，所有位（日志等级值)都设在进程范围，而非ACE_Log_Msg实例范围（THREAD），所以，所有的日志都会被记录（包括各个线程的日志）。

如果要单独设定线程的日志等级，必须把进程的日志等级标志设定为0，允许各个线程设定自己的日志等级。

When evaluating a log message's severity, ACE_Log_Msg examines both the processwide and per instance severity masks.

If either of them has the message's severity enabled, the message is logged.

By default, all bits are set at the process level and none at the instance level, so all message severities are logged.

To make each thread decide for itself which severity levels will be logged, set the processwide mask to 0 and allow each thread set its own per instance mask.

For example, the following code disables all logging severities at the process level and enables LM_DEBUG and LM_NOTICE severities in the current thread only:

ACE_LOG_MSG->priority_mask (0, ACE_Log_Msg::PROCESS);ACE_LOG_MSG->priority_mask (LM_DEBUG | LM_NOTICE, ACE_Log_Msg::THREAD);

A third mask maintained by ACE_Log_Msg is important when you start setting individual severity masks on ACE_Log_Msg instances.

The per instance default mask is used to initialize each ACE_Log_Msg instance's severity mask.

The per instance default mask is initially 0 (no severities are enabled).

Because each ACE_Log_Msg instance's severity mask is set from the default value when the instance is created, you can change the default for groups of threads before spawning them.

 

在线程产生部分加入日志策略信息，使得线程自己的日志设定减少，同时线程还是可以改变自己的日志策略

This puts the logging policy into the thread-spawning part of your application, alleviating the need for the threads to set their own level, although each thread can change its ACE_Log_Msg instance's mask at any time. Consider this example:

ACE_LOG_MSG->priority_mask (0, ACE_Log_Msg::PROCESS);ACE_Log_Msg::enable_debug_messages ();ACE_Thread_Manager::instance ()->spawn (service);ACE_Log_Msg::disable_debug_messages ();ACE_Thread_Manager::instance ()->spawn_n (3, worker);

We'll learn about thread management in Chapter 13.

 

For now, all you need to know is that ACE_Thread_Manager::spawn() spawns one thread and that ACE_Thread_Manager::spawn_n() spawns multiple threads. In the preceding example, the processwide severity mask is set to 0 (all disabled). This means that each ACE_Log_Msg instance's mask controls its enabled severities totally.

The thread executing the service() function will have the LM_DEBUG severity enabled, but the threads executing the worker() function will not.

The complete method signatures for changing the per instance default mask are:

static void disable_debug_messages    (ACE_Log_Priority priority = LM_DEBUG);static void enable_debug_messages    (ACE_Log_Priority priority = LM_DEBUG);

Our example used the default argument, LM_DEBUG, in both cases.

Even though the method names imply that LM_DEBUG is the only severity that can be changed, you can also supply any set of legal severity masks to either method. Unlike the priority_mask() method, which replaces the specified mask, the enable_debug_messages() and disable_debug_messages() methods add and subtract, respectively, the specified severity bits in both the calling thread's per instance mask and the per instance default severity mask.

Of course, you can use any message severity level at any time.

However, take care to specify a reasonable level for each of your messages; then at runtime, you can use the priority_mask() method to enable or disable messages you're interested in. This allows you to easily overinstrument your code and then enable only the things that are useful at any particular time.

ACE_Log_Msg has a rich set of methods for recording the current state of your application.

Table 3.4 summarizes the more commonly used functions. Most methods have both accessor and mutator signatures. For example, there are two op_status() methods:

int op_status(void);void op_status(int status));

Although the method calls are most often made indirectly via the ACE logging macros, they are also available for direct use.

                     

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_tracingstop_tracingtracing_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.

 

 

 

---