Пишем систему логирования в InterSystems Caché

Введение

В предыдущей статье мы рассмотрели основные варианты использования макросов, теперь перейдём к написанию более обширного примера, использующего макросы. Писать будем систему логирования.

Система логирования

Это нужный и полезный инструмент для протоколирования работы приложения. Значительно экономит время, затрачиваемое на отладку и вылавливание различных багов. Система состоит из двух частей:

• Класс хранения логов
• Набор макросов для автоматического добавления новой записи в лог

Класс хранения логов

Составим таблицу того, что нам надо хранить, сразу же напишем, когда возможно получить эти данные — во время компиляции или исполнения программы. Это потребуется при написании второй части системы — макросов, где мы, очевидно, стремимся узнать как можно больше логируемых данных во время компиляции:

Информация	Время получения
Тип события	Компиляция
Имя класса	Компиляция
Имя метода	Компиляция
Аргументы, переданные в метод	Компиляция
№ строки исх. Кода	Выполнение
Имя пользователя	Выполнение
Дата/Время	Выполнение
Сообщение	Выполнение
IP адрес	Выполнение

Создадим класс App.Log. В нём создадим все вышеперечисленные свойства. При создании объекта класса App.Log свойства Имя пользователя, Дата/Время, IP адрес заполняются автоматически.

Класс App.Log

Class App.Log Extends %Persistent
{

/// Замещение несуществующих значений
Parameter Null = "Null";

/// Тип события
Property EventType As %String(MAXLEN = 10, VALUELIST = ",NONE,FATAL,ERROR,WARN,INFO,STAT,DEBUG,RAW");

/// Имя класса
Property ClassName As %String(MAXLEN = 256);

/// Имя метода
Property MethodName As %String(MAXLEN = 128);

/// Строка int кода
Property Source As %String(MAXLEN = 2000);

/// Имя пользователя
Property UserName As %String(MAXLEN = 128) [ InitialExpression = {$username} ];

/// Аргументы, переданные в метод
Property Arguments As %String(MAXLEN = 32000, TRUNCATE = 1);

/// Дата/время
Property TimeStamp As %TimeStamp [ InitialExpression = {$zdt($h, 3, 1)} ];

/// Произвольное сообщение
Property Message As %String(MAXLEN = 32000, TRUNCATE = 1);

/// Сетевой адрес пользователя
Property ClientIPAddress As %String(MAXLEN = 32) [ InitialExpression = {..GetClientAddress()} ];

Index idxEventType On EventType [ Type = bitmap ];
Index idxUserName On UserName [ Type = bitmap ];
Index idxClassName On ClassName [ Type = bitmap ];
Index idxTimeStamp On TimeStamp [ Type = bitslice ];
Index idxClientIPAddress On ClientIPAddress;

/// Определяем сетевой адрес пользователя
ClassMethod GetClientAddress()
{
    // Если существует сессия CSP, то возьмём оттуда
    #dim %request As %CSP.Request
    If ($d(%request)) {
        Return %request.CgiEnvs("REMOTE_ADDR")
    }
    Return $system.Process.ClientIPAddress()
}

/// Добавление события.
/// Использовать не напрямую, а через макросы $$$LogEventTYPE().
ClassMethod AddRecord(ClassName As %String = "", MethodName As %String = "", Source As %String = "", EventType As %String = "", Arguments As %String = "", Message As %String = "")
{
    Set record = ..%New()
    Set record.Arguments = Arguments
    Set record.ClassName = ClassName
    Set record.EventType = EventType
    Set record.Message = Message
    Set record.MethodName = MethodName
    Set record.Source = Source
    Do record.%Save()
}
}

Макросы логирования

Обычно макросы выделяют в отдельные inc файлы, где хранятся только сами определения макросов. Подключают необходимые файлы к классам командой Include MacroFileName. В данном случае Include App.LogMacro.
Для начала определим основной макрос, котором пользователь будет добавлять в код своего приложения:
#define LogEvent(%type, %message) Do ##class(App.Log).AddRecord($$$CurrentClass, $$$CurrentMethod, $$$StackPlace, %type,
$$$MethodArguments, %message)
На вход данный макрос принимает 2 аргумента — Тип события и Сообщение. Сообщение пользователь задаёт сам, а вот для передачи типа события напишем дополнительные макросы, отличающиеся названиями и передающие Тип события без необходимости каких-либо действий со стороны пользователя:

Макросы LogTYPE

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

Таким образом пользователю для использования логирования достаточно установить макрос $$$LogError("Дополнительное сообщение") в коде приложения.
Осталось определить макросы $$$CurrentClass, $$$CurrentMethod, $$$StackPlace, $$$MethodArguments. Начнём с первых трёх:
#define CurrentClass     ##Expression($$$quote(%classname))
#define CurrentMethod     ##Expression($$$quote(%methodname))
#define StackPlace         $st($st(-1),"PLACE")

