DRAMA Logging Facilities

DRAMA's logging facilities have had a somewhat tortured history, with different components using different systems, largely added to help solve particular problems. The AAO's own instrumentation tasks have used a number of different logging systems over the years.

Recently a significant amount of effort has been put into formalizing a generalized logging system and this has now stabilized sufficiently for general use.

Logging System Aims.

Part of the delay in developing a proper DRAMA logging system has been the various, often conflicting, requirements imposed by various jobs. For example:

Highly detailed logging must be available when required - to help chase complex communication problems. But as this generates large log files, the level of logging must be highly controllable.
Logging must have a limited impact on running tasks and in cases where high performance is required must be able to be disabled or turned off.
Logging of significant DRAMA internal operations should be available when required.
The log destination must be controllable - maybe to files, maybe to a network logging facility.
Libraries must be able to log without having to worry about the way the application has chosen to write the logs.

DRAMA Logging overview.

The basic approach implemented is that DRAMA provides standard calls to log messages to an application defined logging system. These calls are available whatever application defined logging system is being used. If the application has not defined a logging system then no logging is done.

In Addition - DRAMA provides an implementation of a logging system which applications can enable if required and which provides an example of the required interface.

The following C/C++ interfaces are provided

DitsLogMsg(3): This function should be invoked to write log messages. The first argument is a mask of logging levels to be associated with the message. These levels are passed through to the logging system which uses them to determine how to treat the logging message (e.g. if it is to be written to the file). The second argument, prefix, is a string which is normally used to indicate the source of the log message, for example, the function/package which is witting the log message.
DitsLogFlush(3): Flush the log file to disk (if supported by logging system). This is done automatically each time DRAMA has finished processing a message, but it can be done on demand using this call
DitsSetLogSys(3): This function is invoked by an application to enable a logging system. It provides to DRAMA a set of routines to be invoked for various logging events. These are well defined, ensuring the logging system has all the information it needs to log. Normally this call is only used by logging system implementations.
DitsSetDebug(3): This function is used to enable/disable logging of DRAMA's internal operations. A mask of various flags is supplied as the first argument.
Dits___Log(3): Only of interest to those modifying DRAMA itself. This call is used by DRAMA to log its internal messages. It is normally invoked only when particular flags set-able by DitsSetDebug(3) are enabled.
GitLogger: A C++ class which is part of the GIT library. This class implements a basic logging facility and it the standard logging facility to be used by AAO DRAMA tasks. The constructor of this class invokes DitsSetLogSys(3). Standard actions and parameters allow the logging level to be set externally in a consistent way.
GitLoggerInit(3): A C interface to the GitLogger constructor. This allows C programs to use the GitLogger. Note that this is only available if DRAMA has been build with C++ support enabled.

The normal procedure in a DRAMA task is for an application to enable a logging system (Eg. it calls GitLoggerInit(3)) as part of application startup or initialization. Then calls to DitsLogMsg(3) are made as desired. The logging system determines exactly what happens to the log message.

The Generic Instrumentation Task Logger.

The GitLogger class is defined by the $GIT_DIR/gitlogger.h include file. This class is designed to implement application logging according to AAO standards, but may be suitable for other organizations as well.

The AAO has historically defined that logging be controlled by an action named LOG_LEVEL, a parameter also named LOG_LEVEL and a environment variable named system_LOG_LEVEL where system is some name uniquely identifying the task but which is independent of the task name (Where there are multiple instances of the same task, system is the same, but the task name is different). These are all used to set a mask of logging levels which determine which log messages are written to a log file. Log messages may also be written to the screen.

GIT Logger Initialization

When the GitLogger constructor is invoked (often by the C interface GitLoggerInit(3)) it does the following

If not being invoked as part of an action, it will define the LOG_LEVEL action and create the parameter if it does not already exist. If being invoked as part of an action, the LOG_LEVEL action must already exist, but its obey routine is overridden.
A log file is created. This has the name dir/ddmmmyyyy.log where dd is the day in the month, mmm is the abbreviated month name and yyyy is the year. The UT date is used.
dir is the directory name. This may be supplied directly (not available from C interface) but is more often the directory specified by the environment variable DRAMA_LOGDIR. If this is not set, then the current default directory is used. Normally DRAMA_LOGDIR is defined to locate the log files for all DRAMA tasks in a system.
The parameter LOG_LEVEL is examined. Its value is a set of logging levels as handled by the LOG_LEVEL action or the value NONE. If NONE then the environment variable system_LOG_LEVEL is examined, system being one of the arguments to the constructor. If this environment variable exists its value should be appropriate as an argument to the LOG_LEVEL action and becomes the initial logging level. If we still don't have a logging level then "ERRORS,MSG" is specified as the default logging level.
The resultant logging level becomes the initial logging level.
Normal behavior is to specify NONE in the parameter such that levels are set by setting the environment variable.
If the parameters ENQ_VER_NUM and ENQ_VER_DATE exist, then their values are logged to the log file.
A background file sync thread is started - if threads are supported on the machine in question. This thread will sync the log file to disk every five seconds - allowing an efficient buffered file to be used as the log file.
DitsSetLogSys(3) is invoked to set the DITS logging system routines.

GIT Logger - Changing Log levels

To change the level of logging use the LOG_LEVEL action. The argument to this action is a string with the following format

[no]level[-s][,| ][[no]level[-s]...]

Which is a touch complicated. First let me introduce the levels. These are

ALL: Indicates ALL levels.
STARTUP: This indicates task start up messages. In most cases, this is any message logged through DitsLogMsg(3) using the DITS_LOG_STARTUP flag.
ERRORS: This indicates error messages. In particular, ERS messages and logging of action exit when the action exited with bad status
ACTENT: This indicates action entry events - an action being started or rescheduled.
ACTEXIT: This indicates action exit events - an action routine returning.
INST: This is really a user logging level - any message logged through DitsLogMsg(3) using the DITS_LOG_INST. These were intended for instrument (hardware) related logs but at AAO have tended to be the normal logging level from an application.
MSG: This indicates MsgOut(3) messages.
DEBUG: Debugging messages - not used in anger by GitLogger.
COMMS: DRAMA communication log events - such as sending of messages.
ARGS: When logging action entry/action exit/message sends, then this indicates that SDS arguments should be logged (this is somewhat more expensive then just logging the basic event)
USER1: User specified logging level 1. In most cases, this is any message logged through DitsLogMsg(3) using the DITS_LOG_USER1 flag.
USER2: User specified logging level 2. In most cases, this is any message logged through DitsLogMsg(3) using the DITS_LOG_USER2 flag.
USER3: User specified logging level 3. Not available from DitsLogMsg(3).
USER4: User specified logging level 4. Not available from DitsLogMsg(3).
SCREEN: Enable corresponding screen levels

The LOG_LEVEL action changes the current log mask, rather then setting the current mask. As a result, you can prefix a level by NO in order to turn it off. Previously enabled levels remain in force unless turned off by this command. To enable the sending of log messages to the screen, suffix the level by "-S"

Various levels may be changed by separating them with commas or spaces. Case is not significant.

The level "SCREEN" is a special case. When supplied, logging to screen (via MsgOut(3))for all other levels are also enabled. When "NOSCREEN" is supplied, the level is enabled but the corresponding screen bit is disabled, unless a level is suffixed by "-S".

Levels names may be abbreviated to the smallest unique name.

Examples

The following are some examples of the LOG_LEVEL action argument.

    INST

Turn on INST level logging, leaving other levels as set.

    NOINST

Turn off INST level logging, leaving other levels as set.

    ERRORS,MSG

Turn on ERRORS and MSG logging - the default logging levels.

    ERRORS,NOMSG

Turn on ERRORS and turn off MSG.

    ERRORS,MSG,INST-s

Turn on ERRORS, MSG and INST levels. INST level messages are also logged to the screen.

GIT Logger - Log File contents

The following is an example of a log file produced by a GitLogger, except that the first column is a line number added to help describe the contents.

