· Mar 24, 2017 9m read

Logging using macros in InterSystems IRIS

In my previous article, we reviewed possible use-cases for macros, so let’s now proceed to a more comprehensive example of macros usability. In this article we will design and build a logging system.

Logging system

Logging system is a useful tool for monitoring the work of an application that saves a lot of time during debugging and monitoring. Our system would consist of two parts:

  • Storage class (for log records)
  • Set of macros that automatically add a new record to the log

Storage class

Let’s create a table of what we need to store and specify when this data can be obtained – during compilation or at runtime. This will be required when working on the second part of the system - macros, where we will aim to have as many loggable details during compilation as possible:

Information Obtained during
Event type Compilation
Class name Compilation
Method name Compilation
Arguments passed to a method Compilation
Line number in the cls source code Runtime
Line number in the generated int code Runtime
Username Runtime
Date/Time Runtime
Message Runtime
IP address Runtime

Let’s create an App.Log class containing the properties from the table above. When an App.Log object is created, User Name, Date/Time and IP address properties are filled out automatically.

App.Log class:

Class App.Log Extends %Persistent

/// Type of event
Property EventType As %String(MAXLEN = 10, VALUELIST = ",NONE,FATAL,ERROR,WARN,INFO,STAT,DEBUG,RAW") [ InitialExpression = "INFO" ];

/// Name of class, where event happened
Property ClassName As %Dictionary.Classname(MAXLEN = 256);

/// Name of method, where event happened
Property MethodName As %String(MAXLEN = 128);

/// Line of int code
Property Source As %String(MAXLEN = 2000);

/// Line of cls code
Property SourceCLS As %String(MAXLEN = 2000);

/// Cache user
Property UserName As %String(MAXLEN = 128) [ InitialExpression = {$username} ];

/// Arguments' values passed to method
Property Arguments As %String(MAXLEN = 32000, TRUNCATE = 1);

/// Date and time
Property TimeStamp As %TimeStamp [ InitialExpression = {$zdt($h, 3, 1)} ];

/// User message
Property Message As %String(MAXLEN = 32000, TRUNCATE = 1);

/// User IP address
Property ClientIPAddress As %String(MAXLEN = 32) [ InitialExpression = {..GetClientAddress()} ];

