Логирование событий в Oracle PLSQL

Добрый день! Работая разработчиком Oracle PL/SQL, часто ли вам приходилось видеть в коде dbms_output.put_line в качестве средства debug-а? Стоит признать, что к сожалению, большинство (по моему личному мнению и опыту) разработчиков Oracle PL/SQL не уделяет должного внимания логированию как к спасательному кругу в случае возникновения ошибок. Более того, большая часть разработчиков не совсем понимает зачем нужно логировать информацию об ошибках и самое главное, не совсем понимают что делать и как использовать эту информацию в будущем.

Предисловие

Данным постом хотел бы начать цикл статей посвященных Логированию ошибок в Oracle PL/SQL. В первую очередь донести мысль до многих разработчиков, о том как можно построить функционал фиксации, хранения логов в БД. На своем опыте продемонстрировать поэтапный процесс создания полноценного логирования в БД. Рассказать как нам удалось создать логирование ошибок, разработать единую нумерацию событий для их дальнейшей идентификации, как поверх логирования натянуть мониторинг событий, создать функционал позволяющий увидеть все текущие ошибки в БД в виде таблиц (с указанием частоты возникновения ошибок и кол-ва и т.д.), графиков (отразить динамику роста кол-ва ошибок) и правильно распределить ресурсы для устранения тех или иных ошибок.

Оговорюсь сразу, что на рынке возможно уже есть успешные существующие коммерческие продукты осуществляющие логирование гораздо лучше и качественнее хотя бы, потому что у них есть многолетний опыт внедрения и сопровождения своего продукта в различных компаниях. Я же хочу показать один из множества примеров реализации функционала логирования, которые вполне можно осуществить силами своих разработчиков.

Введение

В этой и следующих статьях будет показано как реализованный функционал логирования позволяет фиксировать факт возникновения не только ошибок (сообщение с типом Error), но и сообщений с предупреждением (тип Warning), информативных сообщений (с типом Info) и т.д., поэтому, в рамках данных статей введём термин - Модель логирования событий (далее по тексту - "модель") или коротко Логирование событий, где под "событием" подразумевается некоторое ожидаемое действие, возникшее в ходе штатной/внештатной работы алгоритма.

Модель логирования позволяет реализовать:

1. Единый подход в обработке и хранении событий

2. Собственную нумерацию и идентификацию событий происходящих в БД

3. Единый мониторинг событий

4. Анализ событий происходящих в БД

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

Единый подход в обработке и хранении событий

Основной идеей "Единого подхода в обработке и хранении событий" заключается в создании одного одновременно простого и в тоже время очень сложного правила: "Все объекты базы данных (функции, процедуры) в обязательном порядке должны завершаться блоком обработки исключений с последующим логированием события". Простота заключается в том, что легко, в команде разработчиков, на словах договориться об исполнении данного правила. Сложность же заключается в том, что данное правило должно быть установлено на ранних этапах создания вашей БД и выполняться обязательно на протяжении всего жизненного цикла. Внедрить функционал логирования в уже существующие и действующие БД очень сложно (практически не возможно).

Все объекты базы данных (функции, процедуры) в обязательном порядке должны завершаться блоком обработки исключений с последующим логированием события

Наверное сейчас кто-то из читателей может возразить: "Зачем в обязательном порядке?". А всё очень просто, если вы разработчик PL/SQL и вы не согласны с этим правилом, то вот вам пример. Посмотрите на свой текущий проект более внимательно. Скорее всего вы найдете какое-нибудь логирование событий реализованное кем-то, когда-то. Вспомните сколько раз вы обращались к этому логированию при решении багов. Именно в таких ситуациях, когда есть срочность по времени в исправлении бага, вы или ваши коллеги начинают использовать dbms_output.put_line в качестве экспресс-дебага (быстрый способ получения значений переменных используемых в коде). Согласитесь, что для исправления бага мало знать в какой процедуре, в каком запросе и на какой строке возникла ошибка, необходимо знать параметры запроса на которых возникает ошибка. И вот тут нам на помощь приходит "Логирование событий", потому что помимо места возникновения ошибки мы узнаем параметры вызова процедуры, в которой возникает ошибка и это очень упрощает исправление бага.

Первая статья посвящена базовому функционалу Логирования событий. В простейшей реализации это одна общая таблица и пакет процедур для работы с ней. Для создания и демонстрации логирования, нам необходимо реализовать следующие объекты БД (весь список объектов с их исходными кодами представлен в Git):

