Логи

Вместо введения (от редакторов)

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

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

Автор приводит примеры на С, но эти примеры актуальны и для Mac-программистов.

Основные принципы

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

1. Любое логгирование нужно делать через одно место :) В смысле, не через то самое место, а через общий менеджер, который управляет всеми поступающими сообщениями. В то же время, система логгирования должна давать каждому конкретному программисту удобство в реализации и просмотре именно своих протоколов во время отладки своих подсистем (раскрыто в третьем пункте).
2. Любое логгирование должно иметь минимум 3 уровня сообщений — info, warn, err. На практике бывает удобна цифра пять, в разделе про уровни протоколирования я поясню, почему именно так.
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, серьезные рассогласования внутренней логики приложения.

Critical (или Fatal) — ошибки верхнего уровеня, система находится в нестабльном состоянии и готова упасть. Либо это критические ошибки, которые делают невозможным функционирование приложения в целом. Класс Fatal — это протоколы внутри UnhandledExceptionFilter, диагностика нехватки иои повреждения хипов, глобальные отказы ключевых подсистем. Категории Error и Fatal разнесены исключительно ради удобства реализации некоторых outputs, будет показано в комментариях к седьмому пункту.

3. Маркеры сообщений

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

4. Настраиваемые outputs

Настраиваемые 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:toolssrcmain.cpp (56): Report: 1С builder system.
[1201] TOOL c:toolssrcmain.cpp (92): Report: Loading file data.ini...
[1403] EXTFILE d:gamedatadata.ini(10): Error: undefined keyword 'type'
[1404] EXTFILE d:gamedatadata.ini(55): Warning: duplicated source reference "TM124_A1"
[2123] TOOL c:toolssrcmain.cpp (418): Error: Building canceled

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

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

Наполнение лога

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

Протокол — очень удобное средство отладки для отчуждаемой программы, которая запускается на неизвестном компьютере у удаленного пользователя (креш-дампы, конечно, при правильной настройке более «казуальны», но применимы только к более узкому числу событий и не всегда). Если при этом что-то идет не так (либо в конфигурации железа, либо в настройках операционной системы, либо в действиях пользователя), приложение может войти в нестабильное состояние (4 типа нестабильностей были рассмотрены ранее), и последовательность необработанных нестабильностей приведет нас к ошибке. Задача протокола — дать возможность программисту разобраться в возникшей нестабильности, исходных причинах ее появления и исправить поведение программы.

Для этого мы рассмотрим все уровни и выделим, какие ошибки должны отправляться лог и с каким уровнем отчета. Начнем с простого — с уровня Fatal.

Fatal

Ошибки класса Fatal, как было отмечено ранее, являются самыми критическими для приложения. Это:

• ошибки нехватки или повреждения оперативной памяти;
• обработчики unhandled exception;
• критические ошибки подсистем, из-за которых приложение не может продолжать работу.

Обработчики outputs для ошибок уровня Fatal могут предпринимать дополнительные действия для того, чтобы сбросить внутренние буфера и обеспечить пользователя максимально возможной информацией о произошедшем баге. Если уж мы находимся внутри обработчика unhandled exception, то лучше абсолютно все сообщения писать на уровне Fatal, чтобы сбрасывать буфера файловых протоколов после каждой записи, а то еще, неровен час, упадем в повторный access violation.

