Page History

...

H16N161623L (klemen.zagar@ijs.si)
KGB, Jozef Stefan Institute
Radostina Georgieva (rgeorgie@eso.org)
ESO

Change Record

...

Telecom log specification represents a log entry by a structure whose IDL is:

 typedef unsigned long long RecordId; // RecordIds are unique within the
                                       // scope of one log.
  typedef TimeBase::TimeT TimeT; // Timestamp, as defined by the CORBA
                                 // TimeService.
  struct NVPair     // Name-Value pair
  {
    string name;
    any value;
  };
  typedef sequence<NVPair> NVList; // A set of name-value mappings
  struct LogRecord
  {
    RecordId id;      // Unique number assigned by the log
    TimeT time;       // Time when the event is logged (CORBA Time Service)
    NVList attr_list; // List of user defined name/value pairs. Not part of
                      // the event received by the log. Optional.
    any info;         // Event content
  };

...

A generic log entry representation in XML looks like this:

<LogEntryType TimeStamp="yyyy-MM-ddThh:mm:ss.fff"
File="filename" Line="lineno" 
Routine="routine"
Host="hostname" Process="procname" Thread="threadname" Context="context"
SourceObject="source"
StackId="stackid" StackLevel="stacklevel"
LogId="id" Uri="uri"
Priority="p">
<Data Name="name">value</Data>
log entry message
</LogEntryType>

...

• Host: The name of the computer on which the log entry is generated.
• Process: The name of the process from which the log entry is generated.
• Thread: The identification of the thread. For example, in C++ the identification is the name of the thread as supplied to InitThread (see 3.5.1.3. "Enabling the Logging Proxy").
• SourceObject: Identifies the logger that produced the current log entry.
• Context: Any additional context information supplied by the issuer of the log entry. For example, the name of the configuration database that is being used could be put here. This element is optional.
• StackId: Identification of a bundle of related log entries. All log entries in a bundle are caused by the same "root" log entry (e.g., the original cause of an error). This element is only present when logs are stacked.
• StackLevel: Specification of the number of the log entries in the bundle a given entry that have caused the log entry. The root log entry has a StackLevel of 0, the immediate log entries caused by the root log entry have a StackLevel of 1, etc. This element is only present when logs are stacked.

<Error TimeStamp="2000-08-23T13:18:27.432"
       File="FileOpener.cpp" Line="131" Routine="FileOpener::Open"
       Host="Hurricane" Process={_}"{_}Activator" Thread="EventLoop" SourceObject="GeneralLogger"
       \[...\]>
</Error>

...

Every log entry can contain arbitrary number of <Data> sub-elements. These sub-elements are useful for reporting values of individual variables to report the state of the object that submitted the log entry.
The Name attribute is mandatory as well as the content of the element.

<Error TimeStamp="2000-08-23T13:18:27.432"

...

File="FileOpener.cpp" Line="131" Routine="FileOpener::Open"

...

Host="Hurricane" Process="Activator" Thread="EventLoop"

...

LogID="err_File_Not_Found" Priority="8">

...

<Data Name="FullPath">/home/someuser/file.txt</Data>

...

</Error>

Anchor
_Toc424830074 _Toc424830074

Log Entry Message

...

The optional log entry message is a string of characters. The message can be either an XML formatted string, or a CDATA section. The only rule it must obey is not to contain a sub-string \]\]> or characters such as '<', '>' or '&', since it terminates a CDATA section.

Code Block
language xml
<Error TimeStamp="2000-08-23T13:18:27.432" File="FileOpener.cpp" Line="131" Routine="FileOpener::Open" Host="Hurricane" Process={_}"{_}Activator" Thread="EventLoop" LogID="err_File_Not_Found" Priority="8"> <Data Name="FullPath">/home/someuser/file.txt</Data> *<!\[CDATA\[Message\]\]>* </Error> \\ \\

Anchor
_Ref406572988 _Ref406572988

Anchor
_Toc424830075 _Toc424830075

ACS log levels

The ACS log levels are equivalently defined for all ACS programming languages, as defined in §3.4 (for C++), §3.5 (for java) and §3.6 (for python). This section introduces the different log levels defined and its utilization rules. The following is the list of logging levels from lowest to highest level.

• TRACE: See §3.3.2.1
• DELOUSE: See §3.3.2.2
• DEBUG: See §3.3.2.3
• INFO: See §3.3.2.4
• NOTICE: See §3.3.2.5
• WARNING: See §3.3.2.6
• ERROR: See §3.3.2.7
• CRITICAL: See §3.3.2.8
• ALERT: See §3.3.2.9
• EMERGENCY: See §3.3.2.10

ACS logs are filtered out (as described in Figure 1) according to a filtering logic. ACS defines a default system logging level than can be reconfigured at will. This information is detailed in §3.4.

• • INFO log level is used to publish information of interest during the normal operation of the system.This information is directed to operators, engineers or anybody else working with the system.
  • NOTICE logs are used to catch the attention of people (normally operators or software engineering) looking at the logging output.They denote important situations in the system, but not necessarily error/fault conditions.A NOTICE logging level should be selected with care, because many NOTICE messages weaken the attention of the reader.
  • WARNING logs are used to report to readers (normally operators or software engineering) conditions that are not errors but that could lead to errors/problems.A WARNING logging level should be selected with care, because many WARNING messages weaken the attention of the reader.

...

Anchor
_Ref406578621 _Ref406578621

Anchor
_Toc424830076 _Toc424830076

Trace Log Entry

Trace logs are generated whenever a function is entered. And are used to report calls to a function. They are used to build call trees during very critical debugging situations. The amount of TRACE logs can be huge and will very likely affect very substantially the performance of the system TRACE logging should be Trace logs are generated whenever a function is entered. And are used to report calls to a function. They are used to build call trees during very critical debugging situations. The amount of TRACE logs can be huge and will very likely affect very substantially the performance of the system TRACE logging should be switched on only in very particular situations and for a short time.
A trace log entry (<Trace>) corresponds to submitting a log entry of type LM_TRACE to the ACE logging system. The default priority of such an entry is 21.
With trace log entries, the Routine attributes are mandatory. There can also be several <Data> sub-elements, whose purpose is to dump the function's parameters.
The log entry message is a mandatory fully-qualified name of the function that was entered, for example MyNamespace::MyClass::MyFunction.

Anchor
_Ref406578732 _Ref406578732

Anchor
_Toc424830077 _Toc424830077

Delouse Log Entry

Delouse logs are generated only for low level debug purposes. Those logs are of interest for software engineers. Activation of Delouse logs should take place only while investigating low level problems and can put a substantial amount of load on the system.
A delouse log entry (<Delouse>) has no direct match according to according to the ACE logging system, and can be considered a convenient split of LM_DEBUG ACE logs. The default priority of such an entry is 2.
With delouse log entries, the File and Line attributes are mandatory. There can also be several <Data> sub-elements, whose purpose is to dump the object's state.
The log entry message is optional.

...

Local Control UnitACE loggingmacrosACS loggingmacrosACE Logging System:ACE_Log_Msg(thread-wide singleton)MACI logging callback object,implements ACE_Log_Msg_Callback(thread-safe process-wide singleton)Local cache(XML file)log(...)log(...)log(...)Trashcanlog(...)write_records(...)Filtering logic*Logs Publisher*

Figure 2: Architecture of the ACE Logging framework.
The figure gives an overview of ACE Logging framework. The ACE Logging System gets log entries that can be generic or specific (using ACS logging macros). It submits them to an object implementing ACE_Log_Msg_Callback that provides the filtering and the caching capabilities of the framework. The shadowed objects are out of the scope of this document.
The ACE's mechanism is flexible and high-performing and allows the implementation of objects that are specific to the ACS Logging requirements.
Important with respect to the formatting is that fact that the default logging macros of ACE (ACE_DEBUG, ACE_ERROR, etc.) already provide the logging system with the file name and the line number attributes. Additionally, the logging system outputs the runtime context along with all log entry types except for info log entry which has to be taken care of by requesting it explicitly through LoggingProxy's LM_RUNTIME_CONTEXT flag. Though these last attributes are optional according to the XML Schema, their appearance in the log records could be quite helpful.
The implementation of the ACE_Log_Msg_Callback abstract class' log method provides with the rest of the functionality:

//

...

/// The pre-defined macro for outputting log entries. It accepts three parameters

...

///

...

/// - flags: This parameter specifies the priority and additional log-entry

...

/// flags, such as whether to output the runtime context (thread & process)

...

/// or not.

...

/// - routine: The fully qualified name of the routine where the log-entry is

...

/// being generated. Can be 0, in which case the routine name is not output.

...

/// - log: Formatted as (log_type, format_string, . . .). Passed as a parameter

...

/// to ACE's logging macros.

...

///

...

/// Usage example:

...

///

...

/// ACS_LOG(LM_SOURCE_INFO | LM_PRIORITY(7),

...

///"maci::ContainerImpl::init",

...

///(LM_INFO, "A sample log entry %d", i));

...

///

...

#define ACS_LOG(flags, routine, log) \

...

{ \

...

	LoggingProxy::Flags(flags); \

...

	LoggingProxy::Routine(routine); \

...

	ACE_ERROR(log); \

...

}

...

 
///

...

///

...

/// Manipulate priority contained in the log entry's flags. The priority can

...

/// be from 0 ("use default") through 1 (lowest) to 31 (highest).

...

///

...

#define LM_PRIORITY(p) p

...

#define LM_GET_PRIORITY(f) (f & 0x0F)

...

 
/// If OR-ed with log entries' flags, the runtime context (host name, process name,

...

/// thread name, context, stack ID and stack level) will also be output.

...

///

...

#define LM_RUNTIME_CONTEXT

...

 0x00000200 
///

...

/// If OR-ed with log entries' flags, the source code information (file name,

...

/// line number) will also be output.

...

///

...

#define LM_SOURCE_INFO 0x00000100

...

 
/// The Log Message Callback

...

class logging_EXPORT LoggingProxy : public ACE_Log_Msg_Callback

...

{

...

 
	public:

...

	/// Receives all log entries submited

...

	/// within the process. Thread safe!

...

	void log(ACE_Log_Record &log_record);

...

 
	/// Specifies the log entry type, if the output representation is different

...

	/// than the one implied with ACE's log entry type. Applies for the next

...

	/// log entry only. Pointer to the string must be stored in the thread-specific

...

	/// storage!

...

	static void LogEntryType(const ACE_TCHAR *szType);

...

 
	/// Specifies the name of the routine (function) where the following log entry

...

	/// will be generated. Pointer to the string must be stored in the

...

	/// thread-specific storage!

...

	static void Routine(const ACE_TCHAR *szRoutine);

...

 
	/// Set the flags that will apply to the log entry that will be submitted next.

...

	/// Flags must be stored in thread-specific storage! Flags are obtained by OR-ing

...

	/// appropriate LM_* values above. If priority is 0, the default priority

...

	/// associated with ACE's log entry type (LM_INFO, LM_ERROR, ...) is implied.

...

	static void Flags(unsigned int uiFlags);

...

 
	/// Specifies the name of the thread. Pointer to the name must be stored in

...

	/// the thread-specific storage!

...

	static void ThreadName(const ACE_TCHAR *szName);

...

 
	/// Returns the name of the thread.

...

	static const ACE_TCHAR *ThreadName();

...

 
	/// Specifies the name of the process. Must be stored in a process-wide global

...

	/// variable!

...

	static void ProcessName(const ACE_TCHAR *szName);

...

 
	/// Returns the name of the process.

...

	static const ACE_TCHAR *ProcessName();

...

 
	/// Reset the list of custom attributes. The attributes are applicable to the

...

	/// next log entry only.

...

	static void ResetAttributes();

...

 
	/// Add an attribute to the list of next log entries' attributes.

...

	static void AddAttribute(const ACE_TCHAR *szName, const ACE_TCHAR *szValue);

...

 
	/// Specify the LogId attribute of the log entry that follows. Can be 0 (default)

...

	/// in which case no LogId attribute is output.

...

	static void LogId(const ACE_TCHAR *szName);

...

 
	/// Specify the URI attribute of the log entry that follows. Can be 0 (default)

...

	/// in which case no URI attribute is output.

...

	static void URI(const ACE_TCHAR *szName);

...

 
	/// Specifies the stack ID of the current logical thread. Pointer to the name

...

	/// must be stored in the thread-specific storage! Can be set to NULL if

...

	/// the logical thread ID is unknown.

...

	static void StackId(const ACE_TCHAR *szId);

...

 
	/// Returns the the logical thread ID. Must have been set previously using

...

	/// StackId.

...

	static const ACE_TCHAR *StackId();

...

 
	/// Set the stack level in the current logical thread. The value must be stored

...

	/// in the thread-specific storage!

...

	static void StackLevel(int nLevel);

...

 
	/// Retrieve the stack level in the current logical thread.

...

	static int StackLevel();

...

 
	/// Set the context in which the code is operating. Pointer to the name must

...

	/// be stored in the thread-specific storage!

...

	static void Context(const ACE_TCHAR *szName);

...

 
	/// Retrieve the context in which the code is operating.

...

	static const ACE_TCHAR *Context();

...

 
	/// Supply data with the log entry that follows.

...

	/// The maximum length for AddData value is ADD_DATA_VALUE_MAX (255+\0). If it is too long /// it will be truncated.

...

	static void AddData(const ACE_TCHAR *szName, const ACE_TCHAR *szFormat, ...);

...

...

...

}; 

An instance of the LoggingProxy class is created in Container's Init and destroyed in Container's Done method. It is configured from the Container's configuration record This implies that logging proxy can be configured on a per-activator (i.e., per Local Control Unit) basis. using the properties listed below.

...

Due to design of ACE, the callback for logging must be registered as well as unregistered with ACE_Log_Msg per-thread singleton for every thread individually. This is done automatically by the configuration methods of the Container initThread and doneThread that have the following signatures:

class class maci_EXPORT ContainerImpl : : // . . .

...

{

...

 
	// . . .

...

	static void initThread(const char * threadName = 0);

...

	void doneThread();

...

}; 

The two methods are only a part of the Container servant and are not exposed through its CORBA interface.
If a nonempty string is passed as a parameter to initThread, a LM_INFO log entry is output associating the thread-ID of the current thread with its name.

...

The following code submits the source code information:

ACS_LOG(LM_SOURCE_INFO, // flags

...

		"main", // routine name

...

		(LM_INFO, // informational log entry

...

		"")); // no additional message text

The resulting log entry in XML would look like this (there would be no white-spaces in the actual output; they are shown below for purposes of legibility only).

<Info TimeStamp="2000-09-10T21:34:32.132"

...

	File="test.cpp" Line="131"

...

	Routine="main"

...

	Priority='4'></Info>

Anchor
_Toc424830098 _Toc424830098

Submitting the Runtime Context

The configuration methods of the Container take care of setting up the runtime context information, e.g. the host name as well as the process and the thread information:

ACE_Log_Msg::instance()->local_host("host"); // set the host name

...

LoggingProxy::ProcessName("proc"); // called at process startup

...

LoggingProxy::ThreadName("thr"); // called at thread startup

...

 
ACS_LOG(LM_RUNTIME_CONTEXT,

...

		0,

...

		(LM_ERROR,

...

		"hello")); 

The resulting log entry in XML would look like this:

<Error TimeStamp="2000-09-10T21:34:31.435"

...

		Host="host" Thread="thr" Process="proc"

...

		Priority='7'/>

...

	Any number 123

...

</Error>

Anchor
_Toc424830099 _Toc424830099

Submitting a Variable's Value

The following code submits a value of a variable:

LoggingProxy::AddData("dMyDouble", "%f", dMyDouble);

...

ACS_LOG(0, "main", (LM_TRACE, ""));

The length of a value should not exceed 255 characters otherwise it is truncated.

...

The following code overrides the default priority of a log entry:

ACS_LOG(LM_PRIORITY(12), 0,

...

(LM_TRACE, // Could

...

 be anything...
"Message")) // Could be

...

 anything...

Anchor
_Toc424830101 _Toc424830101

Submitting an Arbitrary Message

...

To

...

submit

...

an

...

arbitrary

...

message,

...

care

...

must

...

be

...

taken

...

not

...

to

...

break

...

XML

...

formatting

...

rules

...

(for

...

example,

...

<

...

and

...

>

...

should

...

be

...

used

...

with

...

care).

...

If

...

the

...

message

...

contents

...

are

...

not

...

known

...

in

...

advance

...

and

...

a

...

possibility

...

exists

...

that

...

they

...

would

...

break

...

XML

...

formatting

...

rules,

...

code

...

like

...

this

...

should

...

be

...

used:

_// This macro is predefined by ACS_
#define LM_CDATA(t) "<!\[CDATA\[" t "\]\]>"
ACE_ERROR((LM_WARNING,
           LM_CDATA("Some < text %s >"),
           szAString)) 
 

The

...

unpredictable

...

text

...

is

...

placed

...

in

...

an

...

XML

...

CDATA

...

section.

...

Anchor
_Toc424830102 _Toc424830102

Specifying an Audience, Array and/or Antenna for a log

...