1. Таблица messagelog - единая таблица логов. Именно в данной таблице будет храниться информация о дате и времени события, об объекте где происходит событие, типе события с указанием кода, текста и параметров. В нашем примере, столбец backtrace вынесен в отдельную таблицу messagelog_backtrace для удобства.

   Примечание. Представленное ниже описание таблицы является демонстрационным с минимальным набором столбцов для создания простейшего функционала логирования. Наличие дополнительных столбцов и их тип данных может меняться в зависимости от целей и задач логирования.

   Структура таблицы

   Название столбца	Тип данных	Комментарий
   id	number primary key	Первичный ключ таблицы
   objname	varchar2(60)	Содержит наименование объекта из которого было инициировано событие. Чаще всего это комбинация имя_пакета.имя_процедуры
   msgtype	varchar2(3)	Тип события, например: ERR - сообщение от ошибке; INF - информационное сообщение; WRN - сообщение с предупреждением и т.д.
   insertdate	date	Дата и время создания записи о событии
   msgcode	varchar2(10)	Код ошибки, чаще всего это SQLCODE, либо код ошибки из справочника ошибок (об этом будет отдельная статья)
   msgtext	varchar2(500)	Текст ошибки, чаще всего это SQLERRM, либо текст ошибки из справочника ошибок
   paramvalue	varchar2(500)	Наименования параметров процедуры/функции и их значения. При анализе ошибок удобно видеть с каким параметрами была запущена та или иная процедура, выполнить повторный запуск этой процедуры с указанными параметрами и воспроизвести ошибку
   backtrace	varchar2(4000)	Записывается результат функции dbms_utility.format_error_backtrace, либо иная дополнительная информация

   Исходный код таблицы

   create table messagelog(id         number(38)      not null,                        msgtype    varchar2(3)     not null,                        objname    varchar2(60)    default null,                        insertdate date            default sysdate,                        msgcode    varchar2(10)    default null,                        msgtext    varchar2(4000)  default null,                        paramvalue varchar2(4000)  default null,                        constraint pk_messagelog_id primary key (id))partition by range (insertdate)  interval (numtoyminterval(3, 'MONTH'))    (partition p1 values less than (to_date('01.01.2020', 'DD.MM.YYYY'))); 
   

   *Исходный код других используемых объектов смотрите в Git

   В данной статье не будем подробно описывать способы индексирования и партицирования таблицы, всё зависит от целей и задач логирования. Самый предпочтительный вид хранения таблицы это партицирование по столбцу insertdate с интервалом 3 месяца.

   Отдельно стоит упомянуть про столбцы msgtext, paramvalue и backtrace. По своему опыту скажу, что указанные столбцы в 60% - 70% случаев будут пустыми и это очень сильно не нравится архитекторам и/или руководителям отделов разработки. Поэтому иногда есть смысл вынести указанные столбцы в отдельную таблицу с привязкой по id записи. В нашем примере столбец backtrace вынесен в отдельную таблицу messagelog_backtrace (см. исходный код в git).

2. Пакет pkg_msglog - содержит набор процедур необходимых для логирования событий. В нашем примере будут представлены одна "корневая" и две процедуры для логирования событий: "ERR" - событие об ошибке; "WRN" - предупреждающее событие. Вызов корневой процедуры выполняется в автономной транзакции и делается это для того, чтобы была возможность выполнить сохранение данных об ошибке с откатом всех предыдущих изменений.

   Исходный код процедур пакета

   -- процедура логирования ошибокprocedure p_log_err(p_objname    in varchar2,                    p_msgcode    in varchar2,                    p_msgtext    in varchar2 default null,                    p_paramvalue in varchar2 default null,                    p_backtrace  in varchar2 default null)  is  begin    p_insert_log(p_msgtype_    => 'ERR',                 p_objname_    => p_objname,                 p_insertdate_ => sysdate,                 p_msgcode_    => p_msgcode,                 p_msgtext_    => p_msgtext,                 p_paramvalue_ => p_paramvalue,                 p_backtrace_  => p_backtrace);  end p_log_err;    -- корневая процедура логирования  procedure p_insert_log(p_msgtype_    in varchar2,                         p_objname_    in varchar2,                         p_insertdate_ in date,                         p_msgcode_    in varchar2,                         p_msgtext_    in varchar2 default null,                         p_paramvalue_ in varchar2 default null,                         p_backtrace_  in varchar2 default null)  is    v_id   messagelog.id%type;    pragma autonomous_transaction;  begin    insert into messagelog(msgtype,                           objname,                           insertdate,                           msgcode,                           msgtext,                           paramvalue,                           backtrace)        values(p_msgtype_,               p_objname_,               p_insertdate_,               p_msgcode_,               p_msgtext_,               p_paramvalue_,               p_backtrace_)    return id      into v_id;    if trim(p_backtrace_) is not null then      insert into messagelog_backtrace(id,                                       backtrace)      values(v_id,             trim(p_backtrace_));    end if;    commit;  end p_insert_log;
   

   *Исходный код других используемых объектов смотрите в Git

3. Тестовый пакет pkg_clients - пакет с демонстрационными процедурами поиска и создания пользователей. Обратите внимание, что процедура p_insert_user выполняет функции аудита события - "создание нового пользователя".

   Исходный код процедур поиска и создания пользователей

   create or replace package body pkg_clients as  procedure p_insert_user(p_login_     in varchar2,                          p_firstname_ in varchar2,                          p_lastname_  in varchar2,                          p_id_        out number)  is    v_id clients.id%type;  begin    insert into clients(login,                        firstname,                        lastname)        values(upper(p_login_),               p_firstname_,               p_lastname_)    return id      into v_id;    if v_id > 0 then      -- аудит события - создание нового пользователя      pkg_msglog.p_log_wrn(p_objname    => 'pkg_clients.p_insert_user',                           p_msgcode    => '101',                           p_msgtext    => 'Создан новый пользователь с id = '||v_id,                           p_paramvalue => 'p_login = '||p_login_                                             ||', p_firstname = '||p_firstname_                                             ||', p_lastname = '||p_lastname_);    end if;    commit;  exception    when others then      pkg_msglog.p_log_err(p_objname    => 'pkg_clients.p_insert_user',                           p_msgcode    => SQLCODE,                           p_msgtext    => SQLERRM,                           p_paramvalue => 'p_login_ = '||p_login_                                             ||', p_firstname_ = '||p_firstname_                                             ||', p_lastname_ = '||p_lastname_,                           p_backtrace  => dbms_utility.format_error_backtrace);      rollback;  end p_insert_user;    procedure p_create_user(p_login     in varchar2,                          p_firstname in varchar2,                          p_lastname  in varchar2,                          p_id        out number)  is    v_id clients.id%type;  begin    begin      select id        into v_id        from clients       where login = upper(p_login);    exception      when no_data_found then        p_insert_user(p_login_     => p_login,                      p_firstname_ => p_firstname,                      p_lastname_  => p_lastname,                      p_id_        => v_id);    end;       p_id := v_id;  exception    when others then      pkg_msglog.p_log_err(p_objname    => 'pkg_clients.p_create_user',                           p_msgcode    => SQLCODE,                           p_msgtext    => SQLERRM,                           p_paramvalue => 'p_login = '||p_login                                             ||', p_firstname = '||p_firstname                                             ||', p_lastname = '||p_lastname,                           p_backtrace  => dbms_utility.format_error_backtrace);  end p_create_user;end pkg_clients;
   

   *Исходный код других используемых объектов смотрите в Git

Демонстрация логирования событий

Для демонстрации работы выполним три стандартных кейса с помощью созданного ранее пакета pkg_clients.

1. (Ошибочная ситуация) Создание пользователя с длиной имени превышающей допустимое значение в таблице

   Пример 1
   рис. пример запуска процедуры

   Результат

   рис. описание ошибки

2. (Ошибочная ситуация) Создание пользователя с пустым значением имени или фамилии (предположим, что есть такое требование)

   Пример 2
   рис. пример запуска процедуры

   Результат

   рис. описание ошибки

3. (Успешная ситуация) Создание нового пользователя с аудитом события

   Пример 3
   рис. пример запуска процедуры

   Результат

   рис. описание ошибки

   Обратите внимание, что все демонстрационные процедуры завершаются блоком exception when others then с дальнейшим вызовом процедуры логирования события вне зависимости от "важности" процедуры.

Заключение

В заключении я повторюсь, что гораздо проще и правильнее добавлять логирование событий в обработку исключений при первом написании процедуры (функции) т.к. это не занимает много времени. Гораздо сложнее в будущем, внести правки в большое количество объектов БД и это займет гораздо больше времени на написание кода, тестирование и т.д.

По своему опыту отмечу, что пакет pkg_msglog (со всеми дополнительными объектами логирования) должен быть создан самым первым в проектируемой БД и в дальнейшем другие объекты создаются с логированием событий. Также, часто в командах появляются разработчики, которые говорят: "Зачем логировать все процедуры (функции)? Давайте вести логирование только важных и нужных процедур (функций)!". Вот здесь скрывается самая главная и распространенная ошибка. У всех нас разное понимание что есть "важная и нужная" процедура (функция). По сути, вы создаете логирование ошибок, которое "как бы и есть, но как бы его нет" т.е. все в команде знают, что в БД есть лог ошибок, но в нужный момент (например, при возникновении "блокера" на продакшн) вы обнаружите что в логах нет никакой информации об ошибке. Именно в такие моменты и возникает ошибочное мнение, что логировать события бесполезно и бессмысленно, а ведь это не так.

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

Спасибо за внимание.