...
    catch (std::bad_alloc a)
    {
        LogFatal(CORE, "Bad alloc exception: " << a.what());
        MEMORYSTATUS m;
        GlobalMemoryStatus(&m);
        LogFatal(CORE, "Total memory: " << m.dwTotalPhys << "; AVailable: " << m.dwAvailPhys);
        // Вызовы функций, которые потенциально могут обрушить приложение (heapchk()), лучше размещать в конце
        LogFatal(CORE, "Heap check result: " << _heapchk());
    }


    static LONG WINAPI UnhandledExceptionFilter(struct _EXCEPTION_POINTERS* e)
    {
        ...
        LogFatal(CORE, "Unhandled exeception: " << e->ExceptionRecord->ExceptionCode);
        LogFatal(CORE, "Exception address: " << e->ExceptionRecord->ExceptionAddress);
        LogFatal(CORE, "Exception flags: " << e->ExceptionRecord->ExceptionFlags);

Error

Ошибки уровня Error — это ошибки, которые могут привести к полной неработоспособности отдельных компонент, но приложение в целом может продолжать работу, пусть и в каком-то менее функциональном виде (хотя бы в теории :). Грань между Error и смежными уровнями довольно близкая, для простоты можно считать Error'ом все, когда приложение уже не может продолжать работу, но пока еще не упало по эксепшену. К Error также можно отнести и те пре- и пост- кондишены (ассерты), которые не имеют должной обработки. То есть, если мы диагностировали NULL-pointer в функции myStrlen() — то если эта ситуация не обработана корректно, то это можно считать Error, а если обработана и возвращен нулевой код возврата, то Warning.

hr = p->CreateDevice(AdapterToUse, DeviceType, hwnd, D3DCREATE_HARDWARE_VERTEXPROCESSING | mt, &d3dpp, &pD3DDevice);
if (hr != S_OK)
{
    LogError(RENDER, "Unable to initialize D3D Device. Error code " << hr);
...

К уровню Error можно отнести и обработку исключений С++. При этом настойчиво рекомендуется начинать протооклирование не в блоке catch(), а непосредственно в конструкторе объекта исключения (если это возможно). Потому что что там еще может свалиться по дороге — одному богу известно, а так вы будете уверены, что первое ошибочное сообщение в файле протокола является самым информативным, а остальное — только его последствия.

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

Warning

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

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

Нестабильности третьего рода (собственная нестабильность функции или модуля). Обычно только ассертируются и логгируются в ходе работы функции. У меня код напичкан несколькими сотнями assert(…, "internal error"); которые несмотря на всю свою невозможность, случаются несколько раз в год. Например, был ассерт в списке объектов, что если m_count = 0, то m_tail и m_head == NULL. Один раз срубился, гад. Оказалось, что между if (m_count == 0) и самим ассертом на m_head второй тред, сцуко, успел зарегистрировать новый объект :)

Нестабильности четвертого рода (коды возврата вызываемого API). Ассертирование обычно не используется, логгирование и корректная обработка должны применяться почти всегда. Очень часто удобно использовать макросы типа VERIFY и автоматом писать в лог информацию о том, что именно срубилось и с каким кодом возврата.

В нормально работающем приложении сообщений уровня Warning в протоколе быть не должно. Однако, увы, очень часто можно встретить ситуацию, в которой например DirectX осыпается варнингами, так как та или иная функция не поддержана капсами. Чтобы такие сообщения не засирали протокол, можно либо понижать их уровень до Debug'а, либо вставлять счетчики, которые будут информировать о предупреждении либо 1 раз на сессию, либо раз на фрейме.

Report

Информационный лог, используется для следующих событий:

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

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

Debug

Все остальные сообщения, в том числе:

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

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

Данная классификация не является единственно возможной. bishop3000 в коментариях к ЖЖ-версии этой статьи части рассказывал про уровень Insane, который стоит ниже Debug и в который пишется вообще все. С точки зрения разделения уровня Debug на Debug и Insane, на нижний уровень можно было бы перенести, например, протоколирование всех аргументов и переменных. Другая идея — это между Report и Debug ввести уровень протоколирования Perf, в который вынести все замеры производительности компонент и функций. Тогда понижением общего уровня протоколирования от дефолтовского Report до Perf можно получить замеры быстродействия системы, не засирая логи лишней отладочной информацией. Но самое главное во всем этом — это то, чтобы у программистов компании было четкое понимание того, что именно и на каких уровнях протоколирования следует выводить. Не будет такого понимания — уровни логов очень быстро потеряют всякую осмысленность, а разобраться в гигабайтном протоколе не будет никакой возможности.

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

Может быть очень полезным вести счетчики количества поступивших сообщений и при завершении работы приложения выводить в окно Output MSVC отчет о том, сколько в приложении встретилось сообщений и какого они были уровня. Если количество Errors или Warnings было больше нуля, на файл протокола стоит обратить пристальное внимание.

Анализ логов

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

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

Основной поинт здесь заключается в том, что найденная цепочка нестабильностей может быть исправлена (и, соответственно, разорвана) в любом месте кода, а вот логи имеет смысл добавлять во все точки нестабильности. Подробнее про нестабильности рассказывалось в цикле «Теория ошибок»: Нестабильности первого рода, Нестабильности второго рода и Нестабильности третьего и четвертого рода.

Во-вторых, если приложение ведет себя не так, как ожидается (например, графические артефакты на экране или неправильное поведение NPC), есть ли сообщения в логе с уровнем больше чем Report? Если нет, то почему? Если есть, то достаточно ли их для того, чтобы локализовать проблему?

Только очень небольшая часть ошибок приложения является следствием каких-то «мифических» воздействий. К мифическим можно отнести: changed memory global, side effects библиотечных функций, непроинициализированные переменные и прочую порчу стека. Остальные ошибки являются результатом воздействия цепочек нестабильностей. Если ваше приложение ведет себя не так — почти наверняка в коде есть нестабильности, которые можно перехватить и залоггировать.

В-третьих. Если приложение ведет себя полностью нормально, ассертов нет, но на выходе из игры в финальном отчете (я писал во второй части, что суммарный отчет по приложению может быть крайне полезен) есть ненулевое количество Warnings и Errors, то почему внимание программиста не было обращено на проблему в точке возникновения?

Этот вопрос корреллирует с другой глобальной темой, о которой нужно писать отдельно — любой баг, который проявляется в системе, должен быть продиагностирован максимально близко к точке возникновения. Отсутствие такой диагностики приводит к весьма странных эффектам — от четырехмесячного дебага до необходимости выполнять длинные и труднореализуемые игровые секвенции в попытках выяснить, ведет ли себя система так, как запланировано, или нет. Если например у вас в игре есть режим «неубиваемого» героя, то проверка того, что он действительно встал в режим неубиения должна вестить при помощи лога, игровой консоли или как-то еще. А никак не методом «пойди через всю карту, найди врага и проверь, будет ли от тебя отлетать здоровье». Как это ни странно, такой метод «проверки» режима работы приложения встречается чуть более, чем часто :(

Реально первая серьезная работа с логами начинается, как только продукт попадает в руки к внешним тестерам. Мне неоднократно приходилось встречаться (и, увы, приходится до сих пор), когда любая мало-мальски серьезная проблема в обязательном порядке требует воспроизведения под отладчиком на компьютере у программиста. Хорошо еще, если есть сейвы, которые помогают диагностировать проблему. Иногда же для того, чтобы понять и воспроизвести баг, приходится гонять через систему контроля багов гигабайты видеоматериала — кто куда пошел и на что нажал :( Или вообще баг зависает в трекере с сообщение «х.з. что случилось, воспроизвести невозможно, соответственно, исправить — тоже».

Минимальное разумное покрытие протоколом исходного кода (в количестве строк протокола на 100 строк исходного кода) оказалось вычленить довольно сложно. В среднем получилось около одной строки лога на 80 строк кода. Я пытался собрать статистику по имеющимся у меня библиотекам и движкам, но материала оказалось, во-первых, откровенно мало, а во вторых, информация сильно зависит от подсистем. Например, сообщения уровня Fatal встречаются в основном в core движка — там, где сосредоточены unhandled exception filters, память и прочее. При этом есть программисты, которые любят сообщение Fatal настолько, что впихивают его в практически любой if(), встречающийся в коде (по видимому, считая, что любое отклонение от нормального течения программы является фатальным по определению). Компоненты, в которых встречается многопоточность, намного качественнее покрыты Debug-сообщениями, чем те, которые можно отлаживать через привычный IDE-отладчик. Сообщения Report в основном сосредоточены в локальной части кода приложений — там, где непосредственно начинается обработка входных событий от пользователя. Наконец, есть программисты, которые протокол не любят, по-видимому, на инстинктивном уровне. Впрочем, обычно это хорошо коррелирует с наплевательским отношением к своим компонентам и к судьбе приложения в целом. Но это уже совсем другая история, к логам не имеющая отношения…

Технические аспекты протоколирования

Последняя часть рассказа про логи — это технические аспекты реализации лог системы — что может быть удачным, а что — нет. И на какие грабли можно наступить в процессе реализации.

Основой для протоколирования в С/С++ может стать макрос, который на вход принимает следующие параметры:

• уровень протоколирования;
• метка сообщения;
• сам текст сообщения;
• имя файла и номер строки, опционально — имя функции.

На основе этого делается уже набор макросов/функций протоколирования:

LogDebug(label, msg) -> Log(DEBUG, __FILE__, __LINE__, __FUNCTION__, label, msg);
LogReport(label, msg) -> Log(REPORT, __FILE__, __LINE__, __FUNCTION__, label, msg);
...

В зависимости от конфигурации системы какие-то логи (например, LogDebug()) могут сворачиваться в ((void)0).

Для логов с меткой ExternFile требуется альтернативный вариант.

LogFileReport(file, line, msg) -> Log(REPORT, file, line, NULL, EXTRENFILE, msg);
...

Если чтение текстовых файлов унифицировано и ведется только через специальный класс, то переменные file и line можно заменить на file_stream_pointer.

В случае, если Log() представлен макросом, то msg может быть не просто готовой строкой, а секвенцией с перегруженным оператором <<. Только нежелательно использовать std::string — гораздо лучше будет, если там будут собственные фиксированные строчки. По этому поводу — см. дискуссию. Основных вариантов реализации я вижу два: это либо классический "Coord: " << x << "; " << y; либо "Coord: %1, %2" << x << y; второй вариант удобнее для локализации. См. также ниже замечание про работу со стеком.

После предварительной обработки в функции Log() мы попадаем в ядро менеджера. Первая задача на этом этапе — это определить, является ли сообщение удовлетворяющим текущим фильтрам {label, level}. У многих рука наверняка потянулась написать std::map, хотя в данном конкретном случае этого можно и избежать. Я бы хотел предложить следующую реализацию:

• считаем CRC имени метки сообщения;
• берем от CRC младший байт и смотрим в массиве на 256 значений — какой уровень протоколирования выставлен для данной метки;
• пропускаем сообщение дальше или игнорируем его.

Данная схема очень быстра и не требует дополнительного распределения оперативной памяти. Учитывая, что количество меток вряд ли превысит несколько десятков, они все «расползутся» по массиву. Что не расползется, может быть быстро поймано со следующими вариантами решения:

• изменить метку (есть гипотеза, что метка библиотеки — это некоторая символьная контанта в хидере);
• увеличить размер массива с 256 байт до 512;
• изменить алгоритм подсчета CRC.

Если ядро менеджера пропустило лог по уровню, дальше идет блокировка рекурсий / вторых тредов и рассылка сообщения по outputs. Как я уже говорил ранее, outputs могут быть различными. Например, если вы хотите иметь отдельный файл, в который валятся только сообщения ресурс-менеджера — сделайте output, который скидывает в свой файл логи с меткой «RESOURCE». Если вы хотите отдельно иметь perf.log и у вас есть отдельный уровень протоколирования perf, сделайте подписчик, который ловит только сообщения уровня Perf. Только надо будет доработать ядро — чтобы лог-менеджер знал об эксклюзивных подписчиках, которым надо отдавать сообщения независимо от общего уровня протоколирования.

По поводу строк фиксированной длины есть одна проблема. Разумеется, в макросе лога можно написать char buf[1024], куда скидывать отформатированное сообщение. Но такой подход требует большого стека. Дело в том, что стек резервируется на входе в функцию, и поэтому протокол следующего вида:

switch (i)
case 1: Log(); ...
case 2: Log(); ...
...
case 10: Log(); ...

отожрет на стеке 10 Кб при входе в функцию. Чтобы этого избежать, можно аллоцировать стек в функции только по конкретному событию через alloca(). Или сделать отдельный пул на 10‒20 строк по одному килобайту и две thread-safe функции для него — AllocLogString(), FreeLogString(). Тогда переполнения стека удастся избежать.

Поскольку подписчиков любого типа output в одном приложении может быть много, то лучше оформить это отдельным классом. Конструктор экземпляра класса автоматически регистрирует callback или virtual func, деструктор объекта удаляет регистрацию callback и закрывает файл или pipe. В таком случае получается, например, следующее:

void main()
{
    LogOutputFile f1("out.log");
    LogOutputCout f2(stderr, "{file}({line}): {message}");

    ... Все функции протоколирования внутри main попадут в f1 и f2.

    // Деструктор LogOutputFile завершит протоколирования в файл.
    // Деструктор LogOutputCout прекратит выводить сообщения в консоль
}

Итого, внешний интерфейс системы протоколирования описывается следующим набором функций:

• регистрация и дерегистрация подписчиков outputs;
• сами макросы протоколирования;
• функции установки фильтров уровней протоколирования для системы в целом или для конкретных меток;
• типовой набор outputs, которые можно использовать в любом приложении: file, cout, OutputDebugString, Pipe… все эти outputs можно настраивать следующим образом:
  • имена файлов или Pipes или что там еще нужно для успешного вывода,
  • указать, что output работает только с конкретной меткой лога или с конкретным уровнем лога,
  • указать формат выдаваемых сообщений, например {file}({line}): {message}; плюс возможно установка кастомного формата для отдельных меток типа ExternFile.