А именно — расскажу о том как сделать исключения С++ более информативными, а логирование ошибок — более компактным.
После полутора лет работы с Java я привык к исключениям содержащим в себе StackTrace наподобие
Exception in thread "main" java.lang.IllegalStateException: A book has a null property
at com.example.myproject.Author.getBookIds(Author.java:38)
at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
at com.example.myproject.Book.getId(Book.java:22)
at com.example.myproject.Author.getBookIds(Author.java:35)
... 1 more
Переключившись на С++ я через какое-то время был поражён неинформативностью исключений в плане выявления причин ошибки и дальнейшей отладки. Пришлось логировать прохождение всех важных точек программы, чтобы по логам понять где же именно что-то пошло не так и привело к исключению.
Далее я представлю упрощённую эволюцию логирования, через которую прошёл сам.
void foo(int a)
{
if (a == 0)
{
throw runtime_error("foo throw because zero argument");
}
}
void bar(int a)
{
foo(a - 10);
}
int main()
{
try
{
for (int i = 0; i < 100; i++)
{
bar(i);
}
}
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;
}
return 0;
}
В данном виде не зная ничего о пути вызова foo и функции bar очень сложно понять что делать с полученным исключением
Caught exception: foo throw because zero argument
void bar(int a)
{
cerr << "Calling foo(" << a - 10 << ")" << endl;
foo(a - 10);
}
int main()
{
try
{
for (int i = 0; i < 100; i++)
{
cerr << "Calling bar(" << i << ")" << endl;
bar(i);
}
}
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;
}
return 0;
}
Calling bar(0)
Calling foo(-10)
Calling bar(1)
Calling foo(-9)
Calling bar(2)
Calling foo(-8)
Calling bar(3)
Calling foo(-7)
Calling bar(4)
Calling foo(-6)
Calling bar(5)
Calling foo(-5)
Calling bar(6)
Calling foo(-4)
Calling bar(7)
Calling foo(-3)
Calling bar(8)
Calling foo(-2)
Calling bar(9)
Calling foo(-1)
Calling bar(10)
Calling foo(0)
Caught exception: foo throw because zero argument
Теперь понятно что произошло, но лог оказался чересчур захламлённым. А представим кошмар, в который это превратиться, если программа должна обработать все файлы в директории, на каждый файл приходится 5 строчек лога и исключение возникло через 1000 файлов. Итого — 5000 строк лога о том, как всё хорошо, и 10 строк лога об ошибке.
За время чтения этого лога проклятия коллег-разработчиков и тестировщиков, которые вместо праздника читают мой лог и пишут баг-репорт, загонят мою карму в минус бесконечность.
Значит придётся логировать только «ошибочные» ветви исполнения.
Очевидно что на момент вызова функции неизвестно завершится она нормально или выкинет исключение. Значит запись в лог придётся отложить до выхода из функции и анализировать ход выполнения программы.
void bar(int a)
{
try
{
foo(a - 10);
}
catch (const exception &e)
{
string msg = string("calling foo(") + to_string(a - 10) + ") failed";
throw runtime_error(string(e.what()) + "\n" + msg);
}
}
int main()
{
try
{
int i;
try
{
for (i = 0; i < 100; i++)
{
bar(i);
}
}
catch (const exception &e)
{
string msg = string("calling bar(") + to_string(i) + ") failed";
throw runtime_error(string(e.what()) + "\n" + msg);
}
}
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;
}
return 0;
}
Caught exception: foo throw because zero argument
calling foo(0) failed
calling bar(10) failed
Теперь тестировщики легко напишут баг-репорт и приложат к нему красивый, информативный и чистый лог. А вот программа стала уродливой и потеряла всю прелесть исключений — возможность разнести рабочий код и обработку ошибок. Фактически мы вернулись чуть ли не к проверке кодов возврата функции и жестоким временам чистого C. А хочется красивого решения, которое позволит использовать создавать чистый лог и не уродовать программу. Т.е. кто-то должен за нас при выходе из функции проанализировать и залогировать происходящее. Тут нам на помощь приходит подход, уже описаный на Хабре, а именно — запись логов при вызове деструктора.
Итак требования к классу логирования:
- Задание сообщения для лога
- Вывод сообщения, только в случае исключения
Тут нам на помощь приходит функция bool uncaught_exception(), которая как раз и говорит есть ли необработанное исключение.
class ExceptionContext
{
public:
ExceptionContext(const std::string &msg);
~ExceptionContext();
private:
std::string message;
};
ExceptionContext::ExceptionContext(const std::string &msg): message(msg)
{}
ExceptionContext::~ExceptionContext()
{
if (std::uncaught_exception())
{
std::cerr << message << std::endl;
}
}
void bar(int a)
{
ExceptionContext e(string("calling foo(") + to_string(a - 10) + ")");
foo(a - 10);
}
int main()
{
try
{
for (int i = 0; i < 100; i++)
{
ExceptionContext e(string("calling bar(") + to_string(i) + ")");
bar(i);
}
}
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;http://habrahabr.ru/topic/edit/266729/#
}
return 0;
}
calling foo(0)
calling bar(10)
Caught exception: foo throw because zero argument
Видно, что данный вариант сочетает компактность лога (логируем только упавшую ветку исполнения) с компактностью программы (основной код и обработка исключений разнесены, в основной код логирование вставляется одной строчкой). Теперь и разработчики, и тестировщики перестали меня проклинать.
Вообще-то основная цель уже достигнута, но можно пойти по пути множества дальнейших улучшений, в том числе описанных в конце уже упомянутого поста.
Я же рассмотрю всего два момента:
- Взаимодействие с другими логгерами
- Потокобезопасность
Распечатывание лога напрямую в cerr может быть неудобно отсутствием возможности получить с таким трудом накопленый контекст для дублирования его ещё куда-нибудь (да хоть на почту разработчику, раз уж мы существенно сократили его объём!). Опять же, при наличии других инструментов логирования или многопоточного исполнения, возможны неприятные спецэффекты вроде строк лога вперемешку. Поэтому теперь класс ExceptionContext будет логи хранить внутри себя, а наружу выдавать по запросу, на манер printStackTrace из Java.
class ExceptionContext
{
public:
ExceptionContext(const std::string &msg);
~ExceptionContext();
static void Print(); //! Вывод контекста в cerr с последующей очисткой.
private:
std::string message;
static thread_local std::string global_context; //! Хранилище контекста последнего исключения данного потока.
};
ExceptionContext::ExceptionContext(const std::string &msg): message(msg)
{}
ExceptionContext::~ExceptionContext()
{
if (std::uncaught_exception())
{
global_context += message + std::string("\n");
}
}
void ExceptionContext::Print()
{
std::cerr << global_context << std::endl;
global_context.clear();
}
thread_local std::string ExceptionContext::global_context = std::string("");
А catch-блок в основной программе теперь выглядит так:
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;
ExceptionContext::Print();
}
От С++11 здесь используется модификатор thread_local, который гарантирует что в каждом потоке исполнения объект global_context будет собственный, несмотря на то, что он является статическим членом класса и должен быть един для всех экземпляров.
Хороших всем выходных, чистого кода, читаемых логов и остальных успехов в работе!
Комментарии (17)
billyevans
12.09.2015 20:59+4Довольно стремно выглядит += для std::string-а в деструкторе, тк может бросить исключение. Может правильнее держать не строку, а некий связанный список(естесственно intrusive) и при создании контекста провязывать в него новый элемент, а в деструкторе соответственно вывязывать. Притом можно сделать все данные чисто на стеке, необходимые для текущего контекста, а при исключении соответственно брать этот список и распечатывать его. Кажется более безопасный вариант и легкий, тк на создание-удаление такого объекта по сути провязка и вывязка из списка ну и инициализация структуры. И сериализация будет происходить всего содержимого только при исключении.
Corviniol
12.09.2015 21:17Пожалуй += для std::string выглядит стрёмновато, тут я с вами соглашусь. А вот дальнейшую мысль я понял не совсем.
Может правильнее держать не строку, а некий связанный список(естесственно intrusive) и при создании контекста провязывать в него новый элемент, а в деструкторе соответственно вывязывать.
Вы предлагаете ExceptionContext::global_context сделать списком и добавлять/удалять конкретные сообщения?
Если добавлять сообщение в конструкторе, а удалять в деструкторе в случае нормального выполнения то получим много лишних операций добавления/удаления в список. Если добавлять в деструкторе, в случае раскручивания исключения, то точно также можно получить новое исключение. Хотя будет удобнее в использовании, так как можно будет контролируемо двигаться по уровням. Например — чтобы распечатать ближайшие 10 уровней.
Притом можно сделать все данные чисто на стеке
Если не ограничиваться константными строками, то не получится. Как ни странно даже простой sprintf требует наличия malloc. Опять же в catch-блоке вызывающей функции нижележащий стек уже размотан и созданные на нём объекты уничтожены. Так что при исключении придётся всё равно данные из стека куда-то переносить.billyevans
12.09.2015 23:10Операция добавления в односвязанный список — это изменение 1 указателя( или 2х, когда он пуст), удаление последнего элемента, аналогично. Сам объект ExceptionContext является уже элементом списка и лежит прям на стеке. При присваивании указателей не возникнет никаких исключений. Да тут возникнет сложность с местом, где хотим залоггировать все это дело. Можно напечатать прям на месте, в момент создания исключения, тогда можно будет печатать итеративно обходя список, без сбора целой строки из списка и список будет еще жив, если же логгировать в месте приема исключения, то тогда, да нужно будет собирать строку из списка в момент создания объекта исключения, тк наверху список будет уже не такой.
Corviniol
13.09.2015 11:11Что объект ExceptionContext лежит на стеке это понятно. Вопрос в том содержит ли он внутри себя указатель на кучу. Насколько я понимаю по умолчанию std::string свой внутренний буфер выделяет в куче, если не прибегать к особым ухищрениям с указанием конкретного аллокатора. Это описано, например, здесь. А здесь описан один из аллокаторов. Можно попробовать использовать их.
Если не нужно тащить все сообщения до catch-блока — то первая версия ExceptionContext в статье ровно это и делает, вообще не используя списки, а опираясь только на порядок вызова деструкторов.
Скорее уж, если мы не отказываемся от работы с кучей и используем С++11, я бы попробовал воспользоваться move-семантикой при добавлении сообщений в список в деструкторе ExceptionContext. Я не уверен, но мне кажется что если заранее зарезервировать (reserve) разумное количество элементов (по числу уровней вложенности приложения) то move-семантика для push_back не будет требовать выделения памяти и, соответственно, не вызовет исключений.
hoxnox
12.09.2015 22:45А разве libunwind не позволит получить backtrace?
hoxnox
12.09.2015 22:51По-моему п.2.4 в разделе С++ ABI то, что Вам нужно.
AxisPod
13.09.2015 04:20Да, штука удобная, но к примеру на FreeBSD работает только в дебаг режиме без оптимизации. Иначе просто падает, проблема не решена даже в Chromium (используют C++ ABI). А в Linux удобно, но к сожалению не показывают контекст выполнения, но для этих целей есть готовые релизации NDC.
Corviniol
13.09.2015 10:32Да, почитал про ThreadContext в Log4j. Выглядит удобно (работал с подобным под Android) и частично решает проблему — позволяет легче читать огромные логи. Но, как мне кажется, оставляет проблему избыточности логирования — логирует даже абсолютно правильное исполнение 1000 итераций перед одной упавшей.
Или вы под NDC имели в виду что-то другое?
Corviniol
13.09.2015 10:21+1Если мне нужен ТОЛЬКО backtrace — то безусловно мне хватит libunwind. Или даже просто связки backtrace — addr2line. Но тогда может встать другая проблема — я знаю путь к тому что упало. Но если ошибка обусловлена входными данными и встречается довольно редко то мне всё равно будет сложно её локализовать. А так я могу попробовать заранее вставить логирование ключевых моментов и, если повезёт, в логах будет нужная мне информация. При этом я могу логировать «как можно больше» (в разумных пределах) не опасаясь за раздувание лога.
Основной упор я делаю на две возможности:
1) логировать входы-выходы не только из функций, но из любых областей видимости, включая итерации циклов.
2) добавлять в лог дополнительную информацию по моему усмотрению. В примере в статье — аргумент с которым я вызываю функцию.
MacIn
13.09.2015 17:14Только читая такие статьи, начинаешь по-настоящему ценить те инструменты, которые имеешь. У нас используется Eurekalog (для borlandовских builder'а и delphi), который генерирует полные репорты для всех потоков + дампы + стеки вызовов для всех потоков с полной информацией — адрес, модуль, класс, номер строки примерно так:
Call Stack Information:
—
|Address |Module |Unit |Class |Procedure/Method |Line |
—
|*Exception Thread: ID=8820; Priority=0; Class=; [Main] |
|----------------------------------------------------------------------|
|004D316F|Project8.exe|Unit9.pas |TForm9|Button1Click |33[3]|
|76BCF6A5|user32.dll | | |GetWindowLongW | |
…
…
|76BD005B|user32.dll | | |DispatchMessageW | |
|76BD0051|user32.dll | | |DispatchMessageW | |
|004D499D|Project8.exe|Project8.dpr| | |17[4]|
|7691490F|kernel32.dll| | |BaseThreadInitThunk | |
— Сразу предупреждаю — никаких языкосрачей не предполагается.
kmu1990
Кажется, что для таких целей как раз разумно использовать не стандартные расширения, например, у glibc есть execinfo.h, мне кажется для других систем/компиляторов тоже найдется что-нибудь подобное. Еще когда-то тема переносимой библиотеки для получения stacktrace-ов поднималась в boost, но не знаю чем это закончилось.
Corviniol
Вариант с execinfo.h я тоже проходил, но он решает только половину задачи — определить StackTrace.
А вот проблему определения на какой итерации цикла (в каком контексте) произошло исключение он не решит.
Оптимально было бы их объединить — может быть напишу об этом в следующей статье, если данная покажет интерес сообщетсва.
kmu1990
Я правильно понимаю, что ваше решение каждый цикл залогировать с помощью ExceptionContext? Не будет ли при таком подходе для больших программ ExceptionContext забивать весь код своим присутствием? Особенно, если вам приходится ручками генерировать сообщение, а как этого избежать при таком подробном логировании не очень понятно.
Corviniol
Каждый цикл скорее всего избыточно. По крайней мере в leaf-функции это не потребуется, т.к. самый вложенный уровень контекста доступен напрямую, в точке возбуждения исключения. Соответственно можно надеяться что наиболее узкие места, вроде внутреннего цикла в пузырьковой сортировке, не будут включать в себя сохранение контекста каждой итерации. Использование ExceptionContext целесообразно для сохранения целостности контекста между местом возбуждения исключения и местом обработки.
Вы имеете в виду строки исходного кода, размер бинарного файла, время выполнения или размер используемой памяти?По строкам исходного кода — сколько-то будет, но не очень сильно. В зависимости от подробности сообщения. Если сводить только к месту вызова, наподобии ExceptionContext(string(__FILE_) + string(___LINE__)), то backtrace и addr2line или их аналоги действительно эффективнее. А вот экономного способа позволяющего логировать не только точку входа, но и дополнительный контекст (например аргументы или состояние переменных в вызывающей функции) я не видел и буду благодарен, если кто-то укажет имеющийся.
Про размер бинарного файла — сам по себе класс ExceptionContext вроде бы легковесен (точных замеро не проводил) и прирост обусловлен, в основном, кодом генерации сообщения. Здесь нужно искать баланс между информативностью и размером.
Время выполнения — да, оно вырастет, т.к. сообщение будет генерироваться всегда, даже если оно потом не востребовано. Это явно хуже, чем вариант с backtrace, где дополнительная обработка вызывается только при возбуждении исключения. Другой вопрос в том, будет ли это являться узким местом программы. Ну и соотнести пользу потенциальную пользу от лучшего логирования и вред от утяжеления.
Размер используемой памяти — мне кажется что им можно пренебречь для большинства систем. Конечно иногда речь идёт об embedded проектах с 16Кб RAM (а иногда и с 1Кб!), но это скорее экзотика. Да и С++ я для таких систем стараюсь не применять — обычно хватает С, где нет ни исключений, ни деструкторов. Если же речь идёт о более крупных проектах — давайте оценим потребление. Все экземпляры ExceptionContext имеют очень ограниченную область видимости. Фактически в одном потоке не может быть одновременно больше экземпляров, чем уровень вложенности областей видимости. И этот параметр для нерекурсивных алгоритмов поддаётся оценке на этапе проектирования, а не на этапе выполнения.
Понятно что во время сессии отладки поставив breakpoint на возбуждение исключения можно получить гораздо больше информации гораздо более лёгкими методами. Но речь-то идёт о том, чтобы получать осмысленную отладочную информацию после передачи программы на тестирование или в эксплуатацию.
kmu1990
Меня интересует исходный код, вопросы вызывает то, что этот ExceptionContext нужно явно втыкать в код, в то время как execinfo не коснется ничего кроме места генерации ошибки. И это в дополнение к тому, что пока полезность таких подробных логов не кажется очевидной.
Ошибки на то и ошибки, что валятся откуда не ждешь. Нет ведь никаких гарантий, что такие составленные ручками логи будут содержать ту самую нужную информацию. Такому явному логированию не было бы цены, если бы заранее было известно, что нужно логировать.
В моем понимании, подробные логи нужны в месте, где ошибка обнаружена, потому что там собралась вся нужная информация, чтобы ее заметить, а stacktrace покажет путь, которым мы к ошибке пришли. Но для этого ExceptionContext не нужен. А все остальное выглядит как тыканье пальцем в небо (если повезет то в логах будет что-то полезное, а может и не повезти). А если в логах перепутать какую-нибудь i с какой-нибудь j, потом можно долго искать ошибку там, где ее нет (маловероятно конечно, но с кем не бывыает).
При тестировании можно получать core dump — больше информации просто нельзя получить. При эксплуатации использование core dump, вероятно, будет ограничено, но я бы все равно посмотрел на него.