Классифицируем ошибки из PostgreSQL-логов10.06.2020 13:32

Посвящается всем любителям анализировать логи.

В логах работающих систем рано или поздно появляются тексты каких-то ошибок. Чем таких систем больше в обозримом пространстве, тем больше вероятность ошибку увидеть. Серверы PostgreSQL, которые находятся под нашим мониторингом ежедневно генерируют от 300K до, в неудачный день, 12M записей об ошибках.

И такие ошибки — это не какой-то там «о, ужас!», а вполне нормальное поведение сложных алгоритмов с высокой степенью конкурентности вроде тех, о которых я рассказывал в статье про расчет себестоимости в СБИС — все эти deadlock, could not obtain lock on row in relation …, canceling statement due to lock timeout как следствие выставленных разработчиком statement/lock timeout.

Но есть ведь и другие виды ошибок — например, you don't own a lock of type ..., которая возникает при неправильном использовании рекомендательных блокировок и может очень быстро «закопать» ваш сервер, или, мало ли, кто-то периодически пытается «подобрать ключик» к нему, вызывая возникновение password authentication failed for user …

qkyr781jndcrofru0piaemvxaqy.png

[источник КДПВ]

Собственно, это все нас подводит к мысли, что если мы не хотим потом хвататься за голову, то возникающие в логах PostgreSQL ошибки недостаточно просто «считать поштучно» — их надо аккуратно классифицировать. Но для этого нам придется решить нетривиальную задачу индексированного поиска регулярного выражения, наиболее подходящего для строки.
Понятно, что можно хранить оригинальный текст всех ошибок и как-то потом обобщать и группировать их «в динамике», но это не очень-то эффективно. Гораздо полезнее оставлять только ссылку на оригинальный формат, плюс аргументы из конкретной строки.

Поскольку разработчики PostgreSQL тоже достаточно разумные ребята, все вызовы форматирования строки ошибки сделаны через единую функцию errmsg.

На самом деле, это не совсем правда, и полный список выглядит чуть шире:
elog, errmsg, psql_error, gettext_noop, GUC_check_errmsg

Если мы будем иметь возможность разбора строки ошибки «по формату», то вместо текста сможем хранить лишь ID формата и переменную часть (если она присутствует). Очевидно, что это занимает меньше места, чем полная строка. Плюсом, мы получаем ту самую возможность группировки по формату.

Шаг №1: собираем форматы


Тут все просто — идем в официальный репозиторий PostgreSQL, качаем исходники, парсим, получаем форматы. Звучит просто, на деле же нам потребуется доступ к GitHub API (и чтобы им не злоупотреблять, мы постараемся соблюдать паузы 10ms между запросами, а вот распараллеливанием работы заниматься не будем) и немного RegExp-магии: 

const util   = require('util');
// npm install async github-api
const async  = require('async');
const GitHub = require('github-api');

// сюда будем складывать все промежуточные результаты
let scheduler = {
  'path' : []
, 'file' : []
, 'msgs' : []
};

// timestamp последнего запроса
let tsReq;

// потребуются ваши user/pass на github
let gh = new GitHub({
  username : 'foo'
, password : 'bar'
});

// подключаемся к репозиторию
let repo = gh.getRepo('postgres/postgres');

async.series([
  cb => {
    // заносим в очередь пути до всех релизных веток и master
    repo.listBranches((err, res) => {
      if (err) {
        console.log(util.inspect(err));
      }
      else {
        // можно не качать все-все версии, а ограничиться только теми, которые у вас реально присутствуют
        scheduler.path = [
          ...res.map(obj => obj.name).filter(name => name.endsWith('_STABLE'))
        , 'master'
        ].map(name => name + ':');
      }
      return cb(err);
    });
  }
, cb => {
    // сканируем всю структуру веток "в глубину", отбирая файлы *.c/*.l
    async.whilst(
      cb => cb(null, scheduler.path.length)
    , cb => {
        let _path = scheduler.path.shift();

        console.log('now scanned : ' + _path);

        let [ref, path] = _path.split(':');
        tsReq = Date.now();
        repo.getContents(ref, path, false, (err, res) => {
          if (err) {
            console.log(util.inspect(err));
            scheduler.path.unshift(_path);
            setTimeout(() => cb(), 1000); // sleep
            return;
          }
          else {
            scheduler.path = scheduler.path.concat(
              res
                .filter(item => item.type == 'dir')
                .map(item => ref + ':' + item.path)
            );
            scheduler.file = scheduler.file.concat(
              res
                .filter(item => item.type == 'file' && /\.(c|l)$/.test(item.path)) // .c | .l
                .map(item => ref + ':' + item.path)
            );

            let lag = Date.now() - tsReq;
            setTimeout(() => cb(), lag >= 10 ? 0 : 10 - lag); // API rate
          }
        });
      }
    , (err, n) => cb(err)
    );
  }
, cb => {
    // выкачиваем содержимое всех найденных файлов и вырезаем форматные строки
    const RE_ERR = ['elog', 'errmsg', 'psql_error', 'gettext_noop', 'GUC_check_errmsg']
      .map(func => '(?:\\W)' + func + '\\((?:\\w+,|)[\\s\\n]*"(.*?[^\\\\])"((?:\\s*\\n\\s*"(.*?[^\\\\])")*)[,\\)]')
      .map(re => ({
        g : RegExp(re, 'gm')
      , l : RegExp(re)
      }));
    const RE_SPC = RegExp('\\s*\\n\\s*"(.*?[^\\\\])"', 'g');

    scheduler.file.sort();

    async.whilst(
      cb => cb(null, scheduler.file.length)
    , cb => {
        let _path = scheduler.file.shift();

        console.log('now parsed : ' + _path);

        let [ref, path] = _path.split(':');
        tsReq = Date.now();
        repo.getContents(ref, path, false, (err, res) => {
          if (err) {
            console.log(util.inspect(err));
            scheduler.file.unshift(_path);
            setTimeout(() => cb(), 1000); // sleep
            return;
          }
          else {
            let str = Buffer.from(res.content, 'base64').toString();

            let errs = RE_ERR.reduce((rv, re) => rv.concat(
              (str.match(re.g) || [])
                .map(s => {
                  re.l.exec(s);
                  let re1 = RegExp.$1
                    , re2 = RegExp.$2;
                  if (re2) {
                    re2 = re2.replace(RE_SPC, '$1');
                  }

                  return (re1 + (re2 ? re2 : '')).replace(/\\"/g, '"');
                })
            ), []);

            let msgs = [...new Set(errs)]; // избавляемся от дублей

            if (msgs.length) {
              console.log(msgs);
              scheduler.msgs.push(msgs);
            }

            let lag = Date.now() - tsReq;
            setTimeout(() => cb(), lag >= 10 ? 0 : 10 - lag); // API rate
          }
        });
      }
    , (err, n) => cb(err)
    );
  }
, cb => {
    // готовим в errmsg.sql итоговый запрос для вставки, уникализируя форматы
    let sql = ['INSERT INTO dicerrmsg(message) VALUES\n  '];
    sql.push(
      [...new Set(scheduler.msgs.reduce((rv, arr) => rv.concat(arr), []))]
        .map(msg => "(E'" + msg.replace(/'/g, "''") + "')")
        .join('\n, ')
    );
    sql.push('\n;\n');
    require('fs').writeFileSync('errmsg.sql', sql.join(''));
    return cb(null);
  }
]);


На данный момент со всех версий получается чуть больше 14K форматов.

Шаг №2: словарь форматов


Маленькая неприятность — форматы описаны в терминах printf-подстановок. То есть получаем что-то вроде:

syntax error at or near "%s"
cursor "%s" does not exist
block number %u is out of range for relation "%s"
could not parse value "%s" for parameter "%s"

С такими форматами работать не очень удобно, поэтому приведем каждый из них в вид, который нам поможет быстро определять формат по строке и отображать подстановки переменных: 

CREATE TABLE dicerrmsg(
  errmsg
    serial
      PRIMARY KEY
, message  -- оригинальный формат
    varchar
      UNIQUE
, regexp   -- проверяющее регулярное выражение
    varchar
, template -- шаблон для подстановки аргументов
    varchar
, prefix   -- префикс до первой подстановки
    varchar
);
-- индекс для префиксного поиска префиксов :)
CREATE INDEX ON dicerrmsg(prefix varchar_pattern_ops);


Должно получиться что-то типа этого:

vaylwpddkou-3qpnkrw0jqazo1k.png


В этом нам поможет триггер на вставку в таблицу: 

CREATE OR REPLACE FUNCTION errins() RETURNS trigger AS $$
BEGIN
  -- защита от повторной перезаливки через COPY
  PERFORM
    NULL
  FROM
    dicerrmsg
  WHERE
    message = NEW.message
  LIMIT 1;
  IF FOUND THEN
    RETURN NULL;
  END IF;
  -- рекурсивно находим и подменяем все printf-подстановки на regexp-формат
  -- http://www.cplusplus.com/reference/cstdio/printf/
  WITH RECURSIVE rpl AS (
    SELECT
      row_number() OVER() rn
    , *
    FROM
      (
        VALUES
          ('%%',      E'\1%\1')
        , ('%d',      E'(-?\\d+)')
        , ('%02d',    E'(-?\\d{2})')
        , ('%3d',     E'(-?\\d{3})')
        , ('%03d',    E'(-?\\d{3})')
        , ('%ld',     E'(-?\\d+)')
        , ('%i',      E'(-?\\d+)')
        , ('%u',      E'(\\d+)')
        , ('%lu',     E'(\\d+)')
        , ('%zu',     E'(\\d+)')
        , ('%o',      E'([0-7]+)')
        , ('%x',      E'([0-9a-f]+)')
        , ('%2x',     E'([0-9a-f]{2})')
        , ('%02x',    E'([0-9a-f]{2})')
        , ('%X',      E'([0-9A-F]+)')
        , ('%02X',    E'([0-9A-F]{2})')
        , ('%08X',    E'([0-9A-F]{8})')
        , ('%f',      E'(-?\\d+(?:\\.\\d+)?)')
        , ('%\\.0f',  E'(-?\\d+)')
        , ('%\\.1f',  E'(-?\\d+\\.\\d{1})')
        , ('%\\.2f',  E'(-?\\d+\\.\\d{2})')
        , ('%\\.3f',  E'(-?\\d+\\.\\d{3})')
        , ('%e',      E'(-?\\d+(?:\\.\\d+)?e[-+]\\d+)')
        , ('%02g',    E'(-?\\d{2})')
        , ('%g',      E'(-?\\d+(?:\\.\\d+)?|-?\\d+(?:\\.\\d+)?e[-+]\\d+)')
        , ('%c',      E'(.*)')
        , ('%s',      E'(.*)')
        , ('%\\.32s', E'(.{32})')
        , ('%\\.*s',  E'(.*)')
        , ('%p',      E'([0-9a-f]{8})')
        , ('%m',      E'(.*)')
      ) T(token, re)
  )
  , T AS (
    SELECT
      0 lvl
    , '^' ||
      regexp_replace(
        regexp_replace(
          regexp_replace(
            regexp_replace(
              NEW.message
            , '\r'
            , '\\r'
            , 'g'
            )
          , '\n'
          , '\\n'
          , 'g'
          )
        , '\t'
        , '\\t'
        , 'g'
        )
      , '([\(\)\[\]\{\}\^\$\.\+\-\?\|\\])'
      , '\\\1'
      , 'ig'
      )
      || '$' str
    , NEW.message tmp
  UNION ALL
    SELECT
      T.lvl + 1 lvl
    , regexp_replace(str, rpl.token, rpl.re, 'g') str
    , regexp_replace(tmp, rpl.token, E'\1', 'g') tmp
    FROM
      T
    JOIN
      rpl
        ON T.lvl + 1 = rpl.rn
  )
  -- формируем regexp, шаблон отображения и префикс по итогу последней подстановки
  SELECT
    regexp_replace(str, E'\1%\1', '%', 'g') str
  , regexp_replace(tmp, E'\1%\1', '%', 'g') tmp
  , regexp_replace(
      regexp_replace(tmp, E'\1%\1', '%', 'g')
    , E'\1.*$'
    , ''
    ) prf
  INTO
    NEW.regexp
  , NEW.template
  , NEW.prefix
  FROM
    T
  ORDER BY
    lvl DESC
  LIMIT 1;
  -- 
  RETURN NEW;
END;
$$ LANGUAGE plpgsql;

CREATE TRIGGER ins BEFORE INSERT ON dicerrmsg
  FOR EACH ROW
  EXECUTE PROCEDURE errins();


Внимательный взгляд уже заметил на предыдущей картинке, что в таблице у нас помимо оригинального формата и regexp лежат еще два поля: разбитая на сегменты строка и константный префикс. Строку мы используем в интерфейсе для красивого отображения, а вот с префиксом все интереснее…

Префикс — это тот «фиксированный» текст, который должен присутствовать в начале строки, чтобы она могла быть отнесена к данному формату. То есть текст формата до позиции первой подстановки:

Берем формат: block number %u is out of range for relation "%s"
Получаем: block number


Шаг №3: разбор ошибки по форматам


В большинстве случаев формат определяется, но бывают и «неформатные» ошибки — например, результат явно сгенерированного разработчиком RAISE ERROR. Для таких мы держим в базе отдельное поле с полным текстом — обычно там NULL, поэтому практически ничего не «стоит» для хранения. Если же мы определили формат — сохраняем его ID и массив подставляемых параметров: 

CREATE TABLE err(
-- ...
, errpos  -- позиция ошибки, если в тексте есть "... at position 123"
    integer
, errmsg  -- ID формата
    integer
, errargs -- массив параметров
    text[]
, error   -- почти всегда пустой "неформатный" текст
    varchar
);


Заранее мы не знаем, присутствует ли вообще в строке с ошибкой какая-то подстановка и где она начинается, если все-таки она там есть. И если индексный поиск строк по regexp существует в pg_trgm еще с версии 9.3, то для обратной задачи поиска наиболее подходящего regexp для строки алгоритм придется реализовать нам самим.

Какие вообще возможны варианты при разборе строки по набору форматов?

Совпадающие префиксы


Префикс какого-то формата полностью совпал с нашей строкой ошибки. Тогда нам надо всего лишь убедиться, что наша строка подходит под полный regexp. И из подходящих выбрать формат наибольшей длины (чтобы у нас не выбирался постоянно формат »%s», например).

«Мы делили апельсин…»


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

Ну что ж… Префикс неизвестен, его длина неизвестна, но длина строки-то нам известна! Что в таких случаях рекомендуют классики? Дихотомию!

Вывернем задачу наизнанку:

  1. Ищем по началу строки текущей длины префиксы в базе префиксным поиском. :)
    Для этого нам понадобится тот самый индекс с varchar_pattern_ops, который позволяет делать поиски по LIKE 'anystr%'.
  2. Если не нашли ничего — длину префикса строки надо уменьшить в соответствии с шагом дихотомии.
  3. Если нашли — увеличить длину префикса.
  4. Если наконец получилось, что для префикса длины N форматы находятся, а для длины N+1 уже ни одного, то берем найденные для N и анализируем по первому варианту совпадающих префиксов.


На примере:

>> исходная строка [1:54]: 'block number 12345 is out of range for relation "test"'
<< ничего
>> уменьшили [1:27]: 'block number 12345 is out o'
<< ничего
>> уменьшили [1:13]: 'block number '
<< нашли 2: 'block number ' и 'block number out of range'
>> увеличили [1:20]: 'block number 12345 i'
<< ничего
…
>> уменьшили [1:14]: 'block number 1'
<< ничего

значит, берем вариант от [1:13] и по regexp проверяем, что подходящий — 'block number %u is out of range for relation "%s"'


А вот как это выглядит в виде триггера на вставку в таблицу ошибок: 

CREATE OR REPLACE FUNCTION errfmt() RETURNS trigger AS $$
DECLARE
  repos varchar = E'^(.*) at (?:character|position) (\\d+)$';
  err dicerrmsg;
  matches text[];
BEGIN
  -- отсекаем позицию
  IF NEW.error ~ repos THEN
    SELECT
      rm[1]
    , rm[2]::integer
    INTO
      NEW.error
    , NEW.errpos
    FROM
      regexp_matches(NEW.error, repos) rm
    LIMIT 1;
  END IF;

  WITH RECURSIVE orig AS (
    SELECT
      NEW.error str
  )
  , T AS (
    SELECT
      0 i
    , str chk
    , NULL::varchar pfx
    , ARRAY[1, length(str), length(str)] rng
    FROM
      orig
  UNION ALL
    SELECT
      i + 1
      -- шаг #0: формируем проверяемый префикс
    , CASE
        WHEN i % 3 = 0 THEN
          substr((TABLE orig), 1, rng[2])
        ELSE
          chk
      END
      -- шаг #1: находим любой из подходящих форматов
    , CASE
        WHEN i % 3 = 1 THEN
          (
            SELECT
              prefix
            FROM
              dicerrmsg
            WHERE
              prefix ~>=~ chk AND
              prefix ~<~ (chk || chr(255))
            LIMIT 1
          )
        ELSE
          pfx
      END
      -- шаг #2: движение дихотомии
    , CASE
        WHEN i % 3 = 2 THEN
          CASE
            -- уменьшаем слишком длинный префикс, по которому ничего не найдено
            WHEN pfx IS NULL THEN
              ARRAY[rng[1], (rng[1] + rng[2]) >> 1, rng[2]]
            -- найденный префикс формата подходит в качестве префикса всей строки
            WHEN starts_with((TABLE orig), pfx) THEN
              ARRAY[length(pfx), (length(pfx) + rng[3]) >> 1, rng[3]]
            -- увеличиваем длину префикса
            ELSE
              ARRAY[rng[2], (rng[2] + rng[3]) >> 1, rng[3]]
          END
        ELSE
          rng
      END
    FROM
      T
    WHERE
      rng[1] < rng[2]
  )
  -- отбираем самый последний префикс, для которого еще был формат
  , pre AS (
    SELECT
      *
    FROM
      T
    WHERE
      pfx IS NOT NULL
    ORDER BY
      i DESC
    LIMIT 1
  )
  -- отбираем наиболее подходящий формат по этому префиксу
  SELECT
    Q.*
  INTO
    err
  FROM
    pre
  , orig
  , LATERAL(
      SELECT
        *
      FROM
        dicerrmsg
      WHERE
        prefix = pfx AND
        str ~ regexp -- фильтруем по совпадению регулярки
    ) Q
  ORDER BY
    length(Q.template) DESC -- выбираем по самой длинной "константной" части
  LIMIT 1;
  
  -- для полученного формата с помощью его regexp выделяем аргументы
  IF err.errmsg IS NOT NULL THEN
    NEW.errmsg = err.errmsg;
    SELECT
      rm
    INTO
      matches
    FROM
      regexp_matches(NEW.error, err.regexp) rm
    LIMIT 1;
    IF array_length(matches, 1) > 1 OR matches[1] <> NEW.error THEN
      NEW.errargs = matches;
    END IF;
    NEW.error = NULL;
  END IF;
  RETURN NEW;
END;
$$ LANGUAGE plpgsql;

CREATE TRIGGER ins BEFORE INSERT ON err
  FOR EACH ROW
  EXECUTE PROCEDURE errfmt();


Давайте убедимся на примере выше, что наш основной поисковый запрос получился вовсе не «тяжелым»:

ghqhoncp33xvxtipf3hkdhw9dzu.png
[посмотреть на explain.tensor.ru]

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

mb0xkhbvdedlg6moo5tmd-a9vke.png

© Habrahabr.ru