Часть 2. Идентификация событий происходящих в Oracle PL/SQL

Предисловие

Убедительная просьба, рассматривать данный текст только как продолжение к статье о "Событийной модели логирования". Эта статья будет полезна тем, у кого уже реализовано логирование событий в БД и кто хотел бы осуществлять сбор статистики и начать проводить аналитику этих событий. Только представьте, что ваша БД сможет информировать вас о критичных сбоях системы, накапливать информацию о событиях в БД (кол-во повторений, период повторений и т.д.). И всё это без использования стороннего ПО силами одного PL/SQL.

Введение

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

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

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

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

3. Единый мониторинг событий (статья в разработке)

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

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

Для чего это нужно?

Для начала давайте рассмотрим пример. Вы реализовали логирование ошибок в вашей БД. С течением времени в ваш лог «прилетают» самые разнообразные ошибки. Предположим, имеются две ошибки вида «no_data_found» возникшие в двух разных процедурах при двух разных запросах (select). Первая ошибка возникла при попытке найти «email» клиента, что в принципе не является критичной ошибкой. Вторая ошибка возникла при попытке найти номер лицевого счета клиента, что вполне может являться критичной ошибкой. При этом если мы посмотрим в таблицу лога (из статьи), то увидим, что указанные ошибки будут храниться с одинаковым кодом 1403 (ORA-01403) в столбце msgcode. Более того, текст указанных ошибок будет практически аналогичным (текст полученный с помощью функции SQLERRM) за исключением имен объектов, на которых произошла ошибка. Для того чтобы понять является ли критичной конкретная ошибка, разработчику необходимо вникать в текст ошибки, смотреть в каком объекте возникла ошибка и на основе этой информации сделать вывод о срочности исправления. При этом, если мы сможем задать более четкое описание ошибки отличное от текста Oracle (SQLERRM), то это позволит упростить понимание причин возникновения и способов решения ошибки.

 Из этого примера видно, что одна и та же ошибка «no_data_found» (ORA-01403: данные не найдены) может иметь совершенно разное значение с точки зрения бизнес логики, а значит нам необходимо разработать механизм, который позволит идентифицировать каждое событие происходящее в БД как отдельное событие с нашим внутренним уникальным кодом и текстом события (отличную от Oracle). Таким образом мы решаем две проблемы:

1) В месте возникновения ошибки мы устанавливаем уникальный код ошибки. В будущем это позволяет достаточно быстро найти место возникновения ошибки. Также, наличие уникальных кодов позволяет нам произвести точечный подсчет повторений и на основании этой информации принять решение об устранении данной ошибки.

2) Дополнительный "читаемый" текст позволяет сильно упростить понимание ошибки. В таблице выше показано, как одна и та же ошибка может запутать или разъяснить пользователю сведения об ошибке.

Надеюсь мне удалось объяснить зачем необходимо кодировать события в таблице логов. Далее по тексту, будут введены термины «Архитектурный лог» и «Пользовательский лог». На примере процедуры поиска активного номера телефона клиента будет показано как и зачем создано разделение на архитектурный и пользовательский лог.

Архитектурное логирование событий

Давайте рассмотрим пример, имеется процедура поиска активного номера телефона принадлежащего конкретному клиенту (для примера его id = 43). Предположим, что при постановке задачи для разработчика не было описания каких-либо особых условий т.е. по условиям задачи предполагалось, что для конкретного пользователя (id = 43, идентификатор передается в качестве параметра) в таблице client_telnumbers всегда будет хотя бы одна запись с номером телефона клиента и признаком «активный» (значение поля enddate равно дате 31.12.5999 23:59:59, что означает что номер используется клиентом. В случае, любой другой даты в указанном поле означает, что номер перестал быть активным и более не используется), поэтому наша процедура будет выглядеть примерно так:

procedure p_get_telnumber(p_userid    in number,
                          p_telnumber out number,
                          p_errcode   out number,
                          p_errtext   out varchar2)
  is
    v_objname   varchar2(60) := utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram(1));
    v_telnumber client_telnumbers.telnumber%type;
  begin
    select telnumber
      into v_telnumber
      from client_telnumbers
     where id = p_userid
       and enddate = to_date('31.12.5999 23:59:59', 'dd.mm.yyyy hh24:mi:ss');

    p_telnumber := v_telnumber;
    p_errcode   := 1;
  exception
    when others then
      pkg_msglog.p_log_err(p_objname    => v_objname,
                           p_msgcode    => SQLCODE,
                           p_msgtext    => SQLERRM,
                           p_paramvalue => 'p_userid = '||p_userid,
                           p_backtrace  => dbms_utility.format_error_backtrace);
      raise;
  end p_get_telnumber;

  Если мы будем использовать логирование ошибок как показано в предыдущей статье, то с течением времени обнаружим, что идентифицировать ошибки из данной процедуры будет сложно. Поэтому для всех ошибок попадающих в обработку исключения «WHEN OTHERS» реализована процедура pkg_msglog.p_log_archerr, которая при первом возникновении ошибки автоматически присваивает ей уникальный код и сохраняет ошибку в таблице лога. В дальнейшем, при повторении данной ошибки процедура найдет ранее созданный код и использует его при логировании в таблице лога.

В итоге, после добавления блока «архитектурного» логирования (строки с 18 по 24), наша процедура будет выглядеть следующим образом:

procedure p_get_telnumber(p_userid    in number,
                          p_telnumber out number,
                          p_errcode   out number,
                          p_errtext   out varchar2)

  is
    v_objname   varchar2(60) := utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram(1));
    v_telnumber client_telnumbers.telnumber%type;
  begin
    select telnumber
      into v_telnumber
      from client_telnumbers
     where id = p_userid
       and enddate = to_date('31.12.5999 23:59:59', 'dd.mm.yyyy hh24:mi:ss');

    p_telnumber := v_telnumber;
    p_errcode   := 1;
  exception
    -- Архитектурное логирование
    when others then
      pkg_msglog.p_log_archerr(p_objname    => v_objname,
                               p_msgcode    => SQLCODE,
                               p_msgtext    => SQLERRM,
                               p_paramvalue => 'p_userid = '||to_char(p_userid),
                               p_backtrace  => dbms_utility.format_error_backtrace);
      raise;
  end p_get_telnumber; 

  На этапе написания текста процедуры разработчик не всегда может предугадать возникновение той или иной ошибки (если честно, не всегда есть на это время), поэтому на начальном этапе ему достаточно «отлавливать» абсолютно все ошибки возникающие в данной процедуре с помощью оператора «WHEN OTHERS». Таким образом мы можем ввести новый термин (в рамках данного цикла статей), «Архитектурные логирование» - это логирование всех ошибок, возникновение которых не предполагается при штатной работе алгоритма. Для функционала «Архитектурных ошибок» были созданы объекты: отдельный справочник ошибок messagecodes_arch и процедура pkg_msglog.p_log_archerr создания записи в таблице лога для указанного типа ошибок.

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

create table messagecodes_arch(objectname  varchar2(120) not null,
                               sqlerrcode  number        not null,
                               msgcode     varchar2(10)  not null,
                               insertdate  date          default sysdate,
                               constraint pk_msgcode_arch_id primary key (objectname,sqlerrcode));

Ограничение в таблице на комбинацию (Имя объекта, код ошибки SQLCODE). При первом появлении ошибки создается запись в таблице и генерируется код ошибки "SYS0000" + счетчик ошибок. При повторном появлении указанной ошибки будет взят уже сгенерированный ранее код ошибки.

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

Обратите внимание, что при использовании описанной модели «архитектурного» логирования у вас появляется функционал позволяющий максимально быстро реагировать на первое появление ошибки (в конкретной функции/процедуре). Для этого необходимо реализовать отдельный мониторинг архитектурных ошибок, который постараюсь продемонстрировать в следующей (третьей) статье. Использование процедуры pkg_msglog.p_log_archerr не требует каких-либо действий кроме описания входных параметров.

Таким образом мы можем создать базовый шаблон процедуры (функции), использование которого позволит вам гарантированно отлавливать все архитектурные ошибки в вашем коде.

  -- Шаблон процедуры/функции для построения Событийной модели логирования
  -- Обратите внимание, что каждый блок "begin ... end" содержит исключение вида "when others",
  -- который осуществляет логирование Архитектурных ошибок.
  -- Все остальные исключения вида "no_data_found", "too_many_rows" и др. 
  -- будут осуществлять логирование Пользовательских ошибок
  procedure p_procedure_name(p_param1  in number,
                             p_param2  in varchar2,
                             p_param3  in date,
                             /* others param */
                             p_errcode out number,
                             p_errtext out varchar2)
  is
    v_objname varchar2(60) := utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram(1));
    /* variable */
    v_msgcode   messagelog.msgcode%type;
    v_msgtext   messagelog.msgtext%type;
  begin
  
    /* code */

    begin
    
      /* code */
  
    exception
      -- Пользовательское логирование
      when no_data_found then
        v_msgcode := 'USR0000'; -- внутренний код
        v_msgtext := pkg_msglog.f_get_errcode(v_msgcode);
        pkg_msglog.p_log_wrn(p_objname    => v_objname,
                             p_msgcode    => v_msgcode,
                             p_msgtext    => v_msgtext,
                             p_paramvalue => 'p_param1 = '||to_char(p_param1)
                                                ||', p_param2 = '||p_param2
                                                ||', p_param3 = '||to_char(p_param3,'dd.mm.yyyy hh24:mi:ss'));
	      p_errcode := -1;
        p_errtext := v_msgtext;                                           
    end;   
    
    /* code */
    
    /* result */
    p_errcode := 1;
  exception
    -- Пользовательское логирование
    when no_data_found or too_many_rows then
      v_msgcode := 'USR0000';  -- внутренний код
      v_msgtext := pkg_msglog.f_get_errcode(v_msgcode);
      pkg_msglog.p_log_wrn(p_objname    => v_objname,
                           p_msgcode    => v_msgcode,
                           p_msgtext    => v_msgtext,
                           p_paramvalue => 'p_param1 = '||to_char(p_param1)
                                                ||', p_param2 = '||p_param2
                                                ||', p_param3 = '||to_char(p_param3,'dd.mm.yyyy hh24:mi:ss'));
    	p_errcode := -1;
      p_errtext := v_msgtext;
    -- Архитектурное логирование
    when others then
      pkg_msglog.p_log_archerr(p_objname    => v_objname,
                               p_msgcode    => SQLCODE,
                               p_msgtext    => SQLERRM,
                               p_paramvalue => 'p_param1 = '||to_char(p_param1)
                                                ||', p_param2 = '||p_param2
                                                ||', p_param3 = '||to_char(p_param3,'dd.mm.yyyy hh24:mi:ss'),
                               p_backtrace  => dbms_utility.format_error_backtrace);
      raise;
 end p_procedure_name;

В рамках событийной модели логирования, предполагается, что все архитектурные ошибки будут исправляться отдельной задачей т.е. основная цель это устранить повторное появление ошибок с кодом "SYS****" в таблице лога. В указанной задаче вам необходимо либо устранить причины возникновения данной ошибки, либо добавить отдельную обработку ошибки отличную от «when others», которую в дальнейшем будем назвать «пользовательское» логирование (в рамках данного цикла статей).

Пользовательское логирование событий

Предположим, что однажды в нашей процедуре get_telnumber произошла «архитектурная ошибка». В частности, для конкретного пользователя в таблице client_telnumbers хранится два номера телефона с признаком «активный». В таком случае, процедура «упадёт» с ошибкой «ORA-01422: too_many_rows». При этом, наш функционал архитектурного логирования сгенерировал новый код ошибки «SYS0061» и создал запись в таблице лога.

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

Предположим ,что была создана отдельная задача для устранения ошибки и назначена разработчику. В рамках этой задачи, разработчик совместно с технологом, аналитиком и др. коллегами пришел к выводу, что указанная ошибка носит систематический характер, является некорректной работой системы и требует исправления. В качестве мер исправления было решено добавить обработку события «too_many_rows» с последующим логированием события в таблице лога и выводом текста ошибки для пользователя.

Для этого в процедуре get_telnumber добавлено исключение (exception) «too_many_rows» пользовательского логирования. Также, был создан справочник пользовательских ошибок отличный от архитектурного справочника, тем что в него все записи добавляются разработчиком "вручную". Наверное это самое слабое место во всей архитектуре логирования. Предполагается, что разработчик должен описать исключение (exception) и создать для него уникальный код ошибки. Также, желательно к указанной ошибке сформулировать читаемый текст ошибки (для своих коллег, пользователя, техподдержки и т.д.), что бывает иногда очень сложным (из личного опыта).

Таблица пользовательских ошибок и процедура их "регистрации" будет выглядеть следующим образом:

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

create table messagecodes(msgcode     varchar2(10)  not null,
                          rustext     varchar2(500) not null,
                          msgpriority number(1)     default 1,
                          insertdate  date          default sysdate,
                          lastupdate  date          default null,
                          constraint pk_messagecodes_id primary key (msgcode));

Регистрация пользовательских ошибок производится процедурой p_insert_msgcode. На вход подается код и текст ошибки. В случае, если по указанному коду нет записей в справочнике messagecodes, то создается новая запись (производится регистрация). В случае, если по коду ошибки найдена запись, то производится сравнение текстов ошибки, в случае расхождений производится обновление текста, иначе работа процедуры завершается без изменений. Таким образом мы всегда можем корректировать текст ошибок.

-- Пример регистации пользовательских ошибок
begin
  pkg_msglog.p_insert_msgcode('USR0001','Не найден адрес электронной почты клиента id = $1!',1);
  pkg_msglog.p_insert_msgcode('USR0002','Не найден лицевой счет клиента id = $1!',5);
  pkg_msglog.p_insert_msgcode('USR0003','Для клиента id = $1 найдено два и более активных номеров телефона!',1);
  pkg_msglog.p_insert_msgcode('USR0004','Номер мобильного телефона не соответствует маске (clientid = $2)',1);
  commit;
end;

Обратите внимание, что текст ошибок имеет параметризацию т.е. для ошибки в тексте имеются специальные символы $1, $2, $3 и т.д. Например, рассмотрим ошибку "USR0003" с текстом "Для клиента id = $1 найдено два и более активных номеров телефона!" при вызове функции f_get_errcode на вход подаётся код ошибки и параметры ошибки. Далее, функция по коду ошибки найдет строку, в тексте ошибки заменит подстроку "$1" на значение параметра to_char(p_userid) т.е. подставит значение to_char(p_userid).

v_msgcode := 'USR0003'; -- внутренний код
v_msgtext := pkg_msglog.f_get_errcode(p_msgcode  => v_msgcode,
                                      p_msgparam => to_char(p_userid));

В случае если в тексте ошибки будут два и более спецсимвола $1, $2, $3 и т.д., то параметры передаются с использованием символа-разделителя ";".

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

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

После того, как мы "зарегистрировали" пользовательскую ошибку "USR0003" и добавив отдельную обработку пользовательского логирования (строки с 19 по 28), наша процедура get_telnumber будет выглядеть следующим образом:

  procedure p_get_telnumber(p_userid    in number,
                            p_telnumber out number,
                            p_errcode   out number,
                            p_errtext   out varchar2)
  is
    v_objname   varchar2(60) := utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram(1));
    v_telnumber client_telnumbers.telnumber%type;
    v_msgcode   messagelog.msgcode%type;
    v_msgtext   messagelog.msgtext%type;
  begin
    select telnumber
      into v_telnumber
      from client_telnumbers
     where id = p_userid
       and enddate = to_date('31.12.5999 23:59:59', 'dd.mm.yyyy hh24:mi:ss');

    p_telnumber := v_telnumber;
    p_errcode   := 1;
  exception
    -- Пользовательское логирование
    when too_many_rows then
      v_msgcode := 'USR0003'; -- внутренний код
      v_msgtext := pkg_msglog.f_get_errcode(v_msgcode,to_char(p_userid));
      pkg_msglog.p_log_wrn(p_objname    => v_objname,
                           p_msgcode    => v_msgcode,
                           p_msgtext    => v_msgtext,
                           p_paramvalue => 'p_userid = '||to_char(p_userid));
      p_errcode := -1;
      p_errtext := v_msgtext;
    -- Архитектурное логирование
    when others then
      pkg_msglog.p_log_archerr(p_objname    => v_objname,
                               p_msgcode    => SQLCODE,
                               p_msgtext    => SQLERRM,
                               p_paramvalue => 'p_userid = '||to_char(p_userid),
                               p_backtrace  => dbms_utility.format_error_backtrace);
      raise;
  end p_get_telnumber;

При повторном возникновении ошибки «too_many_rows» обработка события пройдет по нашему сценарию «пользовательского» логирования. Таким образом мы можем ввести второй термин (в рамках данного цикла статей), «Пользовательские логирование» - это логирование всех ошибок, возникновение которых предполагается и ожидается при нештатной работе алгоритма. В итоге, пользователь получит читаемый текст ошибки с кодом «USR0003», также, мы же всегда сможем подсчитать количество ошибок с указанным кодом. В случае большого количества ошибок у нас на руках будет «живая» статистика частоты возникновения ошибки и их количества, что позволит нам выйти на руководство с предложением по доработке/оптимизации процесса.

Давайте рассмотрим еще один пример (кейс из реального случая), в момент когда процедура get_telnumber по id клиента находит один "активный" номер телефона иногда возникает ситуация, что номер телефона не принадлежит мобильному оператору. Ситуации бывают разные иногда указанный номер мог быть номером городской телефонной сети, иногда номером международного оператора, а иногда вообще набор из нескольких цифр и т.д. Основным требованием от бизнес-заказчика было использование номера телефона российских операторов мобильной связи. Поэтому было решено добавить проверку соответствия найденного номера некому "корректному" шаблону (строки с 18 по 29). В случае обнаружения некорректного номера, логировать данное событие отдельным кодом "USR0004" и типом "WRN". Добавим функцию проверки корректности номера телефона, если номер соответствует шаблону (требованиям), то вернем номер телефона, иначе пустое значение.

  procedure p_get_telnumber(p_userid    in number,
                            p_telnumber out number,
                            p_errcode   out number,
                            p_errtext   out varchar2)
  is
    v_objname      varchar2(60) := utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram(1));
    v_telnumber    client_telnumbers.telnumber%type;
    v_newtelnumber client_telnumbers.telnumber%type;
    v_msgcode      messagelog.msgcode%type;
    v_msgtext      messagelog.msgtext%type;
  begin
    select telnumber
      into v_telnumber
      from client_telnumbers
     where id = p_userid
       and enddate = to_date('31.12.5999 23:59:59', 'dd.mm.yyyy hh24:mi:ss');
    
    v_newtelnumber := f_check_telnumber(v_telnumber);
    if v_newtelnumber is not null then
      p_telnumber := v_telnumber;
      p_errcode   := 1;
    else
      -- Пользовательское логирование
      v_msgcode := 'USR0004'; -- внутренний код
      v_msgtext := pkg_msglog.f_get_errcode(v_msgcode,to_char(p_userid));
      pkg_msglog.p_log_wrn(p_objname    => v_objname,
                           p_msgcode    => v_msgcode,
                           p_msgtext    => v_msgtext,
                           p_paramvalue => 'p_userid = '||to_char(p_userid));
      p_errcode := -1;
      p_errtext := v_msgtext;
    end if;
  exception
    -- Пользовательское логирование
    when too_many_rows then
      v_msgcode := 'USR0003'; -- внутренний код
      v_msgtext := pkg_msglog.f_get_errcode(v_msgcode,to_char(p_userid));
      pkg_msglog.p_log_wrn(p_objname    => v_objname,
                           p_msgcode    => v_msgcode,
                           p_msgtext    => v_msgtext,
                           p_paramvalue => 'p_userid = '||to_char(p_userid));
      p_errcode := -1;
      p_errtext := v_msgtext;
    -- Архитектурное логирование
    when others then
      pkg_msglog.p_log_archerr(p_objname    => v_objname,
                               p_msgcode    => SQLCODE,
                               p_msgtext    => SQLERRM,
                               p_paramvalue => 'p_userid = '||to_char(p_userid),
                               p_backtrace  => dbms_utility.format_error_backtrace);
      raise;
 end p_get_telnumber;

После сбора статистических данных по конкретной ошибке с кодом "USR0004", руководству стало понятно, что ошибка актуальна и количество ошибок с течением времени не только не уменьшается, а наоборот растет с линейной прогрессией. В дальнейшем, были выявлены источники "кривых" данных и были установлены внутренние требования по первичной обработке номера телефона клиентов. В итоге, со временем количество ошибок уменьшилось до нуля. И этого нельзя было добиться до тех пор, пока у всех участвующих лиц не возникло понимание о масштабе проблемы.

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

Исходный код запроса

select msgtype, 
       objname, 
       msgcode, 
       count(*) 
  from messagelog
where insertdate between to_date('01.01.2021', 'dd.mm.yyyy') and to_date('31.03.2021', 'dd.mm.yyyy')
group by msgtype, objname, msgcode
order by 4 desc

Результат запроса:

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

Заключение

В заключении наверное скажу банальную вещь, о том что ваша БД является сложным механизмом ежесекундно выполняющая рутинные операции. Прямо сейчас в БД могут происходить различные ошибки. Критичные, которые вы исправляете практически сразу или некритичные, о которых вы можете вообще не знать. И если у вас нет информации о подобных ошибках, то возникает вопрос: "Нужно ли их вообще исправлять? Или можно подождать до тех пор, пока проблема не всплывёт?". Вопрос наверное "риторический".

Я же данной статьёй хотел показать один из способов ведения логирования с кодированием отдельных событий. Данный метод требует некоторых "обязательств" от разработчика и в нынешнее время этого тяжело добиться. В следующей статье постараюсь показать один из способов мониторинга ошибок основанный напрямую по кодам ошибок созданных в текущей статье.

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