Переменные %classname,%methodname описаны в документации макросов. Для получения номера строки int кода используется функция $stack.
Для получения списка аргументов методов и их значений воспользуемся пакетом %Dictionary. Там хранятся все описания классов, в том числе и описания методов. В частности на интересует класс %Dictionary.CompiledMethod и его свойство FormalSpecParsed — $lb структура следующего вида: $lb($lb("Название","Класс","Тип(Output/ByRef)","Значение по умолчанию"),...)
соответствующая сигнатуре метода. К примеру у метода ClassMethod Test(a As %Integer = 1, ByRef b = 2, Output c) будет следующий FormalSpecParsed:
$lb(
$lb("a","%Library.Integer","","1"),
$lb("b","%Library.String","&","2"),
$lb("c","%Library.String","*",""))
В результате выполнения макроса $$$MethodArguments нужно получить следующий код (для метода Test): "a="_$g(a,"Null")_"; b="_$g(b,"Null")_"; c="_$g(c,"Null")_";"

Для этого на этапе компиляции нужно:

• Получить имя класса и имя метода
• Открыть соответствующий экземпляр класса %Dictionary.CompiledMethod и получить свойство FormalSpec
• Преобразовать его в строку исходного кода

Добавим соответствующие методы в класс App.Log:

Методы GetMethodArguments, GetMethodArgumentsList, ArgumentsListToString

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)_")_" 
        _$s(i=$ll(List)=0:"",1:$$$quote(";"))
    }
    Return result
}

Теперь определим макрос $$$MethodArguments как:#define MethodArguments ##Expression(##class(App.Log).GetMethodArguments(%classname,%methodname))

Пример использования

Создадим класс App.Use с методом Test для демонстрации возможностей системы логирования

App.Use

Include App.LogMacro
Class App.Use [ CompileAfter = App.Log ]
{
/// Do ##class(App.Use).Test()
ClassMethod Test(a As %Integer = 1, ByRef b = 2)
{
    $$$LogWarn("Текст")
}
}

В результате макрос $$$LogWarn("Текст") в int коде преобразуется в строку:
Do ##class(App.Log).AddRecord("App.Use","Test",$st($st(-1),"PLACE"),"WARN","a="_$g(a,"Null")_"; b="_$g(b,"Null")_";", "Текст")

После выполнения этого кода создается новый объект класса App.Log:

Улучшения

Написав основу системы логирования, подумаем как её можно улучшить.
Во-первых добавим возможность обработки аргументов-объектов, потому что в данный момент будут записаны только oref объектов.
Во-вторых добавим возможность открытия контекста — в том случае, из хранимых значений аргументов восстанавливать контекст (аргументы) метода.

Обработка аргументов-объектов

Генерация строки, которая записывает значение аргумента в лог происходит в методе ArgumentsListToString и выглядит как: "_$g(" _ $lg($lg(List,i)) _ ","_$$$quote(..#Null)_")_". Произведём рефакторинг и выделим её в отдельный метод GetArgumentValue, который на вход будет принимать имя переменной и её класс (а всё это нам известно из FormalSpecParsed) а на выходе будет код преобразующий переменную в строку. Для типов данных это будет уже существующий код, объекты будем преобразовывать в JSON методами SerializeObject (для вызова из клиентского кода) и WriteJSONFromObject (для конвертации объекта в JSON):

Методы GetArgumentValue, SerializeObject и WriteJSONFromObject:

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 ]
{
    // Create a string that we will redirect to
    Set Str = ""
    Use $io::("^"_$ZNAME)
 
    // Enable redirection
    Do ##class(%Device).ReDirectIO(1)
 
    // Any write statements here will be redirected to the labels defined below
    Do ##class(%ZEN.Auxiliary.jsonProvider).%ObjectToJSON(Object)
 
    // Disable redirection
    Do ##class(%Device).ReDirectIO(0)
    
    Return Str
 
    // Labels that allow for IO redirection
    // Read Character - we don't care about reading
rchr      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
}

Запись в лог с аргументом-объектом выглядит следующим образом:

Открытие контекста

Идея этого метода состоит в том, чтобы сделать доступными все аргументы в текущем контексте (в основном — терминала, для отладки приложения). Для этого используется параметр метода ProcedureBlock, если установить его равным 0, то все переменные объявленные внутри такого метода, будут доступны и после выхода их метода. Наш метод, соответственно, будет открывать объект класса App.Log и десериализировать свойство Arguments.

Методы LoadContext и DeserializeObject

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
}

В терминале это выглядит следующим образом:

zw
>
do ##class(App.Log).LoadContext(9)
zw
>a=3
>b=<OBJECT REFERENCE>[2@%ZEN.proxyObject]
zw b
>
+----------------- general information ---------------
|      oref value: 2
|      class name: %ZEN.proxyObject
| reference count: 2
+----------------- attribute values ------------------
|           %changed = 1
|         %data("A") = 1
|         %data("B") = "stringvalue"
|             %index = ""

Что дальше?

Основное улучшение, которое здесь можно сделать — это добавление ещё одного аргумента в основной макрос с произвольным списком переменных, созданных уже внутри метода.

Выводы

Макросы позволяют реализовать на этапе компиляции часть логики приложения, уменьшая таким образом нагрузку в рантайме.

Ссылки

Часть I. Макросы
GitHub репозиторий системы логирования
Классы системы логирования

Автор выражает благодарность хабраюзерам Daimor, Greyder и еще одному очень компетентному инженеру, пожелавшему остаться неназванным, за помощь в написании кода.