Разрабатываем самый удобный в мире* интерфейс для просмотра логов

Если Вам приходилось когда-нибудь пользоваться веб-интерфейсами для просмотра логов, то Вы наверняка замечали, насколько, как правило, эти интерфейсы громоздки и (зачастую) не слишком-то удобны и отзывчивы. К некоторым можно привыкнуть, некоторые совсем ужасны, но, как мне кажется, причина всех проблем заключается в том, что мы неправильно подходим к задаче просмотра логов: мы пытаемся создать веб-интерфейс там, где лучше работает CLI (интерфейс командной строки). Мне лично очень комфортно работать с tail, grep, awk и прочими, и поэтому для меня идеальным интерфейсом для работы с логами было бы что-то аналогичное tail и grep, но которое при этом можно было использовать для чтения логов, которые пришли с множества серверов. То есть, конечно же, читать их из ClickHouse!

*по личному мнению хабрапользователя youROCK

Встречайте logscli

Я не придумал названия своему интерфейсу, и, сказать честно, он скорее существует в виде прототипа, но если Вы хотите сразу посмотреть исходники, то добро пожаловать: https://github.com/YuriyNasretdinov/logscli (350 строк отборного кода на Go).

Возможности

Я ставил перед собой цель сделать интерфейс, который будет казаться знакомым тем, кто привык к tail/grep, то есть поддерживать следующие вещи:

1. Просмотр всех логов, без фильтрации.
2. Оставить строки, в которых содержится фиксированная подстрока (флаг -F у grep).
3. Оставить строки, подходящие под регулярное выражение (флаг -E у grep).
4. По умолчанию просмотр в обратном хронологическом порядке, поскольку обычно в первую очередь интересны самые свежие логи.
5. Показ контекста возле каждой строки (параметры -A, -B и -C у grep, печатающие N строк до, после, и вокруг каждой совпадающей строки соответственно).
6. Просмотр поступающих логов в режиме реального времени, с фильтрацией и без (по сути tail -f | grep).
7. Интерфейс должен быть совместим с less, head, tail и прочими — по умолчанию должны возвращаться результаты без ограничений по их количеству; строки печатаются потоково до тех пор, пока пользователь заинтересован в их получении; сигнал SIGPIPE должен молча прерывать стриминг логов, также, как это делают tail, grep и остальные UNIX-утилиты.

Реализация

Я буду предполагать, что вы уже каким-то образом умеете доставлять логи до ClickHouse. Если нет, то рекомендую попробовать lsd и kittenhouse, а также эту статью про доставку логов.

Для начала нужно определиться со схемой базы. Поскольку логи обычно хочется получать отсортированными по времени, то представляется логичным так их и хранить. Если категорий логов много и они все однотипные, то можно в качестве первой колонки первичного ключа сделать категорию логов — это позволит иметь одну таблицу вместо нескольких, что при вставке в ClickHouse будет большим плюсом (на серверах с жёсткими дисками рекомендуется вставлять данные не чаще ~1 раза в секунду на весь сервер).

То есть, нам нужна примерно следующая схема таблиц:

CREATE TABLE logs(
    category LowCardinality(String), -- категория логов (опционально)
    time DateTime, -- время события
    millis UInt16, -- миллисекунды (могут быть и микросекунды, и т.д.): рекомендуется хранить, если событий много, чтобы было легче различать события между собой
    ..., -- ваши собственные поля, например имя сервера, уровень логирования, и так далее
    message String -- текст сообщения
) ENGINE=MergeTree()
ORDER BY (category, time, millis)

К сожалению, я не смог сразу найти каких-либо открытых источников с реалистичными логами, которые можно было бы взять и скачать, поэтому я взял вместо этого для примера отзывы от товарах из Amazon до 2015 года. Безусловно, их структура не совсем такая же, как у текстовых логов, но для иллюстрации это не принципиально.

CREATE TABLE amazon(
   review_date Date,
   time DateTime DEFAULT toDateTime(toUInt32(review_date) * 86400 + rand() % 86400),
   millis UInt16 DEFAULT rand() % 1000,
   marketplace LowCardinality(String),
   customer_id Int64,
   review_id String,
   product_id LowCardinality(String),
   product_parent Int64,
   product_title String,
   product_category LowCardinality(String),
   star_rating UInt8,
   helpful_votes UInt32,
   total_votes UInt32,
   vine FixedString(1),
   verified_purchase FixedString(1),
   review_headline String,
   review_body String
)
ENGINE=MergeTree()
ORDER BY (time, millis)
SETTINGS index_granularity=8192

for i in *.tsv; do
    echo $i;
    tail -n +2 $i | pv |
    clickhouse-client --input_format_allow_errors_ratio 0.5 --query='INSERT INTO amazon(marketplace,customer_id,review_id,product_id,product_parent,product_title,product_category,star_rating,helpful_votes,total_votes,vine,verified_purchase,review_headline,review_body,review_date) FORMAT TabSeparated'
done

Все иллюстрации я буду производить именно с этим датасетом, поскольку это всё, что у меня было под рукой.

Показ прогресса сканирования данных

Поскольку в ClickHouse мы будем использовать full scan по таблице с логами, а эта операция может занимать существенное время и долго не отдавать никаких результатов, если совпадений найдено мало, желательно уметь показывать прогресс выполнения запроса до получения первых строк с результатом. Для этого в HTTP-интерфейсе есть параметр, позволяющий отдавать прогресс в заголовках HTTP: send_progress_in_http_headers=1. К сожалению, стандартная библиотека Go не умеет читать заголовки по мере их получения, но интерфейс HTTP 1.0 (не путайте с 1.1!) поддерживается ClickHouse, поэтому можно открыть сырое TCP-соединение с ClickHouse, послать туда GET /?query=... HTTP/1.0nn и получить в ответ заголовки и тело ответа без какого-либо экранирования и шифрования, так что нам в этом случае стандартную библиотеку использовать даже не требуется.

Стриминг логов из ClickHouse

В ClickHouse уже относительно давно (с 2019 года?) есть оптимизация для запросов с ORDER BY, так что запрос вида

SELECT time, millis, message
FROM logs
WHERE message LIKE '%something%'
ORDER BY time DESC, millis DESC

Начнет сразу возвращать строки, у которых в message есть подстрока "something", не дожидаясь окончания сканирования.

Также, было бы очень удобно, если бы ClickHouse сам отменял запрос, когда с ним закрыли соединение, но это не является поведением по умолчанию. Автоматическую отмену запроса можно включить опцией cancel_http_readonly_queries_on_client_close=1.

Корректная обработка SIGPIPE в Go

Когда Вы выполняете, скажем, команду some_cmd | head -n 10, каким именно образом команда some_cmd прекращает свое исполнение, когда head вычитал 10 строк? Ответ прост: когда head завершается, pipe закрывается, и stdout команды some_cmd начинает указывать, условно, «вникуда». Когда some_cmd пытается записать в закрытый pipe, ей приходит сигнал SIGPIPE, который по умолчанию молча завершает программу.

В Go по умолчанию это тоже происходит, но обработчик сигнала SIGPIPE в конце также печатает "signal: SIGPIPE" или похожее сообщение, и чтобы это сообщение убрать, нужно просто самому обработать SIGPIPE так, как мы хотим, то есть просто молча выйти:

ch := make(chan os.Signal)
signal.Notify(ch, syscall.SIGPIPE)
go func() {
    <-ch
    os.Exit(0)
}()

Показ контекста сообщения

Часто хочется увидеть контекст, в котором произошла какая-то ошибка (например, какой запрос вызвал панику, или какие сопутствующие проблемы были видны до падения), и в grep для этого служат опции -A, -B и -C, которые показывают указанное число строк после, до, и вокруг сообщения соответственно.

К сожалению, я не нашел простого способа сделать то же самое в ClickHouse, поэтому, для отображения контекста, на каждую строчку результата посылается дополнительный запрос примерно следующего вида (детали зависят от сортировки и от того, показывается контекст до или после):

SELECT time,millis,review_body FROM amazon
WHERE (time = 'ВРЕМЯ_СОБЫТИЯ' AND millis < МИЛЛИСЕКУНДЫ_СОБЫТИЯ) OR (time < 'ВРЕМЯ_СОБЫТИЯ')
ORDER BY time DESC, millis DESC
LIMIT КОЛИЧЕСТВО_СТРОК_КОНТЕКСТА
SETTINGS max_threads=1

Поскольку запрос посылается почти сразу после того, как ClickHouse вернул соответствующую строку, она попадает в кеш и в целом запрос выполняется достаточно быстро и тратит немножко CPU (обычно запрос занимает около ~6 мс на моей виртуалке).

Показ новых сообщений в режиме реального времени

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

Примеры команд

Как выглядят типичные команды logscli на практике?

Если Вы загрузили датасет Amazon, который я упоминал в начале статьи, то сможете выполнить следующие команды:

# Показать строки, где встречается слово walmart
$ logscli -F 'walmart' | less

# Показать самые свежие 10 строк, где встречается "terrible"
$ logscli -F terrible -limit 10

# То же самое без -limit:
$ logscli -F terrible | head -n 10

# Показать все строки, подходящие под /times [0-9]/, написанные для vine и у которых высокий рейтинг
$ logscli -E 'times [0-9]' -where="vine='Y' AND star_rating>4" | less

# Показать все строки со словом "panic" и 3 строки контекста вокруг
$ logscli -F 'panic' -C 3 | less

# Непрерывно показывать новые строки со словом "5-star"
$ logscli -F '5-star' -tailf

Ссылки

Код утилиты (без документации) доступен на github по адресу https://github.com/YuriyNasretdinov/logscli. Буду рад услышать Ваши мысли по поводу моей идеи для консольного интерфейса для просмотра логов на основе ClickHouse.

Автор: Юрий Насретдинов

Источник