...

Keywords: KGB-SPE-01/04|Approved by:|Signature:|

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

...

Scope

This document describes the architecture and design for logging and archiving data generated by ACS applications. This architecture is in accordance with the Logging and Archiving section of the ALMA Common Software Architecture document [RD05].

Introduction

Every properly built system needs to be able to log the

...

Scope

This document describes the architecture and design for logging and archiving data generated by ACS applications. This architecture is in accordance with the Logging and Archiving section of the ALMA Common Software Architecture document [RD05].

...

Every properly built system needs to be able to log the events that occur in it (logging) so that the user of the system can gain an accurate understanding of the system's state, especially in case of a failure. For example, every component should log when it is created and destroyed. For systems with more stringent security requirements it might be required that every access to the system is logged, along with the user that performed it (auditing). Also, the system should log all unusual and error conditions.
Logging is very useful during debugging. Every entering or leaving of an important function could be logged to determine whether a function has been called at all and with what parameters. This information is also useful for profiling because more frequently used functions can be easily identified and more effort can be invested in their optimization.
Logging subsystem can be built very easily in a single computer scenario: a simple fprintf does the job. However, in a distributed system, means must be provided to centralize all logging activity in a single place, and still not overload the network too much. Also, the temporary unavailability of the network connectivity should not cause the logging subsystem to malfunction.
Another very important issue is the consistence of log entries. If all log entries stick to the same formatting rules (for example, the name of the log entry issuer, followed by a colon, followed by an error code, …), then automated log parsers can be built to intelligently filter or transform the log output, assisting the administrator to more efficiently manage the huge amount of data contained in the log.
A control system generates a huge amount of data, such as:

...

• A specialized protocol for transferring archive data.
• An existing mechanism for logging (i.e., archive is nothing else but a huge log file).
• An existing mechanism for monitoring.

...

...

Reference Documents

The following documents have been referenced in this document.
*\[RD01\] ALMA ACS Basic* *Control* *Interface* *Specification{*}, M. Plesko, G. Tkacik, G. Chiozzi - ([http://www.eso.org/~gchiozzi/<ac:structured-macro ac:name="anchor" ac:schema-version="1" ac:macro-id="a99e0bb0-90fe-4e53-90b7-2a42cc1f3cd9"><ac:parameter ac:name="">_Hlt408496900</ac:parameter></ac:structured-macro>AlmaAcs/Releases/ACS_2_0_Docs/ACS_Basic_Control_Interface_Specification.pdf|http://www.eso.org/~gchiozzi/AlmaAcs/Releases/ACS_2_0_Docs/ACS_Basic_Control_Interface_Specification.pdf])
*\[RD02\] Adaptive Communications Environment (ACE) -* ([http://www.cs.wustl.<ac:structured-macro ac:name="anchor" ac:schema-version="1" ac:macro-id="b396a73a-7ba6-45d1-960d-fcffefc7e31f"><ac:parameter ac:name="">_Hlt408497061</ac:parameter></ac:structured-macro>edu/~schmidt/ACE-overview.html|http://www.cs.wustl.edu/~schmidt/ACE-overview.html])
*\[RD03\] OMG: CORBA Telecom Log Service Specification -{*}([ftp://ftp.omg.org/pub/docs/form<ac:structured-macro ac:name="anchor" ac:schema-version="1" ac:macro-id="5cd1f43a-ec5d-46fd-81fd-f0dde8920263"><ac:parameter ac:name="">_Hlt408497072</ac:parameter></ac:structured-macro>al/00-01-04.pdf|ftp://ftp.omg.org/pub/docs/formal/00-01-04.pdf])
*\[RD04\] ALMA Common Software Technical Requirements,* ALMA-TRE-ESO-XXXXX-XXXX, G.Raffi, B.Glendenning, Issue 1.0, 2000-06-05
*\[RD05\] ALMA Common Software Architecture,* G.Chiozzi, B.Gustafsson, B.Jeram *-* ([http://almaedm.tuc.nrao.edu<ac:structured-macro ac:name="anchor" ac:schema-version="1" ac:macro-id="3064770b-be38-46ce-8f41-fd8fc29b9d69"><ac:parameter ac:name="">_Hlt408497327</ac:parameter></ac:structured-macro>/forums/alma/dispatch.cgi/Architecture/docProfile/100017/d20021117183329/No/ALMASoftwareArchitecture.pdf|http://almaedm.tuc.nrao.edu/forums/alma/dispatch.cgi/Architecture/docProfile/100017/d20021117183329/No/ALMASoftwareArchitecture.pdf])
\\
*\[RD06\] OMG: Notification Service Specification -{*}([ftp://ftp.omg.org/pub/docs/formal/00-06-20.pdf|ftp://ftp.omg.org/pub/docs/formal/00-06-20.pdf])
*\[RD07\] Java Logging Overview -{*}([http://java.sun.com/j2se/1.4.1/docs/guide/util/logging/overview.html|http://java.sun.com/j2se/1.4.1/docs/guide/util/logging/overview.html])
*\[RD08\] ACS Online Documentation for schema files -{*}([To De Updated.html|http://java.sun.com/j2se/1.4.1/docs/guide/util/logging/overview.html])
\\
 \\
\\

...

...

Requirements

...

Logging

The logging subsystem must allow for the following:

1. It must provide an easy-to-use programming interface to the application developer.
2. Every log entry has an associated priority and type (error, fatal error, information, …).
3. Every log entry is equipped with a timestamp accurate to a deci-microsecond (100's of ns).
4. The logging subsystem must be centralized, so that all log entries generated in the systems sooner or later find their way to a central log. The order of the log entries is defined by their timestamp.
5. The subsystem should allow for filtering, so that log entries with insufficient priority do not get logged, whereas those with high priority get routed to the central log immediately.
6. The log entries are consistent, so that they can be interpreted by various automated tools for filtering and transforming.
7. Log entries can be buffered locally on the machine where they were generated, and transmitted over the network to the central log on demand or when the local buffer reaches a predetermined size.
8. The logging subsystem shall be capable of generating basics statistics of the logs generated (). This capability must be configurable (either to be active or inactive)

...

Archiving

The archiving subsystem must allow for the following:

1. Every property in the control system is eligible for archiving.
2. Archiving can be enabled or disabled on per-parameter basis.
3. Archiving can be configured on per-parameter basis.
4. Individual parameter can be archived when it changes or with a certain fixed frequency.
5. There is a central point where the archive of all parameters is kept.
6. Individual parameter's archived data can be stored on a local machine, or immediately forwarded to the central archive.
7. Each parameter can be uniquely identified through the unique distributed object name and the parameter name.
8. The archiving subsystem supplies a mechanism for retrieving the historical value of any parameter at any time, provided that the value was archived prior to that time.

...

...

Logging Architecture

Logging subsystem leverages three systems that have been either already built, or at least well designed and specified. These are:

1. CORBA Telecom Log Service for centralizing all log entries generated throughout the system.
2. CORBA Notification Service for distributing log entries to interested clients (consumers of logs) when the entries are submitted to the centralized logger.
3. The mechanism for generating, formatting, filtering and caching log entries.

...

1. • C++

...

1. • suppliers

...

1. • of

...

1. • logs

...

1. • use

...

1. • the

...

1. • ACE

...

1. • Logging framework with its C++ API RD02
   • Java suppliers of logs use the standard Java Logging API RD07

...

1. • Other suppliers of logs, e.g. a Python application, can use the stand-alone ACS Log Server which provides the generic functionality.

The logging subsystem is a very basic one and it should be considered as a part of the infrastructure. Image Removed Centralized Logging HostHTTP ServerRelational DatabaseEventChannelsClientpush*Centralized Logging*XMLParserDatabaseLogger ClientpushpushFiltering logicWeb ClientXSLTHTTP request/replyClientquerySELECT UPDATESELECTOut of scope of this documentLogs Publisher*write_records*Implements Log interface
Anchor_Ref406581088_Ref406581088

Image AddedFigure 1: Architecture of the logging system.
The figure shows an overview of the ACS Logging System, based on the CORBA Telecom Log Service and The CORBA Notification Service. The CORBA Telecom Log Service has a Centralized Log object that is responsible for getting the logs from the log suppliers, validating them and submitting them to the Event Channels. The Event Channels push the logs to the subscribed log consumers. The shadowed objects are out of the scope of this document.

...

...

CORBA Telecom Log Service

The Telecom log service specification defines a set of IDL interfaces that are suitable for implementation of any kind of a log service [RD03]. The implementation using CORBA is done in the Centralized Log. All interfaces inherit from the Log interface which defines the following operations for submitting and querying log entries

...

:

interface Log
{ 
  // . . .   
  // Write records to the log storage
  void write_records(in Anys records) raises(LogFull, LogLocked);

  // Returns all records in the log that match the given
  // constraint <c>. 
  RecordList query(in string grammar,
                   in Constraint c,
                   out Iterator i)
    raises(InvalidGrammar, InvalidConstraint);

 // Retrieve <how_many> records from time <from_time> using
  // iterator <i>. Negative <how_many> indicates backwards
  // retrieval

  RecordList retrieve(in TimeT from_time,
                      in long how_many,
                      out Iterator i);
};

...

 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
  };

The listings presented here are excerpts from file $TAO_ROOT/orbsvcs/orbsvcs/DsLogAdmin.idl, courtesy of Matthew Brown.:

For our purposes, the info element of the LogRecord structure consists of an XML string containing all the information about the record, such as the timestamp (time element is not suitable for our purposes, since it will contain the time when the log entry was logged to the central log, and not when the log entry was submitted; due to caching these two times could be significantly different). The details about the XML schema of the info element are described in 3.3 "Syntax of a Log Entry".

...

...

Centralized Log

The Centralized Log that implements the CORBA Telecom Log Service is the facility that receives log entries from the entire system and dispatches them to interested clients. Particularly, it implements the Log interface of the Telecom Log Service. An example of an implementation of such a service is already bundled with TAO's implementation of the Telecom Log Service and can be found under $TAO_ROOT/orbsvcs/Logging_Service.

The Centralized Log uses CORBA for getting the routed logs from the suppliers of logs (publishers) -applications that use the formatting, buffering and pushing capabilities of ACE API, Java Logging API, the ACS Log Service, etc. as they send log records to it.

Thus, the Centralized Logging Service receives an XML string as the "any" parameters in a call to write_records from a supplier. The XML string is formatted according to the specifications described in 3.3 "Syntax of a Log Entry". Since the XML string already contains the timestamp information, that information should take precedence over the actual current timestamp of the receipt of the log entry.

The parsed log entry is then forwarded to appropriate event channel of the CORBA Notification Service which distributes the log entries further. The choice of the event channel depends on the log entry's type and content. For example, log entries related to debugging could be forwarded to a different event channel than those related to archiving. The consumers of logs (clients) can access log entries by subscribing to the event channel of interest.
To store log records, the Centralized Logging Service needs a Database Logger client that has to make the log entries the Centralized Logging Service receives persistent. If such a client exists, other subscribed clients have additional options to access the database:

• Direct access to the SQL database (SELECT).
• Via Database Logging client's query and retrieve methods.
• Via HTTP (the client is a web browser). HTTP server accesses the relational database, transforms the requested entries to XML, transmits them to the browser, which then uses XSLT to transform incoming XML to HTML.

The Centralized Logging Service reconnects to the event channel by default when it detects that the distribution of log entries cannot be performed because of some specific errors. This feature can be disabled by passing the option --no-autoreconnect to the Centralized Logging Service when it's launched.

...

Syntax of a Log Entry

Every log entry is represented as an XML document node. The schema of the XML is described in this chapter and the complete schema is provided in appendix A.

...

A Generic Log Entry

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>

...

Log Entry Type

The log entries exist in different types to distinguish between the importance of information it provides. These types are described in the following sections and follow the convention specified by $(ACE_ROOT)/ace/Log_Priority.h. Logging level Delouse has been introduced to ACS.
Note that LogEntryType is not actually an XML tag, but merely a placeholder for the actual XML tag name such as Debug described in the following sections.
More detail on the actual Log Entry Types is provided in §3.3 Anchor_Hlt406572992_Hlt406572992 Anchor_Hlt406572993_Hlt406572993.2

...

TimeStamp

The timestamp is a mandatory attribute of every log entry. It specifies the exact time when the log entry was submitted. The time is encoded in ISO 8601 format with a precision to one millisecond. The time is specified in TAI.

...

Source Code Information

The element representing a log entry is equipped with these attributes that convey the location in the source code from which the log entry was generated:

...

These three attributes are optional since they cannot be provided for log entries in each language due to grammar or implementation restrictions. For example, in Java getting the source code line of the log record is very inefficient. Therefore, a log entry would only supply the file name and the method where the log entry originates from.

...

...

Runtime Context Information

The log element has six seven attributes that give more information regarding the runtime context in which the log entry is submitted:

...

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

...

Log Entry Identification

Every log entry can be supplied with an optional LogId attribute which uniquely identifies the log entry's class (e.g., "file not found", "out of memory", "container starting", etc.).
LogId is particularly useful when used with error messages where it can be used as a key in the help system to look up detailed help/troubleshooting information. Variable sub-elements are also useful in such cases to provide more details about the source of the log entry. For example, if a file could not be found, the following XML could be generated:

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

...

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

...

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

...

       LogID="err_File_Not_Found" Priority="8"

...

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

...

</Error>

In addition to LogId, an optional Uri attribute is provided, which uniquely identifies the log entry's class. (e.g., log://www.eso.org/acs/errors/OutOfMemory).

...

Priority

The log type implies default priority of a log message. However, if the priority is explicitly specified, then the default is overridden.

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

...

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

...

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

...

       LogID="err_File_Not_Found" Priority="8">

...

</Error> 

Priority element is optional and is measured as an integer number ranging from 1 to 15, where 1 is lowest and 15 highest priority. The value of 0 indicates the default priority.

...

...

Data Sub-element

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>

...

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

...

...

...

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.

...

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.

...

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

...

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.

...

state.
The log entry message is optional.

...

Debug Log Entry

Debug logs are used only while debugging the system. Therefore such logs are normally only interesting for software engineers. Analysis of DEBUG logs should take place only while investigating problems and can put a substantial amount of load on the system.
A debug log entry (<Debug>) corresponds to submitting a log entry of type LM_DEBUG according to the ACE logging system. The default priority of such an entry is 3. Debug logs are useful for dumping object state.
With debug 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.

...

...

Info Log Entry

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. They can also be employed for transmitting useful payload (such as archiving data).
An info log entry (<Info>) corresponds to submitting a log entry of type LM_INFO to the ACE logging system. The default priority of such an entry is 4.

...

Notice Log Entry

Notice logs are useful for logging normal, but significant activity of the system, for example startup or shutdown of individual services. They 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.
A notice log entry (<Notice>) corresponds to submitting a log entry of type LM_NOTICE to the ACE logging system. The default priority of such an entry is 5.

...

...

Warning Log Entry

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.
A warning log entry (<Warning>) corresponds to submitting a log entry of type LM_WARNING to the ACE logging system. The default priority of such an entry is 6.

...

Error Log Entry

Error logs denote error conditions.
They are normally generated by the Error System and not explicitly use in applications by calling the logging API.
An error log entry (<Error>) corresponds to submitting a log entry of type LM_ERROR to the ACE logging system. The default priority of such an entry is 8.

...

...

Critical Log Entry

Critical logs denote an Alarm condition that shall be reported to operators.
They are normally generated by the Alarm System and not explicitly used in applications by calling the logging API.
A critical log entry (<Critical>) corresponds to submitting a log entry of type LM_CRITICAL to the ACE logging system. The default priority of such an entry is 9.

...

...

Alert Log Entry

Alert logs denote an Alarm condition that shall be reported to operators. This denotes a problem more important than Critical.
They are normally generated by the Alarm System and not explicitly use in applications by calling the logging API.
An alert log entry (<Alert>) corresponds to submitting a log entry of type LM_ALERT to the ACE logging system. The default priority of such an entry is 10. Alerts are used for reporting errors that must be solved immediately.

...

Emergency Log Entry

Emergency logs denote an Alarm condition of the highest priority.
They are normally generated by the Alarm System and not explicitly use in applications by calling the logging API.
An emergency log entry (<Emergency>) corresponds to submitting a log entry of type LM_EMERGENCY to the ACE logging system. The default priority of such an entry is 11. Alerts are used for reporting errors that must be solved immediately.

...

...

ACS log audiences

In order to allow log filtering flexibility ACS logs can be targeted to a particular audience. The following audiences are currently defined within the system:

...

But ACS provides specific wrappers only for the most popular audiences, which are: OPERATOR, DEVELOPER, and SCILOG.

...

ACS system logging level

ACS logging filtering logic determines if a particular log shall be logged or not depending on the system logging level. All logs with log level equal and above the system logging level will pass the filtering logic and be actually logged; all logs with log level below this value will not be logged out.
ACS defines as default system logging level DEBUG log level. This value can be configured in different ways by means of environment variables:

...

The CBD is capable of setting different logging levels per process or per logger

...

logger

ACS logging statistics

ACS logging service incorporates an embedded logging statistics module allowing each logger calculating and reporting logs statistics. The statistics logger module is designed as a configurable module that can be activated or deactivated at will. By default the logger statistics module is disabled. Statistics are reported using the same logger channel whose statistics belong to, encapsulated within a clearly identifiable frame.
The following statistics are calculated for a time period and reported when the module is active:
Total number of messages successfully sent during last statistics calculation period
Number of messages per second successfully sent during last calculation period
Increase (decrease) of successfully sent messages with regards to previous calculation period

• Total number of log errors found during last statistics calculation period
• Number of log errors per second log errors found during last calculation period
• Increase (decrease) of log errors found with regards to previous calculation period

...

...

Design notes

The logging statistics module is added over all already functionalities of the logger system, for all available programming languages. The design of the logging statistics module has been driven by the following aspects:
Statistics are provided per logger instance, enabling therefore low level analysis. Clear identification of the logger to whom the statistics belong to shall be clearly identifiable
Statistics generated for a logger are reported thought the same logger channel

...

Minimization of service performance impact. While statistics module is disables no calculations are performed. Trivial mathematical operations are performed when the service is enabled
Language independency. The same behavior shall be obtained independently of the programming language
Anchor_Toc408496850_Toc408496850 Anchor_Toc421029038_Toc421029038 Anchor_Toc424830090_Toc424830090

...

ACS C++ Logging API

...

ACE Logging

The ACS C++ Logging API for generating, formatting and filtering log entries is based on the ACE Logging API and is provided by a collection of operating system wrappers and common design pattern implementations with the following functionality:

1. A data structure that can hold a log entry (the ACE_Log_Record, defined in $ACE_ROOT/ace/Log_Record.h). The structure also holds priority, type and the timestamp of the log entry, fulfilling requirements 2.1.2 (priority and type) and 2.1.3 (timestamp). Furthermore, ACE logs filename and line number of the source code where the log entry originates from. It should be noted that priority and type in ACE can not be set separately, because type implies priority, and vice-versa.
2. A mechanism for submitting log entries. The mechanism is modeled by the ACE_Log_Msg class ($ACE_ROOT/ace/Log_Msg.h). There is one instance of this class per thread.
3. ACE's logging mechanism is extensible, allowing for custom callbacks to be registered with an ACE_Log_Msg object. These callbacks (implementations of a ACE_Log_Msg_Callback abstract class) receive all entries submitted to the logging mechanism and can process them any way they want. (Please note that the callback must be registered with the ACE_Log_Msg at the beginning of each thread's lifetime.)
4. ACE defines several macros which the application programmer can use to submit log entries, such as ACE_ERROR and ACE_DEBUG (defined in $ACE_ROOT/ace/Log_Msg.h). This fulfills the requirement 2.1.1 (programming interface).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*
   

...

Image Added
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.

...

Logging Proxy's Configuration Data

The logging system caches logs before transmitting them to the centralized logging service. The logging is done on a per-process basis. The following parameters control logging with respect to how and what messages are published, e.g. whether they are printed or logged at all, whether they are cached locally or transferred to the logging service immediately, etc.
ACS_LOG_STOUT (unsigned 32-bit integer): The environmental variable corresponding to the least priority of a log message that is to be sent to stout. By default, only log messages with priority equal or higher than LM_INFO (3) are sent to stout. If ACS_LOG_STOUT>0, all log messages with priority >= ACS_LOG_STOUT are also sent to stdout.
cacheSize (unsigned 32-bit integer): The number of log entries to be cached before logging. When this number is reached, all log entries are transferred to the centralized logging. If network connection is not available, the local cache continues to grow, and every submitting of a log entry will attempt to flush the cache to the centralized logging.
minCachePriority (unsigned 32-bit integer): Minimum log priority. Log entries the priority of which is below (smaller than) the one specified with this property are ignored (neither cached nor submitted to the Centralized Logging Service). By default, the value is set to zero so that all messages are logged. In release version of the system, this is set to LM_INFO (3), ignoring LM_TRACE and LM_DEBUG log entries. Debug version of the system sets this to LM_DEBUG (2). During development, it is set to LM_TRACE (1).
maxCachePriority (unsigned 32-bit integer): Maximum log cache priority. Log entries whose priority exceeds (is greater than) the one specified with this property are directly transmitted to the Centralized Logging Service, bypassing the local cache. If this is set to MinCachePriority – 1, the local cache feature is disabled.
centralizedLogger (string): An IOR string representing the centralized logging object. The IOR is expected to denote a persistent object which implements the Telecom Log Service's Log interface, in particular the write_records method.

...

log Method Semantics

The log method receives an ACE_Log_Record object, which it first transforms into an XML string, obeying the XML schema of the 2.1.6 - "Consistence of Log Entries".
Depending on the log entry's type (and thus priority) the string is either written to a local cache (a regular XML file opened for appending and flushed for every submitted log entry, or an in-memory XML string), or transmitted to the Centralized Logging Service. If the local cache contains CacheSize or more elements, an attempt is made to transmit the entire local cache to the Centralized Logging Service.
The reference to the Centralized Logging Service is given by the CentralizedLogger configuration property. To submit an entry to the Centralized Logging Service, its write_records method is employed, passing the XML string as the expected any parameter.

...

Enabling the Logging Proxy

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:

...

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.

...

...

Submitting Log Entries

As already mentioned, ACE's logging infrastructure is used for submitting log entries. It can be used at these levels:

• The macro ACS_LOG, or one of specialized macros ACS_TRACE, ACS_DEBUG, ACS_DEBUG_PARAM, ACS_SHORT_LOG, and ACS_LOG_TIME, defined in the ACS include file logging.h.
• Using ACE_Log_Msg and LoggingProxy directly.

...

Submitting the Source Code Information

The following code submits the source code information:

...

<Info TimeStamp="2000-09-10T21:34:32.132"
	File="test.cpp" Line="131"
	Routine="main"
	Priority='4'></Info>

...

...

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:

...

<Error TimeStamp="2000-09-10T21:34:31.435"
		Host="host" Thread="thr" Process="proc"
		Priority='7'/>
	Any number 123
</Error>

...

Submitting a Variable's Value

The following code submits a value of a variable:

...

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

...

...

Overriding the Default Priority

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

...

...

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:

...

The unpredictable text is placed in an XML CDATA section.

...

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

...

API

• The possible audiences are defined in acscommon.idl, to use them, just access the appropriate one, for example:

string a = log_audience::OPERATOR;

• New macros have been defined in loggingMACROS.h::

#define LOG_FULL(logPriority, logRoutine, logMessage, logAudience, logArray, logAntenna)

...

#define LOG_With_ANTENNA_CONTEXT(logPriority, logRoutine, logMessage, logArray, logAntenna)

...

#define LOG_TO_AUDIENCE(logPriority, logRoutine, logMessage, logAudience)

...

Examples

...

...

...

#include <stdlib.h>
#include <stdio.h>
#include <string.h>

...

...

#include <maciSimpleClient.h>

...

int main(int argc, char *argv

...

[

...

])

...

{
        maci::SimpleClient client;

...

        if (client.init(argc,argv) == 0)

...

{
                return -1;
        

...

}
        else

...

{
                // Log into the manager before doing anything
                client.login();
        

...

}

...

        ACS_SHORT_LOG((LM_WARNING,"ACS_SHORT_LOG"));
        LOG_FULL(LM_WARNING,"main","LOG_FULL",log_audience::OPERATOR,"array01","Antenna01");
        LOG_WITH_ANTENNA_CONTEXT(LM_WARNING,"main","LOG_WITH_ANTENNA_CONTEXT","array01","Antenna01");
        LOG_TO_AUDIENCE(LM_WARNING,"main","LOG_TO_AUDIENCE",log_audience::OPERATOR);
        client.logout();

...

        return 0;

...

...

}

...

...

Logging statistics configuration

...

API

Default values are defined within the logging statistics module, notably:

• Default statistics period: Defined as 600 seconds (i.e. 10 minutes). That means that by default the module will provide statistics every 10 minutes
• Default statistics granularity: Defined as 1 second. That means that statics are calculated as messages per second
• Default statistics state: Defined as true is used to configure disableStatistics attribute. That means that by default the statistics module is disabled

const uint32_t loggingStatistics::INITIAL_NUMBER_MESSAGES = 0;

...

const uint32_t loggingStatistics::INITIAL_NUMBER_ERRORS = 0;

...

const uint32_t loggingStatistics::DEFAULT_STATISTICS_PERIOD = 60 * 10; // 10 minutes

...

const uint32_t loggingStatistics::DEFAULT_STATISTICS_GRANULARITY = 1; // 1 second

...

const bool loggingStatistics::DEFAULT_STATISTICS_STATE = true; // disabled 

To use the logging statistics module for a certain logger it is only required to configure it to enable statistics: configureStatistics() method require the following parameters (ordered):

• elementName: Defines the name of the module the logger belong to. The statistics report will be identifies as elementName.loggerName
• state: Configuration of the disableStatistics attribute. Allows to enable / disable the logging statistics module.
  • True: Statistics disabled
  • False: Statistics enabled
• period: Configuration of the statisticsCalculationPeriod attribute. Allows setting the time between statistics calculation and reporting. Introduced in seconds
• granularity: Configuration of the statisticsGranularity attribute. Allows setting the granularity used to calculate the statistics (i.e. if the result shall be provided in messages per second, messages per minute…). Introduced in seconds

/**

...

    This method allows the statistic module to be configured
    @param elementName String defining the name of the module the statistics belong to
    @param state Configuaration of disableStatistics attribute (to enable / diable statistics module)
    @param period Configuration of statisticsCalculationPeriod
    @param granularity Configuration of statisticsGranularity
    @return void
    */
    virtual void configureStatistics(const std::string elementName,
    const bool state,
    const uint32_t period,
    const uint32_t granularity); 

Code examples

#include "loggingACSLogger.h"
#include "loggingHandler.h"
#include "loggingLogTrace.h"
#include "logging.h"

...

int main(int argc, char *argv

...

[

...

])

...

{
    ACS_CHECK_LOGGER;

...

    // Create logger (by default statistics are inactive)
    Logging::Logger::LoggerSmartPtr firstLoggerSmartPtr = getLogger();
    firstLoggerSmartPtr->setName("FirstLogger");

...

    // Activate statistics for the logger
    firstLoggerSmartPtr->stats.configureStatistics("testLoggerStats",false, 600, 1);

...

    // Direct log example (will be counted)
    logger->log(Logging::Logger::LM_TRACE, "Testing LM_TRACE message: Messages indicating function-calling sequence");

...

    // Macro log example (will be counted)
    ACS_LOG( LM_FULL_INFO, __PRETTY_FUNCTION__, (LM_DEBUG, "Test of LM_DEBUG log"));

...

    return 0;

...

}

...

...

Log examples

Wiki MarkupThe statistics report is a log with additional data containing the name of the logger and the identificator of the statistics module (if configured) as well as the statistics calculated and described on §3.5 \\

2015-07-15T13:59:04.890 

...

[GlobalLogger - virtual Logging::Logger::~Logger()

...

] LOGGING STATISTICS FOR: testLoggerStats.FirstLogger ErrorMessageIncrement="nan" MessageIncrement="-26.6667" LastPeriodNumberOfErrorMessages="0" LastPeriodNumberOfMessages="22" LastPeriodDuration="0.123412" ErrorMessageStatistics="0" MessageStatistics="178.265" StatisticsGranularity="1" LoggerId="FirstLogger" StatisticsIdentification="testLoggerStats"

...

...

...

Online (re)configuration

The logging statistics module can be re-configured while in operation independently of the programming language of the module (for nominal configuration see §3.6.7 for cpp, §3.7.11 for java and §3.8.2 for python). Re-configuration can be achieved by means of the binary "maciContainerLogStatsConfiguration" which can be executed with the following options:

...

Type safe logs work on top of the free format logs defined above in the previous sections. These are logs with a formalized structure and contents, mainly thought for the implementation of operational logs of direct interest for the operator of the system, while free format logs are used for post-mortem analysis and debugging. However, this does not exclude that type-safe logs can be used for lower level logs, when deemed convenient.
The module loggingtsTypes contains standard log definitions used over the project. Before you create your own definition, check this module to see if it isn't already there.
Here follows the XML schema file, that type safe log definitions must comply to. It is located in the loggingts module, and is called ACSLogTS.xsd.

<?xml version="1.0" encoding="

...

UTF-

...

8"?>

...

<xs:schema

...

 xmlns:

...

xs="http://www.w3.org/2001/XMLSchema"

...

 xmlns:common="urn:schemas-cosylab-com:COMMONTYPES:1.0

...

" xmlns:loggingts="Alma/ACSLogTS" targetNamespace="Alma/ACSLogTS"

...

 elementFormDefault="qualified"

...

 attributeFormDefault="unqualified">

...

   <xs:import namespace="urn:schemas-cosylab-com:COMMONTYPES:1.0" schemaLocation="commontypes.xsd" />

...

   <xs:element name="LogDefinitionType">

...

      <xs:complexType>

...

         <xs:choice maxOccurs="unbounded">

...

            <xs:element name="LogDefinition" maxOccurs="unbounded">

...

               <xs:complexType>
                  <xs:choice minOccurs="0" maxOccurs="unbounded">

...

                     <xs:element name="Member" type="common:Member_" />

...

                  </xs:choice>

...

                  <xs:attribute name="logName" type="common:nameType" use="required" />

...

                  <xs:attribute name="shortDescription" type="common:shortDescriptionString" use="required" />

...

                  <xs:attribute name="description" type="common:nonEmptyString" use="required" />

...

                  <xs:attribute name="URL" type="xs:string"

...

 use="optional" />
                  <xs:attribute name="priority" type="loggingts:priorityType" use="required" />

...

               </xs:complexType>

...

            </xs:element>

...

         </xs:choice>

...

         <xs:attribute name="name" type="common:nameType" use="required" />

...

         <xs:attribute name="type" type="loggingts:logType" use="required" />

...

         <xs:attribute name="shortDescription" type="common:shortDescriptionString" use="optional" />

...

         <xs:attribute name="description" type="common:nonEmptyString" use="optional" />

...

         <xs:attribute name="URL" type="xs:string" use="optional" />

...

         <xs:attribute name="_prefix" type="common:prefixType" default="alma" />

...

      </xs:complexType>

...

   </xs:element>

...

   <xs:simpleType name="logType">

...

      <xs:restriction base="xs:nonNegativeInteger" />

...

   </xs:simpleType>

...

   <xs:simpleType name="priorityType">

...

      <xs:restriction base="common:nonEmptyString">

...

         <xs:enumeration value="TRACE" />

...

         <xs:enumeration value="DEBUG" />

...

         <xs:enumeration value="INFO" />

...

         <xs:enumeration value="NOTICE" />

...

         <xs:enumeration value="WARNING" />

...

         <xs:enumeration value="ERROR" />

...

         <xs:enumeration value="CRITICAL" />

...

         <xs:enumeration value="ALERT" />

...

         <xs:enumeration value="EMERGENCY" />

...

      </xs:restriction>

...

   </xs:simpleType>

...

</xs:

...

schema

An example log definition file is as follows:
<?xml version="1.0" encoding="ISO-8859-1"?>
<LogDefinitionType
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns="Alma/ACSLogTS"
name="SampleLog"
type="10"
shortDescription="Example LogDefinitionType"
description="Longer description of the sample LogDefinitionType"
URL="http://someurl.org"
_prefix="alma">
<LogDefinition
logName="logWithMembers"
shortDescription="Log with members"
description="This is a somewhat more complex log using members"
URL="http://someurl.org"
priority="WARNING">
<Member name="someMember"
type="string"
description="member description"/>
</LogDefinition>
</LogDefinitionType>
After you have defined your logs, you must include them in your module's Makefile, adding the following line(let's assume the file is called SampleLog.xml):
ACSLOGTSDEF=SampleLog
This will produce the code necessary to use the logs from C++, Java and Python.
Example C++ usage(to compile this remember to add -lSampleLog to the LDFLAGS):
#include <SampleLog.h>
...
SampleLog::logWithMembers my_log(_FILE,LINE_,"this_function_name");
my_log.setsomeMember("this is the value of someMember");
my_log.log();
...
Example Java usage:
import alma.SampleLog.*
...
// m_logger is the logger of this class
// i.e. If you are in the main of a class that extends ComponentClient
// you should use this.m_logger
logWithMembers my_log=new logWithMembers(m_logger);
my_log.setsomeMember("this is the value of someMember");
my_log.log();
...
Example Python usage:
from SampleLog import logWithMembers
...
my_log=logWithMembers()
my_log.setsomeMember("this is the value of someMember")
my_log.log()
...

...