Oracle лог ошибок

Время на прочтение
9 мин

Количество просмотров 15K

Добрый день! Работая разработчиком 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 для удобства.

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

   Также, учитывайте пожалуйста, что создание партиции требует как минимум Oracle EE. Создание партиции вне указанной версии Oracle приведет к нарушению лицензионного соглашения.

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

   Название столбца	Тип данных	Комментарий
   id	number primary key	Первичный ключ таблицы
   sessionid	number(38)	Идентификатор сессии для объединения группы ошибок
   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,
                           sessionid  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_sessionid_  => v_sid,
                    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_sessionid_  in number,
                            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,
                              sessionid,
                              objname,
                              insertdate,
                              msgcode,
                              msgtext,
                              paramvalue)
           values(p_msgtype_,
                  p_sessionid_,
                  p_objname_,
                  p_insertdate_,
                  p_msgcode_,
                  p_msgtext_,
                  p_paramvalue_)
       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);
         raise;
     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);
         raise;
     end p_create_user;
   end pkg_clients;

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

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

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

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

   Пример 1

   

   Результат

   

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

   Пример 2

   

   Результат

   

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

   Пример 3

   

   Результат

   

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

Заключение

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

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

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

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

Upd. 15.04.2021. Добавлен столбец sessionid для объединения группы ошибок возникших в рамках одной сессии.

Upd. 04.05.2021. Слияние, создание перекрестных ссылок со второй статьей.

Администраторы баз данных Oracle обычно используют сценарии SQL для предупреждений о ненормальных ситуациях. В Oracle Database 11g и 12c предусмотрена встроенная система сигналов (Oracle alerts), формально именуемая генерируемыми сервером сигналами тревоги, которые автоматически предупреждают о возникновении проблемных ситуаций. База данных генерирует сигналы в ответ на возникновение специфических событий, или когда определенные метрики базы данных превышают свои пороговые значения.

В Oracle сигналы на основе пороговых значений называют сигналами с состоянием (stateful alerts), и они могут быть настроены как на предупреждающие пороговые значения, так и на критичные. Таким образом, сигналы на основе пороговых значений основаны на метриках, а не событиях. В отличие от старых систем уведомления OEM, сама база данных собирает связанные с сигналами метрики вместо OEM. Предупреждающие и критичные пороговые значения могут быть установлены администратором баз данных или же можно принять внутренние настройки порогов Oracle.

Сигналы Oracle, не связанные с порогами — это сигналы, вызванные проблемами, которые основаны на возникновении в базе данных определенных событий (обычно плохих). В Oracle это называют сигналами без состояния (stateless alerts). Ниже даны некоторые примеры.

• Переполнение пространства области восстановления.
• Приостановка возобновляемого сеанса.
• Устаревший снимок.

Таким образом, существуют три ситуации, когда база данных может посылать сигнал.

• Метрика преодолевает критичное пороговое значение.
• Метрика преодолевает пороговое значение предупреждения.
• Возникновение непорогового (проблемного) типа сигналов.

При использовании сигналов на основе пороговых значений Oracle делает различие между предупреждающим сигналом (уровень серьезности 5) и критичным сигналом (уровень серьезности 1). Например, по умолчанию база данных будет посылать предупреждающий сигнал, когда любое табличное пространство превысит порог в 85% занятого места. Когда использованное пространство достигнет 97%, вы получите критичный сигнал.

Генерируемые сервером сигналы по умолчанию (Oracle Alerts default)

Oracle предлагает несколько генерируемых сервером сигналов по умолчанию, которые могут базироваться как пороговых значениях, так и на возникновении проблем. Ниже перечислены некоторые готовые генерируемые сервером сигналы в Oracle Database 11g.

• Устаревший снимок.
• Использование табличного пространства (предупреждающий сигнал при 85% занятого места и критичный — при 97%).
• Приостановка возобновляемого сеанса.
• Исчерпано свободное место в области восстановления.

На заметку! Oracle автоматически устанавливает пороги на всех метриках объектного типа SYSTEM.

В дополнение к сигналам по умолчанию можно выбирать и другие сигналы, а также изменять пороги сигналов по умолчанию. Эти задачи решаются с помощью OEM Database Control или поставляемых с Oracle пакетов PL/SQL. Средство Database Control можно так-же использовать для установки правил уведомления, например, указать период задержки сигналов, в течение которого никакие сигналы базой данных посылаться не будут.

Когда база выдает сигнал, его можно увидеть в таблице Alerts (Сигналы), показанной на рисунке ниже, которая находится в нижней части домашней страницы Database Control, и вы получите уведомление, только если сконфигурируете систему на его отправку. Данные сигнала по умолчанию обновляются каждые 60 секунд. Чтобы получить подробную информацию о сигнале, щелкните на сообщении в столбце Message (Сообщение) таблицы Alerts. Обычно предупреждения сопровождаются рекомендациями по устранению вызвавшей их проблемы.

Удостоверьтесь в установке параметра STATISTICS_LEVEL равным TYPICAL или ALL, чтобы использовать средство серверной генерации сигналов. В дополнение можно отображать сигналы, непосредственно подписавшись на очередь доставки сигналов.

Oracle alert log — лог сигналов тревоги

В файле alert.log хранится журнал сигналов тревоги и ошибок экземпляра. Многих системных администраторов интересует, где он располагается. Его нахождение задается настройкой background_dump_dest в  файле параметров init[SID].ora. Выполните такой запрос:

SQL> show parameter dump_dest
NAME                    TYPE    VALUE
----------------------- ------- -------------------------------------------
background_dump_dest    string  /u01/app/oracle/diag/rdbms/test/test/trace
core_dump_dest          string  /u01/app/oracle/diag/rdbms/test/test/cdump
user_dump_dest          string  /u01/app/oracle/diag/rdbms/test/test/trace

Также местоположение файла alert log можно узнать из представления  V$PARAMETER:

SQL> SELECT NAME,VALUE 
   2 FROM V$PARAMETER
   3 WHERE NAME = 'background_dump_dest';
NAME                     VALUE
------------------------ -------------------------------------------
background_dump_dest      /u01/app/oracle/diag/rdbms/test/test/trace

Также вы может писать свои сообщения в alert.log:

-- Запись в alert.log
exec dbms_system.ksdwrt
    (2, 'Пример записи в alert.log подготовлен для сайта http://all-oracle.ru');
PL/SQL procedure successfully completed.

-- Очистка буфера
exec dbms_system.ksdfls;
PL/SQL procedure successfully completed.

The Default Oracle Alert Log Location

Oracle alert log location may vary from version to version, and sometimes it’s not easily found. However, it usually locates at 3 locations.

For 11g and later releases (12c, 18c, 19c)

$ORACLE_BASE/diag/rdbms/$DB_UNIQUE_NAME/$ORACLE_SID/trace/

As we can notice, Oracle software divides alert logs to their own dedicated directories according to their database unique names, which is based on directory structure of diagnostic repository.

For 9i and 10g

$ORACLE_BASE/admin/$ORACLE_SID/bdump/

It’s in bdump.

For rest of cases without any clues

$ORACLE_HOME/rdbms/log/

Which is the same way to determine DIAGNOSTIC_DEST.

Filename Format of Alert Log

Even though its location may vary from version to version, the alert log file name is always:

alert_$ORACLE_SID.log

Occasionally, you cannot find the alert log file anywhere. Next, let’s see how we can find it.

3 Ways to Find Oracle Alert Log Location

Here I introduce three ways to find the right Oracle alert log location.

1. Background Dump Destination

If you are a DBA, you can query the value of BACKGROUND_DUMP_DEST, an initialization parameter, where you can find Oracle alert log.

SQL> show parameter background_dump_dest;

Or in this way:

SQL> select value from v$parameter where name = 'background_dump_dest';

In case that you cannot query the database, you can still find the location of alert log at OS-level.

2. Using Find Command

Almost all UNIX and Linux have find command, so using it to find some files is a very common way to do it.

[oracle@test ~]$ find $ORACLE_BASE -type f -name alert_$ORACLE_SID.log
/u01/app/oracle/diag/rdbms/orcl/ORCL/trace/alert_ORCL.log

We find a file named alert_$ORACLE_SID.log starting from $ORACLE_BASE. As we can see, the file was found.

3. Using Locate Command

Sometimes, using locate command will be faster than find to find the path of alert log file.

[oracle@test ~]$ locate alert_$ORACLE_SID.log
/u01/app/oracle/diag/rdbms/orcl/ORCL/trace/alert_ORCL.log

In some databases, the alert logs are big, maybe too big to make room for other files. We have to know ways to reduce the size of alert logs.

For your reference, the ways to find the location of listener log are slightly different from the ways we find Oracle alert log. You can take a look.