Типы и формат логов

Глобально логи в reindexer можно разделить на 4 основных типа:

  1. Лог ядра (corelog) - основной лог, связанный с работой СУБД (неймспейсов, индексов, репликации, выборок и т.д.).
  2. Лог сервера (serverlog) - лог, связанный с инициализацией и завершением работы сервера (для режимов standalone и built-in server). В этот лог также попадают стек-трейсы в случае критических ошибок.
  3. RPC-лог (rpclog) - лог всех обращений к серверу через RPC по протоколам cproto, cprotos и ucproto.
  4. HTTP-лог (httplog) - лог всех обращений к серверу через HTTP 1.1 по протоколам http и https.

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

Лог ядра

Общий формат записей

Пример записи из лога ядра:

[I13/03 06:06:00.686 12798] Namespace::Construct (ns).Workers: 4, timeout: 800, tm: { state_token: 0xf214c112 (rand), version: 1 }

[I13/03 06:06:00.686 12798] - является заголовком записи, его формат будет одинаков для всех записей лога ядра.

Элементы заголовка:

  • I - обозначает уровень для этой конкретной записи: E - Error, W - Warning, I - Info, T - Trace.
  • 13/03 - дата создания записи.
  • 06:06:00.686 - время создания записи (UTC) с точностью до миллисекунд.
  • 12798 - номер потока, который создал это сообщение.

Остальная часть записи может быть произвольной, хотя для отдельных модулей тоже может иметь одинаковую структуру. Например, для модуля репликации сообщение будет выглядеть следующим образом:

[I13/02 12:32:20.269 170235] [cluster:replicator:async_t] 0:1:ns_async_repl Applying update with type 23 (no batching), id: 25, ns version: 0:0, lsn: 0:0, last synced ns version: 0:11, last synced lsn: 0:4

Здесь к стандартному заголовку ядра добавляются 2 дополнительных части:

  • [cluster:replicator:async_t] - информация о модуле/подсистеме. В данном случае, это подсистема cluster, модуль связанный с реплицированием данных (replicator), работающий в асинхронном режиме (async_t).
  • 0:1:ns_async_repl - информация о сервере-лидере, номере фолловера и конкретном реплицируемом неймспейсе.

В отличие от основного заголовка, для подобных подзаголовков не гарантируется единство и сохранение формата.

Дополнительные сведения

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

  • Лог полнотекстовых индексов. Его уровень задаётся независимо для каждого отдельного текстового индекса через поле log_level в конфигурации этого индекса.
  • Лог выполнения запросов. Его уровень может быть задан на уровне отдельного неймспейса при помощи поля log_level в системном неймспейсе #config, либо передан вместе с самим запросом в момент его формирования (поддержка этой функциональности зависит от конкретного байндинга).
  • Лог асинхронной репликации. Его уровень задаётся через поле log_level при конфигурировании асинхронной репликации.
  • Логи синхронной репликации и RAFT-модуля. Их уровень задаётся через поле log_level в файле конфигурации синхронной репликации.

Уровень логирования для репликации (синхронной и асинхронной) также может быть изменён при помощи action-команды через #config-неймспейс:

{
    "type":"action",
    "action": {
        "command":"set_log_level",
        "type":"async_replication",
        "level":"trace"
    }
}

Например, через reindexer_tool:

reindexer_tool \
--dsn cproto://127.0.0.1:6534/db \
-c '\upsert #config {"type":"action","action":{"command":"set_log_level", "type":"async_replication", "level":"trace"}}'

При этом в поле type передаётся значение async_replication (для асинхронной репликации) или cluster (для RAFT-кластера). А в поле level - требуемый уровень логирования: trace, info, warning, error или none.

Лог сервера

Общий формат записей

Формат сообщений в логах сервера эквивалентен формату логов ядра. Пример записи:

[I13/03 06:05:47.742 12709] Starting reindexer_server (v5.11.1-76-g246572061) on 0.0.0.0:9088 HTTP, 0.0.0.0:6534 RPC(TCP), with db '/tmp/reindex'

[I13/03 06:05:47.742 12709] - является заголовком записи, его формат будет одинаков для всех записей лога сервера.

Элементы заголовка:

  • I - обозначает уровень для этой конкретной записи: E - Error, W - Warning, I - Info, T - Trace, D - Debug.
  • 13/03 - дата создания записи.
  • 06:05:47.742 - время создания записи (UTC) с точностью до миллисекунд.
  • 12709 - номер потока, который создал это сообщение.

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

RPC-лог

Общий формат записей

Этот тип логов пишется на каждое обращение по RPC (например, при работе через Go-клиент по cproto), поэтому каждая отдельная запись лог представляет собой результат выполнения какого-либо запроса. При активной работе по RPC именно этот лог обычно порождает больше всего сообщений.

Запись о выполненной команде попадает в лог только после её завершения.

Примеры записей:

[I13/02 12:33:30.417 196700] p='tcp' c='15' db='@qa_db_anythinguDy1q5FJM' Login {'', '0x0', 'qa_db_anythinguDy1q5FJM', false, false, -1, 'v5.11.0-29-g614ee2463', 'CPP-client', 15, ''} -> OK {'v5.11.0-29-g614ee2463', 1770986004} 76us
[I13/02 12:33:31.213 196700] p='tcp' c='15' db='@qa_db_anythinguDy1q5FJM' ModifyItem {'rxtool_bench', 1, slice{len:22}, 2, '', 1136576710, 0} -> stateToken mismatch:  0x43bec8c6, need -0x4e122742. Can't process item 10us
[I13/02 12:33:31.216 197250] p='tcp' c='12' db='@qa_db_anythinguDy1q5FJM' Select {slice{len:18}, 18, 10000, slice{len:6}} -> OK {slice{len:18}, -1, -1} 137us

