понедельник, 17 июня 2013 г.

[prog.memories] Ruby DSL для логирования в C++ программах

Вдогонку к заметке о статье про DSL для работы с пакетами протокола UCP/EMI, расскажу об еще одном сделанном на Ruby DSL-е, который используется моей командой несколько последних лет. Причем этот DSL мной не разрабатывался. Я только сформулировал его цели и идею, а воплощением и доведением до ума занимались мои подчиненные: Игорь Мирончик и Борис Сивко, а затем Николай Гродзицкий и Николай Шмаков (надеюсь, что никого не забыл).

Потребность в данном DSL возникла из-за требования нашей техподдержки включать в документацию по программным компонентам раздел с перечислением всех сообщений, которые приложение вводит в лог (кстати, если не ошибаюсь, аналогичные требования есть в ГОСТ-овском ЕСПД). Первоначально это перечисление делалось вручную, посредством контекстного поиска по исходному коду обращений к подсистеме логирования. Но, понятное дело, занятие это муторное, результаты дает посредственные. А самое плохое, что если при выпуске документации по первой версии компонента еще удавалось набраться терпения и перечислить в документе все сообщения со всеми параметрами, то вот при обновлении версии разыскать и исправить все изменившиеся сообщения было уже не реально. Тем самым провоцировалось расхождение между приложением и документацией, а это не есть хорошо.

Поэтому появилась идея: сначала делать на специальном языке описание логируемых сообщений и их параметров. Затем из этого описания генерировать C++ные функции и классы, которые будут использоваться в коде приложения. А так же фрагменты документации, которые можно будет вставить в текст описания программного компонента.

Сгенерировать и то, и другое не проблема. Т.к. на выходе будет всегда обычный текст: либо .hpp-файл, либо кусок LaTeX-овского кода (т.к. документацию по своим компонентам мы делали в LaTeX-е и это в очередной раз оказалось выгоднее, чем использовать Word). Ну а в качестве базы для языка описания сообщений лога был взят Ruby. Объяснялось это тем, что, во-первых, Ruby в моем подразделении был вторым рабочим языком и проблем с сопровождением кода на Ruby быть не должно было. Во-вторых, у нас уже имелся опыт разработки embedded DSL-ей на Ruby, поэтому и с этой стороны никаких подвохов не ожидалось.

В общем, после небольшого мозгового штурма, довольно быстрой первой реализации и нескольких последующих доработок получилось следующее. Сообщения, которые компонент должен отображать в лог, описываются в отдельном solog-файле (это обычный .rb-файл но с другим расширением). При компиляции C++ проекта solog-файл отдается внешнему кодогенератору, который по содержимому solog-файла строит .hpp-файл с большим набором вспомогательных классов. Этот .hpp-файл должен быть подключен в соответствующие .hpp/.cpp-файлы проекта. Сгенерированные классы задействуются в C++коде посредством специальных макросов, которые выглядят для программиста как API подсистемы логирования. При написании документации из solog-файла тем же кодогенератором, но с другими параметрами, генерируется .tex-файл, который либо подключается в текст документации посредством \include, либо его содержимое просто копипастится в соответствующий раздел. В Subversion мы хранили только solog-файлы, но не результаты C++ кодогенерации, т.к. эти результаты автоматически воспроизводились при компиляции проекта.

Ну а теперь, думаю, пора переходить к примерам, чтобы не продолжать рассказ на пальцах. Вот как выглядит часть описания сообщений лога в solog-файле:

namespace :ig_inout_door_2 do

   anchor :outgoing_import do

      logic :startedLEVEL_NORMAL do
         brief 'Запущен импорт диапазонов новых исходящих сообщений'
         param :last_stop_point'client_message_id_t''место остановки последнего импорта'
      end

      logic :intermediateLEVEL_NORMAL do
         brief 'Получен промежуточный результат импорта диапазонов новых ' +
               'исходящих сообщений'
         param :range_count'unsigned int''количество найденых новых диапазонов'
         param :stop_point'client_message_id_t''место остановки импорта'
      end

      logic :finishedLEVEL_NORMAL do
         brief 'Импорт диапазонов новых исходящих сообщений завершен'
         param :range_count'unsigned int''количество найденых новых диапазонов'
         param :stop_point'client_message_id_t''место остановки импорта'
      end
   end # anchor :outgoing_import

Здесь нужно дать небольшое пояснение. Наша подсистема логирования отличается от того, что построено на основе идей Log4j. У нас сообщения делятся всего на два типа: сообщения об ошибках (error) или о логических действиях (logic). А уже в рамках каждого типа сообщения есть свои уровни приоритетов (lowest, low, normal, medium, high, highest). Так же из нашего опыта использования лог-файлов, мы пришли к выводу, что сообщения в журнале должны помечаться двойным идентификатором. Его первая часть указывает тип операции, а вторая часть -- конкретное действие или стадию внутри операции. Например, save_to_file::opening говорит о том, что выполняется стадия открытия файла в рамках операции сохранения в файл.

В приведенном выше фрагменте посредством метода anchor описывается операция outgoing_import, которая состоит из трех стадий: started, intermediate и finished. Информация о каждой из стадий содержит свои параметры. В данном случае все параметры обязательны (если бы они описывались посредством метода opt_param, то это были бы опциональные параметры). Поэтому вспомогательный C++ код будет сгенерирован таким образом, что если при логировании какого-то действия операции outgoing_import программист забудет какой-либо из параметров, то он не сможет скомпилировать свой код -- возникнет ошибка компиляции. Так же ошибка компиляции возникнет, если программист ошибется с типом параметров.

В прикладном коде разработчик использует логирование следующим образом:

void
a_inout_door_t::perform_new_outgoing_message_import()
   {
      const client_message_id_t last_stop_point =
            m_local_db->last_outgoing_message_import_stop_point();

      so_log_msg_same_ns(
                  outgoing_import, started )
            .last_stop_point( last_stop_point )
            .finish( *this );


      last_outgoing_message_import_result_auto_ptr_t import_result =
            m_global_db->perform_new_outgoing_message_import( last_stop_point );
      so_log_msg_same_ns(
                  outgoing_import, intermediate )
            .range_count( import_result->m_ranges.size() )
            .stop_point( import_result->m_stop_point )
            .finish( *this );


      initialize_just_loaded_outgoing_message_range_list(
            import_result->m_ranges );

      m_local_db->save_last_outgoing_message_import_result( *import_result );

      m_last_outgoing_message_import_time = ACE_OS::gettimeofday();
      so_log_msg_same_ns(
                  outgoing_import, finished )
            .range_count( import_result->m_ranges.size() )
            .stop_point( import_result->m_stop_point )
            .finish( *this )
;
   }

При работе приложения в лог-файл в итоге помещаются сообщения вида:

LOG [2010.05.04 12:00:16.714] Normal -- ig_inout_door_2::default::a_inout_door [outgoing_import::started] last_stop_point: 100265;

LOG [2010.05.04 12:00:16.714] Normal -- ig_inout_door_2::default::a_inout_door [outgoing_import::intermediate] range_count: 0; stop_point: 100265;

LOG [2010.05.04 12:00:16.714] Normal -- ig_inout_door_2::default::a_inout_door [outgoing_import::finished] range_count: 0; stop_point: 100265;

Здесь первое слово LOG указывает, что это сообщение о логическом действии (соответствует методу logic в solog-файле), Normal -- это уровень важности сообщения. Имя ig_inout_door_2::default::a_inout_door -- это имя SObjectizer-агента, который осуществляет логирование (оно берется подсистемой логирования когда следует вызов .finish(*this) в прикладом коде).

Для документации из вышеприведенного фрагмента строится LaTeX-ный код приблизительно такого вида (в данном случае он копипастом включен прямо в текст документации после комментария):

Компонент \CompIGInoutDoor{} оставляет следующие сообщения в журнале работы:
\begin{flushleft}\begin{description}
%%% Начало автоматически сгенерированного текста.
\item[{[log][outgoing\_import::started]}]{~---
Запущен импорт диапазонов новых исходящих сообщений;

  Параметры сообщения:
  \begin{description}
    \item[last\_stop\_point]{место остановки последнего импорта}
  \end{description}
}
\item[{[log][outgoing\_import::intermediate]}]{~---
Получен промежуточный результат импорта диапазонов новых исходящих сообщений;

  Параметры сообщения:
  \begin{description}
    \item[range\_count]{количество найденых новых диапазонов}
    \item[stop\_point]{место остановки импорта}
  \end{description}
}
\item[{[log][outgoing\_import::finished]}]{~---
Импорт диапазонов новых исходящих сообщений завершен;

  Параметры сообщения:
  \begin{description}
    \item[range\_count]{количество найденых новых диапазонов}
    \item[stop\_point]{место остановки импорта}
  \end{description}
}

Что после генерации PDF-ки дает вот такой результат:


Вот такой инструмент мы себе в свое время соорудили. Удобно. В последние 3-4 года логирование в наших компонентах осуществлялось исключительно с его помощью. Ну а старый код при сопровождении, переписывании и/или доработках, переводится на этот DSL по мере надобности. Конечно, получившийся результат далек от идеала и есть еще над чем работать. Но это рабочий внутренний инструмент, который развивается когда для этого складываются предпосылки и находится время. В общем, обычная ситуация с обычным велосипедом ;)

В заключение хочу сказать, что создание DSL стало возможно из-за использования таких средств, как C++ (#include и #define), Mxx_ru для сборки проектов, LaTeX для документирования. Все это оказалось важным. Для той же Java, боюсь, соорудить что-нибудь подобное на коленке вряд ли получилось бы. Насколько я знаю, в C# поступили мудрее, там фрагменты одного класса могут находится в разных файлах, поэтому в C# использование результатов автоматической генерации исходных текстов так же возможно. Насчет чего-нибудь более модного в настоящий момент (как-то Erlang или Haskell) не знаю, не копенгаген ;)

Комментариев нет: