September 12, 2015 at 15:14Logging Exception Context
In anticipation of the Programmer’s Day and in the wake of the Tester’s Day, I want to talk about how to simplify life for both of them in their common business - development and debugging of software.
Namely, I’ll talk about how to make C ++ exceptions more informative, and error logging more compact.
After a year and a half of working with Java, I got used to exceptions containing StackTrace like
After switching to C ++, after some time I was struck by the uninformative nature of the exceptions in terms of identifying the causes of the error and further debugging. I had to log the passage of all the important points of the program in order to understand from the logs where exactly something went wrong and led to an exception.
Next, I will introduce a simplified evolution of logging through which I went through myself.
In this view, without knowing anything about the call path of foo and the bar function, it is very difficult to understand what to do with the exception received
Now it’s clear what happened, but the log turned out to be too cluttered. And imagine a nightmare into which it would turn out if the program should process all the files in the directory, 5 lines of the log fall on each file and an exception occurred after 1000 files. Total - 5000 lines of the log about how everything is fine, and 10 lines of the error log.
During the reading of this log, the curses of fellow developers and testers, who instead of the holiday read my log and write a bug report, will drive my karma to minus infinity.
So you have to log only "erroneous" execution branches.
It is obvious that at the time the function is called, it is unknown whether it will end normally or throw an exception. This means that the log entry will have to be postponed until the function exits and analyze the progress of the program.
Now testers can easily write a bug report and attach a beautiful, informative and clean log to it. But the program became ugly and lost all the charm of exceptions - the ability to smash the working code and error handling. In fact, we returned almost to checking the function return codes and the cruel times of pure C. But I want a beautiful solution that allows you to use a clean log and not disfigure the program. Those. someone should analyze and pledge what is happening for us when leaving the function. Here the approach already described on Habr comes to the rescue of us , namely record of logs at a call of the destructor.
So the requirements for the logging class:
Here the bool uncaught_exception () function comes to our aid , which just says whether there is an unhandled exception.
It can be seen that this option combines the compactness of the log (we log only the fallen branch of execution) with the compactness of the program (the main code and exception handling are spaced, logging is inserted into the main code with one line). Now both developers and testers have stopped cursing me.
In fact, the main goal has already been achieved, but you can follow the path of many further improvements, including those described at the end of the already mentioned post .
I will consider only two points:
Printing the log directly in cerr can be inconvenient because of the lack of the ability to get the accumulated context with such difficulty to duplicate it somewhere else (yes even to the developer’s mail, since we have significantly reduced its volume!). Again, in the presence of other logging tools or multi-threaded execution, unpleasant special effects like log lines mixed up are possible. Therefore, now the ExceptionContext class will store logs inside itself, and issue outwards on request, in the manner of printStackTrace from Java.
From C ++ 11, the thread_local modifier is used here , which guarantees that in each thread of execution the global_context object will be its own, despite the fact that it is a static member of the class and should be the same for all instances.
Have a good weekend, clean code, readable logs and other success in work!
Namely, I’ll talk about how to make C ++ exceptions more informative, and error logging more compact.
After a year and a half of working with Java, I got used to exceptions containing StackTrace like
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
After switching to C ++, after some time I was struck by the uninformative nature of the exceptions in terms of identifying the causes of the error and further debugging. I had to log the passage of all the important points of the program in order to understand from the logs where exactly something went wrong and led to an exception.
Next, I will introduce a simplified evolution of logging through which I went through myself.
The original program that we will debug and improve
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;
}
In this view, without knowing anything about the call path of foo and the bar function, it is very difficult to understand what to do with the exception received
Caught exception: foo throw because zero argument
Add a little bit of logs
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;
}
Execution Result:
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
Now it’s clear what happened, but the log turned out to be too cluttered. And imagine a nightmare into which it would turn out if the program should process all the files in the directory, 5 lines of the log fall on each file and an exception occurred after 1000 files. Total - 5000 lines of the log about how everything is fine, and 10 lines of the error log.
During the reading of this log, the curses of fellow developers and testers, who instead of the holiday read my log and write a bug report, will drive my karma to minus infinity.
So you have to log only "erroneous" execution branches.
It is obvious that at the time the function is called, it is unknown whether it will end normally or throw an exception. This means that the log entry will have to be postponed until the function exits and analyze the progress of the program.
Like so
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
Now testers can easily write a bug report and attach a beautiful, informative and clean log to it. But the program became ugly and lost all the charm of exceptions - the ability to smash the working code and error handling. In fact, we returned almost to checking the function return codes and the cruel times of pure C. But I want a beautiful solution that allows you to use a clean log and not disfigure the program. Those. someone should analyze and pledge what is happening for us when leaving the function. Here the approach already described on Habr comes to the rescue of us , namely record of logs at a call of the destructor.
So the requirements for the logging class:
- Setting a message for the log
- Message output, only in case of exception
Here the bool uncaught_exception () function comes to our aid , which just says whether there is an unhandled exception.
Class ExceptionContext
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;
}
}
Usage example
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
It can be seen that this option combines the compactness of the log (we log only the fallen branch of execution) with the compactness of the program (the main code and exception handling are spaced, logging is inserted into the main code with one line). Now both developers and testers have stopped cursing me.
In fact, the main goal has already been achieved, but you can follow the path of many further improvements, including those described at the end of the already mentioned post .
I will consider only two points:
- Interaction with other loggers
- Thread safety
Printing the log directly in cerr can be inconvenient because of the lack of the ability to get the accumulated context with such difficulty to duplicate it somewhere else (yes even to the developer’s mail, since we have significantly reduced its volume!). Again, in the presence of other logging tools or multi-threaded execution, unpleasant special effects like log lines mixed up are possible. Therefore, now the ExceptionContext class will store logs inside itself, and issue outwards on request, in the manner of printStackTrace from Java.
Thread safe option (using C ++ 11)
And the catch block in the main program now looks like this:
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("");
And the catch block in the main program now looks like this:
catch (const exception &e)
{
cerr << "Caught exception: " << e.what() << endl;
ExceptionContext::Print();
}
From C ++ 11, the thread_local modifier is used here , which guarantees that in each thread of execution the global_context object will be its own, despite the fact that it is a static member of the class and should be the same for all instances.
Have a good weekend, clean code, readable logs and other success in work!