/// Determine user IP address
ClassMethod GetClientAddress()
    // %CSP.Session source is preferable
    #dim %request As %CSP.Request
    If ($d(%request)) {
        Return %request.CgiEnvs("REMOTE_ADDR")
    Return $system.Process.ClientIPAddress()


Logging macros

Usually, macros are stored in separate *.inc files containing their definitions. The necessary files can be included into classes using the Include MacroFileName command, which in this case will look as follows: Include App.LogMacro.
To start, let’s define the main macro that the user will add to their application’s code:

#define LogEvent(%type, %message) Do ##class(App.Log).AddRecord($$$CurrentClass, $$$CurrentMethod, $$$StackPlace, %type, $$$MethodArguments, %message)

This macro accepts two input arguments: Event Type and Message. The Message argument is defined by the user, but the Event Type parameter will require additional macros with different names that will automatically identify the event type:

#define LogNone(%message)         $$$LogEvent("NONE", %message)
#define LogError(%message)        $$$LogEvent("ERROR", %message)
#define LogFatal(%message)        $$$LogEvent("FATAL", %message)
#define LogWarn(%message)         $$$LogEvent("WARN", %message)
#define LogInfo(%message)         $$$LogEvent("INFO", %message)
#define LogStat(%message)         $$$LogEvent("STAT", %message)
#define LogDebug(%message)        $$$LogEvent("DEBUG", %message)
#define LogRaw(%message)          $$$LogEvent("RAW", %message)

Therefore, in order to perform logging, the user only needs to place the $$$LogError("Additional message") macro in the application code.
All we need to do now is to define the $$$CurrentClass, $$$CurrentMethod, $$$StackPlace, $$$MethodArguments macros. Let’s start with the first three:

#define CurrentClass     ##Expression($$$quote(%classname))
#define CurrentMethod    ##Expression($$$quote(%methodname))
#define StackPlace       $st($st(-1),"PLACE")

%classname, %methodname variables are described in the documentation. The $stack function returns INT code line number. To convert it into CLS line number we can use this code.

Let's use the %Dictionary package to get a list of method arguments and their values. It contains all the information about the classes, including method descriptions. We are particularly interested in the %Dictionary.CompiledMethod class and its FormalSpecParsed property, which is a list:

$lb($lb("Name","Classs","Type(Output/ByRef)","Default value "),...)

corresponding to the method signature. For example:

ClassMethod Test(a As %Integer = 1, ByRef b = 2, Output c)

will have the following FormalSpecParsed value:


We need to make $$$MethodArguments macro expand into the following code (for the Test method):

"a="_$g(a,"Null")_"; b="_$g(b,"Null")_"; c="_$g(c,"Null")_";"

To achieve this, we have to do the following during compilation:

  1. Get a class name and a method name
  2. Open a corresponding instance of the %Dictionary.CompiledMethod class and get its FormalSpec property
  3. Convert it into a source code line

Let's add corresponding methods to the App.Log class:

ClassMethod GetMethodArguments(ClassName As %String, MethodName As %String) As %String
    Set list = ..GetMethodArgumentsList(ClassName,MethodName)
    Set string = ..ArgumentsListToString(list)
    Return string

ClassMethod GetMethodArgumentsList(ClassName As %String, MethodName As %String) As %List
    Set result = ""
    Set def = ##class(%Dictionary.CompiledMethod).%OpenId(ClassName _ "||" _ MethodName)
    If ($IsObject(def)) {
        Set result = def.FormalSpecParsed
    Return result

ClassMethod ArgumentsListToString(List As %List) As %String
    Set result = ""
    For i=1:1:$ll(List) {
        Set result = result _ $$$quote($s(i>1=0:"",1:"; ") _ $lg($lg(List,i))_"=")
        _ "_$g(" _ $lg($lg(List,i)) _ ","_$$$quote(..#Null)_")_"
    Return result

Let’s now define the $$$MethodArguments macro as:

#define MethodArguments ##Expression(##class(App.Log).GetMethodArguments(%classname,%methodname))

Use case

Next, let's create an App.Use class with a Test method to demonstrate the capabilities of the logging system:

Include App.LogMacro
Class App.Use [ CompileAfter = App.Log ]
/// Do ##class(App.Use).Test()
ClassMethod Test(a As %Integer = 1, ByRef b = 2)

As a result, the $$$LogWarn("Text") macro in the int code converts into the following line:

Do ##class(App.Log).AddRecord("App.Use","Test",$st($st(-1),"PLACE"),"WARN","a="_$g(a,"Null")_"; b="_$g(b,"Null")_";", "Text")

Execution of this code will create a new App.Log record:


Having created a logging system, here's some improvement ideas:

  • First of all, a possibility to process object-type arguments since our current implementation only logs object oref.
  • Second, a call to restore the context of a method from stored argument values.

Processing of object-type arguments

The line that puts an argument value to the log is generated in the ArgumentsListToString method and looks like this:

"_$g(" _ $lg($lg(List,i)) _ ","_$$$quote(..#Null)_")_"

Let's do some refactoring and move it into a separate GetArgumentValue method that will accept a variable name and class (all of which we know from FormalSpecParsed) and output a code that will convert the variable into a line. We'll use existing code for data types, and objects will be converted into JSON with the help of SerializeObject (for calling from the user code) and WriteJSONFromObject (for converting an object into JSON) methods:

ClassMethod GetArgumentValue(Name As %String, ClassName As %Dictionary.CacheClassname) As %String
    If $ClassMethod(ClassName, "%Extends", "%RegisteredObject") {
        // it's an object
        Return "_##class(App.Log).SerializeObject("_Name _ ")_"
    } Else {
        // it's a datatype
        Return "_$g(" _ Name _ ","_$$$quote(..#Null)_")_"

ClassMethod SerializeObject(Object) As %String
    Return:'$IsObject(Object) Object
    Return ..WriteJSONFromObject(Object)

ClassMethod WriteJSONFromObject(Object) As %String [ ProcedureBlock = 0 ]
    Set OldIORedirected = ##class(%Device).ReDirectIO()
    Set OldMnemonic = ##class(%Device).GetMnemonicRoutine()
    Set OldIO = $io
    Try {
        Set Str=""

        //Redirect IO to the current routine - makes use of the labels defined below
        Use $io::("^"_$ZNAME)

        //Enable redirection
        Do ##class(%Device).ReDirectIO(1)

        Do ##class(%ZEN.Auxiliary.jsonProvider).%ObjectToJSON(Object)
    } Catch Ex {
        Set Str = ""

    //Return to original redirection/mnemonic routine settings
    If (OldMnemonic '= "") {
        Use OldIO::("^"_OldMnemonic)
    } Else {
        Use OldIO
    Do ##class(%Device).ReDirectIO(OldIORedirected)

    Quit Str
    // Labels that allow for IO redirection
    // Read Character - we don't care about reading
rchr(c)      Quit
    // Read a string - we don't care about reading
rstr(sz,to)  Quit
    // Write a character - call the output label
wchr(s)      Do output($char(s))  Quit
    // Write a form feed - call the output label
wff()        Do output($char(12))  Quit
    // Write a newline - call the output label
wnl()        Do output($char(13,10))  Quit
    // Write a string - call the output label
wstr(s)      Do output(s)  Quit
    // Write a tab - call the output label
wtab(s)      Do output($char(9))  Quit
    // Output label - this is where you would handle what you actually want to do.
    // in our case, we want to write to Str
output(s)    Set Str = Str_s Quit

A log entry with an object-type argument looks like this:

Restoring the context

The idea of this method is to make all arguments available in the current context (mostly in the terminal, for debugging). To this end, we can use the ProcedureBlock method parameter. When set to 0, all variables declared within such a method will remain available upon quitting the method. Our method will open an object of the App.Log class and deserialize the Arguments property.

ClassMethod LoadContext(Id) As %Status [ ProcedureBlock = 0 ]
    Return:'..%ExistsId(Id) $$$OK
    Set Obj = ..%OpenId(Id)
    Set Arguments = Obj.Arguments
    Set List = ..GetMethodArgumentsList(Obj.ClassName,Obj.MethodName)
    For i=1:1:$Length(Arguments,";")-1 {
        Set Argument = $Piece(Arguments,";",i)
        Set @$lg($lg(List,i)) = ..DeserializeObject($Piece(Argument,"=",2),$lg($lg(List,i),2))
    Kill Obj,Arguments,Argument,i,Id,List

ClassMethod DeserializeObject(String, ClassName) As %String
    If $ClassMethod(ClassName, "%Extends", "%RegisteredObject") {
        // it's an object
        Set st = ##class(%ZEN.Auxiliary.jsonProvider).%ConvertJSONToObject(String,,.obj)
        Return:$$$ISOK(st) obj
    Return String

This is how it looks in the terminal:

>do ##class(App.Log).LoadContext(2)

b=<OBJECT REFERENCE>[2@%ZEN.proxyObject]

>zw b
b=<OBJECT REFERENCE>[2@%ZEN.proxyObject]
+----------------- general information ---------------
|      oref value: 2
|      class name: %ZEN.proxyObject
| reference count: 2
+----------------- attribute values ------------------
|           %changed = 1
|     %data("prop1") = 123
|     %data("prop2") = "abc"
|             %index = ""

What’s next?

The key potential improvement  is to add another argument to the log class with an arbitrary list of variables created inside the method.


Macros can be quite useful for application development.


Is there a way to obtain line number during compilation?


Discussion (6)3
Log in or sign up to continue

Cool article Edward! Nevertheless I have a little note here.

According to my experience working on a huge code base, logging with macros may turn to a big pain as soon as you decide to change (add, etc) arguments to your macro, or in other words, change the macro code.

We had an application full of logging macros with something like you mentioned:

#define LogFatal(%message)        $$$LogEvent("FATAL", %message)

And at some point the logging mechanism became working improperly and we needed to change it (yuh, this logger used TCP connections and some other stuff to behave like "universal" logger in the application). But simply changing the macros code was not the case: we needed to recompile everything (as macros is compile-time code generator)! Every class on live system which used this macro. This was not successful (even on test environment) for the reasons I don't remember to be honest. What we did instead is... We spent a few days replacing all the macro code to simple class method calls like do ##class(Logger.Log).Warn(whatever). With this approach, when you change the Warn method and recompile, everything is applied immediately.

The pros I see for using macros to class methods is the thing that you can type around 15 less characters for logging, and optionally have some compile-time expressions about the logged class using macros. But the cons here is using macros itself... I believe the similar approach can be done with class methods and with the help of $stack variable.

Any comments on this? Thanks!

Nice article Eduard.

Re: last comment. Not sure how having to change the implementation of a Macro is any less of a pain than having to change hundreds of class method arguments. If anything Macro's are a great way to abstract application wide changes with a single line of code. Granted recompilation is required, but code that can't withstand recompilation all day long has a deeper problem.

My only negative about Macro's is when you can't read the code for Macro soup, less is more for me. 

One tip to add. I like to have auto complete work for Macros. If you precede each macro with a triple comment, then they will appear in the auto complete suggestions...

#define LogNone(%message)         $$$LogEvent("NONE", %message)
#define LogError(%message)        $$$LogEvent("ERROR", %message)
#define LogFatal(%message)        $$$LogEvent("FATAL", %message)


I have developed a Debug Logging system that is not quite as expansive as this version. The Debug Log class has the following properties:






It is called with one macro

#define DebugLog(%s1,%s2,%s3,%s4)

where %s1 = Username (defaults to $username)

%s2 is the Key which could be a method name or some other meaningful way to locate logs from a certain area in your code

%s3 is the Message which is a string of Human readable text 

%s4 is a %Status returned by reference (in case the code has crashed)

I use it in all of my developments

There is a Configuration class as well that basically determines whether logging is turned on or off depending on whether you are working in DEV or PRODUCTION.

The class comes with a number of methods including a Purge method that will purge all logs older than a certain number of days.

If anyone is interested in this please let me know