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

Если Вам приходилось когда-нибудь пользоваться веб-интерфейсами для просмотра логов, то Вы наверняка замечали, насколько, как правило, эти интерфейсы громоздки и (зачастую) не слишком-то удобны и отзывчивы. К некоторым можно привыкнуть, некоторые совсем ужасны, но, как мне кажется, причина всех проблем заключается в том, что мы неправильно подходим к задаче просмотра логов: мы пытаемся создать веб-интерфейс там, где лучше работает 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.0\n\n и получить в ответ заголовки и тело ответа без какого-либо экранирования и шифрования, так что нам в этом случае стандартную библиотеку использовать даже не требуется.

Стриминг логов из 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.