Формат здесь является более строгим, чем в случае логов ядра или сервера. Каждое сообщение удовлетворяет следующему шаблону:

<Заголовок> p='<Протокол>' c='<ID соединения>' db='@<Имя БД>' <Команда> {<Набор аргументов команды>} -> <Результат выполнения> [{<Ответ>}] <Время выполнения>

Подробнее о частях шаблона:

  • <Заголовок> - формат заголовка такой же, как у логов ядра и сервера. В примере выше заголовком является следующая подстрока: [I13/02 12:33:33.417 196700].
  • <Протокол> - Название используемого протокола. Для cproto и cprotos там будет tcp, а для ucproto - unix. В примере выше подстрока с протоколом выглядит так: p='tcp'.
  • <ID соединения> - Числовой идентификатор соединения. Он присваивается каждому соединению в момент его создания (обычно это соответствует вызову команды Login) и сохраняется на протяжении всего его времени жизни. В примере выше есть два разных идентификатора соединений: c='15' и c='12'. Две записи из лога выше относятся к соединению 15, а третья - к 12.
  • <Имя БД> - имя базы данных, с которой работает эта команда. К этому имени в логе всегда добавляется символ @. В примере выше подстрока с именем БД выглядит так: db='@qa_db_anythinguDy1q5FJM'.
  • <Команда> - наименование выполненной команды. В примере выше это команды Login, ModifyItem и Select.
  • <Набор аргументов команды> - набор аргументов, которые были переданы в вызов. Список зависит от конкретной команды. Строковые аргументы могут выводиться в виде записи типа slice{len:22}, если содержат непечатные символы или длина строки слишком велика. В примере выше списки аргументов это подстроки {'', '0x0', 'qa_db_anythinguDy1q5FJM', false, false, -1, 'v5.11.0-29-g614ee2463', 'CPP-client', 15, ''}, {'rxtool_bench', 1, slice{len:22}, 2, '', 1136576710, 0} и {slice{len:18}, 18, 10000, slice{len:6}}.
  • <Результат выполнения> - результат выполнения команды. В случае успеха это просто запись OK, а в случае ошибки - текст этой ошибки. В примере выше команды Login и Select завершились успешно, а команда ModifyItem вернула ошибку: stateToken mismatch: 0x43bec8c6, need -0x4e122742. Can't process item
  • <Ответ> - содержимое ответа. Присутствует в логе, только если команда завершилась успешно. Как и в случае списка аргументов, формат ответа зависит от конкретного вызова. В примере выше ответами являются следующие подстроки: {'v5.11.0-29-g614ee2463', 1770986004} и {slice{len:18}, -1, -1}.
  • <Время выполнения> - полное время выполнения команды в микросекундах, начиная с момента парсинга самой команды и заканчивая моментом сериализации ответа.

Если сервер был запущен с флагом debug.allocs, установленным в true, то у каждого сообщения будет дополнительный хвост с информацией о динамических аллокациях памяти, произошедших при выполнении команды:

[I13/02 12:33:23.530 195431] p='tcp'c='7' db='@test' ModifyItem {'items', 1, slice{len:11}, 2, slice{len:20}, -5550529, 0} -> OK {slice{len:34}, -1, -1} 185us | allocs: 2, allocated: 1576 bytes

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

HTTP-лог

Этот тип логов пишется на каждое обращение по HTTP (например, при обращении через WebUI), поэтому каждая отдельная запись лог представляет собой результат выполнения какого-либо запроса.

Запись о выполненном запросе попадает в лог только после его завершения.

Общий формат записей

Пример записи:

[I13/03 09:46:03.980 25643] 127.0.0.1:46896 -  GET /api/v1/db/db/namespaces?sort_order=asc 200 235 70us

Как и в случае с RPC-логом, формат записи является строгим и соответствует шаблону:

<Заголовок> <Адрес:Порт> - <Имя пользователя> <Тип запроса> <Путь> <Код ответа> <Размер ответа> <Время выполнения>

Подробнее о частях шаблона:

  • <Заголовок> - формат заголовка такой же, как у логов ядра и сервера. В примере выше заголовком является следующая подстрока: [I13/02 12:33:33.417 196700].
  • <Адрес:Порт> - IP-адрес и порт, с которых пришёл запрос. В примере выше это 127.0.0.1:46896 (запрос выполнен с localhost).
  • <Имя пользователя> - имя пользователя, выполнившего запроса. Попадает в лог в маскированном виде, только если сервер запущен с флагом security. В примере выше отсутствует.
  • <Тип запроса> - GET/POST/PUT/DELETE.
  • <Путь> - Path-часть для вызванного метода (endpoint’a) вместе со всеми query-параметрами, переданными в URL. В примере выше подстрока пути - /api/v1/db/db/namespaces?sort_order=asc.
  • <Код ответа> - HTTP-код ответа. В примере выше - код 200.
  • <Размер ответа> - размер сериализованного ответа в байтах. В примере выше размер ответа равен 235 байтам.
  • <Время выполнения> - полное время выполнения запроса в микросекундах, начиная с момента парсинга самого запроса и заканчивая моментом сериализации ответа.

Если сервер был запущен с флагом debug.allocs, установленным в true, то у каждого сообщения будет дополнительный хвост с информацией о динамических аллокациях памяти, произошедших при выполнении запроса:

[I13/02 12:31:52.783 137389] 127.0.0.1:44536 -  POST /api/v1/db/qa_db_toojRu1ni/namespaces/qa_nspk_southernouQieQFh/items 200 28 112us | allocs: 1, allocated: 106 byte(s)

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