01  ----------- task GITTEST ----------------------
02  Time of Message     :Action Name      :Sequence:Message Prefix  :Message
03  08-Oct-2003 23:38:28:--UFACE-CONTEXT- :       0:GitLogger       :Opened log file
04  08-Oct-2003 23:38:28:--UFACE-CONTEXT- :       0:GitLogger       :*** Logging levels set, old = c0022, 80000, new = c0022, 80000
05  08-Oct-2003 23:38:28:--UFACE-CONTEXT- :       0:GitLogger       :*** Logging levels set, old = c0022, 80000, new = c0022, 80000
06  08-Oct-2003 23:38:28:--UFACE-CONTEXT- :       0:GitLogger       :Task Version is P0.0, date 11-Dec-1992
07  08-Oct-2003 23:38:35:LOG_LEVEL        :       0:GitLogger       :*** Logging levels set, old = c0022, 80000, new = ffffffff, 80000
08  08-Oct-2003 23:38:35:LOG_LEVEL        :       0:MSG             :Logging levels set to ALL
09  08-Oct-2003 23:38:35:LOG_LEVEL        :       0:ACTEXIT-OK      :Action Finished - request = 0 (END)
10  08-Oct-2003 23:38:35:LOG_LEVEL        :       0:ACTEXIT-ARG     :No output argument supplied
11  08-Oct-2003 23:38:39:TEST             :       0:ACTSTART        :Action Starting
12  08-Oct-2003 23:38:39:TEST             :       0:ACTENT-ARG      :No argument supplied
13  08-Oct-2003 23:38:39:TEST             :       0:ACTEXIT-OK      :Action Finished - request = 0 (END)
14  08-Oct-2003 23:38:39:TEST             :       0:ACTEXIT-ARG     :No output argument supplied
15  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : Failed to release semaphore id 10878985
16  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : semop returned errno value 22, Invalid argument
17  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             :Error trying to send a 'close' message on connection 1
18  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             :Annulling 3 messages at context 2
19  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : Failed to flag shared memory file /tmp/tjf/imp_scratch/imp_192.231...
20  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : Task 12878, unlink() returned errno value 2, No such file or directory
21  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : Failed to delete semaphore number 10878985
22  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             : semctl returned errno value 22, Invalid argument
23  08-Oct-2003 23:38:39:--UFACE-CONTEXT- :       0:ERS             :Annulling 4 messages at context 2
24  08-Oct-2003 23:38:42:EXIT             :       0:ACTSTART        :Action Starting
25  08-Oct-2003 23:38:42:EXIT             :       0:ACTENT-ARG      :No argument supplied
26  08-Oct-2003 23:38:42:EXIT             :       0:ACTEXIT-OK      :Action Finished - request = 5 (EXIT)
27  08-Oct-2003 23:38:42:EXIT             :       0:ACTEXIT-ARG     :No output argument supplied
28  08-Oct-2003 23:38:42:--UFACE-CONTEXT- :       0:GitLogger       :Logging system shutdown via DRAMA callback (DitsStop)
29  08-Oct-2003 23:38:42:--UFACE-CONTEXT- :       0:GitLogger       :Log file closed
30  #################################################

Line 1 indicates the beginning of the log file and the task writing it. Line 2 gives the column headings for the remainder of the log file. The columns are fixed with the the exception of the last column. Columns are separated by a colon ":"

The first column gives the UT time the message was written. The second column gives the name of the action writing the message. If this is "--UFACE-CONTEXT-" then no action is active. The third column gives the action sequence number, if any (may be -1 for internal DRAMA messages). The fourth column gives the prefix of the message and the sixth is the message itself.

Lines 3 through 6 are start up messages from GitLogger itself, as indicated by the prefix. They indicate when the log file was opened, the logging levels being set and the task version number and date (as fetched from the parameters ENQ_VER_NUM and ENQ_VER_DATE).

Lines 7 through 10 are from the action LOG_LEVEL, which was the first message sent to the task. Line 7 was logged by GitLogger itself as the logging levels were changed. Line 8 is a log of a MsgOut(3) call. Since all logging levels are now enabled we see the logging of the action exit on line 9 and an indication that no output argument was supplied on line 10.

Lines 11 through 14 are from the action TEST, which was the second message sent to the task. This does not do much - you see the action starting and exiting and indication that no argument was supplied in either case. If the action had an input/output argument then these would be converted to strings (max 200 characters) and output. If the action rescheduled or completed with error then full details are logged if ACTEXIT logging is in force.

Lines 15 through 23 are ERS library log events. These show (lines 15 through 17 and 19 through 22) that calls to ErsRep(3) were made. But lines 18 and 23 show that ErsAnnul(3) was then called so the error was never output. This sequence occurred due to the way the IMP handled the shutdown of the task which sent the TEST action to this program. The annulling of the message indicates it was nothing to worry about.

Lines 24 through 27 are from the action EXIT. You can see on line 26 that the Action Exit Request (the value put by DitsPutRequest(3)) was 5 (DITS_REQ_EXIT) - indicating the task should be shutdown.

Lines 28 and 29 record the logging system shutting down and line 30 is used to separate this run from a subsequent run appending to the same log file.

GitLogger - Background Sync Thread

Where possible (Currently VxWorks, (Currently disabled on Solaris, Linux and Mac Os X through can be enabled if required)) initialization of GitLogger creates a second thread in the program. This is necessary because logging is done using buffered files - for efficiency. Buffered files have the problem that if the task crashes or doesn't write anything for a while, the file may not be flushed to disk. The background thread is designed to get around this, ensuring the file is written to disk every five seconds.

The use of the background thread does cause a couple of complications. First, on Solaris (at least version 2.6) it delays the shutdown of the task by up to five seconds. Second, on Mac Os X you may have problems if a task crashes without cleaning up correctly. A message is output in these cases indicating the background thread has been disabled, but telling you how to fix the problem.

GitLogger - change of UT day

