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

    Monet impression sunrise

    Введение


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

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


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


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


    Составим таблицу того, что нам надо хранить, сразу же напишем, когда возможно получить эти данные — во время компиляции или исполнения программы. Это потребуется при написании второй части системы — макросов, где мы, очевидно, стремимся узнать как можно больше логируемых данных во время компиляции:
    Информация Время получения
    Тип события Компиляция
    Имя класса Компиляция
    Имя метода Компиляция
    Аргументы, переданные в метод Компиляция
    № строки исх. Кода Выполнение
    Имя пользователя Выполнение
    Дата/Время Выполнение
    Сообщение Выполнение
    IP адрес Выполнение
    Создадим класс App.Log. В нём создадим все вышеперечисленные свойства. При создании объекта класса App.Log свойства Имя пользователя, Дата/Время, IP адрес заполняются автоматически.
    Класс App.Log
    Class App.Log Extends %Persistent
    {

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

    /// Тип события
    Property 
    EventType As %String(MAXLEN 10VALUELIST ",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 32000TRUNCATE 1);

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

    /// Произвольное сообщение
    Property 
    Message As %String(MAXLEN 32000TRUNCATE 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(As %Integer 1ByRef 2Output 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 %StringMethodName As %StringAs %String
    {
        
    Set list = ..GetMethodArgumentsList(ClassName,MethodName)
        
    Set string = ..ArgumentsListToString(list)
        
    Return string
    }
    ClassMethod GetMethodArgumentsList(ClassName As %StringMethodName As %StringAs %List
    {
        
    Set result ""
        
    Set def ##class(%Dictionary.CompiledMethod).%OpenId(ClassName "||" MethodName)
        
    If ($IsObject(def)) {
            
    Set result def.FormalSpecParsed
        
    }
        
    Return result
    }
    ClassMethod ArgumentsListToString(List As %ListAs %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(As %Integer 1ByRef 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 %StringClassName As %Dictionary.CacheClassnameAs %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(ObjectAs %String
    {
        
    Return:'$IsObject(ObjectObject
        
    Return ..WriteJSONFromObject(Object)
    }
    ClassMethod WriteJSONFromObject(ObjectAs %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_Quit
    }

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


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


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

    Методы LoadContext и DeserializeObject
    ClassMethod LoadContext(IdAs %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(StringClassNameAs %String
    {
        
    If $ClassMethod(ClassName"%Extends""%RegisteredObject"{
            
    // it's an object
            
    Set st ##class(%ZEN.Auxiliary.jsonProvider).%ConvertJSONToObject(String,,.obj)
            
    Return:$$$ISOK(stobj
        
    }
        
    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 и еще одному очень компетентному инженеру, пожелавшему остаться неназванным, за помощь в написании кода.
    InterSystems
    76,00
    Вендор: СУБД Caché, OLAP DeepSee, шина Ensemble
    Поделиться публикацией

    Похожие публикации

    Комментарии 4

      0
      Штука хорошая. Как я понял, все записи в лог помещаются в хранимые классы — это очевидный оверхед к работе системы. А есть какой-то флаг включать/отключать логирование?
        0
        А есть какой-то флаг включать/отключать логирование?

        Отключение логирования возможно — для этого надо закомментировать 1 строку (сохранения записи). Как более постоянный вариант можно сделать получение настройки вкл/выкл из параметра или глобала. Но это, мне кажется, нужно делать при интеграции системы логирования с конкретным приложением — вместе с остальными настройками приложения.
          +1
          Хранимыми логи и должны быть, разве что тут точно не хватает отключения журналирования в коде, чтобы ошибка записанная в рамках транзакции не была по роллбеку откачена, и увеличить немного скорость. Так же добавленение можно сделать асинхронно. По поводу отключения легирования, классический способ loglevel установленный в приложении должен контролировать какие логи пишем.
            0
            Согласен, что хранимость логов это плюс: можно SQL по ним потом легко или DeepSee. Да и параметр loglevel бы добавить. Про отключение журналирования +1

        Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

        Самое читаемое