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

В логах работающих систем рано или поздно появляются тексты каких-то ошибок. Чем таких систем больше в обозримом пространстве, тем больше вероятность ошибку увидеть. Серверы 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 …

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

Собственно, это все нас подводит к мысли, что если мы не хотим потом хвататься за голову, то возникающие в логах 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); 

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

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

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();

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

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

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