The first log message written on a new UT day causes GitLogger to close the log file and open a new file. This ensures that log files can be cleaned up etc. regardless of if a task runs indefinitely.

GitLogger - cleanup

GitLogger is automatically cleaned up when DRAMA shut's down or when a new logging system is enabled. You cannot invoke the destructor directly.

Future Enhancements to GitLogger

The current version of GitLogger has one significant lacking feature which we hope to attend to at some point. Currently, log entries are made to disk only if a logging level is currently enabled. What would be nice is to buffer logging events internally and send the buffer to disk when an error occurs. This would require more CPU and memory but is a nice feature to have. It may be implemented as an option at some point.

Additionally, at the moment there is no automatically generated documentation on the GitLogger class.

Tcl Interface

DRAMA's TCL interface - DTCL, provides access to both DitsLogMsg(3) and the GitLogger. The DTCL Tcl command DitsLogMsg(n) is a simply TCL interface to the C level call. An additional DTCL Tcl command - DitsLogSysEnabled(n) simply returns true/false to indicate if a logging system is enabled. (This is used by some code which may be used in older tasks which don't have logging enabled).

The GitLogger is not available by default in DTCL - due to the requirement to link against C++ run time libraries which are not available in all DRAMA environments. To enable support for GitLogger your Tcl application could use the following commands

global env
load $env(DTCL_DEV)/libgitlogger.so

(This may or may not work depending on the operating system. Future work will hopefully tidy this up). Alternatively, if your Tcl application includes C/C++ code, it can just call GitLogger_Init(n) from its application initialization routine.

Having done either of these, the command "GitLogger::Init" is available to initialize the logger.. The first argument is the logging system name the optional second argument is the directory for the log

Java Interface

The DRAMA Java interface (DJAVA) provides the DramaTask.Log method for logging messages. This is just an interface to DitsLogMsg(3).

The GitLogger is built into DJAVA and is enabled by invoking DramaTask.GitLogger.

DRAMA Internal debugging

The DRAMA internal debugging facility was intended to help debug DRAMA itself, but also helps in determining exactly what is happening in a DRAMA task.

The call DitsSetDebug(3) sets the levels to be logged. When internal logging is enabled, calls are then made to Dits___Log(3) to log the message. If a logging system is enabled, then Dits___Log(3) will invoke the same function used by DitsLogMsg(3) but specifying a level of DITS_LOG_INTERNAL. Normally the logging system will ensure these logs goto the file. This to enable DRAMA internal logging through the logging system you need only call DitsSetDebug(3).

If no logging system is enabled by an application, then Dits___Log(3) will output its log messages to the stderr using fprintf(3).

It should be noted that the logging level DITS_LOG_LIBS is used by libraries such as DJAVA and DCPP to trigger their logging. It is defined as enabling logging in DRAMA's libraries.

The DitsSetDebug(3) interface is available in various other ways. First, if when a task starts up, the environment variable DITS_DEBUG is defined, then its value should be an integer which is then passed to DitsSetDebug(3). Thus you can enable debugging when starting up tasks.

Alternatively, you may turn debugging on an offset at any time using the "DEBUG" control message. For example

ditscmd -c TICKER DEBUG 65535

Turns on all debugging levels (65535 = hex FFFF = enable all levels) in the task named TICKER. You can log at the file $DITS_DIR/DitsSystem.h to find the integer values of the various logging levels.

A Tcl command named DitsSetDebug(n) allows the call to be made from Tcl whilst the JAVA method DramaTask.SetDebug() is available from DJAVA.

Other DRAMA Logging facilities

These are older facilities and are somewhat haphazard.

The DUI routines use a flag in their details structure to trigger logging for a particular message transaction. For the particular message, this is equivalent to setting the DITS_LOG_LIBS level via DitsSetDebug(3) as far as the DUI library is concern, but it only impact DUI (not any other library that may be in use). In older versions such messages where logged using MsgOut(3) but now use Dits___Log(3).

DRAMA's Tcl interface uses the global variable named Logging (or Drama::Logging if namespaces are in use) to trigger logging of messages. This value is actually passed through to the DUI routines used to send the messages.

DRAMA's C++ interface message sending interface (DcppTask) provides its own flags for controlling logging set-able via DcppTask::LoggingOn(), DcppTask::LoggingOff(), DcppTask::TaskLoggingOn() and DcppTask::TaskLoggingOn(). Again, all logging triggered by these calls can be enabled by setting DITS_LOG_LIBS when calling DitsSetDebug(3), but these methods trigger logging specific to either DcppTask or the DcppTask object they are operating on.

Please see DRAMA debugging for details of other older schemes and the IMP layer schemes.

Click here for the DRAMA home page and here for the AAO home page.

For more information, contact tony.farrell@mq.edu.au