Посвящается всем любителям анализировать логи.
В логах работающих систем рано или поздно появляются тексты каких-то ошибок. Чем таких систем больше в обозримом пространстве, тем больше вероятность ошибку увидеть. Серверы PostgreSQL, которые находятся под нашим мониторингом ежедневно генерируют от 300K до, в неудачный день, 12M записей об ошибках.
И такие ошибки — это не какой-то там «о, ужас!», а вполне нормальное поведение сложных алгоритмов с высокой степенью конкурентности вроде тех, о которых я рассказывал в статье про расчет себестоимости в СБИС — все эти deadlock,
Но есть ведь и другие виды ошибок — например,
[источник КДПВ]
Собственно, это все нас подводит к мысли, что если мы не хотим потом хвататься за голову, то возникающие в логах PostgreSQL ошибки недостаточно просто «считать поштучно» — их надо аккуратно классифицировать. Но для этого нам придется решить нетривиальную задачу индексированного поиска регулярного выражения, наиболее подходящего для строки.
Понятно, что можно хранить оригинальный текст всех ошибок и как-то потом обобщать и группировать их «в динамике», но это не очень-то эффективно. Гораздо полезнее оставлять только ссылку на оригинальный формат, плюс аргументы из конкретной строки.
Поскольку разработчики PostgreSQL тоже достаточно разумные ребята, все вызовы форматирования строки ошибки сделаны через единую функцию
Тут все просто — идем в официальный репозиторий PostgreSQL, качаем исходники, парсим, получаем форматы. Звучит просто, на деле же нам потребуется доступ к GitHub API (и чтобы им не злоупотреблять, мы постараемся соблюдать паузы 10ms между запросами, а вот распараллеливанием работы заниматься не будем) и немного RegExp-магии:
На данный момент со всех версий получается чуть больше 14K форматов.
Маленькая неприятность — форматы описаны в терминах printf-подстановок. То есть получаем что-то вроде:
Должно получиться что-то типа этого:
В этом нам поможет триггер на вставку в таблицу:
Внимательный взгляд уже заметил на предыдущей картинке, что в таблице у нас помимо оригинального формата и regexp лежат еще два поля: разбитая на сегменты строка и константный префикс. Строку мы используем в интерфейсе для красивого отображения, а вот с префиксом все интереснее…
Префикс — это тот «фиксированный» текст, который должен присутствовать в начале строки, чтобы она могла быть отнесена к данному формату. То есть текст формата до позиции первой подстановки:
В большинстве случаев формат определяется, но бывают и «неформатные» ошибки — например, результат явно сгенерированного разработчиком
Заранее мы не знаем, присутствует ли вообще в строке с ошибкой какая-то подстановка и где она начинается, если все-таки она там есть. И если индексный поиск строк по regexp существует в pg_trgm еще с версии 9.3, то для обратной задачи поиска наиболее подходящего regexp для строки алгоритм придется реализовать нам самим.
Какие вообще возможны варианты при разборе строки по набору форматов?
Префикс какого-то формата полностью совпал с нашей строкой ошибки. Тогда нам надо всего лишь убедиться, что наша строка подходит под полный regexp. И из подходящих выбрать формат наибольшей длины (чтобы у нас не выбирался постоянно формат "%s", например).
Если же с префиксом совпадает только часть строки, то тут сложнее, ведь мы вообще не знаем, где в нашей входной строке кончается префикс и начинается подставленный параметр.
Ну что ж… Префикс неизвестен, его длина неизвестна, но длина строки-то нам известна! Что в таких случаях рекомендуют классики? Дихотомию!
Вывернем задачу наизнанку:
На примере:
А вот как это выглядит в виде триггера на вставку в таблицу ошибок:
Давайте убедимся на примере выше, что наш основной поисковый запрос получился вовсе не «тяжелым»:
[посмотреть на explain.tensor.ru]
А когда мы все ошибки аккуратно «разложили по полочкам», можно их подходящим образом сгруппировать по форматам и наборам аргументов и показать для дальнейшей зачистки:
В логах работающих систем рано или поздно появляются тексты каких-то ошибок. Чем таких систем больше в обозримом пространстве, тем больше вероятность ошибку увидеть. Серверы 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
.На самом деле, это не совсем правда, и полный список выглядит чуть шире:Если мы будем иметь возможность разбора строки ошибки «по формату», то вместо текста сможем хранить лишь ID формата и переменную часть (если она присутствует). Очевидно, что это занимает меньше места, чем полная строка. Плюсом, мы получаем ту самую возможность группировки по формату.
elog, errmsg, psql_error, gettext_noop, GUC_check_errmsg
Шаг №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", например).
«Мы делили апельсин...»
Если же с префиксом совпадает только часть строки, то тут сложнее, ведь мы вообще не знаем, где в нашей входной строке кончается префикс и начинается подставленный параметр.
Ну что ж… Префикс неизвестен, его длина неизвестна, но длина строки-то нам известна! Что в таких случаях рекомендуют классики? Дихотомию!
Вывернем задачу наизнанку:
- Ищем по началу строки текущей длины префиксы в базе префиксным поиском. :)
Для этого нам понадобится тот самый индекс с varchar_pattern_ops, который позволяет делать поиски поLIKE 'anystr%'
. - Если не нашли ничего — длину префикса строки надо уменьшить в соответствии с шагом дихотомии.
- Если нашли — увеличить длину префикса.
- Если наконец получилось, что для префикса длины 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)) AND
(TABLE orig) ~ regexp
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]
А когда мы все ошибки аккуратно «разложили по полочкам», можно их подходящим образом сгруппировать по форматам и наборам аргументов и показать для дальнейшей зачистки: