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

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

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

2. Любое логгирование должно иметь минимум 3 уровня сообщений - info, warn, err. На практике бывает удобна цифра 5, в комментариях поясню, почему именно так.

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

4. У системы логгирования может быть несколько настраиваемых outputs. Могут быть как стандартные outputs (stdout, file, OutputDebugString, ram pool), так и пользователские выходы, форматы и настройки всех outputs должны легко конфигурироваться независимо от лог-менеджера.

5. Менеджер должен также поддерживать возможность получения логов из многопоточного приложения и на всякий случай предусмотреть ресурсию, когда процесс обработки сообщения в каком-то из outputs приводит к получению повторного сообщения в протокол.

6. Должна быть возможность вырезать ненужные протоколы из игры (функциями препроцессора или еще как-то).

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

Теперь со всем этим мы попробуем взлететь.

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

FILE* s = fopen("mylog.txt", "wt");
fwrite(s, "Init done\n");

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

2. Удобные уровни протоколирования следующие:
Debug - отладочные сообщения. К ним относятся - все сообщения о производительности компонент, сообщения, которые возникают больше, чем раз в секунду, вспомогательные сообщения, которые требуются программисту в процессе отладки, инспекты переменных и т.п. По умолчанию ошибки уровня Debug в логи не выдаются.
Report (или Info) - рабочие сообщения компонент. Эти сообщения выдаются редко (не чаще, чем раз в несколько секунд, их основная задача - информировать файл протокола (а в некоторых случаях - и пользователя) о существенных изменениях в работе приложения. Примеры таких сообщений: loading map ###, user ### joined, game saved, print operation complete и т.п.
Warning - предупреждения, которые не являются критическими для системы в целом (отдельные функции либо сохраняют работоспособность, либо имеют корректный возврат), но которые информируют программиста, что что-то идет не так, как запланировано. В некоторых случаях бывает крайне полезно добавить в код библиотеки вспомогательный счетчик, который будет выдавать warning в протокол, а затем сообщать, что последущие сообщения этого же плана будут исключены. А то часты случаи того, что критическое падение производительности системы наступает из-за того, что незначительный warning начинает засирать протокол со скоростью несколько мегабайт в секунду.
Error - серьезные ошибки, которые как правило ведут к неработоспособности той или иной подсистемы. Сюда относятся - файловые ошибки, ошибки основных функций DirectX, серьезные рассогласования внутренней логики приложения.
Crtiical (или Fatal) - ошибки верхнего уровеня, система находится в нестабльном состоянии и готова упасть. Либо это критические ошибки, которые делают невозможным функционирование приложения в целом. Класс Fatal - это протоколы внутри UnhandledExceptionFilter, диагностика нехватки иои повреждения хипов, глобальные отказы ключевых подсистем. Категории Error и Fatal разнесены исключительно ради удобства реализации некоторых outputs, будет показано в комментариях к седьмому пункту.

3. Маркеры сообщений требуются для того, чтобы можно было удобно настраивать уровни и способы протоколирования. Допустим, программист отлаживает свою подсистему. Он может для нее выставить уровень протоколирования Debug, для остальных будет сохранен уровень Report. Он получает подробный протокол, не мешая другим пользователям и не засирая их логи. Кроме этого, крайне удобным оказывается маркер "Extern File". Почему он нужен - также будет показано ниже.

4. Настраиваемые outputs, или различные регистрируемые коллбеки сообщений позволяют конфигурировать выход протокола так, как это требуется приложению, причем в разные моменты времени могут существовать разные outputs. При возникновении новой записи в протокол происходит вызов всех зарегистрированных обработчиков с передачей следующей информации:
- глобальный инкрементальный номер сообщения;
- время возникновения сообщения;
- сам текст сообщения;
- уровень сообщения (Debug/Report/Warning/Error/Fatal)
- маркер сообщения;
- имя файла;
- номер строки;
- функция возникновения сообщения (опционально);
- идентификатор процесса и/или треда (зависит от платформы и наличия нужных данных);
- дополнительная информация или пользовательские данные колбека;

Обработчик outputs может выполнить необходимые действия по выводу данной сообщения в свой канал. Как сказано выше, такими каналами могут быть: стандартные каналы вывода (файл, stdout, OutputDebugString, ram pool) и пользовательские каналы вывода (отправка в TCP/IP, игровая консоль и т.п.).

5. С этим пунктом все просто - достаточно добавить внутреннюю синхронизацию в менеджер логов. Тогда у каждого конкретного output не будет возникать проблем с выводом типа [Mess[Message2]age1], даже если сообщения проходят из разных тредов. Рекурсивное протоколирование можно складывать во временный буфер небольшого размера или даже попросту игнорировать. У нас сделано так: в случае первого рекурсивного вызова output получает сообщение с дополнительным параметром LOG2 (повторный лог из обработчика), последующие рекурсивные вызовы лога попросту игнорируются.

6. Функции логгирования должны выглядеть как LogDebug(), LogReport() и т.д. В этом случае препроцессор может превратить ненужные в мастер-версии протоколы в (void(0)) и не тратить время на протоколирование. Для PC-версий приложений для мастера рекомендуется удалять уровень Debug, для консольных игр - весь протокол целиком, для других платформ - зависит от специфики приложения и платформы. Количество аргументов при этом должно быть постоянным, поэтому удобнее всего встроить форматирование строки вывода при помощи << прямо в вызов функции. Разумеется, если для вывода лога требуется дополнительная подготовительная обработка, ее лучше окаймить препроцессором вручную.

7. Этот пункт накладывает определенные ограничения на использование функций в логах. В частности, из-за критически длительного времени работы и влияния на хип не рекомендуется использовать в логах std::string. Для файловых протоколов также удобным является вариант, при котором сохранение всех записей производится просто в файловых поток, а ошибки уровня Fatal, предвещающие скорое падение программы, обязательно добавляют flush внутренних буферов. Это, с одной стороны, не создает серьезных нагрузок для простых сообщений (а то я видел примеры того, как любая запись в лог - это секвенция fopen()/fprintf()/fclose()), с другой стороны, гарантирует, что при возникновении критических ошибок вся информация будет сброшена на диск.

Итого, вывод сообщений может регулироваться следующими уровнями протоколов:
- (на уровне менеджера) - общая обрезка сообщений, чей уровень протоколирования слабее заданного (обычно имеет смысл резать только Debug);
- (на уровне менеджера) - пропуск сообщений с какими-то идентификаторами, с персональной настройкой уровня сообщений;
- (на уровне менеджера) - общая обрезка рекурсивных сообщений;
- (на уровне конкретного обработчика output) - обрезка сообщений, чьи уровни протоколирования или идентификаторы не соответствуют установкам.
- (на уровне конкретного обработчика output) - форматирование конкретных сообщений так, как это удобно для вывода.

Последний пункт в свое время привел к интересной реализации системы протоколирования для консольных утилит. Стандартный подписчик output в stdout можно сконфигурировать таким образом, что он выводит сообщения как "(message body)" для всех логов уровня report и выше для всех маркеров  != "Extern File", и выводит сообщения как "(file) line: (type) (message body)" для всех сообщений с маркером "Extern File". Тем самым мы получаем на экране протокол следующего вида:

1С builder system.
Loading file data.ini...
data.ini(10) Error: undefined keyword 'type'
data.ini(55) Warning: duplicated source reference "TM124_A1"
Building canceled

Здесь сообщения из data.ini имеют маркер "Extern File" и сконфигурированы для вывода как {short file}({line} {type}: {message}. Остальные маркеры сконфигурированы как {Message}. При этом получается красивый и привычный для пользователя протокол.

При этом локальная конфигурация вывода в stdout не мешает тому, чтобы в файл выводились собщения вида:

[1018] TOOL c:\tools\src\main.cpp (56): Report: 1С builder system.
[1201] TOOL c:\tools\src\main.cpp (92): Report: Loading file data.ini...
[1403] EXTFILE d:\game\data\data.ini(10): Error: undefined keyword 'type'
[1404] EXTFILE d:\game\data\data.ini(55): Warning: duplicated source reference "TM124_A1"
[2123] TOOL c:\tools\src\main.cpp (418): Error: Building canceled

То есть {timestamp} {marker} {long file}({line}): {type}: {message}

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

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