VisiBroker for C++ Developer’s Guide : VisiBroker Logging

VisiBroker Logging
VisiBroker for C++ provides a logging mechanism, which allows applications to log messages and have them directed, via configurable logging forwarders called appenders, to appropriate destination or destinations. The ORB and all its services themselves use this mechanism for the output of any error, warning or informational messages. By using this feature, the application can choose to log its and the ORB’s messages to the same destination, producing a single message log for the entire system, or to log messages from different sources to independent destinations. Filters and layouts give additional capability for filtering and formatting the log messages.
Note
This logging mechanism is different from the OMG’s Telecom Logging Service (VisiTelcoLog). This is a lightweight C++ only logging library, which the ORB and its services including VisiTelcoLog use to log internal messages. The entire logging framework and the inbuilt appenders and layouts are in a shared library named:
Here “p” is for Standard C++ libraries, bitmode is “64” for 64 bit platforms, and <version> is the version of VisiBroker. The APIs of the library are exposed in the vdlog.h header file.
Logging Overview
Logging in VisiBroker employs one or more Logger objects, that applications (including the ORB) may log messages to. ORB and all its C++ services use a special Logger instance (the ‘Default Logger’ with the name “default”), which is created automatically the first time the ORB logs a message. Applications can log messages to the Default Logger as well, to integrate their logging output with that of the ORB, or they can create one or more other Loggers, to log messages independently as said earlier.
A Logger in the framework can have one or more appenders associated with them to which all the log messages are sequentially forwarded and each appender in turn is responsible to output to desired destinations such as standard error, a file, over a network, an OMG Telecom Logging Service log etc.
The figure below explains how a logger is associated with three appenders named A1, A2 and A3 where each appender is of a different type forwarding the logs to different types of destinations.
Along with forwarding the message, an appender may optionally choose to use a configured layout to format the log before outputting. Here, appenders A1 and A3 are using layouts L1 and L3. With no explicit configuration, by default, a logger logs to an appender of type “stdout” using a layout instance of type “simple”.
The logger has another feature to allow it to filter the log messages. Prior to sending the log message to the list of appenders, the logger processes the message for its source name and log level using a filter and based on the outcome, does the logger decide whether to forward to the appenders or discard the message. By changing the settings of the allowable source names and their log levels, high filtering fidelity can be achieved.
This chapter covers the following topics:
Logger Manager
Logger Manager is the starting point for using the functionality provided by the logger framework and one of the main functionality of the Logger Manager is to manage the lifecycle of Loggers. The Logger Manager is a singleton object and a reference to it is obtained by calling its static instance method. No reference counting is performed upon the Logger Manager. The code snippet below explains how the static instance function can be used to access the singleton logger manager object.
// Use static instance function to obtain Logger Manager reference
VISLoggerManager_ptr logger_manager = VISLoggerManager::instance();
VISLogger_ptr logger = logger_manager->get_default_logger();
...
// Alternatively, the Logger Manager reference may be obtained each time it
// is used. Here, for example, when calling its get_default_logger method
VISLogger_ptr logger = VISLoggerManager::instance()->get_default_logger();
Apart from giving access to the loggers, this singleton is also responsible for being a registrar for the custom appender and layout factories. It is also responsible for providing and configuring the global enabling switch and the verbosity level.
Logging
As mentioned earlier applications can make use of the logging interface to log messages either using the default logger or a separate logger. All log messages to a single logger are bound to a common set of destinations and by using multiple loggers for logging, messages from different components could be output to various independent end points.
In the code snippet below, the server application is using the default logger to log its application specific messages. It is using the source name bankagentserver to identify its log messages from server code and bankagentimpl from the implementation code. Source names can be a very helpful tool for modularization and proves its worth during the filter configuration stages.
#define MYLOG(LVL, COMP, MESG) \
if (VISDLoggerMgr::instance()->global_log_enabled()) { \
VISDLoggerMgr::instance()->get_default_logger()->log( \
LVL, COMP, MESG \
, __FILE__, __LINE__ \
); \
}
#define MYLOGDBG(COMP, MESG) \
MYLOG(VISDLogLevel::DEBUG_, COMP, MESG)
#define MYLOGINF(COMP, MESG) \
MYLOG(VISDLogLevel::INFO_, COMP, MESG)
#define BAS "bankagentserver"
#define BAS_LOGDBG(MESG) MYLOGDBG(BAS,MESG)
#define BAS_LOGINF(MESG) MYLOGINF(BAS,MESG)
#define BAI "bankagentimpl"
#define BAI_LOGDBG(MESG) MYLOGDBG(BAI,MESG)
#define BAI_LOGINF(MESG) MYLOGINF(BAI,MESG)
int main(int argc, char* const* argv)
{
BAS_LOGINF("Bank agent server start");
try {
BAS_LOGINF("Initializing ORB");
// Initialize the ORB.
CORBA::ORB_var orb = CORBA::ORB_init(argc, argv);
BAS_LOGINF("Resolving Initial reference to Root POA");
// get a reference to the root POA
CORBA::Object_var obj = orb->resolve_initial_references("RootPOA");
...
}
Alternatively, the application could have chosen to use a logger specific for its logging by changing the macro MYLOG as follows:
#define MYLOG(LVL, COMP, MESG) \
if (VISDLoggerMgr::instance()->global_log_enabled()) { \
VISDLoggerMgr::instance()->get_logger(“mylogger”)->log( \
LVL, COMP, MESG \
, __FILE__, __LINE__ \
); \
}
All the log messages from the source bankagentserver and bankagentimpl will then be directed to the logger mylogger and its configured appenders. The log messages coming from the ORB will go to the appenders configured on the default logger.
Filtering
During troubleshooting exercises it is sometimes very useful to filter out log messages from particular modules or source names or change their verbosity. The logger framework provides a powerful yet simple means to have a sophisticated filtering mechanism using the logger filters. The filter in each logger considers two components of a logged message based on which message is forwarded to the appenders. Each log message has information regarding its source of logging and its log level. The filter uses this information and following the logic below, recommends forwarding:
If source name is registered with the filter
If source name is enabled
If log’s log level is greater than or equal to source’s log level
Forward
Else
Reject
Else
Reject
Else If the source name “all” is enabled
If the log’s log level is greater than or equal to the global log level
(on the log manager) setting
Forward
Else
Reject
Else
Reject
“all” is a special source name indicating all the sources that have not been registered with the filter.
The ORB is organized in modules using the following source names:
Each of the services is also modular and uses appropriate source names for components. Some examples given below illustrate how some filtering objectives can be achieved. For more information about the properties, see the configuration section below.
The following properties enable logging and set the global verbosity level to info. Any log messages with alower level are filtered out.
vbroker.log.enable=true
vbroker.log.logLevel=info
The following properties enable logging and only turns off the log messages from the component that performs osagent communication. All other messages are logged.
vbroker.log.enable=true
vbroker.log.default.filter.register=agent
vroker.log.default.filter.agent.enable=false
The following set of properties enable logging and allow all log messages, except for messages from the component that performs osagent communication with a verbosity value lower than info.
vbroker.log.enable=true
vbroker.log.default.filter.register=agent
vbroker.log.default.filter.agent.enable=true
vbroker.log.default.filter.agent.logLevel=info
The following set of properties enable logging and allow only the logs from osagent communication component whose verbosity is either greater or equal to info. All other log messages are filtered out.
vbroker.log.enable=true
vbroker.log.default.filter.register=agent
vbroker.log.default.filter.agent.enable=true
vbroker.log.default.filter.agent.logLevel=info
vbroker.log.default.filter.all.enable=false
Reserved names
The following names are reserved and cannot be used for naming loggers, appender and layout types, appender instances or source names: “default”, “appender”, “appenders”, “layout”, filter”, “simple”, “full”, “xml”, “stdout”, “rolling”, “all”, and any name starting with “v”. Behavior is indeterminate if such strings are used.
Customization
If the built in-appenders and layouts are not sufficient, then custom objects can be implemented and provided in shared library and the logger framework made to load them at runtime.
To do this, the following steps need to be performed.
1
2
3
Similar steps could be also performed for custom layouts.
For example, if an application wanted to use its own appender that logged to the console, using a custom layout that just printed the log message and omitted all other details, first the appender and layout interface need to be implemented as described below.
The following code snippet shows the classes that implement the appender factory and the appender.
class StdOutAppFactory : public VISDAppenderFactory {
public:
// Constructor
StdOutAppFactory() {
// register when the global instance object is created
VISDLoggerMgr::instance()->register_app_factory(this);
}
...
// unique appender type name for this custom appender
virtual const char* type_name() { return “mystdout”; }
// API that the framework will call when it needs an appender
// instance of this type
virtual VISDAppender_ptr create(const char* logger_name,
VISDConfig::LogAppenderConfig_ptr p);
// API that the framework will call when it needs to destroy
// an appender instance created by this factory
virtual void destroy(VISDAppender_ptr app);
// global instance object that gets created when the library
// or DLL gets loaded
static StdOutAppFactory _instance;
};
class StdOutApp : public VISDAppender {
public:
...
// should return TRUE if the appender is using ORB features else FALSE.
// Since this appender type does not need any ORB feature
// it returns FALSE
virtual CORBA::Boolean ORB_initialized(void* orb_ptr);
// After shutdown notification, ORB features should not be used
virtual void ORB_shutdown();
// actual append implementation. Should return TRUE is append
// operation is successful
virtual CORBA::Boolean append(const VISDLogRecord& record);
...
};
The following code snippet similarly explains an implementation for a custom layout.
class SimpleLayoutFactory : public VISDLayoutFactory {
public:
// Constructor
SimpleLayoutFactory() {
// register when the global instance object is created
VISDLoggerMgr::instance()->register_lyt_factory(this);
}
// unique type name for this layout
virtual const char* type_name() { return “mysimple”; }
// logger framework will call this API when it desires a layout instance
// of this type
virtual VISDLayout_ptr create(const char* logger_name,
VISDConfig::LogAppenderConfig_ptrp);
// calls this API when a layout instance created by this factory
// is to be destroyed
virtual void destroy(VISDLayout_ptr layout);
// global instance object that gets created when the library
// or DLL gets loaded
static SimpleLayoutFactory _instance;
...
};
class SimpleLayout : public VISDLayout {
public:
...
// API that will be called by an appender using this layout to format
// the message
virtual void format(const VISDLogRecord& record,
char* buf,
CORBA::ULong buf_size,
CORBA::String_var& other_buf);
...
};
If the above implementation were built into a library, say Custom.dll (or libCustom.so), then by using the following properties, the framework could be made to use this:
vbroker.log.enable=true
 
# Define the appender and layout types for the framework to use
vbroker.log.appender.register=”mystdout”
vbroker.log.appender.mystdout.sharedLib=Custom.dll (or libCustom.so)
vbroker.log.layout.register=”mysimple”
vbroker.log.layout.mysimple.sharedLib=Custom.dll (or libCustom.so)
 
# Attach an instance of the above custom types on the default logger
vbroker.log.default.appenders=app1
vbroker.log.default.appender.app1.appenderType=mystdout
vbroker.log.default.appender.app1.layoutType=mysimple
At runtime, when the default logger is first accessed, the framework will read the configuration information, will identify that the appenders needed for the default logger are in a shared library, will try to load the shared library (assuming that the custom objects contained within would have registered themselves with the logger manager using the register_<>_factory APIs) and will then assemble the logger.
Configuration
All the composition of the logger framework setup is done through configuration and using a runtime property-based mechanism. The following aspects can be configured:
1
2
3
4
5
Log manager configuration
Setting the following property:
vbroker.log.enable={true|false}
enables or disables the logger manager. The values input may be true or false and by default the value is false.
vbroker.log.logLevel={emerg|alert|crit|err|warning|notice|info|debug}
Setting the above property sets the global coarse-grained verbosity setting for the logger framework. This setting however can be refined for further control by configuring the filter on the logger. By default, the value chosen is debug.
Though there are eight log levels altogether, the ORB and all its services use only the following four:
debug—The lowest level. It specifies fine-grained informational events that are most useful to debug an application for the developers. It is similar to using an offline debugger, for example showing parameter or argument values, the contents of a complex data structure like the marshalling buffer, particular memory contents like the message on the connection wire, etc.
info—Specifies informational messages that highlight the progress of the application at a coarse-grained level. These are general tracing statements. This level gives a linear view of how objects are created and destroyed, the flow of various calling and called functions, how certain actions are carried out, and how different components interact together.
err—Specifies error events that might still allow the application to continue running. These are scenarios where an error condition was detected, but corrective action could be taken and progress continued. Log statements in exception handlers can have this log level.
emerg—The highest level. This designates very severe error events that will presumably lead the application to abort. These are scenarios where ORB cannot proceed with the functional requirements and no corrective actions can be taken, and which lead to undefined behavior.
Appender and layout registration configuration
vbroker.log.appender.register=<comma separated list of appender type names>
vbroker.log.appender.<at>.sharedLib=< shared library file >
vbroker.log.layout.register=<comma separated list of layout type names>
vbroker.log.layout.<lt>.sharedLib=<shared library file>
Using the above properties, custom appender and layout type names and their implementation location in shared libraries and DLLs can be made known to the logger framework. Here, “at” and “lt” are names of appender and layout types respectively which are among the comma separated type names being introduced.
Setting appenders and layouts on loggers
vbroker.log.<ln>.appenders=<comma separated list of app instance names>
vbroker.log.<ln>.appender.<an>.appenderType=<at>
vbroker.log.<ln>.appender.<an>.layoutType=<lt>
To configure appender instances on the loggers, the above set of properties can be used. “ln”, here denotes the logger name. Using the first two properties, the logger framework is instructed on all the appender instance names associated with the logger and their types. If an appender type is not inbuilt, then the shared libraries as explained in the previous set of properties are loaded and appenders obtained. Please note that the logger framework assumes that the shared library on being loaded will automatically register all the appender and layout factories implemented within with the logger manager.
The third property instructs the appender instance of the desired layout. If the appender does not use any layouts, this information is ignored. Otherwise, an instance of the layout type is obtained.
Apart from providing a means to use custom appenders and layouts, the framework also comes inbuilt with some appender and layout types. “stdout” outputs all its messages to console, while “rolling” performs the log append operation on a rolling file based data store. Both these appenders use layouts and can be set with “simple”, “full” or “xml” layouts or any custom layouts. “xml” formats the messages in Log4J xml format.
Asynchronous mode
The mechanism for logging an event asynchronously is primarily used on FileAppender where file IO is usually a constraint to logging performance. In this mode, after the appender receives an event from the pool, it constructs a message that contains logging information in a pre-defined layout. It then pushes this message to the message queues and returns it immediately. This avoids IO blocking and so increases performance of the main thread. Another pool of threads consistently listens to these queues and writes to a configured file destination.
By default, this mode is disabled. To turn on the asynchronous mode, the property below needs to be set:
vbroker.log.default.appender.<appender-instname>.async=true.
Filter configuration
vbroker.log.<ln>.filter.register=<Comma separated source names>
vbroker.log.<ln>.filter.<sn>.enable=true/false
vbroker.log.<ln>.filter.<sn>.logLevel={emerg|alert|crit|err|warning| notice|info|debug}
Each log message being output records the source from where it is emanating. This source name is actually a part of the log record itself. A fine-grained filtering mechanism is provided which allows filtering based on the source names in addition to the global switch provided in the log manager. Using properties, the filter in a logger can be configured to allow log messages based on particular source names and verbosity in context of the source name to be forwarded to the appenders. To configure these attributes of the filter, the above properties can be used. “ln”, here denotes the logger name. First all the source names that we want to control are registered with the filter using the first property. Then setting for each source name is fine tuned using the second and the third properties. “sn” denotes a source name that is registered in the comma separated source names in the first property. A special source name “all” denotes all the source names that have not been configured using the above properties.
Setting the properties
The above properties can be fed into the logger framework using a properties file containing these properties, pointed to by the environment variable VDLOG_PROP_FILE.
ORB and all its services use the default logger named “default” and hence the ORB overrides the setting of the default logger again by using the VisiBroker for C++ property manager when the above properties are fed in using either “–D” command line parameters or through a properties file pointed to by the “–ORBpropStorage” command line parameter.