[prog.experience] Маленькая история про улучшение навигации по логам в arataga

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

Если кто-то не в курсе, то arataga -- это прототип производительного прокси-сервера, который мы делали для одного клиента, пока этот самый клиент не потерял интерес к данной разработке.

Пару месяцев назад представилась возможность погонять arataga под реальной нагрузкой. Чем мы с удовольствием воспользовались. Выявили несколько косяков, кое что поменяли. Но, в общем, в очередной раз убедились, что arataga работает.

Поскольку нагрузка создавалась не тестовыми программами, а реальными клиентами, трафик которых был пущен через arataga, то мы столкнулись с рядом особенностей в реализации SOCKS/HTTP-протоколов. И для разбирательства с тем, правильно ли arataga ведет себя в тех или иных ситуациях, потребовалось шерстить логи.

Грубо говоря, ищешь в логе ситуацию, помеченную как WARN или ERR, а затем смотришь, что предшествовало и/или следовало за этой ситуацией.

Потребовалось легко и быстро находить строки лога, описывающие то соединение, с которым тебе нужно разобраться.

Изначально казалось, что каждая строка лога содержит достаточное количество информации для идентификации конкретного подключения. Вот, например:

[2021-04-16 08:43:02.756] [arataga] [error] socks-3001-192.168.1.178-io_thr_1-v1: connection (3001,38) => socks5: PDU with auth methods too long, methods: 1, bytes read: 22
[2021-04-16 08:43:02.756] [arataga] [debug] socks-3001-192.168.1.178-io_thr_1-v1: connection (3001,38) removed (protocol_error), connections: 0/200

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

• socks-3001-192.168.1.178-io_thr_1-v1 -- это имя агента, который обслуживает конкретную точку входа. Имя составное и сообщает максимум информации об этой точке входа и об агенте: socks -- говорит о точке входа по протоколу SOCKS, точка входа открыта на порту 3001 адреса 192.168.1.178, точка входа привязана к io_thread с порядковым номером 1. Ну и это первая версия данного агента (если агент пересоздается в результате изменения конфигурации, то номер его версии будет увеличиваться);
• (3001,38) -- это идентификатор соединения внутри конкретной точки входа (38-ое соединение на порту 3001).

По идее, если искать подстроки "socks-3001-192.168.1.178-io_thr_1-v1" и "(3001,38)", то в логе будет найдено все, что касается данного конкретного подключения на данной конкретной точке входа.

Проблема, однако, в том, что искать по двум подстрокам не удобно. Гораздо удобнее искать всего одну подстроку. А именно "(3001,38)" вместо "socks-3001-192.168.1.178-io_thr_1-v1".

Это проблема проявилась практически сразу, еще когда мы сами занимались отладкой первых версий arataga на собственных тестовых стендах. Собственно, поэтому и появилась в логе отдельная связка из номера порта и номера соединения на этом порту (та самая подстрока вида "(3001,38)"). Это помогало нам в нашей автономной отладке, т.к. у нас не было повторений номеров портов на точках входа.

Но когда arataga поработала под реальной нагрузкой в условиях, когда есть сотни точек входа с одинаковым номером TCP-порта (на разных IP-адресах), то выяснилось, что подстроки вида "(3001,38)" уже не позволяют легко отыскивать все, что касается конкретного подключения. Слишком уж много оказывалось вхождений "(3001,38)", относящихся к совсем другим точкам входа.

Поэтому arataga была немного доработана дла того, чтобы от пары (порт, номер соединения) перейти к триплету (уникальный ID, порт, номер соединения), где "уникальный ID" был бы неким более коротким и удобным синонимом для "socks-3001-192.168.1.178-io_thr_1-v1".

В результате сейчас в arataga записи в логе имеют вид:

[2021-04-29 09:04:34.558] [arataga] [error] http-5500-192.168.1.161-io_thr_0-v1: connection (6498_2185,5500,6) => update request-target failure: unable to parse request-target, http_parser_parse_url result: 1

Где подстрока "(6498_2185,5500,6)" уже однозначно указывает на строчки лога, относящиеся к конкретному соединению на конкретной точке входа (уникальный ID вида "6498_2185" назначен агенту "http-5500-192.168.1.161-io_thr_0-v1" при его создании):

[2021-04-29 09:04:33.981] [arataga] [info] http-5500-192.168.1.161-io_thr_0-v1: created, acl_id_seed: 6498_2185

---

Пора переходить к итогу и к морали.

Итог простой -- после того, как в arataga каждое соединение начало идентифицироваться не парой из (порт, номер соединения), а триплетом (уникальный ID, порт, номер соединения), то отыскивать в логах информацию, относящуюся к конкретному подключению, стало гораздо проще.

Мораль номер раз. При начале реальной эксплуатации обязательно возникнет необходимость в каких-то незапланированных доработках, которые существенно повысят удобство использования софта (или же упростят разбирательство с проблемами в софте). Эти доработки нельзя предугадать. Но желательно сделать.

И отсюда проистекает мораль номер два. Хорошо, когда между вами и заказчиком установились нормальные рабочие взаимоотношения. И вам не нужно тратить кучу времени на объяснение того, почему в перечне трудозатрат появилась еще какая-то строчка с непонятной на первый взгляд фигней. Ибо если вам придется отдельно объяснять, почему час рабочего времени был потрачен на изменение схемы идентификации подключениях в записях в лог, то желание делать что-то хорошо для этого заказчика у вас быстро исчезнет.

---

Спасибо тем, кто продолжает читать этот блог. Писать что-то интересное и, надеюсь, полезное, становится все сложнее. Но я буду пытаться продолжать это делать. В частности, есть желание поделиться впечатлением от использования noexcept в коде arataga. Надеюсь, что смогу найти время для того, чтобы написать соответствующую заметку.